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 ab29e361220bef7ca93c5e2d5edc0af83d86633e..6fc00395cd1d3de808d8ae999f05f9540f10a86a 100644 (file)
--- 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 <no> <gpu_start> <cpu_start>" << std::endl;
+    std::cout << "# frame end <no> <gpu_end> <gpu_dura> <cpu_end> <cpu_dura>" << std::endl;
+    std::cout << "# call <no> <gpu_start> <gpu_dura> <cpu_start> <cpu_dura> <pixels> <function>" << std::endl;
+    std::cout << "# use shader program <no>" << 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 ff07c957d6c48d042e7b3d56ddb3ef9368664844..da60d72e532d210ada7a75bbf318a6aa8bebcf6a 100644 (file)
--- 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 a39f9c1f367477e22832f783f031d9563c8dc854..bfc6398abdc2c5b7bd3900b38789df49e48c12c0 100644 (file)
--- 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 440366cb87a85f22eb8fdb53201f46b435664cf0..fd012d1719a245b5dd99f207e58dbf4d22e62982 100644 (file)
--- 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 4f5706bdafd16e405f143ef07f6bde54288056c6..ce064021bfa28ba74b99884f92ad5de49c52e28c 100644 (file)
--- 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<CallQuery> callQueries;
 static const int maxActiveCallQueries = 128;
+static std::map<glws::Context*, GLuint> 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, &timestamp);
-    glDeleteQueries(1, &query);
+    if (retrace::profilingGpuTimes) {
+        glGenQueries(1, &query);
+        glQueryCounter(query, GL_TIMESTAMP);
+        glGetQueryObjectui64vEXT(query, GL_QUERY_RESULT, &timestamp);
+        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, &timestamp);
-    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, &timestamp);
+        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<glws::Context*, GLuint>::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 25c3f646de2dc2e5ae46f83a1ab3262c7edd4367..182d1182eece7f2768ebaf15df8de70f249e14d6 100644 (file)
--- 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 311cef9474deb62158b236ba0ab361dda014fe8a..01d2609e8c9debaad11fb35b158e2f90c197818b 100644 (file)
--- 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 2c14b875a788814da4e54e51b13eb725c1cf82ea..5f5e095a9cbe875b5bc96fa4ae97dbe06e863d71 100644 (file)
--- 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])) {