ref: e8cf7530517534ccd9f5b0469191aa7c41581120
dir: /sys/src/cmd/trace.c/
#include <u.h> #include <tos.h> #include <libc.h> #include <thread.h> #include <ip.h> #include <draw.h> #include <mouse.h> #include <cursor.h> #include <keyboard.h> #include "trace.h" #pragma varargck type "t" vlong #pragma varargck type "U" uvlong #define NS(x) ((vlong)x) #define US(x) (NS(x) * 1000ULL) #define MS(x) (US(x) * 1000ULL) #define S(x) (MS(x) * 1000ULL) #define numblocks(a, b) (((a) + (b) - 1) / (b)) #define roundup(a, b) (numblocks((a), (b)) * (b)) enum { OneRound = MS(1)/2LL, MilliRound = US(1)/2LL, }; typedef struct Event Event; typedef struct Task Task; struct Event { Traceevent; vlong etime; /* length of block to draw */ }; struct Task { int pid; char *name; int nevents; Event *events; vlong tstart; vlong total; vlong runtime; vlong runmax; vlong runthis; long runs; ulong tevents[Nevent]; }; enum { Nevents = 1024, Ncolor = 6, K = 1024, }; vlong now, prevts; int newwin; int Width = 1000; int Height = 100; // Per task int topmargin = 8; int bottommargin = 4; int lineht = 12; int wctlfd; int nevents; Traceevent *eventbuf; Event *event; void drawtrace(void); int schedparse(char*, char*, char*); int timeconv(Fmt*); char *schedstatename[] = { [SAdmit] = "Admit", [SSleep] = "Sleep", [SDead] = "Dead", [SDeadline] = "Deadline", [SEdf] = "Edf", [SExpel] = "Expel", [SReady] = "Ready", [SRelease] = "Release", [SRun] = "Run", [SSlice] = "Slice", [SInts] = "Ints", [SInte] = "Inte", [SUser] = "User", [SYield] = "Yield", }; struct { vlong scale; vlong bigtics; vlong littletics; int sleep; } scales[] = { { US(500), US(100), US(50), 0}, { US(1000), US(500), US(100), 0}, { US(2000), US(1000), US(200), 0}, { US(5000), US(1000), US(500), 0}, { MS(10), MS(5), MS(1), 20}, { MS(20), MS(10), MS(2), 20}, { MS(50), MS(10), MS(5), 20}, { MS(100), MS(50), MS(10), 20}, /* starting scaleno */ { MS(200), MS(100), MS(20), 20}, { MS(500), MS(100), MS(50), 50}, { MS(1000), MS(500), MS(100), 100}, { MS(2000), MS(1000), MS(200), 100}, { MS(5000), MS(1000), MS(500), 100}, { S(10), S(50), S(1), 100}, { S(20), S(10), S(2), 100}, { S(50), S(10), S(5), 100}, { S(100), S(50), S(10), 100}, { S(200), S(100), S(20), 100}, { S(500), S(100), S(50), 100}, { S(1000), S(500), S(100), 100}, }; int ntasks, verbose, triggerproc, paused; Task *tasks; Image *cols[Ncolor][4]; Font *mediumfont, *tinyfont; Image *grey, *red, *green, *blue, *bg, *fg; char*profdev = "/proc/trace"; static void usage(void) { fprint(2, "Usage: %s [-d profdev] [-w] [-v] [-t triggerproc] [processes]\n", argv0); exits(nil); } void threadmain(int argc, char **argv) { int fd, i; char fname[80]; fmtinstall('t', timeconv); ARGBEGIN { case 'd': profdev = EARGF(usage()); break; case 'v': verbose = 1; break; case 'w': newwin++; break; case 't': triggerproc = (int)strtol(EARGF(usage()), nil, 0); break; default: usage(); } ARGEND; fname[sizeof fname - 1] = 0; for(i = 0; i < argc; i++){ snprint(fname, sizeof fname - 2, "/proc/%s/ctl", argv[i]); if((fd = open(fname, OWRITE)) < 0){ fprint(2, "%s: cannot open %s: %r\n", argv[0], fname); continue; } if(fprint(fd, "trace 1") < 0) fprint(2, "%s: cannot enable tracing on %s: %r\n", argv[0], fname); close(fd); } drawtrace(); } static void mkcol(int i, int c0, int c1, int c2) { cols[i][0] = allocimagemix(display, c0, DWhite); cols[i][1] = allocimage(display, Rect(0,0,1,1), screen->chan, 1, c1); cols[i][2] = allocimage(display, Rect(0,0,1,1), screen->chan, 1, c2); cols[i][3] = allocimage(display, Rect(0,0,1,1), screen->chan, 1, c0); } static void colinit(void) { mediumfont = openfont(display, "/lib/font/bit/lucidasans/unicode.10.font"); if(mediumfont == nil) mediumfont = font; tinyfont = openfont(display, "/lib/font/bit/lucidasans/unicode.7.font"); if(tinyfont == nil) tinyfont = font; topmargin = mediumfont->height+2; bottommargin = tinyfont->height+2; /* Peach */ mkcol(0, 0xFFAAAAFF, 0xFFAAAAFF, 0xBB5D5DFF); /* Aqua */ mkcol(1, DPalebluegreen, DPalegreygreen, DPurpleblue); /* Yellow */ mkcol(2, DPaleyellow, DDarkyellow, DYellowgreen); /* Green */ mkcol(3, DPalegreen, DMedgreen, DDarkgreen); /* Blue */ mkcol(4, 0x00AAFFFF, 0x00AAFFFF, 0x0088CCFF); /* Grey */ cols[5][0] = allocimage(display, Rect(0,0,1,1), screen->chan, 1, 0xEEEEEEFF); cols[5][1] = allocimage(display, Rect(0,0,1,1), screen->chan, 1, 0xCCCCCCFF); cols[5][2] = allocimage(display, Rect(0,0,1,1), screen->chan, 1, 0x888888FF); cols[5][3] = allocimage(display, Rect(0,0,1,1), screen->chan, 1, 0xAAAAAAFF); grey = cols[5][2]; red = allocimage(display, Rect(0,0,1,1), screen->chan, 1, 0xFF0000FF); green = allocimage(display, Rect(0,0,1,1), screen->chan, 1, 0x00FF00FF); blue = allocimage(display, Rect(0,0,1,1), screen->chan, 1, 0x0000FFFF); bg = display->white; fg = display->black; } static void redraw(int scaleno) { int n, i, j, x; char buf[256]; Point p, q; Rectangle r, rtime; Task *t; vlong ts, oldestts, newestts, period, ppp, scale, s, ss; # define time2x(t) ((int)(((t) - oldestts) / ppp)) scale = scales[scaleno].scale; period = scale + scales[scaleno].littletics; ppp = period / Width; // period per pixel. /* Round `now' to a nice number */ newestts = now - (now % scales[scaleno].bigtics) + (scales[scaleno].littletics>>1); oldestts = newestts - period; //print("newestts %t, period %t, %d-%d\n", newestts, period, time2x(oldestts), time2x(newestts)); if (prevts < oldestts){ oldestts = newestts - period; prevts = oldestts; draw(screen, screen->r, bg, nil, ZP); }else{ /* just white out time */ rtime = screen->r; rtime.min.x = rtime.max.x - stringwidth(mediumfont, "00000000000.000s"); rtime.max.y = rtime.min.y + mediumfont->height; draw(screen, rtime, bg, nil, ZP); } p = screen->r.min; for (n = 0; n != ntasks; n++) { t = &tasks[n]; /* p is upper left corner for this task */ rtime = Rpt(p, addpt(p, Pt(500, mediumfont->height))); draw(screen, rtime, bg, nil, ZP); snprint(buf, sizeof(buf), "%d %s", t->pid, t->name); q = string(screen, p, fg, ZP, mediumfont, buf); s = now - t->tstart; if(t->tevents[SRelease]) snprint(buf, sizeof(buf), " per %t — avg: %t max: %t", (vlong)(s/t->tevents[SRelease]), (vlong)(t->runtime/t->tevents[SRelease]), t->runmax); else if((s /=1000000000LL) != 0) snprint(buf, sizeof(buf), " per 1s — avg: %t total: %t", t->total/s, t->total); else snprint(buf, sizeof(buf), " total: %t", t->total); string(screen, q, fg, ZP, tinyfont, buf); p.y += Height; } x = time2x(prevts); p = screen->r.min; for (n = 0; n != ntasks; n++) { t = &tasks[n]; /* p is upper left corner for this task */ /* Move part already drawn */ r = Rect(p.x, p.y + topmargin, p.x + x, p.y+Height); draw(screen, r, screen, nil, Pt(p.x + Width - x, p.y + topmargin)); r.max.x = screen->r.max.x; r.min.x += x; draw(screen, r, bg, nil, ZP); line(screen, addpt(p, Pt(x, Height - lineht)), Pt(screen->r.max.x, p.y + Height - lineht), Endsquare, Endsquare, 0, cols[n % Ncolor][1], ZP); for (i = 0; i < t->nevents-1; i++) if (prevts < t->events[i + 1].time) break; if (i > 0) { memmove(t->events, t->events + i, (t->nevents - i) * sizeof(Event)); t->nevents -= i; } for (i = 0; i != t->nevents; i++) { Event *e = &t->events[i], *_e; int sx, ex; switch (e->etype & 0xffff) { case SAdmit: if (e->time > prevts && e->time <= newestts) { sx = time2x(e->time); line(screen, addpt(p, Pt(sx, topmargin)), addpt(p, Pt(sx, Height - bottommargin)), Endarrow, Endsquare, 1, green, ZP); } break; case SExpel: if (e->time > prevts && e->time <= newestts) { sx = time2x(e->time); line(screen, addpt(p, Pt(sx, topmargin)), addpt(p, Pt(sx, Height - bottommargin)), Endsquare, Endarrow, 1, red, ZP); } break; case SRelease: if (e->time > prevts && e->time <= newestts) { sx = time2x(e->time); line(screen, addpt(p, Pt(sx, topmargin)), addpt(p, Pt(sx, Height - bottommargin)), Endarrow, Endsquare, 1, fg, ZP); } break; case SDeadline: if (e->time > prevts && e->time <= newestts) { sx = time2x(e->time); line(screen, addpt(p, Pt(sx, topmargin)), addpt(p, Pt(sx, Height - bottommargin)), Endsquare, Endarrow, 1, fg, ZP); } break; case SYield: case SUser: if (e->time > prevts && e->time <= newestts) { sx = time2x(e->time); line(screen, addpt(p, Pt(sx, topmargin)), addpt(p, Pt(sx, Height - bottommargin)), Endsquare, Endarrow, 0, (e->etype == SYield)? green: blue, ZP); } break; case SSlice: if (e->time > prevts && e->time <= newestts) { sx = time2x(e->time); line(screen, addpt(p, Pt(sx, topmargin)), addpt(p, Pt(sx, Height - bottommargin)), Endsquare, Endarrow, 0, red, ZP); } break; case SRun: case SEdf: sx = time2x(e->time); ex = time2x(e->etime); if(ex == sx) ex++; r = Rect(sx, topmargin + 8, ex, Height - lineht); r = rectaddpt(r, p); draw(screen, r, cols[n % Ncolor][e->etype==SRun?1:3], nil, ZP); if(t->pid == triggerproc && ex < Width) paused ^= 1; for(j = 0; j < t->nevents; j++){ _e = &t->events[j]; switch(_e->etype & 0xffff){ case SInts: if (_e->time > prevts && _e->time <= newestts){ sx = time2x(_e->time); line(screen, addpt(p, Pt(sx, topmargin)), addpt(p, Pt(sx, Height / 2 - bottommargin)), Endsquare, Endsquare, 0, green, ZP); } break; case SInte: if (_e->time > prevts && _e->time <= newestts) { sx = time2x(_e->time); line(screen, addpt(p, Pt(sx, Height / 2 - bottommargin)), addpt(p, Pt(sx, Height - bottommargin)), Endsquare, Endsquare, 0, blue, ZP); } break; } } break; } } p.y += Height; } ts = prevts + scales[scaleno].littletics - (prevts % scales[scaleno].littletics); x = time2x(ts); while(x < Width){ p = screen->r.min; for(n = 0; n < ntasks; n++){ int height, width; /* p is upper left corner for this task */ if ((ts % scales[scaleno].scale) == 0){ height = 10 * Height; width = 1; }else if ((ts % scales[scaleno].bigtics) == 0){ height = 12 * Height; width = 0; }else{ height = 13 * Height; width = 0; } height >>= 4; line(screen, addpt(p, Pt(x, height)), addpt(p, Pt(x, Height - lineht)), Endsquare, Endsquare, width, cols[n % Ncolor][2], ZP); p.y += Height; } ts += scales[scaleno].littletics; x = time2x(ts); } rtime = screen->r; rtime.min.y = rtime.max.y - tinyfont->height + 2; draw(screen, rtime, bg, nil, ZP); ts = oldestts + scales[scaleno].bigtics - (oldestts % scales[scaleno].bigtics); x = time2x(ts); ss = 0; while(x < Width){ snprint(buf, sizeof(buf), "%t", ss); string(screen, addpt(p, Pt(x - stringwidth(tinyfont, buf)/2, - tinyfont->height - 1)), fg, ZP, tinyfont, buf); ts += scales[scaleno].bigtics; ss += scales[scaleno].bigtics; x = time2x(ts); } snprint(buf, sizeof(buf), "%t", now); string(screen, Pt(screen->r.max.x - stringwidth(mediumfont, buf), screen->r.min.y), fg, ZP, mediumfont, buf); flushimage(display, 1); prevts = newestts; } Task* newtask(ulong pid) { Task *t; char buf[64], *p; int fd,n; tasks = realloc(tasks, (ntasks + 1) * sizeof(Task)); assert(tasks); t = &tasks[ntasks++]; memset(t, 0, sizeof(Task)); t->events = nil; snprint(buf, sizeof buf, "/proc/%ld/status", pid); t->name = nil; fd = open(buf, OREAD); if (fd >= 0){ n = read(fd, buf, sizeof buf); if(n > 0){ p = buf + sizeof buf - 1; *p = 0; p = strchr(buf, ' '); if (p) *p = 0; t->name = strdup(buf); }else print("%s: %r\n", buf); close(fd); }else print("%s: %r\n", buf); t->pid = pid; prevts = 0; if (newwin){ fprint(wctlfd, "resize -dx %d -dy %d\n", Width + 20, (ntasks * Height) + 5); }else Height = ntasks ? Dy(screen->r)/ntasks : Dy(screen->r); return t; } void doevent(Task *t, Traceevent *ep) { int i, n; Event *event; vlong runt; t->tevents[ep->etype & 0xffff]++; n = t->nevents++; t->events = realloc(t->events, t->nevents*sizeof(Event)); assert(t->events); event = &t->events[n]; memmove(event, ep, sizeof(Traceevent)); event->etime = 0; switch(event->etype & 0xffff){ case SRelease: if (t->runthis > t->runmax) t->runmax = t->runthis; t->runthis = 0; break; case SSleep: case SYield: case SReady: case SSlice: for(i = n-1; i >= 0; i--) if (t->events[i].etype == SRun || t->events[i].etype == SEdf) break; if(i < 0 || t->events[i].etime != 0) break; runt = event->time - t->events[i].time; if(runt > 0){ t->events[i].etime = event->time; t->runtime += runt; t->total += runt; t->runthis += runt; t->runs++; } break; case SDead: print("task died %ld %t %s\n", event->pid, event->time, schedstatename[event->etype & 0xffff]); free(t->events); free(t->name); ntasks--; memmove(t, t+1, sizeof(Task)*(&tasks[ntasks]-t)); if (newwin) fprint(wctlfd, "resize -dx %d -dy %d\n", Width + 20, (ntasks * Height) + 5); else Height = ntasks ? Dy(screen->r)/ntasks : Dy(screen->r); prevts = 0; } } void drawtrace(void) { char *wsys, line[256]; int wfd, logfd; Mousectl *mousectl; Keyboardctl *keyboardctl; int scaleno; Rune r; int i, n; Task *t; Traceevent *ep; eventbuf = malloc(Nevents*sizeof(Traceevent)); assert(eventbuf); if((logfd = open(profdev, OREAD)) < 0) sysfatal("%s: Cannot open %s: %r", argv0, profdev); if(newwin){ if((wsys = getenv("wsys")) == nil) sysfatal("%s: Cannot find windowing system: %r", argv0); if((wfd = open(wsys, ORDWR)) < 0) sysfatal("%s: Cannot open windowing system: %r", argv0); snprint(line, sizeof(line), "new -pid %d -dx %d -dy %d", getpid(), Width + 20, Height + 5); line[sizeof(line) - 1] = '\0'; rfork(RFNAMEG); if(mount(wfd, -1, "/mnt/wsys", MREPL, line) < 0) sysfatal("%s: Cannot mount %s under /mnt/wsys: %r", argv0, line); if(bind("/mnt/wsys", "/dev", MBEFORE) < 0) sysfatal("%s: Cannot bind /mnt/wsys in /dev: %r", argv0); } if((wctlfd = open("/dev/wctl", OWRITE)) < 0) sysfatal("%s: Cannot open /dev/wctl: %r", argv0); if(initdraw(nil, nil, "trace") < 0) sysfatal("%s: initdraw failure: %r", argv0); Width = Dx(screen->r); Height = Dy(screen->r); if((mousectl = initmouse(nil, screen)) == nil) sysfatal("%s: cannot initialize mouse: %r", argv0); if((keyboardctl = initkeyboard(nil)) == nil) sysfatal("%s: cannot initialize keyboard: %r", argv0); colinit(); paused = 0; scaleno = 7; /* 100 milliseconds */ now = nsec(); for(;;) { Alt a[] = { { mousectl->c, nil, CHANRCV }, { mousectl->resizec, nil, CHANRCV }, { keyboardctl->c, &r, CHANRCV }, { nil, nil, CHANNOBLK }, }; switch (alt(a)) { case 0: continue; case 1: if(getwindow(display, Refnone) < 0) sysfatal("drawrt: Cannot re-attach window"); if(newwin){ if(Dx(screen->r) != Width || Dy(screen->r) != (ntasks * Height)){ fprint(2, "resize: x: have %d, need %d; y: have %d, need %d\n", Dx(screen->r), Width + 8, Dy(screen->r), (ntasks * Height) + 8); fprint(wctlfd, "resize -dx %d -dy %d\n", Width + 8, (ntasks * Height) + 8); } } else{ Width = Dx(screen->r); Height = ntasks? Dy(screen->r)/ntasks: Dy(screen->r); } break; case 2: switch(r){ case 'r': for(i = 0; i < ntasks; i++){ tasks[i].tstart = now; tasks[i].total = 0; tasks[i].runtime = 0; tasks[i].runmax = 0; tasks[i].runthis = 0; tasks[i].runs = 0; memset(tasks[i].tevents, 0, Nevent*sizeof(ulong)); } break; case 'p': paused ^= 1; prevts = 0; break; case '-': if (scaleno < nelem(scales) - 1) scaleno++; prevts = 0; break; case '+': if (scaleno > 0) scaleno--; prevts = 0; break; case 'q': threadexitsall(nil); case 'v': verbose ^= 1; default: break; } break; case 3: now = nsec(); while((n = read(logfd, eventbuf, Nevents*sizeof(Traceevent))) > 0){ assert((n % sizeof(Traceevent)) == 0); nevents = n / sizeof(Traceevent); for (ep = eventbuf; ep < eventbuf + nevents; ep++){ if ((ep->etype & 0xffff) >= Nevent){ print("%ld %t Illegal event %ld\n", ep->pid, ep->time, ep->etype & 0xffff); continue; } if (verbose) print("%ld %t %s\n", ep->pid, ep->time, schedstatename[ep->etype & 0xffff]); for(i = 0; i < ntasks; i++) if(tasks[i].pid == ep->pid) break; if(i == ntasks){ t = newtask(ep->pid); t->tstart = ep->time; }else t = &tasks[i]; doevent(t, ep); } } if(!paused) redraw(scaleno); } sleep(scales[scaleno].sleep); } } int timeconv(Fmt *f) { char buf[128], *sign; vlong t; buf[0] = 0; switch(f->r) { case 'U': t = va_arg(f->args, vlong); break; case 't': // vlong in nanoseconds t = va_arg(f->args, vlong); break; default: return fmtstrcpy(f, "(timeconv)"); } if (t < 0) { sign = "-"; t = -t; }else sign = ""; if (t > S(1)){ t += OneRound; sprint(buf, "%s%d.%.3ds", sign, (int)(t / S(1)), (int)(t % S(1))/1000000); }else if (t > MS(1)){ t += MilliRound; sprint(buf, "%s%d.%.3dms", sign, (int)(t / MS(1)), (int)(t % MS(1))/1000); }else if (t > US(1)) sprint(buf, "%s%d.%.3dµs", sign, (int)(t / US(1)), (int)(t % US(1))); else sprint(buf, "%s%dns", sign, (int)t); return fmtstrcpy(f, buf); }