linux-toradex.git/tools/tracing/rtla, branch v6.3 Linux kernel for Apalis and Colibri modules rtla: Add hwnoise tool 2023-02-14T04:56:46+00:00 Daniel Bristot de Oliveira bristot@kernel.org 2023-02-07T21:48:50+00:00 1f428356c38dcbe49fd2f1c488b41e88720ead92 The hwnoise tool is a special mode for the osnoise top tool. hwnoise dispatches the osnoise tracer and displays a summary of the noise. The difference is that it runs the tracer with the OSNOISE_IRQ_DISABLE option set, thus only allowing only hardware-related noise, resulting in a simplified output. hwnoise has the same features of osnoise. An example of the tool's output: # rtla hwnoise -c 1-11 -T 1 -d 10m -q Hardware-related Noise duration: 0 00:10:00 | time is in us CPU Period Runtime Noise % CPU Aval Max Noise Max Single HW NMI 1 #599 599000000 138 99.99997 3 3 4 74 2 #599 599000000 85 99.99998 3 3 4 75 3 #599 599000000 86 99.99998 4 3 6 75 4 #599 599000000 81 99.99998 4 4 2 75 5 #599 599000000 85 99.99998 2 2 2 75 Link: https://lkml.kernel.org/r/2d6f49a6f3a4f8b51b2c806458b1cff71ad4d014.1675805361.git.bristot@kernel.org Signed-off-by: Daniel Bristot de Oliveira <bristot@kernel.org> Cc: Daniel Bristot de Oliveira <bristot@kernel.org> Cc: Juri Lelli <juri.lelli@redhat.com> Cc: Clark Williams <williams@redhat.com> Cc: Bagas Sanjaya <bagasdotme@gmail.com> Cc: Jonathan Corbet <corbet@lwn.net> Signed-off-by: Steven Rostedt (Google) <rostedt@goodmis.org> 
The hwnoise tool is a special mode for the osnoise top tool.

hwnoise dispatches the osnoise tracer and displays a summary of the noise.
The difference is that it runs the tracer with the OSNOISE_IRQ_DISABLE
option set, thus only allowing only hardware-related noise, resulting in
a simplified output. hwnoise has the same features of osnoise.

An example of the tool's output:

 # rtla hwnoise -c 1-11 -T 1 -d 10m -q
                                           Hardware-related Noise
 duration:   0 00:10:00 | time is in us
 CPU Period       Runtime        Noise  % CPU Aval   Max Noise   Max Single          HW          NMI
   1 #599       599000000          138    99.99997           3            3           4           74
   2 #599       599000000           85    99.99998           3            3           4           75
   3 #599       599000000           86    99.99998           4            3           6           75
   4 #599       599000000           81    99.99998           4            4           2           75
   5 #599       599000000           85    99.99998           2            2           2           75

Link: https://lkml.kernel.org/r/2d6f49a6f3a4f8b51b2c806458b1cff71ad4d014.1675805361.git.bristot@kernel.org

Signed-off-by: Daniel Bristot de Oliveira <bristot@kernel.org>
Cc: Daniel Bristot de Oliveira <bristot@kernel.org>
Cc: Juri Lelli <juri.lelli@redhat.com>
Cc: Clark Williams <williams@redhat.com>
Cc: Bagas Sanjaya <bagasdotme@gmail.com>
Cc: Jonathan Corbet <corbet@lwn.net>
Signed-off-by: Steven Rostedt (Google) <rostedt@goodmis.org>
rtla/timerlat: Add auto-analysis support to timerlat top 2023-02-02T15:48:04+00:00 Daniel Bristot de Oliveira bristot@kernel.org 2023-01-31T15:38:54+00:00 5def33df84d2326ebf5f29ae9ddc702a4593c337 Currently, timerlat top displays the timerlat tracer latency results, saving the intuitive timerlat trace for the developer to analyze. This patch goes a step forward in the automaton of the scheduling latency analysis by providing a summary of the root cause of a latency higher than the passed "stop tracing" parameter if the trace stops. The output is intuitive enough for non-expert users to have a general idea of the root cause by looking at each factor's contribution percentage while keeping the technical detail in the output for more expert users to start an in dept debug or to correlate a root cause with an existing one. The terminology is in line with recent industry and academic publications to facilitate the understanding of both audiences. Here is one example of tool output: ----------------------------------------- %< ----------------------------------------------------- # taskset -c 0 timerlat -a 40 -c 1-23 -q Timer Latency 0 00:00:12 | IRQ Timer Latency (us) | Thread Timer Latency (us) CPU COUNT | cur min avg max | cur min avg max 1 #12322 | 0 0 1 15 | 10 3 9 31 2 #12322 | 3 0 1 12 | 10 3 9 23 3 #12322 | 1 0 1 21 | 8 2 8 34 4 #12322 | 1 0 1 17 | 10 2 11 33 5 #12322 | 0 0 1 12 | 8 3 8 25 6 #12322 | 1 0 1 14 | 16 3 11 35 7 #12322 | 0 0 1 14 | 9 2 8 29 8 #12322 | 1 0 1 22 | 9 3 9 34 9 #12322 | 0 0 1 14 | 8 2 8 24 10 #12322 | 1 0 0 12 | 9 3 8 24 11 #12322 | 0 0 0 15 | 6 2 7 29 12 #12321 | 1 0 0 13 | 5 3 8 23 13 #12319 | 0 0 1 14 | 9 3 9 26 14 #12321 | 1 0 0 13 | 6 2 8 24 15 #12321 | 1 0 1 15 | 12 3 11 27 16 #12318 | 0 0 1 13 | 7 3 10 24 17 #12319 | 0 0 1 13 | 11 3 9 25 18 #12318 | 0 0 0 12 | 8 2 8 20 19 #12319 | 0 0 1 18 | 10 2 9 28 20 #12317 | 0 0 0 20 | 9 3 8 34 21 #12318 | 0 0 0 13 | 8 3 8 28 22 #12319 | 0 0 1 11 | 8 3 10 22 23 #12320 | 28 0 1 28 | 41 3 11 41 rtla timerlat hit stop tracing ## CPU 23 hit stop tracing, analyzing it ## IRQ handler delay: 27.49 us (65.52 %) IRQ latency: 28.13 us Timerlat IRQ duration: 9.59 us (22.85 %) Blocking thread: 3.79 us (9.03 %) objtool:49256 3.79 us Blocking thread stacktrace -> timerlat_irq -> __hrtimer_run_queues -> hrtimer_interrupt -> __sysvec_apic_timer_interrupt -> sysvec_apic_timer_interrupt -> asm_sysvec_apic_timer_interrupt -> _raw_spin_unlock_irqrestore -> cgroup_rstat_flush_locked -> cgroup_rstat_flush_irqsafe -> mem_cgroup_flush_stats -> mem_cgroup_wb_stats -> balance_dirty_pages -> balance_dirty_pages_ratelimited_flags -> btrfs_buffered_write -> btrfs_do_write_iter -> vfs_write -> __x64_sys_pwrite64 -> do_syscall_64 -> entry_SYSCALL_64_after_hwframe ------------------------------------------------------------------------ Thread latency: 41.96 us (100%) The system has exit from idle latency! Max timerlat IRQ latency from idle: 17.48 us in cpu 4 Saving trace to timerlat_trace.txt ----------------------------------------- >% ----------------------------------------------------- In this case, the major factor was the delay suffered by the IRQ handler that handles timerlat wakeup: 65.52 %. This can be caused by the current thread masking interrupts, which can be seen in the blocking thread stacktrace: the current thread (objtool:49256) disabled interrupts via raw spin lock operations inside mem cgroup, while doing write syscall in a btrfs file system. A simple search for the function name on Google shows that this is a legit case for disabling the interrupts: cgroup: Use irqsave in cgroup_rstat_flush_locked() lore.kernel.org/linux-mm/20220301122143.1521823-2-bigeasy@linutronix.de/ The output also prints other reasons for the latency root cause, such as: - an IRQ that happened before the IRQ handler that caused delays - The interference from NMI, IRQ, Softirq, and Threads The details about how these factors affect the scheduling latency can be found here: https://bristot.me/demystifying-the-real-time-linux-latency/ Link: https://lkml.kernel.org/r/3d45f40e630317f51ac6d678e2d96d310e495729.1675179318.git.bristot@kernel.org Cc: Daniel Bristot de Oliveira <bristot@kernel.org> Cc: Jonathan Corbet <corbet@lwn.net> Signed-off-by: Daniel Bristot de Oliveira <bristot@kernel.org> Signed-off-by: Steven Rostedt (Google) <rostedt@goodmis.org> 
Currently, timerlat top displays the timerlat tracer latency results, saving
the intuitive timerlat trace for the developer to analyze.

This patch goes a step forward in the automaton of the scheduling latency
analysis by providing a summary of the root cause of a latency higher than
the passed "stop tracing" parameter if the trace stops.

The output is intuitive enough for non-expert users to have a general idea
of the root cause by looking at each factor's contribution percentage while
keeping the technical detail in the output for more expert users to start
an in dept debug or to correlate a root cause with an existing one.

The terminology is in line with recent industry and academic publications
to facilitate the understanding of both audiences.

Here is one example of tool output:
 ----------------------------------------- %< -----------------------------------------------------
  # taskset -c 0 timerlat -a 40 -c 1-23 -q
                                     Timer Latency
    0 00:00:12   |          IRQ Timer Latency (us)        |         Thread Timer Latency (us)
  CPU COUNT      |      cur       min       avg       max |      cur       min       avg       max
    1 #12322     |        0         0         1        15 |       10         3         9        31
    2 #12322     |        3         0         1        12 |       10         3         9        23
    3 #12322     |        1         0         1        21 |        8         2         8        34
    4 #12322     |        1         0         1        17 |       10         2        11        33
    5 #12322     |        0         0         1        12 |        8         3         8        25
    6 #12322     |        1         0         1        14 |       16         3        11        35
    7 #12322     |        0         0         1        14 |        9         2         8        29
    8 #12322     |        1         0         1        22 |        9         3         9        34
    9 #12322     |        0         0         1        14 |        8         2         8        24
   10 #12322     |        1         0         0        12 |        9         3         8        24
   11 #12322     |        0         0         0        15 |        6         2         7        29
   12 #12321     |        1         0         0        13 |        5         3         8        23
   13 #12319     |        0         0         1        14 |        9         3         9        26
   14 #12321     |        1         0         0        13 |        6         2         8        24
   15 #12321     |        1         0         1        15 |       12         3        11        27
   16 #12318     |        0         0         1        13 |        7         3        10        24
   17 #12319     |        0         0         1        13 |       11         3         9        25
   18 #12318     |        0         0         0        12 |        8         2         8        20
   19 #12319     |        0         0         1        18 |       10         2         9        28
   20 #12317     |        0         0         0        20 |        9         3         8        34
   21 #12318     |        0         0         0        13 |        8         3         8        28
   22 #12319     |        0         0         1        11 |        8         3        10        22
   23 #12320     |       28         0         1        28 |       41         3        11        41
  rtla timerlat hit stop tracing
  ## CPU 23 hit stop tracing, analyzing it ##
  IRQ handler delay:				      	    27.49 us (65.52 %)
  IRQ latency:						    28.13 us
  Timerlat IRQ duration:				     9.59 us (22.85 %)
  Blocking thread:					     3.79 us (9.03 %)
			objtool:49256    		     3.79 us
    Blocking thread stacktrace
		-> timerlat_irq
		-> __hrtimer_run_queues
		-> hrtimer_interrupt
		-> __sysvec_apic_timer_interrupt
		-> sysvec_apic_timer_interrupt
		-> asm_sysvec_apic_timer_interrupt
		-> _raw_spin_unlock_irqrestore
		-> cgroup_rstat_flush_locked
		-> cgroup_rstat_flush_irqsafe
		-> mem_cgroup_flush_stats
		-> mem_cgroup_wb_stats
		-> balance_dirty_pages
		-> balance_dirty_pages_ratelimited_flags
		-> btrfs_buffered_write
		-> btrfs_do_write_iter
		-> vfs_write
		-> __x64_sys_pwrite64
		-> do_syscall_64
		-> entry_SYSCALL_64_after_hwframe
  ------------------------------------------------------------------------
    Thread latency:					    41.96 us (100%)

  The system has exit from idle latency!
    Max timerlat IRQ latency from idle: 17.48 us in cpu 4
  Saving trace to timerlat_trace.txt
 ----------------------------------------- >% -----------------------------------------------------

In this case, the major factor was the delay suffered by the IRQ handler
that handles timerlat wakeup: 65.52 %. This can be caused by the
current thread masking interrupts, which can be seen in the blocking
thread stacktrace: the current thread (objtool:49256) disabled interrupts
via raw spin lock operations inside mem cgroup, while doing write
syscall in a btrfs file system.

A simple search for the function name on Google shows that this is
a legit case for disabling the interrupts:

  cgroup: Use irqsave in cgroup_rstat_flush_locked()
  lore.kernel.org/linux-mm/20220301122143.1521823-2-bigeasy@linutronix.de/

The output also prints other reasons for the latency root cause, such as:

  - an IRQ that happened before the IRQ handler that caused delays
  - The interference from NMI, IRQ, Softirq, and Threads

The details about how these factors affect the scheduling latency
can be found here:

   https://bristot.me/demystifying-the-real-time-linux-latency/

Link: https://lkml.kernel.org/r/3d45f40e630317f51ac6d678e2d96d310e495729.1675179318.git.bristot@kernel.org

Cc: Daniel Bristot de Oliveira <bristot@kernel.org>
Cc: Jonathan Corbet <corbet@lwn.net>
Signed-off-by: Daniel Bristot de Oliveira <bristot@kernel.org>
Signed-off-by: Steven Rostedt (Google) <rostedt@goodmis.org>
rtla/timerlat: Add auto-analysis core 2023-02-02T15:48:03+00:00 Daniel Bristot de Oliveira bristot@kernel.org 2023-01-31T15:38:53+00:00 27e348b221f6a78cbe86e7def8e2611f84509211 Currently, timerlat displays a summary of the timerlat tracer results saving the trace if the system hits a stop condition. While this represented a huge step forward, the root cause was not that is accessible to non-expert users. The auto-analysis fulfill this gap by parsing the trace timerlat runs, printing an intuitive auto-analysis. Link: https://lkml.kernel.org/r/1ee073822f6a2cbb33da0c817331d0d4045e837f.1675179318.git.bristot@kernel.org Cc: Daniel Bristot de Oliveira <bristot@kernel.org> Cc: Jonathan Corbet <corbet@lwn.net> Signed-off-by: Daniel Bristot de Oliveira <bristot@kernel.org> Signed-off-by: Steven Rostedt (Google) <rostedt@goodmis.org> 
Currently, timerlat displays a summary of the timerlat tracer results
saving the trace if the system hits a stop condition.

While this represented a huge step forward, the root cause was not
that is accessible to non-expert users.

The auto-analysis fulfill this gap by parsing the trace timerlat runs,
printing an intuitive auto-analysis.

Link: https://lkml.kernel.org/r/1ee073822f6a2cbb33da0c817331d0d4045e837f.1675179318.git.bristot@kernel.org

Cc: Daniel Bristot de Oliveira <bristot@kernel.org>
Cc: Jonathan Corbet <corbet@lwn.net>
Signed-off-by: Daniel Bristot de Oliveira <bristot@kernel.org>
Signed-off-by: Steven Rostedt (Google) <rostedt@goodmis.org>
tools/tracing/rtla: osnoise_hist: display average with two-digit precision 2023-02-01T00:23:36+00:00 Andreas Ziegler br015@umbiko.net 2023-01-03T10:34:00+00:00 1fab1469b66baf7847298b205e5c4aff47c2ae8a Calculate average value in osnoise-hist summary with two-digit precision to avoid displaying too optimitic results. Link: https://lkml.kernel.org/r/20230103103400.275566-3-br015@umbiko.net Signed-off-by: Andreas Ziegler <br015@umbiko.net> Acked-by: Daniel Bristot de Oliveira <bristot@kernel.org> Signed-off-by: Steven Rostedt (Google) <rostedt@goodmis.org> 
Calculate average value in osnoise-hist summary with two-digit
precision to avoid displaying too optimitic results.

Link: https://lkml.kernel.org/r/20230103103400.275566-3-br015@umbiko.net

Signed-off-by: Andreas Ziegler <br015@umbiko.net>
Acked-by: Daniel Bristot de Oliveira <bristot@kernel.org>
Signed-off-by: Steven Rostedt (Google) <rostedt@goodmis.org>
tools/tracing/rtla: osnoise_hist: use total duration for average calculation 2023-02-01T00:23:36+00:00 Andreas Ziegler br015@umbiko.net 2023-01-03T10:33:59+00:00 fe137a4fe0e77eb95396cfc5c3dd7df404421aa4 Sampled durations must be weighted by observed quantity, to arrive at a correct average duration value. Perform calculation of total duration by summing (duration * count). Link: https://lkml.kernel.org/r/20230103103400.275566-2-br015@umbiko.net Fixes: 829a6c0b5698 ("rtla/osnoise: Add the hist mode") Signed-off-by: Andreas Ziegler <br015@umbiko.net> Acked-by: Daniel Bristot de Oliveira <bristot@kernel.org> Signed-off-by: Steven Rostedt (Google) <rostedt@goodmis.org> 
Sampled durations must be weighted by observed quantity, to arrive at a correct
average duration value.

Perform calculation of total duration by summing (duration * count).

Link: https://lkml.kernel.org/r/20230103103400.275566-2-br015@umbiko.net

Fixes: 829a6c0b5698 ("rtla/osnoise: Add the hist mode")

Signed-off-by: Andreas Ziegler <br015@umbiko.net>
Acked-by: Daniel Bristot de Oliveira <bristot@kernel.org>
Signed-off-by: Steven Rostedt (Google) <rostedt@goodmis.org>
rtla: Fix exit status when returning from calls to usage() 2022-12-09T23:06:24+00:00 John Kacur jkacur@redhat.com 2022-11-07T14:43:13+00:00 4c6874374859d89aa6a75019bb0a913369e472c9 rtla_usage(), osnoise_usage() and timerlat_usage() all exit with an error status. However when these are called from help, they should exit with a non-error status. Fix this by passing the exit status to the functions. Note, although we remove the subsequent call to exit after calling usage, we leave it in at the end of a function to suppress the compiler warning "control reaches end of a non-void function". Link: https://lkml.kernel.org/r/20221107144313.22470-1-jkacur@redhat.com Signed-off-by: John Kacur <jkacur@redhat.com> Acked-by: Daniel Bristot de Oliveira <bristot@kernel.org> Signed-off-by: Steven Rostedt (Google) <rostedt@goodmis.org> 
rtla_usage(), osnoise_usage() and timerlat_usage() all exit with an
error status.

However when these are called from help, they should exit with a
non-error status.

Fix this by passing the exit status to the functions.

Note, although we remove the subsequent call to exit after calling
usage, we leave it in at the end of a function to suppress the compiler
warning "control reaches end of a non-void function".

Link: https://lkml.kernel.org/r/20221107144313.22470-1-jkacur@redhat.com

Signed-off-by: John Kacur <jkacur@redhat.com>
Acked-by: Daniel Bristot de Oliveira <bristot@kernel.org>
Signed-off-by: Steven Rostedt (Google) <rostedt@goodmis.org>
rtla: Consolidate and show all necessary libraries that failed for building 2022-08-10T16:03:02+00:00 Steven Rostedt (Google) rostedt@goodmis.org 2022-08-10T15:39:18+00:00 20aec89aac7761e3c096004f5c819aacc86fc542 When building rtla tools, if the necessary libraries are not installed (libtraceevent and libtracefs), show the ones that are missing in one consolidated output, and also show how to install them (at least for Fedora). Link: https://lore.kernel.org/all/CAHk-=wh+e1qcCnEYJ3JRDVLNCYbJ=0u+Ts5bOYZnY3mX_k-hFA@mail.gmail.com/ Link: https://lkml.kernel.org/r/20220810113918.5d19ce59@gandalf.local.home Suggested-by: Linus Torvalds <torvalds@linux-foundation.org> Signed-off-by: Steven Rostedt (Google) <rostedt@goodmis.org> 
When building rtla tools, if the necessary libraries are not installed
(libtraceevent and libtracefs), show the ones that are missing in one
consolidated output, and also show how to install them (at least for
Fedora).

Link: https://lore.kernel.org/all/CAHk-=wh+e1qcCnEYJ3JRDVLNCYbJ=0u+Ts5bOYZnY3mX_k-hFA@mail.gmail.com/
Link: https://lkml.kernel.org/r/20220810113918.5d19ce59@gandalf.local.home

Suggested-by: Linus Torvalds <torvalds@linux-foundation.org>
Signed-off-by: Steven Rostedt (Google) <rostedt@goodmis.org>
tools/rtla: Build with EXTRA_{C,LD}FLAGS 2022-08-10T15:46:28+00:00 Ben Hutchings benh@debian.org 2022-07-16T13:48:34+00:00 1a7b22ab15ebf643e10e54ae5387afee06e39ad0 To allow for distributions and other builders to apply hardening policy and other customisation, append EXTRA_CFLAGS and EXTRA_LDFLAGS to the corresponding variables. Link: https://lore.kernel.org/linux-trace-devel/YtLBshz0nMQ7530H@decadent.org.uk Signed-off-by: Ben Hutchings <benh@debian.org> Acked-by: Daniel Bristot de Oliveira <bristot@kernel.org> Signed-off-by: Steven Rostedt (Google) <rostedt@goodmis.org> 
To allow for distributions and other builders to apply hardening
policy and other customisation, append EXTRA_CFLAGS and EXTRA_LDFLAGS
to the corresponding variables.

Link: https://lore.kernel.org/linux-trace-devel/YtLBshz0nMQ7530H@decadent.org.uk

Signed-off-by: Ben Hutchings <benh@debian.org>
Acked-by: Daniel Bristot de Oliveira <bristot@kernel.org>
Signed-off-by: Steven Rostedt (Google) <rostedt@goodmis.org>
tools/rtla: Fix command symlinks 2022-08-10T15:45:59+00:00 Ben Hutchings benh@debian.org 2022-07-16T13:47:08+00:00 ff5a55dcdb343e3db9b9fb08795b78544b032773 "ln -s" stores the next argument directly as the symlink target, so it needs to be a relative path. In this case, just "rtla". Link: https://lore.kernel.org/linux-trace-devel/YtLBXMI6Ui4HLIF1@decadent.org.uk Fixes: 0605bf009f18 ("rtla: Add osnoise tool") Fixes: a828cd18bc4a ("rtla: Add timerlat tool and timelart top mode") Signed-off-by: Ben Hutchings <benh@debian.org> Acked-by: Daniel Bristot de Oliveira <bristot@kernel.org> Signed-off-by: Steven Rostedt (Google) <rostedt@goodmis.org> 
"ln -s" stores the next argument directly as the symlink target, so
it needs to be a relative path.  In this case, just "rtla".

Link: https://lore.kernel.org/linux-trace-devel/YtLBXMI6Ui4HLIF1@decadent.org.uk

Fixes: 0605bf009f18 ("rtla: Add osnoise tool")
Fixes: a828cd18bc4a ("rtla: Add timerlat tool and timelart top mode")
Signed-off-by: Ben Hutchings <benh@debian.org>
Acked-by: Daniel Bristot de Oliveira <bristot@kernel.org>
Signed-off-by: Steven Rostedt (Google) <rostedt@goodmis.org>
rtla: Fix tracer name 2022-08-10T15:43:59+00:00 Alexandre Vicenzi alexandre.vicenzi@suse.com 2022-08-08T18:03:43+00:00 f1432cd24c240cedf78c0d026631e3b10052c8e1 The correct tracer name is timerlat and not timelat. Link: https://lore.kernel.org/linux-trace-devel/20220808180343.22262-1-alexandre.vicenzi@suse.com Signed-off-by: Alexandre Vicenzi <alexandre.vicenzi@suse.com> Signed-off-by: Steven Rostedt (Google) <rostedt@goodmis.org> 
The correct tracer name is timerlat and not timelat.

Link: https://lore.kernel.org/linux-trace-devel/20220808180343.22262-1-alexandre.vicenzi@suse.com

Signed-off-by: Alexandre Vicenzi <alexandre.vicenzi@suse.com>
Signed-off-by: Steven Rostedt (Google) <rostedt@goodmis.org>