[PATCH] Retrace: Add per frame timing

Anuj Phogat anuj.phogat at gmail.com
Fri Oct 28 17:26:51 PDT 2011


>On Mon, Oct 24, 2011 at 5:44 AM, José Fonseca <jose.r.fonseca at gmail.com>wrote:
>Yes.  I was planning to refactor the last patch that Yuanhan Liu
>posted to this list such that the recording was done in glretrace
>instead of apitrace, but been busy with other stuff.
Here is the patch for cpu/gpu time logging during retracing. Used Yuanhan
Liu's patch as a reference.
This patch logs the cpu and gpu time duration per gl call. cpu time is still
skewed by snappy decompression.
I guess It can be fixed by moving the decompression to a separate thread.

 diff --git a/glretrace.py b/glretrace.py
index e80fedb..3a3fb96 100644
--- a/glretrace.py
+++ b/glretrace.py
@@ -239,9 +239,28 @@ class GlRetracer(Retracer):

         if function.name == 'memcpy':
             print '    if (!dest || !src || !n) return;'
+
+ print '    long long t0, t1;'
+        print '    if (query_index < MAX_QUERIES) {'
+        if function.loggputime:
+           print '        __glGenQueries(1, &gpu_queries[query_index]);'
+           print '        __glBeginQuery(GL_TIME_ELAPSED,
gpu_queries[query_index]);'
+           print '        last_gpu_query = gpu_queries[query_index];'
+        else:
+           print '        gpu_queries[query_index] = 0;'
+        print '        t0 = OS::GetTime();'
+        print '    }'

         Retracer.call_function(self, function)

+ print '    if (query_index < MAX_QUERIES) {'
+ print '        t1 = OS::GetTime();'
+ if function.loggputime:
+    print '        __glEndQuery(GL_TIME_ELAPSED);'
+ print '        cpu_time[query_index] = (double)(t1 - t0) * 1.0E-3;'
+ print '        query_index++;'
+ print '    }'
+
         # Error checking
         if function.name == "glBegin":
             print '    glretrace::insideGlBeginEnd = true;'
@@ -392,7 +411,13 @@ if __name__ == '__main__':
 #include "glretrace.hpp"
 #include "glstate.hpp"

-
+#define MAX_QUERIES  20000
+GLuint gpu_queries[MAX_QUERIES];
+int last_gpu_query = 0;
+int query_index = 0;
+int last_query_index = 0;
+double cpu_time[MAX_QUERIES];
+double gpu_time[MAX_QUERIES];
 '''
     api = glapi.glapi
     retracer = GlRetracer()
diff --git a/glretrace_glx.cpp b/glretrace_glx.cpp
index 8e2e469..df63034 100644
--- a/glretrace_glx.cpp
+++ b/glretrace_glx.cpp
@@ -28,9 +28,12 @@
 #include "retrace.hpp"
 #include "glretrace.hpp"

-
 using namespace glretrace;
-
+extern GLuint gpu_queries[];
+extern int last_gpu_query;
+extern int query_index;
+extern int last_query_index;
+extern double gpu_time[];

 typedef std::map<unsigned long, glws::Drawable *> DrawableMap;
 typedef std::map<unsigned long long, glws::Context *> ContextMap;
@@ -128,6 +131,23 @@ static void retrace_glXSwapBuffers(Trace::Call &call) {
     } else {
         glFlush();
     }
+
+    if (last_gpu_query > 0) {
+        int done = 0;
+        while (!done)
+             __glGetQueryObjectiv(last_gpu_query,
GL_QUERY_RESULT_AVAILABLE, &done);
+       }
+       for (int i = last_query_index;  i < query_index; i++) {
+            GLuint time_gpu;
+            if (gpu_queries[i]) {
+                __glGetQueryObjectuiv(gpu_queries[i], GL_QUERY_RESULT,
&time_gpu);
+                __glDeleteQueries(1, &gpu_queries[i]);
+            } else
+                time_gpu = 0;
+     gpu_time[i] = time_gpu * 1.0E-6;
+       }
+       last_gpu_query = 0;
+       last_query_index = query_index;
 }

 static void retrace_glXCreateNewContext(Trace::Call &call) {
diff --git a/glretrace_main.cpp b/glretrace_main.cpp
index 4e4b8ae..a41e14a 100644
--- a/glretrace_main.cpp
+++ b/glretrace_main.cpp
@@ -32,6 +32,9 @@
 #include "glstate.hpp"
 #include "glretrace.hpp"

+extern double cpu_time[];
+extern double gpu_time[];
+extern int query_index;

 namespace glretrace {

@@ -200,20 +203,19 @@ static void display(void) {
     Trace::Call *call;

     while ((call = parser.parse_call())) {
-        retracer.retrace(*call);
-
-        if (!insideGlBeginEnd &&
+  retracer.retrace(*call);
+
+  if (!insideGlBeginEnd &&
             drawable && context &&
             call->no >= dump_state) {
             glstate::dumpCurrentContext(std::cout);
             exit(0);
         }
-
         delete call;
     }
-
-    // Reached the end of trace
-    glFlush();
+
+   // Reached the end of trace.Before logging endTime, call glFinish() to
complete the execution of all previous gl calls.
+     glFinish();

     long long endTime = OS::GetTime();
     float timeInterval = (endTime - startTime) * 1.0E-6;
@@ -222,16 +224,39 @@ 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 time.log file for timing information\n";
     }
-
-    if (wait) {
+    if (wait)
         while (glws::processEvents()) {}
-    } else {
-        exit(0);
-    }
 }

+static void reparser(void) {
+    Trace::Call *call;
+    FILE *timefile = fopen("time.log", "w+");
+    int i = 0;
+    fprintf(timefile,"Call#\t\t  Function Name\t\tCPU Time\t\t\tGPU
Time\n");
+    while ( ( call = parser.parse_call() ) && ( i <= query_index) ) {
+  if ( !(call->name()[0] == 'g' && call->name()[1] == 'l' &&
call->name()[2] == 'X') &&
+       !(call->name()[2] == 'G' && call->name()[3] == 'e' &&
call->name()[4] == 't')) {
+
+             fprintf(timefile,"%5d\t\t", call->no);
+             fprintf(timefile,"%15s\t\t", call->name());
+             // Minimum cpu time logging can be set appropriately
+      if ( cpu_time[i] > 0.001 || gpu_time[i] )
+                 fprintf(timefile,"cpu time = %4.4f  ms\t\t", cpu_time[i]);
+      if ( gpu_time[i] )
+          fprintf(timefile,"gpu time = %4.4f  ms", gpu_time[i]);
+      fprintf(timefile,"\n");
+             i++;
+  }
+         delete call;
+    }
+    if(timefile != NULL)
+       fclose(timefile);
+
+    exit(0);
+}

 static void usage(void) {
     std::cout <<
@@ -325,11 +350,21 @@ int main(int argc, char **argv)
             std::cerr << "error: failed to open " << argv[i] << "\n";
             return 1;
         }
-
         display();

         parser.close();
     }
+    // Reparsing is required to dump a logfile containing cpu time and gpu
time
+    // for each gl call. As gpu time for a gl call is available only at the
end of
+    // a frame, It's really difficult to write gpu time when parsing for
the first time.
+    // It is an overhead but doesn't effect the cpu or gpu time in anyway.
+    // logging of gpu time can be enabled or disabled by setting a flag in
specs/glapi.py
+    if (!parser.open(argv[1])) {
+        std::cerr << "error: failed to open " << argv[i] << "\n";
+        return 1;
+    }
+    reparser();
+    parser.close();

     delete visual;
     glws::cleanup();
diff --git a/specs/glapi.py b/specs/glapi.py
index 0268479..5566157 100644
--- a/specs/glapi.py
+++ b/specs/glapi.py
@@ -63,9 +63,9 @@ glapi.add_functions([
     GlFunction(Void, "glTexImage1D", [(GLenum, "target"), (GLint, "level"),
(GLenum_int, "internalformat"), (GLsizei, "width"), (GLint, "border"),
(GLenum, "format"), (GLenum, "type"), (Blob(Const(GLvoid),
"__glTexImage1D_size(format, type, width)"), "pixels")]),
     GlFunction(Void, "glTexImage2D", [(GLenum, "target"), (GLint, "level"),
(GLenum_int, "internalformat"), (GLsizei, "width"), (GLsizei, "height"),
(GLint, "border"), (GLenum, "format"), (GLenum, "type"),
(Blob(Const(GLvoid), "__glTexImage2D_size(format, type, width, height)"),
"pixels")]),
     GlFunction(Void, "glDrawBuffer", [(GLenum, "mode")]),
-    GlFunction(Void, "glClear", [(GLbitfield_attrib, "mask")]),
-    GlFunction(Void, "glClearColor", [(GLclampf, "red"), (GLclampf,
"green"), (GLclampf, "blue"), (GLclampf, "alpha")]),
-    GlFunction(Void, "glClearStencil", [(GLint, "s")]),
+    GlFunction(Void, "glClear", [(GLbitfield_attrib,
"mask")],loggputime=True),
+    GlFunction(Void, "glClearColor", [(GLclampf, "red"), (GLclampf,
"green"), (GLclampf, "blue"), (GLclampf, "alpha")],loggputime=True),
+    GlFunction(Void, "glClearStencil", [(GLint, "s")],loggputime=True),
     GlFunction(Void, "glClearDepth", [(GLclampd, "depth")]),
     GlFunction(Void, "glStencilMask", [(GLuint, "mask")]),
     GlFunction(Void, "glColorMask", [(GLboolean, "red"), (GLboolean,
"green"), (GLboolean, "blue"), (GLboolean, "alpha")]),
@@ -82,7 +82,7 @@ glapi.add_functions([
     GlFunction(Void, "glPixelStoref", [(GLenum, "pname"), (GLfloat,
"param")]),
     GlFunction(Void, "glPixelStorei", [(GLenum, "pname"), (GLint,
"param")]),
     GlFunction(Void, "glReadBuffer", [(GLenum, "mode")]),
-    GlFunction(Void, "glReadPixels", [(GLint, "x"), (GLint, "y"), (GLsizei,
"width"), (GLsizei, "height"), (GLenum, "format"), (GLenum, "type"),
Out(GLpointer, "pixels")]),
+    GlFunction(Void, "glReadPixels", [(GLint, "x"), (GLint, "y"), (GLsizei,
"width"), (GLsizei, "height"), (GLenum, "format"), (GLenum, "type"),
Out(GLpointer, "pixels")],loggputime=True),
     GlFunction(Void, "glGetBooleanv", [(GLenum, "pname"),
Out(Array(GLboolean, "__gl_param_size(pname)"), "params")],
sideeffects=False),
     GlFunction(Void, "glGetDoublev", [(GLenum, "pname"),
Out(Array(GLdouble, "__gl_param_size(pname)"), "params")],
sideeffects=False),
     GlFunction(GLenum_error, "glGetError", [], sideeffects=False),
@@ -322,7 +322,7 @@ glapi.add_functions([
     GlFunction(Void, "glPixelMapuiv", [(GLenum, "map"), (GLsizei,
"mapsize"), (Array(Const(GLuint), "mapsize"), "values")]),
     GlFunction(Void, "glPixelMapusv", [(GLenum, "map"), (GLsizei,
"mapsize"), (Array(Const(GLushort), "mapsize"), "values")]),
     GlFunction(Void, "glCopyPixels", [(GLint, "x"), (GLint, "y"), (GLsizei,
"width"), (GLsizei, "height"), (GLenum, "type")]),
-    GlFunction(Void, "glDrawPixels", [(GLsizei, "width"), (GLsizei,
"height"), (GLenum, "format"), (GLenum, "type"), (Blob(Const(GLvoid),
"__glDrawPixels_size(format, type, width, height)"), "pixels")]),
+    GlFunction(Void, "glDrawPixels", [(GLsizei, "width"), (GLsizei,
"height"), (GLenum, "format"), (GLenum, "type"), (Blob(Const(GLvoid),
"__glDrawPixels_size(format, type, width, height)"), "pixels")],
loggputime=True),
     GlFunction(Void, "glGetClipPlane", [(GLenum, "plane"),
Out(Array(GLdouble, 4), "equation")], sideeffects=False),
     GlFunction(Void, "glGetLightfv", [(GLenum, "light"), (GLenum, "pname"),
Out(Array(GLfloat, "__gl_param_size(pname)"), "params")],
sideeffects=False),
     GlFunction(Void, "glGetLightiv", [(GLenum, "light"), (GLenum, "pname"),
Out(Array(GLint, "__gl_param_size(pname)"), "params")], sideeffects=False),
@@ -359,8 +359,8 @@ glapi.add_functions([
     GlFunction(Void, "glTranslatef", [(GLfloat, "x"), (GLfloat, "y"),
(GLfloat, "z")]),

     # GL_VERSION_1_1
-    GlFunction(Void, "glDrawArrays", [(GLenum_mode, "mode"), (GLint,
"first"), (GLsizei, "count")]),
-    GlFunction(Void, "glDrawElements", [(GLenum_mode, "mode"), (GLsizei,
"count"), (GLenum, "type"), (GLpointerConst, "indices")]),
+    GlFunction(Void, "glDrawArrays", [(GLenum_mode, "mode"), (GLint,
"first"), (GLsizei, "count")], loggputime=True),
+    GlFunction(Void, "glDrawElements", [(GLenum_mode, "mode"), (GLsizei,
"count"), (GLenum, "type"), (GLpointerConst, "indices")], loggputime=True),
     GlFunction(Void, "glGetPointerv", [(GLenum, "pname"),
Out(Pointer(GLpointer), "params")], sideeffects=False),
     GlFunction(Void, "glPolygonOffset", [(GLfloat, "factor"), (GLfloat,
"units")]),
     GlFunction(Void, "glCopyTexImage1D", [(GLenum, "target"), (GLint,
"level"), (GLenum, "internalformat"), (GLint, "x"), (GLint, "y"), (GLsizei,
"width"), (GLint, "border")]),
diff --git a/specs/stdapi.py b/specs/stdapi.py
index 0b2fe82..2617813 100644
--- a/specs/stdapi.py
+++ b/specs/stdapi.py
@@ -254,7 +254,7 @@ class Function:
     # 0-3 are reserved to memcpy, malloc, free, and realloc
     __id = 4

-    def __init__(self, type, name, args, call = '', fail = None,
sideeffects=True):
+    def __init__(self, type, name, args, call = '', fail = None,
sideeffects=True, loggputime=False):
         self.id = Function.__id
         Function.__id += 1

@@ -278,6 +278,7 @@ class Function:
         self.call = call
         self.fail = fail
         self.sideeffects = sideeffects
+ self.loggputime = loggputime

     def prototype(self, name=None):
         if name is not None:



>My idea was to have glretrace output the timings to stdout in a TSV format
like:
># call no    function name    cpu start   cpu stop    gpu start    gpu stop
>50 glDrawArrays 1.4  1.5     2.4 2.5
> ...
>The GUI could then use this to produce a joint visualization of both
>cpu and gpu timelines.
As gpu executes the gl commands asynchronously, I didn't find a way to query
the gpu start time.
Is there any way to query the gpu start/stop time per gl call?

I'll appreciate your comments on above patch.

Sample time.log file:
Call#             Function Name         CPU Time
GPU Time
    7              glShadeModel         cpu time = 0.0060  ms
    8              glClearColor            cpu time = 0.0040  ms
    9                   glClear              cpu time = 0.3240  ms
gpu time = 0.0040  ms
   10                 glColor3f             cpu time = 0.0120  ms
   11              glPushMatrix         cpu time = 0.0050  ms
   12                 glRotatef             cpu time = 0.0040  ms
   13                   glBegin             cpu time = 0.0200  ms
   14                glVertex2f            cpu time = 0.0040  ms
   15                glVertex2f
   16                glVertex2f
   17                     glEnd              cpu time = 0.0020  ms
   18               glPopMatrix           cpu time = 16.2530  ms
   21                   glFlush             cpu time = 0.0020  ms
   22                glViewport            cpu time = 0.0030  ms
   23              glMatrixMode         cpu time = 0.0020  ms
   24            glLoadIdentity           cpu time = 0.0020  ms
   25                   glOrtho             cpu time = 0.0030  ms
   27                   glFlush
   28                glViewport
   29              glMatrixMode
   30            glLoadIdentity
   31                   glOrtho
   33              glShadeModel
   34              glClearColor
   35                   glClear             cpu time = 40.7830  ms
 gpu time = 0.1890  ms
   36                 glColor3f            cpu time = 0.0030  ms
   37              glPushMatrix         cpu time = 0.0020  ms
   38                 glRotatef            cpu time = 0.0030  ms


Thanks
Anuj
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://lists.freedesktop.org/archives/apitrace/attachments/20111028/2a81c6ad/attachment-0001.htm>


More information about the apitrace mailing list