Skip to content

Commit d392e49

Browse files
torvaldstorvalds
committed
Merge tag 'trace-tools-v6.3' of git://git.kernel.org/pub/scm/linux/kernel/git/trace/linux-trace
Pull tracing tools updates from Steven Rostedt: - Use total duration to calculate average in rtla osnoise_hist - Use 2 digit precision for displaying average - Print an intuitive auto analysis of timerlat results - Add auto analysis to timerlat top - Add hwnoise, which is the same as osnoise but focuses on hardware - Small clean ups * tag 'trace-tools-v6.3' of git://git.kernel.org/pub/scm/linux/kernel/git/trace/linux-trace: Documentation/rtla: Add hwnoise man page rtla: Add hwnoise tool Documentation/rtla: Add timerlat-top auto-analysis options rtla/timerlat: Add auto-analysis support to timerlat top rtla/timerlat: Add auto-analysis core tools/tracing/rtla: osnoise_hist: display average with two-digit precision tools/tracing/rtla: osnoise_hist: use total duration for average calculation tools/rv: Remove unneeded semicolon
2 parents 2562af6 + 5dc3750 commit d392e49

File tree

15 files changed

+1442
-113
lines changed

15 files changed

+1442
-113
lines changed

‎Documentation/tools/rtla/common_timerlat_aa.rst

Lines changed: 7 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,7 @@
1+
**--dump-tasks**
2+
3+
prints the task running on all CPUs if stop conditions are met (depends on !--no-aa)
4+
5+
**--no-aa**
6+
7+
disable auto-analysis, reducing rtla timerlat cpu usage

‎Documentation/tools/rtla/index.rst

Lines changed: 1 addition & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -17,6 +17,7 @@ behavior on specific hardware.
1717
rtla-timerlat
1818
rtla-timerlat-hist
1919
rtla-timerlat-top
20+
rtla-hwnoise
2021

2122
.. only:: subproject and html
2223

‎Documentation/tools/rtla/rtla-hwnoise.rst

Lines changed: 107 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,107 @@
1+
.. SPDX-License-Identifier: GPL-2.0
2+
3+
============
4+
rtla-hwnoise
5+
============
6+
------------------------------------------
7+
Detect and quantify hardware-related noise
8+
------------------------------------------
9+
10+
:Manual section: 1
11+
12+
SYNOPSIS
13+
========
14+
15+
**rtla hwnoise** [*OPTIONS*]
16+
17+
DESCRIPTION
18+
===========
19+
20+
**rtla hwnoise** collects the periodic summary from the *osnoise* tracer
21+
running with *interrupts disabled*. By disabling interrupts, and the scheduling
22+
of threads as a consequence, only non-maskable interrupts and hardware-related
23+
noise is allowed.
24+
25+
The tool also allows the configurations of the *osnoise* tracer and the
26+
collection of the tracer output.
27+
28+
OPTIONS
29+
=======
30+
.. include:: common_osnoise_options.rst
31+
32+
.. include:: common_top_options.rst
33+
34+
.. include:: common_options.rst
35+
36+
EXAMPLE
37+
=======
38+
In the example below, the **rtla hwnoise** tool is set to run on CPUs *1-7*
39+
on a system with 8 cores/16 threads with hyper-threading enabled.
40+
41+
The tool is set to detect any noise higher than *one microsecond*,
42+
to run for *ten minutes*, displaying a summary of the report at the
43+
end of the session::
44+
45+
# rtla hwnoise -c 1-7 -T 1 -d 10m -q
46+
Hardware-related Noise
47+
duration: 0 00:10:00 | time is in us
48+
CPU Period Runtime Noise % CPU Aval Max Noise Max Single HW NMI
49+
1 #599 599000000 138 99.99997 3 3 4 74
50+
2 #599 599000000 85 99.99998 3 3 4 75
51+
3 #599 599000000 86 99.99998 4 3 6 75
52+
4 #599 599000000 81 99.99998 4 4 2 75
53+
5 #599 599000000 85 99.99998 2 2 2 75
54+
6 #599 599000000 76 99.99998 2 2 0 75
55+
7 #599 599000000 77 99.99998 3 3 0 75
56+
57+
58+
The first column shows the *CPU*, and the second column shows how many
59+
*Periods* the tool ran during the session. The *Runtime* is the time
60+
the tool effectively runs on the CPU. The *Noise* column is the sum of
61+
all noise that the tool observed, and the *% CPU Aval* is the relation
62+
between the *Runtime* and *Noise*.
63+
64+
The *Max Noise* column is the maximum hardware noise the tool detected in a
65+
single period, and the *Max Single* is the maximum single noise seen.
66+
67+
The *HW* and *NMI* columns show the total number of *hardware* and *NMI* noise
68+
occurrence observed by the tool.
69+
70+
For example, *CPU 3* ran *599* periods of *1 second Runtime*. The CPU received
71+
*86 us* of noise during the entire execution, leaving *99.99997 %* of CPU time
72+
for the application. In the worst single period, the CPU caused *4 us* of
73+
noise to the application, but it was certainly caused by more than one single
74+
noise, as the *Max Single* noise was of *3 us*. The CPU has *HW noise,* at a
75+
rate of *six occurrences*/*ten minutes*. The CPU also has *NMIs*, at a higher
76+
frequency: around *seven per second*.
77+
78+
The tool should report *0* hardware-related noise in the ideal situation.
79+
For example, by disabling hyper-threading to remove the hardware noise,
80+
and disabling the TSC watchdog to remove the NMI (it is possible to identify
81+
this using tracing options of **rtla hwnoise**), it was possible to reach
82+
the ideal situation in the same hardware::
83+
84+
# rtla hwnoise -c 1-7 -T 1 -d 10m -q
85+
Hardware-related Noise
86+
duration: 0 00:10:00 | time is in us
87+
CPU Period Runtime Noise % CPU Aval Max Noise Max Single HW NMI
88+
1 #599 599000000 0 100.00000 0 0 0 0
89+
2 #599 599000000 0 100.00000 0 0 0 0
90+
3 #599 599000000 0 100.00000 0 0 0 0
91+
4 #599 599000000 0 100.00000 0 0 0 0
92+
5 #599 599000000 0 100.00000 0 0 0 0
93+
6 #599 599000000 0 100.00000 0 0 0 0
94+
7 #599 599000000 0 100.00000 0 0 0 0
95+
96+
SEE ALSO
97+
========
98+
99+
**rtla-osnoise**\(1)
100+
101+
Osnoise tracer documentation: <https://www.kernel.org/doc/html/latest/trace/osnoise-tracer.html>
102+
103+
AUTHOR
104+
======
105+
Written by Daniel Bristot de Oliveira <[email protected]>
106+
107+
.. include:: common_appendix.rst

‎Documentation/tools/rtla/rtla-timerlat-top.rst

Lines changed: 73 additions & 91 deletions
Original file line numberDiff line numberDiff line change
@@ -30,102 +30,84 @@ OPTIONS
3030

3131
.. include:: common_options.rst
3232

33+
.. include:: common_timerlat_aa.rst
34+
3335
EXAMPLE
3436
=======
3537

36-
In the example below, the *timerlat* tracer is set to capture the stack trace at
37-
the IRQ handler, printing it to the buffer if the *Thread* timer latency is
38-
higher than *30 us*. It is also set to stop the session if a *Thread* timer
39-
latency higher than *30 us* is hit. Finally, it is set to save the trace
40-
buffer if the stop condition is hit::
38+
In the example below, the timerlat tracer is dispatched in cpus *1-23* in the
39+
automatic trace mode, instructing the tracer to stop if a *40 us* latency or
40+
higher is found::
4141

42-
[root@alien ~]# rtla timerlat top -s 30 -T 30 -t
43-
Timer Latency
44-
0 00:00:59 | IRQ Timer Latency (us) | Thread Timer Latency (us)
42+
# timerlat -a 40 -c 1-23 -q
43+
Timer Latency
44+
0 00:00:12 | IRQ Timer Latency (us) | Thread Timer Latency (us)
4545
CPU COUNT | cur min avg max | cur min avg max
46-
0 #58634 | 1 0 1 10 | 11 2 10 23
47-
1 #58634 | 1 0 1 9 | 12 2 9 23
48-
2 #58634 | 0 0 1 11 | 10 2 9 23
49-
3 #58634 | 1 0 1 11 | 11 2 9 24
50-
4 #58634 | 1 0 1 10 | 11 2 9 26
51-
5 #58634 | 1 0 1 8 | 10 2 9 25
52-
6 #58634 | 12 0 1 12 | 30 2 10 30 <--- CPU with spike
53-
7 #58634 | 1 0 1 9 | 11 2 9 23
54-
8 #58633 | 1 0 1 9 | 11 2 9 26
55-
9 #58633 | 1 0 1 9 | 10 2 9 26
56-
10 #58633 | 1 0 1 13 | 11 2 9 28
57-
11 #58633 | 1 0 1 13 | 12 2 9 24
58-
12 #58633 | 1 0 1 8 | 10 2 9 23
59-
13 #58633 | 1 0 1 10 | 10 2 9 22
60-
14 #58633 | 1 0 1 18 | 12 2 9 27
61-
15 #58633 | 1 0 1 10 | 11 2 9 28
62-
16 #58633 | 0 0 1 11 | 7 2 9 26
63-
17 #58633 | 1 0 1 13 | 10 2 9 24
64-
18 #58633 | 1 0 1 9 | 13 2 9 22
65-
19 #58633 | 1 0 1 10 | 11 2 9 23
66-
20 #58633 | 1 0 1 12 | 11 2 9 28
67-
21 #58633 | 1 0 1 14 | 11 2 9 24
68-
22 #58633 | 1 0 1 8 | 11 2 9 22
69-
23 #58633 | 1 0 1 10 | 11 2 9 27
70-
timerlat hit stop tracing
71-
saving trace to timerlat_trace.txt
72-
[root@alien bristot]# tail -60 timerlat_trace.txt
73-
[...]
74-
timerlat/5-79755 [005] ....... 426.271226: #58634 context thread timer_latency 10823 ns
75-
sh-109404 [006] dnLh213 426.271247: #58634 context irq timer_latency 12505 ns
76-
sh-109404 [006] dNLh313 426.271258: irq_noise: local_timer:236 start 426.271245463 duration 12553 ns
77-
sh-109404 [006] d...313 426.271263: thread_noise: sh:109404 start 426.271245853 duration 4769 ns
78-
timerlat/6-79756 [006] ....... 426.271264: #58634 context thread timer_latency 30328 ns
79-
timerlat/6-79756 [006] ....1.. 426.271265: <stack trace>
80-
=> timerlat_irq
81-
=> __hrtimer_run_queues
82-
=> hrtimer_interrupt
83-
=> __sysvec_apic_timer_interrupt
84-
=> sysvec_apic_timer_interrupt
85-
=> asm_sysvec_apic_timer_interrupt
86-
=> _raw_spin_unlock_irqrestore <---- spinlock that disabled interrupt.
87-
=> try_to_wake_up
88-
=> autoremove_wake_function
89-
=> __wake_up_common
90-
=> __wake_up_common_lock
91-
=> ep_poll_callback
92-
=> __wake_up_common
93-
=> __wake_up_common_lock
94-
=> fsnotify_add_event
95-
=> inotify_handle_inode_event
96-
=> fsnotify
97-
=> __fsnotify_parent
98-
=> __fput
99-
=> task_work_run
100-
=> exit_to_user_mode_prepare
101-
=> syscall_exit_to_user_mode
102-
=> do_syscall_64
103-
=> entry_SYSCALL_64_after_hwframe
104-
=> 0x7265000001378c
105-
=> 0x10000cea7
106-
=> 0x25a00000204a
107-
=> 0x12e302d00000000
108-
=> 0x19b51010901b6
109-
=> 0x283ce00726500
110-
=> 0x61ea308872
111-
=> 0x00000fe3
112-
bash-109109 [007] d..h... 426.271265: #58634 context irq timer_latency 1211 ns
113-
timerlat/6-79756 [006] ....... 426.271267: timerlat_main: stop tracing hit on cpu 6
114-
115-
In the trace, it is possible the notice that the *IRQ* timer latency was
116-
already high, accounting *12505 ns*. The IRQ delay was caused by the
117-
*bash-109109* process that disabled IRQs in the wake-up path
118-
(*_try_to_wake_up()* function). The duration of the IRQ handler that woke
119-
up the timerlat thread, informed with the **osnoise:irq_noise** event, was
120-
also high and added more *12553 ns* to the Thread latency. Finally, the
121-
**osnoise:thread_noise** added by the currently running thread (including
122-
the scheduling overhead) added more *4769 ns*. Summing up these values,
123-
the *Thread* timer latency accounted for *30328 ns*.
124-
125-
The primary reason for this high value is the wake-up path that was hit
126-
twice during this case: when the *bash-109109* was waking up a thread
127-
and then when the *timerlat* thread was awakened. This information can
128-
then be used as the starting point of a more fine-grained analysis.
46+
1 #12322 | 0 0 1 15 | 10 3 9 31
47+
2 #12322 | 3 0 1 12 | 10 3 9 23
48+
3 #12322 | 1 0 1 21 | 8 2 8 34
49+
4 #12322 | 1 0 1 17 | 10 2 11 33
50+
5 #12322 | 0 0 1 12 | 8 3 8 25
51+
6 #12322 | 1 0 1 14 | 16 3 11 35
52+
7 #12322 | 0 0 1 14 | 9 2 8 29
53+
8 #12322 | 1 0 1 22 | 9 3 9 34
54+
9 #12322 | 0 0 1 14 | 8 2 8 24
55+
10 #12322 | 1 0 0 12 | 9 3 8 24
56+
11 #12322 | 0 0 0 15 | 6 2 7 29
57+
12 #12321 | 1 0 0 13 | 5 3 8 23
58+
13 #12319 | 0 0 1 14 | 9 3 9 26
59+
14 #12321 | 1 0 0 13 | 6 2 8 24
60+
15 #12321 | 1 0 1 15 | 12 3 11 27
61+
16 #12318 | 0 0 1 13 | 7 3 10 24
62+
17 #12319 | 0 0 1 13 | 11 3 9 25
63+
18 #12318 | 0 0 0 12 | 8 2 8 20
64+
19 #12319 | 0 0 1 18 | 10 2 9 28
65+
20 #12317 | 0 0 0 20 | 9 3 8 34
66+
21 #12318 | 0 0 0 13 | 8 3 8 28
67+
22 #12319 | 0 0 1 11 | 8 3 10 22
68+
23 #12320 | 28 0 1 28 | 41 3 11 41
69+
rtla timerlat hit stop tracing
70+
## CPU 23 hit stop tracing, analyzing it ##
71+
IRQ handler delay: 27.49 us (65.52 %)
72+
IRQ latency: 28.13 us
73+
Timerlat IRQ duration: 9.59 us (22.85 %)
74+
Blocking thread: 3.79 us (9.03 %)
75+
objtool:49256 3.79 us
76+
Blocking thread stacktrace
77+
-> timerlat_irq
78+
-> __hrtimer_run_queues
79+
-> hrtimer_interrupt
80+
-> __sysvec_apic_timer_interrupt
81+
-> sysvec_apic_timer_interrupt
82+
-> asm_sysvec_apic_timer_interrupt
83+
-> _raw_spin_unlock_irqrestore
84+
-> cgroup_rstat_flush_locked
85+
-> cgroup_rstat_flush_irqsafe
86+
-> mem_cgroup_flush_stats
87+
-> mem_cgroup_wb_stats
88+
-> balance_dirty_pages
89+
-> balance_dirty_pages_ratelimited_flags
90+
-> btrfs_buffered_write
91+
-> btrfs_do_write_iter
92+
-> vfs_write
93+
-> __x64_sys_pwrite64
94+
-> do_syscall_64
95+
-> entry_SYSCALL_64_after_hwframe
96+
------------------------------------------------------------------------
97+
Thread latency: 41.96 us (100%)
98+
99+
The system has exit from idle latency!
100+
Max timerlat IRQ latency from idle: 17.48 us in cpu 4
101+
Saving trace to timerlat_trace.txt
102+
103+
In this case, the major factor was the delay suffered by the *IRQ handler*
104+
that handles **timerlat** wakeup: *65.52%*. This can be caused by the
105+
current thread masking interrupts, which can be seen in the blocking
106+
thread stacktrace: the current thread (*objtool:49256*) disabled interrupts
107+
via *raw spin lock* operations inside mem cgroup, while doing write
108+
syscall in a btrfs file system.
109+
110+
The raw trace is saved in the **timerlat_trace.txt** file for further analysis.
129111

130112
Note that **rtla timerlat** was dispatched without changing *timerlat* tracer
131113
threads' priority. That is generally not needed because these threads hava

‎tools/tracing/rtla/Makefile

Lines changed: 2 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -119,6 +119,8 @@ install: doc_install
119119
$(STRIP) $(DESTDIR)$(BINDIR)/rtla
120120
@test ! -f $(DESTDIR)$(BINDIR)/osnoise || rm $(DESTDIR)$(BINDIR)/osnoise
121121
ln -s rtla $(DESTDIR)$(BINDIR)/osnoise
122+
@test ! -f $(DESTDIR)$(BINDIR)/hwnoise || rm $(DESTDIR)$(BINDIR)/hwnoise
123+
ln -s rtla $(DESTDIR)$(BINDIR)/hwnoise
122124
@test ! -f $(DESTDIR)$(BINDIR)/timerlat || rm $(DESTDIR)$(BINDIR)/timerlat
123125
ln -s rtla $(DESTDIR)$(BINDIR)/timerlat
124126

0 commit comments

Comments
 (0)