• Arnaldo Carvalho de Melo's avatar
    perf record: Introduce --switch-output-event · 899e5ffb
    Arnaldo Carvalho de Melo authored
    Now we can use it with --overwrite to have a flight recorder mode that
    gets snapshot requests from arbitrary events that are processed in the
    side band thread together with the PERF_RECORD_BPF_EVENT processing.
    
    Example:
    
    To collect scheduler events until a recvmmsg syscall happens, system
    wide:
    
      [root@five a]# rm -f perf.data.2020042717*
      [root@five a]# perf record --overwrite -e sched:*switch,syscalls:*recvmmsg --switch-output-event syscalls:sys_enter_recvmmsg
      [ perf record: dump data: Woken up 1 times ]
      [ perf record: Dump perf.data.2020042717585458 ]
      [ perf record: dump data: Woken up 1 times ]
      [ perf record: Dump perf.data.2020042717590235 ]
      [ perf record: dump data: Woken up 1 times ]
      [ perf record: Dump perf.data.2020042717590398 ]
      ^C[ perf record: Woken up 1 times to write data ]
      [ perf record: Dump perf.data.2020042717590511 ]
      [ perf record: Captured and wrote 7.244 MB perf.data.<timestamp> ]
    
    So in the above case we had 3 snapshots, the fourth was forced by
    control+C:
    
      [root@five a]# ls -la
      total 20440
      drwxr-xr-x.  2 root root    4096 Apr 27 17:59 .
      dr-xr-x---. 12 root root    4096 Apr 27 17:46 ..
      -rw-------.  1 root root 3936125 Apr 27 17:58 perf.data.2020042717585458
      -rw-------.  1 root root 5074869 Apr 27 17:59 perf.data.2020042717590235
      -rw-------.  1 root root 4291037 Apr 27 17:59 perf.data.2020042717590398
      -rw-------.  1 root root 7617037 Apr 27 17:59 perf.data.2020042717590511
      [root@five a]#
    
    One can make this more precise by adding the switch output event to the
    main -e events list, as since this is done asynchronously, a few events
    after the signal event will appear in the snapshots, as can be seen
    with:
    
      [root@five a]# rm -f perf.data.20200427175*
      [root@five a]# perf record --overwrite -e sched:*switch,syscalls:*recvmmsg --switch-output-event syscalls:sys_enter_recvmmsg
      [ perf record: dump data: Woken up 1 times ]
      [ perf record: Dump perf.data.2020042718024203 ]
      [ perf record: dump data: Woken up 1 times ]
      [ perf record: Dump perf.data.2020042718024301 ]
      [ perf record: dump data: Woken up 1 times ]
      [ perf record: Dump perf.data.2020042718024484 ]
      ^C[ perf record: Woken up 1 times to write data ]
      [ perf record: Dump perf.data.2020042718024562 ]
      [ perf record: Captured and wrote 7.337 MB perf.data.<timestamp> ]
      [root@five a]# perf script -i perf.data.2020042718024203 | tail -15
           PacerThread 148586 [005] 122.830729: sched:sched_switch: prev_comm=PacerThread prev_pid=148586...
               swapper      0 [000] 122.833588: sched:sched_switch: prev_comm=swapper/0 prev_pid=...
        NetworkManager   1251 [000] 122.833619: syscalls:sys_enter_recvmmsg: fd: 0x0000001c, mmsg: 0x7ffe83054a1...
               swapper      0 [002] 122.833624: sched:sched_switch: prev_comm=swapper/2 prev_pid=...
               swapper      0 [003] 122.833624: sched:sched_switch: prev_comm=swapper/3 prev_pid=...
        NetworkManager   1251 [000] 122.833626: syscalls:sys_exit_recvmmsg: 0x1
       kworker/3:3-eve 158946 [003] 122.833628: sched:sched_switch: prev_comm=kworker/3:3 prev_pid=15894...
               swapper      0 [004] 122.833641: sched:sched_switch: prev_comm=swapper/4 prev_pid=...
        NetworkManager   1251 [000] 122.833642: sched:sched_switch: prev_comm=NetworkManage...
                  perf 228273 [002] 122.833645: sched:sched_switch: prev_comm=perf prev_pid=22827...
               swapper      0 [011] 122.833646: sched:sched_switch: prev_comm=swapper/1...
               swapper      0 [002] 122.833648: sched:sched_switch: prev_comm=swapper/...
       kworker/0:2-eve 207387 [000] 122.833648: sched:sched_switch: prev_comm=kworker/0:2 prev_pid=20738...
       kworker/2:3-eve 232038 [002] 122.833652: sched:sched_switch: prev_comm=kworker/2:3 prev_pid=23203...
                  perf 235825 [003] 122.833653: sched:sched_switch: prev_comm=perf prev_pid=23582...
      [root@five a]#
    Acked-by: default avatarJiri Olsa <jolsa@redhat.com>
    Cc: Adrian Hunter <adrian.hunter@intel.com>
    Cc: Namhyung Kim <namhyung@kernel.org>
    Cc: Song Liu <songliubraving@fb.com>
    Cc: Wang Nan <wangnan0@huawei.com>
    Link: http://lore.kernel.org/lkml/20200429131106.27974-8-acme@kernel.orgSigned-off-by: default avatarArnaldo Carvalho de Melo <acme@redhat.com>
    899e5ffb
perf-record.txt 23.5 KB