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