[PATCH] cpu/gpu timing
Anuj Phogat
anuj.phogat at gmail.com
Mon Oct 31 21:47:56 PDT 2011
Signed-off-by: Anuj Phogat <anuj.phogat at gmail.com>
---
glretrace.py | 27 +++++++++++++++++++++-
glretrace_glx.cpp | 24 ++++++++++++++++++-
glretrace_main.cpp | 63 ++++++++++++++++++++++++++++++++++++++++-----------
specs/glapi.py | 14 +++++-----
specs/stdapi.py | 3 +-
5 files changed, 106 insertions(+), 25 deletions(-)
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 18192
+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. Call glFinish() to complete the execution of 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:
--
1.7.7
More information about the apitrace
mailing list