Syscall tracing formatting touchups
authorBarret Rhoden <brho@cs.berkeley.edu>
Wed, 3 Sep 2014 05:06:36 +0000 (22:06 -0700)
committerBarret Rhoden <brho@cs.berkeley.edu>
Wed, 3 Sep 2014 05:06:36 +0000 (22:06 -0700)
The main thing is that we print the real time (since boot) in seconds,
instead of TSC ticks.

As a reminder to anyone using c89, the TSC only resets on a cold boot.
Perhaps that has something to do with its service processor locking up
every so often!  (we'll see if it is every 49 days)

kern/include/time.h
kern/src/syscall.c
kern/src/time.c

index eff60cb..aa03136 100644 (file)
@@ -34,6 +34,7 @@ uint64_t msec2tsc(uint64_t msec);
 uint64_t usec2tsc(uint64_t usec);
 uint64_t nsec2tsc(uint64_t nsec);
 uint64_t epoch_seconds(void);
+void tsc2timespec(uint64_t tsc_time, struct timespec *ts);
 
 /* Just takes a time measurement.  Meant to be paired with stop_timing.  Use
  * this if you don't want to muck with overheads or subtraction. */
index fce4e51..46c3f41 100644 (file)
@@ -65,11 +65,18 @@ static bool __trace_this_proc(struct proc *p)
 static size_t systrace_fill_pretty_buf(struct systrace_record *trace)
 {
        size_t len = 0;
+       struct timespec ts_start;
+       struct timespec ts_end;;
+       tsc2timespec(trace->start_timestamp, &ts_start);
+       tsc2timespec(trace->end_timestamp, &ts_end);
+
        len = snprintf(trace->pretty_buf, SYSTR_PRETTY_BUF_SZ - len,
-                  "[%16llu] [%16lu] Syscall %3d (%12s):(0x%x, 0x%x, 0x%x, 0x%x, "
-                  "0x%x, 0x%x) ret: %p proc: %d core: %d vcore: %d data: ",
-                  trace->start_timestamp,
-                  trace->end_timestamp,
+                  "[%7d.%03d]-[%7d.%03d] 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_end.tv_sec,
+                  ts_end.tv_nsec / 1000000,
                   trace->syscallno,
                   syscall_table[trace->syscallno].name,
                   trace->arg0,
index 3179b80..39955f3 100644 (file)
@@ -139,3 +139,11 @@ uint64_t epoch_seconds(void)
        uint64_t boot_sec = 1242129600; /* nanwan's birthday */
        return tsc2sec(read_tsc()) + boot_sec;
 }
+
+void tsc2timespec(uint64_t tsc_time, struct timespec *ts)
+{
+       ts->tv_sec = tsc2sec(tsc_time);
+       /* subtract off everything but the remainder */
+       tsc_time -= sec2tsc(ts->tv_sec);
+       ts->tv_nsec = tsc2nsec(tsc_time);
+}