Syzkaller triggered a WARN_ON_ONCE(!nest) warning:
WARNING: kernel/trace/ring_buffer.c:821 at ring_buffer_event_time_stamp
Call trace:
ring_buffer_event_time_stamp
hist_field_timestamp
hist_fn_call
event_hist_trigger
event_triggers_call
__event_trigger_test_discard
trace_event_buffer_commit
do_trace_event_raw_event_sched_switch
trace_event_raw_event_sched_switch
The warning is probabilistically reproducible and is related to syzkaller
executing the following commands:
echo 'prev_pid == 999999' > events/sched/sched_switch/filter
echo 'hist:keys=common_timestamp' > events/sched/sched_switch/trigger
The specific triggering process is as follows:
CPU 0 CPU 1
(context switching) (echo
'hist:keys=common_timestamp' > \
events/sched/sched_switch/trigger)
do_trace_event_raw_event_##call
trace_event_buffer_lock_reserve
if (!tr->no_filter_buffering_ref &&
trace_file->flags & EVENT_FILE_FL_FILTERED)
return entry; // return directly
event_hist_trigger_parse
hist_register_trigger
tracing_set_filter_buffering(file->tr, true);
tr->no_filter_buffering_ref++;
__trace_buffer_lock_reserve
rb_start_commit
local_inc(&cpu_buffer->committing); // skipped and not executed
trace_event_buffer_commit
__event_trigger_test_discard
event_triggers_call
event_hist_trigger
hist_fn_call
hist_field_timestamp
ring_buffer_event_time_stamp
nest = local_read(&cpu_buffer->committing);
WARN_ON_ONCE(!nest) // trigger warning
The root cause is that when an event file has a filter attached and the
hist trigger has not yet been attached, trace_event_buffer_lock_reserve()
writes the event into the per-CPU trace_buffered_event temp buffer instead
of reserving it in the ring buffer, so cpu_buffer->committing is not
incremented. When the event is later processed at commit time by a hist
trigger, hist_field_timestamp() -> ring_buffer_event_time_stamp() sees a
zero committing count, triggering WARN_ON_ONCE(!nest).
tracing_event_time_stamp() was added by commit d8279bfc5e959 ("tracing:
Add tracing_event_time_stamp() API") for exactly this case: if the event
is the per-CPU trace_buffered_event, it returns the current ring buffer
timestamp. But it never gained a caller. Use it in hist_field_timestamp(),
so that a hist trigger that races onto a buffered event records the
current time, which is only marginally later than when the event was
recorded, instead of warning and recording a bogus timestamp.
Fixes: b94bc80df648 ("tracing: Use a no_filter_buffering_ref to stop using the
filter buffer")
Signed-off-by: Tengda Wu <[email protected]>
---
kernel/trace/trace_events_hist.c | 2 +-
1 file changed, 1 insertion(+), 1 deletion(-)
diff --git a/kernel/trace/trace_events_hist.c b/kernel/trace/trace_events_hist.c
index 8af97fd4ee2d..89be3139f8e9 100644
--- a/kernel/trace/trace_events_hist.c
+++ b/kernel/trace/trace_events_hist.c
@@ -873,7 +873,7 @@ static u64 hist_field_timestamp(struct hist_field
*hist_field,
struct hist_trigger_data *hist_data = hist_field->hist_data;
struct trace_array *tr = hist_data->event_file->tr;
- u64 ts = ring_buffer_event_time_stamp(buffer, rbe);
+ u64 ts = tracing_event_time_stamp(buffer, rbe);
if (hist_data->attrs->ts_in_usecs && trace_clock_in_ns(tr))
ts = ns2usecs(ts);
--
2.34.1
