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