Re: [PATCH] tracing/snapshot: Avoid CPU buffer swap during reserve/commit

On 2026/7/30 19:11, Steven Rostedt wrote:
> On Thu, 30 Jul 2026 12:10:18 +0800
> Tengda Wu <[email protected]> wrote:
> 
>> On 2026/7/30 10:04, Steven Rostedt wrote:
>>> On Thu, 30 Jul 2026 01:19:12 +0000
>>> Tengda Wu <[email protected]> wrote:
>>>   
>>>> Commit 3163f635b20e ("tracing: Fix race issue between cpu buffer write
>>>> and swap") fixed most of the race conditions between snapshot's
>>>> ring_buffer_swap_cpu and ring_buffer_lock_{reserve, commit}. It achieved
>>>> this by replacing the asynchronous swap with smp_call_function_single to
>>>> trigger an interrupt on the target CPU to handle the swap.  
>>>
>>> I'm curious. How did you discover this race?
>>>   
>>
>> Just run the POC provided in commit 3163f635b20e [1] day after day, and
>> the issue occurs. The call trace points out that the problem happens when
>> tracing the function:
>>
>> [1] https://git.kernel.org/pub/scm/linux/kernel/git/torvalds/linux.git/commit/?id=3163f635b20e9e1fb4659e74f47918c9dddfe64e
>>
>> [   55.864661] ------------[ cut here ]------------
>> [   55.865536] WARNING: CPU: 0 PID: 1451 at kernel/trace/ring_buffer.c:3096 rb_commit.constprop.0+0x367/0x820
>> [   55.866993] Modules linked in: binfmt_misc rpcrdma rdma_cm iw_cm ib_cm ib_core nfsd auth_rpcgss nfs_acl lockd grace sunrpc
>> [   55.869583] CPU: 0 PID: 1451 Comm: DTS202602110403 Not tainted 5.10.0+ #1
>> [   55.871729] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS rel-1.16.3-0-ga6ed6b701f0a-prebuilt.qemu.org 04/01/2014
>> [   55.874671] RIP: 0010:rb_commit.constprop.0+0x367/0x820
>> [   55.871729] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS rel-1.16.3-0-ga6ed6b701f0a-prebuilt.qemu.org 04/0
>> 1/2014
>> [   55.874671] RIP: 0010:rb_commit.constprop.0+0x367/0x820
>> [   55.875637] Code: 8d 7f 10 48 89 f9 48 c1 e9 03 80 3c 01 00 0f 85 af 03 00 00 49 8b 5f 10 be 04 00 00 00 48 8d 7b 08 e8 dd a0 41 00 f0 ff 43 08 <0f> 0b 48 83 c4 60 5b 5d 41 5c 41 5d 41 5e 41 5f e9 54 58 2e 02 be
>> [   55.878367] RSP: 0018:ffffc90000b57a30 EFLAGS: 00010202
>> [   55.879227] RAX: 0000000000000001 RBX: ffff88800105ec00 RCX: ffffffff9e11db33
>> [   55.880366] RDX: ffffed100020bd82 RSI: 0000000000000004 RDI: ffff88800105ec08
>> [   55.881470] RBP: ffff88800105ec00 R08: 0000000000000001 R09: ffff88800105ec0b
>> [   55.882563] R10: ffffed100020bd81 R11: 0000000000000001 R12: ffff8880010520a0
>> [   55.883681] R13: ffff88800105ec40 R14: 0000000000000000 R15: ffff888001052000
>> [   55.884761] FS:  00007f6be3c5d740(0000) GS:ffff888065200000(0000) knlGS:0000000000000000
>> [   55.885980] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
>> [   55.886876] CR2: 000055d8257879e0 CR3: 0000000005c78003 CR4: 0000000000770ef0
>> [   55.887994] DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000
>> [   55.889113] DR3: 0000000000000000 DR6: 00000000fffe0ff0 DR7: 0000000000000400
>> [   55.890232] PKRU: 55555554
>> [   55.890740] Call Trace:
>> [   55.891221]  ? s_show+0x2f0/0x2f0
>> [   55.891815]  ? kallsyms_lookup_size_offset+0x130/0x130
>> [   55.892684]  ring_buffer_unlock_commit+0x68/0x510
>> [   55.893490]  ? kallsyms_lookup_size_offset+0x130/0x130
>> [   55.894341]  ? seq_print_sym+0x13d/0x1a0
>> [   55.895024]  function_trace_call+0x266/0x370
>> [   55.895754]  ? ring_buffer_iter_advance+0x2f/0x80
>> [   55.896584]  0xffffffffc037406a
>> [   55.897180]  ? ring_buffer_iter_advance+0x2f/0x80
>> [   55.897966]  ? kallsyms_lookup+0x5/0x260
>> [   55.898640]  ? _raw_write_unlock_irqrestore+0x60/0x60
>> [   55.899481]  kallsyms_lookup+0x5/0x260
>>
>> The vmcore indicates that the buffer in CPU 0 was swapped:
>>
>> * array_buffer->buffers:
>>
>>   cpu 0, ffff888001052000, committing = 0, entries = 10010687, commits = 10010686
>>   cpu 1, ffff888001fa4400, committing = 0, entries = 18780536, commits = 18780536
>>   cpu 2, ffff888100110400, committing = 0, entries = 20905896, commits = 20905896
>>   cpu 3, ffff888100111c00, committing = 0, entries = 20825484, commits = 20825484
>>
>> * max_buffer->buffers:
>>
>>   cpu 0, ffff888001052400, committing = 1, entries = 9768877, commits = 9768878
>>   cpu 1, ffff888001fa6400, committing = 0, entries = 0, commits = 0
>>   cpu 2, ffff888100112400, committing = 0, entries = 0, commits = 0
>>   cpu 3, ffff888100112800, committing = 0, entries = 0, commits = 0
>>
>> We first checked if the problem could occur before rb_start_commit, but we
>> just couldn't get past the 'READ_ONCE(cpu_buffer->buffer) != buffer' check.
>> So we turned our attention to what happens after rb_start_commit, to see
>> if the committing counter might drop to 0 and then get incremented again.
>> In the end, we found that only rb_move_tail could cause this.
>>
>> Honestly, it was a pretty tough journey.
> 
> I bet. Thanks for doing that work.
> 
>> The work_on_cpu approach does not fix the issue inside the ring buffer
>> itself. However, as far as the current codebase is concerned, the
>> snapshot operation is the only path that triggers a CPU buffer swap.
>> This fix has minimal impact and does not expose users to the internal
>> intermediate state of the ring buffer when they echo to snapshot, thus
>> avoiding the confusion of hitting an -EBUSY error.
> 
> I admit it is a way to avoid the -EBUSY, which is a separate issue and one
> that always existed. Your patch can be added to solve that for this
> specific use case. But then it would not be a fix, just an enhancement.
> 
>>
>> If we were to fix this from within the ring buffer, we might need to
>> introduce a new flag (e.g., a local_t variable similar to committing)
>> to detect such race windows. Based on the current analysis, this race
>> only occurs during a very brief window in rb_move_tail. Adding a new
>> flag for this seems unnecessary.
>>
>> Alternatively, we could simply remove both rb_end_commit(cpu_buffer)
>> and local_inc(&cpu_buffer->committing) inside rb_move_tail, thereby
>> eliminating the 1-0-1 transition of committing and preventing such a
>> race window from existing in the first place. In principle, committing
>> should remain non-zero from the moment rb_start_commit is called until
>> the commit is finished.
> 
> Actually there already exists something that can be used:
> 
>   cpu_buffer->current_context
> 
> It is set to prevent recursion in the ring buffer when the commit starts,
> and is cleared after the commit is finished. If it is anything other than
> 0, it means a commit is in progress and the swap should return -EBUSY.
> 
> This is not affected by the move to next page.
> 
> Something like this should fix it:
> 
> diff --git a/kernel/trace/ring_buffer.c b/kernel/trace/ring_buffer.c
> index 804ccae694d2..ce195bc4136a 100644
> --- a/kernel/trace/ring_buffer.c
> +++ b/kernel/trace/ring_buffer.c
> @@ -6850,7 +6850,7 @@ int ring_buffer_swap_cpu(struct trace_buffer *buffer_a,
>  {
>  	struct ring_buffer_per_cpu *cpu_buffer_a;
>  	struct ring_buffer_per_cpu *cpu_buffer_b;
> -	int ret = -EINVAL;
> +	int ret = -EBUSY;
>  
>  	if (!cpumask_test_cpu(cpu, buffer_a->cpumask) ||
>  	    !cpumask_test_cpu(cpu, buffer_b->cpumask))
> @@ -6891,10 +6891,10 @@ int ring_buffer_swap_cpu(struct trace_buffer *buffer_a,
>  	atomic_inc(&cpu_buffer_a->record_disabled);
>  	atomic_inc(&cpu_buffer_b->record_disabled);
>  
> -	ret = -EBUSY;
> -	if (local_read(&cpu_buffer_a->committing))
> +	/* Do not swap if either buffer is in the process of writing */
> +	if (cpu_buffer_a->current_context)
>  		goto out_dec;
> -	if (local_read(&cpu_buffer_b->committing))
> +	if (cpu_buffer_b->current_context)
>  		goto out_dec;
>  
>  	/*
> 
> Care to send both patches? One with the above to fix the problem, and this
> current patch to make the swap not return -EBUSY. The first would go to
> stable, the latter would go in the next merge window.
> 
> -- Steve

Certainly, I'd be happy to send both patches.

Thank you very much for the detailed analysis and for providing a concrete fix.
I really appreciate the guidance.

I'll make sure to include proper commit messages and tags. I'll send them out shortly.

Thanks,
Tengda