[PATCH] Retrace: Add per frame timing

[Anuj Phogat]

Hi All,

         Here is a simple patch to add per frame timing information while
retracing. Tested this patch with couple of simple applications. It seems to
work fine.
This will provide useful information to identify performance issues with a
specific frame. Currently, this patch creates a new file (frame.time) to
dump the per frame timings.
But the ideal way would be to integrate this information with apitrace UI. I
would try to understand the UI code and integrate this new feature.

diff --git a/glretrace_main.cpp b/glretrace_main.cpp
index 4e4b8ae..5dab825 100644
--- a/glretrace_main.cpp
+++ b/glretrace_main.cpp
@@ -197,22 +197,31 @@ static void display(void) {
     retracer.addCallbacks(cgl_callbacks);

     startTime = OS::GetTime();
+    FILE *timefile = fopen("frame.time", "w+");
+    long long framestartTime = startTime;
     Trace::Call *call;

     while ((call = parser.parse_call())) {
-        retracer.retrace(*call);
-
-        if (!insideGlBeginEnd &&
+       retracer.retrace(*call);
+
+        if (!strcmp(call->name(),"glXSwapBuffers")){
+            static unsigned int frame_count = 0;
+            long long frameendTime = OS::GetTime();
+            float frametimeInterval = (frameendTime - framestartTime) *
1.0E-3;
+            framestartTime =  frameendTime;
+           if (timefile != NULL)
+                fprintf(timefile,"Frame # %4d \t\t Rendering Time =   %4.4f
 ms \n", ++frame_count, frametimeInterval);
+           }
+
+       if (!insideGlBeginEnd &&
             drawable && context &&
             call->no >= dump_state) {
             glstate::dumpCurrentContext(std::cout);
             exit(0);
         }
-
         delete call;
     }
-
-    // Reached the end of trace
+   // Reached the end of trace
     glFlush();

     long long endTime = OS::GetTime();
@@ -222,9 +231,13 @@ static void display(void) {
         std::cout <<
             "Rendered " << frame << " frames"
             " in " <<  timeInterval << " secs,"
-            " average of " << (frame/timeInterval) << " fps\n";
+            " average of " << (frame/timeInterval) << " fps\n"
+           "Refer to frame.time file for per frame timings\n";
     }

+    if(timefile != NULL)
+       fclose(timefile);
+
     if (wait) {
         while (glws::processEvents()) {}
     } else {



Sample frame.time file:

Frame #    1             Rendering Time =   86.8040  ms
Frame #    2             Rendering Time =   52.9150  ms
Frame #    3             Rendering Time =   13.1800  ms
Frame #    4             Rendering Time =   13.5760  ms
Frame #    5             Rendering Time =   16.5770  ms
Frame #    6             Rendering Time =   16.7020  ms
Frame #    7             Rendering Time =   16.4650  ms
Frame #    8             Rendering Time =   17.0980  ms
Frame #    9             Rendering Time =   16.6430  ms
Frame #   10             Rendering Time =   16.6400  ms
Frame #   11             Rendering Time =   16.3250  ms
Frame #   12             Rendering Time =   16.9020  ms
Frame #   13             Rendering Time =   16.7450  ms
Frame #   14             Rendering Time =   16.5160  ms
Frame #   15             Rendering Time =   16.2400  ms
Frame #   16             Rendering Time =   16.9940  ms
Frame #   17             Rendering Time =   16.1750  ms
Frame #   18             Rendering Time =   16.9450  ms
Frame #   19             Rendering Time =   16.7750  ms
Frame #   20             Rendering Time =   16.5170  ms
Frame #   21             Rendering Time =   16.4950  ms
Frame #   22             Rendering Time =   16.4520  ms
Frame #   23             Rendering Time =   16.9910  ms
Frame #   24             Rendering Time =   16.2530  ms
Frame #   25             Rendering Time =   16.6570  ms
Frame #   26             Rendering Time =   16.9600  ms
Frame #   27             Rendering Time =   16.3200  ms
Frame #   28             Rendering Time =   17.0080  ms
Frame #   29             Rendering Time =   16.1800  ms
Frame #   30             Rendering Time =   16.6230  ms
Frame #   31             Rendering Time =   17.1000  ms
Frame #   32             Rendering Time =   16.5390  ms
Frame #   33             Rendering Time =   16.3890  ms
Frame #   34             Rendering Time =   16.8460  ms
Frame #   35             Rendering Time =   16.7060  ms
Frame #   36             Rendering Time =   16.1800  ms
Frame #   37             Rendering Time =   17.0210  ms
Frame #   38             Rendering Time =   16.5970  ms
Frame #   39             Rendering Time =   16.6590  ms
Frame #   40             Rendering Time =   16.6490  ms
Frame #   41             Rendering Time =   16.6930  ms
Frame #   42             Rendering Time =   16.6110  ms
Frame #   43             Rendering Time =   16.5880  ms
Frame #   44             Rendering Time =   16.6480  ms
Frame #   45             Rendering Time =   16.5620  ms
Frame #   46             Rendering Time =   16.5230  ms
Frame #   47             Rendering Time =   16.7410  ms
Frame #   48             Rendering Time =   16.6920  ms
Frame #   49             Rendering Time =   16.5250  ms
Frame #   50             Rendering Time =   16.6510  ms


Regards
Anuj
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://lists.freedesktop.org/archives/apitrace/attachments/20111021/ea58cafc/attachment.html>