[PATCH 1/2] Add simple profiling support to glretrace.

Ryan C. Gordon icculus at icculus.org
Sat Jan 7 22:32:41 PST 2012


This will note the time, in nanoseconds, that each traced call required, and
 will dump this information during the replay, giving a basic idea of where
 time was spent in the GL.
---
 CMakeLists.txt         |    2 +-
 common/trace_dump.cpp  |    4 ++++
 common/trace_model.hpp |    7 +++++++
 glretrace.hpp          |    1 +
 glretrace.py           |    2 +-
 glretrace_main.cpp     |    9 ++++++++-
 retrace.cpp            |   29 ++++++++++++++++++++++++++++-
 retrace.hpp            |    5 +++++
 8 files changed, 55 insertions(+), 4 deletions(-)

diff --git a/CMakeLists.txt b/CMakeLists.txt
index 6f1315a..cbc0d03 100755
--- a/CMakeLists.txt
+++ b/CMakeLists.txt
@@ -552,7 +552,7 @@ if (WIN32 OR APPLE OR X11_FOUND)
                 ${OPENGL_gl_LIBRARY} # CGL*
             )
         else ()
-            target_link_libraries (glretrace ${X11_X11_LIB})
+            target_link_libraries (glretrace ${X11_X11_LIB} rt)
         endif ()
 
         target_link_libraries (glretrace
diff --git a/common/trace_dump.cpp b/common/trace_dump.cpp
index 6b2fdc3..5728f02 100644
--- a/common/trace_dump.cpp
+++ b/common/trace_dump.cpp
@@ -201,6 +201,10 @@ public:
     void visit(Call *call) {
         CallFlags callFlags = call->flags;
 
+        if (callFlags & CALL_FLAG_ELAPSED) {
+            os << "[" << (((double) call->elapsed) / 1000.0) << " usec] ";
+        }
+
         if (callFlags & CALL_FLAG_NON_REPRODUCIBLE) {
             os << strike;
         } else if (callFlags & (CALL_FLAG_FAKE | CALL_FLAG_NO_SIDE_EFFECTS)) {
diff --git a/common/trace_model.hpp b/common/trace_model.hpp
index 4f150bc..0de5820 100644
--- a/common/trace_model.hpp
+++ b/common/trace_model.hpp
@@ -403,6 +403,11 @@ enum {
      * Whether this call is verbose (i.e., not usually interesting).
      */
     CALL_FLAG_VERBOSE                  = (1 << 7),
+
+    /**
+     * Whether this call contains valid profiling information
+     */
+    CALL_FLAG_ELAPSED                  = (1 << 8),
 };
 
 
@@ -414,6 +419,7 @@ public:
     const FunctionSig *sig;
     std::vector<Value *> args;
     Value *ret;
+    unsigned long long elapsed;
 
     CallFlags flags;
 
@@ -421,6 +427,7 @@ public:
         sig(_sig), 
         args(_sig->num_args), 
         ret(0),
+        elapsed(0),
         flags(_flags) {
     }
 
diff --git a/glretrace.hpp b/glretrace.hpp
index 41e2997..d3e2589 100644
--- a/glretrace.hpp
+++ b/glretrace.hpp
@@ -54,6 +54,7 @@ enum frequency {
 };
 
 extern bool benchmark;
+extern bool profiling;
 extern const char *compare_prefix;
 extern const char *snapshot_prefix;
 extern enum frequency snapshot_frequency;
diff --git a/glretrace.py b/glretrace.py
index 6de2882..9550414 100644
--- a/glretrace.py
+++ b/glretrace.py
@@ -248,7 +248,7 @@ class GlRetracer(Retracer):
             print '    glretrace::insideGlBeginEnd = true;'
         elif function.name.startswith('gl'):
             # glGetError is not allowed inside glBegin/glEnd
-            print '    if (!glretrace::benchmark && !glretrace::insideGlBeginEnd) {'
+            print '    if (!glretrace::benchmark && !glretrace::profiling && !glretrace::insideGlBeginEnd) {'
             print '        glretrace::checkGlError(call);'
             if function.name in ('glProgramStringARB', 'glProgramStringNV'):
                 print r'        GLint error_position = -1;'
diff --git a/glretrace_main.cpp b/glretrace_main.cpp
index 978a34e..56a768b 100644
--- a/glretrace_main.cpp
+++ b/glretrace_main.cpp
@@ -49,6 +49,7 @@ long long startTime = 0;
 bool wait = false;
 
 bool benchmark = false;
+bool profiling = false;
 const char *compare_prefix = NULL;
 const char *snapshot_prefix = NULL;
 enum frequency snapshot_frequency = FREQUENCY_NEVER;
@@ -232,7 +233,7 @@ static void display(void) {
     long long endTime = os::getTime();
     float timeInterval = (endTime - startTime) * 1.0E-6;
 
-    if (retrace::verbosity >= -1) { 
+    if ((retrace::verbosity >= -1) || (retrace::profiling)) {
         std::cout << 
             "Rendered " << frame << " frames"
             " in " <<  timeInterval << " secs,"
@@ -253,6 +254,7 @@ static void usage(void) {
         "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"
         "  -core        use core profile\n"
         "  -db          use a double buffer visual (default)\n"
@@ -282,6 +284,11 @@ int main(int argc, char **argv)
             benchmark = true;
             retrace::verbosity = -1;
             glws::debug = false;
+        } else if (!strcmp(arg, "-p")) {
+            profiling = true;
+            retrace::profiling = true;
+            retrace::verbosity = -1;
+            glws::debug = false;
         } else if (!strcmp(arg, "-c")) {
             compare_prefix = argv[++i];
             if (snapshot_frequency == FREQUENCY_NEVER) {
diff --git a/retrace.cpp b/retrace.cpp
index 849c597..73496f0 100644
--- a/retrace.cpp
+++ b/retrace.cpp
@@ -26,6 +26,8 @@
 
 #include <string.h>
 #include <iostream>
+#include <sys/time.h>
+#include <time.h>
 
 #include "trace_dump.hpp"
 #include "retrace.hpp"
@@ -35,6 +37,7 @@ namespace retrace {
 
 
 int verbosity = 0;
+bool profiling = false;
 
 
 static bool call_dumped = false;
@@ -80,6 +83,22 @@ void Retracer::addCallbacks(const Entry *entries) {
     }
 }
 
+static inline unsigned long long now()
+{
+#ifdef __linux__  // !!! FIXME: and others?
+    struct timespec tp;
+    if (clock_gettime(CLOCK_REALTIME, &tp) == -1)
+        return 0;
+    return (((unsigned long long) tp.tv_sec) * 1000000000ull) + ((unsigned long long) tp.tv_nsec);
+#elif defined(__APPLE__) || defined(unix)  // !!! FIXME: is there something higher resolution without resorting to RDSTC?
+    struct timeval tv;
+    gettimeofday(&tv, NULL);
+    return (((unsigned long long) tv.tv_sec) * 1000000000ull) + (((unsigned long long) tv.tv_usec) * 1000ull);
+#else
+#   warning no profiling support on this platform. Write me!
+    return 0;
+#endif
+}
 
 void Retracer::retrace(trace::Call &call) {
     call_dumped = false;
@@ -114,8 +133,16 @@ void Retracer::retrace(trace::Call &call) {
     assert(callback);
     assert(callbacks[id] == callback);
 
+    const unsigned long long start = retrace::profiling ? now() : 0;
+
     callback(call);
-}
 
+    if (retrace::profiling) {
+        call.elapsed = (unsigned long long) (now() - start);
+        call.flags |= trace::CALL_FLAG_ELAPSED;
+        trace::dump(call, std::cout, trace::DUMP_FLAG_NO_COLOR);
+    }
+}
 
 } /* namespace retrace */
+
diff --git a/retrace.hpp b/retrace.hpp
index a59a6eb..57b8b05 100644
--- a/retrace.hpp
+++ b/retrace.hpp
@@ -95,6 +95,11 @@ toPointer(trace::Value &value, bool bind = false);
  */
 extern int verbosity;
 
+/**
+ * Add profiling data to the dump when retracing.
+ */
+extern bool profiling;
+
 
 std::ostream &warning(trace::Call &call);
 
-- 
1.7.5.4


--------------080702070303060002060108--


More information about the apitrace mailing list