69b05b1d75edc4c8259cef18fb8249b5804e5ddd
[akaros.git] / kern / drivers / dev / kprof.c
1 /*
2  * This file is part of the UCB release of Plan 9. It is subject to the license
3  * terms in the LICENSE file found in the top-level directory of this
4  * distribution and at http://akaros.cs.berkeley.edu/files/Plan9License. No
5  * part of the UCB release of Plan 9, including this file, may be copied,
6  * modified, propagated, or distributed except according to the terms contained
7  * in the LICENSE file.
8  */
9
10 // get_fn_name is slowing down the kprocread
11 //      have an array of translated fns
12 //      or a "next" iterator, since we're walking in order
13 //
14 // irqsave locks
15 //
16 // kprof struct should be a ptr, have them per core
17 //              we'll probably need to track the length still, so userspace knows how
18 //              big it is
19 //
20 //              will also want more files in the kprof dir for each cpu or something
21 //
22 // maybe don't use slot 0 and 1 as total and 'not kernel' ticks
23 //
24 // fix the failed assert XXX
25
26 #include <vfs.h>
27 #include <kfs.h>
28 #include <slab.h>
29 #include <kmalloc.h>
30 #include <kref.h>
31 #include <string.h>
32 #include <stdio.h>
33 #include <assert.h>
34 #include <error.h>
35 #include <cpio.h>
36 #include <pmap.h>
37 #include <smp.h>
38 #include <ip.h>
39 #include <profiler.h>
40
41 struct dev kprofdevtab;
42
43 static char *devname(void)
44 {
45         return kprofdevtab.name;
46 }
47
48 #define LRES    3               /* log of PC resolution */
49 #define CELLSIZE        8       /* sizeof of count cell */
50
51 struct kprof
52 {
53         uintptr_t       minpc;
54         uintptr_t       maxpc;
55         int     nbuf;
56         int     time;
57         uint64_t        *buf;   /* keep in sync with cellsize */
58         size_t          buf_sz;
59         spinlock_t lock;
60         struct queue *systrace;
61         bool            mpstat_ipi;
62 };
63 struct kprof kprof;
64
65 /* output format. Nice fixed size. That makes it seekable.
66  * small subtle bit here. You have to convert offset FROM FORMATSIZE units
67  * to CELLSIZE units in a few places.
68  */
69 char *outformat = "%016llx %29.29s %016llx\n";
70 #define FORMATSIZE 64
71 enum{
72         Kprofdirqid = 0,
73         Kprofdataqid,
74         Kprofctlqid,
75         Kprofoprofileqid,
76         Kptraceqid,
77         Kprintxqid,
78         Kmpstatqid,
79         Kmpstatrawqid,
80 };
81
82 struct dirtab kproftab[]={
83         {".",           {Kprofdirqid, 0, QTDIR},0,      DMDIR|0550},
84         {"kpdata",      {Kprofdataqid},         0,      0600},
85         {"kpctl",       {Kprofctlqid},          0,      0600},
86         {"kpoprofile",  {Kprofoprofileqid},     0,      0600},
87         {"kptrace",     {Kptraceqid},           0,      0600},
88         {"kprintx",     {Kprintxqid},           0,      0600},
89         {"mpstat",      {Kmpstatqid},           0,      0600},
90         {"mpstat-raw",  {Kmpstatrawqid},                0,      0600},
91 };
92
93 static size_t mpstatraw_len(void);
94 static size_t mpstat_len(void);
95
96 static struct alarm_waiter *oprof_alarms;
97 static unsigned int oprof_timer_period = 1000;
98
99 static void oprof_alarm_handler(struct alarm_waiter *waiter,
100                                 struct hw_trapframe *hw_tf)
101 {
102         int coreid = core_id();
103         struct timer_chain *tchain = &per_cpu_info[coreid].tchain;
104
105         profiler_add_hw_sample(hw_tf);
106         reset_alarm_rel(tchain, waiter, oprof_timer_period);
107 }
108
109 static struct chan*
110 kprofattach(char *spec)
111 {
112         // Did we initialise completely?
113         if ( !(oprof_alarms && kprof.buf && kprof.systrace) )
114                 error(ENOMEM, NULL);
115
116         return devattach(devname(), spec);
117 }
118
119 static void
120 kproftimer(uintptr_t pc)
121 {
122         if(kprof.time == 0)
123                 return;
124
125         /*
126          * if the pc corresponds to the idle loop, don't consider it.
127
128         if(m->inidle)
129                 return;
130          */
131         /*
132          *  if the pc is coming out of spllo or splx,
133          *  use the pc saved when we went splhi.
134
135         if(pc>=PTR2UINT(spllo) && pc<=PTR2UINT(spldone))
136                 pc = m->splpc;
137          */
138
139 //      ilock(&kprof);
140         /* this is weird. What we do is assume that all the time since the last
141          * measurement went into this PC. It's the best
142          * we can do I suppose. And we are sampling at 1 ms. for now.
143          * better ideas welcome.
144          */
145         kprof.buf[0] += 1; //Total count of ticks.
146         if(kprof.minpc<=pc && pc<kprof.maxpc){
147                 pc -= kprof.minpc;
148                 pc >>= LRES;
149                 kprof.buf[pc] += 1;
150         }else
151                 kprof.buf[1] += 1; // Why?
152 //      iunlock(&kprof);
153 }
154
155 static void setup_timers(void)
156 {
157         void kprof_alarm(struct alarm_waiter *waiter, struct hw_trapframe *hw_tf)
158         {
159                 struct timer_chain *tchain = &per_cpu_info[core_id()].tchain;
160                 kproftimer(get_hwtf_pc(hw_tf));
161                 set_awaiter_rel(waiter, 1000);
162                 set_alarm(tchain, waiter);
163         }
164         struct timer_chain *tchain = &per_cpu_info[core_id()].tchain;
165         struct alarm_waiter *waiter = kmalloc(sizeof(struct alarm_waiter), 0);
166         init_awaiter_irq(waiter, kprof_alarm);
167         set_awaiter_rel(waiter, 1000);
168         set_alarm(tchain, waiter);
169 }
170
171 static void kprofinit(void)
172 {
173         uint32_t n;
174
175         static_assert(CELLSIZE == sizeof kprof.buf[0]); // kprof size
176
177         /* allocate when first used */
178         kprof.minpc = KERN_LOAD_ADDR;
179         kprof.maxpc = (uintptr_t) &etext;
180         kprof.nbuf = (kprof.maxpc-kprof.minpc) >> LRES;
181         n = kprof.nbuf*CELLSIZE;
182         kprof.buf = kzmalloc(n, KMALLOC_WAIT);
183         if (kprof.buf)
184                 kprof.buf_sz = n;
185
186         /* no, i'm not sure how we should do this yet. */
187         profiler_init();
188         oprof_alarms = kzmalloc(sizeof(struct alarm_waiter) * num_cores,
189                                 KMALLOC_WAIT);
190         if (!oprof_alarms)
191                 error(ENOMEM, NULL);
192
193         for (int i = 0; i < num_cores; i++)
194                 init_awaiter_irq(&oprof_alarms[i], oprof_alarm_handler);
195
196         kprof.systrace = qopen(2 << 20, 0, 0, 0);
197         if (!kprof.systrace) {
198                 printk("systrace allocate failed. No system call tracing\n");
199         }
200         kprof.mpstat_ipi = TRUE;
201
202         kproftab[Kprofdataqid].length = kprof.nbuf * FORMATSIZE;
203         kproftab[Kmpstatqid].length = mpstat_len();
204         kproftab[Kmpstatrawqid].length = mpstatraw_len();
205 }
206
207 static void kprofshutdown(void)
208 {
209         kfree(oprof_alarms); oprof_alarms = NULL;
210         kfree(kprof.buf); kprof.buf = NULL;
211         qfree(kprof.systrace); kprof.systrace = NULL;
212         profiler_cleanup();
213 }
214
215 static struct walkqid*
216 kprofwalk(struct chan *c, struct chan *nc, char **name, int nname)
217 {
218         return devwalk(c, nc, name, nname, kproftab, ARRAY_SIZE(kproftab), devgen);
219 }
220
221 static int
222 kprofstat(struct chan *c, uint8_t *db, int n)
223 {
224         kproftab[Kprofoprofileqid].length = profiler_size();
225         if (kprof.systrace)
226                 kproftab[Kptraceqid].length = qlen(kprof.systrace);
227         else
228                 kproftab[Kptraceqid].length = 0;
229
230         return devstat(c, db, n, kproftab, ARRAY_SIZE(kproftab), devgen);
231 }
232
233 static struct chan*
234 kprofopen(struct chan *c, int omode)
235 {
236         if(c->qid.type & QTDIR){
237                 if(openmode(omode) != O_READ)
238                         error(EPERM, NULL);
239         }
240         c->mode = openmode(omode);
241         c->flag |= COPEN;
242         c->offset = 0;
243         return c;
244 }
245
246 static void
247 kprofclose(struct chan*unused)
248 {
249 }
250
251 static size_t mpstat_len(void)
252 {
253         size_t each_row = 7 + NR_CPU_STATES * 26;
254         return each_row * (num_cores + 1) + 1;
255 }
256
257 static long mpstat_read(void *va, long n, int64_t off)
258 {
259         size_t bufsz = mpstat_len();
260         char *buf = kmalloc(bufsz, KMALLOC_WAIT);
261         int len = 0;
262         struct per_cpu_info *pcpui;
263         uint64_t cpu_total;
264         struct timespec ts;
265
266         /* the IPI interferes with other cores, might want to disable that. */
267         if (kprof.mpstat_ipi)
268                 send_broadcast_ipi(I_POKE_CORE);
269
270         len += snprintf(buf + len, bufsz - len, "  CPU: ");
271         for (int j = 0; j < NR_CPU_STATES; j++)
272                 len += snprintf(buf + len, bufsz - len, "%23s%s", cpu_state_names[j],
273                                 j != NR_CPU_STATES - 1 ? "   " : "  \n");
274
275         for (int i = 0; i < num_cores; i++) {
276                 pcpui = &per_cpu_info[i];
277                 cpu_total = 0;
278                 len += snprintf(buf + len, bufsz - len, "%5d: ", i);
279                 for (int j = 0; j < NR_CPU_STATES; j++)
280                         cpu_total += pcpui->state_ticks[j];
281                 cpu_total = MAX(cpu_total, 1);  /* for the divide later */
282                 for (int j = 0; j < NR_CPU_STATES; j++) {
283                         tsc2timespec(pcpui->state_ticks[j], &ts);
284                         len += snprintf(buf + len, bufsz - len, "%10d.%06d (%3d%%)%s",
285                                         ts.tv_sec, ts.tv_nsec / 1000,
286                                         MIN((pcpui->state_ticks[j] * 100) / cpu_total, 100),
287                                         j != NR_CPU_STATES - 1 ? ", " : " \n");
288                 }
289         }
290         n = readstr(off, va, n, buf);
291         kfree(buf);
292         return n;
293 }
294
295 static size_t mpstatraw_len(void)
296 {
297         size_t header_row = 27 + NR_CPU_STATES * 7 + 1;
298         size_t cpu_row = 7 + NR_CPU_STATES * 17;
299         return header_row + cpu_row * num_cores + 1;
300 }
301
302 static long mpstatraw_read(void *va, long n, int64_t off)
303 {
304         size_t bufsz = mpstatraw_len();
305         char *buf = kmalloc(bufsz, KMALLOC_WAIT);
306         int len = 0;
307         struct per_cpu_info *pcpui;
308
309         /* could spit it all out in binary, though then it'd be harder to process
310          * the data across a mnt (if we export #K).  probably not a big deal. */
311
312         /* header line: version, num_cores, tsc freq, state names */
313         len += snprintf(buf + len, bufsz - len, "v%03d %5d %16llu", 1, num_cores,
314                         system_timing.tsc_freq);
315         for (int j = 0; j < NR_CPU_STATES; j++)
316                 len += snprintf(buf + len, bufsz - len, " %6s", cpu_state_names[j]);
317         len += snprintf(buf + len, bufsz - len, "\n");
318
319         for (int i = 0; i < num_cores; i++) {
320                 pcpui = &per_cpu_info[i];
321                 len += snprintf(buf + len, bufsz - len, "%5d: ", i);
322                 for (int j = 0; j < NR_CPU_STATES; j++) {
323                         len += snprintf(buf + len, bufsz - len, "%16llx%s",
324                                         pcpui->state_ticks[j],
325                                         j != NR_CPU_STATES - 1 ? " " : "\n");
326                 }
327         }
328         n = readstr(off, va, n, buf);
329         kfree(buf);
330         return n;
331 }
332
333 static long
334 kprofread(struct chan *c, void *va, long n, int64_t off)
335 {
336         uint64_t w, *bp;
337         char *a, *ea;
338         uintptr_t offset = off;
339         uint64_t pc;
340         int snp_ret, ret = 0;
341
342         switch((int)c->qid.path){
343         case Kprofdirqid:
344                 return devdirread(c, va, n, kproftab, ARRAY_SIZE(kproftab), devgen);
345
346         case Kprofdataqid:
347
348                 if (n < FORMATSIZE){
349                         n = 0;
350                         break;
351                 }
352                 a = va;
353                 ea = a + n;
354
355                 /* we check offset later before deref bp.  offset / FORMATSIZE is how
356                  * many entries we're skipping/offsetting. */
357                 bp = kprof.buf + offset/FORMATSIZE;
358                 pc = kprof.minpc + ((offset/FORMATSIZE)<<LRES);
359                 while((a < ea) && (n >= FORMATSIZE)){
360                         /* what a pain. We need to manage the
361                          * fact that the *prints all make room for
362                          * \0
363                          */
364                         char print[FORMATSIZE+1];
365                         char *name;
366                         int amt_read;
367
368                         if (pc >= kprof.maxpc)
369                                 break;
370                         /* pc is also our exit for bp.  should be in lockstep */
371                         // XXX this assert fails, fix it!
372                         //assert(bp < kprof.buf + kprof.nbuf);
373                         /* do not attempt to filter these results based on w < threshold.
374                          * earlier, we computed bp/pc based on assuming a full-sized file,
375                          * and skipping entries will result in read() calls thinking they
376                          * received earlier entries when they really received later ones.
377                          * imagine a case where there are 1000 skipped items, and read()
378                          * asks for chunks of 32.  it'll get chunks of the next 32 valid
379                          * items, over and over (1000/32 times). */
380                         w = *bp++;
381
382                         if (pc == kprof.minpc)
383                                 name = "Total";
384                         else if (pc == kprof.minpc + 8)
385                                 name = "User";
386                         else
387                                 name = get_fn_name(pc);
388
389                         snp_ret = snprintf(print, sizeof(print), outformat, pc, name, w);
390                         assert(snp_ret == FORMATSIZE);
391                         if ((pc != kprof.minpc) && (pc != kprof.minpc + 8))
392                                 kfree(name);
393
394                         amt_read = readmem(offset % FORMATSIZE, a, n, print, FORMATSIZE);
395                         offset = 0;     /* future loops have no offset */
396
397                         a += amt_read;
398                         n -= amt_read;
399                         ret += amt_read;
400
401                         pc += (1 << LRES);
402                 }
403                 n = ret;
404                 break;
405         case Kprofoprofileqid:
406                 n = profiler_read(va, n);
407                 break;
408         case Kptraceqid:
409                 if (kprof.systrace) {
410                         printd("Kptraceqid: kprof.systrace %p len %p\n", kprof.systrace, qlen(kprof.systrace));
411                         if (qlen(kprof.systrace) > 0)
412                                 n = qread(kprof.systrace, va, n);
413                         else
414                                 n = 0;
415                 } else
416                         error(EFAIL, "no systrace queue");
417                 break;
418         case Kprintxqid:
419                 n = readstr(offset, va, n, printx_on ? "on" : "off");
420                 break;
421         case Kmpstatqid:
422                 n = mpstat_read(va, n, offset);
423                 break;
424         case Kmpstatrawqid:
425                 n = mpstatraw_read(va, n, offset);
426                 break;
427         default:
428                 n = 0;
429                 break;
430         }
431         return n;
432 }
433
434 static void kprof_clear(struct kprof *kp)
435 {
436         spin_lock(&kp->lock);
437         memset(kp->buf, 0, kp->buf_sz);
438         spin_unlock(&kp->lock);
439 }
440
441 static void manage_oprof_timer(int coreid, struct cmdbuf *cb)
442 {
443         struct timer_chain *tchain = &per_cpu_info[coreid].tchain;
444         struct alarm_waiter *waiter = &oprof_alarms[coreid];
445         if (!strcmp(cb->f[2], "on")) {
446                 /* pcpu waiters already inited.  will set/reset each time (1 ms
447                  * default). */
448                 reset_alarm_rel(tchain, waiter, oprof_timer_period);
449         } else if (!strcmp(cb->f[2], "off")) {
450                 /* since the alarm handler runs and gets reset within IRQ context, then
451                  * we should never fail to cancel the alarm if it was already running
452                  * (tchain locks synchronize us).  but it might not be set at all, which
453                  * is fine. */
454                 unset_alarm(tchain, waiter);
455         } else {
456                 error(EFAIL, "optimer needs on|off");
457         }
458 }
459
460 static long
461 kprofwrite(struct chan *c, void *a, long n, int64_t unused)
462 {
463         ERRSTACK(1);
464         uintptr_t pc;
465         struct cmdbuf *cb;
466         char *ctlstring = "startclr|start|stop|clear|opstart|opstop|optimer";
467         cb = parsecmd(a, n);
468
469         if (waserror()) {
470                 kfree(cb);
471                 nexterror();
472         }
473
474         switch((int)(c->qid.path)){
475         case Kprofctlqid:
476                 if (cb->nf < 1)
477                         error(EFAIL, ctlstring);
478
479                 /* Kprof: a "which kaddr are we at when the timer goes off".  not used
480                  * much anymore */
481                 if (!strcmp(cb->f[0], "startclr")) {
482                         kprof_clear(&kprof);
483                         kprof.time = 1;
484                 } else if (!strcmp(cb->f[0], "start")) {
485                         kprof.time = 1;
486                         /* this sets up the timer on the *calling* core! */
487                         setup_timers();
488                 } else if (!strcmp(cb->f[0], "stop")) {
489                         /* TODO: stop the timers! */
490                         kprof.time = 0;
491                 } else if (!strcmp(cb->f[0], "clear")) {
492                         kprof_clear(&kprof);
493
494                 /* oprof: samples and traces using oprofile */
495                 } else if (!strcmp(cb->f[0], "optimer")) {
496                         if (cb->nf < 3)
497                                 error(EFAIL, "optimer [<0|1|..|n|all> <on|off>] [period USEC]");
498                         if (!strcmp(cb->f[1], "period")) {
499                                 oprof_timer_period = strtoul(cb->f[2], 0, 10);
500                         } else if (!strcmp(cb->f[1], "all")) {
501                                 for (int i = 0; i < num_cores; i++)
502                                         manage_oprof_timer(i, cb);
503                         } else {
504                                 int pcoreid = strtoul(cb->f[1], 0, 10);
505                                 if (pcoreid >= num_cores)
506                                         error(EFAIL, "no such coreid %d", pcoreid);
507                                 manage_oprof_timer(pcoreid, cb);
508                         }
509                 } else if (!strcmp(cb->f[0], "opstart")) {
510                         profiler_control_trace(1);
511                 } else if (!strcmp(cb->f[0], "opstop")) {
512                         profiler_control_trace(0);
513                 } else {
514                         error(EFAIL, ctlstring);
515                 }
516                 break;
517
518                 /* The format is a long as text. We strtoul, and jam it into the
519                  * trace buffer.
520                  */
521         case Kprofoprofileqid:
522                 pc = strtoul(a, 0, 0);
523                 profiler_add_trace(pc);
524                 break;
525         case Kprintxqid:
526                 if (!strncmp(a, "on", 2))
527                         set_printx(1);
528                 else if (!strncmp(a, "off", 3))
529                         set_printx(0);
530                 else if (!strncmp(a, "toggle", 6))      /* why not. */
531                         set_printx(2);
532                 else
533                         error(EFAIL, "invalid option to Kprintx %s\n", a);
534                 break;
535         case Kmpstatqid:
536         case Kmpstatrawqid:
537                 if (cb->nf < 1)
538                         error(EFAIL, "mpstat bad option (reset|ipi|on|off)");
539                 if (!strcmp(cb->f[0], "reset")) {
540                         for (int i = 0; i < num_cores; i++)
541                                 reset_cpu_state_ticks(i);
542                 } else if (!strcmp(cb->f[0], "on")) {
543                         /* TODO: enable the ticks */ ;
544                 } else if (!strcmp(cb->f[0], "off")) {
545                         /* TODO: disable the ticks */ ;
546                 } else if (!strcmp(cb->f[0], "ipi")) {
547                         if (cb->nf < 2)
548                                 error(EFAIL, "need another arg: ipi [on|off]");
549                         if (!strcmp(cb->f[1], "on"))
550                                 kprof.mpstat_ipi = TRUE;
551                         else if (!strcmp(cb->f[1], "off"))
552                                 kprof.mpstat_ipi = FALSE;
553                         else
554                                 error(EFAIL, "ipi [on|off]");
555                 } else {
556                         error(EFAIL, "mpstat bad option (reset|ipi|on|off)");
557                 }
558                 break;
559         default:
560                 error(EBADFD, NULL);
561         }
562         kfree(cb);
563         poperror();
564         return n;
565 }
566
567 void kprof_write_sysrecord(char *pretty_buf, size_t len)
568 {
569         int wrote;
570         if (kprof.systrace) {
571                 /* TODO: need qio work so we can simply add the buf as extra data */
572                 wrote = qiwrite(kprof.systrace, pretty_buf, len);
573                 /* based on the current queue settings, we only drop when we're running
574                  * out of memory.  odds are, we won't make it this far. */
575                 if (wrote != len)
576                         printk("DROPPED %s", pretty_buf);
577         }
578 }
579
580 void trace_printk(const char *fmt, ...)
581 {
582         va_list ap;
583         struct timespec ts_now;
584         size_t bufsz = 160;     /* 2x terminal width */
585         size_t len = 0;
586         char *buf = kmalloc(bufsz, 0);
587
588         if (!buf)
589                 return;
590         tsc2timespec(read_tsc(), &ts_now);
591         len += snprintf(buf + len, bufsz - len, "[%7d.%09d] /* ", ts_now.tv_sec,
592                         ts_now.tv_nsec);
593         va_start(ap, fmt);
594         len += vsnprintf(buf + len, bufsz - len, fmt, ap);
595         va_start(ap, fmt);
596         va_end(ap);
597         len += snprintf(buf + len, bufsz - len, " */\n");
598         va_start(ap, fmt);
599         /* snprintf null terminates the buffer, and does not count that as part of
600          * the len.  if we maxed out the buffer, let's make sure it has a \n */
601         if (len == bufsz - 1) {
602                 assert(buf[bufsz - 1] == '\0');
603                 buf[bufsz - 2] = '\n';
604         }
605         kprof_write_sysrecord(buf, len);
606         kfree(buf);
607 }
608
609 struct dev kprofdevtab __devtab = {
610         .name = "kprof",
611
612         .reset = devreset,
613         .init = kprofinit,
614         .shutdown = kprofshutdown,
615         .attach = kprofattach,
616         .walk = kprofwalk,
617         .stat = kprofstat,
618         .open = kprofopen,
619         .create = devcreate,
620         .close = kprofclose,
621         .read = kprofread,
622         .bread = devbread,
623         .write = kprofwrite,
624         .bwrite = devbwrite,
625         .remove = devremove,
626         .wstat = devwstat,
627 };