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)
commit11c7cacb654998bb34a84a91084e6cfbbcddc8ec
tree590d5937cd23b230a67cf2fc8e82395f60909364
parentbbf08ef41daa1e321e25c0b172a2839ec99146bf
Traces syscalls with nsec precision

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