Traces syscalls with nsec precision
authorBarret Rhoden <brho@cs.berkeley.edu>
Wed, 10 Sep 2014 03:58:43 +0000 (20:58 -0700)
committerBarret Rhoden <brho@cs.berkeley.edu>
Wed, 10 Sep 2014 03:58:43 +0000 (20:58 -0700)
And also formats the trace for a terminal, with the 'data' contents
appearing on the next line.

Here's a trace of reading the letter 'h' from the console (with one
extra wrap due to the width of this commit message):

----------------------
[     37.776775555]-[     37.776776330] Syscall  13 (  proc_yield):(0x0,
0x0, 0x0, 0x0, 0x0, 0x0) ret: 0x0 proc: 2 core: 0 vcore: 0 data:
[     37.776770403]-[     37.981424392] Syscall 100 (        read):(0x0,
0xffbfdf51, 0x1, 0x0, 0x0, 0x0) ret: 0x1 proc: 2 core: 0 vcore: 0 data:
                                                                   h
----------------------

Note the 'h' on its own after the read command, lined up after the :
after the syscall name.

If there is an empty line in the trace, that is because there was a
trace data length, but printdump didn't print anything.  I noticed this
when the input was a carriage return.

More importantly, notice the timestamps.  The read started first, but
the yield finished first.  First to finish is the first into the trace
queue.

kern/src/syscall.c

index 46c3f41..c0a9a0b 100644 (file)
@@ -71,12 +71,12 @@ static size_t systrace_fill_pretty_buf(struct systrace_record *trace)
        tsc2timespec(trace->end_timestamp, &ts_end);
 
        len = snprintf(trace->pretty_buf, SYSTR_PRETTY_BUF_SZ - len,
-                  "[%7d.%03d]-[%7d.%03d] Syscall %3d (%12s):(0x%x, 0x%x, 0x%x, "
+                  "[%7d.%09d]-[%7d.%09d] Syscall %3d (%12s):(0x%x, 0x%x, 0x%x, "
                   "0x%x, 0x%x, 0x%x) ret: 0x%x proc: %d core: %d vcore: %d data: ",
                   ts_start.tv_sec,
-                  ts_start.tv_nsec / 1000000, /* msec */
+                  ts_start.tv_nsec,
                   ts_end.tv_sec,
-                  ts_end.tv_nsec / 1000000,
+                  ts_end.tv_nsec,
                   trace->syscallno,
                   syscall_table[trace->syscallno].name,
                   trace->arg0,
@@ -89,6 +89,12 @@ static size_t systrace_fill_pretty_buf(struct systrace_record *trace)
                   trace->pid,
                   trace->coreid,
                   trace->vcoreid);
+       /* if we have extra data, print it out on the next line, lined up nicely.
+        * this is only useful for looking at the dump in certain terminals.  if we
+        * have a tool that processes the info, we shouldn't do this. */
+       if (trace->datalen)
+               len += snprintf(trace->pretty_buf + len, SYSTR_PRETTY_BUF_SZ - len,
+                               "\n%67s", "");
        len += printdump(trace->pretty_buf + len,
                         MIN(trace->datalen, SYSTR_PRETTY_BUF_SZ - len - 1),
                         trace->data);