iv/linux
1
0
Fork 0
Code Issues Pull Requests Actions Packages Projects Releases Wiki Activity
6546b19f95
linux/tools
History
Hagen Paul Pfeifer 26567ed79d 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 <hagen@jauu.net>
Tested-by: Arnaldo Carvalho de Melo <acme@redhat.com>
Cc: Adrian Hunter <adrian.hunter@intel.com>
Cc: Andi Kleen <ak@linux.intel.com>
Cc: Jiri Olsa <jolsa@kernel.org>
Link: http://lore.kernel.org/lkml/20200204173709.489161-1-hagen@jauu.net
[ Added 'perf script' man page entry for --deltatime ]
Signed-off-by: Arnaldo Carvalho de Melo <acme@redhat.com>
2020-03-27 10:38:47 -03:00
..
accounting
arch x86/insn: Add Control-flow Enforcement (CET) instructions to the opcode map 2020-03-27 10:38:46 -03:00
bootconfig bootconfig: Add append value operator support 2020-02-21 09:59:39 -05:00
bpf bpftool: Don't crash on missing xlated program instructions 2020-02-07 22:29:45 +01:00
build perf/ui/gtk: Fix gtk2 build 2020-01-14 12:40:33 -03:00
cgroup iocost: Fix iocost_monitor.py due to helper type mismatch 2020-01-17 11:54:35 -08:00
debugging
firewire
firmware
gpio
hv Tools: hv: Reopen the devices if read() or write() returns errors 2020-01-26 22:10:10 -05:00
iio
include tools headers uapi: Update linux/in.h copy 2020-03-24 10:35:58 -03:00
io_uring
kvm/kvm_stat tools/kvm_stat: Fix kvm_exit filter name 2020-01-23 09:51:06 +01:00
laptop
leds
lib tools lib traceevent: Remove extra '\n' in print_event_time() 2020-03-04 10:34:10 -03:00
memory-model
nfsd
objtool objtool: Fix ARCH=x86_64 build error 2020-01-22 07:54:57 +01:00
pci
pcmcia
perf perf script: Introduce --deltatime option 2020-03-27 10:38:47 -03:00
power cpupower: avoid multiple definition with gcc -fno-common 2020-03-02 08:53:34 -07:00
scripts tools: Let O= makes handle a relative path with -C option 2020-03-06 17:08:28 -03:00
spi
testing Merge git://git.kernel.org/pub/scm/linux/kernel/git/netdev/net 2020-03-12 16:19:19 -07:00
thermal/tmon
time
usb usbip: Fix unsafe unaligned pointer usage 2020-01-09 16:44:26 +01:00
virtio
vm tools/vm/slabinfo: fix sanity checks enabling 2020-01-31 10:30:38 -08:00
wmi
Makefile tools: bootconfig: Add bootconfig command 2020-01-13 13:19:39 -05:00