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 <[email protected]>
Cc: Adrian Hunter <[email protected]>
Cc: Jiri Olsa <[email protected]>
Cc: Arnaldo Carvalho de Melo <[email protected]>
Signed-off-by: Hagen Paul Pfeifer <[email protected]>
---
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
On Tue, Feb 04, 2020 at 06:37:09PM +0100, Hagen Paul Pfeifer wrote:
> 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
It's already implemented as --reltime
-Andi
* Andi Kleen | 2020-02-04 15:16:28 [-0800]:
>> $ perf script --deltatime
>
>It's already implemented as --reltime
Nope ;-)
$ perf script --ns --reltime
sleep 49148 [000] 0.000000000: probe_libc:sbrk: (7f279d9144f0)
sleep 49148 [000] 0.000009153: probe_libc:sbrk: (7f279d9144f0)
sh 49151 [002] 0.099454082: probe_libc:sbrk: (7f9f1c6374f0)
sh 49151 [002] 0.099468538: probe_libc:sbrk: (7f9f1c6374f0)
curl 49153 [003] 0.114459574: probe_libc:sbrk: (7f9bb2dfb4f0)
curl 49153 [003] 0.114474449: probe_libc:sbrk: (7f9bb2dfb4f0)
[...]
$ perf script --ns --deltatime
sleep 49148 [000] 0.000000000: probe_libc:sbrk: (7f279d9144f0)
sleep 49148 [000] 0.000009153: probe_libc:sbrk: (7f279d9144f0)
sh 49151 [002] 0.099444929: probe_libc:sbrk: (7f9f1c6374f0)
sh 49151 [002] 0.000014456: probe_libc:sbrk: (7f9f1c6374f0)
curl 49153 [003] 0.014991036: probe_libc:sbrk: (7f9bb2dfb4f0)
curl 49153 [003] 0.000014875: probe_libc:sbrk: (7f9bb2dfb4f0)
[...]
reltime is relative to the *first event* in the record - deltatime is relative
to the *previous* event.
Hagen
> reltime is relative to the *first event* in the record - deltatime is relative
> to the *previous* event.
Ah ok.
I think it's useful, but you should rather implement it as a new field instead
of as an option. There might be use cases where you want both.
delta time is easier for reading, but absolute time is often important
to find something in a trace.
-Andi
Em Tue, Feb 04, 2020 at 06:37:09PM +0100, Hagen Paul Pfeifer escreveu:
> 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
You forgot to update the man page, I did it, tested and applied, thanks.
- Arnaldo
diff --git a/tools/perf/Documentation/perf-script.txt b/tools/perf/Documentation/perf-script.txt
index db6a36aac47e..4af255bb0977 100644
--- a/tools/perf/Documentation/perf-script.txt
+++ b/tools/perf/Documentation/perf-script.txt
@@ -390,6 +390,9 @@ include::itrace.txt[]
--reltime::
Print time stamps relative to trace start.
+--deltatime::
+ Print time stamps relative to previous event.
+
--per-event-dump::
Create per event files with a "perf.data.EVENT.dump" name instead of
printing to stdout, useful, for instance, for generating flamegraphs.
The following commit has been merged into the perf/urgent branch of tip:
Commit-ID: 26567ed79d13ec54b2c5661ce8a07fd149a23a9b
Gitweb: https://git.kernel.org/tip/26567ed79d13ec54b2c5661ce8a07fd149a23a9b
Author: Hagen Paul Pfeifer <[email protected]>
AuthorDate: Tue, 04 Feb 2020 18:37:09 +01:00
Committer: Arnaldo Carvalho de Melo <[email protected]>
CommitterDate: Fri, 27 Mar 2020 10:38:47 -03:00
perf script: Introduce --deltatime option
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
Committer testing:
So go from default output to --reltime and then this new --deltatime, to
contrast the various timestamp presentation modes for a random perf.data file I
had laying around:
[root@five ~]# perf script --reltime | head
perf 442394 [000] 0.000000: 16 cycles: ffffffff9706e544 native_write_msr+0x4 (/usr/lib/debug/lib/modules/5.5.10-200.fc31.x86_64/vmlinux)
perf 442394 [000] 0.000002: 16 cycles: ffffffff9706e544 native_write_msr+0x4 (/usr/lib/debug/lib/modules/5.5.10-200.fc31.x86_64/vmlinux)
perf 442394 [000] 0.000004: 16 cycles: ffffffff9706e544 native_write_msr+0x4 (/usr/lib/debug/lib/modules/5.5.10-200.fc31.x86_64/vmlinux)
perf 442394 [000] 0.000006: 128 cycles: ffffffff972415a1 perf_event_update_userpage+0x1 (/usr/lib/debug/lib/modules/5.5.10-200.fc31.x86_64/vmlinux)
perf 442394 [000] 0.000009: 2597 cycles: ffffffff97463785 cap_task_setscheduler+0x5 (/usr/lib/debug/lib/modules/5.5.10-200.fc31.x86_64/vmlinux)
perf 442394 [001] 0.000036: 16 cycles: ffffffff9706e544 native_write_msr+0x4 (/usr/lib/debug/lib/modules/5.5.10-200.fc31.x86_64/vmlinux)
perf 442394 [001] 0.000038: 16 cycles: ffffffff9706e544 native_write_msr+0x4 (/usr/lib/debug/lib/modules/5.5.10-200.fc31.x86_64/vmlinux)
perf 442394 [001] 0.000040: 16 cycles: ffffffff9706e544 native_write_msr+0x4 (/usr/lib/debug/lib/modules/5.5.10-200.fc31.x86_64/vmlinux)
perf 442394 [001] 0.000041: 224 cycles: ffffffff9700a53a perf_ibs_handle_irq+0x1da (/usr/lib/debug/lib/modules/5.5.10-200.fc31.x86_64/vmlinux)
perf 442394 [001] 0.000044: 4439 cycles: ffffffff97120d85 put_prev_entity+0x45 (/usr/lib/debug/lib/modules/5.5.10-200.fc31.x86_64/vmlinux)
[root@five ~]# perf script --deltatime | head
perf 442394 [000] 0.000000: 16 cycles: ffffffff9706e544 native_write_msr+0x4 (/usr/lib/debug/lib/modules/5.5.10-200.fc31.x86_64/vmlinux)
perf 442394 [000] 0.000002: 16 cycles: ffffffff9706e544 native_write_msr+0x4 (/usr/lib/debug/lib/modules/5.5.10-200.fc31.x86_64/vmlinux)
perf 442394 [000] 0.000001: 16 cycles: ffffffff9706e544 native_write_msr+0x4 (/usr/lib/debug/lib/modules/5.5.10-200.fc31.x86_64/vmlinux)
perf 442394 [000] 0.000001: 128 cycles: ffffffff972415a1 perf_event_update_userpage+0x1 (/usr/lib/debug/lib/modules/5.5.10-200.fc31.x86_64/vmlinux)
perf 442394 [000] 0.000002: 2597 cycles: ffffffff97463785 cap_task_setscheduler+0x5 (/usr/lib/debug/lib/modules/5.5.10-200.fc31.x86_64/vmlinux)
perf 442394 [001] 0.000027: 16 cycles: ffffffff9706e544 native_write_msr+0x4 (/usr/lib/debug/lib/modules/5.5.10-200.fc31.x86_64/vmlinux)
perf 442394 [001] 0.000002: 16 cycles: ffffffff9706e544 native_write_msr+0x4 (/usr/lib/debug/lib/modules/5.5.10-200.fc31.x86_64/vmlinux)
perf 442394 [001] 0.000001: 16 cycles: ffffffff9706e544 native_write_msr+0x4 (/usr/lib/debug/lib/modules/5.5.10-200.fc31.x86_64/vmlinux)
perf 442394 [001] 0.000001: 224 cycles: ffffffff9700a53a perf_ibs_handle_irq+0x1da (/usr/lib/debug/lib/modules/5.5.10-200.fc31.x86_64/vmlinux)
perf 442394 [001] 0.000002: 4439 cycles: ffffffff97120d85 put_prev_entity+0x45 (/usr/lib/debug/lib/modules/5.5.10-200.fc31.x86_64/vmlinux)
[root@five ~]# perf script | head
perf 442394 [000] 7600.157861: 16 cycles: ffffffff9706e544 native_write_msr+0x4 (/usr/lib/debug/lib/modules/5.5.10-200.fc31.x86_64/vmlinux)
perf 442394 [000] 7600.157864: 16 cycles: ffffffff9706e544 native_write_msr+0x4 (/usr/lib/debug/lib/modules/5.5.10-200.fc31.x86_64/vmlinux)
perf 442394 [000] 7600.157866: 16 cycles: ffffffff9706e544 native_write_msr+0x4 (/usr/lib/debug/lib/modules/5.5.10-200.fc31.x86_64/vmlinux)
perf 442394 [000] 7600.157867: 128 cycles: ffffffff972415a1 perf_event_update_userpage+0x1 (/usr/lib/debug/lib/modules/5.5.10-200.fc31.x86_64/vmlinux)
perf 442394 [000] 7600.157870: 2597 cycles: ffffffff97463785 cap_task_setscheduler+0x5 (/usr/lib/debug/lib/modules/5.5.10-200.fc31.x86_64/vmlinux)
perf 442394 [001] 7600.157897: 16 cycles: ffffffff9706e544 native_write_msr+0x4 (/usr/lib/debug/lib/modules/5.5.10-200.fc31.x86_64/vmlinux)
perf 442394 [001] 7600.157900: 16 cycles: ffffffff9706e544 native_write_msr+0x4 (/usr/lib/debug/lib/modules/5.5.10-200.fc31.x86_64/vmlinux)
perf 442394 [001] 7600.157901: 16 cycles: ffffffff9706e544 native_write_msr+0x4 (/usr/lib/debug/lib/modules/5.5.10-200.fc31.x86_64/vmlinux)
perf 442394 [001] 7600.157903: 224 cycles: ffffffff9700a53a perf_ibs_handle_irq+0x1da (/usr/lib/debug/lib/modules/5.5.10-200.fc31.x86_64/vmlinux)
perf 442394 [001] 7600.157906: 4439 cycles: ffffffff97120d85 put_prev_entity+0x45 (/usr/lib/debug/lib/modules/5.5.10-200.fc31.x86_64/vmlinux)
[root@five ~]#
Andi suggested we better implement it as a new field, i.e. -F deltatime, like:
[root@five ~]# perf script -F deltatime
Invalid field requested.
Usage: perf script [<options>]
or: perf script [<options>] record <script> [<record-options>] <command>
or: perf script [<options>] report <script> [script-args]
or: perf script [<options>] <script> [<record-options>] <command>
or: perf script [<options>] <top-script> [script-args]
-F, --fields <str> comma separated output fields prepend with 'type:'. +field to add and -field to remove.Valid types: hw,sw,trace,raw,synth. Fields: comm,tid,pid,time,cpu,event,trace,ip,sym,dso,addr,symoff,srcline,period,iregs,uregs,brstack,brstacksym,flags,bpf-output,brstackinsn,brstackoff,callindent,insn,insnlen,synth,phys_addr,metric,misc,ipc
[root@five ~]#
I.e. we have -F for maximum flexibility:
[root@five ~]# perf script -F comm,pid,cpu,time | head
perf 442394 [000] 7600.157861:
perf 442394 [000] 7600.157864:
perf 442394 [000] 7600.157866:
perf 442394 [000] 7600.157867:
perf 442394 [000] 7600.157870:
perf 442394 [001] 7600.157897:
perf 442394 [001] 7600.157900:
perf 442394 [001] 7600.157901:
perf 442394 [001] 7600.157903:
perf 442394 [001] 7600.157906:
[root@five ~]#
But since we already have --reltime, having --deltatime, documented one after
the other is sensible.
Signed-off-by: Hagen Paul Pfeifer <[email protected]>
Tested-by: Arnaldo Carvalho de Melo <[email protected]>
Cc: Adrian Hunter <[email protected]>
Cc: Andi Kleen <[email protected]>
Cc: Jiri Olsa <[email protected]>
Link: http://lore.kernel.org/lkml/[email protected]
[ Added 'perf script' man page entry for --deltatime ]
Signed-off-by: Arnaldo Carvalho de Melo <[email protected]>
---
tools/perf/Documentation/perf-script.txt | 3 +++
tools/perf/builtin-script.c | 17 +++++++++++++++++
2 files changed, 20 insertions(+)
diff --git a/tools/perf/Documentation/perf-script.txt b/tools/perf/Documentation/perf-script.txt
index db6a36a..4af255b 100644
--- a/tools/perf/Documentation/perf-script.txt
+++ b/tools/perf/Documentation/perf-script.txt
@@ -390,6 +390,9 @@ include::itrace.txt[]
--reltime::
Print time stamps relative to trace start.
+--deltatime::
+ Print time stamps relative to previous event.
+
--per-event-dump::
Create per event files with a "perf.data.EVENT.dump" name instead of
printing to stdout, useful, for instance, for generating flamegraphs.
diff --git a/tools/perf/builtin-script.c b/tools/perf/builtin-script.c
index 656b347..f63869a 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;
@@ -3555,6 +3564,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,
@@ -3651,6 +3661,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;