2021-12-10 18:11:25 +00:00
|
|
|
// SPDX-License-Identifier: GPL-2.0
|
|
|
|
/*
|
|
|
|
* Copyright (C) 2021 Red Hat Inc, Daniel Bristot de Oliveira <bristot@kernel.org>
|
|
|
|
*/
|
|
|
|
|
|
|
|
#include <getopt.h>
|
|
|
|
#include <stdlib.h>
|
|
|
|
#include <string.h>
|
|
|
|
#include <signal.h>
|
|
|
|
#include <unistd.h>
|
|
|
|
#include <stdio.h>
|
|
|
|
#include <time.h>
|
rtla/timerlat: Add auto-analysis support to timerlat top
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>
2023-01-31 15:38:54 +00:00
|
|
|
#include <errno.h>
|
2021-12-10 18:11:25 +00:00
|
|
|
|
|
|
|
#include "utils.h"
|
|
|
|
#include "osnoise.h"
|
|
|
|
#include "timerlat.h"
|
rtla/timerlat: Add auto-analysis support to timerlat top
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>
2023-01-31 15:38:54 +00:00
|
|
|
#include "timerlat_aa.h"
|
2021-12-10 18:11:25 +00:00
|
|
|
|
|
|
|
struct timerlat_top_params {
|
|
|
|
char *cpus;
|
|
|
|
char *monitored_cpus;
|
|
|
|
char *trace_output;
|
|
|
|
unsigned long long runtime;
|
|
|
|
long long stop_us;
|
|
|
|
long long stop_total_us;
|
|
|
|
long long timerlat_period_us;
|
|
|
|
long long print_stack;
|
|
|
|
int sleep_time;
|
|
|
|
int output_divisor;
|
|
|
|
int duration;
|
|
|
|
int quiet;
|
|
|
|
int set_sched;
|
2022-03-02 19:01:39 +00:00
|
|
|
int dma_latency;
|
rtla/timerlat: Add auto-analysis support to timerlat top
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>
2023-01-31 15:38:54 +00:00
|
|
|
int no_aa;
|
2023-03-29 16:23:32 +00:00
|
|
|
int aa_only;
|
rtla/timerlat: Add auto-analysis support to timerlat top
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>
2023-01-31 15:38:54 +00:00
|
|
|
int dump_tasks;
|
2021-12-10 18:11:25 +00:00
|
|
|
struct sched_attr sched_param;
|
2022-03-02 19:01:31 +00:00
|
|
|
struct trace_events *events;
|
2021-12-10 18:11:25 +00:00
|
|
|
};
|
|
|
|
|
|
|
|
struct timerlat_top_cpu {
|
|
|
|
int irq_count;
|
|
|
|
int thread_count;
|
|
|
|
|
|
|
|
unsigned long long cur_irq;
|
|
|
|
unsigned long long min_irq;
|
|
|
|
unsigned long long sum_irq;
|
|
|
|
unsigned long long max_irq;
|
|
|
|
|
|
|
|
unsigned long long cur_thread;
|
|
|
|
unsigned long long min_thread;
|
|
|
|
unsigned long long sum_thread;
|
|
|
|
unsigned long long max_thread;
|
|
|
|
};
|
|
|
|
|
|
|
|
struct timerlat_top_data {
|
|
|
|
struct timerlat_top_cpu *cpu_data;
|
|
|
|
int nr_cpus;
|
|
|
|
};
|
|
|
|
|
|
|
|
/*
|
|
|
|
* timerlat_free_top - free runtime data
|
|
|
|
*/
|
|
|
|
static void
|
|
|
|
timerlat_free_top(struct timerlat_top_data *data)
|
|
|
|
{
|
|
|
|
free(data->cpu_data);
|
|
|
|
free(data);
|
|
|
|
}
|
|
|
|
|
|
|
|
/*
|
|
|
|
* timerlat_alloc_histogram - alloc runtime data
|
|
|
|
*/
|
|
|
|
static struct timerlat_top_data *timerlat_alloc_top(int nr_cpus)
|
|
|
|
{
|
|
|
|
struct timerlat_top_data *data;
|
|
|
|
int cpu;
|
|
|
|
|
|
|
|
data = calloc(1, sizeof(*data));
|
|
|
|
if (!data)
|
|
|
|
return NULL;
|
|
|
|
|
|
|
|
data->nr_cpus = nr_cpus;
|
|
|
|
|
|
|
|
/* one set of histograms per CPU */
|
|
|
|
data->cpu_data = calloc(1, sizeof(*data->cpu_data) * nr_cpus);
|
|
|
|
if (!data->cpu_data)
|
|
|
|
goto cleanup;
|
|
|
|
|
|
|
|
/* set the min to max */
|
|
|
|
for (cpu = 0; cpu < nr_cpus; cpu++) {
|
|
|
|
data->cpu_data[cpu].min_irq = ~0;
|
|
|
|
data->cpu_data[cpu].min_thread = ~0;
|
|
|
|
}
|
|
|
|
|
|
|
|
return data;
|
|
|
|
|
|
|
|
cleanup:
|
|
|
|
timerlat_free_top(data);
|
|
|
|
return NULL;
|
|
|
|
}
|
|
|
|
|
|
|
|
/*
|
|
|
|
* timerlat_hist_update - record a new timerlat occurent on cpu, updating data
|
|
|
|
*/
|
|
|
|
static void
|
|
|
|
timerlat_top_update(struct osnoise_tool *tool, int cpu,
|
|
|
|
unsigned long long thread,
|
|
|
|
unsigned long long latency)
|
|
|
|
{
|
|
|
|
struct timerlat_top_data *data = tool->data;
|
|
|
|
struct timerlat_top_cpu *cpu_data = &data->cpu_data[cpu];
|
|
|
|
|
|
|
|
if (!thread) {
|
|
|
|
cpu_data->irq_count++;
|
|
|
|
cpu_data->cur_irq = latency;
|
|
|
|
update_min(&cpu_data->min_irq, &latency);
|
|
|
|
update_sum(&cpu_data->sum_irq, &latency);
|
|
|
|
update_max(&cpu_data->max_irq, &latency);
|
|
|
|
} else {
|
|
|
|
cpu_data->thread_count++;
|
|
|
|
cpu_data->cur_thread = latency;
|
|
|
|
update_min(&cpu_data->min_thread, &latency);
|
|
|
|
update_sum(&cpu_data->sum_thread, &latency);
|
|
|
|
update_max(&cpu_data->max_thread, &latency);
|
|
|
|
}
|
|
|
|
}
|
|
|
|
|
|
|
|
/*
|
|
|
|
* timerlat_top_handler - this is the handler for timerlat tracer events
|
|
|
|
*/
|
|
|
|
static int
|
|
|
|
timerlat_top_handler(struct trace_seq *s, struct tep_record *record,
|
|
|
|
struct tep_event *event, void *context)
|
|
|
|
{
|
|
|
|
struct trace_instance *trace = context;
|
rtla/timerlat: Add auto-analysis support to timerlat top
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>
2023-01-31 15:38:54 +00:00
|
|
|
struct timerlat_top_params *params;
|
2021-12-10 18:11:25 +00:00
|
|
|
unsigned long long latency, thread;
|
|
|
|
struct osnoise_tool *top;
|
|
|
|
int cpu = record->cpu;
|
|
|
|
|
|
|
|
top = container_of(trace, struct osnoise_tool, trace);
|
rtla/timerlat: Add auto-analysis support to timerlat top
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>
2023-01-31 15:38:54 +00:00
|
|
|
params = top->params;
|
2021-12-10 18:11:25 +00:00
|
|
|
|
2023-03-29 16:23:32 +00:00
|
|
|
if (!params->aa_only) {
|
|
|
|
tep_get_field_val(s, event, "context", record, &thread, 1);
|
|
|
|
tep_get_field_val(s, event, "timer_latency", record, &latency, 1);
|
2021-12-10 18:11:25 +00:00
|
|
|
|
2023-03-29 16:23:32 +00:00
|
|
|
timerlat_top_update(top, cpu, thread, latency);
|
|
|
|
}
|
2021-12-10 18:11:25 +00:00
|
|
|
|
rtla/timerlat: Add auto-analysis support to timerlat top
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>
2023-01-31 15:38:54 +00:00
|
|
|
if (!params->no_aa)
|
|
|
|
timerlat_aa_handler(s, record, event, context);
|
|
|
|
|
2021-12-10 18:11:25 +00:00
|
|
|
return 0;
|
|
|
|
}
|
|
|
|
|
|
|
|
/*
|
|
|
|
* timerlat_top_header - print the header of the tool output
|
|
|
|
*/
|
|
|
|
static void timerlat_top_header(struct osnoise_tool *top)
|
|
|
|
{
|
|
|
|
struct timerlat_top_params *params = top->params;
|
|
|
|
struct trace_seq *s = top->trace.seq;
|
|
|
|
char duration[26];
|
|
|
|
|
|
|
|
get_duration(top->start_time, duration, sizeof(duration));
|
|
|
|
|
|
|
|
trace_seq_printf(s, "\033[2;37;40m");
|
|
|
|
trace_seq_printf(s, " Timer Latency ");
|
|
|
|
trace_seq_printf(s, "\033[0;0;0m");
|
|
|
|
trace_seq_printf(s, "\n");
|
|
|
|
|
|
|
|
trace_seq_printf(s, "%-6s | IRQ Timer Latency (%s) | Thread Timer Latency (%s)\n", duration,
|
|
|
|
params->output_divisor == 1 ? "ns" : "us",
|
|
|
|
params->output_divisor == 1 ? "ns" : "us");
|
|
|
|
|
|
|
|
trace_seq_printf(s, "\033[2;30;47m");
|
|
|
|
trace_seq_printf(s, "CPU COUNT | cur min avg max | cur min avg max");
|
|
|
|
trace_seq_printf(s, "\033[0;0;0m");
|
|
|
|
trace_seq_printf(s, "\n");
|
|
|
|
}
|
|
|
|
|
|
|
|
/*
|
|
|
|
* timerlat_top_print - prints the output of a given CPU
|
|
|
|
*/
|
|
|
|
static void timerlat_top_print(struct osnoise_tool *top, int cpu)
|
|
|
|
{
|
|
|
|
|
|
|
|
struct timerlat_top_params *params = top->params;
|
|
|
|
struct timerlat_top_data *data = top->data;
|
|
|
|
struct timerlat_top_cpu *cpu_data = &data->cpu_data[cpu];
|
|
|
|
int divisor = params->output_divisor;
|
|
|
|
struct trace_seq *s = top->trace.seq;
|
|
|
|
|
|
|
|
if (divisor == 0)
|
|
|
|
return;
|
|
|
|
|
|
|
|
/*
|
|
|
|
* Skip if no data is available: is this cpu offline?
|
|
|
|
*/
|
|
|
|
if (!cpu_data->irq_count && !cpu_data->thread_count)
|
|
|
|
return;
|
|
|
|
|
|
|
|
/*
|
|
|
|
* Unless trace is being lost, IRQ counter is always the max.
|
|
|
|
*/
|
|
|
|
trace_seq_printf(s, "%3d #%-9d |", cpu, cpu_data->irq_count);
|
|
|
|
|
|
|
|
if (!cpu_data->irq_count) {
|
|
|
|
trace_seq_printf(s, " - ");
|
|
|
|
trace_seq_printf(s, " - ");
|
|
|
|
trace_seq_printf(s, " - ");
|
|
|
|
trace_seq_printf(s, " - |");
|
|
|
|
} else {
|
|
|
|
trace_seq_printf(s, "%9llu ", cpu_data->cur_irq / params->output_divisor);
|
|
|
|
trace_seq_printf(s, "%9llu ", cpu_data->min_irq / params->output_divisor);
|
|
|
|
trace_seq_printf(s, "%9llu ", (cpu_data->sum_irq / cpu_data->irq_count) / divisor);
|
|
|
|
trace_seq_printf(s, "%9llu |", cpu_data->max_irq / divisor);
|
|
|
|
}
|
|
|
|
|
|
|
|
if (!cpu_data->thread_count) {
|
|
|
|
trace_seq_printf(s, " - ");
|
|
|
|
trace_seq_printf(s, " - ");
|
|
|
|
trace_seq_printf(s, " - ");
|
|
|
|
trace_seq_printf(s, " -\n");
|
|
|
|
} else {
|
|
|
|
trace_seq_printf(s, "%9llu ", cpu_data->cur_thread / divisor);
|
|
|
|
trace_seq_printf(s, "%9llu ", cpu_data->min_thread / divisor);
|
|
|
|
trace_seq_printf(s, "%9llu ",
|
|
|
|
(cpu_data->sum_thread / cpu_data->thread_count) / divisor);
|
|
|
|
trace_seq_printf(s, "%9llu\n", cpu_data->max_thread / divisor);
|
|
|
|
}
|
|
|
|
}
|
|
|
|
|
|
|
|
/*
|
|
|
|
* clear_terminal - clears the output terminal
|
|
|
|
*/
|
|
|
|
static void clear_terminal(struct trace_seq *seq)
|
|
|
|
{
|
|
|
|
if (!config_debug)
|
|
|
|
trace_seq_printf(seq, "\033c");
|
|
|
|
}
|
|
|
|
|
|
|
|
/*
|
|
|
|
* timerlat_print_stats - print data for all cpus
|
|
|
|
*/
|
|
|
|
static void
|
|
|
|
timerlat_print_stats(struct timerlat_top_params *params, struct osnoise_tool *top)
|
|
|
|
{
|
|
|
|
struct trace_instance *trace = &top->trace;
|
|
|
|
static int nr_cpus = -1;
|
|
|
|
int i;
|
|
|
|
|
2023-03-29 16:23:32 +00:00
|
|
|
if (params->aa_only)
|
|
|
|
return;
|
|
|
|
|
2021-12-10 18:11:25 +00:00
|
|
|
if (nr_cpus == -1)
|
|
|
|
nr_cpus = sysconf(_SC_NPROCESSORS_CONF);
|
|
|
|
|
|
|
|
if (!params->quiet)
|
|
|
|
clear_terminal(trace->seq);
|
|
|
|
|
|
|
|
timerlat_top_header(top);
|
|
|
|
|
|
|
|
for (i = 0; i < nr_cpus; i++) {
|
|
|
|
if (params->cpus && !params->monitored_cpus[i])
|
|
|
|
continue;
|
|
|
|
timerlat_top_print(top, i);
|
|
|
|
}
|
|
|
|
|
|
|
|
trace_seq_do_printf(trace->seq);
|
|
|
|
trace_seq_reset(trace->seq);
|
|
|
|
}
|
|
|
|
|
|
|
|
/*
|
|
|
|
* timerlat_top_usage - prints timerlat top usage message
|
|
|
|
*/
|
|
|
|
static void timerlat_top_usage(char *usage)
|
|
|
|
{
|
|
|
|
int i;
|
|
|
|
|
|
|
|
static const char *const msg[] = {
|
|
|
|
"",
|
2022-03-02 19:01:29 +00:00
|
|
|
" usage: rtla timerlat [top] [-h] [-q] [-a us] [-d s] [-D] [-n] [-p us] [-i us] [-T us] [-s us] \\",
|
2022-03-02 19:01:35 +00:00
|
|
|
" [[-t[=file]] [-e sys[:event]] [--filter <filter>] [--trigger <trigger>] [-c cpu-list] \\",
|
2023-03-29 16:23:32 +00:00
|
|
|
" [-P priority] [--dma-latency us] [--aa-only us]",
|
2021-12-10 18:11:25 +00:00
|
|
|
"",
|
|
|
|
" -h/--help: print this menu",
|
2022-03-02 19:01:29 +00:00
|
|
|
" -a/--auto: set automatic trace mode, stopping the session if argument in us latency is hit",
|
2023-03-29 16:23:32 +00:00
|
|
|
" --aa-only us: stop if <us> latency is hit, only printing the auto analysis (reduces CPU usage)",
|
2021-12-10 18:11:25 +00:00
|
|
|
" -p/--period us: timerlat period in us",
|
|
|
|
" -i/--irq us: stop trace if the irq latency is higher than the argument in us",
|
|
|
|
" -T/--thread us: stop trace if the thread latency is higher than the argument in us",
|
|
|
|
" -s/--stack us: save the stack trace at the IRQ if a thread latency is higher than the argument in us",
|
|
|
|
" -c/--cpus cpus: run the tracer only on the given cpus",
|
|
|
|
" -d/--duration time[m|h|d]: duration of the session in seconds",
|
|
|
|
" -D/--debug: print debug info",
|
rtla/timerlat: Add auto-analysis support to timerlat top
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>
2023-01-31 15:38:54 +00:00
|
|
|
" --dump-tasks: prints the task running on all CPUs if stop conditions are met (depends on !--no-aa)",
|
2021-12-10 18:11:25 +00:00
|
|
|
" -t/--trace[=file]: save the stopped trace to [file|timerlat_trace.txt]",
|
2022-03-02 19:01:31 +00:00
|
|
|
" -e/--event <sys:event>: enable the <sys:event> in the trace instance, multiple -e are allowed",
|
2022-03-02 19:01:35 +00:00
|
|
|
" --filter <command>: enable a trace event filter to the previous -e event",
|
2022-03-02 19:01:33 +00:00
|
|
|
" --trigger <command>: enable a trace event trigger to the previous -e event",
|
2021-12-10 18:11:25 +00:00
|
|
|
" -n/--nano: display data in nanoseconds",
|
rtla/timerlat: Add auto-analysis support to timerlat top
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>
2023-01-31 15:38:54 +00:00
|
|
|
" --no-aa: disable auto-analysis, reducing rtla timerlat cpu usage",
|
2021-12-10 18:11:25 +00:00
|
|
|
" -q/--quiet print only a summary at the end",
|
2022-03-02 19:01:39 +00:00
|
|
|
" --dma-latency us: set /dev/cpu_dma_latency latency <us> to reduce exit from idle latency",
|
2021-12-10 18:11:25 +00:00
|
|
|
" -P/--priority o:prio|r:prio|f:prio|d:runtime:period : set scheduling parameters",
|
|
|
|
" o:prio - use SCHED_OTHER with prio",
|
|
|
|
" r:prio - use SCHED_RR with prio",
|
|
|
|
" f:prio - use SCHED_FIFO with prio",
|
|
|
|
" d:runtime[us|ms|s]:period[us|ms|s] - use SCHED_DEADLINE with runtime and period",
|
|
|
|
" in nanoseconds",
|
|
|
|
NULL,
|
|
|
|
};
|
|
|
|
|
|
|
|
if (usage)
|
|
|
|
fprintf(stderr, "%s\n", usage);
|
|
|
|
|
|
|
|
fprintf(stderr, "rtla timerlat top: a per-cpu summary of the timer latency (version %s)\n",
|
|
|
|
VERSION);
|
|
|
|
|
|
|
|
for (i = 0; msg[i]; i++)
|
|
|
|
fprintf(stderr, "%s\n", msg[i]);
|
|
|
|
exit(1);
|
|
|
|
}
|
|
|
|
|
|
|
|
/*
|
|
|
|
* timerlat_top_parse_args - allocs, parse and fill the cmd line parameters
|
|
|
|
*/
|
|
|
|
static struct timerlat_top_params
|
|
|
|
*timerlat_top_parse_args(int argc, char **argv)
|
|
|
|
{
|
|
|
|
struct timerlat_top_params *params;
|
2022-03-02 19:01:31 +00:00
|
|
|
struct trace_events *tevent;
|
2022-03-02 19:01:29 +00:00
|
|
|
long long auto_thresh;
|
2021-12-10 18:11:25 +00:00
|
|
|
int retval;
|
|
|
|
int c;
|
|
|
|
|
|
|
|
params = calloc(1, sizeof(*params));
|
|
|
|
if (!params)
|
|
|
|
exit(1);
|
|
|
|
|
2022-03-02 19:01:39 +00:00
|
|
|
/* disabled by default */
|
|
|
|
params->dma_latency = -1;
|
|
|
|
|
2021-12-10 18:11:25 +00:00
|
|
|
/* display data in microseconds */
|
|
|
|
params->output_divisor = 1000;
|
|
|
|
|
|
|
|
while (1) {
|
|
|
|
static struct option long_options[] = {
|
2022-03-02 19:01:29 +00:00
|
|
|
{"auto", required_argument, 0, 'a'},
|
2021-12-10 18:11:25 +00:00
|
|
|
{"cpus", required_argument, 0, 'c'},
|
|
|
|
{"debug", no_argument, 0, 'D'},
|
|
|
|
{"duration", required_argument, 0, 'd'},
|
2022-03-02 19:01:31 +00:00
|
|
|
{"event", required_argument, 0, 'e'},
|
2021-12-10 18:11:25 +00:00
|
|
|
{"help", no_argument, 0, 'h'},
|
|
|
|
{"irq", required_argument, 0, 'i'},
|
|
|
|
{"nano", no_argument, 0, 'n'},
|
|
|
|
{"period", required_argument, 0, 'p'},
|
|
|
|
{"priority", required_argument, 0, 'P'},
|
|
|
|
{"quiet", no_argument, 0, 'q'},
|
|
|
|
{"stack", required_argument, 0, 's'},
|
|
|
|
{"thread", required_argument, 0, 'T'},
|
|
|
|
{"trace", optional_argument, 0, 't'},
|
2022-03-02 19:01:33 +00:00
|
|
|
{"trigger", required_argument, 0, '0'},
|
2022-03-02 19:01:35 +00:00
|
|
|
{"filter", required_argument, 0, '1'},
|
2022-03-02 19:01:39 +00:00
|
|
|
{"dma-latency", required_argument, 0, '2'},
|
rtla/timerlat: Add auto-analysis support to timerlat top
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>
2023-01-31 15:38:54 +00:00
|
|
|
{"no-aa", no_argument, 0, '3'},
|
|
|
|
{"dump-tasks", no_argument, 0, '4'},
|
2023-03-29 16:23:32 +00:00
|
|
|
{"aa-only", required_argument, 0, '5'},
|
2021-12-10 18:11:25 +00:00
|
|
|
{0, 0, 0, 0}
|
|
|
|
};
|
|
|
|
|
|
|
|
/* getopt_long stores the option index here. */
|
|
|
|
int option_index = 0;
|
|
|
|
|
2023-03-29 16:23:32 +00:00
|
|
|
c = getopt_long(argc, argv, "a:c:d:De:hi:np:P:qs:t::T:0:1:2:345:",
|
2021-12-10 18:11:25 +00:00
|
|
|
long_options, &option_index);
|
|
|
|
|
|
|
|
/* detect the end of the options. */
|
|
|
|
if (c == -1)
|
|
|
|
break;
|
|
|
|
|
|
|
|
switch (c) {
|
2022-03-02 19:01:29 +00:00
|
|
|
case 'a':
|
|
|
|
auto_thresh = get_llong_from_str(optarg);
|
|
|
|
|
|
|
|
/* set thread stop to auto_thresh */
|
|
|
|
params->stop_total_us = auto_thresh;
|
rtla/timerlat: Add auto-analysis support to timerlat top
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>
2023-01-31 15:38:54 +00:00
|
|
|
params->stop_us = auto_thresh;
|
2022-03-02 19:01:29 +00:00
|
|
|
|
|
|
|
/* get stack trace */
|
|
|
|
params->print_stack = auto_thresh;
|
|
|
|
|
|
|
|
/* set trace */
|
|
|
|
params->trace_output = "timerlat_trace.txt";
|
|
|
|
break;
|
2023-03-29 16:23:32 +00:00
|
|
|
case '5':
|
|
|
|
/* it is here because it is similar to -a */
|
|
|
|
auto_thresh = get_llong_from_str(optarg);
|
|
|
|
|
|
|
|
/* set thread stop to auto_thresh */
|
|
|
|
params->stop_total_us = auto_thresh;
|
|
|
|
params->stop_us = auto_thresh;
|
|
|
|
|
|
|
|
/* get stack trace */
|
|
|
|
params->print_stack = auto_thresh;
|
|
|
|
|
|
|
|
/* set aa_only to avoid parsing the trace */
|
|
|
|
params->aa_only = 1;
|
|
|
|
break;
|
2021-12-10 18:11:25 +00:00
|
|
|
case 'c':
|
|
|
|
retval = parse_cpu_list(optarg, ¶ms->monitored_cpus);
|
|
|
|
if (retval)
|
|
|
|
timerlat_top_usage("\nInvalid -c cpu list\n");
|
|
|
|
params->cpus = optarg;
|
|
|
|
break;
|
|
|
|
case 'D':
|
|
|
|
config_debug = 1;
|
|
|
|
break;
|
|
|
|
case 'd':
|
|
|
|
params->duration = parse_seconds_duration(optarg);
|
|
|
|
if (!params->duration)
|
|
|
|
timerlat_top_usage("Invalid -D duration\n");
|
|
|
|
break;
|
2022-03-02 19:01:31 +00:00
|
|
|
case 'e':
|
|
|
|
tevent = trace_event_alloc(optarg);
|
|
|
|
if (!tevent) {
|
|
|
|
err_msg("Error alloc trace event");
|
|
|
|
exit(EXIT_FAILURE);
|
|
|
|
}
|
|
|
|
|
|
|
|
if (params->events)
|
|
|
|
tevent->next = params->events;
|
|
|
|
params->events = tevent;
|
|
|
|
break;
|
2021-12-10 18:11:25 +00:00
|
|
|
case 'h':
|
|
|
|
case '?':
|
|
|
|
timerlat_top_usage(NULL);
|
|
|
|
break;
|
|
|
|
case 'i':
|
|
|
|
params->stop_us = get_llong_from_str(optarg);
|
|
|
|
break;
|
|
|
|
case 'n':
|
|
|
|
params->output_divisor = 1;
|
|
|
|
break;
|
|
|
|
case 'p':
|
|
|
|
params->timerlat_period_us = get_llong_from_str(optarg);
|
|
|
|
if (params->timerlat_period_us > 1000000)
|
|
|
|
timerlat_top_usage("Period longer than 1 s\n");
|
|
|
|
break;
|
|
|
|
case 'P':
|
|
|
|
retval = parse_prio(optarg, ¶ms->sched_param);
|
|
|
|
if (retval == -1)
|
|
|
|
timerlat_top_usage("Invalid -P priority");
|
|
|
|
params->set_sched = 1;
|
|
|
|
break;
|
|
|
|
case 'q':
|
|
|
|
params->quiet = 1;
|
|
|
|
break;
|
|
|
|
case 's':
|
|
|
|
params->print_stack = get_llong_from_str(optarg);
|
|
|
|
break;
|
|
|
|
case 'T':
|
|
|
|
params->stop_total_us = get_llong_from_str(optarg);
|
|
|
|
break;
|
|
|
|
case 't':
|
|
|
|
if (optarg)
|
|
|
|
/* skip = */
|
|
|
|
params->trace_output = &optarg[1];
|
|
|
|
else
|
|
|
|
params->trace_output = "timerlat_trace.txt";
|
rtla/timerlat: Add auto-analysis support to timerlat top
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>
2023-01-31 15:38:54 +00:00
|
|
|
|
2021-12-10 18:11:25 +00:00
|
|
|
break;
|
2022-03-02 19:01:33 +00:00
|
|
|
case '0': /* trigger */
|
|
|
|
if (params->events) {
|
|
|
|
retval = trace_event_add_trigger(params->events, optarg);
|
|
|
|
if (retval) {
|
|
|
|
err_msg("Error adding trigger %s\n", optarg);
|
|
|
|
exit(EXIT_FAILURE);
|
|
|
|
}
|
|
|
|
} else {
|
|
|
|
timerlat_top_usage("--trigger requires a previous -e\n");
|
|
|
|
}
|
|
|
|
break;
|
2022-03-02 19:01:35 +00:00
|
|
|
case '1': /* filter */
|
|
|
|
if (params->events) {
|
|
|
|
retval = trace_event_add_filter(params->events, optarg);
|
|
|
|
if (retval) {
|
|
|
|
err_msg("Error adding filter %s\n", optarg);
|
|
|
|
exit(EXIT_FAILURE);
|
|
|
|
}
|
|
|
|
} else {
|
|
|
|
timerlat_top_usage("--filter requires a previous -e\n");
|
|
|
|
}
|
|
|
|
break;
|
2022-03-02 19:01:39 +00:00
|
|
|
case '2': /* dma-latency */
|
|
|
|
params->dma_latency = get_llong_from_str(optarg);
|
|
|
|
if (params->dma_latency < 0 || params->dma_latency > 10000) {
|
|
|
|
err_msg("--dma-latency needs to be >= 0 and < 10000");
|
|
|
|
exit(EXIT_FAILURE);
|
|
|
|
}
|
|
|
|
break;
|
rtla/timerlat: Add auto-analysis support to timerlat top
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>
2023-01-31 15:38:54 +00:00
|
|
|
case '3': /* no-aa */
|
|
|
|
params->no_aa = 1;
|
|
|
|
break;
|
|
|
|
case '4':
|
|
|
|
params->dump_tasks = 1;
|
|
|
|
break;
|
2021-12-10 18:11:25 +00:00
|
|
|
default:
|
|
|
|
timerlat_top_usage("Invalid option");
|
|
|
|
}
|
|
|
|
}
|
|
|
|
|
|
|
|
if (geteuid()) {
|
|
|
|
err_msg("rtla needs root permission\n");
|
|
|
|
exit(EXIT_FAILURE);
|
|
|
|
}
|
|
|
|
|
rtla/timerlat: Add auto-analysis support to timerlat top
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>
2023-01-31 15:38:54 +00:00
|
|
|
/*
|
|
|
|
* Auto analysis only happens if stop tracing, thus:
|
|
|
|
*/
|
|
|
|
if (!params->stop_us && !params->stop_total_us)
|
|
|
|
params->no_aa = 1;
|
|
|
|
|
2023-03-29 16:23:32 +00:00
|
|
|
if (params->no_aa && params->aa_only)
|
|
|
|
timerlat_top_usage("--no-aa and --aa-only are mutually exclusive!");
|
|
|
|
|
2021-12-10 18:11:25 +00:00
|
|
|
return params;
|
|
|
|
}
|
|
|
|
|
|
|
|
/*
|
|
|
|
* timerlat_top_apply_config - apply the top configs to the initialized tool
|
|
|
|
*/
|
|
|
|
static int
|
|
|
|
timerlat_top_apply_config(struct osnoise_tool *top, struct timerlat_top_params *params)
|
|
|
|
{
|
|
|
|
int retval;
|
|
|
|
|
|
|
|
if (!params->sleep_time)
|
|
|
|
params->sleep_time = 1;
|
|
|
|
|
|
|
|
if (params->cpus) {
|
|
|
|
retval = osnoise_set_cpus(top->context, params->cpus);
|
|
|
|
if (retval) {
|
|
|
|
err_msg("Failed to apply CPUs config\n");
|
|
|
|
goto out_err;
|
|
|
|
}
|
|
|
|
}
|
|
|
|
|
|
|
|
if (params->stop_us) {
|
|
|
|
retval = osnoise_set_stop_us(top->context, params->stop_us);
|
|
|
|
if (retval) {
|
|
|
|
err_msg("Failed to set stop us\n");
|
|
|
|
goto out_err;
|
|
|
|
}
|
|
|
|
}
|
|
|
|
|
|
|
|
if (params->stop_total_us) {
|
|
|
|
retval = osnoise_set_stop_total_us(top->context, params->stop_total_us);
|
|
|
|
if (retval) {
|
|
|
|
err_msg("Failed to set stop total us\n");
|
|
|
|
goto out_err;
|
|
|
|
}
|
|
|
|
}
|
|
|
|
|
|
|
|
|
|
|
|
if (params->timerlat_period_us) {
|
|
|
|
retval = osnoise_set_timerlat_period_us(top->context, params->timerlat_period_us);
|
|
|
|
if (retval) {
|
|
|
|
err_msg("Failed to set timerlat period\n");
|
|
|
|
goto out_err;
|
|
|
|
}
|
|
|
|
}
|
|
|
|
|
|
|
|
|
|
|
|
if (params->print_stack) {
|
|
|
|
retval = osnoise_set_print_stack(top->context, params->print_stack);
|
|
|
|
if (retval) {
|
|
|
|
err_msg("Failed to set print stack\n");
|
|
|
|
goto out_err;
|
|
|
|
}
|
|
|
|
}
|
|
|
|
|
|
|
|
return 0;
|
|
|
|
|
|
|
|
out_err:
|
|
|
|
return -1;
|
|
|
|
}
|
|
|
|
|
|
|
|
/*
|
|
|
|
* timerlat_init_top - initialize a timerlat top tool with parameters
|
|
|
|
*/
|
|
|
|
static struct osnoise_tool
|
|
|
|
*timerlat_init_top(struct timerlat_top_params *params)
|
|
|
|
{
|
|
|
|
struct osnoise_tool *top;
|
|
|
|
int nr_cpus;
|
rtla/timerlat: Add auto-analysis support to timerlat top
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>
2023-01-31 15:38:54 +00:00
|
|
|
int retval;
|
2021-12-10 18:11:25 +00:00
|
|
|
|
|
|
|
nr_cpus = sysconf(_SC_NPROCESSORS_CONF);
|
|
|
|
|
|
|
|
top = osnoise_init_tool("timerlat_top");
|
|
|
|
if (!top)
|
|
|
|
return NULL;
|
|
|
|
|
|
|
|
top->data = timerlat_alloc_top(nr_cpus);
|
|
|
|
if (!top->data)
|
|
|
|
goto out_err;
|
|
|
|
|
|
|
|
top->params = params;
|
|
|
|
|
|
|
|
tep_register_event_handler(top->trace.tep, -1, "ftrace", "timerlat",
|
|
|
|
timerlat_top_handler, top);
|
|
|
|
|
rtla/timerlat: Add auto-analysis support to timerlat top
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>
2023-01-31 15:38:54 +00:00
|
|
|
/*
|
|
|
|
* If no auto analysis, we are ready.
|
|
|
|
*/
|
|
|
|
if (params->no_aa)
|
|
|
|
return top;
|
|
|
|
|
|
|
|
retval = timerlat_aa_init(top, nr_cpus, params->dump_tasks);
|
|
|
|
if (retval)
|
|
|
|
goto out_err;
|
|
|
|
|
2021-12-10 18:11:25 +00:00
|
|
|
return top;
|
|
|
|
|
|
|
|
out_err:
|
|
|
|
osnoise_destroy_tool(top);
|
|
|
|
return NULL;
|
|
|
|
}
|
|
|
|
|
|
|
|
static int stop_tracing;
|
|
|
|
static void stop_top(int sig)
|
|
|
|
{
|
|
|
|
stop_tracing = 1;
|
|
|
|
}
|
|
|
|
|
|
|
|
/*
|
|
|
|
* timerlat_top_set_signals - handles the signal to stop the tool
|
|
|
|
*/
|
|
|
|
static void
|
|
|
|
timerlat_top_set_signals(struct timerlat_top_params *params)
|
|
|
|
{
|
|
|
|
signal(SIGINT, stop_top);
|
|
|
|
if (params->duration) {
|
|
|
|
signal(SIGALRM, stop_top);
|
|
|
|
alarm(params->duration);
|
|
|
|
}
|
|
|
|
}
|
|
|
|
|
|
|
|
int timerlat_top_main(int argc, char *argv[])
|
|
|
|
{
|
|
|
|
struct timerlat_top_params *params;
|
2022-02-08 14:36:21 +00:00
|
|
|
struct osnoise_tool *record = NULL;
|
|
|
|
struct osnoise_tool *top = NULL;
|
2021-12-10 18:11:25 +00:00
|
|
|
struct trace_instance *trace;
|
2022-03-02 19:01:39 +00:00
|
|
|
int dma_latency_fd = -1;
|
2021-12-10 18:11:25 +00:00
|
|
|
int return_value = 1;
|
2023-03-29 16:23:32 +00:00
|
|
|
char *max_lat;
|
2021-12-10 18:11:25 +00:00
|
|
|
int retval;
|
|
|
|
|
|
|
|
params = timerlat_top_parse_args(argc, argv);
|
|
|
|
if (!params)
|
|
|
|
exit(1);
|
|
|
|
|
|
|
|
top = timerlat_init_top(params);
|
|
|
|
if (!top) {
|
|
|
|
err_msg("Could not init osnoise top\n");
|
|
|
|
goto out_exit;
|
|
|
|
}
|
|
|
|
|
|
|
|
retval = timerlat_top_apply_config(top, params);
|
|
|
|
if (retval) {
|
|
|
|
err_msg("Could not apply config\n");
|
2022-04-29 16:28:10 +00:00
|
|
|
goto out_free;
|
2021-12-10 18:11:25 +00:00
|
|
|
}
|
|
|
|
|
|
|
|
trace = &top->trace;
|
|
|
|
|
|
|
|
retval = enable_timerlat(trace);
|
|
|
|
if (retval) {
|
|
|
|
err_msg("Failed to enable timerlat tracer\n");
|
2022-04-29 16:28:10 +00:00
|
|
|
goto out_free;
|
2021-12-10 18:11:25 +00:00
|
|
|
}
|
|
|
|
|
|
|
|
if (params->set_sched) {
|
|
|
|
retval = set_comm_sched_attr("timerlat/", ¶ms->sched_param);
|
|
|
|
if (retval) {
|
|
|
|
err_msg("Failed to set sched parameters\n");
|
2022-04-29 16:28:10 +00:00
|
|
|
goto out_free;
|
2021-12-10 18:11:25 +00:00
|
|
|
}
|
|
|
|
}
|
|
|
|
|
2022-03-02 19:01:39 +00:00
|
|
|
if (params->dma_latency >= 0) {
|
|
|
|
dma_latency_fd = set_cpu_dma_latency(params->dma_latency);
|
|
|
|
if (dma_latency_fd < 0) {
|
|
|
|
err_msg("Could not set /dev/cpu_dma_latency.\n");
|
2022-04-29 16:28:10 +00:00
|
|
|
goto out_free;
|
2022-03-02 19:01:39 +00:00
|
|
|
}
|
|
|
|
}
|
|
|
|
|
2021-12-10 18:11:25 +00:00
|
|
|
trace_instance_start(trace);
|
|
|
|
|
|
|
|
if (params->trace_output) {
|
|
|
|
record = osnoise_init_trace_tool("timerlat");
|
|
|
|
if (!record) {
|
|
|
|
err_msg("Failed to enable the trace instance\n");
|
2022-04-29 16:28:10 +00:00
|
|
|
goto out_free;
|
2021-12-10 18:11:25 +00:00
|
|
|
}
|
2022-03-02 19:01:31 +00:00
|
|
|
|
|
|
|
if (params->events) {
|
|
|
|
retval = trace_events_enable(&record->trace, params->events);
|
|
|
|
if (retval)
|
|
|
|
goto out_top;
|
|
|
|
}
|
|
|
|
|
2021-12-10 18:11:25 +00:00
|
|
|
trace_instance_start(&record->trace);
|
|
|
|
}
|
|
|
|
|
|
|
|
top->start_time = time(NULL);
|
|
|
|
timerlat_top_set_signals(params);
|
|
|
|
|
|
|
|
while (!stop_tracing) {
|
|
|
|
sleep(params->sleep_time);
|
|
|
|
|
2023-03-29 16:23:32 +00:00
|
|
|
if (params->aa_only && !trace_is_off(&top->trace, &record->trace))
|
|
|
|
continue;
|
|
|
|
|
2021-12-10 18:11:25 +00:00
|
|
|
retval = tracefs_iterate_raw_events(trace->tep,
|
|
|
|
trace->inst,
|
|
|
|
NULL,
|
|
|
|
0,
|
|
|
|
collect_registered_events,
|
|
|
|
trace);
|
|
|
|
if (retval < 0) {
|
|
|
|
err_msg("Error iterating on events\n");
|
|
|
|
goto out_top;
|
|
|
|
}
|
|
|
|
|
|
|
|
if (!params->quiet)
|
|
|
|
timerlat_print_stats(params, top);
|
|
|
|
|
2022-03-02 19:01:37 +00:00
|
|
|
if (trace_is_off(&top->trace, &record->trace))
|
2021-12-10 18:11:25 +00:00
|
|
|
break;
|
|
|
|
|
2022-03-02 19:01:40 +00:00
|
|
|
}
|
2021-12-10 18:11:25 +00:00
|
|
|
|
|
|
|
timerlat_print_stats(params, top);
|
|
|
|
|
|
|
|
return_value = 0;
|
|
|
|
|
2022-03-02 19:01:37 +00:00
|
|
|
if (trace_is_off(&top->trace, &record->trace)) {
|
2022-08-08 18:03:43 +00:00
|
|
|
printf("rtla timerlat hit stop tracing\n");
|
rtla/timerlat: Add auto-analysis support to timerlat top
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>
2023-01-31 15:38:54 +00:00
|
|
|
|
|
|
|
if (!params->no_aa)
|
|
|
|
timerlat_auto_analysis(params->stop_us, params->stop_total_us);
|
|
|
|
|
2021-12-10 18:11:25 +00:00
|
|
|
if (params->trace_output) {
|
|
|
|
printf(" Saving trace to %s\n", params->trace_output);
|
|
|
|
save_trace_to_file(record->trace.inst, params->trace_output);
|
|
|
|
}
|
2023-03-29 16:23:32 +00:00
|
|
|
} else if (params->aa_only) {
|
|
|
|
/*
|
|
|
|
* If the trace did not stop with --aa-only, at least print the
|
|
|
|
* max known latency.
|
|
|
|
*/
|
|
|
|
max_lat = tracefs_instance_file_read(trace->inst, "tracing_max_latency", NULL);
|
|
|
|
if (max_lat) {
|
|
|
|
printf(" Max latency was %s\n", max_lat);
|
|
|
|
free(max_lat);
|
|
|
|
}
|
2021-12-10 18:11:25 +00:00
|
|
|
}
|
|
|
|
|
|
|
|
out_top:
|
2022-03-02 19:01:39 +00:00
|
|
|
if (dma_latency_fd >= 0)
|
|
|
|
close(dma_latency_fd);
|
2022-03-02 19:01:31 +00:00
|
|
|
trace_events_destroy(&record->trace, params->events);
|
|
|
|
params->events = NULL;
|
2022-04-29 16:28:10 +00:00
|
|
|
out_free:
|
2021-12-10 18:11:25 +00:00
|
|
|
timerlat_free_top(top->data);
|
rtla/timerlat: Add auto-analysis support to timerlat top
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>
2023-01-31 15:38:54 +00:00
|
|
|
timerlat_aa_destroy();
|
2022-02-08 14:36:21 +00:00
|
|
|
osnoise_destroy_tool(record);
|
2021-12-10 18:11:25 +00:00
|
|
|
osnoise_destroy_tool(top);
|
|
|
|
free(params);
|
|
|
|
out_exit:
|
|
|
|
exit(return_value);
|
|
|
|
}
|