RCU stalls and GPFs in ceph/netfs

RCU stalls and GPFs in ceph/netfs

[Max Kellermann]

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.

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.

Max

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@kernel.org>

Re: RCU stalls and GPFs in ceph/netfs

[Max Kellermann]

On Sun, Jul 28, 2024 at 1:45 PM Jeff Layton <jlayton@kernel.org> wrote:
> 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.

Exactly what I thought, I could not imagine how this commit could
cause such a bug. The only chance was that netfs_rreq_assess() now
always directly calls netfs_rreq_completed(), but not
netfs_rreq_write_to_cache(), but I don't know what that means - this
different code path could be a candidate for doing something
differently. Maybe it's an old bug that only got revealed by this
change.

Anyway, I tried to verify this and the preceding commit for hours, and
the picture was consistent: that commit reproduces the RCU stall
within minutes (though only 50% or so of all boots), and the previous
commit never did. There is still a tiny chance that I just wasn't
trying hard enough. I'm out of ideas, and all I can do now is start
digging really deeply into this code, but I thought it would be more
productive to reach out to the people who wrote it.

Max

Re: RCU stalls and GPFs in ceph/netfs

[Max Kellermann]

On Sun, Jul 28, 2024 at 12:49 PM Max Kellermann
<max.kellermann@ionos.com> wrote:
> 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):

Today, I gave this another try and it turned out to be a simple
leftover folio_end_private_2() call. It was really caused by commit
ae678317b95e ("netfs: Remove deprecated use of PG_private_2 as a
second writeback flag"), after all.

I posted two candidate patches which both fix this bug;

Minimal fix: https://lore.kernel.org/lkml/20240729090639.852732-1-max.kellermann@ionos.com/
Fix which removes a bunch of obsolete code:
https://lore.kernel.org/lkml/20240729091532.855688-1-max.kellermann@ionos.com/

You decide which one you prefer.

Max

Re: RCU stalls and GPFs in ceph/netfs

[Max Kellermann]

On Mon, Jul 29, 2024 at 11:18 AM Max Kellermann
<max.kellermann@ionos.com> wrote:
> I posted two candidate patches which both fix this bug;
>
> Minimal fix: https://lore.kernel.org/lkml/20240729090639.852732-1-max.kellermann@ionos.com/
> Fix which removes a bunch of obsolete code:
> https://lore.kernel.org/lkml/20240729091532.855688-1-max.kellermann@ionos.com/

These patches do fix the RCU stall bug (and should be merged), but
after running one cluster with my patch for a while, I found more Ceph
crashes:

 ------------[ cut here ]------------
 WARNING: CPU: 3 PID: 1925 at fs/ceph/caps.c:3386
ceph_put_wrbuffer_cap_refs+0x1bb/0x1f0
 Modules linked in:
 CPU: 3 PID: 1925 Comm: kworker/3:2 Not tainted 6.10.2-cm4all1-vm+ #168
 Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS 1.14.0-2 04/01/2014
 Workqueue: ceph-cap ceph_cap_reclaim_work
 RIP: 0010:ceph_put_wrbuffer_cap_refs+0x1bb/0x1f0
 Code: 30 45 89 f5 bd 01 00 00 00 41 83 c6 01 31 d2 e9 fa fe ff ff 45
8d 6e ff 31 ed 31 d2 48 83 bb 18 04 00 00 00 0f 84 e4 fe ff ff <0f> 0b
e9 dd fe ff ff 45 8d 6e ff bd 01 00 00 00 ba 01 00 00 00 48
 RSP: 0018:ffffb9a7406cba78 EFLAGS: 00010282
 RAX: ffff9a2d42b7eb20 RBX: ffff9a2d42b7e688 RCX: ffffdbdadc446d80
 RDX: 0000000000000000 RSI: ffff9a2d42b7eb18 RDI: ffff9a2d42b7e940
 RBP: 0000000000000000 R08: ffffffffffffffc0 R09: ffff9a2d4254fc40
 R10: 0000000000000020 R11: fefefefefefefeff R12: ffff9a2d42b7e940
 R13: 00000000ffffffff R14: 0000000000000000 R15: 0000000000000000
 FS:  0000000000000000(0000) GS:ffff9a384eec0000(0000) knlGS:0000000000000000
 CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
 CR2: 000055b248c82657 CR3: 000000010d31c002 CR4: 00000000001706b0
 DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000
 DR3: 0000000000000000 DR6: 00000000fffe0ff0 DR7: 0000000000000400
 Call Trace:
  <TASK>
  ? __warn+0x7c/0x110
  ? ceph_put_wrbuffer_cap_refs+0x1bb/0x1f0
  ? report_bug+0x14c/0x170
  ? handle_bug+0x3c/0x70
  ? exc_invalid_op+0x13/0x60
  ? asm_exc_invalid_op+0x16/0x20
  ? ceph_put_wrbuffer_cap_refs+0x1bb/0x1f0
  ? ceph_put_wrbuffer_cap_refs+0x27/0x1f0
  ceph_invalidate_folio+0x9a/0xc0
  truncate_cleanup_folio+0x52/0x90
  truncate_inode_pages_range+0xfe/0x400
  ceph_evict_inode+0x40/0x200
  evict+0xc5/0x170
  __dentry_kill+0x6e/0x160
  dput+0xcb/0x180
  __dentry_leases_walk+0x28d/0x430
  ceph_trim_dentries+0xac/0x100
  ceph_cap_reclaim_work+0x15/0x50
  process_one_work+0x138/0x2e0
  worker_thread+0x2b9/0x3d0
  ? __pfx_worker_thread+0x10/0x10
  kthread+0xba/0xe0
  ? __pfx_kthread+0x10/0x10
  ret_from_fork+0x30/0x50
  ? __pfx_kthread+0x10/0x10
  ret_from_fork_asm+0x1a/0x30
  </TASK>
 ---[ end trace 0000000000000000 ]---
 BUG: kernel NULL pointer dereference, address: 0000000000000356
 #PF: supervisor write access in kernel mode
 #PF: error_code(0x0002) - not-present page
 PGD 0 P4D 0
 Oops: Oops: 0002 [#1] SMP PTI
 CPU: 3 PID: 1925 Comm: kworker/3:2 Tainted: G        W
6.10.2-cm4all1-vm+ #168
 Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS 1.14.0-2 04/01/2014
 Workqueue: ceph-cap ceph_cap_reclaim_work
 RIP: 0010:ceph_put_snap_context+0xf/0x30
 Code: 0f 1f 84 00 00 00 00 00 0f 1f 00 90 90 90 90 90 90 90 90 90 90
90 90 90 90 90 90 0f 1f 44 00 00 48 85 ff 74 12 b8 ff ff ff ff <f0> 0f
c1 07 83 f8 01 74 09 85 c0 7e 0a c3 cc cc cc cc e9 3a 62 70
 RSP: 0018:ffffb9a7406cbaa8 EFLAGS: 00010206
 RAX: 00000000ffffffff RBX: ffffdbdadc4465c0 RCX: ffffdbdadc446d80
 RDX: 0000000000000000 RSI: ffff9a2d42b7eb18 RDI: 0000000000000356
 RBP: 0000000000001000 R08: ffffffffffffffc0 R09: ffff9a2d4254fc40
 R10: 0000000000000020 R11: fefefefefefefeff R12: 0000000000000356
 R13: ffff9a2d42b7e688 R14: ffffffffffffffff R15: 0000000000000001
 FS:  0000000000000000(0000) GS:ffff9a384eec0000(0000) knlGS:0000000000000000
 CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
 CR2: 0000000000000356 CR3: 000000010d31c002 CR4: 00000000001706b0
 DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000
 DR3: 0000000000000000 DR6: 00000000fffe0ff0 DR7: 0000000000000400
 Call Trace:
  <TASK>
  ? __die+0x1f/0x60
  ? page_fault_oops+0x158/0x450
  ? search_extable+0x22/0x30
  ? ceph_put_snap_context+0xf/0x30
  ? search_module_extables+0xe/0x40
  ? exc_page_fault+0x62/0x120
  ? asm_exc_page_fault+0x22/0x30
  ? ceph_put_snap_context+0xf/0x30
  ceph_invalidate_folio+0xa2/0xc0
  truncate_cleanup_folio+0x52/0x90
  truncate_inode_pages_range+0xfe/0x400
  ceph_evict_inode+0x40/0x200
  evict+0xc5/0x170
  __dentry_kill+0x6e/0x160
  dput+0xcb/0x180
  __dentry_leases_walk+0x28d/0x430
  ceph_trim_dentries+0xac/0x100
  ceph_cap_reclaim_work+0x15/0x50
  process_one_work+0x138/0x2e0
  worker_thread+0x2b9/0x3d0
  ? __pfx_worker_thread+0x10/0x10
  kthread+0xba/0xe0
  ? __pfx_kthread+0x10/0x10
  ret_from_fork+0x30/0x50
  ? __pfx_kthread+0x10/0x10
  ret_from_fork_asm+0x1a/0x30
  </TASK>
 Modules linked in:
 CR2: 0000000000000356
 ---[ end trace 0000000000000000 ]---
 RIP: 0010:ceph_put_snap_context+0xf/0x30
 Code: 0f 1f 84 00 00 00 00 00 0f 1f 00 90 90 90 90 90 90 90 90 90 90
90 90 90 90 90 90 0f 1f 44 00 00 48 85 ff 74 12 b8 ff ff ff ff <f0> 0f
c1 07 83 f8 01 74 09 85 c0 7e 0a c3 cc cc cc cc e9 3a 62 70
 RSP: 0018:ffffb9a7406cbaa8 EFLAGS: 00010206
 RAX: 00000000ffffffff RBX: ffffdbdadc4465c0 RCX: ffffdbdadc446d80
 RDX: 0000000000000000 RSI: ffff9a2d42b7eb18 RDI: 0000000000000356
 RBP: 0000000000001000 R08: ffffffffffffffc0 R09: ffff9a2d4254fc40
 R10: 0000000000000020 R11: fefefefefefefeff R12: 0000000000000356
 R13: ffff9a2d42b7e688 R14: ffffffffffffffff R15: 0000000000000001
 FS:  0000000000000000(0000) GS:ffff9a384eec0000(0000) knlGS:0000000000000000
 CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
 CR2: 0000000000000356 CR3: 000000010d31c002 CR4: 00000000001706b0
 DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000
 DR3: 0000000000000000 DR6: 00000000fffe0ff0 DR7: 0000000000000400
 note: kworker/3:2[1925] exited with irqs disabled

The bug hunt continues.

Max

Re: RCU stalls and GPFs in ceph/netfs

[Max Kellermann]

On Mon, Jul 29, 2024 at 12:17 PM Max Kellermann
<max.kellermann@ionos.com> wrote:
>  BUG: kernel NULL pointer dereference, address: 0000000000000356

This is obviously NETFS_FOLIO_COPY_TO_CACHE; this looks like it was
caused by 2ff1e97587f4 ("netfs: Replace PG_fscache by setting
folio->private and marking dirty"). That commit uses
folio_attach_private(), but fs/ceph already used
folio_attach_private() for something else.