trace: record time for a tracepoint

include/osv/trace.hh

@@ -10,6 +10,7 @@
 #include <boost/intrusive/list.hpp>
 #include <string>
 #include <unordered_set>
+#include <drivers/clock.hh>
 
 void enable_trace();
 void enable_tracepoint(std::string wildcard);
@@ -19,6 +20,7 @@ class tracepoint_base;
 struct trace_record {
     tracepoint_base* tp;
     sched::thread* thread;
+    u64 time;
     unsigned cpu;
     union {
         u8 buffer[0];
@@ -268,6 +270,7 @@ public:
             auto tr = allocate_trace_record(size());
             tr->tp = this;
             tr->thread = sched::thread::current();
+            tr->time = clock::get()->time();
             tr->cpu = -1;
             if (tr->thread) {
                 tr->cpu = tr->thread->tcpu()->id;

scripts/loader.py

@@ -444,7 +444,7 @@ def dump_trace():
 
     i = 0
     while i < last:
-        tp_key, thread, cpu = struct.unpack('QQI', trace_log[i:i+20])
+        tp_key, thread, time, cpu = struct.unpack('QQQI', trace_log[i:i+28])
         def trace_function(indent, annotation, data):
             fn, caller = data
             try:
@@ -452,9 +452,11 @@ def dump_trace():
                 fn_name = block.function.print_name
             except:
                 fn_name = '???'
-            gdb.write('0x%016x %2d %s %s %s\n' 
+            gdb.write('0x%016x %2d %12d.%06d %s %s %s\n' 
                       % (thread,
                          cpu,
+                         time / 1000000000,
+                         (time % 1000000000) / 1000,
                          indent,
                          annotation,
                          fn_name,
@@ -464,7 +466,7 @@ def dump_trace():
             continue
         tp = gdb.Value(tp_key).cast(gdb.lookup_type('tracepoint_base').pointer())
         sig = sig_to_string(ulong(tp['sig'])) # FIXME: cache
-        i += 24
+        i += 32
         size = struct.calcsize(sig)
         buffer = trace_log[i:i+size]
         i += size
@@ -484,9 +486,11 @@ def dump_trace():
             format = tp['format'].string()
             format = format.replace('%p', '0x%016x')
             name = tp['name'].string()
-            gdb.write('0x%016x %2d %-20s %s\n'
+            gdb.write('0x%016x %2d %12d.%06d %-20s %s\n'
                       % (thread,
                          cpu,
+                         time / 1000000000,
+                         (time % 1000000000) / 1000,
                          name,
                          format % data,
                          )