* [PATCH v4 0/4] perf timechart io mode
@ 2014-06-20 10:29 Stanislav Fomichev
2014-06-20 10:29 ` [PATCH 1/4] perf timechart: fix rendering in Firefox Stanislav Fomichev
` (5 more replies)
0 siblings, 6 replies; 23+ messages in thread
From: Stanislav Fomichev @ 2014-06-20 10:29 UTC (permalink / raw)
To: a.p.zijlstra, paulus, mingo, acme, stfomichev, namhyung,
artagnon, jolsa, rusty, bp
Cc: linux-kernel
This patchset adds IO mode: instead of process time we record io syscalls
and then draw timechart of writes/reads/tx/rx/polls.
v4:
- another attempt for fix segfault when skipping invalid tracepoints
- added new patch to fix rendering in Firefox
v3:
- fixed segfault when skipping invalid tracepoints
- added ms/us units support for --io-xyz time options
- fixed missing boxes on Firefox
v2:
- separated start_time fix into distinct commit
- separated --io-xyz options into distinct commit
- fixed 'error' shadowing
- initialized variables in declaration when possible
- removed assert usage
- fprintf -> pr_err
- removed wrongly placed __maybe_unused
Stanislav Fomichev (4):
perf timechart: fix rendering in Firefox
perf timechart: implement IO mode
perf timechart: conditionally update start_time on fork
perf timechart: add more options to IO mode
tools/perf/Documentation/perf-timechart.txt | 38 +-
tools/perf/builtin-timechart.c | 686 +++++++++++++++++++++++++++-
tools/perf/util/svghelper.c | 168 +++++--
tools/perf/util/svghelper.h | 6 +-
4 files changed, 838 insertions(+), 60 deletions(-)
--
1.8.3.2
^ permalink raw reply [flat|nested] 23+ messages in thread* [PATCH 1/4] perf timechart: fix rendering in Firefox 2014-06-20 10:29 [PATCH v4 0/4] perf timechart io mode Stanislav Fomichev @ 2014-06-20 10:29 ` Stanislav Fomichev 2014-06-20 10:29 ` [PATCH 2/4] perf timechart: implement IO mode Stanislav Fomichev ` (4 subsequent siblings) 5 siblings, 0 replies; 23+ messages in thread From: Stanislav Fomichev @ 2014-06-20 10:29 UTC (permalink / raw) To: a.p.zijlstra, paulus, mingo, acme, stfomichev, namhyung, artagnon, jolsa, rusty, bp Cc: linux-kernel Firefox doesn't correctly handle cases where we specify number in quotes and have some padding around the number, like the following: <rect ... height=" 3.1" ...> In this case, it doesn't draw the figure. This patch removes 'field width' component from fprintf strings to fix it. Signed-off-by: Stanislav Fomichev <stfomichev@yandex-team.ru> --- tools/perf/util/svghelper.c | 72 ++++++++++++++++++++++----------------------- 1 file changed, 36 insertions(+), 36 deletions(-) diff --git a/tools/perf/util/svghelper.c b/tools/perf/util/svghelper.c index 6a0a13d07a28..27caf0f45469 100644 --- a/tools/perf/util/svghelper.c +++ b/tools/perf/util/svghelper.c @@ -137,7 +137,7 @@ void svg_box(int Yslot, u64 start, u64 end, const char *type) if (!svgfile) return; - fprintf(svgfile, "<rect x=\"%4.8f\" width=\"%4.8f\" y=\"%4.1f\" height=\"%4.1f\" class=\"%s\"/>\n", + fprintf(svgfile, "<rect x=\"%.8f\" width=\"%.8f\" y=\"%.1f\" height=\"%.1f\" class=\"%s\"/>\n", time2pixels(start), time2pixels(end)-time2pixels(start), Yslot * SLOT_MULT, SLOT_HEIGHT, type); } @@ -174,7 +174,7 @@ void svg_running(int Yslot, int cpu, u64 start, u64 end, const char *backtrace) cpu, time_to_string(end - start)); if (backtrace) fprintf(svgfile, "<desc>Switched because:\n%s</desc>\n", backtrace); - fprintf(svgfile, "<rect x=\"%4.8f\" width=\"%4.8f\" y=\"%4.1f\" height=\"%4.1f\" class=\"%s\"/>\n", + fprintf(svgfile, "<rect x=\"%.8f\" width=\"%.8f\" y=\"%.1f\" height=\"%.1f\" class=\"%s\"/>\n", time2pixels(start), time2pixels(end)-time2pixels(start), Yslot * SLOT_MULT, SLOT_HEIGHT, type); @@ -186,7 +186,7 @@ void svg_running(int Yslot, int cpu, u64 start, u64 end, const char *backtrace) text_size = round_text_size(text_size); if (text_size > MIN_TEXT_SIZE) - fprintf(svgfile, "<text x=\"%1.8f\" y=\"%1.8f\" font-size=\"%1.8fpt\">%i</text>\n", + fprintf(svgfile, "<text x=\"%.8f\" y=\"%.8f\" font-size=\"%.8fpt\">%i</text>\n", time2pixels(start), Yslot * SLOT_MULT + SLOT_HEIGHT - 1, text_size, cpu + 1); fprintf(svgfile, "</g>\n"); @@ -202,10 +202,10 @@ static char *time_to_string(u64 duration) return text; if (duration < 1000 * 1000) { /* less than 1 msec */ - sprintf(text, "%4.1f us", duration / 1000.0); + sprintf(text, "%.1f us", duration / 1000.0); return text; } - sprintf(text, "%4.1f ms", duration / 1000.0 / 1000); + sprintf(text, "%.1f ms", duration / 1000.0 / 1000); return text; } @@ -233,14 +233,14 @@ void svg_waiting(int Yslot, int cpu, u64 start, u64 end, const char *backtrace) font_size = round_text_size(font_size); - fprintf(svgfile, "<g transform=\"translate(%4.8f,%4.8f)\">\n", time2pixels(start), Yslot * SLOT_MULT); + fprintf(svgfile, "<g transform=\"translate(%.8f,%.8f)\">\n", time2pixels(start), Yslot * SLOT_MULT); fprintf(svgfile, "<title>#%d waiting %s</title>\n", cpu, time_to_string(end - start)); if (backtrace) fprintf(svgfile, "<desc>Waiting on:\n%s</desc>\n", backtrace); - fprintf(svgfile, "<rect x=\"0\" width=\"%4.8f\" y=\"0\" height=\"%4.1f\" class=\"%s\"/>\n", + fprintf(svgfile, "<rect x=\"0\" width=\"%.8f\" y=\"0\" height=\"%.1f\" class=\"%s\"/>\n", time2pixels(end)-time2pixels(start), SLOT_HEIGHT, style); if (font_size > MIN_TEXT_SIZE) - fprintf(svgfile, "<text transform=\"rotate(90)\" font-size=\"%1.8fpt\"> %s</text>\n", + fprintf(svgfile, "<text transform=\"rotate(90)\" font-size=\"%.8fpt\"> %s</text>\n", font_size, text); fprintf(svgfile, "</g>\n"); } @@ -289,16 +289,16 @@ void svg_cpu_box(int cpu, u64 __max_freq, u64 __turbo_freq) fprintf(svgfile, "<g>\n"); - fprintf(svgfile, "<rect x=\"%4.8f\" width=\"%4.8f\" y=\"%4.1f\" height=\"%4.1f\" class=\"cpu\"/>\n", + fprintf(svgfile, "<rect x=\"%.8f\" width=\"%.8f\" y=\"%.1f\" height=\"%.1f\" class=\"cpu\"/>\n", time2pixels(first_time), time2pixels(last_time)-time2pixels(first_time), cpu2y(cpu), SLOT_MULT+SLOT_HEIGHT); sprintf(cpu_string, "CPU %i", (int)cpu); - fprintf(svgfile, "<text x=\"%4.8f\" y=\"%4.8f\">%s</text>\n", + fprintf(svgfile, "<text x=\"%.8f\" y=\"%.8f\">%s</text>\n", 10+time2pixels(first_time), cpu2y(cpu) + SLOT_HEIGHT/2, cpu_string); - fprintf(svgfile, "<text transform=\"translate(%4.8f,%4.8f)\" font-size=\"1.25pt\">%s</text>\n", + fprintf(svgfile, "<text transform=\"translate(%.8f,%.8f)\" font-size=\"1.25pt\">%s</text>\n", 10+time2pixels(first_time), cpu2y(cpu) + SLOT_MULT + SLOT_HEIGHT - 4, cpu_model()); fprintf(svgfile, "</g>\n"); @@ -319,11 +319,11 @@ void svg_process(int cpu, u64 start, u64 end, int pid, const char *name, const c else type = "sample"; - fprintf(svgfile, "<g transform=\"translate(%4.8f,%4.8f)\">\n", time2pixels(start), cpu2y(cpu)); + fprintf(svgfile, "<g transform=\"translate(%.8f,%.8f)\">\n", time2pixels(start), cpu2y(cpu)); fprintf(svgfile, "<title>%d %s running %s</title>\n", pid, name, time_to_string(end - start)); if (backtrace) fprintf(svgfile, "<desc>Switched because:\n%s</desc>\n", backtrace); - fprintf(svgfile, "<rect x=\"0\" width=\"%4.8f\" y=\"0\" height=\"%4.1f\" class=\"%s\"/>\n", + fprintf(svgfile, "<rect x=\"0\" width=\"%.8f\" y=\"0\" height=\"%.1f\" class=\"%s\"/>\n", time2pixels(end)-time2pixels(start), SLOT_MULT+SLOT_HEIGHT, type); width = time2pixels(end)-time2pixels(start); if (width > 6) @@ -332,7 +332,7 @@ void svg_process(int cpu, u64 start, u64 end, int pid, const char *name, const c width = round_text_size(width); if (width > MIN_TEXT_SIZE) - fprintf(svgfile, "<text transform=\"rotate(90)\" font-size=\"%3.8fpt\">%s</text>\n", + fprintf(svgfile, "<text transform=\"rotate(90)\" font-size=\"%.8fpt\">%s</text>\n", width, name); fprintf(svgfile, "</g>\n"); @@ -353,7 +353,7 @@ void svg_cstate(int cpu, u64 start, u64 end, int type) type = 6; sprintf(style, "c%i", type); - fprintf(svgfile, "<rect class=\"%s\" x=\"%4.8f\" width=\"%4.8f\" y=\"%4.1f\" height=\"%4.1f\"/>\n", + fprintf(svgfile, "<rect class=\"%s\" x=\"%.8f\" width=\"%.8f\" y=\"%.1f\" height=\"%.1f\"/>\n", style, time2pixels(start), time2pixels(end)-time2pixels(start), cpu2y(cpu), SLOT_MULT+SLOT_HEIGHT); @@ -365,7 +365,7 @@ void svg_cstate(int cpu, u64 start, u64 end, int type) width = round_text_size(width); if (width > MIN_TEXT_SIZE) - fprintf(svgfile, "<text x=\"%4.8f\" y=\"%4.8f\" font-size=\"%3.8fpt\">C%i</text>\n", + fprintf(svgfile, "<text x=\"%.8f\" y=\"%.8f\" font-size=\"%.8fpt\">C%i</text>\n", time2pixels(start), cpu2y(cpu)+width, width, type); fprintf(svgfile, "</g>\n"); @@ -407,9 +407,9 @@ void svg_pstate(int cpu, u64 start, u64 end, u64 freq) if (max_freq) height = freq * 1.0 / max_freq * (SLOT_HEIGHT + SLOT_MULT); height = 1 + cpu2y(cpu) + SLOT_MULT + SLOT_HEIGHT - height; - fprintf(svgfile, "<line x1=\"%4.8f\" x2=\"%4.8f\" y1=\"%4.1f\" y2=\"%4.1f\" class=\"pstate\"/>\n", + fprintf(svgfile, "<line x1=\"%.8f\" x2=\"%.8f\" y1=\"%.1f\" y2=\"%.1f\" class=\"pstate\"/>\n", time2pixels(start), time2pixels(end), height, height); - fprintf(svgfile, "<text x=\"%4.8f\" y=\"%4.8f\" font-size=\"0.25pt\">%s</text>\n", + fprintf(svgfile, "<text x=\"%.8f\" y=\"%.8f\" font-size=\"0.25pt\">%s</text>\n", time2pixels(start), height+0.9, HzToHuman(freq)); fprintf(svgfile, "</g>\n"); @@ -435,32 +435,32 @@ void svg_partial_wakeline(u64 start, int row1, char *desc1, int row2, char *desc if (row1 < row2) { if (row1) { - fprintf(svgfile, "<line x1=\"%4.8f\" y1=\"%4.2f\" x2=\"%4.8f\" y2=\"%4.2f\" style=\"stroke:rgb(32,255,32);stroke-width:0.009\"/>\n", + fprintf(svgfile, "<line x1=\"%.8f\" y1=\"%.2f\" x2=\"%.8f\" y2=\"%.2f\" style=\"stroke:rgb(32,255,32);stroke-width:0.009\"/>\n", time2pixels(start), row1 * SLOT_MULT + SLOT_HEIGHT, time2pixels(start), row1 * SLOT_MULT + SLOT_HEIGHT + SLOT_MULT/32); if (desc2) - fprintf(svgfile, "<g transform=\"translate(%4.8f,%4.8f)\"><text transform=\"rotate(90)\" font-size=\"0.02pt\">%s ></text></g>\n", + fprintf(svgfile, "<g transform=\"translate(%.8f,%.8f)\"><text transform=\"rotate(90)\" font-size=\"0.02pt\">%s ></text></g>\n", time2pixels(start), row1 * SLOT_MULT + SLOT_HEIGHT + SLOT_HEIGHT/48, desc2); } if (row2) { - fprintf(svgfile, "<line x1=\"%4.8f\" y1=\"%4.2f\" x2=\"%4.8f\" y2=\"%4.2f\" style=\"stroke:rgb(32,255,32);stroke-width:0.009\"/>\n", + fprintf(svgfile, "<line x1=\"%.8f\" y1=\"%.2f\" x2=\"%.8f\" y2=\"%.2f\" style=\"stroke:rgb(32,255,32);stroke-width:0.009\"/>\n", time2pixels(start), row2 * SLOT_MULT - SLOT_MULT/32, time2pixels(start), row2 * SLOT_MULT); if (desc1) - fprintf(svgfile, "<g transform=\"translate(%4.8f,%4.8f)\"><text transform=\"rotate(90)\" font-size=\"0.02pt\">%s ></text></g>\n", + fprintf(svgfile, "<g transform=\"translate(%.8f,%.8f)\"><text transform=\"rotate(90)\" font-size=\"0.02pt\">%s ></text></g>\n", time2pixels(start), row2 * SLOT_MULT - SLOT_MULT/32, desc1); } } else { if (row2) { - fprintf(svgfile, "<line x1=\"%4.8f\" y1=\"%4.2f\" x2=\"%4.8f\" y2=\"%4.2f\" style=\"stroke:rgb(32,255,32);stroke-width:0.009\"/>\n", + fprintf(svgfile, "<line x1=\"%.8f\" y1=\"%.2f\" x2=\"%.8f\" y2=\"%.2f\" style=\"stroke:rgb(32,255,32);stroke-width:0.009\"/>\n", time2pixels(start), row2 * SLOT_MULT + SLOT_HEIGHT, time2pixels(start), row2 * SLOT_MULT + SLOT_HEIGHT + SLOT_MULT/32); if (desc1) - fprintf(svgfile, "<g transform=\"translate(%4.8f,%4.8f)\"><text transform=\"rotate(90)\" font-size=\"0.02pt\">%s <</text></g>\n", + fprintf(svgfile, "<g transform=\"translate(%.8f,%.8f)\"><text transform=\"rotate(90)\" font-size=\"0.02pt\">%s <</text></g>\n", time2pixels(start), row2 * SLOT_MULT + SLOT_HEIGHT + SLOT_MULT/48, desc1); } if (row1) { - fprintf(svgfile, "<line x1=\"%4.8f\" y1=\"%4.2f\" x2=\"%4.8f\" y2=\"%4.2f\" style=\"stroke:rgb(32,255,32);stroke-width:0.009\"/>\n", + fprintf(svgfile, "<line x1=\"%.8f\" y1=\"%.2f\" x2=\"%.8f\" y2=\"%.2f\" style=\"stroke:rgb(32,255,32);stroke-width:0.009\"/>\n", time2pixels(start), row1 * SLOT_MULT - SLOT_MULT/32, time2pixels(start), row1 * SLOT_MULT); if (desc2) - fprintf(svgfile, "<g transform=\"translate(%4.8f,%4.8f)\"><text transform=\"rotate(90)\" font-size=\"0.02pt\">%s <</text></g>\n", + fprintf(svgfile, "<g transform=\"translate(%.8f,%.8f)\"><text transform=\"rotate(90)\" font-size=\"0.02pt\">%s <</text></g>\n", time2pixels(start), row1 * SLOT_MULT - SLOT_HEIGHT/32, desc2); } } @@ -468,7 +468,7 @@ void svg_partial_wakeline(u64 start, int row1, char *desc1, int row2, char *desc if (row2 > row1) height += SLOT_HEIGHT; if (row1) - fprintf(svgfile, "<circle cx=\"%4.8f\" cy=\"%4.2f\" r = \"0.01\" style=\"fill:rgb(32,255,32)\"/>\n", + fprintf(svgfile, "<circle cx=\"%.8f\" cy=\"%.2f\" r = \"0.01\" style=\"fill:rgb(32,255,32)\"/>\n", time2pixels(start), height); fprintf(svgfile, "</g>\n"); @@ -488,16 +488,16 @@ void svg_wakeline(u64 start, int row1, int row2, const char *backtrace) fprintf(svgfile, "<desc>%s</desc>\n", backtrace); if (row1 < row2) - fprintf(svgfile, "<line x1=\"%4.8f\" y1=\"%4.2f\" x2=\"%4.8f\" y2=\"%4.2f\" style=\"stroke:rgb(32,255,32);stroke-width:0.009\"/>\n", + fprintf(svgfile, "<line x1=\"%.8f\" y1=\"%.2f\" x2=\"%.8f\" y2=\"%.2f\" style=\"stroke:rgb(32,255,32);stroke-width:0.009\"/>\n", time2pixels(start), row1 * SLOT_MULT + SLOT_HEIGHT, time2pixels(start), row2 * SLOT_MULT); else - fprintf(svgfile, "<line x1=\"%4.8f\" y1=\"%4.2f\" x2=\"%4.8f\" y2=\"%4.2f\" style=\"stroke:rgb(32,255,32);stroke-width:0.009\"/>\n", + fprintf(svgfile, "<line x1=\"%.8f\" y1=\"%.2f\" x2=\"%.8f\" y2=\"%.2f\" style=\"stroke:rgb(32,255,32);stroke-width:0.009\"/>\n", time2pixels(start), row2 * SLOT_MULT + SLOT_HEIGHT, time2pixels(start), row1 * SLOT_MULT); height = row1 * SLOT_MULT; if (row2 > row1) height += SLOT_HEIGHT; - fprintf(svgfile, "<circle cx=\"%4.8f\" cy=\"%4.2f\" r = \"0.01\" style=\"fill:rgb(32,255,32)\"/>\n", + fprintf(svgfile, "<circle cx=\"%.8f\" cy=\"%.2f\" r = \"0.01\" style=\"fill:rgb(32,255,32)\"/>\n", time2pixels(start), height); fprintf(svgfile, "</g>\n"); @@ -515,9 +515,9 @@ void svg_interrupt(u64 start, int row, const char *backtrace) if (backtrace) fprintf(svgfile, "<desc>%s</desc>\n", backtrace); - fprintf(svgfile, "<circle cx=\"%4.8f\" cy=\"%4.2f\" r = \"0.01\" style=\"fill:rgb(255,128,128)\"/>\n", + fprintf(svgfile, "<circle cx=\"%.8f\" cy=\"%.2f\" r = \"0.01\" style=\"fill:rgb(255,128,128)\"/>\n", time2pixels(start), row * SLOT_MULT); - fprintf(svgfile, "<circle cx=\"%4.8f\" cy=\"%4.2f\" r = \"0.01\" style=\"fill:rgb(255,128,128)\"/>\n", + fprintf(svgfile, "<circle cx=\"%.8f\" cy=\"%.2f\" r = \"0.01\" style=\"fill:rgb(255,128,128)\"/>\n", time2pixels(start), row * SLOT_MULT + SLOT_HEIGHT); fprintf(svgfile, "</g>\n"); @@ -528,7 +528,7 @@ void svg_text(int Yslot, u64 start, const char *text) if (!svgfile) return; - fprintf(svgfile, "<text x=\"%4.8f\" y=\"%4.8f\">%s</text>\n", + fprintf(svgfile, "<text x=\"%.8f\" y=\"%.8f\">%s</text>\n", time2pixels(start), Yslot * SLOT_MULT+SLOT_HEIGHT/2, text); } @@ -537,9 +537,9 @@ static void svg_legenda_box(int X, const char *text, const char *style) double boxsize; boxsize = SLOT_HEIGHT / 2; - fprintf(svgfile, "<rect x=\"%i\" width=\"%4.8f\" y=\"0\" height=\"%4.1f\" class=\"%s\"/>\n", + fprintf(svgfile, "<rect x=\"%i\" width=\"%.8f\" y=\"0\" height=\"%.1f\" class=\"%s\"/>\n", X, boxsize, boxsize, style); - fprintf(svgfile, "<text transform=\"translate(%4.8f, %4.8f)\" font-size=\"%4.8fpt\">%s</text>\n", + fprintf(svgfile, "<text transform=\"translate(%.8f, %.8f)\" font-size=\"%.8fpt\">%s</text>\n", X + boxsize + 5, boxsize, 0.8 * boxsize, text); } @@ -579,7 +579,7 @@ void svg_time_grid(void) color = 128; } - fprintf(svgfile, "<line x1=\"%4.8f\" y1=\"%4.2f\" x2=\"%4.8f\" y2=\"%" PRIu64 "\" style=\"stroke:rgb(%i,%i,%i);stroke-width:%1.3f\"/>\n", + fprintf(svgfile, "<line x1=\"%.8f\" y1=\"%.2f\" x2=\"%.8f\" y2=\"%" PRIu64 "\" style=\"stroke:rgb(%i,%i,%i);stroke-width:%.3f\"/>\n", time2pixels(i), SLOT_MULT/2, time2pixels(i), total_height, color, color, color, thickness); i += 10000000; -- 1.8.3.2 ^ permalink raw reply related [flat|nested] 23+ messages in thread
* [PATCH 2/4] perf timechart: implement IO mode 2014-06-20 10:29 [PATCH v4 0/4] perf timechart io mode Stanislav Fomichev 2014-06-20 10:29 ` [PATCH 1/4] perf timechart: fix rendering in Firefox Stanislav Fomichev @ 2014-06-20 10:29 ` Stanislav Fomichev 2014-06-24 8:34 ` Jiri Olsa 2014-06-20 10:29 ` [PATCH 3/4] perf timechart: conditionally update start_time on fork Stanislav Fomichev ` (3 subsequent siblings) 5 siblings, 1 reply; 23+ messages in thread From: Stanislav Fomichev @ 2014-06-20 10:29 UTC (permalink / raw) To: a.p.zijlstra, paulus, mingo, acme, stfomichev, namhyung, artagnon, jolsa, rusty, bp Cc: linux-kernel In IO mode timechart shows any disk/network activity. Signed-off-by: Stanislav Fomichev <stfomichev@yandex-team.ru> --- tools/perf/Documentation/perf-timechart.txt | 25 +- tools/perf/builtin-timechart.c | 613 +++++++++++++++++++++++++++- tools/perf/util/svghelper.c | 98 ++++- tools/perf/util/svghelper.h | 6 +- 4 files changed, 718 insertions(+), 24 deletions(-) diff --git a/tools/perf/Documentation/perf-timechart.txt b/tools/perf/Documentation/perf-timechart.txt index 5e0f986dff38..ec6b46c7bca0 100644 --- a/tools/perf/Documentation/perf-timechart.txt +++ b/tools/perf/Documentation/perf-timechart.txt @@ -15,10 +15,20 @@ DESCRIPTION There are two variants of perf timechart: 'perf timechart record <command>' to record the system level events - of an arbitrary workload. + of an arbitrary workload. By default timechart records only scheduler + and CPU events (task switches, running times, CPU power states, etc), + but it's possible to record IO (disk, network) activity using -I argument. 'perf timechart' to turn a trace into a Scalable Vector Graphics file, - that can be viewed with popular SVG viewers such as 'Inkscape'. + that can be viewed with popular SVG viewers such as 'Inkscape'. Depending + on the events in the perf.data file, timechart will contain scheduler/cpu + events or IO events. + + In IO mode, every bar has two charts: upper and lower. + Upper bar shows incoming events (disk reads, ingress network packets). + Lower bar shows outgoing events (disk writes, egress network packets). + There are also poll bars which show how much time application spent + in poll/epoll/select syscalls. TIMECHART OPTIONS ----------------- @@ -63,6 +73,9 @@ RECORD OPTIONS -T:: --tasks-only:: Record only tasks-related events +-I:: +--io-only:: + Record only io-related events -g:: --callchain:: Do call-graph (stack chain/backtrace) recording @@ -87,6 +100,14 @@ Record system-wide timechart: $ perf timechart --highlight gcc +Record system-wide IO events: + + $ perf timechart record -I + + then generate timechart: + + $ perf timechart + SEE ALSO -------- linkperf:perf-record[1] diff --git a/tools/perf/builtin-timechart.c b/tools/perf/builtin-timechart.c index 74db2568b867..8d454c55bc4e 100644 --- a/tools/perf/builtin-timechart.c +++ b/tools/perf/builtin-timechart.c @@ -60,10 +60,14 @@ struct timechart { tasks_only, with_backtrace, topology; + /* IO related settings */ + u64 io_events; + bool io_only; }; struct per_pidcomm; struct cpu_sample; +struct io_sample; /* * Datastructure layout: @@ -84,6 +88,7 @@ struct per_pid { u64 start_time; u64 end_time; u64 total_time; + u64 total_bytes; int display; struct per_pidcomm *all; @@ -97,6 +102,8 @@ struct per_pidcomm { u64 start_time; u64 end_time; u64 total_time; + u64 max_bytes; + u64 total_bytes; int Y; int display; @@ -107,6 +114,7 @@ struct per_pidcomm { char *comm; struct cpu_sample *samples; + struct io_sample *io_samples; }; struct sample_wrapper { @@ -131,6 +139,27 @@ struct cpu_sample { const char *backtrace; }; +enum { + IOTYPE_READ, + IOTYPE_WRITE, + IOTYPE_SYNC, + IOTYPE_TX, + IOTYPE_RX, + IOTYPE_POLL, +}; + +struct io_sample { + struct io_sample *next; + + u64 start_time; + u64 end_time; + u64 bytes; + int type; + int fd; + int err; + int merges; +}; + #define CSTATE 1 #define PSTATE 2 @@ -682,6 +711,212 @@ static void end_sample_processing(struct timechart *tchart) } } +static int pid_begin_io_sample(struct timechart *tchart, int pid, int type, + u64 start, int fd) +{ + struct per_pid *p = find_create_pid(tchart, pid); + struct per_pidcomm *c = p->current; + struct io_sample *sample; + struct io_sample *prev; + + if (!c) { + c = zalloc(sizeof(*c)); + if (!c) + return -ENOMEM; + p->current = c; + c->next = p->all; + p->all = c; + } + + prev = c->io_samples; + + if (prev && prev->start_time && !prev->end_time) { + pr_err("Invalid previous event (duplicate start)!\n"); + return -1; + } + + sample = zalloc(sizeof(*sample)); + if (!sample) + return -ENOMEM; + sample->start_time = start; + sample->type = type; + sample->fd = fd; + sample->next = c->io_samples; + c->io_samples = sample; + + if (c->start_time == 0 || c->start_time > start) + c->start_time = start; + + return 0; +} + +static int pid_end_io_sample(struct timechart *tchart, int pid, int type, + u64 end, long ret) +{ + struct per_pid *p = find_create_pid(tchart, pid); + struct per_pidcomm *c = p->current; + struct io_sample *sample; + + if (!c) { + pr_err("Invalid pidcomm!\n"); + return -1; + } + + sample = c->io_samples; + + if (!sample) /* skip partially captured events */ + return 0; + + if (c->io_samples->end_time) { + pr_err("Invalid previous event (non-zero)!\n"); + return -1; + } + + if (c->io_samples->type != type) { + pr_err("Invalid previous event (type)!\n"); + return -1; + } + + sample->end_time = end; + + if (ret < 0) { + sample->err = ret; + } else if (type == IOTYPE_READ || type == IOTYPE_WRITE || + type == IOTYPE_TX || type == IOTYPE_RX) { + + if ((u64)ret > c->max_bytes) + c->max_bytes = ret; + + c->total_bytes += ret; + p->total_bytes += ret; + sample->bytes = ret; + } + + tchart->io_events++; + + return 0; +} + +static int +process_enter_read(struct timechart *tchart, + struct perf_evsel *evsel, + struct perf_sample *sample) +{ + long fd = perf_evsel__intval(evsel, sample, "fd"); + return pid_begin_io_sample(tchart, sample->tid, IOTYPE_READ, + sample->time, fd); +} + +static int +process_exit_read(struct timechart *tchart, + struct perf_evsel *evsel, + struct perf_sample *sample) +{ + long ret = perf_evsel__intval(evsel, sample, "ret"); + return pid_end_io_sample(tchart, sample->tid, IOTYPE_READ, + sample->time, ret); +} + +static int +process_enter_write(struct timechart *tchart, + struct perf_evsel *evsel, + struct perf_sample *sample) +{ + long fd = perf_evsel__intval(evsel, sample, "fd"); + return pid_begin_io_sample(tchart, sample->tid, IOTYPE_WRITE, + sample->time, fd); +} + +static int +process_exit_write(struct timechart *tchart, + struct perf_evsel *evsel, + struct perf_sample *sample) +{ + long ret = perf_evsel__intval(evsel, sample, "ret"); + return pid_end_io_sample(tchart, sample->tid, IOTYPE_WRITE, + sample->time, ret); +} + +static int +process_enter_sync(struct timechart *tchart, + struct perf_evsel *evsel, + struct perf_sample *sample) +{ + long fd = perf_evsel__intval(evsel, sample, "fd"); + return pid_begin_io_sample(tchart, sample->tid, IOTYPE_SYNC, + sample->time, fd); +} + +static int +process_exit_sync(struct timechart *tchart, + struct perf_evsel *evsel, + struct perf_sample *sample) +{ + long ret = perf_evsel__intval(evsel, sample, "ret"); + return pid_end_io_sample(tchart, sample->tid, IOTYPE_SYNC, + sample->time, ret); +} + +static int +process_enter_tx(struct timechart *tchart, + struct perf_evsel *evsel, + struct perf_sample *sample) +{ + long fd = perf_evsel__intval(evsel, sample, "fd"); + return pid_begin_io_sample(tchart, sample->tid, IOTYPE_TX, + sample->time, fd); +} + +static int +process_exit_tx(struct timechart *tchart, + struct perf_evsel *evsel, + struct perf_sample *sample) +{ + long ret = perf_evsel__intval(evsel, sample, "ret"); + return pid_end_io_sample(tchart, sample->tid, IOTYPE_TX, + sample->time, ret); +} + +static int +process_enter_rx(struct timechart *tchart, + struct perf_evsel *evsel, + struct perf_sample *sample) +{ + long fd = perf_evsel__intval(evsel, sample, "fd"); + return pid_begin_io_sample(tchart, sample->tid, IOTYPE_RX, + sample->time, fd); +} + +static int +process_exit_rx(struct timechart *tchart, + struct perf_evsel *evsel, + struct perf_sample *sample) +{ + long ret = perf_evsel__intval(evsel, sample, "ret"); + return pid_end_io_sample(tchart, sample->tid, IOTYPE_RX, + sample->time, ret); +} + +static int +process_enter_poll(struct timechart *tchart, + struct perf_evsel *evsel, + struct perf_sample *sample) +{ + long fd = perf_evsel__intval(evsel, sample, "fd"); + return pid_begin_io_sample(tchart, sample->tid, IOTYPE_POLL, + sample->time, fd); +} + +static int +process_exit_poll(struct timechart *tchart, + struct perf_evsel *evsel, + struct perf_sample *sample) +{ + long ret = perf_evsel__intval(evsel, sample, "ret"); + return pid_end_io_sample(tchart, sample->tid, IOTYPE_POLL, + sample->time, ret); +} + /* * Sort the pid datastructure */ @@ -852,6 +1087,117 @@ static void draw_cpu_usage(struct timechart *tchart) } } +static void draw_io_bars(struct timechart *tchart) +{ + const char *suf; + double bytes; + char comm[256]; + struct per_pid *p; + struct per_pidcomm *c; + struct io_sample *sample; + int Y = 1; + + p = tchart->all_data; + while (p) { + c = p->all; + while (c) { + if (!c->display) { + c->Y = 0; + c = c->next; + continue; + } + + svg_box(Y, c->start_time, c->end_time, "process3"); + sample = c->io_samples; + for (sample = c->io_samples; sample; sample = sample->next) { + double h = (double)sample->bytes / c->max_bytes; + + if (sample->err) + h = 1; + + if (sample->type == IOTYPE_SYNC) + svg_fbox(Y, + sample->start_time, + sample->end_time, + 1, + sample->err ? "error" : "sync", + sample->fd, + sample->err, + sample->merges); + else if (sample->type == IOTYPE_POLL) + svg_fbox(Y, + sample->start_time, + sample->end_time, + 1, + sample->err ? "error" : "poll", + sample->fd, + sample->err, + sample->merges); + else if (sample->type == IOTYPE_READ) + svg_ubox(Y, + sample->start_time, + sample->end_time, + h, + sample->err ? "error" : "disk", + sample->fd, + sample->err, + sample->merges); + else if (sample->type == IOTYPE_WRITE) + svg_lbox(Y, + sample->start_time, + sample->end_time, + h, + sample->err ? "error" : "disk", + sample->fd, + sample->err, + sample->merges); + else if (sample->type == IOTYPE_RX) + svg_ubox(Y, + sample->start_time, + sample->end_time, + h, + sample->err ? "error" : "net", + sample->fd, + sample->err, + sample->merges); + else if (sample->type == IOTYPE_TX) + svg_lbox(Y, + sample->start_time, + sample->end_time, + h, + sample->err ? "error" : "net", + sample->fd, + sample->err, + sample->merges); + } + + suf = ""; + bytes = c->total_bytes; + if (bytes > 1024) { + bytes = bytes / 1024; + suf = "K"; + } + if (bytes > 1024) { + bytes = bytes / 1024; + suf = "M"; + } + if (bytes > 1024) { + bytes = bytes / 1024; + suf = "G"; + } + + + sprintf(comm, "%s:%i (%3.1f %sbytes)", c->comm ?: "", p->pid, bytes, suf); + svg_text(Y, c->start_time, comm); + + c->Y = Y; + Y++; + c = c->next; + } + p = p->next; + } +} + static void draw_process_bars(struct timechart *tchart) { struct per_pid *p; @@ -987,9 +1333,6 @@ static int determine_display_tasks(struct timechart *tchart, u64 threshold) struct per_pidcomm *c; int count = 0; - if (process_filter) - return determine_display_tasks_filtered(tchart); - p = tchart->all_data; while (p) { p->display = 0; @@ -1025,15 +1368,46 @@ static int determine_display_tasks(struct timechart *tchart, u64 threshold) return count; } +static int determine_display_io_tasks(struct timechart *timechart, u64 threshold) +{ + struct per_pid *p; + struct per_pidcomm *c; + int count = 0; + + p = timechart->all_data; + while (p) { + /* no exit marker, task kept running to the end */ + if (p->end_time == 0) + p->end_time = timechart->last_time; + + c = p->all; + + while (c) { + c->display = 0; + if (c->total_bytes >= threshold) { + c->display = 1; + count++; + } + if (c->end_time == 0) + c->end_time = timechart->last_time; + + c = c->next; + } + p = p->next; + } + return count; +} + +#define BYTES_THRESH (1 * 1024 * 1024) #define TIME_THRESH 10000000 static void write_svg_file(struct timechart *tchart, const char *filename) { u64 i; int count; - int thresh = TIME_THRESH; + int thresh = tchart->io_events ? BYTES_THRESH : TIME_THRESH; if (tchart->power_only) tchart->proc_num = 0; @@ -1041,28 +1415,43 @@ static void write_svg_file(struct timechart *tchart, const char *filename) /* We'd like to show at least proc_num tasks; * be less picky if we have fewer */ do { - count = determine_display_tasks(tchart, thresh); + if (process_filter) + count = determine_display_tasks_filtered(tchart); + else if (tchart->io_events) + count = determine_display_io_tasks(tchart, thresh); + else + count = determine_display_tasks(tchart, thresh); thresh /= 10; } while (!process_filter && thresh && count < tchart->proc_num); if (!tchart->proc_num) count = 0; - open_svg(filename, tchart->numcpus, count, tchart->first_time, tchart->last_time); + if (tchart->io_events) { + open_svg(filename, 0, count, tchart->first_time, tchart->last_time); - svg_time_grid(); - svg_legenda(); + svg_time_grid(0.5); + svg_io_legenda(); - for (i = 0; i < tchart->numcpus; i++) - svg_cpu_box(i, tchart->max_freq, tchart->turbo_frequency); + draw_io_bars(tchart); + } else { + open_svg(filename, tchart->numcpus, count, tchart->first_time, tchart->last_time); - draw_cpu_usage(tchart); - if (tchart->proc_num) - draw_process_bars(tchart); - if (!tchart->tasks_only) - draw_c_p_states(tchart); - if (tchart->proc_num) - draw_wakeups(tchart); + svg_time_grid(0); + + svg_legenda(); + + for (i = 0; i < tchart->numcpus; i++) + svg_cpu_box(i, tchart->max_freq, tchart->turbo_frequency); + + draw_cpu_usage(tchart); + if (tchart->proc_num) + draw_process_bars(tchart); + if (!tchart->tasks_only) + draw_c_p_states(tchart); + if (tchart->proc_num) + draw_wakeups(tchart); + } svg_close(); } @@ -1110,6 +1499,56 @@ static int __cmd_timechart(struct timechart *tchart, const char *output_name) { "power:power_end", process_sample_power_end }, { "power:power_frequency", process_sample_power_frequency }, #endif + + { "syscalls:sys_enter_read", process_enter_read }, + { "syscalls:sys_enter_pread64", process_enter_read }, + { "syscalls:sys_enter_readv", process_enter_read }, + { "syscalls:sys_enter_preadv", process_enter_read }, + { "syscalls:sys_enter_write", process_enter_write }, + { "syscalls:sys_enter_pwrite64", process_enter_write }, + { "syscalls:sys_enter_writev", process_enter_write }, + { "syscalls:sys_enter_pwritev", process_enter_write }, + { "syscalls:sys_enter_sync", process_enter_sync }, + { "syscalls:sys_enter_sync_file_range", process_enter_sync }, + { "syscalls:sys_enter_fsync", process_enter_sync }, + { "syscalls:sys_enter_msync", process_enter_sync }, + { "syscalls:sys_enter_recvfrom", process_enter_rx }, + { "syscalls:sys_enter_recvmmsg", process_enter_rx }, + { "syscalls:sys_enter_recvmsg", process_enter_rx }, + { "syscalls:sys_enter_sendto", process_enter_tx }, + { "syscalls:sys_enter_sendmsg", process_enter_tx }, + { "syscalls:sys_enter_sendmmsg", process_enter_tx }, + { "syscalls:sys_enter_epoll_pwait", process_enter_poll }, + { "syscalls:sys_enter_epoll_wait", process_enter_poll }, + { "syscalls:sys_enter_poll", process_enter_poll }, + { "syscalls:sys_enter_ppoll", process_enter_poll }, + { "syscalls:sys_enter_pselect6", process_enter_poll }, + { "syscalls:sys_enter_select", process_enter_poll }, + + { "syscalls:sys_exit_read", process_exit_read }, + { "syscalls:sys_exit_pread64", process_exit_read }, + { "syscalls:sys_exit_readv", process_exit_read }, + { "syscalls:sys_exit_preadv", process_exit_read }, + { "syscalls:sys_exit_write", process_exit_write }, + { "syscalls:sys_exit_pwrite64", process_exit_write }, + { "syscalls:sys_exit_writev", process_exit_write }, + { "syscalls:sys_exit_pwritev", process_exit_write }, + { "syscalls:sys_exit_sync", process_exit_sync }, + { "syscalls:sys_exit_sync_file_range", process_exit_sync }, + { "syscalls:sys_exit_fsync", process_exit_sync }, + { "syscalls:sys_exit_msync", process_exit_sync }, + { "syscalls:sys_exit_recvfrom", process_exit_rx }, + { "syscalls:sys_exit_recvmmsg", process_exit_rx }, + { "syscalls:sys_exit_recvmsg", process_exit_rx }, + { "syscalls:sys_exit_sendto", process_exit_tx }, + { "syscalls:sys_exit_sendmsg", process_exit_tx }, + { "syscalls:sys_exit_sendmmsg", process_exit_tx }, + { "syscalls:sys_exit_epoll_pwait", process_exit_poll }, + { "syscalls:sys_exit_epoll_wait", process_exit_poll }, + { "syscalls:sys_exit_poll", process_exit_poll }, + { "syscalls:sys_exit_ppoll", process_exit_poll }, + { "syscalls:sys_exit_pselect6", process_exit_poll }, + { "syscalls:sys_exit_select", process_exit_poll }, }; struct perf_data_file file = { .path = input_name, @@ -1154,6 +1593,139 @@ out_delete: return ret; } +static int timechart__io_record(int argc, const char **argv) +{ + unsigned int rec_argc, i; + const char **rec_argv; + const char **p; + char *filter = NULL; + + const char * const common_args[] = { + "record", "-a", "-R", "-c", "1", + }; + unsigned int common_args_nr = ARRAY_SIZE(common_args); + + const char * const disk_events[] = { + "syscalls:sys_enter_read", + "syscalls:sys_enter_pread64", + "syscalls:sys_enter_readv", + "syscalls:sys_enter_preadv", + "syscalls:sys_enter_write", + "syscalls:sys_enter_pwrite64", + "syscalls:sys_enter_writev", + "syscalls:sys_enter_pwritev", + "syscalls:sys_enter_sync", + "syscalls:sys_enter_sync_file_range", + "syscalls:sys_enter_fsync", + "syscalls:sys_enter_msync", + + "syscalls:sys_exit_read", + "syscalls:sys_exit_pread64", + "syscalls:sys_exit_readv", + "syscalls:sys_exit_preadv", + "syscalls:sys_exit_write", + "syscalls:sys_exit_pwrite64", + "syscalls:sys_exit_writev", + "syscalls:sys_exit_pwritev", + "syscalls:sys_exit_sync", + "syscalls:sys_exit_sync_file_range", + "syscalls:sys_exit_fsync", + "syscalls:sys_exit_msync", + }; + unsigned int disk_events_nr = ARRAY_SIZE(disk_events); + + const char * const net_events[] = { + "syscalls:sys_enter_recvfrom", + "syscalls:sys_enter_recvmmsg", + "syscalls:sys_enter_recvmsg", + "syscalls:sys_enter_sendto", + "syscalls:sys_enter_sendmsg", + "syscalls:sys_enter_sendmmsg", + + "syscalls:sys_exit_recvfrom", + "syscalls:sys_exit_recvmmsg", + "syscalls:sys_exit_recvmsg", + "syscalls:sys_exit_sendto", + "syscalls:sys_exit_sendmsg", + "syscalls:sys_exit_sendmmsg", + }; + unsigned int net_events_nr = ARRAY_SIZE(net_events); + + const char * const poll_events[] = { + "syscalls:sys_enter_epoll_pwait", + "syscalls:sys_enter_epoll_wait", + "syscalls:sys_enter_poll", + "syscalls:sys_enter_ppoll", + "syscalls:sys_enter_pselect6", + "syscalls:sys_enter_select", + + "syscalls:sys_exit_epoll_pwait", + "syscalls:sys_exit_epoll_wait", + "syscalls:sys_exit_poll", + "syscalls:sys_exit_ppoll", + "syscalls:sys_exit_pselect6", + "syscalls:sys_exit_select", + }; + unsigned int poll_events_nr = ARRAY_SIZE(poll_events); + + rec_argc = common_args_nr + + disk_events_nr * 4 + + net_events_nr * 4 + + poll_events_nr * 4 + + argc; + rec_argv = calloc(rec_argc + 1, sizeof(char *)); + + if (rec_argv == NULL) + return -ENOMEM; + + if (asprintf(&filter, "common_pid != %d", getpid()) < 0) + return -ENOMEM; + + p = rec_argv; + for (i = 0; i < common_args_nr; i++) + *p++ = strdup(common_args[i]); + + for (i = 0; i < disk_events_nr; i++) { + if (!is_valid_tracepoint(disk_events[i])) { + rec_argc -= 4; + continue; + } + + *p++ = "-e"; + *p++ = strdup(disk_events[i]); + *p++ = "--filter"; + *p++ = filter; + } + for (i = 0; i < net_events_nr; i++) { + if (!is_valid_tracepoint(net_events[i])) { + rec_argc -= 4; + continue; + } + + *p++ = "-e"; + *p++ = strdup(net_events[i]); + *p++ = "--filter"; + *p++ = filter; + } + for (i = 0; i < poll_events_nr; i++) { + if (!is_valid_tracepoint(poll_events[i])) { + rec_argc -= 4; + continue; + } + + *p++ = "-e"; + *p++ = strdup(poll_events[i]); + *p++ = "--filter"; + *p++ = filter; + } + + for (i = 0; i < (unsigned int)argc; i++) + *p++ = argv[i]; + + return cmd_record(rec_argc, rec_argv, NULL); +} + + static int timechart__record(struct timechart *tchart, int argc, const char **argv) { unsigned int rec_argc, i, j; @@ -1314,6 +1886,8 @@ int cmd_timechart(int argc, const char **argv, OPT_BOOLEAN('P', "power-only", &tchart.power_only, "output power data only"), OPT_BOOLEAN('T', "tasks-only", &tchart.tasks_only, "output processes data only"), + OPT_BOOLEAN('I', "io-only", &tchart.io_only, + "record only IO data"), OPT_BOOLEAN('g', "callchain", &tchart.with_backtrace, "record callchain"), OPT_END() }; @@ -1340,7 +1914,10 @@ int cmd_timechart(int argc, const char **argv, return -1; } - return timechart__record(&tchart, argc, argv); + if (tchart.io_only) + return timechart__io_record(argc, argv); + else + return timechart__record(&tchart, argc, argv); } else if (argc) usage_with_options(timechart_usage, timechart_options); diff --git a/tools/perf/util/svghelper.c b/tools/perf/util/svghelper.c index 27caf0f45469..283d3e73e2f2 100644 --- a/tools/perf/util/svghelper.c +++ b/tools/perf/util/svghelper.c @@ -30,6 +30,7 @@ static u64 turbo_frequency, max_freq; #define SLOT_MULT 30.0 #define SLOT_HEIGHT 25.0 +#define SLOT_HALF (SLOT_HEIGHT / 2) int svg_page_width = 1000; u64 svg_highlight; @@ -114,8 +115,14 @@ void open_svg(const char *filename, int cpus, int rows, u64 start, u64 end) fprintf(svgfile, " rect { stroke-width: 1; }\n"); 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.process3 { fill:rgb(180,180,180); fill-opacity:0.5; 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.error { fill:rgb(255, 0, 0); fill-opacity:0.5; stroke-width:0; stroke:rgb( 0, 0, 0); } \n"); + fprintf(svgfile, " rect.net { fill:rgb( 0,128, 0); fill-opacity:0.5; stroke-width:0; stroke:rgb( 0, 0, 0); } \n"); + fprintf(svgfile, " rect.disk { fill:rgb( 0, 0,255); fill-opacity:0.5; stroke-width:0; stroke:rgb( 0, 0, 0); } \n"); + fprintf(svgfile, " rect.sync { fill:rgb(128,128, 0); fill-opacity:0.5; stroke-width:0; stroke:rgb( 0, 0, 0); } \n"); + fprintf(svgfile, " rect.poll { fill:rgb( 0,128,128); fill-opacity:0.2; 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"); @@ -132,6 +139,75 @@ void open_svg(const char *filename, int cpus, int rows, u64 start, u64 end) fprintf(svgfile, " ]]>\n </style>\n</defs>\n"); } +static double normalize_height(double height) +{ + if (height < 0.25) + return 0.25; + else if (height < 0.50) + return 0.50; + else if (height < 0.75) + return 0.75; + else + return 0.100; +} + +void svg_ubox(int Yslot, u64 start, u64 end, double height, const char *type, int fd, int err, int merges) +{ + double w = time2pixels(end) - time2pixels(start); + height = normalize_height(height); + + if (!svgfile) + return; + + fprintf(svgfile, "<g>\n"); + fprintf(svgfile, "<title>fd=%d error=%d merges=%d</title>\n", fd, err, merges); + fprintf(svgfile, "<rect x=\"%.8f\" width=\"%.8f\" y=\"%.1f\" height=\"%.1f\" class=\"%s\"/>\n", + time2pixels(start), + w, + Yslot * SLOT_MULT, + SLOT_HALF * height, + type); + fprintf(svgfile, "</g>\n"); +} + +void svg_lbox(int Yslot, u64 start, u64 end, double height, const char *type, int fd, int err, int merges) +{ + double w = time2pixels(end) - time2pixels(start); + height = normalize_height(height); + + if (!svgfile) + return; + + fprintf(svgfile, "<g>\n"); + fprintf(svgfile, "<title>fd=%d error=%d merges=%d</title>\n", fd, err, merges); + fprintf(svgfile, "<rect x=\"%.8f\" width=\"%.8f\" y=\"%.1f\" height=\"%.1f\" class=\"%s\"/>\n", + time2pixels(start), + w, + Yslot * SLOT_MULT + SLOT_HEIGHT - SLOT_HALF * height, + SLOT_HALF * height, + type); + fprintf(svgfile, "</g>\n"); +} + +void svg_fbox(int Yslot, u64 start, u64 end, double height, const char *type, int fd, int err, int merges) +{ + double w = time2pixels(end) - time2pixels(start); + height = normalize_height(height); + + if (!svgfile) + return; + + fprintf(svgfile, "<g>\n"); + fprintf(svgfile, "<title>fd=%d error=%d merges=%d</title>\n", fd, err, merges); + fprintf(svgfile, "<rect x=\"%.8f\" width=\"%.8f\" y=\"%.1f\" height=\"%.1f\" class=\"%s\"/>\n", + time2pixels(start), + w, + Yslot * SLOT_MULT + SLOT_HEIGHT - SLOT_HEIGHT * height, + SLOT_HEIGHT * height, + type); + fprintf(svgfile, "</g>\n"); +} + void svg_box(int Yslot, u64 start, u64 end, const char *type) { if (!svgfile) @@ -543,6 +619,20 @@ static void svg_legenda_box(int X, const char *text, const char *style) X + boxsize + 5, boxsize, 0.8 * boxsize, text); } +void svg_io_legenda(void) +{ + if (!svgfile) + return; + + fprintf(svgfile, "<g>\n"); + svg_legenda_box(0, "Disk", "disk"); + svg_legenda_box(100, "Network", "net"); + svg_legenda_box(200, "Sync", "sync"); + svg_legenda_box(300, "Poll", "poll"); + svg_legenda_box(400, "Error", "error"); + fprintf(svgfile, "</g>\n"); +} + void svg_legenda(void) { if (!svgfile) @@ -559,7 +649,7 @@ void svg_legenda(void) fprintf(svgfile, "</g>\n"); } -void svg_time_grid(void) +void svg_time_grid(double min_thickness) { u64 i; @@ -579,8 +669,10 @@ void svg_time_grid(void) color = 128; } - fprintf(svgfile, "<line x1=\"%.8f\" y1=\"%.2f\" x2=\"%.8f\" y2=\"%" PRIu64 "\" style=\"stroke:rgb(%i,%i,%i);stroke-width:%.3f\"/>\n", - time2pixels(i), SLOT_MULT/2, time2pixels(i), total_height, color, color, color, thickness); + if (thickness >= min_thickness) + fprintf(svgfile, "<line x1=\"%.8f\" y1=\"%.2f\" x2=\"%.8f\" y2=\"%" PRIu64 "\" style=\"stroke:rgb(%i,%i,%i);stroke-width:%.3f\"/>\n", + time2pixels(i), SLOT_MULT/2, time2pixels(i), + total_height, color, color, color, thickness); i += 10000000; } diff --git a/tools/perf/util/svghelper.h b/tools/perf/util/svghelper.h index e3aff5332e30..9292a5291445 100644 --- a/tools/perf/util/svghelper.h +++ b/tools/perf/util/svghelper.h @@ -4,6 +4,9 @@ #include <linux/types.h> extern void open_svg(const char *filename, int cpus, int rows, u64 start, u64 end); +extern void svg_ubox(int Yslot, u64 start, u64 end, double height, const char *type, int fd, int err, int merges); +extern void svg_lbox(int Yslot, u64 start, u64 end, double height, const char *type, int fd, int err, int merges); +extern void svg_fbox(int Yslot, u64 start, u64 end, double height, const char *type, int fd, int err, int merges); 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, const char *backtrace); extern void svg_running(int Yslot, int cpu, u64 start, u64 end, const char *backtrace); @@ -16,7 +19,8 @@ extern void svg_cstate(int cpu, u64 start, u64 end, int type); extern void svg_pstate(int cpu, u64 start, u64 end, u64 freq); -extern void svg_time_grid(void); +extern void svg_time_grid(double min_thickness); +extern void svg_io_legenda(void); extern void svg_legenda(void); 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); -- 1.8.3.2 ^ permalink raw reply related [flat|nested] 23+ messages in thread
* Re: [PATCH 2/4] perf timechart: implement IO mode 2014-06-20 10:29 ` [PATCH 2/4] perf timechart: implement IO mode Stanislav Fomichev @ 2014-06-24 8:34 ` Jiri Olsa 2014-06-24 17:00 ` Stanislav Fomichev 0 siblings, 1 reply; 23+ messages in thread From: Jiri Olsa @ 2014-06-24 8:34 UTC (permalink / raw) To: Stanislav Fomichev Cc: a.p.zijlstra, paulus, mingo, acme, namhyung, artagnon, rusty, bp, linux-kernel On Fri, Jun 20, 2014 at 02:29:49PM +0400, Stanislav Fomichev wrote: > In IO mode timechart shows any disk/network activity. way too small changelog for the size of the patch ;-) I'll need some more info (description, usage..) to push this throught thanks, jirka > > Signed-off-by: Stanislav Fomichev <stfomichev@yandex-team.ru> > --- > tools/perf/Documentation/perf-timechart.txt | 25 +- > tools/perf/builtin-timechart.c | 613 +++++++++++++++++++++++++++- > tools/perf/util/svghelper.c | 98 ++++- > tools/perf/util/svghelper.h | 6 +- > 4 files changed, 718 insertions(+), 24 deletions(-) > > diff --git a/tools/perf/Documentation/perf-timechart.txt b/tools/perf/Documentation/perf-timechart.txt > index 5e0f986dff38..ec6b46c7bca0 100644 > --- a/tools/perf/Documentation/perf-timechart.txt > +++ b/tools/perf/Documentation/perf-timechart.txt > @@ -15,10 +15,20 @@ DESCRIPTION > There are two variants of perf timechart: > > 'perf timechart record <command>' to record the system level events > - of an arbitrary workload. > + of an arbitrary workload. By default timechart records only scheduler > + and CPU events (task switches, running times, CPU power states, etc), > + but it's possible to record IO (disk, network) activity using -I argument. > > 'perf timechart' to turn a trace into a Scalable Vector Graphics file, > - that can be viewed with popular SVG viewers such as 'Inkscape'. > + that can be viewed with popular SVG viewers such as 'Inkscape'. Depending > + on the events in the perf.data file, timechart will contain scheduler/cpu > + events or IO events. > + > + In IO mode, every bar has two charts: upper and lower. > + Upper bar shows incoming events (disk reads, ingress network packets). > + Lower bar shows outgoing events (disk writes, egress network packets). > + There are also poll bars which show how much time application spent > + in poll/epoll/select syscalls. > > TIMECHART OPTIONS > ----------------- > @@ -63,6 +73,9 @@ RECORD OPTIONS > -T:: > --tasks-only:: > Record only tasks-related events > +-I:: > +--io-only:: > + Record only io-related events > -g:: > --callchain:: > Do call-graph (stack chain/backtrace) recording > @@ -87,6 +100,14 @@ Record system-wide timechart: > > $ perf timechart --highlight gcc > > +Record system-wide IO events: > + > + $ perf timechart record -I > + > + then generate timechart: > + > + $ perf timechart > + > SEE ALSO > -------- > linkperf:perf-record[1] > diff --git a/tools/perf/builtin-timechart.c b/tools/perf/builtin-timechart.c > index 74db2568b867..8d454c55bc4e 100644 > --- a/tools/perf/builtin-timechart.c > +++ b/tools/perf/builtin-timechart.c > @@ -60,10 +60,14 @@ struct timechart { > tasks_only, > with_backtrace, > topology; > + /* IO related settings */ > + u64 io_events; > + bool io_only; > }; > > struct per_pidcomm; > struct cpu_sample; > +struct io_sample; > > /* > * Datastructure layout: > @@ -84,6 +88,7 @@ struct per_pid { > u64 start_time; > u64 end_time; > u64 total_time; > + u64 total_bytes; > int display; > > struct per_pidcomm *all; > @@ -97,6 +102,8 @@ struct per_pidcomm { > u64 start_time; > u64 end_time; > u64 total_time; > + u64 max_bytes; > + u64 total_bytes; > > int Y; > int display; > @@ -107,6 +114,7 @@ struct per_pidcomm { > char *comm; > > struct cpu_sample *samples; > + struct io_sample *io_samples; > }; > > struct sample_wrapper { > @@ -131,6 +139,27 @@ struct cpu_sample { > const char *backtrace; > }; > > +enum { > + IOTYPE_READ, > + IOTYPE_WRITE, > + IOTYPE_SYNC, > + IOTYPE_TX, > + IOTYPE_RX, > + IOTYPE_POLL, > +}; > + > +struct io_sample { > + struct io_sample *next; > + > + u64 start_time; > + u64 end_time; > + u64 bytes; > + int type; > + int fd; > + int err; > + int merges; > +}; > + > #define CSTATE 1 > #define PSTATE 2 > > @@ -682,6 +711,212 @@ static void end_sample_processing(struct timechart *tchart) > } > } > > +static int pid_begin_io_sample(struct timechart *tchart, int pid, int type, > + u64 start, int fd) > +{ > + struct per_pid *p = find_create_pid(tchart, pid); > + struct per_pidcomm *c = p->current; > + struct io_sample *sample; > + struct io_sample *prev; > + > + if (!c) { > + c = zalloc(sizeof(*c)); > + if (!c) > + return -ENOMEM; > + p->current = c; > + c->next = p->all; > + p->all = c; > + } > + > + prev = c->io_samples; > + > + if (prev && prev->start_time && !prev->end_time) { > + pr_err("Invalid previous event (duplicate start)!\n"); > + return -1; > + } > + > + sample = zalloc(sizeof(*sample)); > + if (!sample) > + return -ENOMEM; > + sample->start_time = start; > + sample->type = type; > + sample->fd = fd; > + sample->next = c->io_samples; > + c->io_samples = sample; > + > + if (c->start_time == 0 || c->start_time > start) > + c->start_time = start; > + > + return 0; > +} > + > +static int pid_end_io_sample(struct timechart *tchart, int pid, int type, > + u64 end, long ret) > +{ > + struct per_pid *p = find_create_pid(tchart, pid); > + struct per_pidcomm *c = p->current; > + struct io_sample *sample; > + > + if (!c) { > + pr_err("Invalid pidcomm!\n"); > + return -1; > + } > + > + sample = c->io_samples; > + > + if (!sample) /* skip partially captured events */ > + return 0; > + > + if (c->io_samples->end_time) { > + pr_err("Invalid previous event (non-zero)!\n"); > + return -1; > + } > + > + if (c->io_samples->type != type) { > + pr_err("Invalid previous event (type)!\n"); > + return -1; > + } > + > + sample->end_time = end; > + > + if (ret < 0) { > + sample->err = ret; > + } else if (type == IOTYPE_READ || type == IOTYPE_WRITE || > + type == IOTYPE_TX || type == IOTYPE_RX) { > + > + if ((u64)ret > c->max_bytes) > + c->max_bytes = ret; > + > + c->total_bytes += ret; > + p->total_bytes += ret; > + sample->bytes = ret; > + } > + > + tchart->io_events++; > + > + return 0; > +} > + > +static int > +process_enter_read(struct timechart *tchart, > + struct perf_evsel *evsel, > + struct perf_sample *sample) > +{ > + long fd = perf_evsel__intval(evsel, sample, "fd"); > + return pid_begin_io_sample(tchart, sample->tid, IOTYPE_READ, > + sample->time, fd); > +} > + > +static int > +process_exit_read(struct timechart *tchart, > + struct perf_evsel *evsel, > + struct perf_sample *sample) > +{ > + long ret = perf_evsel__intval(evsel, sample, "ret"); > + return pid_end_io_sample(tchart, sample->tid, IOTYPE_READ, > + sample->time, ret); > +} > + > +static int > +process_enter_write(struct timechart *tchart, > + struct perf_evsel *evsel, > + struct perf_sample *sample) > +{ > + long fd = perf_evsel__intval(evsel, sample, "fd"); > + return pid_begin_io_sample(tchart, sample->tid, IOTYPE_WRITE, > + sample->time, fd); > +} > + > +static int > +process_exit_write(struct timechart *tchart, > + struct perf_evsel *evsel, > + struct perf_sample *sample) > +{ > + long ret = perf_evsel__intval(evsel, sample, "ret"); > + return pid_end_io_sample(tchart, sample->tid, IOTYPE_WRITE, > + sample->time, ret); > +} > + > +static int > +process_enter_sync(struct timechart *tchart, > + struct perf_evsel *evsel, > + struct perf_sample *sample) > +{ > + long fd = perf_evsel__intval(evsel, sample, "fd"); > + return pid_begin_io_sample(tchart, sample->tid, IOTYPE_SYNC, > + sample->time, fd); > +} > + > +static int > +process_exit_sync(struct timechart *tchart, > + struct perf_evsel *evsel, > + struct perf_sample *sample) > +{ > + long ret = perf_evsel__intval(evsel, sample, "ret"); > + return pid_end_io_sample(tchart, sample->tid, IOTYPE_SYNC, > + sample->time, ret); > +} > + > +static int > +process_enter_tx(struct timechart *tchart, > + struct perf_evsel *evsel, > + struct perf_sample *sample) > +{ > + long fd = perf_evsel__intval(evsel, sample, "fd"); > + return pid_begin_io_sample(tchart, sample->tid, IOTYPE_TX, > + sample->time, fd); > +} > + > +static int > +process_exit_tx(struct timechart *tchart, > + struct perf_evsel *evsel, > + struct perf_sample *sample) > +{ > + long ret = perf_evsel__intval(evsel, sample, "ret"); > + return pid_end_io_sample(tchart, sample->tid, IOTYPE_TX, > + sample->time, ret); > +} > + > +static int > +process_enter_rx(struct timechart *tchart, > + struct perf_evsel *evsel, > + struct perf_sample *sample) > +{ > + long fd = perf_evsel__intval(evsel, sample, "fd"); > + return pid_begin_io_sample(tchart, sample->tid, IOTYPE_RX, > + sample->time, fd); > +} > + > +static int > +process_exit_rx(struct timechart *tchart, > + struct perf_evsel *evsel, > + struct perf_sample *sample) > +{ > + long ret = perf_evsel__intval(evsel, sample, "ret"); > + return pid_end_io_sample(tchart, sample->tid, IOTYPE_RX, > + sample->time, ret); > +} > + > +static int > +process_enter_poll(struct timechart *tchart, > + struct perf_evsel *evsel, > + struct perf_sample *sample) > +{ > + long fd = perf_evsel__intval(evsel, sample, "fd"); > + return pid_begin_io_sample(tchart, sample->tid, IOTYPE_POLL, > + sample->time, fd); > +} > + > +static int > +process_exit_poll(struct timechart *tchart, > + struct perf_evsel *evsel, > + struct perf_sample *sample) > +{ > + long ret = perf_evsel__intval(evsel, sample, "ret"); > + return pid_end_io_sample(tchart, sample->tid, IOTYPE_POLL, > + sample->time, ret); > +} > + > /* > * Sort the pid datastructure > */ > @@ -852,6 +1087,117 @@ static void draw_cpu_usage(struct timechart *tchart) > } > } > > +static void draw_io_bars(struct timechart *tchart) > +{ > + const char *suf; > + double bytes; > + char comm[256]; > + struct per_pid *p; > + struct per_pidcomm *c; > + struct io_sample *sample; > + int Y = 1; > + > + p = tchart->all_data; > + while (p) { > + c = p->all; > + while (c) { > + if (!c->display) { > + c->Y = 0; > + c = c->next; > + continue; > + } > + > + svg_box(Y, c->start_time, c->end_time, "process3"); > + sample = c->io_samples; > + for (sample = c->io_samples; sample; sample = sample->next) { > + double h = (double)sample->bytes / c->max_bytes; > + > + if (sample->err) > + h = 1; > + > + if (sample->type == IOTYPE_SYNC) > + svg_fbox(Y, > + sample->start_time, > + sample->end_time, > + 1, > + sample->err ? "error" : "sync", > + sample->fd, > + sample->err, > + sample->merges); > + else if (sample->type == IOTYPE_POLL) > + svg_fbox(Y, > + sample->start_time, > + sample->end_time, > + 1, > + sample->err ? "error" : "poll", > + sample->fd, > + sample->err, > + sample->merges); > + else if (sample->type == IOTYPE_READ) > + svg_ubox(Y, > + sample->start_time, > + sample->end_time, > + h, > + sample->err ? "error" : "disk", > + sample->fd, > + sample->err, > + sample->merges); > + else if (sample->type == IOTYPE_WRITE) > + svg_lbox(Y, > + sample->start_time, > + sample->end_time, > + h, > + sample->err ? "error" : "disk", > + sample->fd, > + sample->err, > + sample->merges); > + else if (sample->type == IOTYPE_RX) > + svg_ubox(Y, > + sample->start_time, > + sample->end_time, > + h, > + sample->err ? "error" : "net", > + sample->fd, > + sample->err, > + sample->merges); > + else if (sample->type == IOTYPE_TX) > + svg_lbox(Y, > + sample->start_time, > + sample->end_time, > + h, > + sample->err ? "error" : "net", > + sample->fd, > + sample->err, > + sample->merges); > + } > + > + suf = ""; > + bytes = c->total_bytes; > + if (bytes > 1024) { > + bytes = bytes / 1024; > + suf = "K"; > + } > + if (bytes > 1024) { > + bytes = bytes / 1024; > + suf = "M"; > + } > + if (bytes > 1024) { > + bytes = bytes / 1024; > + suf = "G"; > + } > + > + > + sprintf(comm, "%s:%i (%3.1f %sbytes)", c->comm ?: "", p->pid, bytes, suf); > + svg_text(Y, c->start_time, comm); > + > + c->Y = Y; > + Y++; > + c = c->next; > + } > + p = p->next; > + } > +} > + > static void draw_process_bars(struct timechart *tchart) > { > struct per_pid *p; > @@ -987,9 +1333,6 @@ static int determine_display_tasks(struct timechart *tchart, u64 threshold) > struct per_pidcomm *c; > int count = 0; > > - if (process_filter) > - return determine_display_tasks_filtered(tchart); > - > p = tchart->all_data; > while (p) { > p->display = 0; > @@ -1025,15 +1368,46 @@ static int determine_display_tasks(struct timechart *tchart, u64 threshold) > return count; > } > > +static int determine_display_io_tasks(struct timechart *timechart, u64 threshold) > +{ > + struct per_pid *p; > + struct per_pidcomm *c; > + int count = 0; > + > + p = timechart->all_data; > + while (p) { > + /* no exit marker, task kept running to the end */ > + if (p->end_time == 0) > + p->end_time = timechart->last_time; > + > + c = p->all; > + > + while (c) { > + c->display = 0; > > + if (c->total_bytes >= threshold) { > + c->display = 1; > + count++; > + } > > + if (c->end_time == 0) > + c->end_time = timechart->last_time; > + > + c = c->next; > + } > + p = p->next; > + } > + return count; > +} > + > +#define BYTES_THRESH (1 * 1024 * 1024) > #define TIME_THRESH 10000000 > > static void write_svg_file(struct timechart *tchart, const char *filename) > { > u64 i; > int count; > - int thresh = TIME_THRESH; > + int thresh = tchart->io_events ? BYTES_THRESH : TIME_THRESH; > > if (tchart->power_only) > tchart->proc_num = 0; > @@ -1041,28 +1415,43 @@ static void write_svg_file(struct timechart *tchart, const char *filename) > /* We'd like to show at least proc_num tasks; > * be less picky if we have fewer */ > do { > - count = determine_display_tasks(tchart, thresh); > + if (process_filter) > + count = determine_display_tasks_filtered(tchart); > + else if (tchart->io_events) > + count = determine_display_io_tasks(tchart, thresh); > + else > + count = determine_display_tasks(tchart, thresh); > thresh /= 10; > } while (!process_filter && thresh && count < tchart->proc_num); > > if (!tchart->proc_num) > count = 0; > > - open_svg(filename, tchart->numcpus, count, tchart->first_time, tchart->last_time); > + if (tchart->io_events) { > + open_svg(filename, 0, count, tchart->first_time, tchart->last_time); > > - svg_time_grid(); > - svg_legenda(); > + svg_time_grid(0.5); > + svg_io_legenda(); > > - for (i = 0; i < tchart->numcpus; i++) > - svg_cpu_box(i, tchart->max_freq, tchart->turbo_frequency); > + draw_io_bars(tchart); > + } else { > + open_svg(filename, tchart->numcpus, count, tchart->first_time, tchart->last_time); > > - draw_cpu_usage(tchart); > - if (tchart->proc_num) > - draw_process_bars(tchart); > - if (!tchart->tasks_only) > - draw_c_p_states(tchart); > - if (tchart->proc_num) > - draw_wakeups(tchart); > + svg_time_grid(0); > + > + svg_legenda(); > + > + for (i = 0; i < tchart->numcpus; i++) > + svg_cpu_box(i, tchart->max_freq, tchart->turbo_frequency); > + > + draw_cpu_usage(tchart); > + if (tchart->proc_num) > + draw_process_bars(tchart); > + if (!tchart->tasks_only) > + draw_c_p_states(tchart); > + if (tchart->proc_num) > + draw_wakeups(tchart); > + } > > svg_close(); > } > @@ -1110,6 +1499,56 @@ static int __cmd_timechart(struct timechart *tchart, const char *output_name) > { "power:power_end", process_sample_power_end }, > { "power:power_frequency", process_sample_power_frequency }, > #endif > + > + { "syscalls:sys_enter_read", process_enter_read }, > + { "syscalls:sys_enter_pread64", process_enter_read }, > + { "syscalls:sys_enter_readv", process_enter_read }, > + { "syscalls:sys_enter_preadv", process_enter_read }, > + { "syscalls:sys_enter_write", process_enter_write }, > + { "syscalls:sys_enter_pwrite64", process_enter_write }, > + { "syscalls:sys_enter_writev", process_enter_write }, > + { "syscalls:sys_enter_pwritev", process_enter_write }, > + { "syscalls:sys_enter_sync", process_enter_sync }, > + { "syscalls:sys_enter_sync_file_range", process_enter_sync }, > + { "syscalls:sys_enter_fsync", process_enter_sync }, > + { "syscalls:sys_enter_msync", process_enter_sync }, > + { "syscalls:sys_enter_recvfrom", process_enter_rx }, > + { "syscalls:sys_enter_recvmmsg", process_enter_rx }, > + { "syscalls:sys_enter_recvmsg", process_enter_rx }, > + { "syscalls:sys_enter_sendto", process_enter_tx }, > + { "syscalls:sys_enter_sendmsg", process_enter_tx }, > + { "syscalls:sys_enter_sendmmsg", process_enter_tx }, > + { "syscalls:sys_enter_epoll_pwait", process_enter_poll }, > + { "syscalls:sys_enter_epoll_wait", process_enter_poll }, > + { "syscalls:sys_enter_poll", process_enter_poll }, > + { "syscalls:sys_enter_ppoll", process_enter_poll }, > + { "syscalls:sys_enter_pselect6", process_enter_poll }, > + { "syscalls:sys_enter_select", process_enter_poll }, > + > + { "syscalls:sys_exit_read", process_exit_read }, > + { "syscalls:sys_exit_pread64", process_exit_read }, > + { "syscalls:sys_exit_readv", process_exit_read }, > + { "syscalls:sys_exit_preadv", process_exit_read }, > + { "syscalls:sys_exit_write", process_exit_write }, > + { "syscalls:sys_exit_pwrite64", process_exit_write }, > + { "syscalls:sys_exit_writev", process_exit_write }, > + { "syscalls:sys_exit_pwritev", process_exit_write }, > + { "syscalls:sys_exit_sync", process_exit_sync }, > + { "syscalls:sys_exit_sync_file_range", process_exit_sync }, > + { "syscalls:sys_exit_fsync", process_exit_sync }, > + { "syscalls:sys_exit_msync", process_exit_sync }, > + { "syscalls:sys_exit_recvfrom", process_exit_rx }, > + { "syscalls:sys_exit_recvmmsg", process_exit_rx }, > + { "syscalls:sys_exit_recvmsg", process_exit_rx }, > + { "syscalls:sys_exit_sendto", process_exit_tx }, > + { "syscalls:sys_exit_sendmsg", process_exit_tx }, > + { "syscalls:sys_exit_sendmmsg", process_exit_tx }, > + { "syscalls:sys_exit_epoll_pwait", process_exit_poll }, > + { "syscalls:sys_exit_epoll_wait", process_exit_poll }, > + { "syscalls:sys_exit_poll", process_exit_poll }, > + { "syscalls:sys_exit_ppoll", process_exit_poll }, > + { "syscalls:sys_exit_pselect6", process_exit_poll }, > + { "syscalls:sys_exit_select", process_exit_poll }, > }; > struct perf_data_file file = { > .path = input_name, > @@ -1154,6 +1593,139 @@ out_delete: > return ret; > } > > +static int timechart__io_record(int argc, const char **argv) > +{ > + unsigned int rec_argc, i; > + const char **rec_argv; > + const char **p; > + char *filter = NULL; > + > + const char * const common_args[] = { > + "record", "-a", "-R", "-c", "1", > + }; > + unsigned int common_args_nr = ARRAY_SIZE(common_args); > + > + const char * const disk_events[] = { > + "syscalls:sys_enter_read", > + "syscalls:sys_enter_pread64", > + "syscalls:sys_enter_readv", > + "syscalls:sys_enter_preadv", > + "syscalls:sys_enter_write", > + "syscalls:sys_enter_pwrite64", > + "syscalls:sys_enter_writev", > + "syscalls:sys_enter_pwritev", > + "syscalls:sys_enter_sync", > + "syscalls:sys_enter_sync_file_range", > + "syscalls:sys_enter_fsync", > + "syscalls:sys_enter_msync", > + > + "syscalls:sys_exit_read", > + "syscalls:sys_exit_pread64", > + "syscalls:sys_exit_readv", > + "syscalls:sys_exit_preadv", > + "syscalls:sys_exit_write", > + "syscalls:sys_exit_pwrite64", > + "syscalls:sys_exit_writev", > + "syscalls:sys_exit_pwritev", > + "syscalls:sys_exit_sync", > + "syscalls:sys_exit_sync_file_range", > + "syscalls:sys_exit_fsync", > + "syscalls:sys_exit_msync", > + }; > + unsigned int disk_events_nr = ARRAY_SIZE(disk_events); > + > + const char * const net_events[] = { > + "syscalls:sys_enter_recvfrom", > + "syscalls:sys_enter_recvmmsg", > + "syscalls:sys_enter_recvmsg", > + "syscalls:sys_enter_sendto", > + "syscalls:sys_enter_sendmsg", > + "syscalls:sys_enter_sendmmsg", > + > + "syscalls:sys_exit_recvfrom", > + "syscalls:sys_exit_recvmmsg", > + "syscalls:sys_exit_recvmsg", > + "syscalls:sys_exit_sendto", > + "syscalls:sys_exit_sendmsg", > + "syscalls:sys_exit_sendmmsg", > + }; > + unsigned int net_events_nr = ARRAY_SIZE(net_events); > + > + const char * const poll_events[] = { > + "syscalls:sys_enter_epoll_pwait", > + "syscalls:sys_enter_epoll_wait", > + "syscalls:sys_enter_poll", > + "syscalls:sys_enter_ppoll", > + "syscalls:sys_enter_pselect6", > + "syscalls:sys_enter_select", > + > + "syscalls:sys_exit_epoll_pwait", > + "syscalls:sys_exit_epoll_wait", > + "syscalls:sys_exit_poll", > + "syscalls:sys_exit_ppoll", > + "syscalls:sys_exit_pselect6", > + "syscalls:sys_exit_select", > + }; > + unsigned int poll_events_nr = ARRAY_SIZE(poll_events); > + > + rec_argc = common_args_nr + > + disk_events_nr * 4 + > + net_events_nr * 4 + > + poll_events_nr * 4 + > + argc; > + rec_argv = calloc(rec_argc + 1, sizeof(char *)); > + > + if (rec_argv == NULL) > + return -ENOMEM; > + > + if (asprintf(&filter, "common_pid != %d", getpid()) < 0) > + return -ENOMEM; > + > + p = rec_argv; > + for (i = 0; i < common_args_nr; i++) > + *p++ = strdup(common_args[i]); > + > + for (i = 0; i < disk_events_nr; i++) { > + if (!is_valid_tracepoint(disk_events[i])) { > + rec_argc -= 4; > + continue; > + } > + > + *p++ = "-e"; > + *p++ = strdup(disk_events[i]); > + *p++ = "--filter"; > + *p++ = filter; > + } > + for (i = 0; i < net_events_nr; i++) { > + if (!is_valid_tracepoint(net_events[i])) { > + rec_argc -= 4; > + continue; > + } > + > + *p++ = "-e"; > + *p++ = strdup(net_events[i]); > + *p++ = "--filter"; > + *p++ = filter; > + } > + for (i = 0; i < poll_events_nr; i++) { > + if (!is_valid_tracepoint(poll_events[i])) { > + rec_argc -= 4; > + continue; > + } > + > + *p++ = "-e"; > + *p++ = strdup(poll_events[i]); > + *p++ = "--filter"; > + *p++ = filter; > + } > + > + for (i = 0; i < (unsigned int)argc; i++) > + *p++ = argv[i]; > + > + return cmd_record(rec_argc, rec_argv, NULL); > +} > + > + > static int timechart__record(struct timechart *tchart, int argc, const char **argv) > { > unsigned int rec_argc, i, j; > @@ -1314,6 +1886,8 @@ int cmd_timechart(int argc, const char **argv, > OPT_BOOLEAN('P', "power-only", &tchart.power_only, "output power data only"), > OPT_BOOLEAN('T', "tasks-only", &tchart.tasks_only, > "output processes data only"), > + OPT_BOOLEAN('I', "io-only", &tchart.io_only, > + "record only IO data"), > OPT_BOOLEAN('g', "callchain", &tchart.with_backtrace, "record callchain"), > OPT_END() > }; > @@ -1340,7 +1914,10 @@ int cmd_timechart(int argc, const char **argv, > return -1; > } > > - return timechart__record(&tchart, argc, argv); > + if (tchart.io_only) > + return timechart__io_record(argc, argv); > + else > + return timechart__record(&tchart, argc, argv); > } else if (argc) > usage_with_options(timechart_usage, timechart_options); > > diff --git a/tools/perf/util/svghelper.c b/tools/perf/util/svghelper.c > index 27caf0f45469..283d3e73e2f2 100644 > --- a/tools/perf/util/svghelper.c > +++ b/tools/perf/util/svghelper.c > @@ -30,6 +30,7 @@ static u64 turbo_frequency, max_freq; > > #define SLOT_MULT 30.0 > #define SLOT_HEIGHT 25.0 > +#define SLOT_HALF (SLOT_HEIGHT / 2) > > int svg_page_width = 1000; > u64 svg_highlight; > @@ -114,8 +115,14 @@ void open_svg(const char *filename, int cpus, int rows, u64 start, u64 end) > fprintf(svgfile, " rect { stroke-width: 1; }\n"); > 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.process3 { fill:rgb(180,180,180); fill-opacity:0.5; 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.error { fill:rgb(255, 0, 0); fill-opacity:0.5; stroke-width:0; stroke:rgb( 0, 0, 0); } \n"); > + fprintf(svgfile, " rect.net { fill:rgb( 0,128, 0); fill-opacity:0.5; stroke-width:0; stroke:rgb( 0, 0, 0); } \n"); > + fprintf(svgfile, " rect.disk { fill:rgb( 0, 0,255); fill-opacity:0.5; stroke-width:0; stroke:rgb( 0, 0, 0); } \n"); > + fprintf(svgfile, " rect.sync { fill:rgb(128,128, 0); fill-opacity:0.5; stroke-width:0; stroke:rgb( 0, 0, 0); } \n"); > + fprintf(svgfile, " rect.poll { fill:rgb( 0,128,128); fill-opacity:0.2; 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"); > @@ -132,6 +139,75 @@ void open_svg(const char *filename, int cpus, int rows, u64 start, u64 end) > fprintf(svgfile, " ]]>\n </style>\n</defs>\n"); > } > > +static double normalize_height(double height) > +{ > + if (height < 0.25) > + return 0.25; > + else if (height < 0.50) > + return 0.50; > + else if (height < 0.75) > + return 0.75; > + else > + return 0.100; > +} > + > +void svg_ubox(int Yslot, u64 start, u64 end, double height, const char *type, int fd, int err, int merges) > +{ > + double w = time2pixels(end) - time2pixels(start); > + height = normalize_height(height); > + > + if (!svgfile) > + return; > + > + fprintf(svgfile, "<g>\n"); > + fprintf(svgfile, "<title>fd=%d error=%d merges=%d</title>\n", fd, err, merges); > + fprintf(svgfile, "<rect x=\"%.8f\" width=\"%.8f\" y=\"%.1f\" height=\"%.1f\" class=\"%s\"/>\n", > + time2pixels(start), > + w, > + Yslot * SLOT_MULT, > + SLOT_HALF * height, > + type); > + fprintf(svgfile, "</g>\n"); > +} > + > +void svg_lbox(int Yslot, u64 start, u64 end, double height, const char *type, int fd, int err, int merges) > +{ > + double w = time2pixels(end) - time2pixels(start); > + height = normalize_height(height); > + > + if (!svgfile) > + return; > + > + fprintf(svgfile, "<g>\n"); > + fprintf(svgfile, "<title>fd=%d error=%d merges=%d</title>\n", fd, err, merges); > + fprintf(svgfile, "<rect x=\"%.8f\" width=\"%.8f\" y=\"%.1f\" height=\"%.1f\" class=\"%s\"/>\n", > + time2pixels(start), > + w, > + Yslot * SLOT_MULT + SLOT_HEIGHT - SLOT_HALF * height, > + SLOT_HALF * height, > + type); > + fprintf(svgfile, "</g>\n"); > +} > + > +void svg_fbox(int Yslot, u64 start, u64 end, double height, const char *type, int fd, int err, int merges) > +{ > + double w = time2pixels(end) - time2pixels(start); > + height = normalize_height(height); > + > + if (!svgfile) > + return; > + > + fprintf(svgfile, "<g>\n"); > + fprintf(svgfile, "<title>fd=%d error=%d merges=%d</title>\n", fd, err, merges); > + fprintf(svgfile, "<rect x=\"%.8f\" width=\"%.8f\" y=\"%.1f\" height=\"%.1f\" class=\"%s\"/>\n", > + time2pixels(start), > + w, > + Yslot * SLOT_MULT + SLOT_HEIGHT - SLOT_HEIGHT * height, > + SLOT_HEIGHT * height, > + type); > + fprintf(svgfile, "</g>\n"); > +} > + > void svg_box(int Yslot, u64 start, u64 end, const char *type) > { > if (!svgfile) > @@ -543,6 +619,20 @@ static void svg_legenda_box(int X, const char *text, const char *style) > X + boxsize + 5, boxsize, 0.8 * boxsize, text); > } > > +void svg_io_legenda(void) > +{ > + if (!svgfile) > + return; > + > + fprintf(svgfile, "<g>\n"); > + svg_legenda_box(0, "Disk", "disk"); > + svg_legenda_box(100, "Network", "net"); > + svg_legenda_box(200, "Sync", "sync"); > + svg_legenda_box(300, "Poll", "poll"); > + svg_legenda_box(400, "Error", "error"); > + fprintf(svgfile, "</g>\n"); > +} > + > void svg_legenda(void) > { > if (!svgfile) > @@ -559,7 +649,7 @@ void svg_legenda(void) > fprintf(svgfile, "</g>\n"); > } > > -void svg_time_grid(void) > +void svg_time_grid(double min_thickness) > { > u64 i; > > @@ -579,8 +669,10 @@ void svg_time_grid(void) > color = 128; > } > > - fprintf(svgfile, "<line x1=\"%.8f\" y1=\"%.2f\" x2=\"%.8f\" y2=\"%" PRIu64 "\" style=\"stroke:rgb(%i,%i,%i);stroke-width:%.3f\"/>\n", > - time2pixels(i), SLOT_MULT/2, time2pixels(i), total_height, color, color, color, thickness); > + if (thickness >= min_thickness) > + fprintf(svgfile, "<line x1=\"%.8f\" y1=\"%.2f\" x2=\"%.8f\" y2=\"%" PRIu64 "\" style=\"stroke:rgb(%i,%i,%i);stroke-width:%.3f\"/>\n", > + time2pixels(i), SLOT_MULT/2, time2pixels(i), > + total_height, color, color, color, thickness); > > i += 10000000; > } > diff --git a/tools/perf/util/svghelper.h b/tools/perf/util/svghelper.h > index e3aff5332e30..9292a5291445 100644 > --- a/tools/perf/util/svghelper.h > +++ b/tools/perf/util/svghelper.h > @@ -4,6 +4,9 @@ > #include <linux/types.h> > > extern void open_svg(const char *filename, int cpus, int rows, u64 start, u64 end); > +extern void svg_ubox(int Yslot, u64 start, u64 end, double height, const char *type, int fd, int err, int merges); > +extern void svg_lbox(int Yslot, u64 start, u64 end, double height, const char *type, int fd, int err, int merges); > +extern void svg_fbox(int Yslot, u64 start, u64 end, double height, const char *type, int fd, int err, int merges); > 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, const char *backtrace); > extern void svg_running(int Yslot, int cpu, u64 start, u64 end, const char *backtrace); > @@ -16,7 +19,8 @@ extern void svg_cstate(int cpu, u64 start, u64 end, int type); > extern void svg_pstate(int cpu, u64 start, u64 end, u64 freq); > > > -extern void svg_time_grid(void); > +extern void svg_time_grid(double min_thickness); > +extern void svg_io_legenda(void); > extern void svg_legenda(void); > 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); > -- > 1.8.3.2 > ^ permalink raw reply [flat|nested] 23+ messages in thread
* Re: [PATCH 2/4] perf timechart: implement IO mode 2014-06-24 8:34 ` Jiri Olsa @ 2014-06-24 17:00 ` Stanislav Fomichev 2014-06-24 18:21 ` Jiri Olsa 0 siblings, 1 reply; 23+ messages in thread From: Stanislav Fomichev @ 2014-06-24 17:00 UTC (permalink / raw) To: Jiri Olsa Cc: a.p.zijlstra, paulus, mingo, acme, namhyung, artagnon, rusty, bp, linux-kernel > I'll need some more info (description, usage..) to push this throught There is actual description and usage example in the documentation, does this count? Or you want me to also have some small explanation in the changelog? ^ permalink raw reply [flat|nested] 23+ messages in thread
* Re: [PATCH 2/4] perf timechart: implement IO mode 2014-06-24 17:00 ` Stanislav Fomichev @ 2014-06-24 18:21 ` Jiri Olsa 0 siblings, 0 replies; 23+ messages in thread From: Jiri Olsa @ 2014-06-24 18:21 UTC (permalink / raw) To: Stanislav Fomichev Cc: a.p.zijlstra, paulus, mingo, acme, namhyung, artagnon, rusty, bp, linux-kernel On Tue, Jun 24, 2014 at 09:00:12PM +0400, Stanislav Fomichev wrote: > > I'll need some more info (description, usage..) to push this throught > There is actual description and usage example in the documentation, does > this count? Or you want me to also have some small explanation in the > changelog? yep, in changelog.. feel free to use the info from documentation jirka ^ permalink raw reply [flat|nested] 23+ messages in thread
* [PATCH 3/4] perf timechart: conditionally update start_time on fork 2014-06-20 10:29 [PATCH v4 0/4] perf timechart io mode Stanislav Fomichev 2014-06-20 10:29 ` [PATCH 1/4] perf timechart: fix rendering in Firefox Stanislav Fomichev 2014-06-20 10:29 ` [PATCH 2/4] perf timechart: implement IO mode Stanislav Fomichev @ 2014-06-20 10:29 ` Stanislav Fomichev 2014-06-20 10:29 ` [PATCH 4/4] perf timechart: add more options to IO mode Stanislav Fomichev ` (2 subsequent siblings) 5 siblings, 0 replies; 23+ messages in thread From: Stanislav Fomichev @ 2014-06-20 10:29 UTC (permalink / raw) To: a.p.zijlstra, paulus, mingo, acme, stfomichev, namhyung, artagnon, jolsa, rusty, bp Cc: linux-kernel We don't need to overwrite current task start_time on fork, so update it only if it's zero. Signed-off-by: Stanislav Fomichev <stfomichev@yandex-team.ru> --- tools/perf/builtin-timechart.c | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/tools/perf/builtin-timechart.c b/tools/perf/builtin-timechart.c index 8d454c55bc4e..011569becc65 100644 --- a/tools/perf/builtin-timechart.c +++ b/tools/perf/builtin-timechart.c @@ -242,7 +242,7 @@ static void pid_fork(struct timechart *tchart, int pid, int ppid, u64 timestamp) pid_set_comm(tchart, pid, pp->current->comm); p->start_time = timestamp; - if (p->current) { + if (p->current && !p->current->start_time) { p->current->start_time = timestamp; p->current->state_since = timestamp; } -- 1.8.3.2 ^ permalink raw reply related [flat|nested] 23+ messages in thread
* [PATCH 4/4] perf timechart: add more options to IO mode 2014-06-20 10:29 [PATCH v4 0/4] perf timechart io mode Stanislav Fomichev ` (2 preceding siblings ...) 2014-06-20 10:29 ` [PATCH 3/4] perf timechart: conditionally update start_time on fork Stanislav Fomichev @ 2014-06-20 10:29 ` Stanislav Fomichev 2014-06-24 6:43 ` [PATCH v4 0/4] perf timechart io mode Namhyung Kim 2014-06-24 8:41 ` Jiri Olsa 5 siblings, 0 replies; 23+ messages in thread From: Stanislav Fomichev @ 2014-06-20 10:29 UTC (permalink / raw) To: a.p.zijlstra, paulus, mingo, acme, stfomichev, namhyung, artagnon, jolsa, rusty, bp Cc: linux-kernel --io-skip-eagain - don't show EAGAIN errors --io-min-time - make small io bursts visible --io-merge-dist - merge adjacent events Signed-off-by: Stanislav Fomichev <stfomichev@yandex-team.ru> --- tools/perf/Documentation/perf-timechart.txt | 13 +++++ tools/perf/builtin-timechart.c | 75 ++++++++++++++++++++++++++++- 2 files changed, 86 insertions(+), 2 deletions(-) diff --git a/tools/perf/Documentation/perf-timechart.txt b/tools/perf/Documentation/perf-timechart.txt index ec6b46c7bca0..df98d1c82688 100644 --- a/tools/perf/Documentation/perf-timechart.txt +++ b/tools/perf/Documentation/perf-timechart.txt @@ -64,6 +64,19 @@ TIMECHART OPTIONS 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. +--io-skip-eagain:: + Don't draw EAGAIN IO events. +--io-min-time=<nsecs>:: + Draw small events as if they lasted min-time. Useful when you need + to see very small and fast IO. It's possible to specify ms or us + suffix to specify time in milliseconds or microseconds. + Default value is 1ms. +--io-merge-dist=<nsecs>:: + Merge events that are merge-dist nanoseconds apart. + Reduces number of figures on the SVG and makes it more render-friendly. + It's possible to specify ms or us suffix to specify time in + milliseconds or microseconds. + Default value is 1us. RECORD OPTIONS -------------- diff --git a/tools/perf/builtin-timechart.c b/tools/perf/builtin-timechart.c index 011569becc65..732dc408ee0b 100644 --- a/tools/perf/builtin-timechart.c +++ b/tools/perf/builtin-timechart.c @@ -62,7 +62,10 @@ struct timechart { topology; /* IO related settings */ u64 io_events; - bool io_only; + bool io_only, + skip_eagain; + u64 min_time, + merge_dist; }; struct per_pidcomm; @@ -755,7 +758,7 @@ static int pid_end_io_sample(struct timechart *tchart, int pid, int type, { struct per_pid *p = find_create_pid(tchart, pid); struct per_pidcomm *c = p->current; - struct io_sample *sample; + struct io_sample *sample, *prev; if (!c) { pr_err("Invalid pidcomm!\n"); @@ -778,6 +781,18 @@ static int pid_end_io_sample(struct timechart *tchart, int pid, int type, } sample->end_time = end; + prev = sample->next; + + /* we want to be able to see small and fast transfers, so make them + * at least min_time long, but don't overlap them */ + if (sample->end_time - sample->start_time < tchart->min_time) + sample->end_time = sample->start_time + tchart->min_time; + if (prev && sample->start_time < prev->end_time) { + if (prev->err) /* try to make errors more visible */ + sample->start_time = prev->end_time; + else + prev->end_time = sample->start_time; + } if (ret < 0) { sample->err = ret; @@ -792,6 +807,24 @@ static int pid_end_io_sample(struct timechart *tchart, int pid, int type, sample->bytes = ret; } + /* merge two requests to make svg smaller and render-friendly */ + if (prev && + prev->type == sample->type && + prev->err == sample->err && + prev->fd == sample->fd && + prev->end_time + tchart->merge_dist >= sample->start_time) { + + sample->bytes += prev->bytes; + sample->merges += prev->merges + 1; + + sample->start_time = prev->start_time; + sample->next = prev->next; + free(prev); + + if (!sample->err && sample->bytes > c->max_bytes) + c->max_bytes = sample->bytes; + } + tchart->io_events++; return 0; @@ -1112,6 +1145,10 @@ static void draw_io_bars(struct timechart *tchart) for (sample = c->io_samples; sample; sample = sample->next) { double h = (double)sample->bytes / c->max_bytes; + if (tchart->skip_eagain && + sample->err == -EAGAIN) + continue; + if (sample->err) h = 1; @@ -1842,6 +1879,30 @@ parse_highlight(const struct option *opt __maybe_unused, const char *arg, return 0; } +static int +parse_time(const struct option *opt, const char *arg, int __maybe_unused unset) +{ + char unit = 'n'; + u64 *value = opt->value; + + if (sscanf(arg, "%" PRIu64 "%cs", value, &unit) > 0) { + switch (unit) { + case 'm': + *value *= 1000000; + break; + case 'u': + *value *= 1000; + break; + case 'n': + break; + default: + return -1; + } + } + + return 0; +} + int cmd_timechart(int argc, const char **argv, const char *prefix __maybe_unused) { @@ -1854,6 +1915,8 @@ int cmd_timechart(int argc, const char **argv, .ordered_samples = true, }, .proc_num = 15, + .min_time = 1000000, + .merge_dist = 1000, }; const char *output_name = "output.svg"; const struct option timechart_options[] = { @@ -1875,6 +1938,14 @@ int cmd_timechart(int argc, const char **argv, "min. number of tasks to print"), OPT_BOOLEAN('t', "topology", &tchart.topology, "sort CPUs according to topology"), + OPT_BOOLEAN(0, "io-skip-eagain", &tchart.skip_eagain, + "skip EAGAIN errors"), + OPT_CALLBACK(0, "io-min-time", &tchart.min_time, "time", + "all IO faster than min-time will visually appear longer", + parse_time), + OPT_CALLBACK(0, "io-merge-dist", &tchart.merge_dist, "time", + "merge events that are merge-dist us apart", + parse_time), OPT_END() }; const char * const timechart_usage[] = { -- 1.8.3.2 ^ permalink raw reply related [flat|nested] 23+ messages in thread
* Re: [PATCH v4 0/4] perf timechart io mode 2014-06-20 10:29 [PATCH v4 0/4] perf timechart io mode Stanislav Fomichev ` (3 preceding siblings ...) 2014-06-20 10:29 ` [PATCH 4/4] perf timechart: add more options to IO mode Stanislav Fomichev @ 2014-06-24 6:43 ` Namhyung Kim 2014-06-24 8:41 ` Jiri Olsa 5 siblings, 0 replies; 23+ messages in thread From: Namhyung Kim @ 2014-06-24 6:43 UTC (permalink / raw) To: Stanislav Fomichev Cc: a.p.zijlstra, paulus, mingo, acme, artagnon, jolsa, rusty, bp, linux-kernel Hi Stanislav, On Fri, 20 Jun 2014 14:29:47 +0400, Stanislav Fomichev wrote: > This patchset adds IO mode: instead of process time we record io syscalls > and then draw timechart of writes/reads/tx/rx/polls. Nice work! For the series, Acked-by: Namhyung Kim <namhyung@kernel.org> Thanks, Namhyung > > v4: > - another attempt for fix segfault when skipping invalid tracepoints > - added new patch to fix rendering in Firefox > > v3: > - fixed segfault when skipping invalid tracepoints > - added ms/us units support for --io-xyz time options > - fixed missing boxes on Firefox > > v2: > - separated start_time fix into distinct commit > - separated --io-xyz options into distinct commit > - fixed 'error' shadowing > - initialized variables in declaration when possible > - removed assert usage > - fprintf -> pr_err > - removed wrongly placed __maybe_unused > > Stanislav Fomichev (4): > perf timechart: fix rendering in Firefox > perf timechart: implement IO mode > perf timechart: conditionally update start_time on fork > perf timechart: add more options to IO mode > > tools/perf/Documentation/perf-timechart.txt | 38 +- > tools/perf/builtin-timechart.c | 686 +++++++++++++++++++++++++++- > tools/perf/util/svghelper.c | 168 +++++-- > tools/perf/util/svghelper.h | 6 +- > 4 files changed, 838 insertions(+), 60 deletions(-) ^ permalink raw reply [flat|nested] 23+ messages in thread
* Re: [PATCH v4 0/4] perf timechart io mode 2014-06-20 10:29 [PATCH v4 0/4] perf timechart io mode Stanislav Fomichev ` (4 preceding siblings ...) 2014-06-24 6:43 ` [PATCH v4 0/4] perf timechart io mode Namhyung Kim @ 2014-06-24 8:41 ` Jiri Olsa 2014-06-24 9:10 ` Stanislav Fomichev 5 siblings, 1 reply; 23+ messages in thread From: Jiri Olsa @ 2014-06-24 8:41 UTC (permalink / raw) To: Stanislav Fomichev Cc: a.p.zijlstra, paulus, mingo, acme, namhyung, artagnon, rusty, bp, linux-kernel On Fri, Jun 20, 2014 at 02:29:47PM +0400, Stanislav Fomichev wrote: > This patchset adds IO mode: instead of process time we record io syscalls > and then draw timechart of writes/reads/tx/rx/polls. > > v4: > - another attempt for fix segfault when skipping invalid tracepoints > - added new patch to fix rendering in Firefox hum, got this when trying: [jolsa@krava perf]$ sudo ./perf timechart record -I ^C[ perf record: Woken up 2 times to write data ] [ perf record: Captured and wrote 1.071 MB perf.data (~46806 samples) ] [jolsa@krava perf]$ ./perf timechart Invalid previous event (non-zero)! 0x113f80 [0x8]: failed to process type: 68 jirka > > v3: > - fixed segfault when skipping invalid tracepoints > - added ms/us units support for --io-xyz time options > - fixed missing boxes on Firefox > > v2: > - separated start_time fix into distinct commit > - separated --io-xyz options into distinct commit > - fixed 'error' shadowing > - initialized variables in declaration when possible > - removed assert usage > - fprintf -> pr_err > - removed wrongly placed __maybe_unused > > Stanislav Fomichev (4): > perf timechart: fix rendering in Firefox > perf timechart: implement IO mode > perf timechart: conditionally update start_time on fork > perf timechart: add more options to IO mode > > tools/perf/Documentation/perf-timechart.txt | 38 +- > tools/perf/builtin-timechart.c | 686 +++++++++++++++++++++++++++- > tools/perf/util/svghelper.c | 168 +++++-- > tools/perf/util/svghelper.h | 6 +- > 4 files changed, 838 insertions(+), 60 deletions(-) > > -- > 1.8.3.2 > ^ permalink raw reply [flat|nested] 23+ messages in thread
* Re: [PATCH v4 0/4] perf timechart io mode 2014-06-24 8:41 ` Jiri Olsa @ 2014-06-24 9:10 ` Stanislav Fomichev 2014-06-24 16:57 ` Stanislav Fomichev 0 siblings, 1 reply; 23+ messages in thread From: Stanislav Fomichev @ 2014-06-24 9:10 UTC (permalink / raw) To: Jiri Olsa Cc: a.p.zijlstra, paulus, mingo, acme, namhyung, artagnon, rusty, bp, linux-kernel > hum, got this when trying: > > [jolsa@krava perf]$ sudo ./perf timechart record -I > ^C[ perf record: Woken up 2 times to write data ] > [ perf record: Captured and wrote 1.071 MB perf.data (~46806 samples) ] > [jolsa@krava perf]$ ./perf timechart > Invalid previous event (non-zero)! > 0x113f80 [0x8]: failed to process type: 68 Hm, I added a bunch of consistency checks which I couldn't actually hit myself. Nice work :-) Can I get you perf.data? ^ permalink raw reply [flat|nested] 23+ messages in thread
* Re: [PATCH v4 0/4] perf timechart io mode 2014-06-24 9:10 ` Stanislav Fomichev @ 2014-06-24 16:57 ` Stanislav Fomichev 2014-06-24 17:01 ` Stanislav Fomichev 2014-06-24 17:38 ` David Ahern 0 siblings, 2 replies; 23+ messages in thread From: Stanislav Fomichev @ 2014-06-24 16:57 UTC (permalink / raw) To: linux-kernel Cc: a.p.zijlstra, paulus, mingo, acme, namhyung, artagnon, rusty, bp, Jiri Olsa On Tue, Jun 24, 2014 at 01:10:22PM +0400, Stanislav Fomichev wrote: > > hum, got this when trying: > > > > [jolsa@krava perf]$ sudo ./perf timechart record -I > > ^C[ perf record: Woken up 2 times to write data ] > > [ perf record: Captured and wrote 1.071 MB perf.data (~46806 samples) ] > > [jolsa@krava perf]$ ./perf timechart > > Invalid previous event (non-zero)! > > 0x113f80 [0x8]: failed to process type: 68 > Hm, I added a bunch of consistency checks which I couldn't actually hit > myself. Nice work :-) Can I get you perf.data? For some reason, in Jiri's trace we see exit from sys_read with 2, and then again exit from sys_read with -EAGAIN: xterm 32028 [000] 43390.908909: syscalls:sys_enter_read: fd: 0x00000004, buf: 0x02076e8c, count: 0x0 xterm 32028 [000] 43390.908917: syscalls:sys_exit_read: 0x2 xterm 32028 [000] 43390.908982: syscalls:sys_exit_read: 0xfffffffffffffff5 I'm not sure how it is possible (either we lost sys_enter, or timestamp of seconds -EAGAIN is wrong?). I think we might just convert this error to a warning (we couldn't reproduce it again). Should I resend the whole series (preferred) or add another patch on top? ^ permalink raw reply [flat|nested] 23+ messages in thread
* Re: [PATCH v4 0/4] perf timechart io mode 2014-06-24 16:57 ` Stanislav Fomichev @ 2014-06-24 17:01 ` Stanislav Fomichev 2014-06-24 17:38 ` David Ahern 1 sibling, 0 replies; 23+ messages in thread From: Stanislav Fomichev @ 2014-06-24 17:01 UTC (permalink / raw) To: linux-kernel Cc: a.p.zijlstra, paulus, mingo, acme, namhyung, artagnon, rusty, bp, Jiri Olsa > For some reason, in Jiri's trace we see exit from sys_read with 2, > and then again exit from sys_read with -EAGAIN: > xterm 32028 [000] 43390.908909: syscalls:sys_enter_read: fd: 0x00000004, buf: 0x02076e8c, count: 0x0 > xterm 32028 [000] 43390.908917: syscalls:sys_exit_read: 0x2 > xterm 32028 [000] 43390.908982: syscalls:sys_exit_read: 0xfffffffffffffff5 > > I'm not sure how it is possible (either we lost sys_enter, or timestamp > of seconds -EAGAIN is wrong?). I think we might just convert this error > to a warning (we couldn't reproduce it again). > Should I resend the whole series (preferred) or add another patch on > top? Or probably left it as is, because perf.data is really weird... ^ permalink raw reply [flat|nested] 23+ messages in thread
* Re: [PATCH v4 0/4] perf timechart io mode 2014-06-24 16:57 ` Stanislav Fomichev 2014-06-24 17:01 ` Stanislav Fomichev @ 2014-06-24 17:38 ` David Ahern 2014-06-24 18:51 ` Jiri Olsa 1 sibling, 1 reply; 23+ messages in thread From: David Ahern @ 2014-06-24 17:38 UTC (permalink / raw) To: Stanislav Fomichev, linux-kernel Cc: a.p.zijlstra, paulus, mingo, acme, namhyung, artagnon, rusty, bp, Jiri Olsa On 6/24/14, 10:57 AM, Stanislav Fomichev wrote: > On Tue, Jun 24, 2014 at 01:10:22PM +0400, Stanislav Fomichev wrote: >>> hum, got this when trying: >>> >>> [jolsa@krava perf]$ sudo ./perf timechart record -I >>> ^C[ perf record: Woken up 2 times to write data ] >>> [ perf record: Captured and wrote 1.071 MB perf.data (~46806 samples) ] >>> [jolsa@krava perf]$ ./perf timechart >>> Invalid previous event (non-zero)! >>> 0x113f80 [0x8]: failed to process type: 68 I see this kind of message a lot, but typically in high event use cases (e.g., 100+MB files in a run of a few seconds). I usually increase the map size (-m 4096) and/or bump the priority of perf (-r1) and re-run the test. >> Hm, I added a bunch of consistency checks which I couldn't actually hit >> myself. Nice work :-) Can I get you perf.data? > > For some reason, in Jiri's trace we see exit from sys_read with 2, > and then again exit from sys_read with -EAGAIN: > xterm 32028 [000] 43390.908909: syscalls:sys_enter_read: fd: 0x00000004, buf: 0x02076e8c, count: 0x0 > xterm 32028 [000] 43390.908917: syscalls:sys_exit_read: 0x2 > xterm 32028 [000] 43390.908982: syscalls:sys_exit_read: 0xfffffffffffffff5 > > I'm not sure how it is possible (either we lost sys_enter, or timestamp > of seconds -EAGAIN is wrong?). I think we might just convert this error > to a warning (we couldn't reproduce it again). Any lost events? David ^ permalink raw reply [flat|nested] 23+ messages in thread
* Re: [PATCH v4 0/4] perf timechart io mode 2014-06-24 17:38 ` David Ahern @ 2014-06-24 18:51 ` Jiri Olsa 2014-06-24 19:03 ` David Ahern 0 siblings, 1 reply; 23+ messages in thread From: Jiri Olsa @ 2014-06-24 18:51 UTC (permalink / raw) To: David Ahern Cc: Stanislav Fomichev, linux-kernel, a.p.zijlstra, paulus, mingo, acme, namhyung, artagnon, rusty, bp On Tue, Jun 24, 2014 at 11:38:44AM -0600, David Ahern wrote: > On 6/24/14, 10:57 AM, Stanislav Fomichev wrote: > >On Tue, Jun 24, 2014 at 01:10:22PM +0400, Stanislav Fomichev wrote: > >>>hum, got this when trying: > >>> > >>>[jolsa@krava perf]$ sudo ./perf timechart record -I > >>>^C[ perf record: Woken up 2 times to write data ] > >>>[ perf record: Captured and wrote 1.071 MB perf.data (~46806 samples) ] > >>>[jolsa@krava perf]$ ./perf timechart > >>>Invalid previous event (non-zero)! > >>>0x113f80 [0x8]: failed to process type: 68 > > I see this kind of message a lot, but typically in high event use cases > (e.g., 100+MB files in a run of a few seconds). I usually increase the map > size (-m 4096) and/or bump the priority of perf (-r1) and re-run the test. maybe we dont need to fail in this case.. seems like it should not be hard to detect, wanr and recover? ;-) jirka ^ permalink raw reply [flat|nested] 23+ messages in thread
* Re: [PATCH v4 0/4] perf timechart io mode 2014-06-24 18:51 ` Jiri Olsa @ 2014-06-24 19:03 ` David Ahern 2014-06-25 11:20 ` Stanislav Fomichev 0 siblings, 1 reply; 23+ messages in thread From: David Ahern @ 2014-06-24 19:03 UTC (permalink / raw) To: Jiri Olsa Cc: Stanislav Fomichev, linux-kernel, a.p.zijlstra, paulus, mingo, acme, namhyung, artagnon, rusty, bp On 6/24/14, 12:51 PM, Jiri Olsa wrote: > On Tue, Jun 24, 2014 at 11:38:44AM -0600, David Ahern wrote: >> On 6/24/14, 10:57 AM, Stanislav Fomichev wrote: >>> On Tue, Jun 24, 2014 at 01:10:22PM +0400, Stanislav Fomichev wrote: >>>>> hum, got this when trying: >>>>> >>>>> [jolsa@krava perf]$ sudo ./perf timechart record -I >>>>> ^C[ perf record: Woken up 2 times to write data ] >>>>> [ perf record: Captured and wrote 1.071 MB perf.data (~46806 samples) ] >>>>> [jolsa@krava perf]$ ./perf timechart >>>>> Invalid previous event (non-zero)! >>>>> 0x113f80 [0x8]: failed to process type: 68 >> >> I see this kind of message a lot, but typically in high event use cases >> (e.g., 100+MB files in a run of a few seconds). I usually increase the map >> size (-m 4096) and/or bump the priority of perf (-r1) and re-run the test. > > maybe we dont need to fail in this case.. seems like it should > not be hard to detect, wanr and recover? ;-) > seems to me it should not be happening at all. It seems like the head caught the tail and was not properly detected. David ^ permalink raw reply [flat|nested] 23+ messages in thread
* Re: [PATCH v4 0/4] perf timechart io mode 2014-06-24 19:03 ` David Ahern @ 2014-06-25 11:20 ` Stanislav Fomichev 2014-06-25 14:01 ` David Ahern 0 siblings, 1 reply; 23+ messages in thread From: Stanislav Fomichev @ 2014-06-25 11:20 UTC (permalink / raw) To: David Ahern Cc: Jiri Olsa, linux-kernel, a.p.zijlstra, paulus, mingo, acme, namhyung, artagnon, rusty, bp > >maybe we dont need to fail in this case.. seems like it should > >not be hard to detect, wanr and recover? ;-) The easiest way is just to bail out and don't try to be smart, that's what I do now. Another approach would be to just convert all my consistency checks to warnings and skip invalid events (and hope it somehow works). I think it makes sense when for some reason we have perf.data which is not really consistent but we still want to get something out of it. > seems to me it should not be happening at all. It seems like the head caught > the tail and was not properly detected. So you mean it perf record's fault? ^ permalink raw reply [flat|nested] 23+ messages in thread
* Re: [PATCH v4 0/4] perf timechart io mode 2014-06-25 11:20 ` Stanislav Fomichev @ 2014-06-25 14:01 ` David Ahern 2014-06-25 14:19 ` Stanislav Fomichev 2014-06-25 14:38 ` Jiri Olsa 0 siblings, 2 replies; 23+ messages in thread From: David Ahern @ 2014-06-25 14:01 UTC (permalink / raw) To: Stanislav Fomichev Cc: Jiri Olsa, linux-kernel, a.p.zijlstra, paulus, mingo, acme, namhyung, artagnon, rusty, bp On 6/25/14, 5:20 AM, Stanislav Fomichev wrote: >>> maybe we dont need to fail in this case.. seems like it should >>> not be hard to detect, wanr and recover? ;-) > The easiest way is just to bail out and don't try to be smart, that's > what I do now. > > Another approach would be to just convert all my consistency > checks to warnings and skip invalid events (and hope it somehow works). I > think it makes sense when for some reason we have perf.data which > is not really consistent but we still want to get something out of it. If the event type does not make sense how can you trust any other field -- like event size? > >> seems to me it should not be happening at all. It seems like the head caught >> the tail and was not properly detected. > So you mean it perf record's fault? > In my cases I am running perf-record. At the end of the session it walks the events and in too many cases I see the message: 0x113f80 [0x8]: failed to process type: 68 So, yes I think something is happening during the record such as the writer passing the reader and corrupting the buffers. David ^ permalink raw reply [flat|nested] 23+ messages in thread
* Re: [PATCH v4 0/4] perf timechart io mode 2014-06-25 14:01 ` David Ahern @ 2014-06-25 14:19 ` Stanislav Fomichev 2014-06-25 14:38 ` Jiri Olsa 1 sibling, 0 replies; 23+ messages in thread From: Stanislav Fomichev @ 2014-06-25 14:19 UTC (permalink / raw) To: David Ahern Cc: Jiri Olsa, linux-kernel, a.p.zijlstra, paulus, mingo, acme, namhyung, artagnon, rusty, bp > If the event type does not make sense how can you trust any other field -- > like event size? I don't mean corruption like this. I mean if event ordering is wrong or some event occurs in unexpected place we may just be tolerant and skip it with a warning. ^ permalink raw reply [flat|nested] 23+ messages in thread
* Re: [PATCH v4 0/4] perf timechart io mode 2014-06-25 14:01 ` David Ahern 2014-06-25 14:19 ` Stanislav Fomichev @ 2014-06-25 14:38 ` Jiri Olsa 1 sibling, 0 replies; 23+ messages in thread From: Jiri Olsa @ 2014-06-25 14:38 UTC (permalink / raw) To: David Ahern Cc: Stanislav Fomichev, linux-kernel, a.p.zijlstra, paulus, mingo, acme, namhyung, artagnon, rusty, bp On Wed, Jun 25, 2014 at 08:01:17AM -0600, David Ahern wrote: > On 6/25/14, 5:20 AM, Stanislav Fomichev wrote: > >>>maybe we dont need to fail in this case.. seems like it should > >>>not be hard to detect, wanr and recover? ;-) > >The easiest way is just to bail out and don't try to be smart, that's > >what I do now. > > > >Another approach would be to just convert all my consistency > >checks to warnings and skip invalid events (and hope it somehow works). I > >think it makes sense when for some reason we have perf.data which > >is not really consistent but we still want to get something out of it. > > If the event type does not make sense how can you trust any other field -- > like event size? > > > > >>seems to me it should not be happening at all. It seems like the head caught > >>the tail and was not properly detected. > >So you mean it perf record's fault? > > > > In my cases I am running perf-record. At the end of the session it walks the > events and in too many cases I see the message: > > 0x113f80 [0x8]: failed to process type: 68 > hum.. 68 is PERF_RECORD_FINISHED_ROUND, so there was something wrong during the queue flush.. thus processing all the queue events and failing only if either the parsing or delivery fails jirka ^ permalink raw reply [flat|nested] 23+ messages in thread
* [PATCH v5 0/4] perf timechart io mode
@ 2014-06-26 16:11 Stanislav Fomichev
2014-06-26 16:11 ` [PATCH 3/4] perf timechart: conditionally update start_time on fork Stanislav Fomichev
0 siblings, 1 reply; 23+ messages in thread
From: Stanislav Fomichev @ 2014-06-26 16:11 UTC (permalink / raw)
To: a.p.zijlstra, paulus, mingo, acme, stfomichev, namhyung,
artagnon, jolsa, bp, rusty
Cc: linux-kernel
This patchset adds IO mode: instead of process time we record io syscalls
and then draw timechart of writes/reads/tx/rx/polls.
v5:
- converted consistency check errors to warnings so we can tolerate
some perf.data errors
- added more info to 'implement IO mode' changelog
v4:
- another attempt for fix segfault when skipping invalid tracepoints
- added new patch to fix rendering in Firefox
v3:
- fixed segfault when skipping invalid tracepoints
- added ms/us units support for --io-xyz time options
- fixed missing boxes on Firefox
v2:
- separated start_time fix into distinct commit
- separated --io-xyz options into distinct commit
- fixed 'error' shadowing
- initialized variables in declaration when possible
- removed assert usage
- fprintf -> pr_err
- removed wrongly placed __maybe_unused
Stanislav Fomichev (4):
perf timechart: fix rendering in Firefox
perf timechart: implement IO mode
perf timechart: conditionally update start_time on fork
perf timechart: add more options to IO mode
tools/perf/Documentation/perf-timechart.txt | 38 +-
tools/perf/builtin-timechart.c | 686 +++++++++++++++++++++++++++-
tools/perf/util/svghelper.c | 168 +++++--
tools/perf/util/svghelper.h | 6 +-
4 files changed, 838 insertions(+), 60 deletions(-)
--
1.9.1
^ permalink raw reply [flat|nested] 23+ messages in thread* [PATCH 3/4] perf timechart: conditionally update start_time on fork 2014-06-26 16:11 [PATCH v5 " Stanislav Fomichev @ 2014-06-26 16:11 ` Stanislav Fomichev 0 siblings, 0 replies; 23+ messages in thread From: Stanislav Fomichev @ 2014-06-26 16:11 UTC (permalink / raw) To: a.p.zijlstra, paulus, mingo, acme, stfomichev, namhyung, artagnon, jolsa, bp, rusty Cc: linux-kernel We don't need to overwrite current task start_time on fork, so update it only if it's zero. Signed-off-by: Stanislav Fomichev <stfomichev@yandex-team.ru> --- tools/perf/builtin-timechart.c | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/tools/perf/builtin-timechart.c b/tools/perf/builtin-timechart.c index 8d454c55bc4e..011569becc65 100644 --- a/tools/perf/builtin-timechart.c +++ b/tools/perf/builtin-timechart.c @@ -242,7 +242,7 @@ static void pid_fork(struct timechart *tchart, int pid, int ppid, u64 timestamp) pid_set_comm(tchart, pid, pp->current->comm); p->start_time = timestamp; - if (p->current) { + if (p->current && !p->current->start_time) { p->current->start_time = timestamp; p->current->state_since = timestamp; } -- 1.9.1 ^ permalink raw reply related [flat|nested] 23+ messages in thread
* [PATCH v4 0/4] perf timechart io mode
@ 2014-07-08 16:03 Stanislav Fomichev
2014-07-08 16:03 ` [PATCH 3/4] perf timechart: conditionally update start_time on fork Stanislav Fomichev
0 siblings, 1 reply; 23+ messages in thread
From: Stanislav Fomichev @ 2014-07-08 16:03 UTC (permalink / raw)
To: a.p.zijlstra, paulus, mingo, acme, stfomichev, namhyung,
artagnon, jolsa, rusty, bp
Cc: linux-kernel
This patchset adds IO mode: instead of process time we record io syscalls
and then draw timechart of writes/reads/tx/rx/polls.
v6:
- v5 didn't actually contained 'converted consistency checks' fix, so
respinning the series once again with the fix folded;
Namhyung, can I still keep your Acked-By?
Jiri, can you please pull it?
v5:
- converted consistency check errors to warnings so we can tolerate
some perf.data errors
- added more info to 'implement IO mode' changelog
v4:
- another attempt for fix segfault when skipping invalid tracepoints
- added new patch to fix rendering in Firefox
v3:
- fixed segfault when skipping invalid tracepoints
- added ms/us units support for --io-xyz time options
- fixed missing boxes on Firefox
v2:
- separated start_time fix into distinct commit
- separated --io-xyz options into distinct commit
- fixed 'error' shadowing
- initialized variables in declaration when possible
- removed assert usage
- fprintf -> pr_err
- removed wrongly placed __maybe_unused
Stanislav Fomichev (4):
perf timechart: fix rendering in Firefox
perf timechart: implement IO mode
perf timechart: conditionally update start_time on fork
perf timechart: add more options to IO mode
tools/perf/Documentation/perf-timechart.txt | 38 +-
tools/perf/builtin-timechart.c | 693 +++++++++++++++++++++++++++-
tools/perf/util/svghelper.c | 168 +++++--
tools/perf/util/svghelper.h | 6 +-
4 files changed, 845 insertions(+), 60 deletions(-)
--
1.9.1
^ permalink raw reply [flat|nested] 23+ messages in thread* [PATCH 3/4] perf timechart: conditionally update start_time on fork 2014-07-08 16:03 [PATCH v4 0/4] perf timechart io mode Stanislav Fomichev @ 2014-07-08 16:03 ` Stanislav Fomichev 0 siblings, 0 replies; 23+ messages in thread From: Stanislav Fomichev @ 2014-07-08 16:03 UTC (permalink / raw) To: a.p.zijlstra, paulus, mingo, acme, stfomichev, namhyung, artagnon, jolsa, rusty, bp Cc: linux-kernel We don't need to overwrite current task start_time on fork, so update it only if it's zero. Signed-off-by: Stanislav Fomichev <stfomichev@yandex-team.ru> --- tools/perf/builtin-timechart.c | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/tools/perf/builtin-timechart.c b/tools/perf/builtin-timechart.c index 4079062d25b0..37bf1eb0755f 100644 --- a/tools/perf/builtin-timechart.c +++ b/tools/perf/builtin-timechart.c @@ -242,7 +242,7 @@ static void pid_fork(struct timechart *tchart, int pid, int ppid, u64 timestamp) pid_set_comm(tchart, pid, pp->current->comm); p->start_time = timestamp; - if (p->current) { + if (p->current && !p->current->start_time) { p->current->start_time = timestamp; p->current->state_since = timestamp; } -- 1.9.1 ^ permalink raw reply related [flat|nested] 23+ messages in thread
* [GIT PULL 0/4] perf/core improvements and fixes
@ 2014-07-10 21:06 Jiri Olsa
2014-07-10 21:06 ` [PATCH 3/4] perf timechart: Conditionally update start_time on fork Jiri Olsa
0 siblings, 1 reply; 23+ messages in thread
From: Jiri Olsa @ 2014-07-10 21:06 UTC (permalink / raw)
To: Ingo Molnar
Cc: linux-kernel, Arnaldo Carvalho de Melo, Corey Ashford,
David Ahern, Frederic Weisbecker, Namhyung Kim, Paul Mackerras,
Peter Zijlstra, Stanislav Fomichev, Jiri Olsa
hi Ingo,
please consider pulling
thanks,
jirka
The following changes since commit 8b5b584daf3b92fc5cdc83919e64231817d2f5a7:
Merge tag 'perf-core-for-mingo' of git://git.kernel.org/pub/scm/linux/kernel/git/jolsa/perf into perf/core (2014-07-05 11:29:32 +0200)
are available in the git repository at:
git://git.kernel.org/pub/scm/linux/kernel/git/jolsa/perf.git tags/perf-core-for-mingo
for you to fetch changes up to d243144af0b52fc5164a0823194f29a5979e236c:
perf timechart: Add more options to IO mode (2014-07-10 00:22:54 +0200)
----------------------------------------------------------------
perf/core improvements and fixes:
. Add IO mode into timechart command (Stanislav Fomichev)
Signed-off-by: Jiri Olsa <jolsa@kernel.org>
----------------------------------------------------------------
Stanislav Fomichev (4):
perf timechart: Fix rendering in Firefox
perf timechart: Implement IO mode
perf timechart: Conditionally update start_time on fork
perf timechart: Add more options to IO mode
tools/perf/Documentation/perf-timechart.txt | 38 +-
tools/perf/builtin-timechart.c | 693 +++++++++++++++++++++++++++-
tools/perf/util/svghelper.c | 168 +++++--
tools/perf/util/svghelper.h | 6 +-
4 files changed, 845 insertions(+), 60 deletions(-)
^ permalink raw reply [flat|nested] 23+ messages in thread* [PATCH 3/4] perf timechart: Conditionally update start_time on fork 2014-07-10 21:06 [GIT PULL 0/4] perf/core improvements and fixes Jiri Olsa @ 2014-07-10 21:06 ` Jiri Olsa 0 siblings, 0 replies; 23+ messages in thread From: Jiri Olsa @ 2014-07-10 21:06 UTC (permalink / raw) To: Ingo Molnar Cc: linux-kernel, Arnaldo Carvalho de Melo, Stanislav Fomichev, Jiri Olsa From: Stanislav Fomichev <stfomichev@yandex-team.ru> We don't need to overwrite current task start_time on fork, so update it only if it's zero. Signed-off-by: Stanislav Fomichev <stfomichev@yandex-team.ru> Acked-by: Namhyung Kim <namhyung@kernel.org> Link: http://lkml.kernel.org/n/1404835423-23098-4-git-send-email-stfomichev@yandex-team.ru Signed-off-by: Jiri Olsa <jolsa@kernel.org> --- tools/perf/builtin-timechart.c | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/tools/perf/builtin-timechart.c b/tools/perf/builtin-timechart.c index 4079062..37bf1eb 100644 --- a/tools/perf/builtin-timechart.c +++ b/tools/perf/builtin-timechart.c @@ -242,7 +242,7 @@ static void pid_fork(struct timechart *tchart, int pid, int ppid, u64 timestamp) pid_set_comm(tchart, pid, pp->current->comm); p->start_time = timestamp; - if (p->current) { + if (p->current && !p->current->start_time) { p->current->start_time = timestamp; p->current->state_since = timestamp; } -- 1.8.3.1 ^ permalink raw reply related [flat|nested] 23+ messages in thread
end of thread, other threads:[~2014-07-10 21:08 UTC | newest] Thread overview: 23+ messages (download: mbox.gz / follow: Atom feed) -- links below jump to the message on this page -- 2014-06-20 10:29 [PATCH v4 0/4] perf timechart io mode Stanislav Fomichev 2014-06-20 10:29 ` [PATCH 1/4] perf timechart: fix rendering in Firefox Stanislav Fomichev 2014-06-20 10:29 ` [PATCH 2/4] perf timechart: implement IO mode Stanislav Fomichev 2014-06-24 8:34 ` Jiri Olsa 2014-06-24 17:00 ` Stanislav Fomichev 2014-06-24 18:21 ` Jiri Olsa 2014-06-20 10:29 ` [PATCH 3/4] perf timechart: conditionally update start_time on fork Stanislav Fomichev 2014-06-20 10:29 ` [PATCH 4/4] perf timechart: add more options to IO mode Stanislav Fomichev 2014-06-24 6:43 ` [PATCH v4 0/4] perf timechart io mode Namhyung Kim 2014-06-24 8:41 ` Jiri Olsa 2014-06-24 9:10 ` Stanislav Fomichev 2014-06-24 16:57 ` Stanislav Fomichev 2014-06-24 17:01 ` Stanislav Fomichev 2014-06-24 17:38 ` David Ahern 2014-06-24 18:51 ` Jiri Olsa 2014-06-24 19:03 ` David Ahern 2014-06-25 11:20 ` Stanislav Fomichev 2014-06-25 14:01 ` David Ahern 2014-06-25 14:19 ` Stanislav Fomichev 2014-06-25 14:38 ` Jiri Olsa 2014-06-26 16:11 [PATCH v5 " Stanislav Fomichev 2014-06-26 16:11 ` [PATCH 3/4] perf timechart: conditionally update start_time on fork Stanislav Fomichev 2014-07-08 16:03 [PATCH v4 0/4] perf timechart io mode Stanislav Fomichev 2014-07-08 16:03 ` [PATCH 3/4] perf timechart: conditionally update start_time on fork Stanislav Fomichev 2014-07-10 21:06 [GIT PULL 0/4] perf/core improvements and fixes Jiri Olsa 2014-07-10 21:06 ` [PATCH 3/4] perf timechart: Conditionally update start_time on fork Jiri Olsa
This is an external index of several public inboxes, see mirroring instructions on how to clone and mirror all data and code used by this external index.