From cbb2e81e5232b1bca5cd2aa1d7a7eb1cd30f8304 Mon Sep 17 00:00:00 2001 From: Stanislav Fomichev Date: Fri, 1 Nov 2013 20:25:49 +0400 Subject: perf timechart: Group figures and add title with details Add titles to figures so we can run SVG interactively in Firefox and check event details in the tooltips. This also aids exploring SVG with Inkscape because when user clicks on one part of logical figure, all parts are selected. It's also possible to read titles with Inkscape in the object details. Signed-off-by: Stanislav Fomichev Acked-by: Namhyung Kim Cc: Ingo Molnar Cc: Namhyung Kim Cc: Paul Mackerras Cc: Peter Zijlstra Link: http://lkml.kernel.org/r/1383323151-19810-6-git-send-email-stfomichev@yandex-team.ru Signed-off-by: Arnaldo Carvalho de Melo --- tools/perf/util/svghelper.h | 5 +++-- 1 file changed, 3 insertions(+), 2 deletions(-) (limited to 'tools/perf/util/svghelper.h') diff --git a/tools/perf/util/svghelper.h b/tools/perf/util/svghelper.h index e0781989cc31..aa533459ab76 100644 --- a/tools/perf/util/svghelper.h +++ b/tools/perf/util/svghelper.h @@ -5,8 +5,9 @@ extern void open_svg(const char *filename, int cpus, int rows, u64 start, u64 end); extern void svg_box(int Yslot, u64 start, u64 end, const char *type); -extern void svg_sample(int Yslot, int cpu, u64 start, u64 end); -extern void svg_waiting(int Yslot, u64 start, u64 end); +extern void svg_blocked(int Yslot, int cpu, u64 start, u64 end); +extern void svg_running(int Yslot, int cpu, u64 start, u64 end); +extern void svg_waiting(int Yslot, int cpu, u64 start, u64 end); extern void svg_cpu_box(int cpu, u64 max_frequency, u64 turbo_frequency); -- cgit v1.2.3 From 6f8d67fa0c6bdca535ecab137c44b095023cc1b4 Mon Sep 17 00:00:00 2001 From: Stanislav Fomichev Date: Fri, 1 Nov 2013 20:25:51 +0400 Subject: perf timechart: Add backtrace support Add -g flag to `perf timechart record` which saves callchain info in the perf.data. When generating SVG, add backtrace information to the figure details, so now it's possible to see which code path woke up the task and why some task went to sleep. Signed-off-by: Stanislav Fomichev Acked-by: Namhyung Kim Cc: Ingo Molnar Cc: Namhyung Kim Cc: Paul Mackerras Cc: Peter Zijlstra Link: http://lkml.kernel.org/r/1383323151-19810-8-git-send-email-stfomichev@yandex-team.ru Signed-off-by: Arnaldo Carvalho de Melo --- tools/perf/Documentation/perf-timechart.txt | 3 + tools/perf/builtin-timechart.c | 169 ++++++++++++++++++++++++---- tools/perf/util/svghelper.c | 27 ++++- tools/perf/util/svghelper.h | 12 +- 4 files changed, 175 insertions(+), 36 deletions(-) (limited to 'tools/perf/util/svghelper.h') diff --git a/tools/perf/Documentation/perf-timechart.txt b/tools/perf/Documentation/perf-timechart.txt index 8359cfadf0ac..271dd4ed5b05 100644 --- a/tools/perf/Documentation/perf-timechart.txt +++ b/tools/perf/Documentation/perf-timechart.txt @@ -68,6 +68,9 @@ RECORD OPTIONS -T:: --tasks-only:: Record only tasks-related events +-g:: +--callchain:: + Do call-graph (stack chain/backtrace) recording SEE ALSO -------- diff --git a/tools/perf/builtin-timechart.c b/tools/perf/builtin-timechart.c index 1c60ed3f5b97..491662bdfe0b 100644 --- a/tools/perf/builtin-timechart.c +++ b/tools/perf/builtin-timechart.c @@ -52,6 +52,7 @@ static u64 first_time, last_time; static bool power_only; static bool tasks_only; +static bool with_backtrace; struct per_pid; @@ -126,6 +127,7 @@ struct cpu_sample { u64 end_time; int type; int cpu; + const char *backtrace; }; static struct per_pid *all_data; @@ -147,6 +149,7 @@ struct wake_event { int waker; int wakee; u64 time; + const char *backtrace; }; static struct power_event *power_events; @@ -231,7 +234,8 @@ static void pid_exit(int pid, u64 timestamp) } static void -pid_put_sample(int pid, int type, unsigned int cpu, u64 start, u64 end) +pid_put_sample(int pid, int type, unsigned int cpu, u64 start, u64 end, + const char *backtrace) { struct per_pid *p; struct per_pidcomm *c; @@ -254,6 +258,7 @@ pid_put_sample(int pid, int type, unsigned int cpu, u64 start, u64 end) sample->type = type; sample->next = c->samples; sample->cpu = cpu; + sample->backtrace = backtrace; c->samples = sample; if (sample->type == TYPE_RUNNING && end > start && start > 0) { @@ -405,7 +410,8 @@ static void p_state_change(int cpu, u64 timestamp, u64 new_freq) } static void -sched_wakeup(int cpu, u64 timestamp, int pid, struct trace_entry *te) +sched_wakeup(int cpu, u64 timestamp, int pid, struct trace_entry *te, + const char *backtrace) { struct per_pid *p; struct wakeup_entry *wake = (void *)te; @@ -416,6 +422,7 @@ sched_wakeup(int cpu, u64 timestamp, int pid, struct trace_entry *te) we->time = timestamp; we->waker = pid; + we->backtrace = backtrace; if ((te->flags & TRACE_FLAG_HARDIRQ) || (te->flags & TRACE_FLAG_SOFTIRQ)) we->waker = -1; @@ -430,13 +437,15 @@ sched_wakeup(int cpu, u64 timestamp, int pid, struct trace_entry *te) p->current->state = TYPE_WAITING; } if (p && p->current && p->current->state == TYPE_BLOCKED) { - pid_put_sample(p->pid, p->current->state, cpu, p->current->state_since, timestamp); + pid_put_sample(p->pid, p->current->state, cpu, + p->current->state_since, timestamp, NULL); p->current->state_since = timestamp; p->current->state = TYPE_WAITING; } } -static void sched_switch(int cpu, u64 timestamp, struct trace_entry *te) +static void sched_switch(int cpu, u64 timestamp, struct trace_entry *te, + const char *backtrace) { struct per_pid *p = NULL, *prev_p; struct sched_switch *sw = (void *)te; @@ -447,10 +456,14 @@ static void sched_switch(int cpu, u64 timestamp, struct trace_entry *te) p = find_create_pid(sw->next_pid); if (prev_p->current && prev_p->current->state != TYPE_NONE) - pid_put_sample(sw->prev_pid, TYPE_RUNNING, cpu, prev_p->current->state_since, timestamp); + pid_put_sample(sw->prev_pid, TYPE_RUNNING, cpu, + prev_p->current->state_since, timestamp, + backtrace); if (p && p->current) { if (p->current->state != TYPE_NONE) - pid_put_sample(sw->next_pid, p->current->state, cpu, p->current->state_since, timestamp); + pid_put_sample(sw->next_pid, p->current->state, cpu, + p->current->state_since, timestamp, + backtrace); p->current->state_since = timestamp; p->current->state = TYPE_RUNNING; @@ -466,8 +479,87 @@ static void sched_switch(int cpu, u64 timestamp, struct trace_entry *te) } } +static const char *cat_backtrace(union perf_event *event, + struct perf_sample *sample, + struct machine *machine) +{ + struct addr_location al; + unsigned int i; + char *p = NULL; + size_t p_len; + u8 cpumode = PERF_RECORD_MISC_USER; + struct addr_location tal; + struct ip_callchain *chain = sample->callchain; + FILE *f = open_memstream(&p, &p_len); + + if (!f) { + perror("open_memstream error"); + return NULL; + } + + if (!chain) + goto exit; + + if (perf_event__preprocess_sample(event, machine, &al, sample) < 0) { + fprintf(stderr, "problem processing %d event, skipping it.\n", + event->header.type); + goto exit; + } + + for (i = 0; i < chain->nr; i++) { + u64 ip; + + if (callchain_param.order == ORDER_CALLEE) + ip = chain->ips[i]; + else + ip = chain->ips[chain->nr - i - 1]; + + if (ip >= PERF_CONTEXT_MAX) { + switch (ip) { + case PERF_CONTEXT_HV: + cpumode = PERF_RECORD_MISC_HYPERVISOR; + break; + case PERF_CONTEXT_KERNEL: + cpumode = PERF_RECORD_MISC_KERNEL; + break; + case PERF_CONTEXT_USER: + cpumode = PERF_RECORD_MISC_USER; + break; + default: + pr_debug("invalid callchain context: " + "%"PRId64"\n", (s64) ip); + + /* + * It seems the callchain is corrupted. + * Discard all. + */ + free(p); + p = NULL; + goto exit; + } + continue; + } + + tal.filtered = false; + thread__find_addr_location(al.thread, machine, cpumode, + MAP__FUNCTION, ip, &tal); + + if (tal.sym) + fprintf(f, "..... %016" PRIx64 " %s\n", ip, + tal.sym->name); + else + fprintf(f, "..... %016" PRIx64 "\n", ip); + } + +exit: + fclose(f); + + return p; +} + typedef int (*tracepoint_handler)(struct perf_evsel *evsel, - struct perf_sample *sample); + struct perf_sample *sample, + const char *backtrace); static int process_sample_event(struct perf_tool *tool __maybe_unused, union perf_event *event __maybe_unused, @@ -487,7 +579,7 @@ static int process_sample_event(struct perf_tool *tool __maybe_unused, if (evsel->handler != NULL) { tracepoint_handler f = evsel->handler; - return f(evsel, sample); + return f(evsel, sample, cat_backtrace(event, sample, machine)); } return 0; @@ -495,7 +587,8 @@ static int process_sample_event(struct perf_tool *tool __maybe_unused, static int process_sample_cpu_idle(struct perf_evsel *evsel __maybe_unused, - struct perf_sample *sample) + struct perf_sample *sample, + const char *backtrace __maybe_unused) { struct power_processor_entry *ppe = sample->raw_data; @@ -508,7 +601,8 @@ process_sample_cpu_idle(struct perf_evsel *evsel __maybe_unused, static int process_sample_cpu_frequency(struct perf_evsel *evsel __maybe_unused, - struct perf_sample *sample) + struct perf_sample *sample, + const char *backtrace __maybe_unused) { struct power_processor_entry *ppe = sample->raw_data; @@ -518,28 +612,31 @@ process_sample_cpu_frequency(struct perf_evsel *evsel __maybe_unused, static int process_sample_sched_wakeup(struct perf_evsel *evsel __maybe_unused, - struct perf_sample *sample) + struct perf_sample *sample, + const char *backtrace) { struct trace_entry *te = sample->raw_data; - sched_wakeup(sample->cpu, sample->time, sample->pid, te); + sched_wakeup(sample->cpu, sample->time, sample->pid, te, backtrace); return 0; } static int process_sample_sched_switch(struct perf_evsel *evsel __maybe_unused, - struct perf_sample *sample) + struct perf_sample *sample, + const char *backtrace) { struct trace_entry *te = sample->raw_data; - sched_switch(sample->cpu, sample->time, te); + sched_switch(sample->cpu, sample->time, te, backtrace); return 0; } #ifdef SUPPORT_OLD_POWER_EVENTS static int process_sample_power_start(struct perf_evsel *evsel __maybe_unused, - struct perf_sample *sample) + struct perf_sample *sample, + const char *backtrace __maybe_unused) { struct power_entry_old *peo = sample->raw_data; @@ -549,7 +646,8 @@ process_sample_power_start(struct perf_evsel *evsel __maybe_unused, static int process_sample_power_end(struct perf_evsel *evsel __maybe_unused, - struct perf_sample *sample) + struct perf_sample *sample, + const char *backtrace __maybe_unused) { c_state_end(sample->cpu, sample->time); return 0; @@ -557,7 +655,8 @@ process_sample_power_end(struct perf_evsel *evsel __maybe_unused, static int process_sample_power_frequency(struct perf_evsel *evsel __maybe_unused, - struct perf_sample *sample) + struct perf_sample *sample, + const char *backtrace __maybe_unused) { struct power_entry_old *peo = sample->raw_data; @@ -741,11 +840,12 @@ static void draw_wakeups(void) } if (we->waker == -1) - svg_interrupt(we->time, to); + svg_interrupt(we->time, to, we->backtrace); else if (from && to && abs(from - to) == 1) - svg_wakeline(we->time, from, to); + svg_wakeline(we->time, from, to, we->backtrace); else - svg_partial_wakeline(we->time, from, task_from, to, task_to); + svg_partial_wakeline(we->time, from, task_from, to, + task_to, we->backtrace); we = we->next; free(task_from); @@ -798,11 +898,20 @@ static void draw_process_bars(void) sample = c->samples; while (sample) { if (sample->type == TYPE_RUNNING) - svg_running(Y, sample->cpu, sample->start_time, sample->end_time); + svg_running(Y, sample->cpu, + sample->start_time, + sample->end_time, + sample->backtrace); if (sample->type == TYPE_BLOCKED) - svg_blocked(Y, sample->cpu, sample->start_time, sample->end_time); + svg_blocked(Y, sample->cpu, + sample->start_time, + sample->end_time, + sample->backtrace); if (sample->type == TYPE_WAITING) - svg_waiting(Y, sample->cpu, sample->start_time, sample->end_time); + svg_waiting(Y, sample->cpu, + sample->start_time, + sample->end_time, + sample->backtrace); sample = sample->next; } @@ -1050,6 +1159,11 @@ static int __cmd_record(int argc, const char **argv) }; unsigned int common_args_nr = ARRAY_SIZE(common_args); + const char * const backtrace_args[] = { + "-g", + }; + unsigned int backtrace_args_no = ARRAY_SIZE(backtrace_args); + const char * const power_args[] = { "-e", "power:cpu_frequency", "-e", "power:cpu_idle", @@ -1089,8 +1203,11 @@ static int __cmd_record(int argc, const char **argv) old_power_args_nr = 0; } + if (!with_backtrace) + backtrace_args_no = 0; + record_elems = common_args_nr + tasks_args_nr + - power_args_nr + old_power_args_nr; + power_args_nr + old_power_args_nr + backtrace_args_no; rec_argc = record_elems + argc; rec_argv = calloc(rec_argc + 1, sizeof(char *)); @@ -1102,6 +1219,9 @@ static int __cmd_record(int argc, const char **argv) for (i = 0; i < common_args_nr; i++) *p++ = strdup(common_args[i]); + for (i = 0; i < backtrace_args_no; i++) + *p++ = strdup(backtrace_args[i]); + for (i = 0; i < tasks_args_nr; i++) *p++ = strdup(tasks_args[i]); @@ -1155,6 +1275,7 @@ int cmd_timechart(int argc, const char **argv, OPT_BOOLEAN('P', "power-only", &power_only, "output power data only"), OPT_BOOLEAN('T', "tasks-only", &tasks_only, "output processes data only"), + OPT_BOOLEAN('g', "callchain", &with_backtrace, "record callchain"), OPT_END() }; const char * const record_usage[] = { diff --git a/tools/perf/util/svghelper.c b/tools/perf/util/svghelper.c index 9a5b41392e01..8b79d3ad1246 100644 --- a/tools/perf/util/svghelper.c +++ b/tools/perf/util/svghelper.c @@ -130,7 +130,7 @@ void svg_box(int Yslot, u64 start, u64 end, const char *type) } static char *time_to_string(u64 duration); -void svg_blocked(int Yslot, int cpu, u64 start, u64 end) +void svg_blocked(int Yslot, int cpu, u64 start, u64 end, const char *backtrace) { if (!svgfile) return; @@ -138,11 +138,13 @@ void svg_blocked(int Yslot, int cpu, u64 start, u64 end) fprintf(svgfile, "\n"); fprintf(svgfile, "#%d blocked %s\n", cpu, time_to_string(end - start)); + if (backtrace) + fprintf(svgfile, "Blocked on:\n%s\n", backtrace); svg_box(Yslot, start, end, "blocked"); fprintf(svgfile, "\n"); } -void svg_running(int Yslot, int cpu, u64 start, u64 end) +void svg_running(int Yslot, int cpu, u64 start, u64 end, const char *backtrace) { double text_size; if (!svgfile) @@ -152,6 +154,8 @@ void svg_running(int Yslot, int cpu, u64 start, u64 end) fprintf(svgfile, "#%d running %s\n", cpu, time_to_string(end - start)); + if (backtrace) + fprintf(svgfile, "Switched because:\n%s\n", backtrace); fprintf(svgfile, "\n", time2pixels(start), time2pixels(end)-time2pixels(start), Yslot * SLOT_MULT, SLOT_HEIGHT); @@ -187,7 +191,7 @@ static char *time_to_string(u64 duration) return text; } -void svg_waiting(int Yslot, int cpu, u64 start, u64 end) +void svg_waiting(int Yslot, int cpu, u64 start, u64 end, const char *backtrace) { char *text; const char *style; @@ -212,6 +216,8 @@ void svg_waiting(int Yslot, int cpu, u64 start, u64 end) fprintf(svgfile, "\n", time2pixels(start), Yslot * SLOT_MULT); fprintf(svgfile, "#%d waiting %s\n", cpu, time_to_string(end - start)); + if (backtrace) + fprintf(svgfile, "Waiting on:\n%s\n", backtrace); fprintf(svgfile, "\n", time2pixels(end)-time2pixels(start), SLOT_HEIGHT, style); if (font_size > MIN_TEXT_SIZE) @@ -382,7 +388,7 @@ void svg_pstate(int cpu, u64 start, u64 end, u64 freq) } -void svg_partial_wakeline(u64 start, int row1, char *desc1, int row2, char *desc2) +void svg_partial_wakeline(u64 start, int row1, char *desc1, int row2, char *desc2, const char *backtrace) { double height; @@ -396,6 +402,9 @@ void svg_partial_wakeline(u64 start, int row1, char *desc1, int row2, char *desc desc1 ? desc1 : "?", desc2 ? desc2 : "?"); + if (backtrace) + fprintf(svgfile, "%s\n", backtrace); + if (row1 < row2) { if (row1) { fprintf(svgfile, "\n", @@ -437,7 +446,7 @@ void svg_partial_wakeline(u64 start, int row1, char *desc1, int row2, char *desc fprintf(svgfile, "\n"); } -void svg_wakeline(u64 start, int row1, int row2) +void svg_wakeline(u64 start, int row1, int row2, const char *backtrace) { double height; @@ -447,6 +456,9 @@ void svg_wakeline(u64 start, int row1, int row2) fprintf(svgfile, "\n"); + if (backtrace) + fprintf(svgfile, "%s\n", backtrace); + if (row1 < row2) fprintf(svgfile, "\n", time2pixels(start), row1 * SLOT_MULT + SLOT_HEIGHT, time2pixels(start), row2 * SLOT_MULT); @@ -463,7 +475,7 @@ void svg_wakeline(u64 start, int row1, int row2) fprintf(svgfile, "\n"); } -void svg_interrupt(u64 start, int row) +void svg_interrupt(u64 start, int row, const char *backtrace) { if (!svgfile) return; @@ -472,6 +484,9 @@ void svg_interrupt(u64 start, int row) fprintf(svgfile, "Wakeup from interrupt\n"); + if (backtrace) + fprintf(svgfile, "%s\n", backtrace); + fprintf(svgfile, "\n", time2pixels(start), row * SLOT_MULT); fprintf(svgfile, "\n", diff --git a/tools/perf/util/svghelper.h b/tools/perf/util/svghelper.h index aa533459ab76..fad79ceeac1a 100644 --- a/tools/perf/util/svghelper.h +++ b/tools/perf/util/svghelper.h @@ -5,9 +5,9 @@ extern void open_svg(const char *filename, int cpus, int rows, u64 start, u64 end); extern void svg_box(int Yslot, u64 start, u64 end, const char *type); -extern void svg_blocked(int Yslot, int cpu, u64 start, u64 end); -extern void svg_running(int Yslot, int cpu, u64 start, u64 end); -extern void svg_waiting(int Yslot, int cpu, u64 start, u64 end); +extern void svg_blocked(int Yslot, int cpu, u64 start, u64 end, const char *backtrace); +extern void svg_running(int Yslot, int cpu, u64 start, u64 end, const char *backtrace); +extern void svg_waiting(int Yslot, int cpu, u64 start, u64 end, const char *backtrace); extern void svg_cpu_box(int cpu, u64 max_frequency, u64 turbo_frequency); @@ -18,9 +18,9 @@ extern void svg_pstate(int cpu, u64 start, u64 end, u64 freq); extern void svg_time_grid(void); extern void svg_legenda(void); -extern void svg_wakeline(u64 start, int row1, int row2); -extern void svg_partial_wakeline(u64 start, int row1, char *desc1, int row2, char *desc2); -extern void svg_interrupt(u64 start, int row); +extern void svg_wakeline(u64 start, int row1, int row2, const char *backtrace); +extern void svg_partial_wakeline(u64 start, int row1, char *desc1, int row2, char *desc2, const char *backtrace); +extern void svg_interrupt(u64 start, int row, const char *backtrace); extern void svg_text(int Yslot, u64 start, const char *text); extern void svg_close(void); -- cgit v1.2.3 From 8b6dcca017aa53fe13066411a653b5997c158a2c Mon Sep 17 00:00:00 2001 From: Stanislav Fomichev Date: Mon, 2 Dec 2013 18:37:33 +0400 Subject: perf timechart: Add backtrace support to CPU info Add backtrace info to the CPU usage timechart. Signed-off-by: Stanislav Fomichev Cc: Ingo Molnar Cc: Jiri Olsa Cc: Namhyung Kim Cc: Paul Mackerras Cc: Peter Zijlstra Cc: Ramkumar Ramachandra Link: http://lkml.kernel.org/r/1385995056-20158-2-git-send-email-stfomichev@yandex-team.ru Signed-off-by: Arnaldo Carvalho de Melo --- tools/perf/builtin-timechart.c | 10 ++++++++-- tools/perf/util/svghelper.c | 4 +++- tools/perf/util/svghelper.h | 2 +- 3 files changed, 12 insertions(+), 4 deletions(-) (limited to 'tools/perf/util/svghelper.h') diff --git a/tools/perf/builtin-timechart.c b/tools/perf/builtin-timechart.c index 0bda620a717d..d955095b6d63 100644 --- a/tools/perf/builtin-timechart.c +++ b/tools/perf/builtin-timechart.c @@ -837,8 +837,14 @@ static void draw_cpu_usage(struct timechart *tchart) while (c) { sample = c->samples; while (sample) { - if (sample->type == TYPE_RUNNING) - svg_process(sample->cpu, sample->start_time, sample->end_time, "sample", c->comm); + if (sample->type == TYPE_RUNNING) { + svg_process(sample->cpu, + sample->start_time, + sample->end_time, + "sample", + c->comm, + sample->backtrace); + } sample = sample->next; } diff --git a/tools/perf/util/svghelper.c b/tools/perf/util/svghelper.c index 8b79d3ad1246..740f0328fc13 100644 --- a/tools/perf/util/svghelper.c +++ b/tools/perf/util/svghelper.c @@ -285,7 +285,7 @@ void svg_cpu_box(int cpu, u64 __max_freq, u64 __turbo_freq) fprintf(svgfile, "\n"); } -void svg_process(int cpu, u64 start, u64 end, const char *type, const char *name) +void svg_process(int cpu, u64 start, u64 end, const char *type, const char *name, const char *backtrace) { double width; @@ -295,6 +295,8 @@ void svg_process(int cpu, u64 start, u64 end, const char *type, const char *name fprintf(svgfile, "\n", time2pixels(start), cpu2y(cpu)); fprintf(svgfile, "%s %s\n", name, time_to_string(end - start)); + if (backtrace) + fprintf(svgfile, "Switched because:\n%s\n", backtrace); fprintf(svgfile, "\n", time2pixels(end)-time2pixels(start), SLOT_MULT+SLOT_HEIGHT, type); width = time2pixels(end)-time2pixels(start); diff --git a/tools/perf/util/svghelper.h b/tools/perf/util/svghelper.h index fad79ceeac1a..7db6ae98bf2c 100644 --- a/tools/perf/util/svghelper.h +++ b/tools/perf/util/svghelper.h @@ -11,7 +11,7 @@ extern void svg_waiting(int Yslot, int cpu, u64 start, u64 end, const char *back extern void svg_cpu_box(int cpu, u64 max_frequency, u64 turbo_frequency); -extern void svg_process(int cpu, u64 start, u64 end, const char *type, const char *name); +extern void svg_process(int cpu, u64 start, u64 end, const char *type, const char *name, const char *backtrace); extern void svg_cstate(int cpu, u64 start, u64 end, int type); extern void svg_pstate(int cpu, u64 start, u64 end, u64 freq); -- cgit v1.2.3 From de996228dedc74d9e72b749bbc8225f5e2bf19d8 Mon Sep 17 00:00:00 2001 From: Stanislav Fomichev Date: Mon, 2 Dec 2013 18:37:34 +0400 Subject: perf timechart: Print pid along the name Add PID to the figures of CPU usage timechart. Signed-off-by: Stanislav Fomichev Cc: Ingo Molnar Cc: Jiri Olsa Cc: Namhyung Kim Cc: Paul Mackerras Cc: Peter Zijlstra Cc: Ramkumar Ramachandra Link: http://lkml.kernel.org/r/1385995056-20158-3-git-send-email-stfomichev@yandex-team.ru Signed-off-by: Arnaldo Carvalho de Melo --- tools/perf/builtin-timechart.c | 1 + tools/perf/util/svghelper.c | 4 ++-- tools/perf/util/svghelper.h | 2 +- 3 files changed, 4 insertions(+), 3 deletions(-) (limited to 'tools/perf/util/svghelper.h') diff --git a/tools/perf/builtin-timechart.c b/tools/perf/builtin-timechart.c index d955095b6d63..99fe363f1de8 100644 --- a/tools/perf/builtin-timechart.c +++ b/tools/perf/builtin-timechart.c @@ -841,6 +841,7 @@ static void draw_cpu_usage(struct timechart *tchart) svg_process(sample->cpu, sample->start_time, sample->end_time, + p->pid, "sample", c->comm, sample->backtrace); diff --git a/tools/perf/util/svghelper.c b/tools/perf/util/svghelper.c index 740f0328fc13..927851d05d03 100644 --- a/tools/perf/util/svghelper.c +++ b/tools/perf/util/svghelper.c @@ -285,7 +285,7 @@ void svg_cpu_box(int cpu, u64 __max_freq, u64 __turbo_freq) fprintf(svgfile, "\n"); } -void svg_process(int cpu, u64 start, u64 end, const char *type, const char *name, const char *backtrace) +void svg_process(int cpu, u64 start, u64 end, int pid, const char *type, const char *name, const char *backtrace) { double width; @@ -294,7 +294,7 @@ void svg_process(int cpu, u64 start, u64 end, const char *type, const char *name fprintf(svgfile, "\n", time2pixels(start), cpu2y(cpu)); - fprintf(svgfile, "%s %s\n", name, time_to_string(end - start)); + fprintf(svgfile, "%d %s running %s\n", pid, name, time_to_string(end - start)); if (backtrace) fprintf(svgfile, "Switched because:\n%s\n", backtrace); fprintf(svgfile, "\n", diff --git a/tools/perf/util/svghelper.h b/tools/perf/util/svghelper.h index 7db6ae98bf2c..8b77ca631686 100644 --- a/tools/perf/util/svghelper.h +++ b/tools/perf/util/svghelper.h @@ -11,7 +11,7 @@ extern void svg_waiting(int Yslot, int cpu, u64 start, u64 end, const char *back extern void svg_cpu_box(int cpu, u64 max_frequency, u64 turbo_frequency); -extern void svg_process(int cpu, u64 start, u64 end, const char *type, const char *name, const char *backtrace); +extern void svg_process(int cpu, u64 start, u64 end, int pid, const char *type, const char *name, const char *backtrace); extern void svg_cstate(int cpu, u64 start, u64 end, int type); extern void svg_pstate(int cpu, u64 start, u64 end, u64 freq); -- cgit v1.2.3 From c507999790438cde78b5618fa64daefd697035af Mon Sep 17 00:00:00 2001 From: Stanislav Fomichev Date: Mon, 2 Dec 2013 18:37:36 +0400 Subject: perf timechart: Add support for topology Add -t switch to sort CPUs topologically. Signed-off-by: Stanislav Fomichev Cc: Ingo Molnar Cc: Jiri Olsa Cc: Namhyung Kim Cc: Paul Mackerras Cc: Peter Zijlstra Cc: Ramkumar Ramachandra Link: http://lkml.kernel.org/r/1385995056-20158-5-git-send-email-stfomichev@yandex-team.ru Signed-off-by: Arnaldo Carvalho de Melo --- tools/perf/Documentation/perf-timechart.txt | 3 + tools/perf/builtin-timechart.c | 17 +++- tools/perf/util/svghelper.c | 132 +++++++++++++++++++++++++++- tools/perf/util/svghelper.h | 2 + 4 files changed, 151 insertions(+), 3 deletions(-) (limited to 'tools/perf/util/svghelper.h') diff --git a/tools/perf/Documentation/perf-timechart.txt b/tools/perf/Documentation/perf-timechart.txt index 271dd4ed5b05..367c1be0551c 100644 --- a/tools/perf/Documentation/perf-timechart.txt +++ b/tools/perf/Documentation/perf-timechart.txt @@ -59,6 +59,9 @@ $ perf timechart -n:: --proc-num:: Print task info for at least given number of tasks. +-t:: +--topology:: + Sort CPUs according to topology. RECORD OPTIONS -------------- diff --git a/tools/perf/builtin-timechart.c b/tools/perf/builtin-timechart.c index db9c4c172587..8bde57c5c908 100644 --- a/tools/perf/builtin-timechart.c +++ b/tools/perf/builtin-timechart.c @@ -58,7 +58,8 @@ struct timechart { first_time, last_time; bool power_only, tasks_only, - with_backtrace; + with_backtrace, + topology; }; struct per_pidcomm; @@ -1077,6 +1078,18 @@ static int process_header(struct perf_file_section *section __maybe_unused, case HEADER_NRCPUS: tchart->numcpus = ph->env.nr_cpus_avail; break; + + case HEADER_CPU_TOPOLOGY: + if (!tchart->topology) + break; + + if (svg_build_topology_map(ph->env.sibling_cores, + ph->env.nr_sibling_cores, + ph->env.sibling_threads, + ph->env.nr_sibling_threads)) + fprintf(stderr, "problem building topology\n"); + break; + default: break; } @@ -1267,6 +1280,8 @@ int cmd_timechart(int argc, const char **argv, "Look for files with symbols relative to this directory"), OPT_INTEGER('n', "proc-num", &tchart.proc_num, "min. number of tasks to print"), + OPT_BOOLEAN('t', "topology", &tchart.topology, + "sort CPUs according to topology"), OPT_END() }; const char * const timechart_usage[] = { diff --git a/tools/perf/util/svghelper.c b/tools/perf/util/svghelper.c index 927851d05d03..9468136735ca 100644 --- a/tools/perf/util/svghelper.c +++ b/tools/perf/util/svghelper.c @@ -17,8 +17,11 @@ #include #include #include +#include +#include "perf.h" #include "svghelper.h" +#include "cpumap.h" static u64 first_time, last_time; static u64 turbo_frequency, max_freq; @@ -39,9 +42,14 @@ static double cpu2slot(int cpu) return 2 * cpu + 1; } +static int *topology_map; + static double cpu2y(int cpu) { - return cpu2slot(cpu) * SLOT_MULT; + if (topology_map) + return cpu2slot(topology_map[cpu]) * SLOT_MULT; + else + return cpu2slot(cpu) * SLOT_MULT; } static double time2pixels(u64 __time) @@ -275,7 +283,7 @@ void svg_cpu_box(int cpu, u64 __max_freq, u64 __turbo_freq) time2pixels(last_time)-time2pixels(first_time), cpu2y(cpu), SLOT_MULT+SLOT_HEIGHT); - sprintf(cpu_string, "CPU %i", (int)cpu+1); + sprintf(cpu_string, "CPU %i", (int)cpu); fprintf(svgfile, "%s\n", 10+time2pixels(first_time), cpu2y(cpu) + SLOT_HEIGHT/2, cpu_string); @@ -568,3 +576,123 @@ void svg_close(void) svgfile = NULL; } } + +#define cpumask_bits(maskp) ((maskp)->bits) +typedef struct { DECLARE_BITMAP(bits, MAX_NR_CPUS); } cpumask_t; + +struct topology { + cpumask_t *sib_core; + int sib_core_nr; + cpumask_t *sib_thr; + int sib_thr_nr; +}; + +static void scan_thread_topology(int *map, struct topology *t, int cpu, int *pos) +{ + int i; + int thr; + + for (i = 0; i < t->sib_thr_nr; i++) { + if (!test_bit(cpu, cpumask_bits(&t->sib_thr[i]))) + continue; + + for_each_set_bit(thr, + cpumask_bits(&t->sib_thr[i]), + MAX_NR_CPUS) + if (map[thr] == -1) + map[thr] = (*pos)++; + } +} + +static void scan_core_topology(int *map, struct topology *t) +{ + int pos = 0; + int i; + int cpu; + + for (i = 0; i < t->sib_core_nr; i++) + for_each_set_bit(cpu, + cpumask_bits(&t->sib_core[i]), + MAX_NR_CPUS) + scan_thread_topology(map, t, cpu, &pos); +} + +static int str_to_bitmap(char *s, cpumask_t *b) +{ + int i; + int ret = 0; + struct cpu_map *m; + int c; + + m = cpu_map__new(s); + if (!m) + return -1; + + for (i = 0; i < m->nr; i++) { + c = m->map[i]; + if (c >= MAX_NR_CPUS) { + ret = -1; + break; + } + + set_bit(c, cpumask_bits(b)); + } + + cpu_map__delete(m); + + return ret; +} + +int svg_build_topology_map(char *sib_core, int sib_core_nr, + char *sib_thr, int sib_thr_nr) +{ + int i; + struct topology t; + + t.sib_core_nr = sib_core_nr; + t.sib_thr_nr = sib_thr_nr; + t.sib_core = calloc(sib_core_nr, sizeof(cpumask_t)); + t.sib_thr = calloc(sib_thr_nr, sizeof(cpumask_t)); + + if (!t.sib_core || !t.sib_thr) { + fprintf(stderr, "topology: no memory\n"); + goto exit; + } + + for (i = 0; i < sib_core_nr; i++) { + if (str_to_bitmap(sib_core, &t.sib_core[i])) { + fprintf(stderr, "topology: can't parse siblings map\n"); + goto exit; + } + + sib_core += strlen(sib_core) + 1; + } + + for (i = 0; i < sib_thr_nr; i++) { + if (str_to_bitmap(sib_thr, &t.sib_thr[i])) { + fprintf(stderr, "topology: can't parse siblings map\n"); + goto exit; + } + + sib_thr += strlen(sib_thr) + 1; + } + + topology_map = malloc(sizeof(int) * MAX_NR_CPUS); + if (!topology_map) { + fprintf(stderr, "topology: no memory\n"); + goto exit; + } + + for (i = 0; i < MAX_NR_CPUS; i++) + topology_map[i] = -1; + + scan_core_topology(topology_map, &t); + + return 0; + +exit: + free(t.sib_core); + free(t.sib_thr); + + return -1; +} diff --git a/tools/perf/util/svghelper.h b/tools/perf/util/svghelper.h index 8b77ca631686..1df4fb6c3a4a 100644 --- a/tools/perf/util/svghelper.h +++ b/tools/perf/util/svghelper.h @@ -23,6 +23,8 @@ extern void svg_partial_wakeline(u64 start, int row1, char *desc1, int row2, cha extern void svg_interrupt(u64 start, int row, const char *backtrace); extern void svg_text(int Yslot, u64 start, const char *text); extern void svg_close(void); +extern int svg_build_topology_map(char *sib_core, int sib_core_nr, + char *sib_thr, int sib_thr_nr); extern int svg_page_width; -- cgit v1.2.3 From e57a2dffbc7e28cef5f4659b98a9d5595010ab4d Mon Sep 17 00:00:00 2001 From: Stanislav Fomichev Date: Tue, 17 Dec 2013 19:53:49 +0400 Subject: perf timechart: Add --highlight option This option highlights tasks (using different color) that run more than given duration or tasks with given name. Signed-off-by: Stanislav Fomichev Acked-by: Ingo Molnar Cc: Ingo Molnar Cc: Jiri Olsa Cc: Namhyung Kim Cc: Paul Mackerras Cc: Peter Zijlstra Cc: Ramkumar Ramachandra Link: http://lkml.kernel.org/r/20131217155349.GA13021@stfomichev-desktop Signed-off-by: Arnaldo Carvalho de Melo --- tools/perf/Documentation/perf-timechart.txt | 13 +++++++++++++ tools/perf/builtin-timechart.c | 21 ++++++++++++++++++++- tools/perf/util/svghelper.c | 23 ++++++++++++++++++++--- tools/perf/util/svghelper.h | 4 +++- 4 files changed, 56 insertions(+), 5 deletions(-) (limited to 'tools/perf/util/svghelper.h') diff --git a/tools/perf/Documentation/perf-timechart.txt b/tools/perf/Documentation/perf-timechart.txt index 367c1be0551c..bc5990c33dc0 100644 --- a/tools/perf/Documentation/perf-timechart.txt +++ b/tools/perf/Documentation/perf-timechart.txt @@ -56,12 +56,25 @@ $ perf timechart Written 10.2 seconds of trace to output.svg. +Record system-wide timechart: + + $ perf timechart record + + then generate timechart and highlight 'gcc' tasks: + + $ perf timechart --highlight gcc + -n:: --proc-num:: Print task info for at least given number of tasks. -t:: --topology:: Sort CPUs according to topology. +--highlight=:: + Highlight tasks (using different color) that run more than given + duration or tasks with given name. If number is given it's interpreted + as number of nanoseconds. If non-numeric string is given it's + interpreted as task name. RECORD OPTIONS -------------- diff --git a/tools/perf/builtin-timechart.c b/tools/perf/builtin-timechart.c index 8bde57c5c908..20d4212fa337 100644 --- a/tools/perf/builtin-timechart.c +++ b/tools/perf/builtin-timechart.c @@ -841,7 +841,6 @@ static void draw_cpu_usage(struct timechart *tchart) sample->start_time, sample->end_time, p->pid, - "sample", c->comm, sample->backtrace); } @@ -1252,6 +1251,23 @@ parse_process(const struct option *opt __maybe_unused, const char *arg, return 0; } +static int +parse_highlight(const struct option *opt __maybe_unused, const char *arg, + int __maybe_unused unset) +{ + unsigned long duration = strtoul(arg, NULL, 0); + + if (svg_highlight || svg_highlight_name) + return -1; + + if (duration) + svg_highlight = duration; + else + svg_highlight_name = strdup(arg); + + return 0; +} + int cmd_timechart(int argc, const char **argv, const char *prefix __maybe_unused) { @@ -1270,6 +1286,9 @@ int cmd_timechart(int argc, const char **argv, OPT_STRING('i', "input", &input_name, "file", "input file name"), OPT_STRING('o', "output", &output_name, "file", "output file name"), OPT_INTEGER('w', "width", &svg_page_width, "page width"), + OPT_CALLBACK(0, "highlight", NULL, "duration or task name", + "highlight tasks. Pass duration in ns or process name.", + parse_highlight), OPT_BOOLEAN('P', "power-only", &tchart.power_only, "output power data only"), OPT_BOOLEAN('T', "tasks-only", &tchart.tasks_only, "output processes data only"), diff --git a/tools/perf/util/svghelper.c b/tools/perf/util/svghelper.c index 9468136735ca..56a84f2cc46d 100644 --- a/tools/perf/util/svghelper.c +++ b/tools/perf/util/svghelper.c @@ -31,6 +31,8 @@ static u64 turbo_frequency, max_freq; #define SLOT_HEIGHT 25.0 int svg_page_width = 1000; +u64 svg_highlight; +const char *svg_highlight_name; #define MIN_TEXT_SIZE 0.01 @@ -112,6 +114,7 @@ void open_svg(const char *filename, int cpus, int rows, u64 start, u64 end) fprintf(svgfile, " rect.process { fill:rgb(180,180,180); fill-opacity:0.9; stroke-width:1; stroke:rgb( 0, 0, 0); } \n"); fprintf(svgfile, " rect.process2 { fill:rgb(180,180,180); fill-opacity:0.9; stroke-width:0; stroke:rgb( 0, 0, 0); } \n"); fprintf(svgfile, " rect.sample { fill:rgb( 0, 0,255); fill-opacity:0.8; stroke-width:0; stroke:rgb( 0, 0, 0); } \n"); + fprintf(svgfile, " rect.sample_hi{ fill:rgb(255,128, 0); fill-opacity:0.8; stroke-width:0; stroke:rgb( 0, 0, 0); } \n"); fprintf(svgfile, " rect.blocked { fill:rgb(255, 0, 0); fill-opacity:0.5; stroke-width:0; stroke:rgb( 0, 0, 0); } \n"); fprintf(svgfile, " rect.waiting { fill:rgb(224,214, 0); fill-opacity:0.8; stroke-width:0; stroke:rgb( 0, 0, 0); } \n"); fprintf(svgfile, " rect.WAITING { fill:rgb(255,214, 48); fill-opacity:0.6; stroke-width:0; stroke:rgb( 0, 0, 0); } \n"); @@ -155,17 +158,24 @@ void svg_blocked(int Yslot, int cpu, u64 start, u64 end, const char *backtrace) void svg_running(int Yslot, int cpu, u64 start, u64 end, const char *backtrace) { double text_size; + const char *type; + if (!svgfile) return; + if (svg_highlight && end - start > svg_highlight) + type = "sample_hi"; + else + type = "sample"; fprintf(svgfile, "\n"); fprintf(svgfile, "#%d running %s\n", cpu, time_to_string(end - start)); if (backtrace) fprintf(svgfile, "Switched because:\n%s\n", backtrace); - fprintf(svgfile, "\n", - time2pixels(start), time2pixels(end)-time2pixels(start), Yslot * SLOT_MULT, SLOT_HEIGHT); + fprintf(svgfile, "\n", + time2pixels(start), time2pixels(end)-time2pixels(start), Yslot * SLOT_MULT, SLOT_HEIGHT, + type); text_size = (time2pixels(end)-time2pixels(start)); if (cpu > 9) @@ -293,13 +303,20 @@ void svg_cpu_box(int cpu, u64 __max_freq, u64 __turbo_freq) fprintf(svgfile, "\n"); } -void svg_process(int cpu, u64 start, u64 end, int pid, const char *type, const char *name, const char *backtrace) +void svg_process(int cpu, u64 start, u64 end, int pid, const char *name, const char *backtrace) { double width; + const char *type; if (!svgfile) return; + if (svg_highlight && end - start >= svg_highlight) + type = "sample_hi"; + else if (svg_highlight_name && strstr(name, svg_highlight_name)) + type = "sample_hi"; + else + type = "sample"; fprintf(svgfile, "\n", time2pixels(start), cpu2y(cpu)); fprintf(svgfile, "%d %s running %s\n", pid, name, time_to_string(end - start)); diff --git a/tools/perf/util/svghelper.h b/tools/perf/util/svghelper.h index 1df4fb6c3a4a..f7b4d6e699ea 100644 --- a/tools/perf/util/svghelper.h +++ b/tools/perf/util/svghelper.h @@ -11,7 +11,7 @@ extern void svg_waiting(int Yslot, int cpu, u64 start, u64 end, const char *back extern void svg_cpu_box(int cpu, u64 max_frequency, u64 turbo_frequency); -extern void svg_process(int cpu, u64 start, u64 end, int pid, const char *type, const char *name, const char *backtrace); +extern void svg_process(int cpu, u64 start, u64 end, int pid, const char *name, const char *backtrace); extern void svg_cstate(int cpu, u64 start, u64 end, int type); extern void svg_pstate(int cpu, u64 start, u64 end, u64 freq); @@ -27,5 +27,7 @@ extern int svg_build_topology_map(char *sib_core, int sib_core_nr, char *sib_thr, int sib_thr_nr); extern int svg_page_width; +extern u64 svg_highlight; +extern const char *svg_highlight_name; #endif /* __PERF_SVGHELPER_H */ -- cgit v1.2.3