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