[PATCH] tracing/timerlat: Add latency threshold

[PATCH] tracing/timerlat: Add latency threshold

[Costa Shulyupin]

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(+)

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;
-- 
2.41.0

Re: [PATCH] tracing/timerlat: Add latency threshold

[Daniel Bristot de Oliveira]

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

Re: [PATCH] tracing/timerlat: Add latency threshold

[Costa Shulyupin]

> 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