Re: 5.4.188 and later: massive performance regression with nfsd

[Chuck Lever III]

> On May 11, 2022, at 11:30 AM, Wolfgang Walter <linux@xxxxxxx> wrote:
> 
> Am 2022-05-11 16:36, schrieb Chuck Lever III:
>>> On May 11, 2022, at 10:23 AM, Greg KH <gregkh@xxxxxxxxxxxxxxxxxxx> wrote:
>>> On Wed, May 11, 2022 at 02:16:19PM +0000, Chuck Lever III wrote:
>>>>> On May 11, 2022, at 8:38 AM, Greg KH <gregkh@xxxxxxxxxxxxxxxxxxx> wrote:
>>>>> On Wed, May 11, 2022 at 12:03:13PM +0200, Wolfgang Walter wrote:
>>>>>> Hi,
>>>>>> starting with 5.4.188 wie see a massive performance regression on our
>>>>>> nfs-server. It basically is serving requests very very slowly with cpu
>>>>>> utilization of 100% (with 5.4.187 and earlier it is 10%) so that it is
>>>>>> unusable as a fileserver.
>>>>>> The culprit are commits (or one of it):
>>>>>> c32f1041382a88b17da5736886da4a492353a1bb "nfsd: cleanup
>>>>>> nfsd_file_lru_dispose()"
>>>>>> 628adfa21815f74c04724abc85847f24b5dd1645 "nfsd: Containerise filecache
>>>>>> laundrette"
>>>>>> (upstream 36ebbdb96b694dd9c6b25ad98f2bbd263d022b63 and
>>>>>> 9542e6a643fc69d528dfb3303f145719c61d3050)
>>>>>> If I revert them in v5.4.192 the kernel works as before and performance is
>>>>>> ok again.
>>>>>> I did not try to revert them one by one as any disruption of our nfs-server
>>>>>> is a severe problem for us and I'm not sure if they are related.
>>>>>> 5.10 and 5.15 both always performed very badly on our nfs-server in a
>>>>>> similar way so we were stuck with 5.4.
>>>>>> I now think this is because of 36ebbdb96b694dd9c6b25ad98f2bbd263d022b63
>>>>>> and/or 9542e6a643fc69d528dfb3303f145719c61d3050 though I didn't tried to
>>>>>> revert them in 5.15 yet.
>>>>> Odds are 5.18-rc6 is also a problem?
>>>> We believe that
>>>> 6b8a94332ee4 ("nfsd: Fix a write performance regression")
>>>> addresses the performance regression. It was merged into 5.18-rc.
>>> And into 5.17.4 if someone wants to try that release.
>> I don't have a lot of time to backport this one myself, so
>> I welcome anyone who wants to apply that commit to their
>> favorite LTS kernel and test it for us.
>>>>> If so, I'll just wait for the fix to get into Linus's tree as this does
>>>>> not seem to be a stable-tree-only issue.
>>>> Unfortunately I've received a recent report that the fix introduces
>>>> a "sleep while spinlock is held" for NFSv4.0 in rare cases.
>>> Ick, not good, any potential fixes for that?
>> Not yet. I was at LSF last week, so I've just started digging
>> into this one. I've confirmed that the report is a real bug,
>> but we still don't know how hard it is to hit it with real
>> workloads.
>> --
>> Chuck Lever
> 
> This maybe unrelated: when I used 5.4.188 for the first time I got this:
> 
> [Mon Apr 11 09:20:23 2022] ------------[ cut here ]------------
> [Mon Apr 11 09:20:23 2022] refcount_t: underflow; use-after-free.

I don't believe this is the same issue as the performance
regression. Hard to say more without knowing what the
server's workload was when this occurred.

The only two NFSD-related patches that appear between
v5.4.187 and v5.4.188 are Trond's filecache. It's implausible
that a callback reference count issue would be related.


> [Mon Apr 11 09:20:23 2022] WARNING: CPU: 18 PID: 7443 at lib/refcount.c:190 refcount_sub_and_test_checked+0x48/0x50
> [Mon Apr 11 09:20:23 2022] Modules linked in: rpcsec_gss_krb5(E) msr(E) 8021q(E) garp(E) stp(E) mrp(E) llc(E) dm_cache_smq(E) binfmt_misc(E) dm_cache(E) dm_persistent_data(E) dm_bio_prison(E) dm_bufio(E) ipmi_ssif(E) intel_rapl_ms
> r(E) intel_rapl_common(E) sb_edac(E) x86_pkg_temp_thermal(E) intel_powerclamp(E) coretemp(E) kvm_intel(E) kvm(E) irqbypass(E) crct10dif_pclmul(E) crc32_pclmul(E) ast(E) snd_pcm(E) drm_vram_helper(E) ttm(E) ghash_clmulni_intel(E) s
> nd_timer(E) rapl(E) snd(E) soundcore(E) drm_kms_helper(E) intel_cstate(E) pcspkr(E) iTCO_wdt(E) intel_uncore(E) drm(E) iTCO_vendor_support(E) mei_me(E) joydev(E) i2c_algo_bit(E) watchdog(E) mei(E) ioatdma(E) evdev(E) sg(E) ipmi_si
> (E) ipmi_devintf(E) ipmi_msghandler(E) acpi_power_meter(E) acpi_pad(E) button(E) poly1305_x86_64(E) poly1305_generic(E) sha256_ssse3(E) sha1_ssse3(E) chacha_generic(E) chacha20poly1305(E) aesni_intel(E) crypto_simd(E) glue_helper(
> E) cryptd(E) drbd(E) lru_cache(E) nfsd(E) nfs_acl(E) lockd(E) grace(E) auth_rpcgss(E) sunrpc(E)
> [Mon Apr 11 09:20:23 2022]  ip_tables(E) x_tables(E) autofs4(E) ext4(E) crc16(E) mbcache(E) jbd2(E) dm_mod(E) raid10(E) raid456(E) async_raid6_recov(E) async_memcpy(E) async_pq(E) async_xor(E) async_tx(E) xor(E) raid6_pq(E) libcrc
> 32c(E) crc32c_generic(E) raid0(E) multipath(E) linear(E) ses(E) enclosure(E) hid_generic(E) usbhid(E) hid(E) raid1(E) md_mod(E) sd_mod(E) crc32c_intel(E) ixgbe(E) ahci(E) xhci_pci(E) libahci(E) ehci_pci(E) xfrm_algo(E) mpt3sas(E)
> xhci_hcd(E) ehci_hcd(E) dca(E) raid_class(E) libata(E) libphy(E) usbcore(E) scsi_transport_sas(E) lpc_ich(E) ptp(E) i2c_i801(E) mfd_core(E) usb_common(E) pps_core(E) scsi_mod(E) mdio(E) wmi(E)
> [Mon Apr 11 09:20:23 2022] CPU: 18 PID: 7443 Comm: kworker/u50:1 Tainted: G        W   E     5.4.188-debian64.all+1.2 #1
> [Mon Apr 11 09:20:23 2022] Hardware name: Supermicro X10DRi/X10DRI-T, BIOS 1.1a 10/16/2015
> [Mon Apr 11 09:20:23 2022] Workqueue: rpciod rpc_async_schedule [sunrpc]
> [Mon Apr 11 09:20:23 2022] RIP: 0010:refcount_sub_and_test_checked+0x48/0x50
> [Mon Apr 11 09:20:23 2022] Code: 31 e4 44 89 e0 41 5c c3 eb f8 44 0f b6 25 7c ee ce 00 45 84 e4 75 e8 48 c7 c7 80 97 8b b1 c6 05 69 ee ce 00 01 e8 78 3f 3a 00 <0f> 0b eb d4 0f 1f 40 00 48 89 fe bf 01 00 00 00 eb a6 66 0f 1f 44
> [Mon Apr 11 09:20:23 2022] RSP: 0018:ffffad8a8d01fe48 EFLAGS: 00010286
> [Mon Apr 11 09:20:23 2022] RAX: 0000000000000000 RBX: 0000000000002a81 RCX: 0000000000000000
> [Mon Apr 11 09:20:23 2022] RDX: 0000000000000001 RSI: 0000000000000082 RDI: 00000000ffffffff
> [Mon Apr 11 09:20:23 2022] RBP: ffff9fb4a2394400 R08: 0000000000000001 R09: 000000000000085b
> [Mon Apr 11 09:20:23 2022] R10: 0000000000030f5c R11: 0000000000000004 R12: 0000000000000000
> [Mon Apr 11 09:20:23 2022] R13: ffff9feaf358d400 R14: 0000000000000000 R15: ffff9fb7e1b25148
> [Mon Apr 11 09:20:23 2022] FS:  0000000000000000(0000) GS:ffff9feaff980000(0000) knlGS:0000000000000000
> [Mon Apr 11 09:20:23 2022] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
> [Mon Apr 11 09:20:23 2022] CR2: 00007ffe62ca3080 CR3: 000000350880a002 CR4: 00000000001606e0
> [Mon Apr 11 09:20:23 2022] Call Trace:
> [Mon Apr 11 09:20:23 2022]  nfsd4_cb_offload_release+0x16/0x30 [nfsd]
> [Mon Apr 11 09:20:23 2022]  rpc_free_task+0x39/0x70 [sunrpc]
> [Mon Apr 11 09:20:23 2022]  rpc_async_schedule+0x29/0x40 [sunrpc]
> [Mon Apr 11 09:20:23 2022]  process_one_work+0x1ab/0x390
> [Mon Apr 11 09:20:23 2022]  worker_thread+0x50/0x3c0
> [Mon Apr 11 09:20:23 2022]  ? rescuer_thread+0x370/0x370
> [Mon Apr 11 09:20:23 2022]  kthread+0x13c/0x160
> [Mon Apr 11 09:20:23 2022]  ? __kthread_bind_mask+0x60/0x60
> [Mon Apr 11 09:20:23 2022]  ret_from_fork+0x1f/0x40
> [Mon Apr 11 09:20:23 2022] ---[ end trace c58c1aaca9be5d21 ]---
> [Mon Apr 11 09:56:32 2022] perf: interrupt took too long (6293 > 6228), lowering kernel.perf_event_max_sample_rate to 31750
> [Mon Apr 11 09:59:17 2022] ------------[ cut here ]------------



> [Mon Apr 11 09:59:17 2022] nfsd4_process_open2 failed to open newly-created file! status=10008

This is definitely not the same problem. This is a failure
to open a freshly created file. Maybe due to a memory shortage?
But this area has been a problem for a long time.

I have some patches going into 5.19 that might help in this
area by making NFSv4 OPEN(CREATE) atomic.


> [Mon Apr 11 09:59:17 2022] WARNING: CPU: 2 PID: 3061 at fs/nfsd/nfs4proc.c:456 nfsd4_open+0x39a/0x710 [nfsd]
> [Mon Apr 11 09:59:17 2022] Modules linked in: rpcsec_gss_krb5(E) msr(E) 8021q(E) garp(E) stp(E) mrp(E) llc(E) dm_cache_smq(E) binfmt_misc(E) dm_cache(E) dm_persistent_data(E) dm_bio_prison(E) dm_bufio(E) ipmi_ssif(E) intel_rapl_msr(E) intel_rapl_common(E) sb_edac(E) x86_pkg_temp_thermal(E) intel_powerclamp(E) coretemp(E) kvm_intel(E) kvm(E) irqbypass(E) crct10dif_pclmul(E) crc32_pclmul(E) ast(E) snd_pcm(E) drm_vram_helper(E) ttm(E) ghash_clmulni_intel(E) snd_timer(E) rapl(E) snd(E) soundcore(E) drm_kms_helper(E) intel_cstate(E) pcspkr(E) iTCO_wdt(E) intel_uncore(E) drm(E) iTCO_vendor_support(E) mei_me(E) joydev(E) i2c_algo_bit(E) watchdog(E) mei(E) ioatdma(E) evdev(E) sg(E) ipmi_si(E) ipmi_devintf(E) ipmi_msghandler(E) acpi_power_meter(E) acpi_pad(E) button(E) poly1305_x86_64(E) poly1305_generic(E) sha256_ssse3(E) sha1_ssse3(E) chacha_generic(E) chacha20poly1305(E) aesni_intel(E) crypto_simd(E) glue_helper(E) cryptd(E) drbd(E) lru_cache(E) nfsd(E) nfs_acl(E) lockd(E) grace(E) auth_rpcgss(E) sunrpc(E)
> [Mon Apr 11 09:59:17 2022]  ip_tables(E) x_tables(E) autofs4(E) ext4(E) crc16(E) mbcache(E) jbd2(E) dm_mod(E) raid10(E) raid456(E) async_raid6_recov(E) async_memcpy(E) async_pq(E) async_xor(E) async_tx(E) xor(E) raid6_pq(E) libcrc32c(E) crc32c_generic(E) raid0(E) multipath(E) linear(E) ses(E) enclosure(E) hid_generic(E) usbhid(E) hid(E) raid1(E) md_mod(E) sd_mod(E) crc32c_intel(E) ixgbe(E) ahci(E) xhci_pci(E) libahci(E) ehci_pci(E) xfrm_algo(E) mpt3sas(E) xhci_hcd(E) ehci_hcd(E) dca(E) raid_class(E) libata(E) libphy(E) usbcore(E) scsi_transport_sas(E) lpc_ich(E) ptp(E) i2c_i801(E) mfd_core(E) usb_common(E) pps_core(E) scsi_mod(E) mdio(E) wmi(E)
> [Mon Apr 11 09:59:17 2022] CPU: 2 PID: 3061 Comm: nfsd Tainted: G        W   E     5.4.188-debian64.all+1.2 #1
> [Mon Apr 11 09:59:17 2022] Hardware name: Supermicro X10DRi/X10DRI-T, BIOS 1.1a 10/16/2015
> [Mon Apr 11 09:59:17 2022] RIP: 0010:nfsd4_open+0x39a/0x710 [nfsd]
> [Mon Apr 11 09:59:17 2022] Code: e8 db 0f 01 00 41 89 c5 85 c0 0f 84 5e 01 00 00 80 bd 15 01 00 00 00 74 13 44 89 ee 48 c7 c7 a8 08 6f c0 0f ce e8 b6 f8 ae f0 <0f> 0b 4d 85 ff 0f 84 58 fd ff ff 4d 39 fc 0f 84 4f fd ff ff 4c 89
> [Mon Apr 11 09:59:17 2022] RSP: 0018:ffffad8ab09c7db8 EFLAGS: 00010286
> [Mon Apr 11 09:59:17 2022] RAX: 0000000000000000 RBX: ffff9feaaf7cb000 RCX: 0000000000000000
> [Mon Apr 11 09:59:17 2022] RDX: 0000000000000001 RSI: 0000000000000082 RDI: 00000000ffffffff
> [Mon Apr 11 09:59:17 2022] RBP: ffff9feaae54f460 R08: 0000000000000001 R09: 000000000000087a
> [Mon Apr 11 09:59:17 2022] R10: 0000000000031e00 R11: 0000000000000004 R12: ffff9feaae550070
> [Mon Apr 11 09:59:17 2022] R13: 0000000018270000 R14: ffff9feaae5ae000 R15: ffff9fc07ccfd400
> [Mon Apr 11 09:59:17 2022] FS:  0000000000000000(0000) GS:ffff9fcb1f880000(0000) knlGS:0000000000000000
> [Mon Apr 11 09:59:17 2022] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
> [Mon Apr 11 09:59:17 2022] CR2: 00007fdae60db000 CR3: 00000037e87fe005 CR4: 00000000001606e0
> [Mon Apr 11 09:59:17 2022] Call Trace:
> [Mon Apr 11 09:59:17 2022]  nfsd4_proc_compound+0x45d/0x730 [nfsd]
> [Mon Apr 11 09:59:17 2022]  nfsd_dispatch+0xc1/0x200 [nfsd]
> [Mon Apr 11 09:59:17 2022]  svc_process_common+0x399/0x6e0 [sunrpc]
> [Mon Apr 11 09:59:17 2022]  ? svc_recv+0x312/0x9f0 [sunrpc]
> [Mon Apr 11 09:59:17 2022]  ? nfsd_svc+0x2f0/0x2f0 [nfsd]
> [Mon Apr 11 09:59:17 2022]  ? nfsd_destroy+0x60/0x60 [nfsd]
> [Mon Apr 11 09:59:17 2022]  svc_process+0xd4/0x110 [sunrpc]
> [Mon Apr 11 09:59:17 2022]  nfsd+0xed/0x150 [nfsd]
> [Mon Apr 11 09:59:17 2022]  kthread+0x13c/0x160
> [Mon Apr 11 09:59:17 2022]  ? __kthread_bind_mask+0x60/0x60
> [Mon Apr 11 09:59:17 2022]  ret_from_fork+0x1f/0x40
> [Mon Apr 11 09:59:17 2022] ---[ end trace c58c1aaca9be5d22 ]---
> 
> I never saw this with an earlier kernel (and we use 5.4 since a long time).
> 
> I did not see this with the unchanged 5.4.192, though, which I tested before running 5.4.192 with the above mentioned patches reverted.
> 
> Regards,
> -- 
> Wolfgang Walter
> Studentenwerk München
> Anstalt des öffentlichen Rechts

--
Chuck Lever