[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