Bug 1480770 - trace-cmd report -w -F 'sched_switch,sched_wakeup' broken after 2.4.2
trace-cmd report -w -F 'sched_switch,sched_wakeup' broken after 2.4.2
Product: Red Hat Enterprise Linux 7
Classification: Red Hat
Component: trace-cmd (Show other bugs)
x86_64 Linux
unspecified Severity medium
: rc
: ---
Assigned To: John Kacur
Ziqian SUN (Zamir)
Depends On:
Blocks: 1442258
  Show dependency treegraph
Reported: 2017-08-11 16:42 EDT by Joe Mario
Modified: 2018-04-10 14:14 EDT (History)
3 users (show)

See Also:
Fixed In Version:
Doc Type: If docs needed, set a value
Doc Text:
Story Points: ---
Clone Of:
Last Closed: 2018-04-10 14:13:55 EDT
Type: Bug
Regression: ---
Mount Type: ---
Documentation: ---
Verified Versions:
Category: ---
oVirt Team: ---
RHEL 7.3 requirements from Atomic Host:
Cloudforms Team: ---

Attachments (Terms of Use)
trace-cmd-record-Fix-filtering-when-using-set_event_pid_part2 (1.62 KB, patch)
2017-08-28 12:32 EDT, John Kacur
no flags Details | Diff

External Trackers
Tracker ID Priority Status Summary Last Updated
Red Hat Product Errata RHBA-2018:0968 None None None 2018-04-10 14:14 EDT

  None (edit)
Description Joe Mario 2017-08-11 16:42:32 EDT
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.

How reproducible:

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'

Expected results:
Each "sched_switch" line would report the individual Latency value.  See these two sched_switch lines:

          <idle>-0     [073]  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     [026]  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

Actual results:
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.

Additional info:
Comment 2 Ziqian SUN (Zamir) 2017-08-25 01:52:21 EDT
Reproduced with trace-cmd-2.6.0-8.el7.x86_64 on RHEL-7.4.

Patch sent upstream.
Comment 3 John Kacur 2017-08-28 12:32 EDT
Created attachment 1319156 [details]
Comment 5 John Kacur 2017-08-29 10:47:37 EDT
After applying the fix, you see output like
sshd-13379 [004]  1276.358690: sched_switch:         sshd:13379 [120] S ==> kworker/4:1:67 [120] Latency: 30.552 usecs
Comment 10 errata-xmlrpc 2018-04-10 14:13:55 EDT
Since the problem described in this bug report should be
resolved in a recent advisory, it has been closed with a
resolution of ERRATA.

For information on the advisory, and where to find the updated
files, follow the link below.

If the solution does not work for you, open a new bug report.


Note You need to log in before you can comment on or make changes to this bug.