From: James Benton Date: Wed, 25 Jul 2012 12:48:20 +0000 (+0100) Subject: Improved profiling capabilities. X-Git-Url: https://git.cworth.org/git?p=apitrace;a=commitdiff_plain;h=6d92327e88d2bb4c03a1b84663e50497f99fc24f Improved profiling capabilities. Logs which shader is active to allow per shader profiling. Merged cpu profiling code from retrace to trace_profiler. Allow choice of profiling for gpu / cpu / pixels drawn. --- diff --git a/common/trace_profiler.cpp b/common/trace_profiler.cpp index ab29e36..6fc0039 100644 --- a/common/trace_profiler.cpp +++ b/common/trace_profiler.cpp @@ -28,7 +28,12 @@ namespace trace { Profiler::Profiler() - : baseTime(0) + : lastProgram(0), + baseGpuTime(0), + baseCpuTime(0), + cpuTimes(false), + gpuTimes(true), + pixelsDrawn(false) { } @@ -36,42 +41,115 @@ Profiler::~Profiler() { } -void Profiler::addCall(unsigned no, const char *name, uint64_t gpu_start, uint64_t gpu_duration, uint64_t samples_passed) +void Profiler::setup(bool cpuTimes_, bool gpuTimes_, bool pixelsDrawn_) { - if (baseTime == 0) - baseTime = gpu_start; - - std::cout << "call " - << no << " " - << (gpu_start - baseTime) << " " - << gpu_duration << " " - << samples_passed << " " - << name << std::endl; + cpuTimes = cpuTimes_; + gpuTimes = gpuTimes_; + pixelsDrawn = pixelsDrawn_; + + std::cout << "# frame begin " << std::endl; + std::cout << "# frame end " << std::endl; + std::cout << "# call " << std::endl; + std::cout << "# use shader program " << std::endl; } -void Profiler::addFrameStart(unsigned no, uint64_t timestamp) +void Profiler::addCall(unsigned no, + const char *name, + unsigned program, + uint64_t pixels, + uint64_t gpuStart, uint64_t gpuDuration, + uint64_t cpuStart, uint64_t cpuDuration) { - if (baseTime == 0) - baseTime = timestamp; + if (baseGpuTime == 0) + baseGpuTime = gpuStart; + + if (baseCpuTime == 0) + baseCpuTime = cpuStart; + + if (program != lastProgram) { + std::cout << "use shader program " << program << std::endl; + lastProgram = program; + } + + std::cout << "call " << no; + + if (gpuTimes) { + std::cout << " " + << (gpuStart - baseGpuTime) << " " + << gpuDuration; + } else { + std::cout << " _ _"; + } + + if (cpuTimes) { + std::cout << " " + << (cpuStart - baseCpuTime) << " " + << cpuDuration; + } else { + std::cout << " _ _"; + } + + if (pixelsDrawn) { + std::cout << " " << pixels; + } else { + std::cout << " _"; + } + + std::cout << " " << name << std::endl; +} + +void Profiler::addFrameStart(unsigned no, uint64_t gpuStart, uint64_t cpuStart) +{ + if (baseGpuTime == 0) + baseGpuTime = gpuStart; + + if (baseCpuTime == 0) + baseCpuTime = cpuStart; lastFrame.no = no; - lastFrame.start = timestamp - baseTime; + lastFrame.gpuStart = gpuStart - baseGpuTime; + + std::cout << "frame begin " << lastFrame.no; + + if (gpuTimes) { + std::cout << " " << lastFrame.gpuStart; + } else { + std::cout << " _"; + } + + if (gpuTimes) { + std::cout << " " << lastFrame.cpuStart; + } else { + std::cout << " _"; + } - std::cout << "frame begin " - << lastFrame.no << " " - << lastFrame.start << std::endl; + std::cout << std::endl; } -void Profiler::addFrameEnd(uint64_t timestamp) +void Profiler::addFrameEnd(uint64_t gpuEnd, uint64_t cpuEnd) { - if (baseTime == 0) - baseTime = timestamp; + if (baseGpuTime == 0) + baseGpuTime = gpuEnd; + + if (baseCpuTime == 0) + baseCpuTime = cpuEnd; + + lastFrame.gpuEnd = gpuEnd - baseGpuTime; + + std::cout << "frame end " << lastFrame.no; + + if (gpuTimes) { + std::cout << " " << lastFrame.gpuEnd << " " << (lastFrame.gpuEnd - lastFrame.gpuStart); + } else { + std::cout << " _ _"; + } - lastFrame.end = timestamp - baseTime; + if (cpuTimes) { + std::cout << " " << lastFrame.cpuEnd << " " << (lastFrame.cpuEnd - lastFrame.cpuStart); + } else { + std::cout << " _ _"; + } - std::cout << "frame end " - << lastFrame.no << " " - << lastFrame.end << " " - << (lastFrame.end - lastFrame.start) << std::endl; + std::cout << std::endl; } } diff --git a/common/trace_profiler.hpp b/common/trace_profiler.hpp index ff07c95..da60d72 100644 --- a/common/trace_profiler.hpp +++ b/common/trace_profiler.hpp @@ -37,18 +37,33 @@ public: Profiler(); ~Profiler(); - void addCall(unsigned no, const char* name, uint64_t gpu_start, uint64_t gpu_duration, uint64_t samples_passed); + void setup(bool cpuTimes_, bool gpuTimes_, bool pixelsDrawn_); - void addFrameStart(unsigned no, uint64_t timestamp); - void addFrameEnd(uint64_t timestamp); + void addFrameStart(unsigned no, uint64_t gpuStart, uint64_t cpuStart); + void addFrameEnd(uint64_t gpuEnd, uint64_t cpuEnd); + + void addCall(unsigned no, + const char* name, + unsigned program, + uint64_t pixels, + uint64_t gpuStart, uint64_t gpuDuration, + uint64_t cpuStart, uint64_t cpuDuration); private: - uint64_t baseTime; + unsigned lastProgram; + uint64_t baseGpuTime; + uint64_t baseCpuTime; + + bool cpuTimes; + bool gpuTimes; + bool pixelsDrawn; struct { unsigned no; - uint64_t start; - uint64_t end; + uint64_t gpuStart; + uint64_t gpuEnd; + uint64_t cpuStart; + uint64_t cpuEnd; } lastFrame; }; } diff --git a/retrace/glretrace.hpp b/retrace/glretrace.hpp index a39f9c1..bfc6398 100644 --- a/retrace/glretrace.hpp +++ b/retrace/glretrace.hpp @@ -71,10 +71,12 @@ void frame_complete(trace::Call &call); void updateDrawable(int width, int height); void flushQueries(); -void beginProfileGPU(trace::Call &call); -void endProfileGPU(trace::Call &call); +void beginProfile(trace::Call &call); +void endProfile(trace::Call &call); +void setActiveProgram(GLuint program); } /* namespace glretrace */ +GLuint retrace_unmap_program(GLuint val); #endif /* _GLRETRACE_HPP_ */ diff --git a/retrace/glretrace.py b/retrace/glretrace.py index 440366c..fd012d1 100644 --- a/retrace/glretrace.py +++ b/retrace/glretrace.py @@ -297,16 +297,19 @@ class GlRetracer(Retracer): function.name in self.misc_draw_function_names ) - # Only profile if not inside a list as the queries get inserted into lsit + if function.name in ('glUseProgram', 'glUseProgramObjectARB'): + print r' glretrace::setActiveProgram((call.arg(0)).toUInt());' + + # Only profile if not inside a list as the queries get inserted into list if function.name == 'glNewList': - print r' glretrace::insideList = true;'; + print r' glretrace::insideList = true;' if function.name == 'glEndList': - print r' glretrace::insideList = false;'; + print r' glretrace::insideList = false;' if profileDraw: - print r' if (!glretrace::insideList && retrace::profileGPU) {' - print r' glretrace::beginProfileGPU(call);' + print r' if (!glretrace::insideList && retrace::profiling) {' + print r' glretrace::beginProfile(call);' print r' }' if function.name == 'glCreateShaderProgramv': @@ -341,8 +344,8 @@ class GlRetracer(Retracer): Retracer.invokeFunction(self, function) if profileDraw: - print r' if (!glretrace::insideList && retrace::profileGPU) {' - print r' glretrace::endProfileGPU(call);' + print r' if (!glretrace::insideList && retrace::profiling) {' + print r' glretrace::endProfile(call);' print r' }' # Error checking diff --git a/retrace/glretrace_main.cpp b/retrace/glretrace_main.cpp index 4f5706b..ce06402 100644 --- a/retrace/glretrace_main.cpp +++ b/retrace/glretrace_main.cpp @@ -30,6 +30,7 @@ #include "glproc.hpp" #include "glstate.hpp" #include "glretrace.hpp" +#include "os_time.hpp" namespace glretrace { @@ -41,12 +42,16 @@ struct CallQuery { GLuint ids[3]; unsigned call; + GLuint program; const trace::FunctionSig *sig; + uint64_t start; + uint64_t duration; }; static bool firstFrame = true; static std::list callQueries; static const int maxActiveCallQueries = 128; +static std::map activePrograms; void @@ -95,29 +100,47 @@ checkGlError(trace::Call &call) { } static GLuint64 -getTimestamp() { +getGpuTimestamp() { GLuint query = 0; GLuint64 timestamp = 0; - glGenQueries(1, &query); - glQueryCounter(query, GL_TIMESTAMP); - glGetQueryObjectui64vEXT(query, GL_QUERY_RESULT, ×tamp); - glDeleteQueries(1, &query); + if (retrace::profilingGpuTimes) { + glGenQueries(1, &query); + glQueryCounter(query, GL_TIMESTAMP); + glGetQueryObjectui64vEXT(query, GL_QUERY_RESULT, ×tamp); + glDeleteQueries(1, &query); + } return timestamp; } +static GLuint64 +getCpuTimestamp() { + if (retrace::profilingCpuTimes) { + return os::getTime() * (1.0E9 / os::timeFrequency); + } else { + return 0; + } +} + static void completeCallQuery(CallQuery& query) { /* Get call start and duration */ GLuint64 timestamp = 0, duration = 0, samples = 0; - glGetQueryObjectui64vEXT(query.ids[0], GL_QUERY_RESULT, ×tamp); - glGetQueryObjectui64vEXT(query.ids[1], GL_QUERY_RESULT, &duration); - glGetQueryObjectui64vEXT(query.ids[2], GL_QUERY_RESULT, &samples); + + if (retrace::profilingGpuTimes) { + glGetQueryObjectui64vEXT(query.ids[0], GL_QUERY_RESULT, ×tamp); + glGetQueryObjectui64vEXT(query.ids[1], GL_QUERY_RESULT, &duration); + } + + if (retrace::profilingPixelsDrawn) { + glGetQueryObjectui64vEXT(query.ids[2], GL_QUERY_RESULT, &samples); + } + glDeleteQueries(3, query.ids); /* Add call to profile */ - retrace::profiler.addCall(query.call, query.sig->name, timestamp, duration, samples); + retrace::profiler.addCall(query.call, query.sig->name, query.program, samples, timestamp, duration, query.start, query.duration); } void @@ -129,8 +152,24 @@ flushQueries() { callQueries.clear(); } +void setActiveProgram(GLuint program) +{ + activePrograms[glretrace::currentContext] = program; +} + +static GLuint +getActiveProgram() +{ + std::map::iterator it; + it = activePrograms.find(glretrace::currentContext); + if (it == activePrograms.end()) + return 0; + + return it->second; +} + void -beginProfileGPU(trace::Call &call) { +beginProfile(trace::Call &call) { if (firstFrame) { frame_start(); } @@ -145,38 +184,59 @@ beginProfileGPU(trace::Call &call) { CallQuery query; query.call = call.no; query.sig = call.sig; + query.program = getActiveProgram(); glGenQueries(3, query.ids); - glQueryCounter(query.ids[0], GL_TIMESTAMP); - glBeginQuery(GL_TIME_ELAPSED, query.ids[1]); - glBeginQuery(GL_SAMPLES_PASSED, query.ids[2]); + + if (retrace::profilingGpuTimes) { + glQueryCounter(query.ids[0], GL_TIMESTAMP); + glBeginQuery(GL_TIME_ELAPSED, query.ids[1]); + } + + if (retrace::profilingPixelsDrawn) { + glBeginQuery(GL_SAMPLES_PASSED, query.ids[2]); + } callQueries.push_back(query); + + if (retrace::profilingCpuTimes) { + query.start = os::getTime(); + } } void -endProfileGPU(trace::Call &call) { - glEndQuery(GL_TIME_ELAPSED); - glEndQuery(GL_SAMPLES_PASSED); +endProfile(trace::Call &call) { + if (retrace::profilingCpuTimes) { + CallQuery& query = callQueries.back(); + query.duration = (os::getTime() - query.start) * (1.0E9 / os::timeFrequency); + } + + if (retrace::profilingGpuTimes) { + glEndQuery(GL_TIME_ELAPSED); + } + + if (retrace::profilingPixelsDrawn) { + glEndQuery(GL_SAMPLES_PASSED); + } } void frame_start() { firstFrame = false; - if (retrace::profileGPU) { - retrace::profiler.addFrameStart(retrace::frameNo, getTimestamp()); + if (retrace::profiling) { + retrace::profiler.addFrameStart(retrace::frameNo, getGpuTimestamp(), getCpuTimestamp()); } } void frame_complete(trace::Call &call) { - if (retrace::profileGPU) { + if (retrace::profiling) { /* Complete any remaining queries */ flushQueries(); /* Indicate end of current frame */ - retrace::profiler.addFrameEnd(getTimestamp()); + retrace::profiler.addFrameEnd(getGpuTimestamp(), getCpuTimestamp()); } retrace::frameComplete(call); diff --git a/retrace/retrace.cpp b/retrace/retrace.cpp index 25c3f64..182d118 100644 --- a/retrace/retrace.cpp +++ b/retrace/retrace.cpp @@ -112,20 +112,7 @@ void Retracer::retrace(trace::Call &call) { assert(callback); assert(callbacks[id] == callback); - if (retrace::profiling) { - long long startTime = os::getTime(); - callback(call); - long long stopTime = os::getTime(); - float timeInterval = (stopTime - startTime) * (1.0E6 / os::timeFrequency); - - std::cout - << call.no << " " - << "[" << timeInterval << " usec] " - ; - trace::dump(call, std::cout, trace::DUMP_FLAG_NO_CALL_NO | trace::DUMP_FLAG_NO_COLOR); - } else { - callback(call); - } + callback(call); } diff --git a/retrace/retrace.hpp b/retrace/retrace.hpp index 311cef9..01d2609 100644 --- a/retrace/retrace.hpp +++ b/retrace/retrace.hpp @@ -148,6 +148,9 @@ extern bool debug; * Add profiling data to the dump when retracing. */ extern bool profiling; +extern bool profilingCpuTimes; +extern bool profilingGpuTimes; +extern bool profilingPixelsDrawn; /** * State dumping. @@ -158,8 +161,6 @@ extern bool dumpingState; extern bool doubleBuffer; extern bool coreProfile; -extern bool profileGPU; - extern unsigned frameNo; diff --git a/retrace/retrace_main.cpp b/retrace/retrace_main.cpp index 2c14b87..5f5e095 100644 --- a/retrace/retrace_main.cpp +++ b/retrace/retrace_main.cpp @@ -54,14 +54,15 @@ trace::Profiler profiler; int verbosity = 0; bool debug = true; -bool profiling = false; -bool profileGPU = false; bool dumpingState = false; - bool doubleBuffer = true; bool coreProfile = false; +bool profiling = false; +bool profilingGpuTimes = false; +bool profilingCpuTimes = false; +bool profilingPixelsDrawn = false; unsigned frameNo = 0; @@ -171,7 +172,7 @@ mainLoop() { long long endTime = os::getTime(); float timeInterval = (endTime - startTime) * (1.0 / os::timeFrequency); - if ((retrace::verbosity >= -1) || (retrace::profiling) || (retrace::profileGPU)) { + if ((retrace::verbosity >= -1) || (retrace::profiling)) { std::cout << "Rendered " << frameNo << " frames" " in " << timeInterval << " secs," @@ -196,8 +197,9 @@ usage(const char *argv0) { "Replay TRACE.\n" "\n" " -b benchmark mode (no error checking or warning messages)\n" - " -p profiling mode (run whole trace, dump profiling info)\n" - " -pgpu gpu profiling mode (run whole trace, dump gpu profiling info)\n" + " -pcpu cpu profiling (cpu times per call)\n" + " -pgpu gpu profiling (gpu times per draw call)\n" + " -ppd pixels drawn profiling (pixels drawn per draw call)\n" " -c PREFIX compare against snapshots\n" " -C CALLSET calls to compare (default is every frame)\n" " -core use core profile\n" @@ -232,16 +234,6 @@ int main(int argc, char **argv) } else if (!strcmp(arg, "-b")) { retrace::debug = false; retrace::verbosity = -1; - } else if (!strcmp(arg, "-p")) { - retrace::debug = false; - retrace::profiling = true; - retrace::verbosity = -1; - } else if (!strcmp(arg, "-pgpu")) { - retrace::profileGPU = true; - - retrace::debug = false; - retrace::profiling = false; - retrace::verbosity = -1; } else if (!strcmp(arg, "-c")) { comparePrefix = argv[++i]; if (compareFrequency.empty()) { @@ -283,6 +275,18 @@ int main(int argc, char **argv) ++retrace::verbosity; } else if (!strcmp(arg, "-w")) { waitOnFinish = true; + } else if (arg[1] == 'p') { + retrace::debug = false; + retrace::profiling = true; + retrace::verbosity = -1; + + if (!strcmp(arg, "-pcpu")) { + retrace::profilingCpuTimes = true; + } else if (!strcmp(arg, "-pgpu")) { + retrace::profilingGpuTimes = true; + } else if (!strcmp(arg, "-ppd")) { + retrace::profilingPixelsDrawn = true; + } } else { std::cerr << "error: unknown option " << arg << "\n"; usage(argv[0]); @@ -291,6 +295,9 @@ int main(int argc, char **argv) } retrace::setUp(); + if (retrace::profiling) { + retrace::profiler.setup(retrace::profilingCpuTimes, retrace::profilingGpuTimes, retrace::profilingPixelsDrawn); + } for ( ; i < argc; ++i) { if (!retrace::parser.open(argv[i])) {