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