Re: [PATCH] ring-buffer: Add barrire in rb_move_tail

[Steven Rostedt <rostedt@goodmis.org>]

On Tue, 30 Aug 2022 20:08:54 +0800
"Jiazi.Li" <jqqlijiazi@gmail.com> wrote:

> The following crash issue was encountered several times when read
> trace_pipe:
> 
> 1. in ring_buffer_event_data, found event's type is bigger than
> RINGBUF_TYPE_DATA_TYPE_LEN_MAX, print WARNING:
> [249033.677658]WARNING: CPU: 1 PID: 9975 at ring_buffer_event_data+0x38/0x48
> 
> 2. trace_read_pipe print this event resulting in crash issue:
> [249033.806200] die+0xac/0x37c
> [249033.806891] die_kernel_fault+0x60/0x70
> [249033.807710] die_kernel_fault+0x0/0x70
> [249033.808518] do_bad_area+0x30/0x130
> [249033.809296] do_translation_fault+0x34/0x40
> [249033.810158] do_mem_abort+0x4c/0xf8
> [249033.810935] el1_da+0x1c/0xac
> [249033.811647] string+0x38/0x74
> [249033.812357] vsnprintf+0x430/0x65c
> [249033.813122] seq_buf_vprintf+0x64/0xcc
> [249033.813934] trace_seq_printf+0x70/0xd8
> [249033.814755] trace_raw_output_ipi_handler+0x40/0x54
> [249033.815705] print_trace_line+0x3ec/0x424
> [249033.816547] tracing_read_pipe+0x28c/0x3ec
> [249033.817402] __vfs_read+0x44/0x13c
> [249033.818166] vfs_read+0xb8/0x150
> [249033.818908] ksys_read+0x6c/0xcc
> [249033.819651] __arm64_sys_read+0x18/0x20
> [249033.820470] el0_svc_common+0x98/0x160
> [249033.821278] el0_svc_handler+0x60/0x78
> [249033.822086] el0_svc+0x8/0x300
> 
> ipi event is not enable in my device, the event tracing_read_pipe

The ipi event is *not* enabled? So you are saying that it translated the
extra data at the end that was suppose to be PADDING?

> want to print is a PADDING event generated in rb_move_tail.
> array[0] of this event is 0x18, ipi entry trace event's type value
> is 0x18 too in my device.
> so trace_read_pipe call trace_raw_output_ipi_handler to print this
> event, eventually, system crash because illegal pointers.
> 
> In ring_buffer_peek, PADDING type event will not return to caller.
> So at least when ring_buffer_peek is called, this event has not
> been set to PADDING.
> 
> My reader task poll on trace_pipe and other files, wakeup
> by other files and found that trace ring_buffer is not empty
> because of read != commit.
> But maybe because of cpu out-of-order execution, new event has not
> been set to PADDING type, and leads to above issue.
> 
> Can we fix this issue by add a barrier between rb_reset_tail
> and rb_end_commit?
> Or are there other bugs that cause this issue?

I rather not add a barrier in the writer because that will slow down the
tracing.

> 
> Signed-off-by: Jiazi.Li <jiazi.li@transsion.com>
> ---
>  kernel/trace/ring_buffer.c | 5 +++++
>  1 file changed, 5 insertions(+)
> 
> diff --git a/kernel/trace/ring_buffer.c b/kernel/trace/ring_buffer.c
> index d59b6a328b7f..20f3ef839467 100644
> --- a/kernel/trace/ring_buffer.c
> +++ b/kernel/trace/ring_buffer.c
> @@ -2717,6 +2717,11 @@ rb_move_tail(struct ring_buffer_per_cpu *cpu_buffer,
>  
>  	rb_reset_tail(cpu_buffer, tail, info);
>  
> +	/*
> +	 * Add barrier to make sure tail event be set to
> +	 * PADDING type before update commit.
> +	 */
> +	smp_mb();

Hmm, I'm thinking this may be a bigger race than a memory barrier. I'm
thinking that the reader has full access to this information at this
moment, as soon as the tail page moved forward. I unfortunately do not have
the time right now to do a full investigation, but thank you for reporting
this.

I think your mb() solution is just making the race window smaller and not
actually fixing the race.

-- Steve

>  	/* Commit what we have for now. */
>  	rb_end_commit(cpu_buffer);
>  	/* rb_end_commit() decs committing */