[PATCH 0/5] rtla, osnoise: Fixes to address intermittent test issues

[PATCH 0/5] rtla, osnoise: Fixes to address intermittent test issues

[Crystal Wood]

With these fixes, I'm able to run the tests in a loop overnight with no
failures.

Crystal Wood (5):
  rtla/tests: Don't rely on matching ^1ALL
  tracing/osnoise: Dump stack on timerlat uret threshold event
  tracing/osnoise: Array printk init and cleanup
  rtla/timerlat: Exit top main loop on any non-zero wait_retval
  rtla: Set stop threshold after all instances are enabled

 kernel/trace/trace_osnoise.c          | 46 +++++++++++++++++----------
 tools/tracing/rtla/src/common.c       | 20 ++++++++++++
 tools/tracing/rtla/src/common.h       |  4 +++
 tools/tracing/rtla/src/osnoise.c      | 17 +++-------
 tools/tracing/rtla/src/osnoise.h      |  5 ---
 tools/tracing/rtla/src/timerlat.c     | 29 ++++++-----------
 tools/tracing/rtla/src/timerlat_top.c |  2 +-
 tools/tracing/rtla/tests/timerlat.t   |  2 +-
 8 files changed, 69 insertions(+), 56 deletions(-)

-- 
2.48.1

[PATCH 1/5] rtla/tests: Don't rely on matching ^1ALL

[Crystal Wood]

The timerlat "top stop at failed action" test was relying on "ALL" being
printed immediately after the "1" from the threshold action.  Besides being
fragile, this depends on stdbuf behavior, which is easy to miss when
recreating the test outside of the framework for debugging purposes.

Instead, use the expected/unexpected text mechanism from the
corresponding osnoise test.

Signed-off-by: Crystal Wood <crwood@redhat.com>
---
 tools/tracing/rtla/tests/timerlat.t | 2 +-
 1 file changed, 1 insertion(+), 1 deletion(-)

diff --git a/tools/tracing/rtla/tests/timerlat.t b/tools/tracing/rtla/tests/timerlat.t
index d1cc7106ae26..fd4935fd7b49 100644
--- a/tools/tracing/rtla/tests/timerlat.t
+++ b/tools/tracing/rtla/tests/timerlat.t
@@ -58,7 +58,7 @@ check "multiple actions" \
 check "hist stop at failed action" \
 	"timerlat hist -T 2 --on-threshold shell,command='echo -n 1; false' --on-threshold shell,command='echo -n 2'" 2 "^1# RTLA timerlat histogram$"
 check "top stop at failed action" \
-	"timerlat top -T 2 --on-threshold shell,command='echo -n 1; false' --on-threshold shell,command='echo -n 2'" 2 "^1ALL"
+	"timerlat top -T 2 --on-threshold shell,command='echo -n abc; false' --on-threshold shell,command='echo -n defgh'" 2 "^abc" "defgh"
 check "hist with continue" \
 	"timerlat hist -T 2 -d 5s --on-threshold shell,command='echo TestOutput' --on-threshold continue" 0 "^TestOutput$"
 check "top with continue" \
-- 
2.48.1

[PATCH 2/5] tracing/osnoise: Dump stack on timerlat uret threshold event

[Crystal Wood]

Dump the saved IRQ stack trace regardless of whether the event was
THREAD_CONTEXT or THREAD_URET.

In the uret case, the latency presumably had not yet crossed the
threshold at IRQ time (or else it would have dumped the stack at thread
wakeup time, unless we're racing with a change to the threshold), but it
may have at least contributed -- and this is possible with THREAD_CONTEXT
as well.

In any case, it helps with writing reliable rtla tests if we always get
a stack trace on a threshold event.

Signed-off-by: Crystal Wood <crwood@redhat.com>
---
 kernel/trace/trace_osnoise.c | 7 +++++--
 1 file changed, 5 insertions(+), 2 deletions(-)

diff --git a/kernel/trace/trace_osnoise.c b/kernel/trace/trace_osnoise.c
index a9962d4497e8..bb4d195ec74f 100644
--- a/kernel/trace/trace_osnoise.c
+++ b/kernel/trace/trace_osnoise.c
@@ -2508,9 +2508,12 @@ timerlat_fd_read(struct file *file, char __user *ubuf, size_t count,
 		notify_new_max_latency(diff);
 
 		tlat->tracing_thread = false;
-		if (osnoise_data.stop_tracing_total)
-			if (time_to_us(diff) >= osnoise_data.stop_tracing_total)
+		if (osnoise_data.stop_tracing_total) {
+			if (time_to_us(diff) >= osnoise_data.stop_tracing_total) {
+				timerlat_dump_stack(time_to_us(diff));
 				osnoise_stop_tracing();
+			}
+		}
 	} else {
 		tlat->tracing_thread = false;
 		tlat->kthread = current;
-- 
2.48.1

[PATCH 3/5] tracing/osnoise: Array printk init and cleanup

[Crystal Wood]

None of the calls to trace_array_printk_buf() will do anything
if we don't initialize the buffer on instance creation (unless
some other tracer called it), so do that.

Add an osnoise_print() macro to facilitate adding debug prints (without
tainting).

Use trace_array_printk() instead of trace_array_printk_buf(), as we're
only writing to the main buffer (of a non-main instance) anyway -- and
trace_array_printk_buf() skips the check to make sure we're not printing
to the global instance.

Signed-off-by: Crystal Wood <crwood@redhat.com>
---
Technically this isn't needed to make the tests pass, but it was helpful
in debugging the issues and would be nice to have around for next time.

What's the intended use case for trace_array_printk_buf()?  It seems like
it should be an internal function if it's not going to check the
instance.  I don't see any non-internal uses other than here and in
trace_hwlat.c, which also only prints to the main buffer.
---
 kernel/trace/trace_osnoise.c | 39 ++++++++++++++++++++++--------------
 1 file changed, 24 insertions(+), 15 deletions(-)

diff --git a/kernel/trace/trace_osnoise.c b/kernel/trace/trace_osnoise.c
index bb4d195ec74f..b53a698f8e81 100644
--- a/kernel/trace/trace_osnoise.c
+++ b/kernel/trace/trace_osnoise.c
@@ -81,6 +81,22 @@ struct osnoise_instance {
 
 static struct list_head osnoise_instances;
 
+static void osnoise_print(const char *fmt, ...)
+{
+	struct osnoise_instance *inst;
+	struct trace_array *tr;
+	va_list ap;
+
+	rcu_read_lock();
+	list_for_each_entry_rcu(inst, &osnoise_instances, list) {
+		tr = inst->tr;
+		va_start(ap, fmt);
+		trace_array_vprintk(tr, _RET_IP_, fmt, ap);
+		va_end(ap);
+	}
+	rcu_read_unlock();
+}
+
 static bool osnoise_has_registered_instances(void)
 {
 	return !!list_first_or_null_rcu(&osnoise_instances,
@@ -121,6 +137,7 @@ static int osnoise_register_instance(struct trace_array *tr)
 	 * trace_types_lock.
 	 */
 	lockdep_assert_held(&trace_types_lock);
+	trace_array_init_printk(tr);
 
 	inst = kmalloc(sizeof(*inst), GFP_KERNEL);
 	if (!inst)
@@ -455,15 +472,7 @@ static void print_osnoise_headers(struct seq_file *s)
  * osnoise_taint - report an osnoise error.
  */
 #define osnoise_taint(msg) ({							\
-	struct osnoise_instance *inst;						\
-	struct trace_buffer *buffer;						\
-										\
-	rcu_read_lock();							\
-	list_for_each_entry_rcu(inst, &osnoise_instances, list) {		\
-		buffer = inst->tr->array_buffer.buffer;				\
-		trace_array_printk_buf(buffer, _THIS_IP_, msg);			\
-	}									\
-	rcu_read_unlock();							\
+	osnoise_print(msg);							\
 	osnoise_data.tainted = true;						\
 })
 
@@ -1173,10 +1182,10 @@ static __always_inline void osnoise_stop_exception(char *msg, int cpu)
 	rcu_read_lock();
 	list_for_each_entry_rcu(inst, &osnoise_instances, list) {
 		tr = inst->tr;
-		trace_array_printk_buf(tr->array_buffer.buffer, _THIS_IP_,
-				       "stop tracing hit on cpu %d due to exception: %s\n",
-				       smp_processor_id(),
-				       msg);
+		trace_array_printk(tr, _THIS_IP_,
+				   "stop tracing hit on cpu %d due to exception: %s\n",
+				   smp_processor_id(),
+				   msg);
 
 		if (test_bit(OSN_PANIC_ON_STOP, &osnoise_options))
 			panic("tracer hit on cpu %d due to exception: %s\n",
@@ -1346,8 +1355,8 @@ static __always_inline void osnoise_stop_tracing(void)
 	rcu_read_lock();
 	list_for_each_entry_rcu(inst, &osnoise_instances, list) {
 		tr = inst->tr;
-		trace_array_printk_buf(tr->array_buffer.buffer, _THIS_IP_,
-				"stop tracing hit on cpu %d\n", smp_processor_id());
+		trace_array_printk(tr, _THIS_IP_,
+				   "stop tracing hit on cpu %d\n", smp_processor_id());
 
 		if (test_bit(OSN_PANIC_ON_STOP, &osnoise_options))
 			panic("tracer hit stop condition on CPU %d\n", smp_processor_id());
-- 
2.48.1

[PATCH 4/5] rtla/timerlat: Exit top main loop on any non-zero wait_retval

[Crystal Wood]

Comparing to exactly 1 will fail if more than one ring buffer
event was seen since the last call to timerlat_bpf_wait(), which
can happen in some race scenarios.

Signed-off-by: Crystal Wood <crwood@redhat.com>
---
 tools/tracing/rtla/src/timerlat_top.c | 2 +-
 1 file changed, 1 insertion(+), 1 deletion(-)

diff --git a/tools/tracing/rtla/src/timerlat_top.c b/tools/tracing/rtla/src/timerlat_top.c
index da5d5db1bc17..56cf4ad64847 100644
--- a/tools/tracing/rtla/src/timerlat_top.c
+++ b/tools/tracing/rtla/src/timerlat_top.c
@@ -921,7 +921,7 @@ timerlat_top_bpf_main_loop(struct osnoise_tool *tool)
 		if (!params->common.quiet)
 			timerlat_print_stats(tool);
 
-		if (wait_retval == 1) {
+		if (wait_retval != 0) {
 			/* Stopping requested by tracer */
 			actions_perform(&params->common.threshold_actions);
 
-- 
2.48.1

[PATCH 5/5] rtla: Set stop threshold after all instances are enabled

[Crystal Wood]

This avoids startup races where one of the instances hit a threshold
before all instances were enabled, and thus tracing stops without
the relevant event.  In particular, this is not uncommon with the
tests that set a very tight threshold and then complain if there's
no analysis.

This also ensures that we don't stop tracing during a warmup.

The downside is a small chance of having an event over the threshold
early in the output, without stopping on it, which could cause user
confusion.  This should be less likely if the warmup feature is used, but
that doesn't eliminate the race window, just the odds of an unusual spike
right at that moment.

Signed-off-by: Crystal Wood <crwood@redhat.com>
---
 tools/tracing/rtla/src/common.c   | 20 ++++++++++++++++++++
 tools/tracing/rtla/src/common.h   |  4 ++++
 tools/tracing/rtla/src/osnoise.c  | 17 ++++-------------
 tools/tracing/rtla/src/osnoise.h  |  5 -----
 tools/tracing/rtla/src/timerlat.c | 29 ++++++++++-------------------
 5 files changed, 38 insertions(+), 37 deletions(-)

diff --git a/tools/tracing/rtla/src/common.c b/tools/tracing/rtla/src/common.c
index b197037fc58b..46e0263d6ae8 100644
--- a/tools/tracing/rtla/src/common.c
+++ b/tools/tracing/rtla/src/common.c
@@ -348,3 +348,23 @@ int hist_main_loop(struct osnoise_tool *tool)
 
 	return retval;
 }
+
+int osn_set_stop(struct osnoise_tool *tool)
+{
+	struct common_params *params = tool->params;
+	int retval;
+
+	retval = osnoise_set_stop_us(tool->context, params->stop_us);
+	if (retval) {
+		err_msg("Failed to set stop us\n");
+		return retval;
+	}
+
+	retval = osnoise_set_stop_total_us(tool->context, params->stop_total_us);
+	if (retval) {
+		err_msg("Failed to set stop total us\n");
+		return retval;
+	}
+
+	return 0;
+}
diff --git a/tools/tracing/rtla/src/common.h b/tools/tracing/rtla/src/common.h
index 355f113a14a3..64004a030a56 100644
--- a/tools/tracing/rtla/src/common.h
+++ b/tools/tracing/rtla/src/common.h
@@ -148,7 +148,11 @@ void osnoise_destroy_tool(struct osnoise_tool *top);
 struct osnoise_tool *osnoise_init_tool(char *tool_name);
 struct osnoise_tool *osnoise_init_trace_tool(const char *tracer);
 bool osnoise_trace_is_off(struct osnoise_tool *tool, struct osnoise_tool *record);
+int osnoise_set_stop_us(struct osnoise_context *context, long long stop_us);
+int osnoise_set_stop_total_us(struct osnoise_context *context,
+			      long long stop_total_us);
 
 int common_apply_config(struct osnoise_tool *tool, struct common_params *params);
 int top_main_loop(struct osnoise_tool *tool);
 int hist_main_loop(struct osnoise_tool *tool);
+int osn_set_stop(struct osnoise_tool *tool);
diff --git a/tools/tracing/rtla/src/osnoise.c b/tools/tracing/rtla/src/osnoise.c
index 312c511fa004..945eb61efc46 100644
--- a/tools/tracing/rtla/src/osnoise.c
+++ b/tools/tracing/rtla/src/osnoise.c
@@ -1128,18 +1128,6 @@ osnoise_apply_config(struct osnoise_tool *tool, struct osnoise_params *params)
 		goto out_err;
 	}
 
-	retval = osnoise_set_stop_us(tool->context, params->common.stop_us);
-	if (retval) {
-		err_msg("Failed to set stop us\n");
-		goto out_err;
-	}
-
-	retval = osnoise_set_stop_total_us(tool->context, params->common.stop_total_us);
-	if (retval) {
-		err_msg("Failed to set stop total us\n");
-		goto out_err;
-	}
-
 	retval = osnoise_set_tracing_thresh(tool->context, params->threshold);
 	if (retval) {
 		err_msg("Failed to set tracing_thresh\n");
@@ -1184,9 +1172,12 @@ int osnoise_enable(struct osnoise_tool *tool)
 			debug_msg("Error cleaning up the buffer");
 			return retval;
 		}
-
 	}
 
+	retval = osn_set_stop(tool);
+	if (retval)
+		return retval;
+
 	return 0;
 }
 
diff --git a/tools/tracing/rtla/src/osnoise.h b/tools/tracing/rtla/src/osnoise.h
index 895687030c0b..3c927c179b35 100644
--- a/tools/tracing/rtla/src/osnoise.h
+++ b/tools/tracing/rtla/src/osnoise.h
@@ -34,12 +34,7 @@ int osnoise_set_runtime_period(struct osnoise_context *context,
 			       unsigned long long period);
 void osnoise_restore_runtime_period(struct osnoise_context *context);
 
-int osnoise_set_stop_us(struct osnoise_context *context,
-			long long stop_us);
 void osnoise_restore_stop_us(struct osnoise_context *context);
-
-int osnoise_set_stop_total_us(struct osnoise_context *context,
-			      long long stop_total_us);
 void osnoise_restore_stop_total_us(struct osnoise_context *context);
 
 int osnoise_set_timerlat_period_us(struct osnoise_context *context,
diff --git a/tools/tracing/rtla/src/timerlat.c b/tools/tracing/rtla/src/timerlat.c
index 19bab3d189f9..fe93cdc5354f 100644
--- a/tools/tracing/rtla/src/timerlat.c
+++ b/tools/tracing/rtla/src/timerlat.c
@@ -59,25 +59,6 @@ timerlat_apply_config(struct osnoise_tool *tool, struct timerlat_params *params)
 			goto out_err;
 	}
 
-	if (params->mode != TRACING_MODE_BPF) {
-		/*
-		 * In tracefs and mixed mode, timerlat tracer handles stopping
-		 * on threshold
-		 */
-		retval = osnoise_set_stop_us(tool->context, params->common.stop_us);
-		if (retval) {
-			err_msg("Failed to set stop us\n");
-			goto out_err;
-		}
-
-		retval = osnoise_set_stop_total_us(tool->context, params->common.stop_total_us);
-		if (retval) {
-			err_msg("Failed to set stop total us\n");
-			goto out_err;
-		}
-	}
-
-
 	retval = osnoise_set_timerlat_period_us(tool->context,
 						params->timerlat_period_us ?
 						params->timerlat_period_us :
@@ -200,6 +181,16 @@ int timerlat_enable(struct osnoise_tool *tool)
 		}
 	}
 
+	/*
+	 * In tracefs and mixed mode, timerlat tracer handles stopping
+	 * on threshold
+	 */
+	if (params->mode != TRACING_MODE_BPF) {
+		retval = osn_set_stop(tool);
+		if (retval)
+			return retval;
+	}
+
 	return 0;
 }
 
-- 
2.48.1

Re: [PATCH 0/5] rtla, osnoise: Fixes to address intermittent test issues

[Crystal Wood]

On Wed, 2025-11-12 at 09:25 -0600, Crystal Wood wrote:
> With these fixes, I'm able to run the tests in a loop overnight with no
> failures.
> 
> Crystal Wood (5):
>   rtla/tests: Don't rely on matching ^1ALL
>   tracing/osnoise: Dump stack on timerlat uret threshold event
>   tracing/osnoise: Array printk init and cleanup
>   rtla/timerlat: Exit top main loop on any non-zero wait_retval
>   rtla: Set stop threshold after all instances are enabled
> 
>  kernel/trace/trace_osnoise.c          | 46 +++++++++++++++++----------
>  tools/tracing/rtla/src/common.c       | 20 ++++++++++++
>  tools/tracing/rtla/src/common.h       |  4 +++
>  tools/tracing/rtla/src/osnoise.c      | 17 +++-------
>  tools/tracing/rtla/src/osnoise.h      |  5 ---
>  tools/tracing/rtla/src/timerlat.c     | 29 ++++++-----------
>  tools/tracing/rtla/src/timerlat_top.c |  2 +-
>  tools/tracing/rtla/tests/timerlat.t   |  2 +-
>  8 files changed, 69 insertions(+), 56 deletions(-)

Oh, forgot to mention that this is on top of Tomas's pending patches.

-Crystal

Re: [PATCH 0/5] rtla, osnoise: Fixes to address intermittent test issues

[Wander Lairson Costa]

On Wed, Nov 12, 2025 at 09:25:24AM -0600, Crystal Wood wrote:
> With these fixes, I'm able to run the tests in a loop overnight with no
> failures.
> 
> Crystal Wood (5):
>   rtla/tests: Don't rely on matching ^1ALL
>   tracing/osnoise: Dump stack on timerlat uret threshold event
>   tracing/osnoise: Array printk init and cleanup
>   rtla/timerlat: Exit top main loop on any non-zero wait_retval
>   rtla: Set stop threshold after all instances are enabled
> 
>  kernel/trace/trace_osnoise.c          | 46 +++++++++++++++++----------
>  tools/tracing/rtla/src/common.c       | 20 ++++++++++++
>  tools/tracing/rtla/src/common.h       |  4 +++
>  tools/tracing/rtla/src/osnoise.c      | 17 +++-------
>  tools/tracing/rtla/src/osnoise.h      |  5 ---
>  tools/tracing/rtla/src/timerlat.c     | 29 ++++++-----------
>  tools/tracing/rtla/src/timerlat_top.c |  2 +-
>  tools/tracing/rtla/tests/timerlat.t   |  2 +-
>  8 files changed, 69 insertions(+), 56 deletions(-)
> 
> -- 
> 2.48.1
> 

On patch 3 the commit message says that osnoise_print() is implemented
as a macro, but it is actually implemented as a function. But that isn't
a blocker.

Reviewed-by: Wander Lairson Costa <wander@redhat.com>