hulk inclusion category: bugfix bugzilla: https://atomgit.com/openeuler/kernel/issues/10071 ---------------------------------------- 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 <wutengda2@huawei.com> --- 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 d5602a4c6eb5..856d75942581 100644 --- a/kernel/trace/trace_events_hist.c +++ b/kernel/trace/trace_events_hist.c @@ -874,7 +874,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