[<prev] [next>] [<thread-prev] [thread-next>] [day] [month] [year] [list]
Message-ID: <63ff741f-b781-37da-3f47-15d1a8ff76a4@huawei.com>
Date: Mon, 10 Jul 2023 09:37:52 +0800
From: Zheng Yejian <zhengyejian1@...wei.com>
To: Steven Rostedt <rostedt@...dmis.org>
CC: <mhiramat@...nel.org>, <linux-kernel@...r.kernel.org>,
<linux-trace-kernel@...r.kernel.org>
Subject: Re: [PATCH] ring-buffer: Fix deadloop issue on reading trace_pipe
On 2023/7/10 03:45, Steven Rostedt wrote:
> On Sun, 9 Jul 2023 06:51:44 +0800
> Zheng Yejian <zhengyejian1@...wei.com> wrote:
>
>> Soft lockup occurs when reading file 'trace_pipe':
>>
>> watchdog: BUG: soft lockup - CPU#6 stuck for 22s! [cat:4488]
>> [...]
>> RIP: 0010:ring_buffer_empty_cpu+0xed/0x170
>> RSP: 0018:ffff88810dd6fc48 EFLAGS: 00000246
>> RAX: 0000000000000000 RBX: 0000000000000246 RCX: ffffffff93d1aaeb
>> RDX: ffff88810a280040 RSI: 0000000000000008 RDI: ffff88811164b218
>> RBP: ffff88811164b218 R08: 0000000000000000 R09: ffff88815156600f
>> R10: ffffed102a2acc01 R11: 0000000000000001 R12: 0000000051651901
>> R13: 0000000000000000 R14: ffff888115e49500 R15: 0000000000000000
>> [...]
>> CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033
>> CR2: 00007f8d853c2000 CR3: 000000010dcd8000 CR4: 00000000000006e0
>> DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000
>> DR3: 0000000000000000 DR6: 00000000fffe0ff0 DR7: 0000000000000400
>> Call Trace:
>> __find_next_entry+0x1a8/0x4b0
>> ? peek_next_entry+0x250/0x250
>> ? down_write+0xa5/0x120
>> ? down_write_killable+0x130/0x130
>> trace_find_next_entry_inc+0x3b/0x1d0
>> tracing_read_pipe+0x423/0xae0
>> ? tracing_splice_read_pipe+0xcb0/0xcb0
>> vfs_read+0x16b/0x490
>> ksys_read+0x105/0x210
>> ? __ia32_sys_pwrite64+0x200/0x200
>> ? switch_fpu_return+0x108/0x220
>> do_syscall_64+0x33/0x40
>> entry_SYSCALL_64_after_hwframe+0x61/0xc6
>>
>> Through the vmcore, I found it's because in tracing_read_pipe(),
>> ring_buffer_empty_cpu() found some buffer is not empty but then it
>> cannot read anything due to "rb_num_of_entries() == 0" always true,
>> Then it infinitely loop the procedure due to user buffer not been
>> filled, see following code path:
>>
>> tracing_read_pipe() {
>> ... ...
>> waitagain:
>> tracing_wait_pipe() // 1. find non-empty buffer here
>> trace_find_next_entry_inc() // 2. loop here try to find an entry
>> __find_next_entry()
>> ring_buffer_empty_cpu(); // 3. find non-empty buffer
>> peek_next_entry() // 4. but peek always return NULL
>> ring_buffer_peek()
>> rb_buffer_peek()
>> rb_get_reader_page()
>> // 5. because rb_num_of_entries() == 0 always true here
>> // then return NULL
>> // 6. user buffer not been filled so goto 'waitgain'
>> // and eventually leads to an deadloop in kernel!!!
>> }
>>
>> By some analyzing, I found that when resetting ringbuffer, the 'entries'
>> of its pages are not all cleared (see rb_reset_cpu()). Then when reducing
>> the ringbuffer, and if some reduced pages exist dirty 'entries' data, they
>> will be added into 'cpu_buffer->overrun' (see rb_remove_pages()), which
>> cause wrong 'overrun' count and eventually cause the deadloop issue.
>>
>> To fix it, we need to clear every pages in rb_reset_cpu().
>
> Nice catch and analysis!
>
Thanks!
Steve, IIUC, following tags should be added?
Cc: stable@...r.kernel.org
Fixes: 48fdc72f23ad ("ring-buffer: Fix accounting of entries when
removing pages")
Fixes: 83f40318dab0 ("ring-buffer: Make removal of ring buffer pages
atomic")
---
Thanks,
Zheng Yejian
>>
>> Signed-off-by: Zheng Yejian <zhengyejian1@...wei.com>
>> ---
>> kernel/trace/ring_buffer.c | 24 +++++++++++++++---------
>> 1 file changed, 15 insertions(+), 9 deletions(-)
>>
>> diff --git a/kernel/trace/ring_buffer.c b/kernel/trace/ring_buffer.c
>> index 834b361a4a66..14d8001140c8 100644
>> --- a/kernel/trace/ring_buffer.c
>> +++ b/kernel/trace/ring_buffer.c
>> @@ -5242,28 +5242,34 @@ unsigned long ring_buffer_size(struct trace_buffer *buffer, int cpu)
>> }
>> EXPORT_SYMBOL_GPL(ring_buffer_size);
>>
>> +static void rb_clear_buffer_page(struct buffer_page *page)
>> +{
>> + local_set(&page->write, 0);
>> + local_set(&page->entries, 0);
>> + rb_init_page(page->page);
>> + page->read = 0;
>> +}
>> +
>> static void
>> rb_reset_cpu(struct ring_buffer_per_cpu *cpu_buffer)
>> {
>> + struct buffer_page *page;
>> +
>> rb_head_page_deactivate(cpu_buffer);
>>
>> cpu_buffer->head_page
>> = list_entry(cpu_buffer->pages, struct buffer_page, list);
>> - local_set(&cpu_buffer->head_page->write, 0);
>> - local_set(&cpu_buffer->head_page->entries, 0);
>> - local_set(&cpu_buffer->head_page->page->commit, 0);
>> -
>> - cpu_buffer->head_page->read = 0;
>> + rb_clear_buffer_page(cpu_buffer->head_page);
>> + list_for_each_entry(page, cpu_buffer->pages, list) {
>> + rb_clear_buffer_page(page);
>> + }
>>
>> cpu_buffer->tail_page = cpu_buffer->head_page;
>> cpu_buffer->commit_page = cpu_buffer->head_page;
>>
>> INIT_LIST_HEAD(&cpu_buffer->reader_page->list);
>> INIT_LIST_HEAD(&cpu_buffer->new_pages);
>> - local_set(&cpu_buffer->reader_page->write, 0);
>> - local_set(&cpu_buffer->reader_page->entries, 0);
>> - local_set(&cpu_buffer->reader_page->page->commit, 0);
>> - cpu_buffer->reader_page->read = 0;
>> + rb_clear_buffer_page(cpu_buffer->reader_page);
>
> Looks good. I'll apply it shortly and start running it through my tests. >
Thanks!
> Thanks!
>
> -- Steve
>
>>
>> local_set(&cpu_buffer->entries_bytes, 0);
>> local_set(&cpu_buffer->overrun, 0);
>
>
Powered by blists - more mailing lists