| Message ID | 20230716193000.231406-1-costa.shul@redhat.com (mailing list archive) |
|---|---|
| State | Changes Requested |
| Headers | show |
| Series | tracing/timerlat: Add latency threshold | expand |
Hi Costa, On 7/16/23 21:30, Costa Shulyupin wrote: > The timerlat tracer generates a huge amount of traces. > This affects the performance of the system and > the delays we are trying to measure with timerlat. More explanations in the code, but that is not the dominant factor, neither relevant for large spikes. > However, we are often interested in spikes of delay > rather than small values. That is why the stop tracing exists. One can set stop tracing, ignore the trace buffer while tracing is on. Once tracing turns off, tail the trace. rtla timerlat has the --aa-only that ignores the trace until the tracing stops, and then do the auto-analysis based on the tail of the trace. > > The patch effectively filters out irrelevant traces > before they are generated and produces more reliable > data. More in the code, but it is not more reliable data... did you mean human-readable data? > > This patch helped to debug a very big problem > and find this solution: > https://lore.kernel.org/lkml/20221208075604.811710-1-junxiao.chang@intel.com/ Can you explain more about this? Because AFAICT, the patch above is dealing with a SOFT timer. timerlat uses a HARD timer, so timerlat is not affected by that bug... so I might be missing a point here. > > Signed-off-by: Costa Shulyupin <costa.shul@redhat.com> > --- > Documentation/trace/timerlat-tracer.rst | 1 + > kernel/trace/trace_osnoise.c | 17 +++++++++++++++++ > 2 files changed, 18 insertions(+) > > diff --git a/Documentation/trace/timerlat-tracer.rst b/Documentation/trace/timerlat-tracer.rst > index 53a56823e903..71b1c63ca403 100644 > --- a/Documentation/trace/timerlat-tracer.rst > +++ b/Documentation/trace/timerlat-tracer.rst > @@ -68,6 +68,7 @@ directory. The timerlat configs are: > > - cpus: CPUs at which a timerlat thread will execute. > - timerlat_period_us: the period of the timerlat thread. > + - timerlat_threshold_ns: filter out timer latencies below the threshold All the interface is in us.... > - stop_tracing_us: stop the system tracing if a > timer latency at the *irq* context higher than the configured > value happens. Writing 0 disables this option. > diff --git a/kernel/trace/trace_osnoise.c b/kernel/trace/trace_osnoise.c > index bd0d01d00fb9..43284a1e8bea 100644 > --- a/kernel/trace/trace_osnoise.c > +++ b/kernel/trace/trace_osnoise.c > @@ -346,6 +346,7 @@ static struct osnoise_data { > u64 stop_tracing_total; /* stop trace in the final operation (report/thread) */ > #ifdef CONFIG_TIMERLAT_TRACER > u64 timerlat_period; /* timerlat period */ > + u64 timerlat_threshold_ns; comment.... > u64 print_stack; /* print IRQ stack if total > */ > int timerlat_tracer; /* timerlat tracer */ > #endif > @@ -358,6 +359,7 @@ static struct osnoise_data { > #ifdef CONFIG_TIMERLAT_TRACER > .print_stack = 0, > .timerlat_period = DEFAULT_TIMERLAT_PERIOD, > + .timerlat_threshold_ns = 0, > .timerlat_tracer = 0, > #endif > }; > @@ -597,6 +599,10 @@ static void trace_timerlat_sample(struct timerlat_sample *sample) > struct osnoise_instance *inst; > struct trace_buffer *buffer; > > + if (osnoise_data.timerlat_threshold_ns && > + sample->timer_latency < osnoise_data.timerlat_threshold_ns) > + return; > + From the entire timerlat machinery, skipping the print is not the dominant factor. It can save a few nanoseconds, but the values are already produced at this point... so why not? You mentioned that this is useful for large spikes, so... it will not be the few ns to cause problems. And I'm not convinced that it produces more reliable results. For example, if you find a large latency in the thread context, but skip the IRQ context trace, you will lose useful data.... so your analysis is prone to be less reliable. Did you mean readable? improve the readability... That I can see. Also, for debugging purposes, one needs to enable more events... at least the osnoise: ones. These events happen more frequently than the timerlat ones... and they are not being filtered here... Filtering them using the event filtering interface will not help either, e.g., hiding 1k one us interrupts bomb will mask you a 1ms delay... So, as I said, I am not convinced that adding this interface file is better than setting the stop-tracing option... and then waiting for the trace to stop... parsing only the tail of the buffer. Thoughts? -- Daniel
> rtla timerlat has the --aa-only that ignores the trace until > the tracing stops, and then do the auto-analysis based on the > tail of the trace. > So, as I said, I am not convinced that adding this interface file is > better than setting the stop-tracing option... and then waiting for > the trace to stop... parsing only the tail of the buffer. I see. Stop-tracing option of rtla timerlat solves the problem for most of the cases. Thank you very much! Costa
diff --git a/Documentation/trace/timerlat-tracer.rst b/Documentation/trace/timerlat-tracer.rst index 53a56823e903..71b1c63ca403 100644 --- a/Documentation/trace/timerlat-tracer.rst +++ b/Documentation/trace/timerlat-tracer.rst @@ -68,6 +68,7 @@ directory. The timerlat configs are: - cpus: CPUs at which a timerlat thread will execute. - timerlat_period_us: the period of the timerlat thread. + - timerlat_threshold_ns: filter out timer latencies below the threshold - stop_tracing_us: stop the system tracing if a timer latency at the *irq* context higher than the configured value happens. Writing 0 disables this option. diff --git a/kernel/trace/trace_osnoise.c b/kernel/trace/trace_osnoise.c index bd0d01d00fb9..43284a1e8bea 100644 --- a/kernel/trace/trace_osnoise.c +++ b/kernel/trace/trace_osnoise.c @@ -346,6 +346,7 @@ static struct osnoise_data { u64 stop_tracing_total; /* stop trace in the final operation (report/thread) */ #ifdef CONFIG_TIMERLAT_TRACER u64 timerlat_period; /* timerlat period */ + u64 timerlat_threshold_ns; u64 print_stack; /* print IRQ stack if total > */ int timerlat_tracer; /* timerlat tracer */ #endif @@ -358,6 +359,7 @@ static struct osnoise_data { #ifdef CONFIG_TIMERLAT_TRACER .print_stack = 0, .timerlat_period = DEFAULT_TIMERLAT_PERIOD, + .timerlat_threshold_ns = 0, .timerlat_tracer = 0, #endif }; @@ -597,6 +599,10 @@ static void trace_timerlat_sample(struct timerlat_sample *sample) struct osnoise_instance *inst; struct trace_buffer *buffer; + if (osnoise_data.timerlat_threshold_ns && + sample->timer_latency < osnoise_data.timerlat_threshold_ns) + return; + rcu_read_lock(); list_for_each_entry_rcu(inst, &osnoise_instances, list) { buffer = inst->tr->array_buffer.buffer; @@ -2663,6 +2669,11 @@ static struct trace_min_max_param timerlat_period = { .min = &timerlat_min_period, }; +static struct trace_min_max_param timerlat_threshold = { + .lock = &interface_lock, + .val = &osnoise_data.timerlat_threshold_ns, +}; + static const struct file_operations timerlat_fd_fops = { .open = timerlat_fd_open, .read = timerlat_fd_read, @@ -2759,6 +2770,12 @@ static int init_timerlat_tracefs(struct dentry *top_dir) if (!tmp) return -ENOMEM; + tmp = tracefs_create_file("timerlat_threshold_ns", TRACE_MODE_WRITE, + top_dir, &timerlat_threshold, + &trace_min_max_fops); + if (!tmp) + return -ENOMEM; + retval = osnoise_create_cpu_timerlat_fd(top_dir); if (retval) return retval;
The timerlat tracer generates a huge amount of traces. This affects the performance of the system and the delays we are trying to measure with timerlat. However, we are often interested in spikes of delay rather than small values. The patch effectively filters out irrelevant traces before they are generated and produces more reliable data. This patch helped to debug a very big problem and find this solution: https://lore.kernel.org/lkml/20221208075604.811710-1-junxiao.chang@intel.com/ Signed-off-by: Costa Shulyupin <costa.shul@redhat.com> --- Documentation/trace/timerlat-tracer.rst | 1 + kernel/trace/trace_osnoise.c | 17 +++++++++++++++++ 2 files changed, 18 insertions(+)