From 956f9b36d2b035c3c934747f7399ec4b6d45b7eb Mon Sep 17 00:00:00 2001 From: Aggelos Economopoulos Date: Sat, 13 Feb 2010 14:35:15 +0200 Subject: [PATCH] evtr: dump core frequencies and use them to print timestamps in usecs This commit dumps the same frequency for each core; there's no point supporting different frequencies unless we monitor frequency change events. We use the frequency to print out relative timestamps in microseconds. This relies on ktrdump having done correct sorting. --- lib/libevtr/evtr.c | 92 +++++++++++++++++++++++-- lib/libevtr/evtr.h | 9 ++- usr.bin/evtranalyze/evtranalyze.c | 111 ++++++++++++++++++++++-------- usr.bin/ktrdump/ktrdump.c | 19 ++++- 4 files changed, 194 insertions(+), 37 deletions(-) diff --git a/lib/libevtr/evtr.c b/lib/libevtr/evtr.c index 240444b26d..4ae988d644 100644 --- a/lib/libevtr/evtr.c +++ b/lib/libevtr/evtr.c @@ -96,6 +96,11 @@ struct fmt_event_header { uint8_t fmt_len; } __attribute__((packed)); +struct cpuinfo_event_header { + double freq; + uint8_t cpu; +} __attribute__((packed)); + struct hashentry { const char *str; uint16_t id; @@ -145,6 +150,7 @@ struct event_callback { struct cpu { struct evtr_thread *td; /* currently executing thread */ + double freq; }; struct evtr { @@ -997,9 +1003,9 @@ evtr_dump_probe(evtr_t evtr, evtr_event_t ev) static int -evtr_dump_cpuinfo(evtr_t evtr, evtr_event_t ev) +evtr_dump_sysinfo(evtr_t evtr, evtr_event_t ev) { - uint8_t type = EVTR_TYPE_CPUINFO; + uint8_t type = EVTR_TYPE_SYSINFO; uint16_t ncpus = ev->ncpus; if (ncpus <= 0) { @@ -1018,6 +1024,34 @@ evtr_dump_cpuinfo(evtr_t evtr, evtr_event_t ev) return !0; return 0; } +static +int +evtr_dump_cpuinfo(evtr_t evtr, evtr_event_t ev) +{ + struct cpuinfo_event_header ci; + uint8_t type; + + if (evtr_dump_avoid_boundary(evtr, sizeof(type) + sizeof(ci))) + return !0; + type = EVTR_TYPE_CPUINFO; + if (evtr_write(evtr, &type, sizeof(type))) { + return !0; + } + ci.cpu = ev->cpu; + ci.freq = ev->cpuinfo.freq; + if (ci.cpu < 0) { + evtr->errmsg = "invalid cpu"; + return !0; + } + if (evtr_dump_avoid_boundary(evtr, sizeof(ci))) + return !0; + if (evtr_write(evtr, &ci, sizeof(ci))) { + return !0; + } + if (evtr_dump_pad(evtr)) + return !0; + return 0; +} int evtr_rewind(evtr_t evtr) @@ -1037,6 +1071,8 @@ evtr_dump_event(evtr_t evtr, evtr_event_t ev) switch (ev->type) { case EVTR_TYPE_PROBE: return evtr_dump_probe(evtr, ev); + case EVTR_TYPE_SYSINFO: + return evtr_dump_sysinfo(evtr, ev); case EVTR_TYPE_CPUINFO: return evtr_dump_cpuinfo(evtr, ev); } @@ -1090,7 +1126,7 @@ evtr_open_read(FILE *f) } /* * Load the first event so we can pick up any - * cpuinfo entries. + * sysinfo entries. */ if (evtr_next_event(evtr, &ev)) { goto free_cbs; @@ -1471,7 +1507,7 @@ evtr_skip_to_record(evtr_t evtr) static int -evtr_load_cpuinfo(evtr_t evtr) +evtr_load_sysinfo(evtr_t evtr) { uint16_t ncpus; int i; @@ -1489,10 +1525,40 @@ evtr_load_cpuinfo(evtr_t evtr) evtr->ncpus = ncpus; for (i = 0; i < ncpus; ++i) { evtr->cpus[i].td = NULL; + evtr->cpus[i].freq = -1.0; } return 0; } +static +int +evtr_load_cpuinfo(evtr_t evtr) +{ + struct cpuinfo_event_header cih; + struct cpu *cpu; + + if (evtr_read(evtr, &cih, sizeof(cih))) { + return !0; + } + if (cih.freq < 0.0) { + evtr->errmsg = "cpu freq is negative"; + evtr->err = EINVAL; + return !0; + } + /* + * Notice that freq is merely a multiplier with + * which we convert a timestamp to seconds; if + * ts is not in cycles, freq is not the frequency. + */ + if (!(cpu = evtr_cpu(evtr, cih.cpu))) { + evtr->errmsg = "freq for invalid cpu"; + evtr->err = EINVAL; + return !0; + } + cpu->freq = cih.freq; + return 0; +} + static int _evtr_next_event(evtr_t evtr, evtr_event_t ev, struct evtr_query *q) @@ -1512,7 +1578,10 @@ _evtr_next_event(evtr_t evtr, evtr_event_t ev, struct evtr_query *q) evtr_skip_to_record(evtr); continue; } - if (evhdr->type == EVTR_TYPE_CPUINFO) { + if (evhdr->type == EVTR_TYPE_SYSINFO) { + evtr_load_sysinfo(evtr); + continue; + } else if (evhdr->type == EVTR_TYPE_CPUINFO) { evtr_load_cpuinfo(evtr); continue; } @@ -1672,3 +1741,16 @@ evtr_ncpus(evtr_t evtr) { return evtr->ncpus; } + +int +evtr_cpufreqs(evtr_t evtr, double *freqs) +{ + int i; + + if (!freqs) + return EINVAL; + for (i = 0; i < evtr->ncpus; ++i) { + freqs[i] = evtr->cpus[i].freq; + } + return 0; +} diff --git a/lib/libevtr/evtr.h b/lib/libevtr/evtr.h index cefa9c23fe..fc9033f568 100644 --- a/lib/libevtr/evtr.h +++ b/lib/libevtr/evtr.h @@ -42,7 +42,8 @@ enum { EVTR_TYPE_PROBE = 0x1, EVTR_TYPE_STR = 0x2, EVTR_TYPE_FMT = 0x3, - EVTR_TYPE_CPUINFO = 0x4, + EVTR_TYPE_SYSINFO = 0x4, + EVTR_TYPE_CPUINFO = 0x5, }; struct evtr_thread { @@ -62,7 +63,10 @@ typedef struct evtr_event { union { /* timestamp. Must be nondecreasing */ uint64_t ts; - uint16_t ncpus; /* EVTR_TYPE_CPUINFO */ + uint16_t ncpus; /* EVTR_TYPE_SYSINFO */ + struct evtr_cpuinfo { /* EVTR_TYPE_CPUINFO */ + double freq; + } cpuinfo; }; /* * Pointer to filename. NULL if n/a. @@ -148,6 +152,7 @@ int evtr_last_event(evtr_t, evtr_event_t); int evtr_rewind(evtr_t); int evtr_ncpus(evtr_t); +int evtr_cpufreqs(evtr_t, double *); void evtr_set_debug(int); diff --git a/usr.bin/evtranalyze/evtranalyze.c b/usr.bin/evtranalyze/evtranalyze.c index 790b9e93db..f91d6326ad 100644 --- a/usr.bin/evtranalyze/evtranalyze.c +++ b/usr.bin/evtranalyze/evtranalyze.c @@ -179,8 +179,10 @@ struct td_switch_ctx { svg_rect_t thread_rect; svg_rect_t inactive_rect; svg_text_t thread_label; - struct cpu *cpus; - int ncpus; + struct cpu_table { + struct cpu *cpus; + int ncpus; + } cputab; struct evtr_thread **top_threads; int nr_top_threads; double thread_rows_yoff; @@ -191,6 +193,7 @@ struct cpu { int i; /* cpu index */ uint64_t ts; /* time cpu switched to td */ uint64_t first_ts, last_ts; + double freq; }; static @@ -360,7 +363,7 @@ void ctxsw_prepare_event(void *_ctx, evtr_event_t ev) { struct td_switch_ctx *ctx = _ctx; - struct cpu *c, *cpus = ctx->cpus; + struct cpu *c, *cpus = ctx->cputab.cpus; struct thread_info *tdi; (void)evtr; @@ -406,14 +409,14 @@ void ctxsw_prepare_post(void *_ctx) { struct td_switch_ctx *ctx = _ctx; - struct cpu *cpus = ctx->cpus; + struct cpu *cpus = ctx->cputab.cpus; int i; (void)evtr; ctx->first_ts = -1; ctx->last_ts = 0; printd("first_ts[0] = %llu\n",cpus[0].first_ts); - for (i = 0; i < ctx->ncpus; ++i) { + for (i = 0; i < ctx->cputab.ncpus; ++i) { printd("first_ts[%d] = %llu\n", i, cpus[i].first_ts); if (cpus[i].first_ts && (cpus[i].first_ts < ctx->first_ts)) ctx->first_ts = cpus[i].first_ts; @@ -463,7 +466,7 @@ void ctxsw_draw_event(void *_ctx, evtr_event_t ev) { struct td_switch_ctx *ctx = _ctx; - struct cpu *c = &ctx->cpus[ev->cpu]; + struct cpu *c = &ctx->cputab.cpus[ev->cpu]; int i; /* @@ -492,15 +495,52 @@ ctxsw_draw_event(void *_ctx, evtr_event_t ev) } } +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("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].first_ts = 0; + cpus[i].last_ts = 0; + cpus[i].freq = freqs[i]; + } + free(freqs); +} + + static int cmd_svg(int argc, char **argv) { svg_document_t svg; - int ncpus, i, ch; + int ch; double height, width; struct rows cpu_rows, thread_rows; - struct cpu *cpus; struct td_switch_ctx td_ctx; struct evtr_filter ctxsw_filts[2] = { { @@ -561,22 +601,8 @@ cmd_svg(int argc, char **argv) height = 200.0; width = 700.0; td_ctx.width = width; - if ((ncpus = evtr_ncpus(evtr)) <= 0) - err(1, "No cpu information!\n"); - printd("evtranalyze: ncpus %d\n", ncpus); - if (!(cpus = malloc(ncpus * sizeof(struct cpu)))) - err(1, "Can't allocate memory\n"); - /* initialize cpu array */ - for (i = 0; i < ncpus; ++i) { - cpus[i].td = NULL; - cpus[i].ts = 0; - cpus[i].i = i; - cpus[i].first_ts = 0; - cpus[i].last_ts = 0; - } - td_ctx.cpus = cpus; - td_ctx.ncpus = ncpus; + cputab_init(&td_ctx.cputab); 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("output.svg"))) @@ -594,7 +620,7 @@ cmd_svg(int argc, char **argv) /* text for thread names */ if (!(td_ctx.thread_label = svg_text_new("generic"))) err(1, "Can't create text\n"); - rows_init(&cpu_rows, ncpus, height, 0.9); + 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; @@ -620,8 +646,26 @@ 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("using freq = %lf\n", freq); filt.fmt = NULL; optind = 0; optreset = 1; @@ -640,16 +684,27 @@ cmd_show(int argc, char **argv) err(1, "Can't initialize query\n"); while(!evtr_query_next(q, &ev)) { char buf[1024]; - printf("%s\t%llu cycles\t[%.3d]\t%s:%d", - ev.td ? ev.td->comm : "unknown", - ev.ts, ev.cpu, - basename(ev.file), ev.line); + + if (!last_ts) + last_ts = ev.ts; + if (freq < 0.0) { + printf("%s\t%llu cycles\t[%.3d]\t%s:%d", + ev.td ? ev.td->comm : "unknown", + ev.ts - last_ts, ev.cpu, + basename(ev.file), 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(ev.file), ev.line); + } if (ev.fmt) { evtr_event_data(&ev, buf, sizeof(buf)); printf(" !\t%s\n", buf); } else { printf("\n"); } + last_ts = ev.ts; } if (evtr_error(evtr)) { err(1, evtr_errmsg(evtr)); diff --git a/usr.bin/ktrdump/ktrdump.c b/usr.bin/ktrdump/ktrdump.c index 0f8fe2687e..d7856563de 100644 --- a/usr.bin/ktrdump/ktrdump.c +++ b/usr.bin/ktrdump/ktrdump.c @@ -328,11 +328,26 @@ void dump_machine_info(evtr_t evtr) { struct evtr_event ev; + int i; - ev.type = EVTR_TYPE_CPUINFO; + bzero(&ev, sizeof(ev)); + ev.type = EVTR_TYPE_SYSINFO; ev.ncpus = ncpus; - evtr_dump_event(evtr, &ev); + if (evtr_error(evtr)) { + err(1, evtr_errmsg(evtr)); + } + + for (i = 0; i < ncpus; ++i) { + bzero(&ev, sizeof(ev)); + ev.type = EVTR_TYPE_CPUINFO; + ev.cpu = i; + ev.cpuinfo.freq = tsc_frequency; + evtr_dump_event(evtr, &ev); + if (evtr_error(evtr)) { + err(1, evtr_errmsg(evtr)); + } + } } static void -- 2.41.0