Fixes #K open
[akaros.git] / kern / drivers / dev / kprof.c
index 499fd94..476a279 100644 (file)
@@ -7,6 +7,22 @@
  * in the LICENSE file.
  */
 
+// get_fn_name is slowing down the kprocread 
+//     have an array of translated fns
+//     or a "next" iterator, since we're walking in order
+//
+// irqsave locks
+//
+// kprof struct should be a ptr, have them per core
+//             we'll probably need to track the length still, so userspace knows how
+//             big it is
+//
+//             will also want more files in the kprof dir for each cpu or something
+//             
+// maybe don't use slot 0 and 1 as total and 'not kernel' ticks
+//
+// fix the failed assert XXX
+
 #include <vfs.h>
 #include <kfs.h>
 #include <slab.h>
 #include <pmap.h>
 #include <smp.h>
 #include <ip.h>
-
+#include <oprofile.h>
 
 #define LRES   3               /* log of PC resolution */
-#define CELLSIZE       8       /* sizeof of count cell; well known as 4 */
+#define CELLSIZE       8       /* sizeof of count cell */
 
-struct
+struct kprof
 {
        uintptr_t       minpc;
        uintptr_t       maxpc;
        int     nbuf;
        int     time;
-       uint64_t        *buf;
+       uint64_t        *buf;   /* keep in sync with cellsize */
+       size_t          buf_sz;
        spinlock_t lock;
-}kprof;
+       struct queue *systrace;
+       bool            mpstat_ipi;
+};
+struct kprof kprof;
 
 /* output format. Nice fixed size. That makes it seekable.
  * small subtle bit here. You have to convert offset FROM FORMATSIZE units
  * to CELLSIZE units in a few places.
  */
-char *outformat = "%016llx %29s %016llx\n";
+char *outformat = "%016llx %29.29s %016llx\n";
 #define FORMATSIZE 64
 enum{
-       Kprofdirqid,
+       Kprofdirqid = 0,
        Kprofdataqid,
        Kprofctlqid,
+       Kprofoprofileqid,
+       Kptraceqid,
+       Kprintxqid,
+       Kmpstatqid,
+       Kmpstatrawqid,
 };
+
 struct dirtab kproftab[]={
        {".",           {Kprofdirqid, 0, QTDIR},0,      DMDIR|0550},
        {"kpdata",      {Kprofdataqid},         0,      0600},
        {"kpctl",       {Kprofctlqid},          0,      0600},
+       {"kpoprofile",  {Kprofoprofileqid},     0,      0600},
+       {"kptrace",     {Kptraceqid},           0,      0600},
+       {"kprintx",     {Kprintxqid},           0,      0600},
+       {"mpstat",      {Kmpstatqid},           0,      0600},
+       {"mpstat-raw",  {Kmpstatrawqid},                0,      0600},
 };
 
+static size_t mpstatraw_len(void);
+static size_t mpstat_len(void);
+
 static struct chan*
 kprofattach(char *spec)
 {
@@ -63,12 +97,20 @@ kprofattach(char *spec)
        kprof.nbuf = (kprof.maxpc-kprof.minpc) >> LRES;
        n = kprof.nbuf*CELLSIZE;
        if(kprof.buf == 0) {
-               printk("Allocate %d bytes\n", n);
                kprof.buf = kzmalloc(n, KMALLOC_WAIT);
                if(kprof.buf == 0)
                        error(Enomem);
        }
-       kproftab[1].length = n;
+       kproftab[Kprofdataqid].length = kprof.nbuf * FORMATSIZE;
+       kprof.buf_sz = n;
+       /* NO, I'm not sure how we should do this yet. */
+       int alloc_cpu_buffers(void);
+       alloc_cpu_buffers();
+       kprof.systrace = qopen(2 << 20, 0, 0, 0);
+       if (! kprof.systrace) {
+               printk("systrace allocate failed. No system call tracing\n");
+       }
+       kprof.mpstat_ipi = TRUE;
        return devattach('K', spec);
 }
 
@@ -110,24 +152,27 @@ kproftimer(uintptr_t pc)
 
 static void setup_timers(void)
 {
-       void handler(struct alarm_waiter *waiter)
+       void kprof_alarm(struct alarm_waiter *waiter, struct hw_trapframe *hw_tf)
        {
                struct timer_chain *tchain = &per_cpu_info[core_id()].tchain;
-               kproftimer(per_cpu_info[core_id()].rip);
+               kproftimer(get_hwtf_pc(hw_tf));
                set_awaiter_rel(waiter, 1000);
                __set_alarm(tchain, waiter);
        }
        struct timer_chain *tchain = &per_cpu_info[core_id()].tchain;
        struct alarm_waiter *waiter = kmalloc(sizeof(struct alarm_waiter), 0);
-       init_awaiter(waiter, handler);
+       init_awaiter_irq(waiter, kprof_alarm);
        set_awaiter_rel(waiter, 1000);
        set_alarm(tchain, waiter);
 }
+
 static void
 kprofinit(void)
 {
        if(CELLSIZE != sizeof kprof.buf[0])
                panic("kprof size");
+       kproftab[Kmpstatqid].length = mpstat_len();
+       kproftab[Kmpstatrawqid].length = mpstatraw_len();
 }
 
 static struct walkqid*
@@ -139,6 +184,12 @@ kprofwalk(struct chan *c, struct chan *nc, char **name, int nname)
 static int
 kprofstat(struct chan *c, uint8_t *db, int n)
 {
+       kproftab[Kprofoprofileqid].length = oproflen();
+       if (kprof.systrace)
+               kproftab[Kptraceqid].length = qlen(kprof.systrace);
+       else
+               kproftab[Kptraceqid].length = 0;
+
        return devstat(c, db, n, kproftab, ARRAY_SIZE(kproftab), devgen);
 }
 
@@ -146,7 +197,7 @@ static struct chan*
 kprofopen(struct chan *c, int omode)
 {
        if(c->qid.type & QTDIR){
-               if(omode != OREAD)
+               if(openmode(omode) != OREAD)
                        error(Eperm);
        }
        c->mode = openmode(omode);
@@ -160,22 +211,102 @@ kprofclose(struct chan*unused)
 {
 }
 
+static size_t mpstat_len(void)
+{
+       size_t each_row = 7 + NR_CPU_STATES * 26;
+       return each_row * (num_cpus + 1) + 1;
+}
+
+static long mpstat_read(void *va, long n, int64_t off)
+{
+       size_t bufsz = mpstat_len();
+       char *buf = kmalloc(bufsz, KMALLOC_WAIT);
+       int len = 0;
+       struct per_cpu_info *pcpui;
+       uint64_t cpu_total;
+       struct timespec ts;
+
+       /* the IPI interferes with other cores, might want to disable that. */
+       if (kprof.mpstat_ipi)
+               send_broadcast_ipi(I_POKE_CORE);
+
+       len += snprintf(buf + len, bufsz - len, "  CPU: ");
+       for (int j = 0; j < NR_CPU_STATES; j++)
+               len += snprintf(buf + len, bufsz - len, "%23s%s", cpu_state_names[j],
+                               j != NR_CPU_STATES - 1 ? "   " : "  \n");
+
+       for (int i = 0; i < num_cpus; i++) {
+               pcpui = &per_cpu_info[i];
+               cpu_total = 0;
+               len += snprintf(buf + len, bufsz - len, "%5d: ", i);
+               for (int j = 0; j < NR_CPU_STATES; j++)
+                       cpu_total += pcpui->state_ticks[j];
+               cpu_total = MAX(cpu_total, 1);  /* for the divide later */
+               for (int j = 0; j < NR_CPU_STATES; j++) {
+                       tsc2timespec(pcpui->state_ticks[j], &ts);
+                       len += snprintf(buf + len, bufsz - len, "%10d.%06d (%3d%%)%s",
+                                       ts.tv_sec, ts.tv_nsec / 1000,
+                                       MIN((pcpui->state_ticks[j] * 100) / cpu_total, 100),
+                                       j != NR_CPU_STATES - 1 ? ", " : " \n");
+               }
+       }
+       n = readstr(off, va, n, buf);
+       kfree(buf);
+       return n;
+}
+
+static size_t mpstatraw_len(void)
+{
+       size_t header_row = 27 + NR_CPU_STATES * 7 + 1;
+       size_t cpu_row = 7 + NR_CPU_STATES * 17;
+       return header_row + cpu_row * num_cpus + 1;
+}
+
+static long mpstatraw_read(void *va, long n, int64_t off)
+{
+       size_t bufsz = mpstatraw_len();
+       char *buf = kmalloc(bufsz, KMALLOC_WAIT);
+       int len = 0;
+       struct per_cpu_info *pcpui;
+
+       /* could spit it all out in binary, though then it'd be harder to process
+        * the data across a mnt (if we export #K).  probably not a big deal. */
+
+       /* header line: version, num_cpus, tsc freq, state names */
+       len += snprintf(buf + len, bufsz - len, "v%03d %5d %16llu", 1, num_cpus,
+                       system_timing.tsc_freq);
+       for (int j = 0; j < NR_CPU_STATES; j++)
+               len += snprintf(buf + len, bufsz - len, " %6s", cpu_state_names[j]);
+       len += snprintf(buf + len, bufsz - len, "\n");
+
+       for (int i = 0; i < num_cpus; i++) {
+               pcpui = &per_cpu_info[i];
+               len += snprintf(buf + len, bufsz - len, "%5d: ", i);
+               for (int j = 0; j < NR_CPU_STATES; j++) {
+                       len += snprintf(buf + len, bufsz - len, "%16llx%s",
+                                       pcpui->state_ticks[j],
+                                       j != NR_CPU_STATES - 1 ? " " : "\n");
+               }
+       }
+       n = readstr(off, va, n, buf);
+       kfree(buf);
+       return n;
+}
+
 static long
 kprofread(struct chan *c, void *va, long n, int64_t off)
 {
-       uintptr_t end;
        uint64_t w, *bp;
        char *a, *ea;
        uintptr_t offset = off;
        uint64_t pc;
-       int ret = 0;
+       int snp_ret, ret = 0;
 
        switch((int)c->qid.path){
        case Kprofdirqid:
                return devdirread(c, va, n, kproftab, ARRAY_SIZE(kproftab), devgen);
 
        case Kprofdataqid:
-               end = kprof.nbuf*CELLSIZE;
 
                if (n < FORMATSIZE){
                        n = 0;
@@ -183,6 +314,9 @@ kprofread(struct chan *c, void *va, long n, int64_t off)
                }
                a = va;
                ea = a + n;
+
+               /* we check offset later before deref bp.  offset / FORMATSIZE is how
+                * many entries we're skipping/offsetting. */
                bp = kprof.buf + offset/FORMATSIZE;
                pc = kprof.minpc + ((offset/FORMATSIZE)<<LRES);
                while((a < ea) && (n >= FORMATSIZE)){
@@ -192,22 +326,67 @@ kprofread(struct chan *c, void *va, long n, int64_t off)
                         */
                        char print[FORMATSIZE+1];
                        char *name;
+                       int amt_read;
 
-                       if(offset/FORMATSIZE >= kprof.nbuf){
+                       if (pc >= kprof.maxpc)
                                break;
-                       }
+                       /* pc is also our exit for bp.  should be in lockstep */
+                       // XXX this assert fails, fix it!
+                       //assert(bp < kprof.buf + kprof.nbuf);
+                       /* do not attempt to filter these results based on w < threshold.
+                        * earlier, we computed bp/pc based on assuming a full-sized file,
+                        * and skipping entries will result in read() calls thinking they
+                        * received earlier entries when they really received later ones.
+                        * imagine a case where there are 1000 skipped items, and read()
+                        * asks for chunks of 32.  it'll get chunks of the next 32 valid
+                        * items, over and over (1000/32 times). */
                        w = *bp++;
-                       name = get_fn_name(pc);
-                       snprintf(print, sizeof(print), outformat, pc, name, w);
-                       memmove(a, print, FORMATSIZE);
-                       a += FORMATSIZE;
-                       n -= FORMATSIZE;
-                       ret += FORMATSIZE;
-                       pc++;
+
+                       if (pc == kprof.minpc)
+                               name = "Total";
+                       else if (pc == kprof.minpc + 8)
+                               name = "User";
+                       else
+                               name = get_fn_name(pc);
+
+                       snp_ret = snprintf(print, sizeof(print), outformat, pc, name, w);
+                       assert(snp_ret == FORMATSIZE);
+                       if ((pc != kprof.minpc) && (pc != kprof.minpc + 8))
+                               kfree(name);
+
+                       amt_read = readmem(offset % FORMATSIZE, a, n, print, FORMATSIZE);
+                       offset = 0;     /* future loops have no offset */
+
+                       a += amt_read;
+                       n -= amt_read;
+                       ret += amt_read;
+
+                       pc += (1 << LRES);
                }
                n = ret;
                break;
-
+       case Kprofoprofileqid:
+               n = oprofread(va,n);
+               break;
+       case Kptraceqid:
+               if (kprof.systrace) {
+                       printd("Kptraceqid: kprof.systrace %p len %p\n", kprof.systrace, qlen(kprof.systrace));
+                       if (qlen(kprof.systrace) > 0)
+                               n = qread(kprof.systrace, va, n);
+                       else
+                               n = 0;
+               } else
+                       error("no systrace queue");
+               break;
+       case Kprintxqid:
+               n = readstr(offset, va, n, printx_on ? "on" : "off");
+               break;
+       case Kmpstatqid:
+               n = mpstat_read(va, n, offset);
+               break;
+       case Kmpstatrawqid:
+               n = mpstatraw_read(va, n, offset);
+               break;
        default:
                n = 0;
                break;
@@ -215,26 +394,140 @@ kprofread(struct chan *c, void *va, long n, int64_t off)
        return n;
 }
 
+static void kprof_clear(struct kprof *kp)
+{
+       spin_lock(&kp->lock);
+       memset(kp->buf, 0, kp->buf_sz);
+       spin_unlock(&kp->lock);
+}
+
 static long
 kprofwrite(struct chan *c, void *a, long n, int64_t unused)
 {
+       ERRSTACK(1);
+       uintptr_t pc;
+       struct cmdbuf *cb;
+       cb = parsecmd(a, n);
+
+       if (waserror()) {
+               kfree(cb);
+               nexterror();
+       }
+
        switch((int)(c->qid.path)){
        case Kprofctlqid:
                if(strncmp(a, "startclr", 8) == 0){
-                       memset((char *)kprof.buf, 0, kprof.nbuf*CELLSIZE);
+                       kprof_clear(&kprof);
                        kprof.time = 1;
                }else if(strncmp(a, "start", 5) == 0) {
                        kprof.time = 1;
+                       /* this sets up the timer on the *calling* core! */
                        setup_timers();
-               } else if(strncmp(a, "stop", 4) == 0)
+               } else if(strncmp(a, "stop", 4) == 0) {
+                       /* TODO: stop the timers! */
                        kprof.time = 0;
+               } else if(strncmp(a, "clear", 5) == 0) {
+                       kprof_clear(&kprof);
+               }else if(strncmp(a, "opstart", 7) == 0) {
+                       oprofile_control_trace(1);
+               }else if(strncmp(a, "opstop", 6) == 0) {
+                       oprofile_control_trace(0);
+               } else  {
+                       error("startclr|start|stop|clear|opstart|opstop");
+               }
+               break;
+
+               /* The format is a long as text. We strtoul, and jam it into the
+                * trace buffer.
+                */
+       case Kprofoprofileqid:
+               pc = strtoul(a, 0, 0);
+               oprofile_add_trace(pc);
+               break;
+       case Kprintxqid:
+               if (!strncmp(a, "on", 2))
+                       set_printx(1);
+               else if (!strncmp(a, "off", 3))
+                       set_printx(0);
+               else if (!strncmp(a, "toggle", 6))      /* why not. */
+                       set_printx(2);
+               else
+                       error("invalid option to Kprintx %s\n", a);
+               break;
+       case Kmpstatqid:
+       case Kmpstatrawqid:
+               if (cb->nf < 1)
+                       error("mpstat bad option (reset|ipi|on|off)");
+               if (!strcmp(cb->f[0], "reset")) {
+                       for (int i = 0; i < num_cpus; i++)
+                               reset_cpu_state_ticks(i);
+               } else if (!strcmp(cb->f[0], "on")) {
+                       /* TODO: enable the ticks */ ;
+               } else if (!strcmp(cb->f[0], "off")) {
+                       /* TODO: disable the ticks */ ;
+               } else if (!strcmp(cb->f[0], "ipi")) {
+                       if (cb->nf < 2)
+                               error("need another arg: ipi [on|off]");
+                       if (!strcmp(cb->f[1], "on"))
+                               kprof.mpstat_ipi = TRUE;
+                       else if (!strcmp(cb->f[1], "off"))
+                               kprof.mpstat_ipi = FALSE;
+                       else
+                               error("ipi [on|off]");
+               } else {
+                       error("mpstat bad option (reset|ipi|on|off)");
+               }
                break;
        default:
                error(Ebadusefd);
        }
+       kfree(cb);
+       poperror();
        return n;
 }
 
+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. */
+               if (wrote != len)
+                       printk("DROPPED %s", pretty_buf);
+       }
+}
+
+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",