[PATCH] perf script: introduce deltatime option

From: Hagen Paul Pfeifer
Date: Tue Feb 04 2020 - 12:45:19 EST


For some kind of analysis a deltatime output is more human friendly and reduce
the cognitive load for further analysis.

The following output demonstrate the new option "deltatime": calculate
the time difference in relation to the previous event.

$ perf script --deltatime
test 2525 [001] 0.000000: sdt_libev:ev_add: (5635e72a5ebd)
test 2525 [001] 0.000091: sdt_libev:epoll_wait_enter: (5635e72a76a9)
test 2525 [001] 1.000051: sdt_libev:epoll_wait_return: (5635e72a772e) arg1=1
test 2525 [001] 0.000685: sdt_libev:ev_add: (5635e72a5ebd)
test 2525 [001] 0.000048: sdt_libev:epoll_wait_enter: (5635e72a76a9)
test 2525 [001] 1.000104: sdt_libev:epoll_wait_return: (5635e72a772e) arg1=1
test 2525 [001] 0.003895: sdt_libev:epoll_wait_enter: (5635e72a76a9)
test 2525 [001] 0.996034: sdt_libev:epoll_wait_return: (5635e72a772e) arg1=1
test 2525 [001] 0.000058: sdt_libev:epoll_wait_enter: (5635e72a76a9)
test 2525 [001] 1.000004: sdt_libev:epoll_wait_return: (5635e72a772e) arg1=1
test 2525 [001] 0.000064: sdt_libev:epoll_wait_enter: (5635e72a76a9)
test 2525 [001] 0.999934: sdt_libev:epoll_wait_return: (5635e72a772e) arg1=1
test 2525 [001] 0.000056: sdt_libev:epoll_wait_enter: (5635e72a76a9)
test 2525 [001] 0.999930: sdt_libev:epoll_wait_return: (5635e72a772e) arg1=1

Cc: Andi Kleen <ak@xxxxxxxxxxxxxxx>
Cc: Adrian Hunter <adrian.hunter@xxxxxxxxx>
Cc: Jiri Olsa <jolsa@xxxxxxxxxx>
Cc: Arnaldo Carvalho de Melo <acme@xxxxxxxxxx>
Signed-off-by: Hagen Paul Pfeifer <hagen@xxxxxxxx>
---
tools/perf/builtin-script.c | 17 +++++++++++++++++
1 file changed, 17 insertions(+)

diff --git a/tools/perf/builtin-script.c b/tools/perf/builtin-script.c
index e2406b291c1c..d5566b121159 100644
--- a/tools/perf/builtin-script.c
+++ b/tools/perf/builtin-script.c
@@ -63,7 +63,9 @@
static char const *script_name;
static char const *generate_script_lang;
static bool reltime;
+static bool deltatime;
static u64 initial_time;
+static u64 previous_time;
static bool debug_mode;
static u64 last_timestamp;
static u64 nr_unordered;
@@ -704,6 +706,13 @@ static int perf_sample__fprintf_start(struct perf_sample *sample,
if (!initial_time)
initial_time = sample->time;
t = sample->time - initial_time;
+ } else if (deltatime) {
+ if (previous_time)
+ t = sample->time - previous_time;
+ else {
+ t = 0;
+ }
+ previous_time = sample->time;
}
nsecs = t;
secs = nsecs / NSEC_PER_SEC;
@@ -3551,6 +3560,7 @@ int cmd_script(int argc, const char **argv)
"anything beyond the specified depth will be ignored. "
"Default: kernel.perf_event_max_stack or " __stringify(PERF_MAX_STACK_DEPTH)),
OPT_BOOLEAN(0, "reltime", &reltime, "Show time stamps relative to start"),
+ OPT_BOOLEAN(0, "deltatime", &deltatime, "Show time stamps relative to previous event"),
OPT_BOOLEAN('I', "show-info", &show_full_info,
"display extended information from perf.data file"),
OPT_BOOLEAN('\0', "show-kernel-path", &symbol_conf.show_kernel_path,
@@ -3647,6 +3657,13 @@ int cmd_script(int argc, const char **argv)
}
}

+ if (reltime && deltatime) {
+ fprintf(stderr,
+ "reltime and deltatime - the two don't get along well. "
+ "Please limit to --reltime or --deltatime.\n");
+ return -1;
+ }
+
if (itrace_synth_opts.callchain &&
itrace_synth_opts.callchain_sz > scripting_max_stack)
scripting_max_stack = itrace_synth_opts.callchain_sz;
--
2.24.1