* perf inject -s
@ 2017-10-04 17:38 Paul Clarke
2017-10-06 12:40 ` Milian Wolff
0 siblings, 1 reply; 2+ messages in thread
From: Paul Clarke @ 2017-10-04 17:38 UTC (permalink / raw)
To: linux-perf-users
Is there a better description of what "perf inject -s" does?
The man page for "perf inject" says:
--
-s, --sched-stat
Merge sched_stat and sched_switch for getting events
where and how long tasks slept. sched_switch contains
a callchain where a task slept and sched_stat contains
a timeslice how long a task slept.
--
Is it creating a new type of event? If so, is the new event type visible to "perf script" and "perf script -s" ?
I just see events disappearing:
--
$ perf --version
perf version 4.13.rc4.gf2f132
$ perf record -e '{sched:sched_switch,sched:sched_migrate_task,sched:sched_process_exec,sched:sched_process_fork,sched:sched_process_exit,sched:sched_stat_runtime,sched:sched_stat_wait,sched:sched_stat_sleep,sched:sched_stat_blocked,sched:sched_stat_iowait}' -a sleep 0.001
[ perf record: Woken up 1 times to write data ]
[ perf record: Captured and wrote 0.144 MB perf.data (39 samples) ]
$ perf script
perf 5852 [042] 2591904.272752: sched:sched_migrate_task: comm=perf pid=5853 prio=120 orig_cpu=49 dest_cpu=43
perf 5852 [042] 2591904.272756: sched:sched_stat_sleep: comm=perf pid=5853 delay=159273628 [ns]
swapper 0 [043] 2591904.272760: sched:sched_stat_wait: comm=perf pid=5853 delay=0 [ns]
swapper 0 [043] 2591904.272761: sched:sched_switch: swapper/43:0 [120] R ==> perf:5853 [120]
perf 5853 [043] 2591904.273032: sched:sched_stat_runtime: comm=perf pid=5853 runtime=274344 [ns] vruntime=5217430079833775 [ns]
perf 5853 [043] 2591904.273034: sched:sched_switch: perf:5853 [120] R ==> migration/43:222 [0]
migration/43 222 [043] 2591904.273058: sched:sched_stat_wait: comm=perf pid=5853 delay=26246 [ns]
migration/43 222 [043] 2591904.273061: sched:sched_migrate_task: comm=perf pid=5853 prio=120 orig_cpu=43 dest_cpu=50
swapper 0 [050] 2591904.273126: sched:sched_stat_wait: comm=perf pid=5853 delay=0 [ns]
migration/43 222 [043] 2591904.273127: sched:sched_switch: migration/43:222 [0] S ==> swapper/43:0 [120]
swapper 0 [050] 2591904.273129: sched:sched_switch: swapper/50:0 [120] R ==> perf:5853 [120]
perf 5852 [042] 2591904.273647: sched:sched_stat_runtime: comm=perf pid=5852 runtime=3500692 [ns] vruntime=5674786469460196 [ns]
perf 5852 [042] 2591904.273648: sched:sched_switch: perf:5852 [120] S ==> swapper/42:0 [120]
sleep 5853 [050] 2591904.273726: sched:sched_process_exec: filename=/bin/sleep pid=5853 old_pid=5853
sleep 5853 [050] 2591904.274095: sched:sched_stat_runtime: comm=sleep pid=5853 runtime=1032442 [ns] vruntime=5600051654842876 [ns]
swapper 0 [043] 2591904.274112: sched:sched_stat_sleep: comm=rcu_sched pid=7 delay=4010582 [ns]
swapper 0 [043] 2591904.274115: sched:sched_stat_wait: comm=rcu_sched pid=7 delay=0 [ns]
swapper 0 [043] 2591904.274115: sched:sched_switch: swapper/43:0 [120] R ==> rcu_sched:7 [120]
rcu_sched 7 [043] 2591904.274135: sched:sched_stat_runtime: comm=rcu_sched pid=7 runtime=23894 [ns] vruntime=2504293416526246 [ns]
rcu_sched 7 [043] 2591904.274136: sched:sched_switch: rcu_sched:7 [120] S ==> swapper/43:0 [120]
swapper 0 [031] 2591904.274136: sched:sched_switch: swapper/31:0 [120] R ==> watchdog/31:161 [0]
swapper 0 [028] 2591904.274136: sched:sched_switch: swapper/28:0 [120] R ==> watchdog/28:146 [0]
swapper 0 [029] 2591904.274136: sched:sched_switch: swapper/29:0 [120] R ==> watchdog/29:151 [0]
swapper 0 [030] 2591904.274136: sched:sched_switch: swapper/30:0 [120] R ==> watchdog/30:156 [0]
watchdog/30 156 [030] 2591904.274144: sched:sched_switch: watchdog/30:156 [0] S ==> swapper/30:0 [120]
watchdog/31 161 [031] 2591904.274144: sched:sched_switch: watchdog/31:161 [0] S ==> swapper/31:0 [120]
watchdog/29 151 [029] 2591904.274144: sched:sched_switch: watchdog/29:151 [0] S ==> swapper/29:0 [120]
watchdog/28 146 [028] 2591904.274144: sched:sched_switch: watchdog/28:146 [0] S ==> swapper/28:0 [120]
sleep 5853 [050] 2591904.274335: sched:sched_stat_runtime: comm=sleep pid=5853 runtime=240060 [ns] vruntime=5600051655082936 [ns]
sleep 5853 [050] 2591904.274337: sched:sched_switch: sleep:5853 [120] S ==> swapper/50:0 [120]
swapper 0 [050] 2591904.275412: sched:sched_stat_sleep: comm=sleep pid=5853 delay=1073820 [ns]
swapper 0 [050] 2591904.275415: sched:sched_stat_wait: comm=sleep pid=5853 delay=0 [ns]
swapper 0 [050] 2591904.275416: sched:sched_switch: swapper/50:0 [120] R ==> sleep:5853 [120]
sleep 5853 [050] 2591904.275507: sched:sched_process_exit: comm=sleep pid=5853 prio=120
swapper 0 [042] 2591904.275595: sched:sched_stat_sleep: comm=perf pid=5852 delay=1947804 [ns]
swapper 0 [042] 2591904.275598: sched:sched_stat_wait: comm=perf pid=5852 delay=0 [ns]
swapper 0 [042] 2591904.275598: sched:sched_switch: swapper/42:0 [120] R ==> perf:5852 [120]
sleep 5853 [050] 2591904.275600: sched:sched_stat_runtime: comm=sleep pid=5853 runtime=189998 [ns] vruntime=5600051655272934 [ns]
sleep 5853 [050] 2591904.275604: sched:sched_switch: sleep:5853 [120] x ==> swapper/50:0 [120]
$ perf inject -v -s -i perf.data -o perf-inject.data
registering plugin: /home/pc/perf/install/lib64/traceevent/plugins/plugin_cfg80211.so
registering plugin: /home/pc/perf/install/lib64/traceevent/plugins/plugin_hrtimer.so
registering plugin: /home/pc/perf/install/lib64/traceevent/plugins/plugin_kvm.so
registering plugin: /home/pc/perf/install/lib64/traceevent/plugins/plugin_function.so
registering plugin: /home/pc/perf/install/lib64/traceevent/plugins/plugin_sched_switch.so
registering plugin: /home/pc/perf/install/lib64/traceevent/plugins/plugin_mac80211.so
registering plugin: /home/pc/perf/install/lib64/traceevent/plugins/plugin_jbd2.so
registering plugin: /home/pc/perf/install/lib64/traceevent/plugins/plugin_xen.so
registering plugin: /home/pc/perf/install/lib64/traceevent/plugins/plugin_kmem.so
registering plugin: /home/pc/perf/install/lib64/traceevent/plugins/plugin_scsi.so
overriding event (228) sched:sched_switch with new print handler
build id event received for [kernel.kallsyms]: 3a023a26703f05608a46e35e461924ec56867d60
build id event received for [vdso]: 105a65948f683eafab4085b19c97f00175dbf175
Looking at the vmlinux_path (8 entries long)
Failed to open /proc/kcore. Note /proc/kcore requires CAP_SYS_RAWIO capability to access.
Using /proc/kallsyms for symbols
Using CPUID 004b0201
$ perf script -i perf-inject.data
perf 5852 [042] 2591904.272752: sched:sched_migrate_task: comm=perf pid=5853 prio=120 orig_cpu=49 dest_cpu=43
perf 5853 [043] 2591904.273058: sched:sched_switch: perf:5853 [120] R ==> migration/43:222 [0]
migration/43 222 [043] 2591904.273061: sched:sched_migrate_task: comm=perf pid=5853 prio=120 orig_cpu=43 dest_cpu=50
perf 5853 [043] 2591904.273126: sched:sched_switch: perf:5853 [120] R ==> migration/43:222 [0]
sleep 5853 [050] 2591904.273726: sched:sched_process_exec: filename=/bin/sleep pid=5853 old_pid=5853
sleep 5853 [043] 2591904.274095: sched:sched_switch: perf:5853 [120] R ==> migration/43:222 [0]
sleep 5853 [043] 2591904.274335: sched:sched_switch: perf:5853 [120] R ==> migration/43:222 [0]
sleep 5853 [050] 2591904.275412: sched:sched_switch: sleep:5853 [120] S ==> swapper/50:0 [120]
sleep 5853 [050] 2591904.275415: sched:sched_switch: sleep:5853 [120] S ==> swapper/50:0 [120]
perf 5852 [042] 2591904.275595: sched:sched_switch: perf:5852 [120] S ==> swapper/42:0 [120]
perf 5852 [042] 2591904.275598: sched:sched_switch: perf:5852 [120] S ==> swapper/42:0 [120]
--
PC
^ permalink raw reply [flat|nested] 2+ messages in thread
* Re: perf inject -s
2017-10-04 17:38 perf inject -s Paul Clarke
@ 2017-10-06 12:40 ` Milian Wolff
0 siblings, 0 replies; 2+ messages in thread
From: Milian Wolff @ 2017-10-06 12:40 UTC (permalink / raw)
To: Paul Clarke; +Cc: linux-perf-users
On Mittwoch, 4. Oktober 2017 19:38:59 CEST Paul Clarke wrote:
> Is there a better description of what "perf inject -s" does?
>
> The man page for "perf inject" says:
> --
> -s, --sched-stat
> Merge sched_stat and sched_switch for getting events
> where and how long tasks slept. sched_switch contains
> a callchain where a task slept and sched_stat contains
> a timeslice how long a task slept.
> --
>
> Is it creating a new type of event? If so, is the new event type visible to
> "perf script" and "perf script -s" ?
It's meant to be used for off-CPU profiling and also depends on the scheduler
stat tracepoints, see also:
https://perf.wiki.kernel.org/index.php/Tutorial#Profiling_sleep_times
https://github.com/milianw/shell-helpers/blob/master/perf-sleep-record
I concur that the documentation should be expanded. The situation you show
below shows an issue with `perf inject`: It currently takes the cost of the
`sched_stat` tracepoint and sets it as the period of the `sched_switch`
tracepoint. That makes it impossible to trace multiple stats in one go.
Instead, one would need to take the switch out event's callgraph and set it on
the `sched_stat` tracepoints, which would fix this situation.
Hope that helps
> I just see events disappearing:
> --
> $ perf --version
> perf version 4.13.rc4.gf2f132
> $ perf record -e
> '{sched:sched_switch,sched:sched_migrate_task,sched:sched_process_exec,sche
> d:sched_process_fork,sched:sched_process_exit,sched:sched_stat_runtime,sched
> :sched_stat_wait,sched:sched_stat_sleep,sched:sched_stat_blocked,sched:sched
> _stat_iowait}' -a sleep 0.001 [ perf record: Woken up 1 times to write data
> ]
> [ perf record: Captured and wrote 0.144 MB perf.data (39 samples) ]
> $ perf script
> perf 5852 [042] 2591904.272752: sched:sched_migrate_task:
> comm=perf pid=5853 prio=120 orig_cpu=49 dest_cpu=43 perf 5852 [042]
> 2591904.272756: sched:sched_stat_sleep: comm=perf pid=5853
> delay=159273628 [ns] swapper 0 [043] 2591904.272760:
> sched:sched_stat_wait: comm=perf pid=5853 delay=0 [ns] swapper 0 [043]
> 2591904.272761: sched:sched_switch: swapper/43:0 [120] R ==>
> perf:5853 [120] perf 5853 [043] 2591904.273032: sched:sched_stat_runtime:
> comm=perf pid=5853 runtime=274344 [ns] vruntime=5217430079833775 [ns] perf
> 5853 [043] 2591904.273034: sched:sched_switch: perf:5853 [120] R ==>
> migration/43:222 [0] migration/43 222 [043] 2591904.273058:
> sched:sched_stat_wait: comm=perf pid=5853 delay=26246 [ns] migration/43
> 222 [043] 2591904.273061: sched:sched_migrate_task: comm=perf pid=5853
> prio=120 orig_cpu=43 dest_cpu=50 swapper 0 [050] 2591904.273126:
> sched:sched_stat_wait: comm=perf pid=5853 delay=0 [ns] migration/43 222
> [043] 2591904.273127: sched:sched_switch: migration/43:222 [0] S ==>
> swapper/43:0 [120] swapper 0 [050] 2591904.273129:
> sched:sched_switch: swapper/50:0 [120] R ==> perf:5853 [120] perf 5852
> [042] 2591904.273647: sched:sched_stat_runtime: comm=perf pid=5852
> runtime=3500692 [ns] vruntime=5674786469460196 [ns] perf 5852 [042]
> 2591904.273648: sched:sched_switch: perf:5852 [120] S ==>
> swapper/42:0 [120] sleep 5853 [050] 2591904.273726:
> sched:sched_process_exec: filename=/bin/sleep pid=5853 old_pid=5853 sleep
> 5853 [050] 2591904.274095: sched:sched_stat_runtime: comm=sleep pid=5853
> runtime=1032442 [ns] vruntime=5600051654842876 [ns] swapper 0 [043]
> 2591904.274112: sched:sched_stat_sleep: comm=rcu_sched pid=7
> delay=4010582 [ns] swapper 0 [043] 2591904.274115:
> sched:sched_stat_wait: comm=rcu_sched pid=7 delay=0 [ns] swapper 0
> [043] 2591904.274115: sched:sched_switch: swapper/43:0 [120] R ==>
> rcu_sched:7 [120] rcu_sched 7 [043] 2591904.274135:
> sched:sched_stat_runtime: comm=rcu_sched pid=7 runtime=23894 [ns]
> vruntime=2504293416526246 [ns] rcu_sched 7 [043] 2591904.274136:
> sched:sched_switch: rcu_sched:7 [120] S ==> swapper/43:0 [120] swapper
> 0 [031] 2591904.274136: sched:sched_switch: swapper/31:0 [120] R ==>
> watchdog/31:161 [0] swapper 0 [028] 2591904.274136:
> sched:sched_switch: swapper/28:0 [120] R ==> watchdog/28:146 [0] swapper
> 0 [029] 2591904.274136: sched:sched_switch: swapper/29:0 [120] R ==>
> watchdog/29:151 [0] swapper 0 [030] 2591904.274136:
> sched:sched_switch: swapper/30:0 [120] R ==> watchdog/30:156 [0]
> watchdog/30 156 [030] 2591904.274144: sched:sched_switch:
> watchdog/30:156 [0] S ==> swapper/30:0 [120] watchdog/31 161 [031]
> 2591904.274144: sched:sched_switch: watchdog/31:161 [0] S ==>
> swapper/31:0 [120] watchdog/29 151 [029] 2591904.274144:
> sched:sched_switch: watchdog/29:151 [0] S ==> swapper/29:0 [120]
> watchdog/28 146 [028] 2591904.274144: sched:sched_switch:
> watchdog/28:146 [0] S ==> swapper/28:0 [120] sleep 5853 [050]
> 2591904.274335: sched:sched_stat_runtime: comm=sleep pid=5853
> runtime=240060 [ns] vruntime=5600051655082936 [ns] sleep 5853 [050]
> 2591904.274337: sched:sched_switch: sleep:5853 [120] S ==>
> swapper/50:0 [120] swapper 0 [050] 2591904.275412:
> sched:sched_stat_sleep: comm=sleep pid=5853 delay=1073820 [ns] swapper
> 0 [050] 2591904.275415: sched:sched_stat_wait: comm=sleep pid=5853
> delay=0 [ns] swapper 0 [050] 2591904.275416: sched:sched_switch:
> swapper/50:0 [120] R ==> sleep:5853 [120] sleep 5853 [050] 2591904.275507:
> sched:sched_process_exit: comm=sleep pid=5853 prio=120 swapper 0 [042]
> 2591904.275595: sched:sched_stat_sleep: comm=perf pid=5852 delay=1947804
> [ns] swapper 0 [042] 2591904.275598: sched:sched_stat_wait:
> comm=perf pid=5852 delay=0 [ns] swapper 0 [042] 2591904.275598:
> sched:sched_switch: swapper/42:0 [120] R ==> perf:5852 [120] sleep 5853
> [050] 2591904.275600: sched:sched_stat_runtime: comm=sleep pid=5853
> runtime=189998 [ns] vruntime=5600051655272934 [ns] sleep 5853 [050]
> 2591904.275604: sched:sched_switch: sleep:5853 [120] x ==>
> swapper/50:0 [120] $ perf inject -v -s -i perf.data -o perf-inject.data
> registering plugin:
> /home/pc/perf/install/lib64/traceevent/plugins/plugin_cfg80211.so
> registering plugin:
> /home/pc/perf/install/lib64/traceevent/plugins/plugin_hrtimer.so
> registering plugin:
> /home/pc/perf/install/lib64/traceevent/plugins/plugin_kvm.so registering
> plugin: /home/pc/perf/install/lib64/traceevent/plugins/plugin_function.so
> registering plugin:
> /home/pc/perf/install/lib64/traceevent/plugins/plugin_sched_switch.so
> registering plugin:
> /home/pc/perf/install/lib64/traceevent/plugins/plugin_mac80211.so
> registering plugin:
> /home/pc/perf/install/lib64/traceevent/plugins/plugin_jbd2.so registering
> plugin: /home/pc/perf/install/lib64/traceevent/plugins/plugin_xen.so
> registering plugin:
> /home/pc/perf/install/lib64/traceevent/plugins/plugin_kmem.so registering
> plugin: /home/pc/perf/install/lib64/traceevent/plugins/plugin_scsi.so
> overriding event (228) sched:sched_switch with new print handler
> build id event received for [kernel.kallsyms]:
> 3a023a26703f05608a46e35e461924ec56867d60 build id event received for
> [vdso]: 105a65948f683eafab4085b19c97f00175dbf175 Looking at the
> vmlinux_path (8 entries long)
> Failed to open /proc/kcore. Note /proc/kcore requires CAP_SYS_RAWIO
> capability to access. Using /proc/kallsyms for symbols
> Using CPUID 004b0201
> $ perf script -i perf-inject.data
> perf 5852 [042] 2591904.272752: sched:sched_migrate_task:
> comm=perf pid=5853 prio=120 orig_cpu=49 dest_cpu=43 perf 5853 [043]
> 2591904.273058: sched:sched_switch: perf:5853 [120] R ==>
> migration/43:222 [0] migration/43 222 [043] 2591904.273061:
> sched:sched_migrate_task: comm=perf pid=5853 prio=120 orig_cpu=43
> dest_cpu=50 perf 5853 [043] 2591904.273126: sched:sched_switch:
> perf:5853 [120] R ==> migration/43:222 [0] sleep 5853 [050]
> 2591904.273726: sched:sched_process_exec: filename=/bin/sleep pid=5853
> old_pid=5853 sleep 5853 [043] 2591904.274095: sched:sched_switch:
> perf:5853 [120] R ==> migration/43:222 [0] sleep 5853 [043]
> 2591904.274335: sched:sched_switch: perf:5853 [120] R ==>
> migration/43:222 [0] sleep 5853 [050] 2591904.275412:
> sched:sched_switch: sleep:5853 [120] S ==> swapper/50:0 [120] sleep 5853
> [050] 2591904.275415: sched:sched_switch: sleep:5853 [120] S ==>
> swapper/50:0 [120] perf 5852 [042] 2591904.275595:
> sched:sched_switch: perf:5852 [120] S ==> swapper/42:0 [120] perf 5852
> [042] 2591904.275598: sched:sched_switch: perf:5852 [120] S ==>
> swapper/42:0 [120] --
> PC
>
> --
> To unsubscribe from this list: send the line "unsubscribe linux-perf-users"
> in the body of a message to majordomo@vger.kernel.org
> More majordomo info at http://vger.kernel.org/majordomo-info.html
--
Milian Wolff | milian.wolff@kdab.com | Senior Software Engineer
KDAB (Deutschland) GmbH&Co KG, a KDAB Group company
Tel: +49-30-521325470
KDAB - The Qt Experts
^ permalink raw reply [flat|nested] 2+ messages in thread
end of thread, other threads:[~2017-10-06 12:40 UTC | newest]
Thread overview: 2+ messages (download: mbox.gz / follow: Atom feed)
-- links below jump to the message on this page --
2017-10-04 17:38 perf inject -s Paul Clarke
2017-10-06 12:40 ` Milian Wolff
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.