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