Printx commands (off by default)
[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 };
55 struct kprof kprof;
56
57 /* output format. Nice fixed size. That makes it seekable.
58  * small subtle bit here. You have to convert offset FROM FORMATSIZE units
59  * to CELLSIZE units in a few places.
60  */
61 char *outformat = "%016llx %29.29s %016llx\n";
62 #define FORMATSIZE 64
63 enum{
64         Kprofdirqid,
65         Kprofdataqid,
66         Kprofctlqid,
67         Kprofoprofileqid,
68         Kptraceqid,
69         Kprintxqid,
70 };
71 struct dirtab kproftab[]={
72         {".",           {Kprofdirqid, 0, QTDIR},0,      DMDIR|0550},
73         {"kpdata",      {Kprofdataqid},         0,      0600},
74         {"kpctl",       {Kprofctlqid},          0,      0600},
75         {"kpoprofile",  {Kprofoprofileqid},     0,      0600},
76         {"kptrace",     {Kptraceqid},           0,      0600},
77         {"kprintx",     {Kprintxqid},           0,      0600},
78 };
79
80 static struct chan*
81 kprofattach(char *spec)
82 {
83         uint32_t n;
84
85         /* allocate when first used */
86         kprof.minpc = 0xffffffffc2000000; //KERN_LOAD_ADDR;
87         kprof.maxpc = (uintptr_t)&etext;
88         kprof.nbuf = (kprof.maxpc-kprof.minpc) >> LRES;
89         n = kprof.nbuf*CELLSIZE;
90         if(kprof.buf == 0) {
91                 printk("Allocate %d bytes\n", n);
92                 kprof.buf = kzmalloc(n, KMALLOC_WAIT);
93                 if(kprof.buf == 0)
94                         error(Enomem);
95         }
96         kproftab[1].length = kprof.nbuf * FORMATSIZE;
97         kprof.buf_sz = n;
98         /* NO, I'm not sure how we should do this yet. */
99         int alloc_cpu_buffers(void);
100         alloc_cpu_buffers();
101         kprof.systrace = qopen(2 << 20, 0, 0, 0);
102         if (! kprof.systrace) {
103                 printk("systrace allocate failed. No system call tracing\n");
104         }
105         return devattach('K', spec);
106 }
107
108 static void
109 kproftimer(uintptr_t pc)
110 {
111         if(kprof.time == 0)
112                 return;
113
114         /*
115          * if the pc corresponds to the idle loop, don't consider it.
116
117         if(m->inidle)
118                 return;
119          */
120         /*
121          *  if the pc is coming out of spllo or splx,
122          *  use the pc saved when we went splhi.
123
124         if(pc>=PTR2UINT(spllo) && pc<=PTR2UINT(spldone))
125                 pc = m->splpc;
126          */
127
128 //      ilock(&kprof);
129         /* this is weird. What we do is assume that all the time since the last
130          * measurement went into this PC. It's the best
131          * we can do I suppose. And we are sampling at 1 ms. for now.
132          * better ideas welcome.
133          */
134         kprof.buf[0] += 1; //Total count of ticks.
135         if(kprof.minpc<=pc && pc<kprof.maxpc){
136                 pc -= kprof.minpc;
137                 pc >>= LRES;
138                 kprof.buf[pc] += 1;
139         }else
140                 kprof.buf[1] += 1; // Why?
141 //      iunlock(&kprof);
142 }
143
144 static void setup_timers(void)
145 {
146         void kprof_alarm(struct alarm_waiter *waiter, struct hw_trapframe *hw_tf)
147         {
148                 struct timer_chain *tchain = &per_cpu_info[core_id()].tchain;
149                 kproftimer(get_hwtf_pc(hw_tf));
150                 set_awaiter_rel(waiter, 1000);
151                 __set_alarm(tchain, waiter);
152         }
153         struct timer_chain *tchain = &per_cpu_info[core_id()].tchain;
154         struct alarm_waiter *waiter = kmalloc(sizeof(struct alarm_waiter), 0);
155         init_awaiter_irq(waiter, kprof_alarm);
156         set_awaiter_rel(waiter, 1000);
157         set_alarm(tchain, waiter);
158 }
159
160 static void
161 kprofinit(void)
162 {
163         if(CELLSIZE != sizeof kprof.buf[0])
164                 panic("kprof size");
165 }
166
167 static struct walkqid*
168 kprofwalk(struct chan *c, struct chan *nc, char **name, int nname)
169 {
170         return devwalk(c, nc, name, nname, kproftab, ARRAY_SIZE(kproftab), devgen);
171 }
172
173 static int
174 kprofstat(struct chan *c, uint8_t *db, int n)
175 {
176         /* barf. */
177         kproftab[3].length = oproflen();
178         /* twice */
179         if (kprof.systrace)
180                 kproftab[4].length = qlen(kprof.systrace);
181         else
182                 kproftab[4].length = 0;
183
184         return devstat(c, db, n, kproftab, ARRAY_SIZE(kproftab), devgen);
185 }
186
187 static struct chan*
188 kprofopen(struct chan *c, int omode)
189 {
190         if(c->qid.type & QTDIR){
191                 if(omode != OREAD)
192                         error(Eperm);
193         }
194         c->mode = openmode(omode);
195         c->flag |= COPEN;
196         c->offset = 0;
197         return c;
198 }
199
200 static void
201 kprofclose(struct chan*unused)
202 {
203 }
204
205 static long
206 kprofread(struct chan *c, void *va, long n, int64_t off)
207 {
208         uint64_t w, *bp;
209         char *a, *ea;
210         uintptr_t offset = off;
211         uint64_t pc;
212         int snp_ret, ret = 0;
213
214         switch((int)c->qid.path){
215         case Kprofdirqid:
216                 return devdirread(c, va, n, kproftab, ARRAY_SIZE(kproftab), devgen);
217
218         case Kprofdataqid:
219
220                 if (n < FORMATSIZE){
221                         n = 0;
222                         break;
223                 }
224                 a = va;
225                 ea = a + n;
226
227                 /* we check offset later before deref bp.  offset / FORMATSIZE is how
228                  * many entries we're skipping/offsetting. */
229                 bp = kprof.buf + offset/FORMATSIZE;
230                 pc = kprof.minpc + ((offset/FORMATSIZE)<<LRES);
231                 while((a < ea) && (n >= FORMATSIZE)){
232                         /* what a pain. We need to manage the
233                          * fact that the *prints all make room for
234                          * \0
235                          */
236                         char print[FORMATSIZE+1];
237                         char *name;
238                         int amt_read;
239
240                         if (pc >= kprof.maxpc)
241                                 break;
242                         /* pc is also our exit for bp.  should be in lockstep */
243                         // XXX this assert fails, fix it!
244                         //assert(bp < kprof.buf + kprof.nbuf);
245                         /* do not attempt to filter these results based on w < threshold.
246                          * earlier, we computed bp/pc based on assuming a full-sized file,
247                          * and skipping entries will result in read() calls thinking they
248                          * received earlier entries when they really received later ones.
249                          * imagine a case where there are 1000 skipped items, and read()
250                          * asks for chunks of 32.  it'll get chunks of the next 32 valid
251                          * items, over and over (1000/32 times). */
252                         w = *bp++;
253
254                         if (pc == kprof.minpc)
255                                 name = "Total";
256                         else if (pc == kprof.minpc + 8)
257                                 name = "User";
258                         else
259                                 name = get_fn_name(pc);
260
261                         snp_ret = snprintf(print, sizeof(print), outformat, pc, name, w);
262                         assert(snp_ret == FORMATSIZE);
263                         if ((pc != kprof.minpc) && (pc != kprof.minpc + 8))
264                                 kfree(name);
265
266                         amt_read = readmem(offset % FORMATSIZE, a, n, print, FORMATSIZE);
267                         offset = 0;     /* future loops have no offset */
268
269                         a += amt_read;
270                         n -= amt_read;
271                         ret += amt_read;
272
273                         pc += (1 << LRES);
274                 }
275                 n = ret;
276                 break;
277         case Kprofoprofileqid:
278                 n = oprofread(va,n);
279                 break;
280         case Kptraceqid:
281                 if (kprof.systrace) {
282                         printd("Kptraceqid: kprof.systrace %p len %p\n", kprof.systrace, qlen(kprof.systrace));
283                         if (qlen(kprof.systrace) > 0)
284                                 n = qread(kprof.systrace, va, n);
285                         else
286                                 n = 0;
287                 } else
288                         error("no systrace queue");
289                 break;
290         case Kprintxqid:
291                 n = readstr(offset, va, n, printx_on ? "on" : "off");
292                 break;
293         default:
294                 n = 0;
295                 break;
296         }
297         return n;
298 }
299
300 static void kprof_clear(struct kprof *kp)
301 {
302         spin_lock(&kp->lock);
303         memset(kp->buf, 0, kp->buf_sz);
304         spin_unlock(&kp->lock);
305 }
306
307 static long
308 kprofwrite(struct chan *c, void *a, long n, int64_t unused)
309 {
310         uintptr_t pc;
311         switch((int)(c->qid.path)){
312         case Kprofctlqid:
313                 if(strncmp(a, "startclr", 8) == 0){
314                         kprof_clear(&kprof);
315                         kprof.time = 1;
316                 }else if(strncmp(a, "start", 5) == 0) {
317                         kprof.time = 1;
318                         /* this sets up the timer on the *calling* core! */
319                         setup_timers();
320                 } else if(strncmp(a, "stop", 4) == 0) {
321                         /* TODO: stop the timers! */
322                         kprof.time = 0;
323                 } else if(strncmp(a, "clear", 5) == 0) {
324                         kprof_clear(&kprof);
325                 }else if(strncmp(a, "opstart", 7) == 0) {
326                         oprofile_control_trace(1);
327                 }else if(strncmp(a, "opstop", 6) == 0) {
328                         oprofile_control_trace(0);
329                 } else  {
330                         printk("startclr|start|stop|clear|opstart|opstop");
331                         error("startclr|start|stop|clear|opstart|opstop");
332                 }
333                 break;
334
335                 /* The format is a long as text. We strtoul, and jam it into the
336                  * trace buffer.
337                  */
338         case Kprofoprofileqid:
339                 pc = strtoul(a, 0, 0);
340                 oprofile_add_trace(pc);
341                 break;
342         case Kprintxqid:
343                 if (!strncmp(a, "on", 2))
344                         set_printx(1);
345                 else if (!strncmp(a, "off", 3))
346                         set_printx(0);
347                 else if (!strncmp(a, "toggle", 6))      /* why not. */
348                         set_printx(2);
349                 else
350                         error("invalid option to Kprintx %s\n", a);
351                 break;
352         default:
353                 error(Ebadusefd);
354         }
355         return n;
356 }
357
358 void kprof_write_sysrecord(char *pretty_buf, size_t len)
359 {
360         int wrote;
361         if (kprof.systrace) {
362                 /* TODO: need qio work so we can simply add the buf as extra data */
363                 wrote = qiwrite(kprof.systrace, pretty_buf, len);
364                 /* based on the current queue settings, we only drop when we're running
365                  * out of memory.  odds are, we won't make it this far. */
366                 if (wrote != len)
367                         printk("DROPPED %s", pretty_buf);
368         }
369 }
370
371 void trace_printk(const char *fmt, ...)
372 {
373         va_list ap;
374         struct timespec ts_now;
375         size_t bufsz = 160;     /* 2x terminal width */
376         size_t len = 0;
377         char *buf = kmalloc(bufsz, 0);
378
379         if (!buf)
380                 return;
381         tsc2timespec(read_tsc(), &ts_now);
382         len += snprintf(buf + len, bufsz - len, "[%7d.%09d] /* ", ts_now.tv_sec,
383                         ts_now.tv_nsec);
384         va_start(ap, fmt);
385         len += vsnprintf(buf + len, bufsz - len, fmt, ap);
386         va_start(ap, fmt);
387         va_end(ap);
388         len += snprintf(buf + len, bufsz - len, " */\n");
389         va_start(ap, fmt);
390         /* snprintf null terminates the buffer, and does not count that as part of
391          * the len.  if we maxed out the buffer, let's make sure it has a \n */
392         if (len == bufsz - 1) {
393                 assert(buf[bufsz - 1] == '\0');
394                 buf[bufsz - 2] = '\n';
395         }
396         kprof_write_sysrecord(buf, len);
397         kfree(buf);
398 }
399
400 struct dev kprofdevtab __devtab = {
401         'K',
402         "kprof",
403
404         devreset,
405         kprofinit,
406         devshutdown,
407         kprofattach,
408         kprofwalk,
409         kprofstat,
410         kprofopen,
411         devcreate,
412         kprofclose,
413         kprofread,
414         devbread,
415         kprofwrite,
416         devbwrite,
417         devremove,
418         devwstat,
419 };