/* * Copyright (c) 2009, 2010 Aggelos Economopoulos. All rights reserved. * * Redistribution and use in source and binary forms, with or without * modification, are permitted provided that the following conditions * are met: * * 1. Redistributions of source code must retain the above copyright * notice, this list of conditions and the following disclaimer. * 2. Redistributions in binary form must reproduce the above copyright * notice, this list of conditions and the following disclaimer in * the documentation and/or other materials provided with the * distribution. * 3. Neither the name of The DragonFly Project nor the names of its * contributors may be used to endorse or promote products derived * from this software without specific, prior written permission. * * THIS SOFTWARE IS PROVIDED BY THE COPYRIGHT HOLDERS AND CONTRIBUTORS * ``AS IS'' AND ANY EXPRESS OR IMPLIED WARRANTIES, INCLUDING, BUT NOT * LIMITED TO, THE IMPLIED WARRANTIES OF MERCHANTABILITY AND FITNESS * FOR A PARTICULAR PURPOSE ARE DISCLAIMED. IN NO EVENT SHALL THE * COPYRIGHT HOLDERS OR CONTRIBUTORS BE LIABLE FOR ANY DIRECT, INDIRECT, * INCIDENTAL, SPECIAL, EXEMPLARY OR CONSEQUENTIAL DAMAGES (INCLUDING, * BUT NOT LIMITED TO, PROCUREMENT OF SUBSTITUTE GOODS OR SERVICES; * LOSS OF USE, DATA, OR PROFITS; OR BUSINESS INTERRUPTION) HOWEVER CAUSED * AND ON ANY THEORY OF LIABILITY, WHETHER IN CONTRACT, STRICT LIABILITY, * OR TORT (INCLUDING NEGLIGENCE OR OTHERWISE) ARISING IN ANY WAY OUT * OF THE USE OF THIS SOFTWARE, EVEN IF ADVISED OF THE POSSIBILITY OF * SUCH DAMAGE. */ #include #include #include #include #include #include #include #include #include #include #include #include "xml.h" #include "svg.h" #include "plotter.h" #include "trivial.h" enum { NR_TOP_THREADS = 5, NR_BUCKETS = 1021, }; struct rows { double row_increment; double row_off; }; #define CMD_PROTO(name) \ static int cmd_ ## name(int, char **) CMD_PROTO(show); CMD_PROTO(svg); CMD_PROTO(stats); CMD_PROTO(summary); struct command { const char *name; int (*func)(int argc, char **argv); } commands[] = { { .name = "show", .func = &cmd_show, }, { .name = "svg", .func = &cmd_svg, }, { .name = "stats", .func = &cmd_stats, }, { .name = "summary", .func = &cmd_summary, }, { .name = NULL, }, }; evtr_t evtr; static char *opt_infile; unsigned evtranalyze_debug; static void printd_set_flags(const char *str, unsigned int *flags) { /* * This is suboptimal as we don't detect * invalid flags. */ for (; *str; ++str) { if ('A' == *str) { *flags = -1; return; } if (!islower(*str)) err(2, "invalid debug flag %c\n", *str); *flags |= 1 << (*str - 'a'); } } struct hashentry { uintptr_t key; uintptr_t val; struct hashentry *next; }; struct hashtab { struct hashentry *buckets[NR_BUCKETS]; uintptr_t (*hashfunc)(uintptr_t); uintptr_t (*cmpfunc)(uintptr_t, uintptr_t); }; static int ehash_find(const struct hashtab *tab, uintptr_t key, uintptr_t *val) { struct hashentry *ent; for(ent = tab->buckets[tab->hashfunc(key)]; ent && tab->cmpfunc(ent->key, key); ent = ent->next); if (!ent) return !0; *val = ent->val; return 0; } static struct hashentry * ehash_insert(struct hashtab *tab, uintptr_t key, uintptr_t val) { struct hashentry *ent; int hsh; if (!(ent = malloc(sizeof(*ent)))) { fprintf(stderr, "out of memory\n"); return NULL; } hsh = tab->hashfunc(key); ent->next = tab->buckets[hsh]; ent->key = key; ent->val = val; tab->buckets[hsh] = ent; return ent; } static int ehash_delete(struct hashtab *tab, uintptr_t key) { struct hashentry *ent, *prev; prev = NULL; for(ent = tab->buckets[tab->hashfunc(key)]; ent && tab->cmpfunc(ent->key, key); prev = ent, ent = ent->next); if (!ent) return !0; if (prev) prev->next = ent->next; else tab->buckets[tab->hashfunc(key)] = ent->next; free(ent); return 0; } static uintptr_t cmpfunc_pointer(uintptr_t a, uintptr_t b) { return b - a; } static uintptr_t hashfunc_pointer(uintptr_t p) { return p % NR_BUCKETS; } static uintptr_t hashfunc_string(uintptr_t p) { const char *str = (char *)p; unsigned long hash = 5381; int c; while ((c = *str++)) hash = ((hash << 5) + hash) + c; /* hash * 33 + c */ return hash % NR_BUCKETS; } static struct hashtab * ehash_new(void) { struct hashtab *tab; if (!(tab = calloc(sizeof(struct hashtab), 1))) return tab; tab->hashfunc = &hashfunc_pointer; tab->cmpfunc = &cmpfunc_pointer; return tab; } /* returns 0 if equal */ static int cmp_vals(evtr_variable_value_t a, evtr_variable_value_t b) { if (a->type != b->type) return !0; switch (a->type) { case EVTR_VAL_NIL: return 0; case EVTR_VAL_INT: return !(a->num == b->num); case EVTR_VAL_STR: return strcmp(a->str, b->str); case EVTR_VAL_HASH: return !0; /* come on! */ case EVTR_VAL_CTOR: err(3, "not implemented"); } err(3, "can't get here"); } static uintptr_t cmpfunc_ctor(uintptr_t _a, uintptr_t _b) { evtr_variable_value_t vala, valb; vala = (evtr_variable_value_t)_a; valb = (evtr_variable_value_t)_b; if (strcmp(vala->ctor.name, valb->ctor.name)) return !0; vala = TAILQ_FIRST(&vala->ctor.args); valb = TAILQ_FIRST(&valb->ctor.args); for (;;) { if (!vala && !valb) return 0; if ((vala && !valb) || (valb && !vala)) return !0; if (cmp_vals(vala, valb)) return !0; vala = TAILQ_NEXT(vala, link); valb = TAILQ_NEXT(valb, link); } } static uintptr_t hashfunc_ctor(uintptr_t _p) { evtr_variable_value_t val, ctor_val = (evtr_variable_value_t)_p; char buf[1024], *p = &buf[0]; size_t len; p = buf; assert(ctor_val->type == EVTR_VAL_CTOR); len = strlcpy(buf, ctor_val->ctor.name, sizeof(buf)); if (len >= sizeof(buf)) goto done; TAILQ_FOREACH(val, &ctor_val->ctor.args, link) { switch (val->type) { case EVTR_VAL_NIL: assert(!"can't happen"); break; case EVTR_VAL_INT: len += snprintf(p + len, sizeof(buf) - len - 1, "%jd", val->num); break; case EVTR_VAL_STR: len = strlcat(p, val->str, sizeof(buf)); break; case EVTR_VAL_HASH: break; /* come on! */ case EVTR_VAL_CTOR: err(3, "not implemented"); } if (len >= (sizeof(buf) - 1)) break; } done: buf[sizeof(buf) - 1] = '\0'; return hashfunc_string((uintptr_t)buf); } typedef struct vector { uintmax_t *vals; int used; int allocated; } *vector_t; static vector_t vector_new(void) { vector_t v; if (!(v = malloc(sizeof(*v)))) return v; v->allocated = 2; if (!(v->vals = malloc(v->allocated * sizeof(v->vals[0])))) { free(v); return NULL; } v->allocated = v->used = 0; return v; } static void vector_push(vector_t v, uintmax_t val) { uintmax_t *tmp; if (v->used == v->allocated) { tmp = realloc(v->vals, 2 * v->allocated * sizeof(v->vals[0])); if (!tmp) err(1, "out of memory"); v->vals = tmp; v->allocated *= 2; } v->vals[v->used++] = val; } static void vector_destroy(vector_t v) { free(v->vals); free(v); } static int vector_nelems(vector_t v) { return v->used; } #define vector_foreach(v, val, i) \ for (i = 0, val = v->vals[0]; i < v->used; val = v->vals[++i]) static double stddev(vector_t v, double avg) { uintmax_t val; int i; double diff, sqr_sum = 0.0; if (vector_nelems(v) < 2) return 1 / 0.0; vector_foreach(v, val, i) { diff = val - avg; sqr_sum += diff * diff; } return sqrt(sqr_sum / (vector_nelems(v) - 1)); } static void usage(void) { fprintf(stderr, "bad usage :P\n"); exit(2); } static void rows_init(struct rows *rows, int n, double height, double perc) { double row_h; rows->row_increment = height / n; /* actual row height */ row_h = perc * rows->row_increment; rows->row_off = (rows->row_increment - row_h) / 2.0; assert(!isnan(rows->row_increment)); assert(!isnan(rows->row_off)); } static void rows_n(struct rows *rows, int n, double *y, double *height) { *y = n * rows->row_increment + rows->row_off; *height = rows->row_increment - 2 * rows->row_off; } /* * Which fontsize to use so that the string fits in the * given rect. */ static double fontsize_for_rect(double width, double height, int textlen) { double wpc, maxh; /* * We start with a font size equal to the height * of the rectangle and round down so that we only * use a limited number of sizes. * * For a rectangle width comparable to the height, * the text might extend outside of the rectangle. * In that case we need to limit it. */ /* available width per character */ wpc = width / textlen; /* * Assuming a rough hight/width ratio for characters, * calculate the available height and round it down * just to be on the safe side. */ #define GLYPH_HIGHT_TO_WIDTH 1.5 maxh = GLYPH_HIGHT_TO_WIDTH * wpc * 0.9; if (height > maxh) { height = maxh; } else if (height < 0.01) { height = 0.01; } else { /* rounding (XXX: make cheaper)*/ height = log(height); height = round(height); height = exp(height); } return height; } struct pass_hook { void (*pre)(void *); void (*event)(void *, evtr_event_t); void (*post)(void *); void *data; struct evtr_filter *filts; int nfilts; }; struct thread_info { uint64_t runtime; }; struct ts_interval { uint64_t start; uint64_t end; }; struct td_switch_ctx { svg_document_t svg; struct rows *cpu_rows; struct rows *thread_rows; /* which events the user cares about */ struct ts_interval interval; /* first/last event timestamps on any cpu */ struct ts_interval firstlast; double width; double xscale; /* scale factor applied to x */ svg_rect_t cpu_sw_rect; svg_rect_t thread_rect; svg_rect_t inactive_rect; svg_text_t thread_label; struct cpu_table { struct cpu *cpus; int ncpus; } cputab; struct evtr_thread **top_threads; int nr_top_threads; double thread_rows_yoff; }; struct cpu { struct evtr_thread *td; int i; /* cpu index */ uint64_t ts; /* time cpu switched to td */ /* timestamp for first/last event on this cpu */ struct ts_interval firstlast; double freq; uintmax_t evcnt; }; static void do_pass(struct pass_hook *hooks, int nhooks) { struct evtr_filter *filts = NULL; int nfilts = 0, i; struct evtr_query *q; struct evtr_event ev; for (i = 0; i < nhooks; ++i) { struct pass_hook *h = &hooks[i]; if (h->pre) h->pre(h->data); if (h->nfilts > 0) { filts = realloc(filts, (nfilts + h->nfilts) * sizeof(struct evtr_filter)); if (!filts) err(1, "Out of memory"); memcpy(filts + nfilts, h->filts, h->nfilts * sizeof(struct evtr_filter)); nfilts += h->nfilts; } } q = evtr_query_init(evtr, filts, nfilts); if (!q) err(1, "Can't initialize query\n"); while(!evtr_query_next(q, &ev)) { for (i = 0; i < nhooks; ++i) { if (hooks[i].event) hooks[i].event(hooks[i].data, &ev); } } if (evtr_query_error(q)) { err(1, "%s", evtr_query_errmsg(q)); } evtr_query_destroy(q); for (i = 0; i < nhooks; ++i) { if (hooks[i].post) hooks[i].post(hooks[i].data); } if (evtr_rewind(evtr)) err(1, "Can't rewind event stream\n"); } static void draw_thread_run(struct td_switch_ctx *ctx, struct cpu *c, evtr_event_t ev, int row) { double x, w, y, height; w = (ev->ts - c->ts) * ctx->xscale; x = (ev->ts - ctx->firstlast.start) * ctx->xscale; rows_n(ctx->thread_rows, row, &y, &height); svg_rect_draw(ctx->svg, ctx->thread_rect, x - w, y + ctx->thread_rows_yoff, w, height); } static void draw_ctx_switch(struct td_switch_ctx *ctx, struct cpu *c, evtr_event_t ev) { struct svg_transform textrot; char comm[100]; double x, w, fs, y, height; int textlen; assert(ctx->xscale > 0.0); if (!c->ts) return; /* distance to previous context switch */ w = (ev->ts - c->ts) * ctx->xscale; x = (ev->ts - ctx->firstlast.start) * ctx->xscale; if ((x - w) < 0) { fprintf(stderr, "(%ju - %ju) * %.20lf\n", (uintmax_t)ev->ts, (uintmax_t)ctx->firstlast.start, ctx->xscale); abort(); } rows_n(ctx->cpu_rows, c->i, &y, &height); assert(!isnan(y)); assert(!isnan(height)); svg_rect_draw(ctx->svg, ctx->cpu_sw_rect, x - w, y, w, height); /* * Draw the text label describing the thread we * switched out of. */ textrot.tx = x - w; textrot.ty = y; textrot.sx = 1.0; textrot.sy = 1.0; textrot.rot = 90.0; textlen = snprintf(comm, sizeof(comm) - 1, "%s (%p)", c->td ? c->td->comm : "unknown", c->td ? c->td->id: NULL); if (textlen > (int)sizeof(comm)) textlen = sizeof(comm) - 1; comm[sizeof(comm) - 1] = '\0'; /* * Note the width and hight are exchanged because * the bounding rectangle is rotated by 90 degrees. */ fs = fontsize_for_rect(height, w, textlen); svg_text_draw(ctx->svg, ctx->thread_label, &textrot, comm, fs); } /* * The stats for ntd have changed, update ->top_threads */ static void top_threads_update(struct td_switch_ctx *ctx, struct evtr_thread *ntd) { struct thread_info *tdi = ntd->userdata; int i, j; for (i = 0; i < ctx->nr_top_threads; ++i) { struct evtr_thread *td = ctx->top_threads[i]; if (td == ntd) { /* * ntd is already in top_threads and it is at * the correct ranking */ break; } if (!td) { /* empty slot -- just insert our thread */ ctx->top_threads[i] = ntd; break; } if (((struct thread_info *)td->userdata)->runtime >= tdi->runtime) { /* this thread ranks higher than we do. Move on */ continue; } /* * OK, we've found the first thread that we outrank, so we * need to replace it w/ our thread. */ td = ntd; /* td holds the thread we will insert next */ for (j = i + 1; j < ctx->nr_top_threads; ++j, ++i) { struct evtr_thread *tmp; /* tmp holds the thread we replace */ tmp = ctx->top_threads[j]; ctx->top_threads[j] = td; if (tmp == ntd) { /* * Our thread was already in the top list, * and we just removed the second instance. * Nothing more to do. */ break; } td = tmp; } break; } } static void ctxsw_prepare_event(void *_ctx, evtr_event_t ev) { struct td_switch_ctx *ctx = _ctx; struct cpu *c, *cpus = ctx->cputab.cpus; struct thread_info *tdi; (void)evtr; printd(INTV, "test1 (%ju:%ju) : %ju\n", (uintmax_t)ctx->interval.start, (uintmax_t)ctx->interval.end, (uintmax_t)ev->ts); if ((ev->ts > ctx->interval.end) || (ev->ts < ctx->interval.start)) return; printd(INTV, "PREPEV on %d\n", ev->cpu); /* update first/last timestamps */ c = &cpus[ev->cpu]; if (!c->firstlast.start) { c->firstlast.start = ev->ts; } c->firstlast.end = ev->ts; /* * c->td can be null when this is the first ctxsw event we * observe for a cpu */ if (c->td) { /* update thread stats */ if (!c->td->userdata) { if (!(tdi = malloc(sizeof(struct thread_info)))) err(1, "Out of memory"); c->td->userdata = tdi; tdi->runtime = 0; } tdi = c->td->userdata; tdi->runtime += ev->ts - c->ts; top_threads_update(ctx, c->td); } /* Notice that ev->td is the new thread for ctxsw events */ c->td = ev->td; c->ts = ev->ts; } static void find_first_last_ts(struct cpu_table *cputab, struct ts_interval *fl) { struct cpu *cpus = &cputab->cpus[0]; int i; fl->start = -1; fl->end = 0; for (i = 0; i < cputab->ncpus; ++i) { printd(INTV, "cpu%d: (%ju, %ju)\n", i, (uintmax_t)cpus[i].firstlast.start, (uintmax_t)cpus[i].firstlast.end); if (cpus[i].firstlast.start && (cpus[i].firstlast.start < fl->start)) fl->start = cpus[i].firstlast.start; if (cpus[i].firstlast.end && (cpus[i].firstlast.end > fl->end)) fl->end = cpus[i].firstlast.end; cpus[i].td = NULL; cpus[i].ts = 0; } printd(INTV, "global (%jd, %jd)\n", (uintmax_t)fl->start, (uintmax_t)fl->end); } static void ctxsw_prepare_post(void *_ctx) { struct td_switch_ctx *ctx = _ctx; find_first_last_ts(&ctx->cputab, &ctx->firstlast); } static void ctxsw_draw_pre(void *_ctx) { struct td_switch_ctx *ctx = _ctx; struct svg_transform textrot; char comm[100]; double y, height, fs; int i, textlen; struct evtr_thread *td; textrot.tx = 0.0 - 0.2; /* XXX */ textrot.sx = 1.0; textrot.sy = 1.0; textrot.rot = 270.0; for (i = 0; i < ctx->nr_top_threads; ++i) { td = ctx->top_threads[i]; if (!td) break; rows_n(ctx->thread_rows, i, &y, &height); svg_rect_draw(ctx->svg, ctx->inactive_rect, 0.0, y + ctx->thread_rows_yoff, ctx->width, height); textlen = snprintf(comm, sizeof(comm) - 1, "%s (%p)", td->comm, td->id); if (textlen > (int)sizeof(comm)) textlen = sizeof(comm) - 1; comm[sizeof(comm) - 1] = '\0'; fs = fontsize_for_rect(height, 100.0, textlen); textrot.ty = y + ctx->thread_rows_yoff + height; svg_text_draw(ctx->svg, ctx->thread_label, &textrot, comm, fs); } } static void ctxsw_draw_event(void *_ctx, evtr_event_t ev) { struct td_switch_ctx *ctx = _ctx; struct cpu *c = &ctx->cputab.cpus[ev->cpu]; int i; /* * ctx->firstlast.end can be 0 if there were no events * in the specified interval, in which case * ctx->firstlast.start is invalid too. */ assert(!ctx->firstlast.end || (ev->ts >= ctx->firstlast.start)); printd(INTV, "test2 (%ju:%ju) : %ju\n", (uintmax_t)ctx->interval.start, (uintmax_t)ctx->interval.end, (uintmax_t)ev->ts); if ((ev->ts > ctx->interval.end) || (ev->ts < ctx->interval.start)) return; printd(INTV, "DRAWEV %d\n", ev->cpu); if (c->td != ev->td) { /* thread switch (or preemption) */ draw_ctx_switch(ctx, c, ev); /* XXX: this is silly */ for (i = 0; i < ctx->nr_top_threads; ++i) { if (!ctx->top_threads[i]) break; if (ctx->top_threads[i] == c->td) { draw_thread_run(ctx, c, ev, i); break; } } c->td = ev->td; c->ts = ev->ts; } } static void cputab_init(struct cpu_table *ct) { struct cpu *cpus; double *freqs; int i; if ((ct->ncpus = evtr_ncpus(evtr)) <= 0) err(1, "No cpu information!\n"); printd(MISC, "evtranalyze: ncpus %d\n", ct->ncpus); if (!(ct->cpus = malloc(sizeof(struct cpu) * ct->ncpus))) { err(1, "Can't allocate memory\n"); } cpus = ct->cpus; if (!(freqs = malloc(sizeof(double) * ct->ncpus))) { err(1, "Can't allocate memory\n"); } if ((i = evtr_cpufreqs(evtr, freqs))) { warnc(i, "Can't get cpu frequencies\n"); for (i = 0; i < ct->ncpus; ++i) { freqs[i] = -1.0; } } /* initialize cpu array */ for (i = 0; i < ct->ncpus; ++i) { cpus[i].td = NULL; cpus[i].ts = 0; cpus[i].i = i; cpus[i].firstlast.start = 0; cpus[i].firstlast.end = 0; cpus[i].evcnt = 0; cpus[i].freq = freqs[i]; } free(freqs); } static void parse_interval(const char *_str, struct ts_interval *ts, struct cpu_table *cputab) { double s, e, freq; const char *str = _str + 1; if ('c' == *_str) { /* cycles */ if (sscanf(str, "%" SCNu64 ":%" SCNu64, &ts->start, &ts->end) == 2) return; } else if ('m' == *_str) { /* miliseconds */ if (sscanf(str, "%lf:%lf", &s, &e) == 2) { freq = cputab->cpus[0].freq; freq *= 1000.0; /* msecs */ if (freq < 0.0) { fprintf(stderr, "No frequency information" " available\n"); err(2, "Can't convert time to cycles\n"); } ts->start = s * freq; ts->end = e * freq; return; } } fprintf(stderr, "invalid interval format: %s\n", _str); usage(); } static int cmd_svg(int argc, char **argv) { svg_document_t svg; int ch; double height, width; struct rows cpu_rows, thread_rows; struct td_switch_ctx td_ctx; const char *outpath = "output.svg"; struct evtr_filter ctxsw_filts[2] = { { .flags = 0, .cpu = -1, .ev_type = EVTR_TYPE_PROBE, }, { .flags = 0, .cpu = -1, .ev_type = EVTR_TYPE_PROBE, }, }; struct pass_hook ctxsw_prepare = { .pre = NULL, .event = ctxsw_prepare_event, .post = ctxsw_prepare_post, .data = &td_ctx, .filts = ctxsw_filts, .nfilts = sizeof(ctxsw_filts)/sizeof(ctxsw_filts[0]), }, ctxsw_draw = { .pre = ctxsw_draw_pre, .event = ctxsw_draw_event, .post = NULL, .data = &td_ctx, .filts = ctxsw_filts, .nfilts = sizeof(ctxsw_filts)/sizeof(ctxsw_filts[0]), }; /* * We are interested in thread switch and preemption * events, but we don't use the data directly. Instead * we rely on ev->td. */ ctxsw_filts[0].fmt = "sw %p > %p"; ctxsw_filts[1].fmt = "pre %p > %p"; td_ctx.interval.start = 0; td_ctx.interval.end = -1; /* i.e. no interval given */ td_ctx.nr_top_threads = NR_TOP_THREADS; cputab_init(&td_ctx.cputab); /* needed for parse_interval() */ optind = 0; optreset = 1; while ((ch = getopt(argc, argv, "i:o:")) != -1) { switch (ch) { case 'i': parse_interval(optarg, &td_ctx.interval, &td_ctx.cputab); break; case 'o': outpath = optarg; break; default: usage(); } } argc -= optind; argv += optind; height = 200.0; width = 700.0; td_ctx.width = width; if (!(td_ctx.top_threads = calloc(td_ctx.nr_top_threads, sizeof(struct evtr_thread *)))) err(1, "Can't allocate memory\n"); if (!(svg = svg_document_create(outpath))) err(1, "Can't open svg document\n"); /* * Create rectangles to use for output. */ if (!(td_ctx.cpu_sw_rect = svg_rect_new("generic"))) err(1, "Can't create rectangle\n"); if (!(td_ctx.thread_rect = svg_rect_new("thread"))) err(1, "Can't create rectangle\n"); if (!(td_ctx.inactive_rect = svg_rect_new("inactive"))) err(1, "Can't create rectangle\n"); /* text for thread names */ if (!(td_ctx.thread_label = svg_text_new("generic"))) err(1, "Can't create text\n"); rows_init(&cpu_rows, td_ctx.cputab.ncpus, height, 0.9); td_ctx.svg = svg; td_ctx.xscale = -1.0; td_ctx.cpu_rows = &cpu_rows; do_pass(&ctxsw_prepare, 1); td_ctx.thread_rows_yoff = height; td_ctx.thread_rows = &thread_rows; rows_init(td_ctx.thread_rows, td_ctx.nr_top_threads, 300, 0.9); td_ctx.xscale = width / (td_ctx.firstlast.end - td_ctx.firstlast.start); printd(SVG, "first %ju, last %ju, xscale %lf\n", (uintmax_t)td_ctx.firstlast.start, (uintmax_t)td_ctx.firstlast.end, td_ctx.xscale); do_pass(&ctxsw_draw, 1); svg_document_close(svg); return 0; } static int cmd_show(int argc, char **argv) { struct evtr_event ev; struct evtr_query *q; struct evtr_filter filt; struct cpu_table cputab; double freq; int ch; uint64_t last_ts = 0; cputab_init(&cputab); /* * Assume all cores run on the same frequency * for now. There's no reason to complicate * things unless we can detect frequency change * events as well. * * Note that the code is very simplistic and will * produce garbage if the kernel doesn't fixup * the timestamps for cores running with different * frequencies. */ freq = cputab.cpus[0].freq; freq /= 1000000; /* we want to print out usecs */ printd(MISC, "using freq = %lf\n", freq); filt.flags = 0; filt.cpu = -1; filt.ev_type = EVTR_TYPE_PROBE; filt.fmt = NULL; optind = 0; optreset = 1; while ((ch = getopt(argc, argv, "f:")) != -1) { switch (ch) { case 'f': filt.fmt = optarg; break; } } q = evtr_query_init(evtr, &filt, 1); if (!q) err(1, "Can't initialize query\n"); while(!evtr_query_next(q, &ev)) { char buf[1024]; char *tmpbuf; if (!last_ts) last_ts = ev.ts; tmpbuf = strdup(ev.file); if (freq < 0.0) { printf("%s\t%ju cycles\t[%.3d]\t%s:%d", ev.td ? ev.td->comm : "unknown", (uintmax_t)(ev.ts - last_ts), ev.cpu, basename(tmpbuf), ev.line); } else { printf("%s\t%.3lf usecs\t[%.3d]\t%s:%d", ev.td ? ev.td->comm : "unknown", (ev.ts - last_ts) / freq, ev.cpu, basename(tmpbuf), ev.line); } free(tmpbuf); if (ev.fmt) { evtr_event_data(&ev, buf, sizeof(buf)); printf(" !\t%s\n", buf); } else { printf("\n"); } last_ts = ev.ts; } if (evtr_query_error(q)) { err(1, "%s", evtr_query_errmsg(q)); } evtr_query_destroy(q); return 0; } struct stats_ops { const char *statscmd; void *(*prepare)(int, char **, struct evtr_filter *); void (*each_event)(void *, evtr_event_t); void (*report)(void *); }; struct stats_integer_ctx { const char *varname; struct { int plot; const char *path; } opts; void *plotter_ctx; struct plotter *plotter; plotid_t time_plot; uintmax_t sum; uintmax_t occurrences; }; static void * stats_integer_prepare(int argc, char **argv, struct evtr_filter *filt) { struct stats_integer_ctx *ctx; int ch; if (!(ctx = calloc(1, sizeof(*ctx)))) return ctx; optind = 0; optreset = 1; while ((ch = getopt(argc, argv, "p:")) != -1) { switch (ch) { case 'p': ctx->opts.plot = !0; ctx->opts.path = optarg; break; default: usage(); } } argc -= optind; argv += optind; if (argc != 1) err(2, "Need exactly one variable"); ctx->varname = argv[0]; ctx->sum = ctx->occurrences = 0; filt->flags = 0; filt->cpu = -1; filt->ev_type = EVTR_TYPE_STMT; filt->var = ctx->varname; if (!ctx->opts.plot) return ctx; if (!(ctx->plotter = plotter_factory())) err(1, "can't allocate plotter"); if (!(ctx->plotter_ctx = ctx->plotter->plot_init(ctx->opts.path))) err(1, "can't allocate plotter context"); if ((ctx->time_plot = ctx->plotter->plot_new(ctx->plotter_ctx, PLOT_TYPE_LINE, ctx->varname)) < 0) err(1, "can't create histogram"); return ctx; } static void stats_integer_each(void *_ctx, evtr_event_t ev) { struct stats_integer_ctx *ctx = _ctx; if (EVTR_VAL_INT != ev->stmt.val->type) { fprintf(stderr, "event at %jd (cpu %d) does not treat %s as an" "integer variable; ignored\n", ev->ts, ev->cpu, ctx->varname); return; } if (ctx->plotter) ctx->plotter->plot_line(ctx->plotter_ctx, ctx->time_plot, (double)ev->ts, (double)ev->stmt.val->num); ctx->sum += ev->stmt.val->num; ++ctx->occurrences; } static void stats_integer_report(void *_ctx) { struct stats_integer_ctx *ctx = _ctx; printf("median for variable %s is %lf\n", ctx->varname, (double)ctx->sum / ctx->occurrences); if (ctx->plotter) ctx->plotter->plot_finish(ctx->plotter_ctx); free(ctx); } struct stats_completion_ctx { struct stats_completion_options { int plot; const char *path; } opts; struct plotter *plotter; void *plotter_ctx; plotid_t durations_plot; const char *varname; const char *ctor; const char *dtor; struct hashtab *ctors; uintmax_t historical_dtors; uintmax_t uncompleted_events; uintmax_t begun_events; uintmax_t completed_events; uintmax_t completed_duration_sum; vector_t durations; }; struct ctor_data { evtr_variable_value_t val; uintmax_t ts; }; static struct ctor_data * ctor_data_new(evtr_event_t ev) { struct ctor_data *cd; if (!(cd = malloc(sizeof(*cd)))) return cd; cd->val = ev->stmt.val; cd->ts = ev->ts; return cd; } static void * stats_completion_prepare(int argc, char **argv, struct evtr_filter *filt) { struct stats_completion_ctx *ctx; int ch; if (!(ctx = calloc(1, sizeof(*ctx)))) return ctx; optind = 0; optreset = 1; while ((ch = getopt(argc, argv, "p:")) != -1) { switch (ch) { case 'p': ctx->opts.plot = !0; ctx->opts.path = optarg; break; default: usage(); } } argc -= optind; argv += optind; if (argc != 3) err(2, "need a variable, a constructor and a destructor"); if (!(ctx->ctors = ehash_new())) goto free_ctx; ctx->ctors->hashfunc = &hashfunc_ctor; ctx->ctors->cmpfunc = &cmpfunc_ctor; if (!(ctx->durations = vector_new())) goto free_ctors; ctx->varname = argv[0]; ctx->ctor = argv[1]; ctx->dtor = argv[2]; filt->flags = 0; filt->cpu = -1; filt->ev_type = EVTR_TYPE_STMT; filt->var = ctx->varname; if (!ctx->opts.plot) return ctx; if (!(ctx->plotter = plotter_factory())) err(1, "can't allocate plotter"); if (!(ctx->plotter_ctx = ctx->plotter->plot_init(ctx->opts.path))) err(1, "can't allocate plotter context"); if ((ctx->durations_plot = ctx->plotter->plot_new(ctx->plotter_ctx, PLOT_TYPE_HIST, ctx->varname)) < 0) err(1, "can't create histogram"); return ctx; free_ctors: ; /* XXX */ free_ctx: free(ctx); return NULL; } static void stats_completion_each(void *_ctx, evtr_event_t ev) { struct stats_completion_ctx *ctx = _ctx; struct ctor_data *cd; if (ev->stmt.val->type != EVTR_VAL_CTOR) { fprintf(stderr, "event at %jd (cpu %d) does not assign to %s " "with a data constructor; ignored\n", ev->ts, ev->cpu, ctx->varname); return; } if (!strcmp(ev->stmt.val->ctor.name, ctx->ctor)) { uintptr_t v; if (!ehash_find(ctx->ctors, (uintptr_t)ev->stmt.val, &v)) { /* XXX:better diagnostic */ fprintf(stderr, "duplicate ctor\n"); err(3, "giving up"); } if (!(cd = ctor_data_new(ev))) err(1, "out of memory"); v = (uintptr_t)cd; if (!ehash_insert(ctx->ctors, (uintptr_t)ev->stmt.val, v)) err(1, "out of memory"); ++ctx->begun_events; } else if (!strcmp(ev->stmt.val->ctor.name, ctx->dtor)) { uintptr_t v; const char *tmp = ev->stmt.val->ctor.name; ev->stmt.val->ctor.name = ctx->ctor; if (ehash_find(ctx->ctors, (uintptr_t)ev->stmt.val, &v)) { ++ctx->historical_dtors; ev->stmt.val->ctor.name = tmp; return; } cd = (struct ctor_data *)v; if (cd->ts >= ev->ts) { /* XXX:better diagnostic */ fprintf(stderr, "destructor preceds constructor;" " ignored\n"); ev->stmt.val->ctor.name = tmp; return; } if (ctx->plotter) ctx->plotter->plot_histogram(ctx->plotter_ctx, ctx->durations_plot, (double)(ev->ts - cd->ts)); vector_push(ctx->durations, ev->ts - cd->ts); ++ctx->completed_events; ctx->completed_duration_sum += ev->ts - cd->ts; if (ehash_delete(ctx->ctors, (uintptr_t)ev->stmt.val)) err(3, "ctor disappeared from hash!"); ev->stmt.val->ctor.name = tmp; } else { fprintf(stderr, "event at %jd (cpu %d) assigns to %s " "with an unexpected data constructor; ignored\n", ev->ts, ev->cpu, ctx->varname); return; } } static void stats_completion_report(void *_ctx) { struct stats_completion_ctx *ctx = _ctx; double avg; printf("Events completed without having started:\t%jd\n", ctx->historical_dtors); printf("Events started but didn't complete:\t%jd\n", ctx->begun_events - ctx->completed_events); avg = (double)ctx->completed_duration_sum / ctx->completed_events; printf("Average event duration:\t%lf (stddev %lf)\n", avg, stddev(ctx->durations, avg)); if (ctx->plotter) ctx->plotter->plot_finish(ctx->plotter_ctx); vector_destroy(ctx->durations); /* XXX: hash */ free(ctx); } static struct stats_ops cmd_stat_ops[] = { { .statscmd = "integer", .prepare = &stats_integer_prepare, .each_event = &stats_integer_each, .report = &stats_integer_report, }, { .statscmd = "completion", .prepare = &stats_completion_prepare, .each_event = &stats_completion_each, .report = &stats_completion_report, }, { .statscmd = NULL, }, }; static int cmd_stats(int argc, char **argv) { struct evtr_event ev; struct evtr_query *q; struct evtr_filter filt; struct cpu_table cputab; double freq; uint64_t last_ts = 0; struct stats_ops *statsops = &cmd_stat_ops[0]; void *statctx; for (; statsops->statscmd; ++statsops) { if (!strcmp(statsops->statscmd, argv[1])) break; } if (!statsops->statscmd) err(2, "No such stats type: %s", argv[1]); --argc; ++argv; cputab_init(&cputab); /* * Assume all cores run on the same frequency * for now. There's no reason to complicate * things unless we can detect frequency change * events as well. * * Note that the code is very simplistic and will * produce garbage if the kernel doesn't fixup * the timestamps for cores running with different * frequencies. */ freq = cputab.cpus[0].freq; freq /= 1000000; /* we want to print out usecs */ printd(MISC, "using freq = %lf\n", freq); if (!(statctx = statsops->prepare(argc, argv, &filt))) err(1, "Can't allocate stats context"); q = evtr_query_init(evtr, &filt, 1); if (!q) err(1, "Can't initialize query"); while(!evtr_query_next(q, &ev)) { if (!last_ts) last_ts = ev.ts; assert(ev.type == EVTR_TYPE_STMT); statsops->each_event(statctx, &ev); last_ts = ev.ts; } if (evtr_query_error(q)) { err(1, "%s", evtr_query_errmsg(q)); } evtr_query_destroy(q); statsops->report(statctx); return 0; } static int cmd_summary(int argc, char **argv) { struct evtr_filter filt; struct evtr_event ev; struct evtr_query *q; double freq; struct cpu_table cputab; struct ts_interval global; uintmax_t global_evcnt; int i; (void)argc; (void)argv; cputab_init(&cputab); filt.ev_type = EVTR_TYPE_PROBE; filt.fmt = NULL; filt.flags = 0; filt.cpu = -1; q = evtr_query_init(evtr, &filt, 1); if (!q) err(1, "Can't initialize query\n"); while(!evtr_query_next(q, &ev)) { struct cpu *c = &cputab.cpus[ev.cpu]; if (!c->firstlast.start) c->firstlast.start = ev.ts; ++c->evcnt; c->firstlast.end = ev.ts; } if (evtr_query_error(q)) { err(1, "%s", evtr_query_errmsg(q)); } evtr_query_destroy(q); find_first_last_ts(&cputab, &global); freq = cputab.cpus[0].freq; global_evcnt = 0; for (i = 0; i < cputab.ncpus; ++i) { struct cpu *c = &cputab.cpus[i]; printf("CPU %d: %jd events in %.3lf secs\n", i, c->evcnt, (c->firstlast.end - c->firstlast.start) / freq); global_evcnt += c->evcnt; } printf("Total: %jd events on %d cpus in %.3lf secs\n", global_evcnt, cputab.ncpus, (global.end - global.start) / freq); return 0; } int main(int argc, char **argv) { int ch; FILE *inf; struct command *cmd; char *tmp; while ((ch = getopt(argc, argv, "f:D:")) != -1) { switch (ch) { case 'f': opt_infile = optarg; break; case 'D': if ((tmp = strchr(optarg, ':'))) { *tmp++ = '\0'; evtr_set_debug(tmp); } printd_set_flags(optarg, &evtranalyze_debug); break; default: usage(); } } argc -= optind; argv += optind; if (argc == 0) { err(2, "need to specify a command\n"); } if (!opt_infile) { err(2, "you need to specify an input file\n"); } else if (!strcmp(opt_infile, "-")) { inf = stdin; } else { inf = fopen(opt_infile, "r"); if (!inf) { err(2, "Can't open input file\n"); } } if (!(evtr = evtr_open_read(inf))) { err(1, "Can't open evtr stream\n"); } for (cmd = commands; cmd->name != NULL; ++cmd) { if (strcmp(argv[0], cmd->name)) continue; cmd->func(argc, argv); break; } if (!cmd->name) { err(2, "no such command: %s\n", argv[0]); } evtr_close(evtr); return 0; }