X-Git-Url: https://git.cworth.org/git?a=blobdiff_plain;f=retrace%2Fglretrace_main.cpp;h=1418ca3d0fcc9bd54326263af35763136dd656c8;hb=73341c2fc4c5d70ccca9871043edfd588477d8b8;hp=313a563459216f4508edfa2ae836af2a0c6c3a84;hpb=9d27a54b0381610c30964880a5fdd4c27bb6e732;p=apitrace diff --git a/retrace/glretrace_main.cpp b/retrace/glretrace_main.cpp old mode 100644 new mode 100755 index 313a563..1418ca3 --- a/retrace/glretrace_main.cpp +++ b/retrace/glretrace_main.cpp @@ -26,365 +26,431 @@ #include -#include "os_binary.hpp" -#include "os_string.hpp" -#include "os_time.hpp" -#include "image.hpp" #include "retrace.hpp" -#include "trace_callset.hpp" #include "glproc.hpp" #include "glstate.hpp" #include "glretrace.hpp" +#include "os_time.hpp" +/* Synchronous debug output may reduce performance however, + * without it the callNo in the callback may be inaccurate + * as the callback may be called at any time. + */ +#define DEBUG_OUTPUT_SYNCHRONOUS 0 namespace glretrace { -bool double_buffer = true; +bool insideList = false; bool insideGlBeginEnd = false; -glws::Profile defaultProfile = glws::PROFILE_COMPAT; -glws::Visual *visual[glws::PROFILE_MAX]; -glws::Drawable *drawable = NULL; -glws::Context *context = NULL; -unsigned frame = 0; -long long startTime = 0; -bool wait = false; +struct CallQuery +{ + GLuint ids[3]; + unsigned call; + bool isDraw; + GLuint program; + const trace::FunctionSig *sig; + int64_t cpuStart; + int64_t cpuEnd; +}; + +static bool supportsElapsed = true; +static bool supportsTimestamp = true; +static bool supportsOcclusion = true; +static bool supportsDebugOutput = true; -bool benchmark = false; -static const char *compare_prefix = NULL; -static const char *snapshot_prefix = NULL; -static trace::CallSet snapshot_frequency; -static trace::CallSet compare_frequency; +static std::list callQueries; -unsigned dump_state = ~0; +static void APIENTRY +debugOutputCallback(GLenum source, GLenum type, GLuint id, GLenum severity, GLsizei length, const GLchar* message, GLvoid* userParam); void checkGlError(trace::Call &call) { GLenum error = glGetError(); - if (error == GL_NO_ERROR) { - return; - } + while (error != GL_NO_ERROR) { + std::ostream & os = retrace::warning(call); - std::ostream & os = retrace::warning(call); - - os << "glGetError("; - os << call.name(); - os << ") = "; - - switch (error) { - case GL_INVALID_ENUM: - os << "GL_INVALID_ENUM"; - break; - case GL_INVALID_VALUE: - os << "GL_INVALID_VALUE"; - break; - case GL_INVALID_OPERATION: - os << "GL_INVALID_OPERATION"; - break; - case GL_STACK_OVERFLOW: - os << "GL_STACK_OVERFLOW"; - break; - case GL_STACK_UNDERFLOW: - os << "GL_STACK_UNDERFLOW"; - break; - case GL_OUT_OF_MEMORY: - os << "GL_OUT_OF_MEMORY"; - break; - case GL_INVALID_FRAMEBUFFER_OPERATION: - os << "GL_INVALID_FRAMEBUFFER_OPERATION"; - break; - case GL_TABLE_TOO_LARGE: - os << "GL_TABLE_TOO_LARGE"; - break; - default: - os << error; - break; + os << "glGetError("; + os << call.name(); + os << ") = "; + + switch (error) { + case GL_INVALID_ENUM: + os << "GL_INVALID_ENUM"; + break; + case GL_INVALID_VALUE: + os << "GL_INVALID_VALUE"; + break; + case GL_INVALID_OPERATION: + os << "GL_INVALID_OPERATION"; + break; + case GL_STACK_OVERFLOW: + os << "GL_STACK_OVERFLOW"; + break; + case GL_STACK_UNDERFLOW: + os << "GL_STACK_UNDERFLOW"; + break; + case GL_OUT_OF_MEMORY: + os << "GL_OUT_OF_MEMORY"; + break; + case GL_INVALID_FRAMEBUFFER_OPERATION: + os << "GL_INVALID_FRAMEBUFFER_OPERATION"; + break; + case GL_TABLE_TOO_LARGE: + os << "GL_TABLE_TOO_LARGE"; + break; + default: + os << error; + break; + } + os << "\n"; + + error = glGetError(); } - os << "\n"; } -/** - * Grow the current drawble. - * - * We need to infer the drawable size from GL calls because the drawable sizes - * are specified by OS specific calls which we do not trace. - */ -void -updateDrawable(int width, int height) { - if (!drawable) { - return; - } +static void +getCurrentTimes(int64_t& cpuTime, int64_t& gpuTime) { + GLuint query; - if (drawable->visible && - width <= drawable->width && - height <= drawable->height) { - return; + if (retrace::profilingGpuTimes && supportsTimestamp) { + glGenQueries(1, &query); + glQueryCounter(query, GL_TIMESTAMP); + glGetQueryObjecti64vEXT(query, GL_QUERY_RESULT, &gpuTime); + } else { + gpuTime = 0; } - // Ignore zero area viewports - if (width == 0 || height == 0) { - return; + if (retrace::profilingCpuTimes) { + cpuTime = os::getTime(); + } else { + cpuTime = 0; } - // Check for bound framebuffer last, as this may have a performance impact. - GLint draw_framebuffer = 0; - glGetIntegerv(GL_DRAW_FRAMEBUFFER_BINDING, &draw_framebuffer); - if (draw_framebuffer != 0) { - return; + if (retrace::profilingGpuTimes && supportsTimestamp) { + glDeleteQueries(1, &query); } +} - drawable->resize(width, height); - drawable->show(); +static void +completeCallQuery(CallQuery& query) { + /* Get call start and duration */ + int64_t gpuStart = 0, gpuDuration = 0, cpuDuration = 0, pixels = 0; + + if (query.isDraw) { + if (retrace::profilingGpuTimes) { + if (supportsTimestamp) { + glGetQueryObjecti64vEXT(query.ids[0], GL_QUERY_RESULT, &gpuStart); + } - glScissor(0, 0, width, height); -} + glGetQueryObjecti64vEXT(query.ids[1], GL_QUERY_RESULT, &gpuDuration); + } + if (retrace::profilingPixelsDrawn) { + glGetQueryObjecti64vEXT(query.ids[2], GL_QUERY_RESULT, &pixels); + } -static void -snapshot(unsigned call_no) { - assert(snapshot_prefix || compare_prefix); + glDeleteQueries(3, query.ids); + } else { + pixels = -1; + } - if (!drawable) { - return; + if (retrace::profilingCpuTimes) { + cpuDuration = query.cpuEnd - query.cpuStart; } - image::Image *ref = NULL; + /* Add call to profile */ + retrace::profiler.addCall(query.call, query.sig->name, query.program, pixels, gpuStart, gpuDuration, query.cpuStart, cpuDuration); +} - if (compare_prefix) { - os::String filename = os::String::format("%s%010u.png", compare_prefix, call_no); - ref = image::readPNG(filename); - if (!ref) { - return; - } - if (retrace::verbosity >= 0) { - std::cout << "Read " << filename << "\n"; - } +void +flushQueries() { + for (std::list::iterator itr = callQueries.begin(); itr != callQueries.end(); ++itr) { + completeCallQuery(*itr); } - image::Image *src = glstate::getDrawBufferImage(); - if (!src) { - return; - } + callQueries.clear(); +} - if (snapshot_prefix) { - if (snapshot_prefix[0] == '-' && snapshot_prefix[1] == 0) { - char comment[21]; - snprintf(comment, sizeof comment, "%u", call_no); - src->writePNM(std::cout, comment); - } else { - os::String filename = os::String::format("%s%010u.png", snapshot_prefix, call_no); - if (src->writePNG(filename) && retrace::verbosity >= 0) { - std::cout << "Wrote " << filename << "\n"; +void +beginProfile(trace::Call &call, bool isDraw) { + glretrace::Context *currentContext = glretrace::getCurrentContext(); + + /* Create call query */ + CallQuery query; + query.isDraw = isDraw; + query.call = call.no; + query.sig = call.sig; + query.program = currentContext ? currentContext->activeProgram : 0; + + /* GPU profiling only for draw calls */ + if (isDraw) { + glGenQueries(3, query.ids); + + if (retrace::profilingGpuTimes) { + if (supportsTimestamp) { + glQueryCounter(query.ids[0], GL_TIMESTAMP); } + + glBeginQuery(GL_TIME_ELAPSED, query.ids[1]); + } + + if (retrace::profilingPixelsDrawn) { + glBeginQuery(GL_SAMPLES_PASSED, query.ids[2]); } } - if (ref) { - std::cout << "Snapshot " << call_no << " average precision of " << src->compare(*ref) << " bits\n"; - delete ref; + callQueries.push_back(query); + + /* CPU profiling for all calls */ + if (retrace::profilingCpuTimes) { + callQueries.back().cpuStart = os::getTime(); + } +} + +void +endProfile(trace::Call &call, bool isDraw) { + GLint64 time = os::getTime(); + + /* CPU profiling for all calls */ + if (retrace::profilingCpuTimes) { + CallQuery& query = callQueries.back(); + query.cpuEnd = time; } - delete src; + /* GPU profiling only for draw calls */ + if (isDraw) { + if (retrace::profilingGpuTimes) { + glEndQuery(GL_TIME_ELAPSED); + } + + if (retrace::profilingPixelsDrawn) { + glEndQuery(GL_SAMPLES_PASSED); + } + } } +void +initContext() { + glretrace::Context *currentContext = glretrace::getCurrentContext(); + + /* Ensure we have adequate extension support */ + assert(currentContext); + supportsTimestamp = currentContext->hasExtension("GL_ARB_timer_query"); + supportsElapsed = currentContext->hasExtension("GL_EXT_timer_query") || supportsTimestamp; + supportsOcclusion = currentContext->hasExtension("GL_ARB_occlusion_query"); + supportsDebugOutput = currentContext->hasExtension("GL_ARB_debug_output"); + + /* Check for timer query support */ + if (retrace::profilingGpuTimes) { + if (!supportsTimestamp && !supportsElapsed) { + std::cout << "Error: Cannot run profile, GL_EXT_timer_query extension is not supported." << std::endl; + exit(-1); + } -void frame_complete(trace::Call &call) { - ++frame; + GLint bits = 0; + glGetQueryiv(GL_TIME_ELAPSED, GL_QUERY_COUNTER_BITS, &bits); - if (!drawable) { - return; + if (!bits) { + std::cout << "Error: Cannot run profile, GL_QUERY_COUNTER_BITS == 0." << std::endl; + exit(-1); + } } - if (!drawable->visible) { - retrace::warning(call) << "could not infer drawable size (glViewport never called)\n"; + /* Check for occlusion query support */ + if (retrace::profilingPixelsDrawn && !supportsOcclusion) { + std::cout << "Error: Cannot run profile, GL_ARB_occlusion_query extension is not supported." << std::endl; + exit(-1); } -} + /* Setup debug message call back */ + if (retrace::debug && supportsDebugOutput) { + glretrace::Context *currentContext = glretrace::getCurrentContext(); + glDebugMessageCallbackARB(&debugOutputCallback, currentContext); -static void display(void) { - retrace::Retracer retracer; - - retracer.addCallbacks(gl_callbacks); - retracer.addCallbacks(glx_callbacks); - retracer.addCallbacks(wgl_callbacks); - retracer.addCallbacks(cgl_callbacks); - retracer.addCallbacks(egl_callbacks); - - startTime = os::getTime(); - trace::Call *call; - - while ((call = retrace::parser.parse_call())) { - bool swapRenderTarget = call->flags & trace::CALL_FLAG_SWAP_RENDERTARGET; - bool doSnapshot = - snapshot_frequency.contains(*call) || - compare_frequency.contains(*call) - ; - - // For calls which cause rendertargets to be swaped, we take the - // snapshot _before_ swapping the rendertargets. - if (doSnapshot && swapRenderTarget) { - if (call->flags & trace::CALL_FLAG_END_FRAME) { - // For swapbuffers/presents we still use this call number, - // spite not have been executed yet. - snapshot(call->no); - } else { - // Whereas for ordinate fbo/rendertarget changes we use the - // previous call's number. - snapshot(call->no - 1); - } + if (DEBUG_OUTPUT_SYNCHRONOUS) { + glEnable(GL_DEBUG_OUTPUT_SYNCHRONOUS_ARB); } + } - retracer.retrace(*call); + /* Sync the gpu and cpu start times */ + if (retrace::profilingCpuTimes || retrace::profilingGpuTimes) { + if (!retrace::profiler.hasBaseTimes()) { + GLint64 gpuTime, cpuTime; - if (doSnapshot && !swapRenderTarget) { - snapshot(call->no); + getCurrentTimes(cpuTime, gpuTime); + retrace::profiler.setBaseCpuTime(cpuTime); + retrace::profiler.setBaseGpuTime(gpuTime); } + } +} - if (!insideGlBeginEnd && - drawable && context && - call->no >= dump_state) { - glstate::dumpCurrentContext(std::cout); - exit(0); +void +frame_complete(trace::Call &call) { + if (retrace::profiling) { + /* Complete any remaining queries */ + flushQueries(); + + /* GPU time drifts due to being relative times, not absolute and can be + * affected by the gpu switch between processes. + * + * To attempt to compensate we resynchronise on frame end however there is + * still noticeable drift within a single frame which we do not account for. + */ + if (retrace::profilingCpuTimes || retrace::profilingGpuTimes) { + int64_t cpuTime, gpuTime, error; + + getCurrentTimes(cpuTime, gpuTime); + cpuTime = cpuTime - retrace::profiler.getBaseCpuTime(); + gpuTime = gpuTime - retrace::profiler.getBaseGpuTime(); + error = gpuTime - cpuTime * (1.0E9 / os::timeFrequency); + + retrace::profiler.setBaseGpuTime(retrace::profiler.getBaseGpuTime() + error); } - delete call; + /* Indicate end of current frame */ + retrace::profiler.addFrameEnd(); } - // Reached the end of trace - glFlush(); + retrace::frameComplete(call); - long long endTime = os::getTime(); - float timeInterval = (endTime - startTime) * (1.0 / os::timeFrequency); + glretrace::Context *currentContext = glretrace::getCurrentContext(); + if (!currentContext) { + return; + } - if ((retrace::verbosity >= -1) || (retrace::profiling)) { - std::cout << - "Rendered " << frame << " frames" - " in " << timeInterval << " secs," - " average of " << (frame/timeInterval) << " fps\n"; + assert(currentContext->drawable); + if (retrace::debug && !currentContext->drawable->visible) { + retrace::warning(call) << "could not infer drawable size (glViewport never called)\n"; } +} - if (wait) { - while (glws::processEvents()) {} - } else { - exit(0); +static const char* +getDebugOutputSource(GLenum source) { + switch(source) { + case GL_DEBUG_SOURCE_API_ARB: + return "API"; + case GL_DEBUG_SOURCE_WINDOW_SYSTEM_ARB: + return "Window System"; + case GL_DEBUG_SOURCE_SHADER_COMPILER_ARB: + return "Shader Compiler"; + case GL_DEBUG_SOURCE_THIRD_PARTY_ARB: + return "Third Party"; + case GL_DEBUG_SOURCE_APPLICATION_ARB: + return "Application"; + case GL_DEBUG_SOURCE_OTHER_ARB: + default: + return ""; } } +static const char* +getDebugOutputType(GLenum type) { + switch(type) { + case GL_DEBUG_TYPE_ERROR_ARB: + return "error"; + case GL_DEBUG_TYPE_DEPRECATED_BEHAVIOR_ARB: + return "deprecated behaviour"; + case GL_DEBUG_TYPE_UNDEFINED_BEHAVIOR_ARB: + return "undefined behaviour"; + case GL_DEBUG_TYPE_PORTABILITY_ARB: + return "portability issue"; + case GL_DEBUG_TYPE_PERFORMANCE_ARB: + return "performance issue"; + case GL_DEBUG_TYPE_OTHER_ARB: + default: + return "unknown issue"; + } +} -static void usage(void) { - std::cout << - "Usage: glretrace [OPTION] TRACE\n" - "Replay TRACE.\n" - "\n" - " -b benchmark mode (no error checking or warning messages)\n" - " -p profiling mode (run whole trace, dump profiling info)\n" - " -c PREFIX compare against snapshots\n" - " -C CALLSET calls to compare (default is every frame)\n" - " -core use core profile\n" - " -db use a double buffer visual (default)\n" - " -sb use a single buffer visual\n" - " -s PREFIX take snapshots; `-` for PNM stdout output\n" - " -S CALLSET calls to snapshot (default is every frame)\n" - " -v increase output verbosity\n" - " -D CALLNO dump state at specific call no\n" - " -w wait on final frame\n"; +static const char* +getDebugOutputSeverity(GLenum severity) { + switch(severity) { + case GL_DEBUG_SEVERITY_HIGH_ARB: + return "High"; + case GL_DEBUG_SEVERITY_MEDIUM_ARB: + return "Medium"; + case GL_DEBUG_SEVERITY_LOW_ARB: + return "Low"; + default: + return "usnknown"; + } } -extern "C" -int main(int argc, char **argv) -{ - assert(compare_frequency.empty()); - assert(snapshot_frequency.empty()); +static void APIENTRY +debugOutputCallback(GLenum source, GLenum type, GLuint id, GLenum severity, GLsizei length, const GLchar* message, GLvoid* userParam) { + std::cerr << retrace::callNo << ": "; + std::cerr << "glDebugOutputCallback: "; + std::cerr << getDebugOutputSeverity(severity) << " severity "; + std::cerr << getDebugOutputSource(source) << " " << getDebugOutputType(type); + std::cerr << " " << id; + std::cerr << ", " << message; + std::cerr << std::endl; +} - int i; - for (i = 1; i < argc; ++i) { - const char *arg = argv[i]; +} /* namespace glretrace */ - if (arg[0] != '-') { - break; + +class GLDumper : public retrace::Dumper { +public: + image::Image * + getSnapshot(void) { + if (!glretrace::getCurrentContext()) { + return NULL; } + return glstate::getDrawBufferImage(); + } - if (!strcmp(arg, "--")) { - break; - } else if (!strcmp(arg, "-b")) { - benchmark = true; - retrace::verbosity = -1; - glws::debug = false; - } else if (!strcmp(arg, "-p")) { - retrace::profiling = true; - retrace::verbosity = -1; - glws::debug = false; - } else if (!strcmp(arg, "-c")) { - compare_prefix = argv[++i]; - if (compare_frequency.empty()) { - compare_frequency = trace::CallSet(trace::FREQUENCY_FRAME); - } - } else if (!strcmp(arg, "-C")) { - compare_frequency = trace::CallSet(argv[++i]); - if (compare_prefix == NULL) { - compare_prefix = ""; - } - } else if (!strcmp(arg, "-D")) { - dump_state = atoi(argv[++i]); - retrace::verbosity = -2; - } else if (!strcmp(arg, "-core")) { - defaultProfile = glws::PROFILE_CORE; - } else if (!strcmp(arg, "-db")) { - double_buffer = true; - } else if (!strcmp(arg, "-sb")) { - double_buffer = false; - } else if (!strcmp(arg, "--help")) { - usage(); - return 0; - } else if (!strcmp(arg, "-s")) { - snapshot_prefix = argv[++i]; - if (snapshot_frequency.empty()) { - snapshot_frequency = trace::CallSet(trace::FREQUENCY_FRAME); - } - if (snapshot_prefix[0] == '-' && snapshot_prefix[1] == 0) { - os::setBinaryMode(stdout); - retrace::verbosity = -2; - } - } else if (!strcmp(arg, "-S")) { - snapshot_frequency = trace::CallSet(argv[++i]); - if (snapshot_prefix == NULL) { - snapshot_prefix = ""; - } - } else if (!strcmp(arg, "-v")) { - ++retrace::verbosity; - } else if (!strcmp(arg, "-w")) { - wait = true; - } else { - std::cerr << "error: unknown option " << arg << "\n"; - usage(); - return 1; + bool + dumpState(std::ostream &os) { + glretrace::Context *currentContext = glretrace::getCurrentContext(); + if (glretrace::insideGlBeginEnd || + !currentContext) { + return false; } + glstate::dumpCurrentContext(os); + return true; } +}; + +static GLDumper glDumper; + +void +retrace::setUp(void) { glws::init(); - visual[glws::PROFILE_COMPAT] = glws::createVisual(double_buffer, glws::PROFILE_COMPAT); - visual[glws::PROFILE_CORE] = glws::createVisual(double_buffer, glws::PROFILE_CORE); - visual[glws::PROFILE_ES1] = glws::createVisual(double_buffer, glws::PROFILE_ES1); - visual[glws::PROFILE_ES2] = glws::createVisual(double_buffer, glws::PROFILE_ES2); - - for ( ; i < argc; ++i) { - if (!retrace::parser.open(argv[i])) { - std::cerr << "error: failed to open " << argv[i] << "\n"; - return 1; - } + dumper = &glDumper; +} - display(); - retrace::parser.close(); +void +retrace::addCallbacks(retrace::Retracer &retracer) +{ + retracer.addCallbacks(glretrace::gl_callbacks); + retracer.addCallbacks(glretrace::glx_callbacks); + retracer.addCallbacks(glretrace::wgl_callbacks); + retracer.addCallbacks(glretrace::cgl_callbacks); + retracer.addCallbacks(glretrace::egl_callbacks); +} + + +void +retrace::flushRendering(void) { + glretrace::Context *currentContext = glretrace::getCurrentContext(); + if (currentContext) { + glretrace::flushQueries(); + glFlush(); } +} - for (int n = 0; n < glws::PROFILE_MAX; n++) { - delete visual[n]; +void +retrace::waitForInput(void) { + while (glws::processEvents()) { + os::sleep(100*1000); } +} +void +retrace::cleanUp(void) { glws::cleanup(); - - return 0; } - -} /* namespace glretrace */