X-Git-Url: https://git.cworth.org/git?a=blobdiff_plain;f=retrace%2Fglretrace_main.cpp;h=3645b4f3978cde994afab5da7b86176df15d8687;hb=7a9fb5103e052150232b64cb5d99374cda3f1234;hp=011a3549f9d0b01b81018a052599b80c14bfc2cf;hpb=2133d27c0f719205881e2f050c38f9b3d6bcf046;p=apitrace diff --git a/retrace/glretrace_main.cpp b/retrace/glretrace_main.cpp old mode 100644 new mode 100755 index 011a354..3645b4f --- a/retrace/glretrace_main.cpp +++ b/retrace/glretrace_main.cpp @@ -1,6 +1,8 @@ /************************************************************************** * * Copyright 2011 Jose Fonseca + * Copyright (C) 2013 Intel Corporation. All rights reversed. + * Author: Shuang He * All Rights Reserved. * * Permission is hereby granted, free of charge, to any person obtaining a copy @@ -26,364 +28,463 @@ #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" +#include "os_memory.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; +bool supportsARBShaderObjects = false; -static const char *compare_prefix = NULL; -static const char *snapshot_prefix = NULL; -static trace::CallSet snapshot_frequency; -static trace::CallSet compare_frequency; +enum { + GPU_START = 0, + GPU_DURATION, + OCCLUSION, + NUM_QUERIES, +}; -unsigned dump_state = ~0; +struct CallQuery +{ + GLuint ids[NUM_QUERIES]; + unsigned call; + bool isDraw; + GLuint program; + const trace::FunctionSig *sig; + int64_t cpuStart; + int64_t cpuEnd; + int64_t vsizeStart; + int64_t vsizeEnd; + int64_t rssStart; + int64_t rssEnd; +}; + +static bool supportsElapsed = true; +static bool supportsTimestamp = true; +static bool supportsOcclusion = true; +static bool supportsDebugOutput = true; + +static std::list callQueries; + +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); + + 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(); } +} - 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; +static inline int64_t +getCurrentTime(void) { + if (retrace::profilingGpuTimes && supportsTimestamp) { + /* Get the current GL time without stalling */ + GLint64 timestamp = 0; + glGetInteger64v(GL_TIMESTAMP, ×tamp); + return timestamp; + } else { + return os::getTime(); } - 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 inline int64_t +getTimeFrequency(void) { + if (retrace::profilingGpuTimes && supportsTimestamp) { + return 1000000000; + } else { + return os::timeFrequency; } +} - if (drawable->visible && - width <= drawable->width && - height <= drawable->height) { - return; +static inline void +getCurrentVsize(int64_t& vsize) { + vsize = os::getVsize(); +} + +static inline void +getCurrentRss(int64_t& rss) { + rss = os::getRss(); +} + +static void +completeCallQuery(CallQuery& query) { + /* Get call start and duration */ + int64_t gpuStart = 0, gpuDuration = 0, cpuDuration = 0, pixels = 0, vsizeDuration = 0, rssDuration = 0; + + if (query.isDraw) { + if (retrace::profilingGpuTimes) { + if (supportsTimestamp) { + glGetQueryObjecti64vEXT(query.ids[GPU_START], GL_QUERY_RESULT, &gpuStart); + } + + glGetQueryObjecti64vEXT(query.ids[GPU_DURATION], GL_QUERY_RESULT, &gpuDuration); + } + + if (retrace::profilingPixelsDrawn) { + glGetQueryObjecti64vEXT(query.ids[OCCLUSION], GL_QUERY_RESULT, &pixels); + } + + } else { + pixels = -1; } - // Ignore zero area viewports - if (width == 0 || height == 0) { - return; + if (retrace::profilingCpuTimes) { + double cpuTimeScale = 1.0E9 / getTimeFrequency(); + cpuDuration = (query.cpuEnd - query.cpuStart) * cpuTimeScale; + query.cpuStart *= cpuTimeScale; } - // 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::profilingMemoryUsage) { + vsizeDuration = query.vsizeEnd - query.vsizeStart; + rssDuration = query.rssEnd - query.rssStart; } - drawable->resize(width, height); - drawable->show(); + glDeleteQueries(NUM_QUERIES, query.ids); - glScissor(0, 0, width, height); + /* Add call to profile */ + retrace::profiler.addCall(query.call, query.sig->name, query.program, pixels, gpuStart, gpuDuration, query.cpuStart, cpuDuration, query.vsizeStart, vsizeDuration, query.rssStart, rssDuration); } - -static void -snapshot(unsigned call_no) { - assert(snapshot_prefix || compare_prefix); - - if (!drawable) { - return; +void +flushQueries() { + for (std::list::iterator itr = callQueries.begin(); itr != callQueries.end(); ++itr) { + completeCallQuery(*itr); } - image::Image *ref = NULL; + callQueries.clear(); +} + +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; + + glGenQueries(NUM_QUERIES, query.ids); + + /* GPU profiling only for draw calls */ + if (isDraw) { + if (retrace::profilingGpuTimes) { + if (supportsTimestamp) { + glQueryCounter(query.ids[GPU_START], GL_TIMESTAMP); + } - if (compare_prefix) { - os::String filename = os::String::format("%s%010u.png", compare_prefix, call_no); - ref = image::readPNG(filename); - if (!ref) { - return; + glBeginQuery(GL_TIME_ELAPSED, query.ids[GPU_DURATION]); } - if (retrace::verbosity >= 0) { - std::cout << "Read " << filename << "\n"; + + if (retrace::profilingPixelsDrawn) { + glBeginQuery(GL_SAMPLES_PASSED, query.ids[OCCLUSION]); } } - image::Image *src = glstate::getDrawBufferImage(); - if (!src) { - return; - } + callQueries.push_back(query); - 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"; - } - } + /* CPU profiling for all calls */ + if (retrace::profilingCpuTimes) { + CallQuery& query = callQueries.back(); + query.cpuStart = getCurrentTime(); } - if (ref) { - std::cout << "Snapshot " << call_no << " average precision of " << src->compare(*ref) << " bits\n"; - delete ref; + if (retrace::profilingMemoryUsage) { + CallQuery& query = callQueries.back(); + query.vsizeStart = os::getVsize(); + query.rssStart = os::getRss(); } - - delete src; } +void +endProfile(trace::Call &call, bool isDraw) { -void frame_complete(trace::Call &call) { - ++frame; + /* CPU profiling for all calls */ + if (retrace::profilingCpuTimes) { + CallQuery& query = callQueries.back(); + query.cpuEnd = getCurrentTime(); + } - if (!drawable) { - return; + /* GPU profiling only for draw calls */ + if (isDraw) { + if (retrace::profilingGpuTimes) { + glEndQuery(GL_TIME_ELAPSED); + } + + if (retrace::profilingPixelsDrawn) { + glEndQuery(GL_SAMPLES_PASSED); + } } - if (!drawable->visible) { - retrace::warning(call) << "could not infer drawable size (glViewport never called)\n"; + if (retrace::profilingMemoryUsage) { + CallQuery& query = callQueries.back(); + query.vsizeEnd = os::getVsize(); + query.rssEnd = os::getRss(); } } +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"); + supportsARBShaderObjects = currentContext->hasExtension("GL_ARB_shader_objects"); + + /* 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); + } -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); - } + GLint bits = 0; + glGetQueryiv(GL_TIME_ELAPSED, GL_QUERY_COUNTER_BITS, &bits); + + if (!bits) { + std::cout << "Error: Cannot run profile, GL_QUERY_COUNTER_BITS == 0." << std::endl; + exit(-1); } + } + + /* 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); + } - retracer.retrace(*call); + /* Setup debug message call back */ + if (retrace::debug && supportsDebugOutput) { + glretrace::Context *currentContext = glretrace::getCurrentContext(); + glDebugMessageCallbackARB(&debugOutputCallback, currentContext); - if (doSnapshot && !swapRenderTarget) { - snapshot(call->no); + if (DEBUG_OUTPUT_SYNCHRONOUS) { + glEnable(GL_DEBUG_OUTPUT_SYNCHRONOUS_ARB); } + } - if (!insideGlBeginEnd && - drawable && context && - call->no >= dump_state) { - glstate::dumpCurrentContext(std::cout); - exit(0); + /* Sync the gpu and cpu start times */ + if (retrace::profilingCpuTimes || retrace::profilingGpuTimes) { + if (!retrace::profiler.hasBaseTimes()) { + double cpuTimeScale = 1.0E9 / getTimeFrequency(); + GLint64 currentTime = getCurrentTime() * cpuTimeScale; + retrace::profiler.setBaseCpuTime(currentTime); + retrace::profiler.setBaseGpuTime(currentTime); } + } - delete call; + if (retrace::profilingMemoryUsage) { + GLint64 currentVsize, currentRss; + getCurrentVsize(currentVsize); + retrace::profiler.setBaseVsizeUsage(currentVsize); + getCurrentRss(currentRss); + retrace::profiler.setBaseRssUsage(currentRss); } +} + +void +frame_complete(trace::Call &call) { + if (retrace::profiling) { + /* Complete any remaining queries */ + flushQueries(); - // Reached the end of trace - glFlush(); + /* Indicate end of current frame */ + retrace::profiler.addFrameEnd(); + } - long long endTime = os::getTime(); - float timeInterval = (endTime - startTime) * (1.0 / os::timeFrequency); + retrace::frameComplete(call); - if ((retrace::verbosity >= -1) || (retrace::profiling)) { - std::cout << - "Rendered " << frame << " frames" - " in " << timeInterval << " secs," - " average of " << (frame/timeInterval) << " fps\n"; + glretrace::Context *currentContext = glretrace::getCurrentContext(); + if (!currentContext) { + return; } - if (wait) { - while (glws::processEvents()) {} - } else { - exit(0); + assert(currentContext->drawable); + if (retrace::debug && !currentContext->drawable->visible) { + retrace::warning(call) << "could not infer drawable size (glViewport never called)\n"; } } +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 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* +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"; + } } -extern "C" -int main(int argc, char **argv) -{ - assert(compare_frequency.empty()); - assert(snapshot_frequency.empty()); +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"; + } +} - int i; - for (i = 1; i < argc; ++i) { - const char *arg = argv[i]; +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; +} - if (arg[0] != '-') { - break; +} /* namespace glretrace */ + + +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")) { - retrace::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 */