evtr: dump core frequencies and use them to print timestamps in usecs
authorAggelos Economopoulos <aoiko@cc.ece.ntua.gr>
Sat, 13 Feb 2010 12:35:15 +0000 (14:35 +0200)
committerAggelos Economopoulos <aoiko@cc.ece.ntua.gr>
Sat, 13 Feb 2010 13:11:42 +0000 (15:11 +0200)
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
lib/libevtr/evtr.h
usr.bin/evtranalyze/evtranalyze.c
usr.bin/ktrdump/ktrdump.c

index 240444b..4ae988d 100644 (file)
@@ -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,12 +1525,42 @@ 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)
 {
        char buf[MAX_EVHDR_SIZE];
@@ -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;
+}
index cefa9c2..fc9033f 100644 (file)
@@ -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);
 
 
index 790b9e9..f91d632 100644 (file)
@@ -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;
 
        /*
@@ -493,14 +496,51 @@ 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));
index 0f8fe26..d785656 100644 (file)
@@ -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