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().
Signed-off-by: Zheng Yejian <[email protected]>
---
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);
local_set(&cpu_buffer->entries_bytes, 0);
local_set(&cpu_buffer->overrun, 0);
--
2.25.1
On Sun, 9 Jul 2023 06:51:44 +0800
Zheng Yejian <[email protected]> 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!
>
> Signed-off-by: Zheng Yejian <[email protected]>
> ---
> 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!
-- Steve
>
> local_set(&cpu_buffer->entries_bytes, 0);
> local_set(&cpu_buffer->overrun, 0);
On 2023/7/10 03:45, Steven Rostedt wrote:
> On Sun, 9 Jul 2023 06:51:44 +0800
> Zheng Yejian <[email protected]> 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: [email protected]
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 <[email protected]>
>> ---
>> 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);
>
>
On Mon, 10 Jul 2023 09:37:52 +0800
Zheng Yejian <[email protected]> wrote:
> teve, IIUC, following tags should be added?
>
> Cc: [email protected]
> Fixes: 48fdc72f23ad ("ring-buffer: Fix accounting of entries when
> removing pages")
> Fixes: 83f40318dab0 ("ring-buffer: Make removal of ring buffer pages
> atomic")
I actually added:
Fixes: a5fb833172eca ("ring-buffer: Fix uninitialized read_stamp")
-- Steve
On 2023/7/13 00:14, Steven Rostedt wrote:
> On Mon, 10 Jul 2023 09:37:52 +0800
> Zheng Yejian <[email protected]> wrote:
>
>> teve, IIUC, following tags should be added?
>>
>> Cc: [email protected]
>> Fixes: 48fdc72f23ad ("ring-buffer: Fix accounting of entries when
>> removing pages")
>> Fixes: 83f40318dab0 ("ring-buffer: Make removal of ring buffer pages
>> atomic")
>
> I actually added:
>
> Fixes: a5fb833172eca ("ring-buffer: Fix uninitialized read_stamp")
>
> -- Steve
>
Yes, a5fb833172eca directly cause the deadloop issue.
--
Thanks,
Zheng Yejian