trace_printk()
authorBarret Rhoden <brho@cs.berkeley.edu>
Wed, 17 Sep 2014 17:53:52 +0000 (10:53 -0700)
committerBarret Rhoden <brho@cs.berkeley.edu>
Wed, 17 Sep 2014 18:42:25 +0000 (11:42 -0700)
trace_printk() will drop lines of formatted text into the trace buffer,
up to a limited size.

A couple things to note.
- The trace buffer prints syscalls as the complete, not when they start.
  If you have some trace prints from a syscalls execution, they will
  show up before the syscall entry
- If you have a trace print, it will always kmalloc and build the trace.
  We don't have controls (yet) for globally disabling any prints.  I
  didn't bother coupling it to the "trace" monitor commands, opting to
  wait to control it via #K.  Might not even be necessary, since these
  are for debugging.
- If kprof is not attached, the traces aren't saved (or accessible).
- I'd like it if we could use all traces as extra_data blobs, so we just
  pass the pointer to a block in the queue, instead of copying
  everything.  Not a big deal though.

kern/drivers/dev/kprof.c
kern/include/stdio.h
kern/src/syscall.c

index ba92eeb..85f8ae0 100644 (file)
@@ -344,6 +344,7 @@ void kprof_write_sysrecord(char *pretty_buf, size_t len)
 {
        int wrote;
        if (kprof.systrace) {
+               /* TODO: need qio work so we can simply add the buf as extra data */
                wrote = qiwrite(kprof.systrace, pretty_buf, len);
                /* based on the current queue settings, we only drop when we're running
                 * out of memory.  odds are, we won't make it this far. */
@@ -352,6 +353,35 @@ void kprof_write_sysrecord(char *pretty_buf, size_t len)
        }
 }
 
+void trace_printk(const char *fmt, ...)
+{
+       va_list ap;
+       struct timespec ts_now;
+       size_t bufsz = 160;     /* 2x terminal width */
+       size_t len = 0;
+       char *buf = kmalloc(bufsz, 0);
+
+       if (!buf)
+               return;
+       tsc2timespec(read_tsc(), &ts_now);
+       len += snprintf(buf + len, bufsz - len, "[%7d.%09d] /* ", ts_now.tv_sec,
+                       ts_now.tv_nsec);
+       va_start(ap, fmt);
+       len += vsnprintf(buf + len, bufsz - len, fmt, ap);
+       va_start(ap, fmt);
+       va_end(ap);
+       len += snprintf(buf + len, bufsz - len, " */\n");
+       va_start(ap, fmt);
+       /* snprintf null terminates the buffer, and does not count that as part of
+        * the len.  if we maxed out the buffer, let's make sure it has a \n */
+       if (len == bufsz - 1) {
+               assert(buf[bufsz - 1] == '\0');
+               buf[bufsz - 2] = '\n';
+       }
+       kprof_write_sysrecord(buf, len);
+       kfree(buf);
+}
+
 struct dev kprofdevtab __devtab = {
        'K',
        "kprof",
index 87f9c60..2b8fe00 100644 (file)
@@ -59,4 +59,7 @@ void printip(void (*putch)(int, void**), void **putdat, uint8_t *ip);
 void printipmask(void (*putch)(int, void**), void **putdat, uint8_t *ip);
 void printipv4(void (*putch)(int, void**), void **putdat, uint8_t *ip);
 
+/* #K */
+void trace_printk(const char *fmt, ...);
+
 #endif /* !ROS_INC_STDIO_H */
index c0a9a0b..6cf286a 100644 (file)
@@ -66,7 +66,7 @@ static size_t systrace_fill_pretty_buf(struct systrace_record *trace)
 {
        size_t len = 0;
        struct timespec ts_start;
-       struct timespec ts_end;;
+       struct timespec ts_end;
        tsc2timespec(trace->start_timestamp, &ts_start);
        tsc2timespec(trace->end_timestamp, &ts_end);