Re: RCU stalls and GPFs in ceph/netfs

[Jeff Layton]

On Sun, 2024-07-28 at 12:49 +0200, Max Kellermann wrote:
> Hi David,
> 
> in the last few days, I have been chasing a 6.10 regression. After
> updating one of our servers from 6.9.10 to 6.10.1, I found various
> problems that may or may not be caused by the same code change
> (abbreviated):
> 
> [  108.043488] WARNING: CPU: 0 PID: 2860 at fs/ceph/caps.c:3386
> ceph_put_wrbuffer_cap_refs+0x1bb/0x1f0
> [  108.043498] Modules linked in:
> [  108.043500] CPU: 0 PID: 2860 Comm: rsync Not tainted 6.10.1-cm4all1-vm+ #117
> [  108.043505] RIP: 0010:ceph_put_wrbuffer_cap_refs+0x1bb/0x1f0
> [  108.043526] Call Trace:
> [  108.043573]  ? ceph_put_wrbuffer_cap_refs+0x27/0x1f0
> [  108.043575]  ceph_invalidate_folio+0x9a/0xc0
> [  108.043577]  truncate_cleanup_folio+0x52/0x90
> [  108.043583]  truncate_inode_pages_range+0xfe/0x400
> [  108.043585]  ? __rseq_handle_notify_resume+0x25b/0x480
> [  108.043589]  ? vfs_read+0x246/0x340
>
> [  108.043705] BUG: kernel NULL pointer dereference, address: 0000000000000356
> [  108.043948] #PF: supervisor write access in kernel mode
> [  108.044166] #PF: error_code(0x0002) - not-present page
> [  108.044341] PGD 0 P4D 0
> [  108.044465] Oops: Oops: 0002 [#1] SMP PTI
> [  108.048393] Call Trace:
> [  108.050002]  ? ceph_put_snap_context+0xf/0x30
> [  108.050178]  ceph_invalidate_folio+0xa2/0xc0
> [  108.050356]  truncate_cleanup_folio+0x52/0x90
> [  108.050532]  truncate_inode_pages_range+0xfe/0x400
> [  108.050711]  ? __rseq_handle_notify_resume+0x25b/0x480
> [  108.050896]  ? vfs_read+0x246/0x340
> 
> [  104.587469] Oops: general protection fault, probably for
> non-canonical address 0xe01ffbf110207cde: 0000 [#1] SMP KASAN PTI
> [  104.588429] KASAN: maybe wild-memory-access in range
> [0x00ffff888103e6f0-0x00ffff888103e6f7]
> [  104.588663] CPU: 6 PID: 2882 Comm: php-cgi8.1 Not tainted
> 6.10.1-cm4all1-vm+ #120
> [  104.591880] Call Trace:
> [  104.592015]  <TASK>
> [  104.592207]  ? die_addr+0x3c/0xa0
> [  104.592411]  ? exc_general_protection+0x113/0x200
> [  104.592650]  ? asm_exc_general_protection+0x22/0x30
> [  104.592876]  ? netfs_alloc_request+0x761/0xbd0
> [  104.593099]  ? netfs_read_folio+0x11f/0xad0
> [  104.593318]  ? netfs_read_folio+0xf6/0xad0
> [  104.593498]  ? filemap_get_read_batch+0x2dd/0x650
> [  104.593677]  ? __pfx_netfs_read_folio+0x10/0x10
> [  104.593854]  filemap_read_folio+0xb2/0x210
> [  104.594042]  ? __pfx_filemap_read_folio+0x10/0x10
> [  104.594226]  ? __pfx_stack_trace_save+0x10/0x10
> [  104.594417]  ? stack_depot_save_flags+0x24/0x690
> [  104.594616]  filemap_get_pages+0xaf8/0x1200
> [  104.594821]  ? __pfx_filemap_get_pages+0x10/0x10
> [  104.595012]  ? _raw_spin_lock+0x7a/0xd0
> 
>  rcu: INFO: rcu_sched self-detected stall on CPU
>  rcu:         7-....: (2099 ticks this GP)
> idle=4874/1/0x4000000000000000 softirq=1503/1503 fqs=1049
>  rcu:         (t=2100 jiffies g=4053 q=344 ncpus=16)
>  CPU: 7 PID: 3443 Comm: php-was Not tainted 6.9.0-vm+ #139
>  Call Trace:
>   <IRQ>
>   ? rcu_dump_cpu_stacks+0xed/0x170
>   ? rcu_sched_clock_irq+0x558/0xbc0
>   ? __smp_call_single_queue+0x8b/0xe0
>   ? update_process_times+0x69/0xa0
>   ? tick_nohz_handler+0x87/0x120
>   ? __pfx_tick_nohz_handler+0x10/0x10
>   ? __hrtimer_run_queues+0x110/0x250
>   ? hrtimer_interrupt+0xf6/0x230
>   ? __sysvec_apic_timer_interrupt+0x51/0x120
>   ? sysvec_apic_timer_interrupt+0x60/0x80
>   </IRQ>
>   <TASK>
>   ? asm_sysvec_apic_timer_interrupt+0x16/0x20
>   ? __xas_next+0xc6/0xe0
>   filemap_get_read_batch+0x163/0x240
>   filemap_get_pages+0x9a/0x5c0
>   filemap_read+0xd9/0x310
>   ? __ceph_get_caps+0xd5/0x580
>   ? __ceph_caps_issued_mask+0x156/0x210
> 
> These servers have Ceph mounts with fscache.
> 
> At first, it looked like these bugs could be triggered easily and I
> did a bisect; however the WARNING in Ceph code went away, and going
> back further in the git history made reproducing the problem less
> likely. I tried KASAN but it didn't give any more information.
> 
> After a few dead ends (due to some false "good" commits), the bisect
> arrived at your commit 2e9d7e4b984a61 ("mm: Remove the PG_fscache
> alias for PG_private_2"). This commit easily reproduces the RCU stalls
> on my server. The preceding commit 2ff1e97587f4d3 ("netfs: Replace
> PG_fscache by setting folio->private and marking dirty") never did,
> not even after an hour of rebooting and retrying.
> 

That is really weird. AFAICT, 2e9d7e4b984a61 is just removing some
wrapper functions and changing the names of some others. There should
be no functional changes there. I'll keep looking but I don't see how
that commit would break anything.

> This is how the RCU stall looks like on 2e9d7e4b984a61:
> 
>  rcu: INFO: rcu_sched self-detected stall on CPU
>  rcu:         6-....: (46220 ticks this GP)
> idle=4bfc/1/0x4000000000000000 softirq=1594/1594 fqs=21190
>  rcu:         (t=46221 jiffies g=2577 q=7220 ncpus=16)
>  CPU: 6 PID: 3119 Comm: wordpress-manag Not tainted
> 6.9.0-rc6-vm-00004-gae678317b95e #160
>  Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS 1.14.0-2 04/01/2014
>  RIP: 0010:filemap_get_read_batch+0x7b/0x240
>  Code: 48 c7 44 24 30 00 00 00 00 48 89 e7 e8 ee d4 99 00 48 85 c0 0f
> 84 bf 00 00 00 48 89 c7 48 81 ff 06 04 00 00 0f 84 fd 00 00 00 <48> 81
> ff 02 04 00 00 0f 84 ca 00 00 00 48 3b 6c 24 08 0f 82 97 00
>  RSP: 0018:ffffbb2500fef8f8 EFLAGS: 00000296
>  RAX: ffffefa30509c740 RBX: ffffbb2500fefa50 RCX: 0000000000000000
>  RDX: 0000000000000000 RSI: 0000000000000000 RDI: ffffefa30509c740
>  RBP: 0000000000000003 R08: 0000000000000000 R09: ffffbb2500fefaec
>  R10: ffff9acb4a77ec80 R11: 0000000000000000 R12: ffffbb2500fefc58
>  R13: ffff9acb5c381d00 R14: 0000000000000000 R15: ffffbb2500fefc80
>  FS:  00007f5f6b6eeb80(0000) GS:ffff9ad64ef80000(0000) knlGS:0000000000000000
>  CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
>  CR2: 00005623dea2b3d8 CR3: 000000011b658003 CR4: 00000000001706b0
>  DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000
>  DR3: 0000000000000000 DR6: 00000000fffe0ff0 DR7: 0000000000000400
>  Call Trace:
>   <IRQ>
>   ? rcu_dump_cpu_stacks+0xed/0x170
>   ? rcu_sched_clock_irq+0x558/0xbc0
>   ? __smp_call_single_queue+0x8b/0xe0
>   ? update_process_times+0x69/0xa0
>   ? tick_nohz_handler+0x87/0x120
>   ? __pfx_tick_nohz_handler+0x10/0x10
>   ? __hrtimer_run_queues+0x110/0x250
>   ? hrtimer_interrupt+0xf6/0x230
>   ? __sysvec_apic_timer_interrupt+0x51/0x120
>   ? sysvec_apic_timer_interrupt+0x60/0x80
>   </IRQ>
>   <TASK>
>   ? asm_sysvec_apic_timer_interrupt+0x16/0x20
>   ? filemap_get_read_batch+0x7b/0x240
>   ? filemap_get_read_batch+0x163/0x240
>   filemap_get_pages+0x9a/0x5c0
>   ? __call_rcu_common.constprop.0+0x87/0x220
>   filemap_read+0xd9/0x310
>   ? __ceph_get_caps+0xd5/0x580
>   ? terminate_walk+0x95/0x100
>   ? path_openat+0xca3/0xf10
>   ceph_read_iter+0x3e1/0x620
>   vfs_read+0x23a/0x330
>   ksys_read+0x63/0xe0
>   do_syscall_64+0x66/0x100
>   ? __alloc_pages+0x176/0x2e0
>   ? __count_memcg_events+0x4e/0xb0
>   ? __pte_offset_map_lock+0x60/0xe0
>   ? __mod_memcg_lruvec_state+0x89/0x110
>   ? __lruvec_stat_mod_folio+0x41/0x70
>   ? do_anonymous_page+0x6dc/0x840
>   ? __handle_mm_fault+0x936/0x1250
>   ? __count_memcg_events+0x4e/0xb0
>   ? handle_mm_fault+0xa2/0x2a0
>   ? do_user_addr_fault+0x308/0x5d0
>   ? exc_page_fault+0x62/0x120
>   ? irqentry_exit_to_user_mode+0x40/0xf0
>   entry_SYSCALL_64_after_hwframe+0x76/0x7e
> 
> When that happens, the process is at 100% CPU usage, but gdb/strace
> cannot attach, and /proc/PID/stack is empty. I tried "perf record" and
> found the process was busy-looping inside filemap_get_pages(), calling
> filemap_get_read_batch() over and over, saw some xas_ calls but
> nothing else.
> 
> Your commit 2e9d7e4b984a61 is too obscure for me, I don't know that
> part of the kernel, and I can't imagine how it can cause such a
> regression, but maybe you have an idea?
> 
> I can get you more information or try patches with more debugging code
> if you want.
> 


-- 
Jeff Layton <jlayton@xxxxxxxxxx>