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