trace: measure time for each gallium call

To get a rough idea of how much time is spent in each gallium driver
function.  The time is measured in microseconds.

3 files changed, 38 insertions, 2 deletions

diff --git a/src/gallium/drivers/trace/tr_dump.c b/src/gallium/drivers/trace/tr_dump.c
index cd106af9cda..48c8914f7bb 100644
--- a/src/gallium/drivers/trace/tr_dump.c
+++ b/src/gallium/drivers/trace/tr_dump.c
@@ -45,6 +45,7 @@
 
 #include "pipe/p_compiler.h"
 #include "os/os_thread.h"
+#include "os/os_time.h"
 #include "util/u_debug.h"
 #include "util/u_memory.h"
 #include "util/u_string.h"
@@ -234,6 +235,20 @@ trace_dump_trace_close(void)
    }
 }
 
+
+static void
+trace_dump_call_time(int64_t time)
+{
+   if (stream) {
+      trace_dump_indent(2);
+      trace_dump_tag_begin("time");
+      trace_dump_int(time);
+      trace_dump_tag_end("time");
+      trace_dump_newline();
+   }
+}
+
+
 boolean
 trace_dump_trace_begin(void)
 {
@@ -345,6 +360,8 @@ boolean trace_dumping_enabled(void)
  * Dump functions
  */
 
+static int64_t call_start_time = 0;
+
 void trace_dump_call_begin_locked(const char *klass, const char *method)
 {
    if (!dumping)
@@ -360,13 +377,20 @@ void trace_dump_call_begin_locked(const char *klass, const char *method)
    trace_dump_escape(method);
    trace_dump_writes("\'>");
    trace_dump_newline();
+
+   call_start_time = os_time_get();
 }
 
 void trace_dump_call_end_locked(void)
 {
+   int64_t call_end_time;
+
    if (!dumping)
       return;
 
+   call_end_time = os_time_get();
+
+   trace_dump_call_time(call_end_time - call_start_time);
    trace_dump_indent(1);
    trace_dump_tag_end("call");
    trace_dump_newline();
diff --git a/src/gallium/tools/trace/model.py b/src/gallium/tools/trace/model.py
index 9f2d5bc7e9d..8276a8f9c61 100755
--- a/src/gallium/tools/trace/model.py
+++ b/src/gallium/tools/trace/model.py
@@ -101,12 +101,13 @@ class Pointer(Node):
 
 class Call:
     
-    def __init__(self, no, klass, method, args, ret):
+    def __init__(self, no, klass, method, args, ret, time):
         self.no = no
         self.klass = klass
         self.method = method
         self.args = args
         self.ret = ret
+        self.time = time
         
     def visit(self, visitor):
         visitor.visit_call(self)
@@ -210,6 +211,8 @@ class PrettyPrinter:
         if node.ret is not None:
             self.formatter.text(' = ')
             node.ret.visit(self)
+        self.formatter.text(' // time ')
+        node.time.visit(self)
 
     def visit_trace(self, node):
         for call in node.calls:
diff --git a/src/gallium/tools/trace/parse.py b/src/gallium/tools/trace/parse.py
index feb0b64e231..07f2d6c7659 100755
--- a/src/gallium/tools/trace/parse.py
+++ b/src/gallium/tools/trace/parse.py
@@ -215,6 +215,7 @@ class TraceParser(XmlParser):
         method = attrs['method']
         args = []
         ret = None
+        time = 0
         while self.token.type == ELEMENT_START:
             if self.token.name_or_data == 'arg':
                 arg = self.parse_arg()
@@ -224,11 +225,13 @@ class TraceParser(XmlParser):
             elif self.token.name_or_data == 'call':
                 # ignore nested function calls
                 self.parse_call()
+            elif self.token.name_or_data == 'time':
+                time = self.parse_time()
             else:
                 raise TokenMismatch("<arg ...> or <ret ...>", self.token)
         self.element_end('call')
         
-        return Call(no, klass, method, args, ret)
+        return Call(no, klass, method, args, ret, time)
 
     def parse_arg(self):
         attrs = self.element_start('arg')
@@ -245,6 +248,12 @@ class TraceParser(XmlParser):
 
         return value
 
+    def parse_time(self):
+        attrs = self.element_start('time')
+        time = self.parse_value();
+        self.element_end('time')
+        return time
+
     def parse_value(self):
         expected_tokens = ('null', 'bool', 'int', 'uint', 'float', 'string', 'enum', 'array', 'struct', 'ptr', 'bytes')
         if self.token.type == ELEMENT_START: