On Tue, Sep 06, 2022 at 12:25:42PM -0400, Steven Rostedt wrote:
> On Mon, 5 Sep 2022 11:23:14 +0800
> lijiazi <jqqlijiazi@xxxxxxxxx> wrote:
>
> > >From ramdump, current reader page's commit is 0xff0, not bigger than
> > BUF_PAGE_SIZE:
> > crash> struct buffer_page 0xffffffd10b599580 -x
> > struct buffer_page {
> > list = {
> > next = 0xffffffd10b599500,
> > prev = 0xffffffd10b599680
> > },
> > write = {
> > a = {
> > counter = 0x100ff0
> > }
> > },
> > read = 0xfd4,
> > entries = {
> > a = {
> > counter = 0x100053
> > }
> > },
> > real_end = 0xfd4,
> > page = 0xffffffd10b553000
> > }
> > crash> struct buffer_data_page 0xffffffd10b553000 -x
> > struct buffer_data_page {
> > time_stamp = 0xe2679ca0cd3d,
> > commit = {
> > a = {
> > counter = 0xff0
> > }
> > },
> > data = 0xffffffd10b553010 "\b"
> > }
> > I also can extrace trace log from ramdump by crash-trace extension tool:
> > bsp: <...>-32191 [006] 249032.606401: signal_generate: sig=17 errno=0 code=1 comm=WifiDiagnostics pid=1535 grp=1 res=1
> > bsp: <...>-32183 [006] 249032.625192: sched_process_exit: comm=osi_bin pid=32183 prio=120
> > bsp: <...>-32196 [006] 249033.677333: sched_process_exit: comm=ip pid=32196 prio=120
> > bsp: <...>-32196 [006] 249033.677562: signal_generate: sig=17 errno=0 code=1 comm=sh pid=32195 grp=1 res=0
> > Above logs is on reader page, reader task try to read PADDING event
> > after this event and lead to crash.
>
> Ah, it's not an issue with the commit value but the write value.
>
> Can you test this patch.
>
> -- Steve
>
> diff --git a/kernel/trace/ring_buffer.c b/kernel/trace/ring_buffer.c
> index d59b6a328b7f..6bf7706bb33b 100644
> --- a/kernel/trace/ring_buffer.c
> +++ b/kernel/trace/ring_buffer.c
> @@ -2608,6 +2608,9 @@ rb_reset_tail(struct ring_buffer_per_cpu *cpu_buffer,
> /* Mark the rest of the page with padding */
> rb_event_set_padding(event);
>
> + /* Make sure the padding is visible before the write update */
> + smp_wmb();
> +
I checked several ramdumps, most of the padding event that caused crash not be
written here. Because its corresponding ring_buffer_event->time_delta is
not 0, take one of them as an example:
crash> struct ring_buffer_event ffffffd10b553fe4
struct ring_buffer_event {
type_len = 29,
time_delta = 1,
array = 0xffffffd10b553fe8
}
and array[0] is 0x18:
crash> rd ffffffd10b553fe8
ffffffd10b553fe8: 0000000500000018 ........
0x18 = 0xff0 - 0xfd4 - 0x4
0xfd4 is end address of last data event in reader page.
The available space size is 0x18 bytes, and next event want to write is
signal_deliver, this event need 0x28 bytes:
crash> trace_event_raw_signal_deliver -x
struct trace_event_raw_signal_deliver {
struct trace_entry ent;
int sig;
int errno;
int code;
unsigned long sa_handler;
unsigned long sa_flags;
char __data[0];
}
SIZE: 0x28
So trigger rb move tail, tail value in rb_reset_tail is 0xfd4, the
following if condition is false:
if (tail > (BUF_PAGE_SIZE - RB_EVNT_MIN_SIZE))
> /* Set the write back to the previous setting */
> local_sub(length, &tail_page->write);
> return;
> @@ -4580,6 +4583,13 @@ rb_get_reader_page(struct ring_buffer_per_cpu *cpu_buffer)
> goto again;
>
> out:
> + /* If the write is past the end of page, a writer is still updating it */
> + if (reader && reader->write > BUF_PAGE_SIZE)
> + reader = NULL;
> +
> + /* Make sure we see any padding after the write update */
> + smp_rmb();
> +
> /* Update the read_stamp on the first event */
> if (reader && reader->read == 0)
> cpu_buffer->read_stamp = reader->page->time_stamp;
|