TTRACE timed trace kernel profiler.
authorGodfrey van der Linden <gvdl@google.com>
Thu, 12 Feb 2015 23:30:26 +0000 (15:30 -0800)
committerBarret Rhoden <brho@cs.berkeley.edu>
Tue, 21 Apr 2015 16:08:44 +0000 (12:08 -0400)
Initial ttrace development, checkpoint commit.

Kconfig
kern/drivers/dev/devttrace.c
kern/include/ros/ttrace.h
kern/include/trace.h
kern/include/ttrace.h [new file with mode: 0644]
kern/src/Kbuild
kern/src/init.c
kern/src/ttrace.c [new file with mode: 0644]

diff --git a/Kconfig b/Kconfig
index b37e18d..fb30c90 100644 (file)
--- a/Kconfig
+++ b/Kconfig
@@ -131,14 +131,6 @@ config TTRACE
                (meaning it'll clobber older events).  Always enables scheduling timed
                tracing.
 
-config TTRACE_SEMAPHORES
-       bool "Timed Trace Semaphores"
-       depends on TTRACE
-       default n
-       help
-               Turn on timestamp based thread tracing recording a timestamp, a
-               semaphore up/down event type thread_id(gvdl?) in the TTRACE buffer.
-
 config TTRACE_CV
        bool "Timed Trace Condition Vars"
        depends on TTRACE
@@ -148,14 +140,30 @@ config TTRACE_CV
                condition waits and signals and underlying semaphore up/down event
                types thread_id(gvdl?) in the TTRACE buffer.
 
+config TTRACE_PROCESS
+       bool "Timed Trace Process spawn, exec and death"
+       depends on TTRACE
+       default n
+       help
+               Turn on timestamp based processtracing recording the timestamp,
+               of interesting process related events such as proc creation,
+                destruction and execing.
+
 config TTRACE_RWLOCK
        bool "Timed Trace Readers/Writers locking"
        depends on TTRACE
        default n
        help
-               Turn on timestamp based thread tracing recording the timestamp,
-               reader/writer lock type, thread_id, number of readers waiting, number
-               of writes waiting.
+               Turn on timestamp based tracing recording timestamp and other
+                data for reader/writer lock interactions.
+
+config TTRACE_SEMAPHORES
+       bool "Timed Trace Semaphores"
+       depends on TTRACE
+       default n
+       help
+               Turn on timestamp based thread tracing recording a timestamp, a
+               semaphore up/down event type thread_id(gvdl?) in the TTRACE buffer.
 
 endmenu
 
index 067282f..7ea62bd 100644 (file)
@@ -7,9 +7,9 @@
  * in the LICENSE file.
  */
 
-//
-// This file implements the #T device and was based upon the UCB Plan 9 kprof.c
-//
+/*
+ * This file implements the #T device and was based upon the UCB Plan 9 kprof.c
+ */
 
 #include <assert.h>
 #include <atomic.h>
 #include <smp.h>
 #include <stdio.h>
 #include <string.h>
-#include <syscall.h>
+#include <trace.h>
+#include <ttrace.h>
 #include <umem.h>
 
 #include <ros/fs.h>
-#include <ros/ttrace.h>
-
-#warning Remove this scaffold when ttrace profiling is going
-uint64_t ttrace_type_mask;
 
 /*
  * ttrace macros and constant data
@@ -41,10 +38,10 @@ uint64_t ttrace_type_mask;
 #define TTRACE_NUM_OPENERS 8
 #define TT_SAFE_GENBUF_SZ  (GENBUF_SZ-1)  // Leave room for newline
 
-// TODO(gvdl): I don't get plan 9's permissions, why do directories get group
-// rx permissions, and what's with the DMDIR. Some devices use it and others
-// don't. In theory the DMDIR is copied over by a higher layer but I have no
-// idea why two copies seems necessary.
+/* TODO(gvdl): I don't get plan 9's permissions, why do directories get group
+ * rx permissions, and what's with the DMDIR. Some devices use it and others
+ * don't. In theory the DMDIR is copied over by a higher layer but I have no
+ * idea why two copies seems necessary. */
 #define TTPERMDIR    (S_IRUSR|S_IXUSR|S_IRGRP|S_IXGRP|DMDIR)
 #define TTPERMRWFILE (S_IRUSR|S_IWUSR)
 #define TTPERMROFILE (S_IRUSR)
@@ -53,7 +50,7 @@ enum {
        Ttdevdirqid = 0,
        Ttdevbase,
        Ttdevctlqid = Ttdevbase,        // 1
-       Ttdevdataqid,                           // 2
+       Ttdevauxqid,                            // 2
        Ttdevcpudataqid,                        // 3
 
        Logtype = 4,  // Enough for 16 unique qids types
@@ -64,8 +61,8 @@ enum {
        Maskcpu = (1 << Logcpu) - 1,
        Shiftcpu = Shifttype + Logtype,
 
-       // ttrace timestamp id, used by data file readers
-       Logtsid = 13 + 3, // 4096 ttrace/cpus + a ttrace/data file by 8 opened
+       /* ttrace timestamp id, used by data file readers */
+       Logtsid = 12 + 3, // 4096 cpus by 8 simultaneous opened
        Masktsid = (1 << Logtsid) - 1,
        Shifttsid = Shiftcpu + Logcpu,
 };
@@ -77,34 +74,42 @@ enum {
 #define TTTSIDQID(q, i)        ( ((i) << Shifttsid) | (q).path )
 
 /*
- * ttrace static data
+ * ttrace timestamp pool and accessor
  */
 static uintptr_t *ttdevtimestamp;              // array of open file timestamps
-static struct u16_pool *ttdevtspool;           // pool of timestamp indices
-
-//
-// ttrace device gen implementation
-//
-// #T directory layout
-// [-1]        {".",      {Ttdevdirqid, 0, QTDIR},    0, TTPERMDIR},
-// [0..ncpu-1] {"cpunnn", {Ttdevcpudataqid|core_id},  0, TTPERMRWFILE},
-// [ncpu]      {"ctl",    {Ttdevctlqid}, TTRACE_CTL_LEN, TTPERMRWFILE},
-// [ncpu+1]    {"data",   {Ttdevdataqid},             0, TTPERMRWFILE},
-
-// Generate qids for the top level directory
+static struct u16_pool *ttdevtspool;   // pool of timestamp indices
+static inline int get_tsid(void) {
+       return (ttdevtspool)? get_u16(ttdevtspool) : -1;
+}
+static inline put_tsid(int tsid) {
+       dassert(tsid >= 1 && ttdevtspool);
+       put_u16(ttdevtspool, tsid);
+}
+
+/*
+ * ttrace device gen implementation
+ *
+ * #T directory layout
+ * [-1]        {".",      {Ttdevdirqid, 0, QTDIR},    0, TTPERMDIR},
+ * [0..ncpu-1] {"cpunnn", {Ttdevcpudataqid|coreid},   0, TTPERMRWFILE},
+ * [ncpu]      {"ctl",    {Ttdevctlqid}, TTRACE_CTL_LEN, TTPERMROFILE},
+ * [ncpu+1]    {"aux",    {Ttdevauxqid},              0, TTPERMRWFILE},
+ */
+
+/* Generate qids for the top level directory */
 static inline int ttdev1gen(const struct chan *c, int s, struct qid *qp)
 {
        int ret = 1;
        int path = -1;
-       // Must only be called to decode top level dir channel
+       /* Must only be called to decode top level dir channel */
        dassert(TTYPE(c->qid) == Ttdevdirqid);
 
        if (s < num_cpus) // "cpunnn" data files
                path = TTCPUQID(s, Ttdevcpudataqid);
        else {
                switch (s - num_cpus) {
-               case 0:  path = Ttdevctlqid;  break; // "ctl"
-               case 1:  path = Ttdevdataqid; break; // "data"
+               case 0:  path = Ttdevctlqid; break;             // "ctl"
+               case 1:  path = Ttdevauxqid; break;             // "aux"
                default: return -1;
                }
        }
@@ -130,9 +135,10 @@ static int ttdevgen(struct chan *c, char *unused_name,
                return -1;
 
        const char *name = NULL;
+       long perm = TTPERMRWFILE;
        switch (TTYPE(q)) {
-       case Ttdevctlqid:  name = "ctl";  break;
-       case Ttdevdataqid: name = "data"; break;
+       case Ttdevctlqid: name = "ctl"; break;
+       case Ttdevauxqid: name = "aux"; perm = TTPERMROFILE; break;
        case Ttdevcpudataqid:
                snprintf(get_cur_genbuf(), GENBUF_SZ, "cpu%03d", TTCPU(q));
                name = get_cur_genbuf();
@@ -144,7 +150,7 @@ static int ttdevgen(struct chan *c, char *unused_name,
                panic("devttrace: What happened to ttdev1gen decode?\n");
        }
        dassert(name);
-       devdir(c, q, (char *) name, 0, eve, TTPERMRWFILE, dp);
+       devdir(c, q, (char *) name, 0, eve, perm, dp);
        return 1;
 }
 
@@ -160,6 +166,7 @@ static size_t ttdevcopyout(char *va, long n, size_t offset,
        if (!current)
                memcpy(&va[offset], buf, len);
        else if (ESUCCESS != memcpy_to_user(current, &va[offset], buf, len)) {
+               /* UMEM */
                // TODO(gvdl): No p9 equivalent to EFAULT, determine causes of failure.
                error(Enovmem);
        }
@@ -167,124 +174,72 @@ static size_t ttdevcopyout(char *va, long n, size_t offset,
        return len;
 }
 
-static inline int ttdevputchar(char *buf, int len, char c)
-{
-       dassert(len >= 1);
-       *buf = c;
-       return 1;
-}
-
-static inline int ttdevputhex8(char* buf, int len, uint8_t x)
-{
-       static const char hex_digits[] = "0123456789abcdef";
-       int c = 0;
-       c += ttdevputchar(&buf[c], len-c, hex_digits[x >> 4]);
-       c += ttdevputchar(&buf[c], len-c, hex_digits[x & 0xf]);
-       return c;
-}
-
-static inline int ttdevputhex16(char *buf, int len, uint16_t x)
-{
-       int c = ttdevputhex8(&buf[0], len, x >> 8);
-       ttdevputhex8(&buf[c], len-c, (uint8_t) x);
-       return sizeof(uint16_t) * 2;
-}
-
-static int ttdevputhex32(char *buf, int len, uint32_t x)
-{
-       int c = ttdevputhex16(&buf[0], len, x >> 16);
-       ttdevputhex16(&buf[c], len-c, (uint16_t) x);
-       return sizeof(uint32_t) * 2;
-}
-
-static int ttdevputhex64(char *buf, int len, uint64_t x)
-{
-       int c = ttdevputhex32(&buf[0], len, x >> 32);
-       ttdevputhex32(&buf[c], len-c, (uint32_t) x);
-       return sizeof(uint64_t) * 2;
-}
+/* Context for trace_ring_foreach call of ttdevread_cpu_entry() */
+#define TTRACE_ENTRY_QUADS (sizeof(struct ttrace_entry) / sizeof(uint64_t))
+/* #quads * (whitespace + len(hex(quad))) */
+#define CTXT_GENBUF_SZ     (TTRACE_ENTRY_QUADS * (1 + 2 * sizeof(uint64_t)))
+
+struct ttdevread_cpu_ctxt {
+       int64_t c;
+       uintptr_t min_timestamp;
+       char *va;
+       long n;
+       char genbuf[CTXT_GENBUF_SZ];
+};
 
-static inline int ttdevputmem(char *buf, int len, const void *mem, int mem_len)
+static inline int ttdevhexdigit(uint8_t x)
 {
-       dassert(mem_len <= len);
-       memcpy(buf, mem, mem_len);
-       return mem_len;
+       return "0123456789abcdef"[x];
 }
 
-static int ttdevputhdr(char *buf, int len,
-                                          uint8_t rec_len, uint8_t tag, uintptr_t timestamp)
+static void ttdevread_cpu_entry(void *ventry, void *vctxt)
 {
-       int c = 0;
-       c += ttdevputhex8(&buf[c], len-c, rec_len);
-       c += ttdevputhex8(&buf[c], len-c, tag);
-       c += ttdevputhex64(&buf[c], len-c, timestamp);
-       return c;
-}
+       struct ttdevread_cpu_ctxt *ctxt = (struct ttdevread_cpu_ctxt *) vctxt;
+       /* A cache line aligned copy of the input entry, should make partial entrys
+        * less likely. Still an entry is bracketted with timestamp == -1 */
+       uint8_t buf[2 * sizeof(struct ttrace_entry)];  // 128 byte buffer
+       const uintptr_t size_mask = sizeof(struct ttrace_entry) - 1;
+       struct ttrace_entry* entry = (struct ttrace_entry *)
+               (((uintptr_t) buf + size_mask) & ~size_mask); // align to cache line
+       *entry = *((struct ttrace_entry *) ventry);  // Grab the entry
+
+       /* If time stamp == -1 (i.e. entry is a partial) or is less than
+        * the minimum then ignore this entry */
+       if (!(entry->timestamp + 1) || entry->timestamp < ctxt->min_timestamp)
+               return;
 
-static size_t ttdev_readnamerec(void *va, long n, uint8_t tag,
-                                                               uintptr_t timestamp, uint64_t id,
-                                                               const char *name)
-{
-       const int len = TT_SAFE_GENBUF_SZ; // Always leave room for newline
-       char * const buffer = get_cur_genbuf();
-       int remaining = strlen(name);
-       size_t out_len = 0;
-
-       /* Output first header */
-       int nc = min(len - TTRACEH_NAME_LEN, remaining);
-       int rec_len = TTRACEH_NAME_LEN + nc; dassert(rec_len <= len);
-       int c = 0;
-       c += ttdevputhdr(&buffer[c], len-c, rec_len, tag, timestamp);
-       c += ttdevputhex64(&buffer[c], len-c, id);
-       c += ttdevputmem(&buffer[c], len-c, name, nc);
-       c += ttdevputchar(&buffer[c], len+1-c, '\n');
-       out_len = ttdevcopyout(va, n, out_len, buffer, c);
-
-       tag |= TTRACEH_TAG_CONT;
-       const int buf_nm_len = len - TTRACEH_CONT_LEN;
-       while ((remaining -= nc) > 0) {
-               name += nc;
-
-               nc = min(buf_nm_len, remaining);
-               rec_len = TTRACEH_CONT_LEN + nc; dassert(rec_len <= len);
-               c = 0;
-               c += ttdevputhex8(&buffer[c], len-c, rec_len);
-               c += ttdevputhex8(&buffer[c], len-c, tag);
-               c += ttdevputmem(&buffer[c], len-c, name, nc);
-               c += ttdevputchar(&buffer[c], len+1-c, '\n');
-               out_len += ttdevcopyout(va, n, out_len, buffer, c);
+       uint64_t *sqp = (uint64_t *) entry;
+       char *dcp = ctxt->genbuf;
+       for (int i = 0; i < TTRACE_ENTRY_QUADS; i++) {
+               const uint64_t quad = sqp[i];
+               dcp[0] = ttdevhexdigit((quad >> 28) & 0xf);
+               dcp[1] = ttdevhexdigit((quad >> 24) & 0xf);
+               dcp[2] = ttdevhexdigit((quad >> 20) & 0xf);
+               dcp[3] = ttdevhexdigit((quad >> 16) & 0xf);
+               dcp[4] = ttdevhexdigit((quad >> 12) & 0xf);
+               dcp[5] = ttdevhexdigit((quad >>  8) & 0xf);
+               dcp[6] = ttdevhexdigit((quad >>  4) & 0xf);
+               dcp[7] = ttdevhexdigit((quad >>  0) & 0xf);
+               dcp[8] = ' ';
+               dcp += 9;
        }
-       return out_len;
-}
+       dassert(&ctxt->genbuf[sizeof(ctxt->genbuf)] == dcp);
+       dcp[-1] = '\n';  // Replace trailing space with a newline
 
-static size_t ttdevread_info(void *va, long n, uintptr_t timestamp)
-{
-       char * const buffer = get_cur_genbuf();
-       const int len = TT_SAFE_GENBUF_SZ; /* Room for new line */
-       const int rec_len = TTRACEH_LEN + 12;  /* header + 3*h[4] versions */
-       dassert(rec_len <= len);
-       int c = 0;
-
-       c += ttdevputhdr(&buffer[c], len-c, rec_len, TTRACEH_TAG_INFO, timestamp);
-       c += ttdevputhex16(&buffer[c], len-c, TTRACEH_V1);
-       c += ttdevputhex16(&buffer[c], len-c, TTRACEE_V1);
-       c += ttdevputhex16(&buffer[c], len-c, num_cpus);
-       dassert(c == rec_len); // Don't count '\n' in rec_len
-       c += ttdevputchar(&buffer[c], len+1-c, '\n'); // Always have room for newline
-
-       return ttdevcopyout(va, n, /* offset */ 0, buffer, c);
+       ctxt->c += ttdevcopyout(ctxt->va, ctxt->n, ctxt->c,
+                                       ctxt->genbuf, sizeof(ctxt->genbuf));
 }
 
-// iotimestamp takes the timestamp pointer and the I/Os offset and returns the
-// minimum timestamp last requested in a write. In the case where the channel
-// has been opened readonly we will complete the offset == 0 request and return
-// end of file for all subsequent (offset > 0) requests; this allows cat to
-// return one page of data.
+/* iotimestamp takes the timestamp pointer and the I/Os offset and returns the
+ * minimum timestamp last requested in a write. In the case where the channel
+ * has been opened readonly we will complete the offset == 0 request and return
+ * end of file for all subsequent (offset > 0) requests; this allows cat to
+ * return one page of data. */
 static inline uintptr_t ttdevread_mintimestamp(const int tsid, int64_t offset)
 {
-       // If we don't have a timestamp, then only satisfy a single I/O, that is
-       // anything with an offset of 0
-       if (!tsid && offset)
+       /* ttdevread_cpu code can not deal sensibly with offsets without making the
+        * code much more complicated, probably not worth it. */ 
+       if (offset)
                return 0;
 
        const uintptr_t min_timestamp = ttdevtimestamp[tsid];
@@ -296,13 +251,42 @@ static inline uintptr_t ttdevread_mintimestamp(const int tsid, int64_t offset)
        return min_timestamp;
 }
 
+static inline long ttdevread_cpu(const int tsid,
+                                                                int coreid, void *va, long n, int64_t offset)
+{
+       ERRSTACK(1);
+       const uintptr_t min_timestamp = ttdevread_mintimestamp(tsid, offset);
+       if (!min_timestamp)
+               return 0;
+
+       struct ttdevread_cpu_ctxt *ctxt = kzalloc(sizeof(*ctxt), KMALLOC_WAIT);
+       if (!ctxt)
+               error(Enomem);
+       else if (waserror()) {
+               kfree(ctxt);
+               nexterror();
+       }
+
+       ctxt->min_timestamp = min_timestamp
+       ctxt->va = va;
+       ctxt->n = n;
+
+       struct trace_ring * const ring = get_ttrace_ring_for_core(coreid);
+       trace_ring_foreach(ring, &ttdevread_cpu_entry, ctxt);
+
+       kfree(ctxt);
+       poperror();
+       return ctxt->c;
+}
+
 static inline long ttdevread_ctl(void *va, long n, int64_t offset)
 {
-       // Read the ttrace_type_mask and create a 'setmask' ctl command
-       //
-       // cmd     ttrace_bits       bit mask
-       // setmask 0x0123456789abcdef 0x0123456789abcdef\n"
-       // 123456789012345678901234567890123456789012345 6  len 46 bytes
+       /* Read the ttrace_type_mask and create a 'setmask' ctl command
+        *
+        * cmd     ttrace_bits       bit mask
+        * setmask 0x0123456789abcdef 0x0123456789abcdef\n"
+        * 123456789012345678901234567890123456789012345 6  len 46 bytes
+        */
        char * const buffer = get_cur_genbuf();
        static_assert(TTRACE_CTL_LEN <= GENBUF_SZ);
 
@@ -313,53 +297,52 @@ static inline long ttdevread_ctl(void *va, long n, int64_t offset)
        return readstr(offset, va, n, buffer);
 }
 
-static inline long ttdevread_data(const int tsid,
-                                                                 uint8_t *va, long n, int64_t offset)
+/* This code will be more efficient if the user data is page aligned, but
+ * should work no matter which alignment the use gives.
+ * Output:
+ *   Page 0:   struct ttrace_version
+ *   Page 1-n: Auxillary buffer.
+ */
+static inline long ttdevread_aux(uint8_t *va, long n, int64_t offset)
 {
-       const int min_timestamp = ttdevread_mintimestamp(tsid, offset);
-       if (!min_timestamp)
-               return 0;
-
-       // All data requested, Copy out basic data: version ids and syscall table
-       size_t c = 0;  // Number of characters output
-       if (min_timestamp == 1) {
-               c += ttdevread_info(&va[c], n - c, min_timestamp);
-               for (size_t i = 0; i < max_syscall; i++) {
-                       const char * const name = syscall_table[i].name;
-                       if (!name) continue;
+       ptrdiff_t dummy_offset;
+       struct ttrace_version vers;
+       fill_ttrace_version(&vers);
+
+       const long buffer_length = vers.buffer_mask + 1;
+       if (offset)
+               return 0; // Only allow single reads at offset 0, all others are empty
+       else if (n < PGSIZE + buffer_length)
+               error(Etoosmall);
+
+       size_t c = PGSIZE; // Advance count to second page
+
+       /* Implements reader side of auxillary buffer protocol, see
+        * _ttrace_point_string comment in ttrace.c
+        *
+        * Touch memory to get any page faults out of the way now, hopefully we
+        * will not be under paging pressure. Note that I'm accumulating into the
+        * vers.last_offset so that the compiler doesn't throw out the memory touch
+        * loop, the vers.last_offset is reset when we take a buffer snapshot.
+        *
+        * TODO(gvdl): formalise memory pinning for later I/O.
+        */
+       vers.last_offset = 0;
+       size_t t = PGSIZE + ((uintptr_t) va & (sizeof(long) - 1));
+       for (t = 0; t < n, t += PGSIZE)
+               vers.last_offset += atomic_read((atomic_t *) va[t]);
+
+       get_ttrace_aux_buffer_snapshot(&dummy_offset, &vers.last_offset);
+       const uint8_t * const aux_buffer = get_ttrace_aux_buffer();
+       c += ttdevcopyout(va, n, c, aux_buffer, buffer_length);
+       get_ttrace_aux_buffer_snapshot(&vers.first_offset, &dummy_ffset);
+
+       /* Output version with buffer offsets last */
+       ttdevcopyout(va, n, 0, &vers, sizeof(vers));
 
-                       c += ttdev_readnamerec(&va[c], n - c, TTRACEH_TAG_SYSC,
-                                                                  min_timestamp, i, name);
-               }
-       }
-
-       // Read ttrace data file, contains names and other data, this data is slow
-       // to store and generate and is expected to be done only rarely. Such as at
-       // process, semaphore, ktask creation.
        return c;
 }
 
-static inline long ttdevread_cpu(const int tsid,
-                                                                int core_id, void *va, long n, int64_t offset)
-{
-       const int min_timestamp = ttdevread_mintimestamp(tsid, offset);
-       if (!min_timestamp)
-               return 0;
-
-#warning Scaffolding, test cpu timestamp reading
-       // Read the timestamp and output it in decimal (max 20 digits).
-       // cmd   timestamp
-       // setts 12345678901234567890\n"
-       // 12345678901234567890123456 7  len 27
-       char * const buffer = get_cur_genbuf();
-       static_assert(27 <= GENBUF_SZ);
-
-       int c = snprintf(buffer, GENBUF_SZ, "setts %lld\n", min_timestamp);
-       dassert(c <= 27);
-
-       return readstr(offset, va, n, buffer);
-}
-
 /*
  * ttrace write utility routines and macros
  */
@@ -372,8 +355,6 @@ static uint64_t parseul(const char * const num_str, int base)
        return ret;
 }
 
-#define CONST_STRNCMP(vp, conststr) strncmp((vp), conststr, sizeof(conststr)-1)
-
 /*
  * ttrace devtab entry points
  */
@@ -381,29 +362,32 @@ static void ttdevinit(void)
 {
        static_assert(MAX_NUM_CPUS <= Maskcpu);  // Assert encoding is still good
 
-       // Support upto 8 simultaneous opens on the ttrace/{data,cpu*} files.
+       /* Support upto 8 simultaneous opens on the ttrace/cpunnn files. */
        const int pool_size
-               = min(TTRACE_MAX_TSID, TTRACE_NUM_OPENERS * (1 + num_cpus));
-       // Test for too many cpus for our tsid mechanism, re-implement.
-       dassert(1 + num_cpus <= pool_size);
-       if (1 + num_cpus > pool_size) return;
+               = min(TTRACE_MAX_TSID, TTRACE_NUM_OPENERS * num_cpus);
+       /* Test for too many cpus for our tsid mechanism, re-implement. */
+       dassert(num_cpus <= pool_size);
+       if (num_cpus > pool_size) {
+               printk("Insufficient ids for ttrace timestamp pool");
+               return;
+       }
 
        const size_t ts_size = pool_size * sizeof(*ttdevtimestamp);
        ttdevtimestamp = kmalloc(ts_size, KMALLOC_WAIT);
        memset(ttdevtimestamp, 0xff, ts_size);
        ttdevtspool = create_u16_pool(pool_size);
 
-       // Always allocate 0 as a unused/NULL sentinel
-       int tsidnull = get_u16(ttdevtspool);
+       /* Always allocate 0 as a unused/NULL sentinel */
+       int tsidnull = get_tsid(ttdevtspool);
        assert(!tsidnull);
-       ttdevtimestamp[tsidnull] = 1;  // tsid==0 always has a 1 minimum timestamp.
+       ttdevtimestamp[tsidnull] = 1;  // tsid[0] is set to timestamp of 1.
 }
 
-#define kfree_and_null(x) do { kfree(x); x = NULL; } while(false)
+#define KFREE_AND_NULL(x) do { kfree(x); x = NULL; } while(false)
 static void ttdevshutdown(void)
 {
-       kfree_and_null(ttdevtspool);
-       kfree_and_null(ttdevtimestamp);
+       KFREE_AND_NULL(ttdevtspool);
+       KFREE_AND_NULL(ttdevtimestamp);
 }
 
 static struct chan *ttdevattach(char *spec)
@@ -437,14 +421,12 @@ static struct chan *ttdevopen(struct chan *c, int omode)
                        error(Eperm);
                break;
 
-       case Ttdevdataqid:
        case Ttdevcpudataqid:
                if (tsid)
                        break; // Already allocated, reopen
 
-               // Allocate a timestamp from the pool
                if (o == O_RDWR) {
-                       tsid = get_u16(ttdevtspool);
+                       tsid = get_tsid(ttdevtspool);
                        if (tsid < 0)
                                error(Enoenv);
                        else
@@ -457,6 +439,7 @@ static struct chan *ttdevopen(struct chan *c, int omode)
                        error(Eperm);
                break;
 
+       case Ttdevauxqid:
        case Ttdevctlqid:
                break;
        }
@@ -475,14 +458,14 @@ static void ttdevclose(struct chan *c)
 
        const int tsid = TTTSID(c->qid);
        switch (TTYPE(c->qid)) {
-       case Ttdevdataqid:
        case Ttdevcpudataqid:
-               // Release timestamp
+               /* Release timestamp */
                if (tsid) {
                        ttdevtimestamp[tsid] = -1;
-                       put_u16(ttdevtspool, tsid);
+                       put_tsid(ttdevtspool, tsid);
                }
                break;
+       case Ttdevauxqid:
        case Ttdevctlqid:
        case Ttdevdirqid:
                break;
@@ -501,14 +484,15 @@ static long ttdevread(struct chan *c, void *va, long n, int64_t offset)
                return devdirread(c, va, n, NULL, 0, ttdevgen);
        case Ttdevctlqid:
                return ttdevread_ctl(va, n, offset);
-       case Ttdevdataqid:
-               return ttdevread_data(tsid, va, n, offset);
+       case Ttdevauxqid:
+               return ttdevread_aux(va, n, offset);
        case Ttdevcpudataqid:
                return ttdevread_cpu(tsid, TTCPU(c->qid), va, n, offset);
        }
        return 0; // Not us
 }
 
+#define CONST_STRNCMP(vp, conststr) strncmp((vp), conststr, sizeof(conststr)-1)
 static long ttdevwrite(struct chan *c, void *a, long n, int64_t unused_off)
 {
        ERRSTACK(1);
@@ -516,7 +500,7 @@ static long ttdevwrite(struct chan *c, void *a, long n, int64_t unused_off)
        struct cmdbuf *cb;
        static const char ctlstring[]
                = "setmask <value> <mask>|setbits <value>|clrbits <mask>";
-       static const char tsstring[] = "setts <minimum timestamp>";
+       static const char tsstring[] = "settimestamp <minimum timestamp>";
 
        cb = parsecmd(a, n);
        if (waserror()) {
@@ -545,10 +529,10 @@ static long ttdevwrite(struct chan *c, void *a, long n, int64_t unused_off)
                else
                        error(ctlstring);
 
-               // Thread safe, but... lets face it if we have competing controllers
-               // setting anc clearing mask bits then the behaviour is going to be
-               // unexpected. Perhaps I should enforce exclusive open of the ctl
-               // channel.
+               /* Thread safe, but... lets face it if we have competing controllers
+                * setting and clearing mask bits then the behaviour is going to be
+                * unexpected. Perhaps we could enforce exclusive open of the ctl
+                * channel. */
                {
                        uint64_t cur_mask, new_mask;
                        do {
@@ -560,8 +544,7 @@ static long ttdevwrite(struct chan *c, void *a, long n, int64_t unused_off)
                break;
 
        case Ttdevcpudataqid:
-       case Ttdevdataqid:
-               if (cb->nf == 2 && !CONST_STRNCMP(cb->f[0], "setts")) {
+               if (cb->nf == 2 && !CONST_STRNCMP(cb->f[0], "settimestamp")) {
                        if (!tsid) error(Ebadfd);
 
                        const char *endptr = NULL;
index a1fc87f..f4191ce 100644 (file)
  * See LICENSE for details.
  *
  * Timed tracing.
- *
- * This is the first cut at a TTRACE header. At the moment only sufficient type
- * information for the initial implementation of kprof_ttrace logging output
- * subsystem to be prototyped. That is this file is currently part of the
- * scaffolding necessary to bring up a comlicated facility and break it up into
- * reasonably sized changes.
- */
+ * TODO(gvdl): Documentation goes here. */
 #ifndef INC_ROS_TTRACE_H
 #define INC_ROS_TTRACE_H
 
-#ifndef CONFIG_TTRACE
+#define TTRACE_DEV        "#T"
+#define TTRACE_DEV_CTL    TTRACE_DEV "/ctl"
+#define TTRACE_DEV_AUX    TTRACE_DEV "/aux"
+#define TTRACE_DEV_CPUFMT TTRACE_DEV "/cpu%03d"
 
-// If the TTRACE is not configured then null out the initter
-#define ttrace_init()    do { } while(false)
-#define ttrace_cleanup() do { } while(false)
+enum {
+       TTRACE_ENTRY_MASK      = 0x0000000000000003ULL,  /* two spare bits */
+       /* Exact meaning varies depends on TYPE */
+       TTRACE_ENTRY_START     = 0x0000000000000000ULL,  /* Start/unblock */
+       TTRACE_ENTRY_STOP      = 0x0000000000000001ULL,  /* Stop/block */
+       TTRACE_ENTRY_ENTRY     = 0x0000000000000002ULL,  /* Entry */
+       TTRACE_ENTRY_EXIT      = 0x0000000000000003ULL,  /* Exit */
 
-#else /* CONFIG_TTRACE */
+       /* Tag mask for the ctx union */
+       TTRACE_CTX_MASK        = 0x0000000000000070ULL,  /* one spare bit */
+       TTRACE_CTX_KTASK       = 0x0000000000000000ULL,  /* ctx.kthread */
+       TTRACE_CTX_RKMSG       = 0x0000000000000010ULL,  /* ctx.kthread */
+       TTRACE_CTX_PIDSYSC     = 0x0000000000000020ULL,  /* ctx.pid_syscall */
+       TTRACE_CTX_PIDTRAP     = 0x0000000000000030ULL,  /* ctx.pid_syscall */
+       TTRACE_CTX_IRQ         = 0x0000000000000040ULL,  /* ctx.ctx_depth */
+       TTRACE_CTX_TRAP        = 0x0000000000000050ULL,  /* ctx.ctx_depth */
 
-extern uint64_t ttrace_type_mask;
+       /* 12 bits to encode cpu_id */
+       TTRACE_TYPE_PCPU_MASK  = 0x00000000000fff00ULL,  /* Not set by kernel */
 
-enum {
        /* Block of scheduling tracking trace type bits */
        TTRACE_TYPE_MASK       = 0xfffffffffff00000ULL,
+       TTRACE_TYPE_SCHED      = 0x0000000000100000ULL,
+       TTRACE_TYPE_SEMA       = 0x0000000000200000ULL,
+       TTRACE_TYPE_RWLOCK     = 0x0000000000400000ULL,
+       TTRACE_TYPE_SYSCALL    = 0x0000000000800000ULL,
+       TTRACE_TYPE_INTR       = 0x0000000001000000ULL,
+       TTRACE_TYPE_PROCESS    = 0x0000000002000000ULL,
+
+       /* ttrace_version */
+       TTRACEVH_MAGIC         = 0x0001020304050607;
+       TTRACEVH_CIGAM         = 0x0706050403020100;
+       TTRACEVH_H_V1_0        = 0x00010000,  /* Version 1.0 ttrace/data format */
+       TTRACEVH_S_V1_0        = 0x00010000,  /* Version 1.0 ttrace/data format */
+       TTRACEVH_C_V1_0        = 0x00010000,  /* Version 1.0 ttrace/cpu* format */
+
+       /* ttrace/shared data tags */
+       TTRACES_TAG_CONT       = 0x80000000,  /* Tag continuation, top bit set */
+       TTRACES_TAG_INFO       = 0x00000001,  /* Data file specification */
+       TTRACES_TAG_SYSC       = 0x00000002,  /* Syscall entry */
+       TTRACES_TAG_PROC       = 0x00000003,  /* Proc name */
+       TTRACES_TAG_KTASK      = 0x00000004,  /* Ktask name */
+       TTRACES_TAG_SEM        = 0x00000005,  /* Semaphore name */
+       TTRACES_TAG_CV         = 0x00000006,  /* Condition name */
+       TTRACES_TAG_QLOCK      = 0x00000007,  /* Qlock name */
+}
+
+// Binary information is always in host endianness, the reader makes right
+// assert(((struct ttrace_version *) <hdrp>)->magic == TTRACEVH_MAGIC);
+// TODO: Endianness correcting inlines when required
+
+struct ttrace_version {
+       uint64_t magic; // Endianness of ttrace binary data, reader makes right
+       uint32_t header_version; // Version of this header
+       uint32_t shared_data_version; // Version of shared data
+       uint32_t percpu_data_version; // Version of percpu entries
+       uint32_t num_cpus;
+       ptrdiff_t buffer_mask; // Mask for offsets into shared buffer
+       ptrdiff_t first_offset; // First valid data in auxilary buffer
+       ptrdiff_t last_offset; // Last data entry in auxilary
+} __attribute__ ((packed));
+
+struct ttrace_type {
+       /* 0x00 */ uint64_t type_id;
+       /* 0x08 */ union {
+               uintptr_t kthread;
+               uintptr_t pid_syscall;
+               uint32_t ctx_depth;
+       } ctx;
+} __attribute__ ((packed));
+
+/* ttrace entry must be a 64byte (that is power of two cachelines) */
+struct ttrace_entry {
+       /* 0x00 */ uint64_t timestamp;
+       /* 0x08 */ struct ttrace_type t;
+       /* 0x18 */ uintptr_t data0;
+       /* 0x20 */ uintptr_t data1;
+       /* 0x28 */ uintptr_t data2;
+       /* 0x30 */ uintptr_t data3;
+       /* 0x38 */ uintptr_t data4;
+} __attribute__ ((packed));
+
+/* Continuations have the same timestamp with 0x1 bit set */
+struct ttrace_entry_continuation {
+       /* 0x00 */ uint64_t timestamp;
+       /* 0x08 */ uintptr_t data0;
+       /* 0x10 */ uintptr_t data1;
+       /* 0x18 */ uintptr_t data2;
+       /* 0x20 */ uintptr_t data3;
+       /* 0x28 */ uintptr_t data4;
+       /* 0x30 */ uintptr_t data5;
+       /* 0x38 */ uintptr_t data6;
+} __attribute__ ((packed));
+
+// len in bytes but records are laid down on 64bit boundaries, actual
+// length in memory is computed using ttrace_aux_entry_size().
+struct ttrace_aux_entry {
+       uint64_t path;     // See path decode macros below
+       uint64_t timestamp;
+       // Payload
+       uintptr_t ident;  // Optional: Identifier for record, eg. syscall number
+       uint8_t string[]; // String is not nul terminated
+} __attribute__ ((packed));
+
+#define TTRACE_AUX_PATH(tag, coreid, len, flags) ({                                                    \
+       const uint64_t t = (uint32_t) tag;                                                                              \
+       const uint64_t c = (uint16_t) coreid;                                                                   \
+       const uint64_t paylen = (uint16_t) len - 16;                                                    \
+       const uint64_t f = flags & 0xf;                                                                                 \
+       (t << 32) | c << 16 | paylen << 4 | f;                                                                  \
+})
+#define TTRACE_AUX_TAG(path)    ((path >> 32))
+#define TTRACE_AUX_CPUID(path)  ((path >> 16) & 0xffff)
+#define TTRACE_AUX_LEN(path)   (((path >>  4) &  0xfff) + 16)
+#define TTRACE_AUX_FLAGS(path)   (path & 0xf)
+#define TTRACE_AUX_ENTRY_MAXLEN ((size_t) 4096)
+#define TTRACE_AUX_ENTRY_MAXPAYLEN (TTRACE_AUX_ENTRY_MAXLEN  - 16)
+#define TTRACE_AUX_ENTRY_MAXSTRLEN \
+       (TTRACE_AUX_ENTRY_MAXLEN - sizeof(struct ttrace_aux_entry))
+
+static inline size_t ttrace_aux_align(ptrdiff_t offset)
+{
+       const size_t align_mask = sizeof(uint64_t) - 1;  // 8 byte alignment
+       return ((offset & ~align_mask) + align_mask) & ~align_mask;
+}
+
+static inline struct ttrace_aux_entry *ttrace_aux_entry_next(
+          const struct ttrace_aux_entry * const entry)
+{
+       const size_t len = ttrace_aux_entry_size(entry->len);
+       return (struct ttrace_aux_entry *) &((uint8_t*) entry)[len];
+}
 
-       /* ttrace/data tags and misc */
-       TTRACEH_V1             = 0x0100,  /* Version 1.0 ttrace/data format */
-       TTRACEE_V1             = 0x0090,  /* Version 0.9 ttrace/cpu* scaffold */
-       TTRACEH_TAG_CONT       = 0x80,    /* Continuation record top bit set */
-       TTRACEH_TAG_INFO       = 0x01,    /* Data file info version */
-       TTRACEH_TAG_SYSC       = 0x02,    /* Syscall entry */
-       TTRACEH_TAG_PROC       = 0x03,    /* Proc name */
-       TTRACEH_TAG_KTASK      = 0x04,    /* Ktask name */
-       TTRACEH_TAG_SEM        = 0x05,    /* Semaphore name */
-       TTRACEH_TAG_CV         = 0x06,    /* Condition name */
-       TTRACEH_TAG_QLOCK      = 0x07,    /* Qlock name */
-
-       /* ttrace/data header lengths */
-       TTRACEH_CONT_LEN = 2 + 2, /* len, tag */
-       TTRACEH_LEN = TTRACEH_CONT_LEN + 16, /* len + tag + timestamp */
-       TTRACEH_NAME_LEN = TTRACEH_LEN + 16, /* header len + id len */
-};
-
-// Timed trace data version 1 record format,
-//   All lines are nl terminated.
-//   where h[n]-> n hex digits, s[n] -> n byte string
-//
-//   Header:
-//   h[2]: len  Max 127(0xff)
-//   h[2]: tag
-//   h[16]: timestamp
-//
-//   Info record:
-//   h[20]: header, timestamp is always 1 tag: TTRACEH_TAG_INFO
-//   h[4]: summary data version
-//   h[4]: cpu data version
-//   h[4]: num cpus
-//
-//   Name record:
-//   h[20]: header
-//   h[16]: id;  uintptr_t, such as kthread, pid or syscall number
-//   s[hdr.len-36]: string (not nul terminated)
-//
-//   Name continuation record(no timestamp), always follows a Name record:
-//   h[2]: len
-//   h[2]: tag (top bit set)
-//   s[hdr.len-4]: string (not nul terminated)
-//
-
-#endif /* CONFIG_TTRACE */
 #endif /* INC_ROS_TTRACE_H */
index 611eb11..b854f04 100644 (file)
  *             }
  *             trace_ring_foreach(my_trace_ring_ptr, trace_handler, optional_blob);
  *
- * Rings can be racy or not, and can overwrite entries or not.  If you are not
- * overwriting, the ring will stop giving you slots.  You need to reset the ring
- * to get fresh slots again.  If you are overwriting, you don't need to check
- * the return value of get_trace_slot_overwrite().
+ * Rings can be smp safe, per cpu or racy, and can overwrite entries or not.
+ * If you are not overwriting, the ring will stop giving you slots.  You need
+ * to reset the ring to get fresh slots again.  If you are overwriting, you
+ * don't need to check the return value of get_trace_slot_overwrite().  Per cpu
+ * rings are interrupt safe.
  *
  * Given there is overwrite, tr_next doesn't really tell us which ones were
  * used.  So your handler should check for a flag or something.  Timestamps
 #define ROS_INC_TRACE_H
 
 #include <ros/common.h>
+#include <arch/arch.h>
 #include <assert.h>
 
 struct trace_ring {
-       unsigned char                           *tr_buf;
+       uint8_t                                         *tr_buf;
        size_t                                          tr_buf_sz;
        unsigned int                            tr_event_sz_shift;
        unsigned int                            tr_max;
@@ -85,6 +87,18 @@ __get_tr_slot_overwrite(struct trace_ring *tr, unsigned long slot)
        return __get_tr_slot(tr, slot);
 }
 
+/* Interrupt safe modification of tr_next */
+static inline unsigned int
+__get_next_percpu_and_add(struct trace_ring *tr, int8_t n)
+{
+       int8_t irq_state = 0;
+       disable_irqsave(&irq_state);
+       unsigned int ret = tr->tr_next;
+       tr->tr_next += n;
+       enable_irqsave(&irq_state);
+       return ret;
+}
+
 static inline void *get_trace_slot(struct trace_ring *tr)
 {
        /* Using syncs, instead of atomics, since we access tr_next as both atomic
@@ -104,6 +118,22 @@ static inline void *get_trace_slot_overwrite(struct trace_ring *tr)
        return __get_tr_slot_overwrite(tr, __sync_fetch_and_add(&tr->tr_next, 1));
 }
 
+static inline void *get_trace_slot_percpu(struct trace_ring *tr)
+{
+       unsigned long my_slot = __get_next_percpu_and_add(tr, 1);
+       if (my_slot >= tr->tr_max) {
+               /* See comment in get_trace_slot. */
+           __get_next_percpu_and_add(tr, -1);
+               return 0;
+       }
+       return __get_tr_slot(tr, my_slot);
+}
+
+static inline void *get_trace_slot_overwrite_percpu(struct trace_ring *tr)
+{
+       return __get_tr_slot_overwrite(tr, __get_next_percpu_and_add(tr, 1));
+}
+
 static inline void *get_trace_slot_racy(struct trace_ring *tr)
 {
        unsigned long my_slot = tr->tr_next;
diff --git a/kern/include/ttrace.h b/kern/include/ttrace.h
new file mode 100644 (file)
index 0000000..4b38c58
--- /dev/null
@@ -0,0 +1,132 @@
+/* TODO(gvdl): Who holds the copyright?
+ * Godfrey van der Linden <gvdl@google.com>
+ * See LICENSE for details.
+ *
+ * Timed tracing.
+ * Kernel header
+ * TODO(gvdl): Documentation goes here. */
+#ifndef INC_TTRACE_H
+#define INC_TTRACE_H
+
+#define TTRACE_NULL_STATEMENT do { } while(0)
+
+#ifndef CONFIG_TTRACE
+
+// If the TTRACE is not configured then null out the initters
+#define ttrace_init()    TTRACE_NULL_STATEMENT
+#define ttrace_cleanup() TTRACE_NULL_STATEMENT
+
+#else /* CONFIG_TTRACE */
+
+#include <atomic.h>
+#include <ros/ttrace.h>
+
+// Global data
+
+// Active tracepoint mask, see TTRACE_TYPE... enums in ros/ttrace.h
+extern uint64_t ttrace_type_mask;
+
+// Two phase initialisation. Call ttrace_init() as soon as page memory
+// allocation is possible so that we can trace very early in system boot.
+// However, that early in boot we do not yet know how many cores we will
+// manange, ttrace_cleanup() is called once we know and returns memory
+// previously allocated for unused cores.
+extern void ttrace_init();
+extern void ttrace_cleanup();
+
+// devttrace accessor routines
+struct trace_ring* get_ttrace_ring_for_core(uint32_t coreid);
+void fill_ttrace_version(struct ttrace_version *versp);
+const uint8_t *bufferp get_ttrace_aux_buffer(void)
+void get_ttrace_aux_buffer_snapshot(ptrdiff_t *firstp, ptrdiff_t *lastp);
+
+// Low level data collection apis, do not use directly but rather use the macro
+// wrappers, such as TTRACE_PROC_ALLOC() below.
+extern uint64_t _ttrace_point(uint64_t type_start_stop,
+                                                         uintptr_t d0, uintptr_t d1, uintptr_t d2,
+                                                         uintptr_t d3, uintptr_t d4);
+extern void _ttrace_point_cont(uint64_t timestamp, uintptr_t d0, uintptr_t d1,
+                                                          uintptr_t d2, uintptr_t d3, uintptr_t d4,
+                                                          uintptr_t d5, uintptr_t d6);
+// Slow takes rwlock, updates auxillary buffer, call this rarely
+extern void _ttrace_point_string(uint8_t tag, uintptr_t ident, const char *str);
+
+static inline uintptr_t __attribute__((always_inline))
+take_tracepoint(uintptr_t type_start_stop)
+{
+       uintptr_t cur_mask = atomic_read((atomic_t *) &ttrace_type_mask);
+       return cur_mask & type_start_stop & TTRACE_TYPE_MASK;
+}
+
+static inline uint64_t _ttrace_point5(uint64_t type_start_stop,
+                                                                         uintptr_t d0, uintptr_t d1, uintptr_t d2,
+                                                                         uintptr_t d3, uintptr_t d4)
+{
+       if (take_tracepoint(type_start_stop))
+               return _ttrace_point(type_start_stop, d0, d1, d2, d3, d4);
+       return 0;
+}
+#define TTRACE_POINT5(type, start_stop, data...) do {                                          \
+       static_assert(type & TTRACE_TYPE_MASK);                                                                 \
+       _ttrace_point5(type | start_stop, data);                                                                \
+} while(false)
+
+static inline uint64_t _ttrace_point12(uint64_t type_start_stop,
+                                                                          uintptr_t d0, uintptr_t d1, uintptr_t d2,
+                                                                          uintptr_t d3, uintptr_t d4, uintptr_t d5,
+                                                                          uintptr_t d6, uintptr_t d7, uintptr_t d8,
+                                                                          uintptr_t d9, uintptr_t da, uintptr_t db)
+{
+       if (take_tracepoint(type_start_stop)) {
+               const uint64_t tsc = _ttrace_point(type_start_stop, d0, d1, d2, d3, d4);
+               _ttrace_point_cont(tsc, d5, d6, d7, d8, d9, da, db);
+               return tsc;
+       } else
+               return 0;
+}
+#define TTRACE_POINT12(type, start_stop, data...) do {                                         \
+       static_assert(type & TTRACE_TYPE_MASK);                                                                 \
+       _ttrace_point12(type | start_stop, data);                                                               \
+} while(false)
+
+static inline void _ttrace_string(uint64_t type, uint8_t tag,
+                                                                 uintptr_t ident, const char* str)
+{
+       if (take_tracepoint(type))
+               _ttrace_point_string(tag, ident, str);
+}
+// string len < TTRACE_AUX_ENTRY_MAXSTRLEN
+#define TTRACE_STRING(type, tag, ident, str) do {                                                      \
+       static_assert(type & TTRACE_TYPE_MASK);                                                                 \
+       static_assert(tag & TTRACEH_TAG_MASK);                                                                  \
+       _ttrace_string(type, tag, ident, str);
+} while(false)
+
+//
+// CONFIG_TTRACE macros
+//
+// These macros are the data collection side of ttrace. Each CONFIG_TTRACE type
+// has its own group of macros which are empty if the group is not configured.
+
+// CONFIG_TTRACE_PROCESS trace point macros.
+#ifdef CONFIG_TTRACE_PROCESS
+#define TTRACE_PROC_ALLOC(pid, ppid) TTRACE_POINT5(                                                    \
+       TTRACE_TYPE_PROCESS, TTRACE_ENTRY_START, pid, ppid, 0, 0, 0);
+#define TTRACE_PROC_FREE(pid, cpid) TTRACE_POINT5(                                                     \
+       TTRACE_TYPE_PROCESS, TTRACE_ENTRY_STOP, pid, cpid, 0, 0, 0);
+#define TTRACE_PROC_READY(pid) TTRACE_POINT5(                                                          \
+       TTRACE_TYPE_PROCESS, TTRACE_ENTRY_ENTRY, pid, 0, 0, 0, 0);
+#define TTRACE_PROC_SETSTATE(pid, state, curstate) TTRACE_POINT5(                      \
+       TTRACE_TYPE_PROCESS, TTRACE_ENTRY_EXIT, pid, state, curstate, 0, 0);
+#define TTRACE_PROC_SETNAME(pid, name)                                                                         \
+       TTRACE_STRING(TTRACE_TYPE_PROCESS, TTRACEH_TAG_PROC, pid, name)
+#else /* !CONFIG_TTRACE_PROCESS */
+#define TTRACE_PROC_ALLOC(pid, ppid)               TTRACE_NULL_STATEMENT
+#define TTRACE_PROC_FREE(pid, cpid)                TTRACE_NULL_STATEMENT
+#define TTRACE_PROC_READY(pid)                     TTRACE_NULL_STATEMENT
+#define TTRACE_PROC_SETSTATE(pid, state, curstate) TTRACE_NULL_STATEMENT
+#define TTRACE_PROC_SETNAME(pid, name)             TTRACE_NULL_STATEMENT
+#endif /* CONFIG_TTRACE_PROCESS */
+
+#endif /* !CONFIG_TTRACE */
+#endif /* INC_TTRACE_H */
index e62fdce..4cce4b4 100644 (file)
@@ -52,6 +52,7 @@ obj-y                                         += syscall.o
 obj-y                                          += taskqueue.o
 obj-y                                          += time.o
 obj-y                                          += trace.o
+obj-$(CONFIG_TTRACE)        += ttrace.o
 obj-y                                          += trap.o
 obj-y                                          += ucq.o
 obj-y                                          += umem.o
index be24026..ff49a5a 100644 (file)
@@ -43,6 +43,7 @@
 #include <ip.h>
 #include <acpi.h>
 #include <coreboot_tables.h>
+#include <ros/ttrace.h>
 
 int booting = 1;
 struct sysinfo_t sysinfo;
@@ -65,6 +66,7 @@ void kernel_init(multiboot_info_t *mboot_info)
 
        cache_init();                                   // Determine systems's cache properties
        pmem_init(multiboot_kaddr);
+       ttrace_init();                  // Setup timed tracer, depends on pmem
        kmem_cache_init();              // Sets up slab allocator
        kmalloc_init();
        hashtable_init();
@@ -85,6 +87,7 @@ void kernel_init(multiboot_info_t *mboot_info)
        kb_buf_init(&cons_buf);
        arch_init();
        block_init();
+       ttrace_cleanup(); // Must be called after arch_init()
        enable_irq();
        run_linker_funcs();
        /* reset/init devtab after linker funcs 3 and 4.  these run NIC and medium
diff --git a/kern/src/ttrace.c b/kern/src/ttrace.c
new file mode 100644 (file)
index 0000000..9cfa60a
--- /dev/null
@@ -0,0 +1,402 @@
+/* TODO(gvdl): Who holds the copyright?
+ * Godfrey van der Linden <gvdl@google.com>
+ * See LICENSE for details.
+ *
+ * Timed tracing.
+ *
+ * This file is only included if CONFIG_TTRACE=y
+ * TODO(gvdl): Documentation goes here. */
+
+#include <ttrace.h>
+
+#include <arch/arch.h>
+#include <atomic.h>
+#include <env.h>
+#include <page_alloc.h>
+#include <rwlock.h>
+#include <smp.h>
+#include <syscall.h>
+#include <trace.h>
+#include <trap.h>
+
+#ifndef min
+#define min(a, b) ({ \
+       typeof (a) _a = (a); typeof (b) _b = (b); _a < _b ? _a : _b; })
+#endif
+
+// Shared buffer must be a power of 2, static_asserted in ttrace_init.
+#define TTRACE_AUX_BUFFER_MB   ((size_t) 1)
+#define TTRACE_AUX_BUFFER_SZ   (TTRACE_AUX_BUFFER_MB * 1024 * 1024)
+#define TTRACE_AUX_BUFFER_MASK (TTRACE_AUX_BUFFER_SZ - 1)
+
+// TODO(gvdl): Need to make this a config parameter
+// TODO(gvdl): Implement dynamic buffer resize, virtually contig pages
+#define TTRACE_PER_CPU_BUFFER_MB ((size_t) 1) // 16K ttrace entries per cpu
+
+#define TTRACE_PER_CPU_BUFFER_SZ (TTRACE_PER_CPU_BUFFER_MB * 1024 * 1024)
+#define PER_CPU_ORDER ({                                                                                                       \
+       const uint64_t per_cpu_pages = TTRACE_PER_CPU_BUFFER_SZ / PGSIZE;               \
+       (size_t) LOG2_UP(per_cpu_pages);                                                                                \
+})
+
+// Global data
+uint64_t ttrace_type_mask;
+
+// Local data
+static rwlock_t ttrace_aux_rwlock;
+static ptrdiff_t ttrace_aux_first, ttrace_aux_last; // Offsets into aux
+static uint8_t ttrace_aux_buffer[TTRACE_AUX_BUFFER_SZ];
+static struct trace_ring ttrace_ring[MAX_NUM_CPUS];
+
+//
+// TTRACE implementation
+//
+void ttrace_init()
+{
+       // Single tracepoint entries should be atomically written.
+       static_assert(sizeof(struct ttrace_entry) == ARCH_CL_SIZE);
+       static_assert(
+          sizeof(struct ttrace_entry_continuation) == sizeof(struct ttrace_entry));
+       static_assert(sizeof(ttrace_type_mask) == sizeof(atomic_t));
+       static_assert(IS_PWR2(TTRACE_AUX_BUFFER_MB));
+
+       atomic_init((atomic_t *) &ttrace_type_mask, 0);
+       rwinit(&ttrace_aux_rwlock);
+
+       /* ttrace_init() is called as soon as memory is initialised so that we can
+        * profile the early boot sequence if we wish.  But that means it is called
+        * before arch_init and until arch_init is called num_cpus is invalid. So
+        * we allocate as much memory as we'll ever need here and will give the
+        * memory back in ttrace_cleanup() which is called much later in the init
+        * process. */
+       const size_t per_cpu_order = PER_CPU_ORDER;
+       const size_t per_cpu_bytes = (1 << per_cpu_order) * PGSIZE;
+
+       for (int i = 0; i < MAX_NUM_CPUS; i++) {
+               /* TODO(gvdl): Only need virtually contiguous pages! */
+               trace_ring_init(&ttrace_ring[i], get_cont_pages(per_cpu_order, 0),
+                                               TTRACE_PER_CPU_BUFFER_SZ, sizeof(struct ttrace_entry));
+       }
+
+       // Quickly record all of the systems calls, known at compile time
+       for (size_t i = 0; i < max_syscall; i++) {
+               const char * const name = syscall_table[i].name;
+               if (name)
+                       _ttrace_point_string(TTRACEH_TAG_SYSC, i, name);
+       }
+}
+
+void ttrace_cleanup()
+{
+       /* Give back un-used trace_rings, assumes core_id is contiguous from 0 */
+       const size_t per_cpu_order = PER_CPU_ORDER;
+       for (int i = num_cpus; i < MAX_NUM_CPUS; i++) {
+               free_cont_pages(ttrace_ring[i].tr_buf, per_cpu_order);
+               memset(&ttrace_ring[i], 0, sizeof(ttrace_ring[i]));
+       }
+}
+
+//
+// devttrace interface
+//
+struct trace_ring* get_ttrace_ring_for_core(uint32_t coreid)
+{
+       return coreid < num_cpus? &ttrace_ring[coreid] : NULL;
+}
+
+void fill_ttrace_version(struct ttrace_version *versp)
+{
+       versp->magic = TTRACEVH_MAGIC;
+       versp->header_version = TTRACEVH_H_V1_0;
+       versp->shared_data_version = TTRACEVH_S_V1_0;
+       versp->percpu_data_version = TTRACEVH_C_V1_0;
+       versp->num_cpus = num_cpus;
+       versp->buffer_mask = TTRACE_AUX_BUFFER_MASK;
+       versp->first_offset = versp->last_offset = (ptrdiff_t) -1;
+}
+
+const uint8_t *bufferp get_ttrace_aux_buffer(void)
+{
+       return ttrace_aux_buffer;
+}
+
+void get_ttrace_aux_buffer_snapshot(ptrdiff_t *firstp, ptrdiff_t *lastp)
+{
+       rlock(&ttrace_aux_rwlock);
+       *firstp = ttrace_aux_first;
+       *lastp = ttrace_aux_last;
+       runlock(&ttrace_aux_rwlock);
+}
+
+//
+// ttrace data collection
+//
+
+// From Barret
+// An arbitrary kernel thread, running in the kernel, that might block in
+// sem_down can have a few sources:
+//   1) Process issued syscall, when it was submitted locally (trap/sysenter)
+//      and before it blocks. Then owning_proc, cur_proc, owning_vcoreid,
+//      kthread->sysc are accurate.
+//   2) Process issued syscall, either remotely or after it blocked and
+//      restarted at least once.  cur_proc and kthread->sysc are accurate.
+//   3) Process issued trap (SCP page faults on files are handled by the kernel
+//      with blocking kthreads.  There may be others.)  cur_proc is accurate.
+//      kthread->sysc should be 0. Might be fault into in cur_ctx.
+//   4) Kernel task, aka ktask.  It's kernel thread not in a user's context,
+//      has a name. No cur_proc or anything like that. There is kthread->name.
+//   5) Unnamed routine kernel messages.  Like a ktask, there is no user
+//      component. They have no names. Can use kmsg function pointer.
+//
+// For the syscalls (case 1 and 2), it is tempting to track the vcoreid, but it
+// can be wrong in case 2.  I think cur_proc->pid and kthread->sysc->num will
+// work.
+//
+// Case 3 is like case 1 and 2, but there is no kthread->sysc. Right now, it's
+// probably not worth it, but you can peak in cur_ctx and extract the trap
+// number.  that might be arch-dependent and nasty, so probably not worth it.
+// the only one that happens now is a PF.
+//
+// Case 4 and 5 are basically the same.  5 just has a blank name.
+// Incidentally, we can try to attach names to all RKMs.  It'll require some
+// work when it comes to how kthread->name is managed.  Might not be worth it,
+// just for this, unless we have a lot of unnamed RKMs gumming up the works.
+
+// TODO(gvdl): This function is a bit heavy weight for a fast path. It will be
+// better to add ttrace_ctx to per_cpu_info and set it when we change contexts
+// which should be way less frequently than computing it for every record.
+static inline void _ttrace_set_type(struct ttrace_type *tt, uint64_t type,
+                                                                       uint32_t coreid)
+{
+       const struct per_cpu_info *pcpui = &per_cpu_info[coreid];
+       const struct kthread * const kt = pcpui->cur_kthread;
+       const struct proc * const cp = pcpui->cur_proc;
+
+       tt->type_id = type & ~TTRACE_CTX_MASK;
+#if 0
+       /* TODO(gvdl) Investigate TRAP and IRQ contexts */
+       if (pcpui->__ctx_depth) {
+               tt->type_id |= TTRACE_CTX_IRQTRAP;
+               tt->ctx.ctx_depth = pcpui->__ctx_depth;
+       }
+#endif // 0
+       if (!cp) {
+               // case 4-5 Kernel task or routine KMSG
+               tt->ctx.kthread = (uintptr_t) kt;
+               tt->type_id |= (kt->name)? TTRACE_CTX_KTASK : TTRACE_CTX_RKMSG;
+       } else if (kt->sysc) { // case 1-2.
+               // TODO(gvdl) I'd like to log vcore if possible
+               tt->ctx.pid_syscall = (uintptr_t) cp->pid << 32 | kt->sysc->num;
+               tt->type_id |= TTRACE_CTX_PIDSYSC;
+       } else { // case 3
+               // TODO(gvdl) Trap id?
+               tt->ctx.pid_syscall = (uintptr_t) cp->pid << 32;
+               tt->type_id |= TTRACE_CTX_PIDTRAP;
+       }
+}
+
+static inline struct ttrace_entry *_ttrace_next_line(uint32_t coreid)
+{
+       struct trace_ring *per_cpu_ttrace_ring = &ttrace_ring[coreid];
+       return get_trace_slot_overwrite_racy(per_cpu_ttrace_ring);
+}
+
+static inline bool __attribute__((always_inline))
+_ttrace_on_fast_path(uint64_t type_start_stop)
+{
+       (void) type_start_stop; /* unused */
+       return true;  // No slow path dynamic checks yet, will be in future.
+}
+
+uint64_t _ttrace_point(uint64_t type_start_stop, uintptr_t d0, uintptr_t d1,
+                                          uintptr_t d2, uintptr_t d3, uintptr_t d4)
+{
+       if (!_ttrace_on_fast_path(type_start_stop)) {
+               /* Slow path, will contain a list of more selective tests than the
+                * simple TTRACE mask test in the header. */
+               assert(false);  // Unimplemented
+               return 0;
+       }
+
+       /* record tracepoint */
+       const uint32_t coreid = core_id();
+       struct ttrace_entry *cur_trace_entry = _ttrace_next_line(coreid);
+
+       /* Bottom bit of timestamp is used to indicate a continuation record */
+       const uint64_t tsc = read_tscp() & ~1ULL; // Clear bottom bit
+       cur_trace_entry->timestamp = -1ULL; // Invalidate entry
+       wmb();
+
+       _ttrace_set_type(&cur_trace_entry->t, type_start_stop, coreid);
+       cur_trace_entry->data0 = d0;
+       cur_trace_entry->data1 = d1;
+       cur_trace_entry->data2 = d2;
+       cur_trace_entry->data3 = d3;
+       cur_trace_entry->data4 = d4;
+       cur_trace_entry->timestamp = tsc; // Entry complete
+       wmb();
+
+       return tsc | 1;  /* Timestamp for any required continuation */
+}
+
+void _ttrace_point_cont(uint64_t timestamp,
+                                               uintptr_t d0, uintptr_t d1, uintptr_t d2, uintptr_t d3,
+                                               uintptr_t d4, uintptr_t d5, uintptr_t d6)
+{
+       dassert(timestamp & 1);
+       const uint32_t coreid = core_id();
+       struct ttrace_entry_continuation *cur_trace_cont
+               = (struct ttrace_entry_continuation *) _ttrace_next_line(coreid);
+
+       cur_trace_cont->timestamp = -1ULL; // Invalidate entry
+       wmb();
+
+       cur_trace_cont->data0 = d0;
+       cur_trace_cont->data1 = d1;
+       cur_trace_cont->data2 = d2;
+       cur_trace_cont->data3 = d3;
+       cur_trace_cont->data4 = d4;
+       cur_trace_cont->data5 = d5;
+       cur_trace_cont->data6 = d6;
+       cur_trace_cont->timestamp = timestamp; // Entry complete
+       wmb();
+}
+
+// Auxiliary buffer handling.
+// Offsets can be greater than the buffer's size
+static inline struct ttrace_aux_entry *ttrace_aux(ptrdiff_t offset)
+{
+       offset &= TTRACE_AUX_BUFFER_MASK;
+       return (struct ttrace_aux_entry *) (&ttrace_aux_buffer[offset]);
+}
+
+// Copy header concatenated with payload data into target, may wrap around the
+// ttrace_aux_buffer.
+static inline void ttrace_fill_aux(void *vtarget,
+                                                                  const void *vheader,  const int header_len,
+                                                                  const void *vpaydata, const int pay_len)
+{
+       uint8_t * const target = (uint8_t *) vtarget;
+       uint8_t * const header = (uint8_t *) vheader;
+       uint8_t * const paydata = (uint8_t *) vpaydata;
+       size_t offset = 0;
+       size_t remaining = header_len + pay_len;
+       do {
+               const ptrdiff_t buf_remaining
+                       = &ttrace_aux_buffer[sizeof(ttrace_aux_buffer)] - target;
+               size_t len = min(remaining, buf_remaining);
+               uint8_t * const dcp = &target[offset];
+               const uint8_t *scp = NULL;
+               if (offset < header_len) {
+                       scp = &header[offset];
+                       if ((header_len - offset) < len)
+                               len = header_len - offset;
+               } else {
+                       const int pay_offset = offset - header_len;
+                       scp = &paydata[pay_offset];
+                       if ((pay_len - pay_offset) < len)
+                               len = pay_len - pay_offset;
+               }
+               memcpy(dcp, scp, len);
+               offset += len;
+               remaining -= len;
+       } while (remaining > 0);
+}
+
+/* The ttrace_aux_buffer is copied out to user land as a large binary blob. As
+ * _ttrace_point_string is called from performance critical times, e.g.  proc
+ * creation, it is important that writing data does not contend on a long held
+ * reader lock.  Hence the complicated protocol between _ttrace_point_string
+ * and devttrace:ttdevread_aux. The goal is to minimize mutual exclusion time
+ * both between all writers and an occasional reader.
+ *
+ * aux write:
+ *   wlock
+ *     compute last entry
+ *     compute end of new last entry
+ *     advance first entry pointer past new last entry end
+ *     mark entry path, (tag, coreid, len, Entry INVALID)
+ *     wmb()  // Is this barrier necessary before an unlock?
+ *   wunlock
+ *   memcpy data to aux buffer at new entry location
+ *   wmb()
+ *   mark entry path, (tag, coreid, len, Entry VALID)
+ *
+ *  aux_read:
+ *    // Minimise time between offset copies by taking page faults now
+ *    touch every page in user space
+ *    rlock
+ *      copy last entry offset
+ *    runlock
+ *    memcpy auxilary buffer
+ *    rlock
+ *      copy first entry offset
+ *    runlock
+ *  On return from aux_read copied last and first entries are valid, probably,
+ *  and each entry can be checked by the client to determine if it stamped as
+ *  VALID. Note even if the entry is INVALID the length is always ok.
+ */
+void _ttrace_point_string(uint8_t tag, uintptr_t ident, const char *str)
+{
+       int len = strnlen(str, TTRACE_AUX_ENTRY_MAXSTRLEN);
+       assert(!str[len]);
+       len += sizeof(ttrace_aux_entry);  // Length of new record
+       const uint64_t path = TTRACE_AUX_PATH(tag, core_id(), len, 0);
+       struct ttrace_aux_entry *last_aux = NULL;
+
+       wlock(&ttrace_aux_rwlock);
+       do {
+               dassert(ttrace_aux_last == ttrace_aux_align(ttrace_aux_last));
+               dassert(ttrace_aux_first == ttrace_aux_align(ttrace_aux_first));
+
+               const ptrdiff_t old_aux_last = ttrace_aux_last;
+               struct ttrace_aux_entry *old_last_aux = ttrace_aux(old_aux_last);
+
+               // Don't care about wrapping the ttrace_aux function masks out high bits
+               ptrdiff_t new_aux_first = ttrace_aux_first;
+               ptrdiff_t new_aux_last
+                       = old_aux_last + ttrace_aux_align(old_last_aux->len & ~1);
+               dassert(new_aux_last == ttrace_aux_align(new_aux_last));
+
+               const ptrdiff_t next_aux_last = new_aux_last + ttrace_aux_align(len);
+               struct ttrace_aux_entry *first_aux = ttrace_aux(new_aux_first);
+               while (new_aux_first + TTRACE_AUX_BUFFER_SZ < next_aux_last) {
+                       const ptrdiff_t first_len
+                               = ttrace_aux_align(TTRACE_AUX_LEN(first_aux->tag_len));
+                       new_aux_first += first_len;
+                       dassert(new_aux_first == ttrace_aux_align(new_aux_first));
+                       first_aux = ttrace_aux(new_aux_first);
+               }
+               /* Check first for wrap, in which case wrap both first and last */
+               if (new_aux_first >= TTRACE_AUX_BUFFER_SZ) {
+                       new_aux_first -= TTRACE_AUX_BUFFER_SZ;
+                       new_aux_last -= TTRACE_AUX_BUFFER_SZ;
+               }
+               dassert(new_aux_first < TTRACE_AUX_BUFFER_SZ);
+               dassert(new_aux_last < 2 * TTRACE_AUX_BUFFER_SZ);
+
+               ttrace_aux_last = new_aux_last;
+               ttrace_aux_first = new_aux_first;
+               last_aux = ttrace_aux(new_aux_last);
+               atomic_set((atomic_t *) last_aux, path | 1);  // mark entry as invalid
+               /* No barrier necessary before an unlock */
+       } while(false);
+       wunlock(&ttrace_aux_rwlock);
+
+       struct ttrace_aux_entry header = {
+               .path = path | 1;
+               .timestamp = read_tscp();
+               .ident = ident
+       };
+       ttrace_fill_aux(last_aux, &header, sizeof(header), str, len);
+
+       /* The reader is doing a memcpy, not a formal read acquire. but I don't
+        * think that will be an issue. It just means that a record will not be
+        * valid this time the buffer is read. Next time the buffer is read the
+        * write will most probably be complete.  But the wmb is still important
+        * here because we can't have the payload write and release write swapped.
+        * Not that that would happen anyway given we have just called a
+        * function. */
+       wmb(); // Write release, record is valid now.
+       atomic_set((atomic_t *) last_aux, path);
+}