Note: This bug is displayed in read-only format because
the product is no longer active in Red Hat Bugzilla.
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.
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 2Ziqian SUN (Zamir)
2017-08-25 05:52:21 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
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
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: