Use core_id_early() in kprof trace buffer print code
[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 #include <arch/time.h>
11 #include <vfs.h>
12 #include <slab.h>
13 #include <kmalloc.h>
14 #include <kref.h>
15 #include <atomic.h>
16 #include <kthread.h>
17 #include <string.h>
18 #include <stdio.h>
19 #include <assert.h>
20 #include <error.h>
21 #include <pmap.h>
22 #include <smp.h>
23 #include <time.h>
24 #include <circular_buffer.h>
25 #include <umem.h>
26 #include <profiler.h>
27 #include <kprof.h>
28
29 #define KTRACE_BUFFER_SIZE (128 * 1024)
30 #define TRACE_PRINTK_BUFFER_SIZE (8 * 1024)
31
32 enum {
33         Kprofdirqid = 0,
34         Kprofdataqid,
35         Kprofctlqid,
36         Kptraceqid,
37         Kprintxqid,
38         Kmpstatqid,
39         Kmpstatrawqid,
40 };
41
42 struct trace_printk_buffer {
43         atomic_t in_use;
44         char buffer[TRACE_PRINTK_BUFFER_SIZE];
45 };
46
47 struct kprof {
48         qlock_t lock;
49         struct alarm_waiter *alarms;
50         bool mpstat_ipi;
51         bool profiling;
52         char *pdata;
53         size_t psize;
54 };
55
56 struct dev kprofdevtab;
57 struct dirtab kproftab[] = {
58         {".",                   {Kprofdirqid,           0, QTDIR}, 0,   DMDIR|0550},
59         {"kpdata",              {Kprofdataqid},         0,      0600},
60         {"kpctl",               {Kprofctlqid},          0,      0600},
61         {"kptrace",             {Kptraceqid},           0,      0600},
62         {"kprintx",             {Kprintxqid},           0,      0600},
63         {"mpstat",              {Kmpstatqid},           0,      0600},
64         {"mpstat-raw",  {Kmpstatrawqid},        0,      0600},
65 };
66
67 static struct kprof kprof;
68 static bool ktrace_init_done = FALSE;
69 static spinlock_t ktrace_lock = SPINLOCK_INITIALIZER_IRQSAVE;
70 static struct circular_buffer ktrace_data;
71 static char ktrace_buffer[KTRACE_BUFFER_SIZE];
72 static int kprof_timer_period = 1000;
73
74 static size_t mpstat_len(void)
75 {
76         size_t each_row = 7 + NR_CPU_STATES * 26;
77
78         return each_row * (num_cores + 1) + 1;
79 }
80
81 static size_t mpstatraw_len(void)
82 {
83         size_t header_row = 27 + NR_CPU_STATES * 7 + 1;
84         size_t cpu_row = 7 + NR_CPU_STATES * 17;
85
86         return header_row + cpu_row * num_cores + 1;
87 }
88
89 static char *devname(void)
90 {
91         return kprofdevtab.name;
92 }
93
94 static void kprof_alarm_handler(struct alarm_waiter *waiter,
95                                 struct hw_trapframe *hw_tf)
96 {
97         int coreid = core_id();
98         struct timer_chain *tchain = &per_cpu_info[coreid].tchain;
99
100         profiler_add_hw_sample(hw_tf);
101         reset_alarm_rel(tchain, waiter, kprof_timer_period);
102 }
103
104 static struct chan *kprof_attach(char *spec)
105 {
106         if (!kprof.alarms)
107                 error(ENOMEM, NULL);
108
109         return devattach(devname(), spec);
110 }
111
112 static void kprof_enable_timer(int coreid, int on_off)
113 {
114         struct timer_chain *tchain = &per_cpu_info[coreid].tchain;
115         struct alarm_waiter *waiter = &kprof.alarms[coreid];
116
117         if (on_off) {
118                 /* Per CPU waiters already inited.  Will set/reset each time (1 ms
119                  * default). */
120                 reset_alarm_rel(tchain, waiter, kprof_timer_period);
121         } else {
122                 /* Since the alarm handler runs and gets reset within IRQ context, then
123                  * we should never fail to cancel the alarm if it was already running
124                  * (tchain locks synchronize us).  But it might not be set at all, which
125                  * is fine. */
126                 unset_alarm(tchain, waiter);
127         }
128 }
129
130 static void kprof_profdata_clear(void)
131 {
132         kfree(kprof.pdata);
133         kprof.pdata = NULL;
134         kprof.psize = 0;
135 }
136
137 static void kprof_start_profiler(void)
138 {
139         ERRSTACK(2);
140
141         qlock(&kprof.lock);
142         if (waserror()) {
143                 qunlock(&kprof.lock);
144                 nexterror();
145         }
146         if (!kprof.profiling) {
147                 profiler_setup();
148                 if (waserror()) {
149                         profiler_cleanup();
150                         nexterror();
151                 }
152
153                 profiler_control_trace(1);
154
155                 for (int i = 0; i < num_cores; i++)
156                         kprof_enable_timer(i, 1);
157
158                 kprof.profiling = TRUE;
159
160                 kprof_profdata_clear();
161         }
162         poperror();
163         poperror();
164         qunlock(&kprof.lock);
165 }
166
167 static void kprof_fetch_profiler_data(void)
168 {
169         size_t psize = profiler_size();
170
171         kprof.pdata = kmalloc(psize, KMALLOC_WAIT);
172         if (!kprof.pdata)
173                 error(ENOMEM, NULL);
174         kprof.psize = 0;
175         while (kprof.psize < psize) {
176                 size_t csize = profiler_read(kprof.pdata + kprof.psize,
177                                                                          psize - kprof.psize);
178
179                 if (csize == 0)
180                         break;
181                 kprof.psize += csize;
182         }
183 }
184
185 static void kprof_stop_profiler(void)
186 {
187         ERRSTACK(1);
188
189         qlock(&kprof.lock);
190         if (waserror()) {
191                 qunlock(&kprof.lock);
192                 nexterror();
193         }
194         if (kprof.profiling) {
195                 for (int i = 0; i < num_cores; i++)
196                         kprof_enable_timer(i, 0);
197                 profiler_control_trace(0);
198                 kprof_fetch_profiler_data();
199                 profiler_cleanup();
200
201                 kprof.profiling = FALSE;
202         }
203         poperror();
204         qunlock(&kprof.lock);
205 }
206
207 static void kprof_init(void)
208 {
209         int i;
210         ERRSTACK(1);
211
212         profiler_init();
213
214         qlock_init(&kprof.lock);
215         kprof.profiling = FALSE;
216         kprof.pdata = NULL;
217         kprof.psize = 0;
218
219         kprof.alarms = kzmalloc(sizeof(struct alarm_waiter) * num_cores,
220                                                         KMALLOC_WAIT);
221         if (!kprof.alarms)
222                 error(ENOMEM, NULL);
223         if (waserror()) {
224                 kfree(kprof.alarms);
225                 kprof.alarms = NULL;
226                 nexterror();
227         }
228         for (i = 0; i < num_cores; i++)
229                 init_awaiter_irq(&kprof.alarms[i], kprof_alarm_handler);
230
231         for (i = 0; i < ARRAY_SIZE(kproftab); i++)
232                 kproftab[i].length = 0;
233
234         kprof.mpstat_ipi = TRUE;
235         kproftab[Kmpstatqid].length = mpstat_len();
236         kproftab[Kmpstatrawqid].length = mpstatraw_len();
237
238         poperror();
239 }
240
241 static void kprof_shutdown(void)
242 {
243         kprof_stop_profiler();
244         kprof_profdata_clear();
245
246         kfree(kprof.alarms);
247         kprof.alarms = NULL;
248 }
249
250 static void kprofclear(void)
251 {
252         qlock(&kprof.lock);
253         kprof_profdata_clear();
254         qunlock(&kprof.lock);
255 }
256
257 static struct walkqid *kprof_walk(struct chan *c, struct chan *nc, char **name,
258                                                                  int nname)
259 {
260         return devwalk(c, nc, name, nname, kproftab, ARRAY_SIZE(kproftab), devgen);
261 }
262
263 static size_t kprof_profdata_size(void)
264 {
265         return kprof.pdata != NULL ? kprof.psize : profiler_size();
266 }
267
268 static long kprof_profdata_read(void *dest, long size, int64_t off)
269 {
270         qlock(&kprof.lock);
271         if (kprof.pdata && off < kprof.psize) {
272                 size = MIN(kprof.psize - off, size);
273                 memcpy(dest, kprof.pdata + off, size);
274         } else {
275                 size = 0;
276         }
277         qunlock(&kprof.lock);
278
279         return size;
280 }
281
282 static int kprof_stat(struct chan *c, uint8_t *db, int n)
283 {
284         kproftab[Kprofdataqid].length = kprof_profdata_size();
285         kproftab[Kptraceqid].length = kprof_tracedata_size();
286
287         return devstat(c, db, n, kproftab, ARRAY_SIZE(kproftab), devgen);
288 }
289
290 static struct chan *kprof_open(struct chan *c, int omode)
291 {
292         if (c->qid.type & QTDIR) {
293                 if (openmode(omode) != O_READ)
294                         error(EPERM, NULL);
295         }
296         c->mode = openmode(omode);
297         c->flag |= COPEN;
298         c->offset = 0;
299         return c;
300 }
301
302 static void kprof_close(struct chan *c)
303 {
304 }
305
306 static long mpstat_read(void *va, long n, int64_t off)
307 {
308         size_t bufsz = mpstat_len();
309         char *buf = kmalloc(bufsz, KMALLOC_WAIT);
310         int len = 0;
311         struct per_cpu_info *pcpui;
312         uint64_t cpu_total;
313         struct timespec ts;
314
315         /* the IPI interferes with other cores, might want to disable that. */
316         if (kprof.mpstat_ipi)
317                 send_broadcast_ipi(I_POKE_CORE);
318
319         len += snprintf(buf + len, bufsz - len, "  CPU: ");
320         for (int j = 0; j < NR_CPU_STATES; j++)
321                 len += snprintf(buf + len, bufsz - len, "%23s%s", cpu_state_names[j],
322                                 j != NR_CPU_STATES - 1 ? "   " : "  \n");
323
324         for (int i = 0; i < num_cores; i++) {
325                 pcpui = &per_cpu_info[i];
326                 cpu_total = 0;
327                 len += snprintf(buf + len, bufsz - len, "%5d: ", i);
328                 for (int j = 0; j < NR_CPU_STATES; j++)
329                         cpu_total += pcpui->state_ticks[j];
330                 cpu_total = MAX(cpu_total, 1);  /* for the divide later */
331                 for (int j = 0; j < NR_CPU_STATES; j++) {
332                         tsc2timespec(pcpui->state_ticks[j], &ts);
333                         len += snprintf(buf + len, bufsz - len, "%10d.%06d (%3d%%)%s",
334                                         ts.tv_sec, ts.tv_nsec / 1000,
335                                         MIN((pcpui->state_ticks[j] * 100) / cpu_total, 100),
336                                         j != NR_CPU_STATES - 1 ? ", " : " \n");
337                 }
338         }
339         n = readstr(off, va, n, buf);
340         kfree(buf);
341         return n;
342 }
343
344 static long mpstatraw_read(void *va, long n, int64_t off)
345 {
346         size_t bufsz = mpstatraw_len();
347         char *buf = kmalloc(bufsz, KMALLOC_WAIT);
348         int len = 0;
349         struct per_cpu_info *pcpui;
350
351         /* could spit it all out in binary, though then it'd be harder to process
352          * the data across a mnt (if we export #K).  probably not a big deal. */
353
354         /* header line: version, num_cores, tsc freq, state names */
355         len += snprintf(buf + len, bufsz - len, "v%03d %5d %16llu", 1, num_cores,
356                         system_timing.tsc_freq);
357         for (int j = 0; j < NR_CPU_STATES; j++)
358                 len += snprintf(buf + len, bufsz - len, " %6s", cpu_state_names[j]);
359         len += snprintf(buf + len, bufsz - len, "\n");
360
361         for (int i = 0; i < num_cores; i++) {
362                 pcpui = &per_cpu_info[i];
363                 len += snprintf(buf + len, bufsz - len, "%5d: ", i);
364                 for (int j = 0; j < NR_CPU_STATES; j++) {
365                         len += snprintf(buf + len, bufsz - len, "%16llx%s",
366                                         pcpui->state_ticks[j],
367                                         j != NR_CPU_STATES - 1 ? " " : "\n");
368                 }
369         }
370         n = readstr(off, va, n, buf);
371         kfree(buf);
372         return n;
373 }
374
375 static long kprof_read(struct chan *c, void *va, long n, int64_t off)
376 {
377         uint64_t w, *bp;
378         char *a, *ea;
379         uintptr_t offset = off;
380         uint64_t pc;
381
382         switch ((int) c->qid.path) {
383         case Kprofdirqid:
384                 return devdirread(c, va, n, kproftab, ARRAY_SIZE(kproftab), devgen);
385         case Kprofdataqid:
386                 n = kprof_profdata_read(va, n, off);
387                 break;
388         case Kptraceqid:
389                 n = kprof_tracedata_read(va, n, off);
390                 break;
391         case Kprintxqid:
392                 n = readstr(offset, va, n, printx_on ? "on" : "off");
393                 break;
394         case Kmpstatqid:
395                 n = mpstat_read(va, n, offset);
396                 break;
397         case Kmpstatrawqid:
398                 n = mpstatraw_read(va, n, offset);
399                 break;
400         default:
401                 n = 0;
402                 break;
403         }
404         return n;
405 }
406
407 static void kprof_manage_timer(int coreid, struct cmdbuf *cb)
408 {
409         if (!strcmp(cb->f[2], "on")) {
410                 kprof_enable_timer(coreid, 1);
411         } else if (!strcmp(cb->f[2], "off")) {
412                 kprof_enable_timer(coreid, 0);
413         } else {
414                 error(EFAIL, "timer needs on|off");
415         }
416 }
417
418 static void kprof_usage_fail(void)
419 {
420         static const char *ctlstring = "clear|start|stop|timer";
421         const char * const *cmds = profiler_configure_cmds();
422         char msgbuf[128];
423
424         strlcpy(msgbuf, ctlstring, sizeof(msgbuf));
425         for (int i = 0; cmds[i]; i++) {
426                 strlcat(msgbuf, "|", sizeof(msgbuf));
427                 strlcat(msgbuf, cmds[i], sizeof(msgbuf));
428         }
429
430         error(EFAIL, msgbuf);
431 }
432
433 static long kprof_write(struct chan *c, void *a, long n, int64_t unused)
434 {
435         ERRSTACK(1);
436         struct cmdbuf *cb = parsecmd(a, n);
437
438         if (waserror()) {
439                 kfree(cb);
440                 nexterror();
441         }
442         switch ((int) c->qid.path) {
443         case Kprofctlqid:
444                 if (cb->nf < 1)
445                         kprof_usage_fail();
446                 if (profiler_configure(cb))
447                         break;
448                 if (!strcmp(cb->f[0], "clear")) {
449                         kprofclear();
450                 } else if (!strcmp(cb->f[0], "timer")) {
451                         if (cb->nf < 3)
452                                 error(EFAIL, "timer {{all, N} {on, off}, period USEC}");
453                         if (!strcmp(cb->f[1], "period")) {
454                                 kprof_timer_period = strtoul(cb->f[2], 0, 10);
455                         } else if (!strcmp(cb->f[1], "all")) {
456                                 for (int i = 0; i < num_cores; i++)
457                                         kprof_manage_timer(i, cb);
458                         } else {
459                                 int pcoreid = strtoul(cb->f[1], 0, 10);
460
461                                 if (pcoreid >= num_cores)
462                                         error(EFAIL, "No such coreid %d", pcoreid);
463                                 kprof_manage_timer(pcoreid, cb);
464                         }
465                 } else if (!strcmp(cb->f[0], "start")) {
466                         kprof_start_profiler();
467                 } else if (!strcmp(cb->f[0], "stop")) {
468                         kprof_stop_profiler();
469                 } else {
470                         kprof_usage_fail();
471                 }
472                 break;
473         case Kprofdataqid:
474                 profiler_add_trace((uintptr_t) strtoul(a, 0, 0));
475                 break;
476         case Kptraceqid:
477                 if (a && (n > 0)) {
478                         char *uptr = user_strdup_errno(current, a, n);
479
480                         if (uptr) {
481                                 trace_printk(false, "%s", uptr);
482                                 user_memdup_free(current, uptr);
483                         } else {
484                                 n = -1;
485                         }
486                 }
487                 break;
488         case Kprintxqid:
489                 if (!strncmp(a, "on", 2))
490                         set_printx(1);
491                 else if (!strncmp(a, "off", 3))
492                         set_printx(0);
493                 else if (!strncmp(a, "toggle", 6))
494                         set_printx(2);
495                 else
496                         error(EFAIL, "Invalid option to Kprintx %s\n", a);
497                 break;
498         case Kmpstatqid:
499         case Kmpstatrawqid:
500                 if (cb->nf < 1)
501                         error(EFAIL, "Bad mpstat option (reset|ipi|on|off)");
502                 if (!strcmp(cb->f[0], "reset")) {
503                         for (int i = 0; i < num_cores; i++)
504                                 reset_cpu_state_ticks(i);
505                 } else if (!strcmp(cb->f[0], "on")) {
506                         /* TODO: enable the ticks */ ;
507                 } else if (!strcmp(cb->f[0], "off")) {
508                         /* TODO: disable the ticks */ ;
509                 } else if (!strcmp(cb->f[0], "ipi")) {
510                         if (cb->nf < 2)
511                                 error(EFAIL, "Need another arg: ipi [on|off]");
512                         if (!strcmp(cb->f[1], "on"))
513                                 kprof.mpstat_ipi = TRUE;
514                         else if (!strcmp(cb->f[1], "off"))
515                                 kprof.mpstat_ipi = FALSE;
516                         else
517                                 error(EFAIL, "ipi [on|off]");
518                 } else {
519                         error(EFAIL, "Bad mpstat option (reset|ipi|on|off)");
520                 }
521                 break;
522         default:
523                 error(EBADFD, NULL);
524         }
525         kfree(cb);
526         poperror();
527         return n;
528 }
529
530 size_t kprof_tracedata_size(void)
531 {
532         return circular_buffer_size(&ktrace_data);
533 }
534
535 size_t kprof_tracedata_read(void *data, size_t size, size_t offset)
536 {
537         spin_lock_irqsave(&ktrace_lock);
538         if (likely(ktrace_init_done))
539                 size = circular_buffer_read(&ktrace_data, data, size, offset);
540         else
541                 size = 0;
542         spin_unlock_irqsave(&ktrace_lock);
543
544         return size;
545 }
546
547 void kprof_tracedata_write(const char *pretty_buf, size_t len)
548 {
549         spin_lock_irqsave(&ktrace_lock);
550         if (unlikely(!ktrace_init_done)) {
551                 circular_buffer_init(&ktrace_data, sizeof(ktrace_buffer),
552                                                          ktrace_buffer);
553                 ktrace_init_done = TRUE;
554         }
555         circular_buffer_write(&ktrace_data, pretty_buf, len);
556         spin_unlock_irqsave(&ktrace_lock);
557 }
558
559 static struct trace_printk_buffer *kprof_get_printk_buffer(void)
560 {
561         static struct trace_printk_buffer boot_tpb;
562         static struct trace_printk_buffer *cpu_tpbs;
563         static atomic_t alloc_done;
564
565         if (unlikely(!num_cores))
566                 return &boot_tpb;
567         if (unlikely(!cpu_tpbs)) {
568                 /* Poor man per-CPU data structure. I really do no like littering global
569                  * data structures with module specific data.
570                  * We cannot take the ktrace_lock to protect the kzmalloc() call, as
571                  * that might trigger printk()s, and we would reenter here.
572                  * Let only one core into the kzmalloc() path, and let the others get
573                  * the boot_tpb until finished.
574                  */
575                 if (!atomic_cas(&alloc_done, 0, 1))
576                         return &boot_tpb;
577                 cpu_tpbs = kzmalloc(num_cores * sizeof(struct trace_printk_buffer), 0);
578         }
579
580         return cpu_tpbs + core_id_early();
581 }
582
583 void trace_vprintk(bool btrace, const char *fmt, va_list args)
584 {
585         struct print_buf {
586                 char *ptr;
587                 char *top;
588         };
589
590         void emit_print_buf_str(struct print_buf *pb, const char *str, ssize_t size)
591         {
592                 if (size < 0) {
593                         for (; *str && (pb->ptr < pb->top); str++)
594                                 *(pb->ptr++) = *str;
595                 } else {
596                         for (; (size > 0) && (pb->ptr < pb->top); str++, size--)
597                                 *(pb->ptr++) = *str;
598                 }
599         }
600
601         void bt_print(void *opaque, const char *str)
602         {
603                 struct print_buf *pb = (struct print_buf *) opaque;
604
605                 emit_print_buf_str(pb, "\t", 1);
606                 emit_print_buf_str(pb, str, -1);
607         }
608
609         static const size_t bufsz = TRACE_PRINTK_BUFFER_SIZE;
610         static const size_t usr_bufsz = (3 * bufsz) / 8;
611         static const size_t kp_bufsz = bufsz - usr_bufsz;
612         struct trace_printk_buffer *tpb = kprof_get_printk_buffer();
613         struct timespec ts_now = { 0, 0 };
614         struct print_buf pb;
615         char *usrbuf = tpb->buffer, *kpbuf = tpb->buffer + usr_bufsz;
616         const char *utop, *uptr;
617         char hdr[64];
618
619         if (!atomic_cas(&tpb->in_use, 0, 1))
620                 return;
621         if (likely(system_timing.tsc_freq))
622                 tsc2timespec(read_tsc(), &ts_now);
623         snprintf(hdr, sizeof(hdr), "[%lu.%09lu]:cpu%d: ", ts_now.tv_sec,
624                          ts_now.tv_nsec, core_id_early());
625
626         pb.ptr = usrbuf + vsnprintf(usrbuf, usr_bufsz, fmt, args);
627         pb.top = usrbuf + usr_bufsz;
628
629         if (pb.ptr[-1] != '\n')
630                 emit_print_buf_str(&pb, "\n", 1);
631         if (btrace) {
632                 emit_print_buf_str(&pb, "\tBacktrace:\n", -1);
633                 gen_backtrace(bt_print, &pb);
634         }
635         /* snprintf null terminates the buffer, and does not count that as part of
636          * the len.  If we maxed out the buffer, let's make sure it has a \n.
637          */
638         if (pb.ptr == pb.top)
639                 pb.ptr[-1] = '\n';
640         utop = pb.ptr;
641
642         pb.ptr = kpbuf;
643         pb.top = kpbuf + kp_bufsz;
644         for (uptr = usrbuf; uptr < utop;) {
645                 const char *nlptr = memchr(uptr, '\n', utop - uptr);
646
647                 if (nlptr == NULL)
648                         nlptr = utop;
649                 emit_print_buf_str(&pb, hdr, -1);
650                 emit_print_buf_str(&pb, uptr, (nlptr - uptr) + 1);
651                 uptr = nlptr + 1;
652         }
653         kprof_tracedata_write(kpbuf, pb.ptr - kpbuf);
654         atomic_set(&tpb->in_use, 0);
655 }
656
657 void trace_printk(bool btrace, const char *fmt, ...)
658 {
659         va_list args;
660
661         va_start(args, fmt);
662         trace_vprintk(btrace, fmt, args);
663         va_end(args);
664 }
665
666 struct dev kprofdevtab __devtab = {
667         .name = "kprof",
668
669         .reset = devreset,
670         .init = kprof_init,
671         .shutdown = kprof_shutdown,
672         .attach = kprof_attach,
673         .walk = kprof_walk,
674         .stat = kprof_stat,
675         .open = kprof_open,
676         .create = devcreate,
677         .close = kprof_close,
678         .read = kprof_read,
679         .bread = devbread,
680         .write = kprof_write,
681         .bwrite = devbwrite,
682         .remove = devremove,
683         .wstat = devwstat,
684 };