Cleaned up trace profiler output.

Updated profileshader.py to reflect these changes.

diff --git a/common/trace_profiler.cpp b/common/trace_profiler.cpp
index 6fc00395cd1d3de808d8ae999f05f9540f10a86a..02d88dcbc2d167219bca63a6f9a193b1020ed4e8 100644 (file)
--- a/common/trace_profiler.cpp
+++ b/common/trace_profiler.cpp
@@ -28,8 +28,7 @@
 
 namespace trace {
 Profiler::Profiler()
-    : lastProgram(0),
-      baseGpuTime(0),
+    : baseGpuTime(0),
       baseCpuTime(0),
       cpuTimes(false),
       gpuTimes(true),
@@ -47,10 +46,9 @@ void Profiler::setup(bool cpuTimes_, bool gpuTimes_, bool pixelsDrawn_)
     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;
+    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 program name" << std::endl;
 }
 
 void Profiler::addCall(unsigned no,
@@ -60,96 +58,101 @@ void Profiler::addCall(unsigned no,
                        uint64_t gpuStart, uint64_t gpuDuration,
                        uint64_t cpuStart, uint64_t cpuDuration)
 {
-    if (baseGpuTime == 0)
+    if (baseGpuTime == 0) {
         baseGpuTime = gpuStart;
+    }
 
-    if (baseCpuTime == 0)
+    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;
+        gpuStart -= baseGpuTime;
     } else {
-        std::cout << " _ _";
+        gpuStart = 0;
+        gpuDuration = 0;
     }
 
     if (cpuTimes) {
-        std::cout << " "
-                  << (cpuStart - baseCpuTime) << " "
-                  << cpuDuration;
+        cpuStart -= baseCpuTime;
     } else {
-        std::cout << " _ _";
+        cpuStart = 0;
+        cpuDuration = 0;
     }
 
-    if (pixelsDrawn) {
-        std::cout << " " << pixels;
-    } else {
-        std::cout << " _";
+    if (!pixelsDrawn) {
+        pixels = 0;
     }
 
-    std::cout << " " << name << std::endl;
+    std::cout << "call"
+              << " " << no
+              << " " << gpuStart
+              << " " << gpuDuration
+              << " " << cpuStart
+              << " " << cpuDuration
+              << " " << pixels
+              << " " << program
+              << " " << name
+              << std::endl;
 }
 
 void Profiler::addFrameStart(unsigned no, uint64_t gpuStart, uint64_t cpuStart)
 {
-    if (baseGpuTime == 0)
+    if (baseGpuTime == 0) {
         baseGpuTime = gpuStart;
+    }
 
-    if (baseCpuTime == 0)
+    if (baseCpuTime == 0) {
         baseCpuTime = cpuStart;
-
-    lastFrame.no = no;
-    lastFrame.gpuStart = gpuStart - baseGpuTime;
-
-    std::cout << "frame begin " << lastFrame.no;
+    }
 
     if (gpuTimes) {
-        std::cout << " " << lastFrame.gpuStart;
+        lastFrame.gpuStart = gpuStart - baseGpuTime;
     } else {
-        std::cout << " _";
+        lastFrame.gpuStart = 0;
     }
 
-    if (gpuTimes) {
-        std::cout << " " << lastFrame.cpuStart;
+    if (cpuTimes) {
+        lastFrame.cpuStart = cpuStart - baseCpuTime;
     } else {
-        std::cout << " _";
+        lastFrame.cpuStart = 0;
     }
 
-    std::cout << std::endl;
+    lastFrame.no = no;
+
+    std::cout << "frame_begin"
+              << " " << lastFrame.no
+              << " " << lastFrame.gpuStart
+              << " " << lastFrame.cpuStart
+              << std::endl;
 }
 
 void Profiler::addFrameEnd(uint64_t gpuEnd, uint64_t cpuEnd)
 {
-    if (baseGpuTime == 0)
-        baseGpuTime = gpuEnd;
-
-    if (baseCpuTime == 0)
-        baseCpuTime = cpuEnd;
-
-    lastFrame.gpuEnd = gpuEnd - baseGpuTime;
-
-    std::cout << "frame end " << lastFrame.no;
+    uint64_t gpuDuration, cpuDuration;
 
     if (gpuTimes) {
-        std::cout << " " << lastFrame.gpuEnd << " " << (lastFrame.gpuEnd - lastFrame.gpuStart);
+        gpuEnd -= baseGpuTime;
+        gpuDuration = gpuEnd - lastFrame.gpuStart;
     } else {
-        std::cout << " _ _";
+        gpuEnd = 0;
+        gpuDuration = 0;
     }
 
     if (cpuTimes) {
-        std::cout << " " << lastFrame.cpuEnd << " " << (lastFrame.cpuEnd - lastFrame.cpuStart);
+        cpuEnd -= baseCpuTime;
+        cpuDuration = cpuEnd - lastFrame.cpuStart;
     } else {
-        std::cout << " _ _";
+        cpuEnd = 0;
+        cpuDuration = 0;
     }
 
-    std::cout << std::endl;
+    std::cout << "frame_end"
+              << " " << lastFrame.no
+              << " " << gpuEnd
+              << " " << gpuDuration
+              << " " << cpuEnd
+              << " " << cpuDuration
+              << std::endl;
 }
 }

diff --git a/common/trace_profiler.hpp b/common/trace_profiler.hpp
index da60d72e532d210ada7a75bbf318a6aa8bebcf6a..c36fd77f6e0bf491dbd880f148343405faed3197 100644 (file)
--- a/common/trace_profiler.hpp
+++ b/common/trace_profiler.hpp
@@ -50,7 +50,6 @@ public:
                  uint64_t cpuStart, uint64_t cpuDuration);
 
 private:
-    unsigned lastProgram;
     uint64_t baseGpuTime;
     uint64_t baseCpuTime;
 
@@ -61,9 +60,7 @@ private:
     struct {
         unsigned no;
         uint64_t gpuStart;
-        uint64_t gpuEnd;
         uint64_t cpuStart;
-        uint64_t cpuEnd;
     } lastFrame;
 };
 }

diff --git a/scripts/profileshader.py b/scripts/profileshader.py
index 6d693f4d51a00c602682d64710f84c6b8237d167..3cfa850deeb139bddc5929322778adb03b185373 100755 (executable)
--- a/scripts/profileshader.py
+++ b/scripts/profileshader.py
@@ -30,8 +30,11 @@ if len(sys.argv) <= 1:
        print 'Please specify a file to read'
        sys.exit()
 
-shaderTimes = {}
-activeShader = 0
+times = {}
+
+# frame_begin no gpu_start cpu_start
+# frame_end no gpu_end gpu_dura cpu_end cpu_dura
+# call no gpu_start gpu_dura cpu_start cpu_dura pixels program name
 
 for line in open(sys.argv[1], 'r'):
     words = line.split(' ')
@@ -39,29 +42,29 @@ for line in open(sys.argv[1], 'r'):
     if line.startswith('#'):
         continue
 
-    if words[0:3] == ['use','shader','program']:
-        activeShader = long(words[3])
-    elif words[0] == 'call':
+    if words[0] == 'call':
         id = long(words[1])
-        func = words[-1]
         duration = long(words[3])
+        shader = long(words[7])
+        func = words[8]
+
+        if times.has_key(shader):
+            times[shader]['draws'] += 1
+            times[shader]['duration'] += duration
 
-        if shaderTimes.has_key(activeShader):
-            shaderTimes[activeShader]['draws'] += 1
-            shaderTimes[activeShader]['duration'] += duration
-            if duration > shaderTimes[activeShader]['longestDuration']:
-                shaderTimes[activeShader]['longest'] = id
-                shaderTimes[activeShader]['longestDuration'] = duration
+            if duration > times[shader]['longestDuration']:
+                times[shader]['longest'] = id
+                times[shader]['longestDuration'] = duration
         else:
-            shaderTimes[activeShader] = {'draws': 1, 'duration': duration, 'longest': id, 'longestDuration': duration}
+            times[shader] = {'draws': 1, 'duration': duration, 'longest': id, 'longestDuration': duration}
 
-sortedShaderTimes = sorted(shaderTimes.items(), key=lambda x: x[1]['duration'], reverse=True)
+times = sorted(times.items(), key=lambda x: x[1]['duration'], reverse=True)
 
 print '+------------+--------------+--------------------+--------------+-------------+'
 print '| Shader[id] |   Draws [#]  |   Duration [ns]  v | Per Call[ns] | Longest[id] |'
 print '+------------+--------------+--------------------+--------------+-------------+'
 
-for shader in sortedShaderTimes:
+for shader in times:
     id = str(shader[0]).rjust(10)
     draw = str(shader[1]['draws']).rjust(12)
     dura = str(shader[1]['duration']).rjust(18)