RHEL Engineering is moving the tracking of its product development work on RHEL 6 through RHEL 9 to Red Hat Jira (issues.redhat.com). If you're a Red Hat customer, please continue to file support cases via the Red Hat customer portal. If you're not, please head to the "RHEL project" in Red Hat Jira and file new tickets here. Individual Bugzilla bugs in the statuses "NEW", "ASSIGNED", and "POST" are being migrated throughout September 2023. Bugs of Red Hat partners with an assigned Engineering Partner Manager (EPM) are migrated in late September as per pre-agreed dates. Bugs against components "kernel", "kernel-rt", and "kpatch" are only migrated if still in "NEW" or "ASSIGNED". If you cannot log in to RH Jira, please consult article #7032570. That failing, please send an e-mail to the RH Jira admins at rh-issues@redhat.com to troubleshoot your issue as a user management inquiry. The email creates a ServiceNow ticket with Red Hat. Individual Bugzilla bugs that are migrated will be moved to status "CLOSED", resolution "MIGRATED", and set with "MigratedToJIRA" in "Keywords". The link to the successor Jira issue will be found under "Links", have a little "two-footprint" icon next to it, and direct you to the "RHEL project" in Red Hat Jira (issue links are of type "https://issues.redhat.com/browse/RHEL-XXXX", where "X" is a digit). This same link will be available in a blue banner at the top of the page informing you that that bug has been migrated.
Bug 1480770 - trace-cmd report -w -F 'sched_switch,sched_wakeup' broken after 2.4.2
Summary: trace-cmd report -w -F 'sched_switch,sched_wakeup' broken after 2.4.2
Keywords:
Status: CLOSED ERRATA
Alias: None
Product: Red Hat Enterprise Linux 7
Classification: Red Hat
Component: trace-cmd
Version: 7.4
Hardware: x86_64
OS: Linux
unspecified
medium
Target Milestone: rc
: ---
Assignee: John Kacur
QA Contact: Ziqian SUN (Zamir)
URL:
Whiteboard:
Depends On:
Blocks: 1442258
TreeView+ depends on / blocked
 
Reported: 2017-08-11 20:42 UTC by Joe Mario
Modified: 2018-11-16 07:07 UTC (History)
3 users (show)

Fixed In Version:
Doc Type: If docs needed, set a value
Doc Text:
Clone Of:
Environment:
Last Closed: 2018-04-10 18:13:55 UTC
Target Upstream Version:
Embargoed:


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


Links
System ID Private Priority Status Summary Last Updated
Red Hat Product Errata RHBA-2018:0968 0 None None None 2018-04-10 18:14:04 UTC

Description Joe Mario 2017-08-11 20:42:32 UTC
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
issues.

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 05:52:21 UTC
Reproduced with trace-cmd-2.6.0-8.el7.x86_64 on RHEL-7.4.

Patch sent upstream.
https://lkml.org/lkml/2017/8/25/27

Comment 3 John Kacur 2017-08-28 16:32:56 UTC
Created attachment 1319156 [details]
trace-cmd-record-Fix-filtering-when-using-set_event_pid_part2

Comment 5 John Kacur 2017-08-29 14:47:37 UTC
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 18:13:55 UTC
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.

https://access.redhat.com/errata/RHBA-2018:0968


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