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