Red Hat Bugzilla – Bug 1480770
trace-cmd report -w -F 'sched_switch,sched_wakeup' broken after 2.4.2
Last modified: 2017-12-27 00:27:29 EST
Description of problem:
The output of:
trace-cmd report -w -F 'sched_switch,sched_wakeup'
no longer works correctly, as of trace-cmd version 2.4.2
In the 2.4.2 version, it reported the Latency for each sched_switch.
It also reported a nice summary at the end for Average wakeup latency,
for Maximum Latency, and for Minimum Latency.
None of that is reported in newer versions of trace-cmd.
Those latency values are valuable for diagnosing scheduler related
RHEL 7.* uses versions newer than 2.4.2, which do not work correctly.
Steps to Reproduce:
1. trace-cmd record -e all // And then hit ctrl-c immediately
// for a small trace.dat file
2.trace-cmd report -w -F 'sched_switch,sched_wakeup'
Each "sched_switch" line would report the individual Latency value. See these two sched_switch lines:
<idle>-0  3332.027239: sched_switch: prev_comm=swapper/73 prev_pid=0 prev_prio=120 prev_state=R ==> next_comm=trace-cmd next_pid=5581 next_prio=120 Latency: 6.565 usecs
<idle>-0  3332.027241: sched_switch: prev_comm=swapper/26 prev_pid=0 prev_prio=120 prev_state=R ==> next_comm=trace-cmd next_pid=5577 next_prio=120 Latency: 8.630 usecs
And then at the end of the output, the summary would look like this:
Average wakeup latency: 10.324 usecs
Maximum Latency: 214.505 usecs at timestamp: 3332.869763
Minimum Latency: 0.432 usecs at timestamp: 3332.534240
RT task timings:
Average wakeup latency: 8.258 usecs
Maximum Latency: 18.836 usecs at timestamp: 3332.027711
Minimum Latency: 4.599 usecs at timestamp: 3332.432522
After trace-cmd version 2.4.2, the individual Latencies for the sched_switch
entries are missing, as is the summary of Latency information at the
end of the report.
Reproduced with trace-cmd-2.6.0-8.el7.x86_64 on RHEL-7.4.
Patch sent upstream.
Created attachment 1319156 [details]
After applying the fix, you see output like
sshd-13379  1276.358690: sched_switch: sshd:13379  S ==> kworker/4:1:67  Latency: 30.552 usecs