Message-ID: <CAKPOu+_DA8XiMAA2ApMj7Pyshve_YWknw8Hdt1=zCy9Y87R1qw@mail.gmail.com>
Date: Sun, 28 Jul 2024 12:49:51 +0200
From: Max Kellermann <max.kellermann@...os.com>
To: David Howells <dhowells@...hat.com>
Cc: Jeff Layton <jlayton@...nel.org>, netfs@...ts.linux.dev, linux-kernel@...r.kernel.org, 
	ceph-devel@...r.kernel.org
Subject: RCU stalls and GPFs in ceph/netfs

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

Powered by blists - more mailing lists