[LU-9230] soft lockup on v2.9 Lustre clients (ldlm?) Created: 20/Mar/17  Updated: 05/Aug/20  Resolved: 17/May/18

Status: Resolved
Project: Lustre
Component/s: None
Affects Version/s: Lustre 2.9.0
Fix Version/s: Lustre 2.12.0, Lustre 2.10.7

Type: Bug Priority: Minor
Reporter: Daire Byrne (Inactive) Assignee: Yang Sheng
Resolution: Fixed Votes: 0
Labels: None
Environment:

RHEL7.3

Attachments: File ldlm-locks.log.gz     File messages.gz     HTML File sysrq-txt     File sysrqt.txt.gz    
Issue Links:
Duplicate
is duplicated by LU-11693 Soft lockups on Lustre clients Open
is duplicated by LU-10494 clients in locked state: spirit-29 k... Resolved
Related
is related to LU-9313 Soft lockup in ldlm_prepare_lru_list ... Resolved
is related to LU-11391 soft lockup in ldlm_prepare_lru_list() Open
is related to LU-11352 backport of LU-9230 to 2.10.5 Resolved
is related to LU-10537 softlockup in ldlm_prepare_lru_list() Resolved
Severity: 3
Rank (Obsolete): 9223372036854775807

 Description   

Hi,

We have recently configured a new filesystem running v2.9 and the clients are sporadically falling over every 2-3 days. The servers seem to be fine and a reboot of the clients seems to bring everything back to life.

This is the exact same workload that we ran on a v2.8 based cluster (backups with hard links) and we have not seen any similar issues. Here is a snippet of the logs from the moment it started to have issues:

Mar 20 00:50:27 foxtrot1 kernel: NMI watchdog: BUG: soft lockup - CPU#30 stuck for 23s! [ldlm_poold:3201]
Mar 20 00:50:27 foxtrot1 kernel: Modules linked in: mpt3sas mpt2sas raid_class scsi_transport_sas mptctl mptbase dell_rbu osc(OE) mgc(OE) lustre(OE) lmv(OE) mdc(OE) lov(OE) fid(OE) fld(OE) ksocklnd(OE) ptlrpc(OE) obdclass(OE) lnet(OE
) sha512_ssse3 sha512_generic nfsv3 nfs crypto_null fscache libcfs(OE) bonding intel_powerclamp coretemp intel_rapl iosf_mbi kvm_intel iTCO_wdt iTCO_vendor_support dcdbas kvm irqbypass sg ipmi_devintf acpi_pad acpi_power_meter ipmi_s
i sb_edac ipmi_msghandler edac_core mei_me mei shpchp lpc_ich nfsd auth_rpcgss nfs_acl lockd grace binfmt_misc ip_tables xfs sd_mod crc_t10dif crct10dif_generic 8021q garp stp llc mrp scsi_transport_iscsi crct10dif_pclmul crct10dif_c
ommon crc32_pclmul crc32c_intel mgag200 i2c_algo_bit ghash_clmulni_intel drm_kms_helper aesni_intel syscopyarea lrw sysfillrect gf128mul
Mar 20 00:50:27 foxtrot1 kernel: sysimgblt glue_helper fb_sys_fops ablk_helper cryptd ttm dm_multipath drm ahci libahci bnx2x libata i2c_core ptp pps_core megaraid_sas ntb mdio libcrc32c wmi fjes sunrpc dm_mirror dm_region_hash dm_lo
g dm_mod [last unloaded: cdrom]
Mar 20 00:50:27 foxtrot1 kernel: CPU: 30 PID: 3201 Comm: ldlm_poold Tainted: G           OE  ------------   3.10.0-514.el7_lustre.x86_64 #1
Mar 20 00:50:27 foxtrot1 kernel: Hardware name: Dell Inc. PowerEdge R620/0PXXHP, BIOS 2.5.4 01/22/2016
Mar 20 00:50:27 foxtrot1 kernel: task: ffff881ff4613ec0 ti: ffff881ff47d0000 task.ti: ffff881ff47d0000
Mar 20 00:50:27 foxtrot1 kernel: RIP: 0010:[<ffffffff8168da62>]  [<ffffffff8168da62>] _raw_spin_lock+0x32/0x50
Mar 20 00:50:27 foxtrot1 kernel: RSP: 0018:ffff881ff47d3c80  EFLAGS: 00000202
Mar 20 00:50:27 foxtrot1 kernel: RAX: 0000000000006091 RBX: ffffffff810cde74 RCX: 000000000000c172
Mar 20 00:50:27 foxtrot1 kernel: RDX: 000000000000c174 RSI: 000000000000c174 RDI: ffff883fee6bb418
Mar 20 00:50:27 foxtrot1 kernel: RBP: ffff881ff47d3c80 R08: 0000000000000000 R09: 0000000000000001
Mar 20 00:50:27 foxtrot1 kernel: R10: 000000010b885bfc R11: 0000000000000400 R12: 0000000000000000
Mar 20 00:50:27 foxtrot1 kernel: R13: ffff881fff956cc0 R14: ffff881fff956cc0 R15: ffff881ff8f1f400
Mar 20 00:50:27 foxtrot1 kernel: FS:  0000000000000000(0000) GS:ffff881fffbc0000(0000) knlGS:0000000000000000
Mar 20 00:50:27 foxtrot1 kernel: CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
Mar 20 00:50:27 foxtrot1 kernel: CR2: 00007fbeb5124f88 CR3: 00000000019ba000 CR4: 00000000000407e0
Mar 20 00:50:27 foxtrot1 kernel: DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000
Mar 20 00:50:27 foxtrot1 kernel: DR3: 0000000000000000 DR6: 00000000ffff0ff0 DR7: 0000000000000400
Mar 20 00:50:27 foxtrot1 kernel: Stack:
Mar 20 00:50:27 foxtrot1 kernel: ffff881ff47d3cb0 ffffffffa0bc619c ffff883e78f13400 0000000000000000
Mar 20 00:50:27 foxtrot1 kernel: 0000400000000000 0000008000000000 ffff881ff47d3d30 ffffffffa0be5d57
Mar 20 00:50:27 foxtrot1 kernel: ffff881ff47d3d48 000000000bd9af10 ffffffffa0be3d70 00000000000cfc1f
Mar 20 00:50:27 foxtrot1 kernel: Call Trace:
Mar 20 00:50:27 foxtrot1 kernel: [<ffffffffa0bc619c>] ldlm_lock_remove_from_lru_check+0x7c/0x1a0 [ptlrpc]
Mar 20 00:50:27 foxtrot1 kernel: [<ffffffffa0be5d57>] ldlm_prepare_lru_list+0x257/0x480 [ptlrpc]
Mar 20 00:50:27 foxtrot1 kernel: [<ffffffffa0be3d70>] ? ldlm_iter_helper+0x20/0x20 [ptlrpc]
Mar 20 00:50:27 foxtrot1 kernel: [<ffffffffa0beadb1>] ldlm_cancel_lru+0x61/0x170 [ptlrpc]
Mar 20 00:50:27 foxtrot1 kernel: [<ffffffffa0bfe109>] ldlm_cli_pool_recalc+0x249/0x260 [ptlrpc]
Mar 20 00:50:27 foxtrot1 kernel: [<ffffffffa0bfe767>] ldlm_pool_recalc+0x107/0x1d0 [ptlrpc]
Mar 20 00:50:27 foxtrot1 kernel: [<ffffffffa0c0017c>] ldlm_pools_recalc+0x21c/0x3d0 [ptlrpc]
Mar 20 00:50:27 foxtrot1 kernel: [<ffffffffa0c003c5>] ldlm_pools_thread_main+0x95/0x330 [ptlrpc]
Mar 20 00:50:27 foxtrot1 kernel: [<ffffffff810c4ec0>] ? wake_up_state+0x20/0x20
Mar 20 00:50:27 foxtrot1 kernel: [<ffffffffa0c00330>] ? ldlm_pools_recalc+0x3d0/0x3d0 [ptlrpc]
Mar 20 00:50:27 foxtrot1 kernel: [<ffffffff810b052f>] kthread+0xcf/0xe0
Mar 20 00:50:27 foxtrot1 kernel: [<ffffffff810b0460>] ? kthread_create_on_node+0x140/0x140
Mar 20 00:50:27 foxtrot1 kernel: [<ffffffff81696658>] ret_from_fork+0x58/0x90
Mar 20 00:50:27 foxtrot1 kernel: [<ffffffff810b0460>] ? kthread_create_on_node+0x140/0x140
Mar 20 00:50:27 foxtrot1 kernel: Code: 00 02 00 f0 0f c1 07 89 c2 c1 ea 10 66 39 c2 75 01 c3 55 83 e2 fe 0f b7 f2 48 89 e5 b8 00 80 00 00 eb 0d 66 0f 1f 44 00 00 f3 90 <83> e8 01 74 0a 0f b7 0f 66 39 ca 75 f1 5d c3 66 66 66 90 66 66 
Mar 20 00:50:55 foxtrot1 kernel: NMI watchdog: BUG: soft lockup - CPU#30 stuck for 23s! [ldlm_poold:3201]
Mar 20 00:50:55 foxtrot1 kernel: Modules linked in: mpt3sas mpt2sas raid_class scsi_transport_sas mptctl mptbase dell_rbu osc(OE) mgc(OE) lustre(OE) lmv(OE) mdc(OE) lov(OE) fid(OE) fld(OE) ksocklnd(OE) ptlrpc(OE) obdclass(OE) lnet(OE
) sha512_ssse3 sha512_generic nfsv3 nfs crypto_null fscache libcfs(OE) bonding intel_powerclamp coretemp intel_rapl iosf_mbi kvm_intel iTCO_wdt iTCO_vendor_support dcdbas kvm irqbypass sg ipmi_devintf acpi_pad acpi_power_meter ipmi_s
i sb_edac ipmi_msghandler edac_core mei_me mei shpchp lpc_ich nfsd auth_rpcgss nfs_acl lockd grace binfmt_misc ip_tables xfs sd_mod crc_t10dif crct10dif_generic 8021q garp stp llc mrp scsi_transport_iscsi crct10dif_pclmul crct10dif_c
ommon crc32_pclmul crc32c_intel mgag200 i2c_algo_bit ghash_clmulni_intel drm_kms_helper aesni_intel syscopyarea lrw sysfillrect gf128mul
Mar 20 00:50:55 foxtrot1 kernel: sysimgblt glue_helper fb_sys_fops ablk_helper cryptd ttm dm_multipath drm ahci libahci bnx2x libata i2c_core ptp pps_core megaraid_sas ntb mdio libcrc32c wmi fjes sunrpc dm_mirror dm_region_hash dm_log dm_mod [last unloaded: cdrom]
Mar 20 00:50:55 foxtrot1 kernel: CPU: 30 PID: 3201 Comm: ldlm_poold Tainted: G           OEL ------------   3.10.0-514.el7_lustre.x86_64 #1
Mar 20 00:50:55 foxtrot1 kernel: Hardware name: Dell Inc. PowerEdge R620/0PXXHP, BIOS 2.5.4 01/22/2016
Mar 20 00:50:55 foxtrot1 kernel: task: ffff881ff4613ec0 ti: ffff881ff47d0000 task.ti: ffff881ff47d0000
Mar 20 00:50:55 foxtrot1 kernel: RIP: 0010:[<ffffffff8168da62>]  [<ffffffff8168da62>] _raw_spin_lock+0x32/0x50
Mar 20 00:50:55 foxtrot1 kernel: RSP: 0018:ffff881ff47d3c80  EFLAGS: 00000216
Mar 20 00:50:55 foxtrot1 kernel: RAX: 0000000000003624 RBX: ffffffff810cde74 RCX: 000000000000123a
Mar 20 00:50:55 foxtrot1 kernel: RDX: 0000000000001244 RSI: 0000000000001244 RDI: ffff883fee6bb418
Mar 20 00:50:55 foxtrot1 kernel: RBP: ffff881ff47d3c80 R08: 0000000000000000 R09: 0000000000000001
Mar 20 00:50:55 foxtrot1 kernel: R10: 000000010b885de8 R11: 0000000000000400 R12: 0000000000000000
Mar 20 00:50:55 foxtrot1 kernel: R13: ffff881fff956cc0 R14: ffff881fff956cc0 R15: ffff881ff8f1f400
Mar 20 00:50:55 foxtrot1 kernel: FS:  0000000000000000(0000) GS:ffff881fffbc0000(0000) knlGS:0000000000000000
Mar 20 00:50:55 foxtrot1 kernel: CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
Mar 20 00:50:55 foxtrot1 kernel: CR2: 00007fbeb5124f88 CR3: 00000000019ba000 CR4: 00000000000407e0
Mar 20 00:50:55 foxtrot1 kernel: DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000
Mar 20 00:50:55 foxtrot1 kernel: DR3: 0000000000000000 DR6: 00000000ffff0ff0 DR7: 0000000000000400
Mar 20 00:50:55 foxtrot1 kernel: Stack:
Mar 20 00:50:55 foxtrot1 kernel: ffff881ff47d3cb0 ffffffffa0bc619c ffff883da559b200 0000000000000000
Mar 20 00:50:55 foxtrot1 kernel: 0000400000000000 0000008000000000 ffff881ff47d3d30 ffffffffa0be5d57
Mar 20 00:50:55 foxtrot1 kernel: ffff881ff47d3d48 000000000bd9af10 ffffffffa0be3d70 00000000000cfb78
Mar 20 00:50:55 foxtrot1 kernel: Call Trace:
Mar 20 00:50:55 foxtrot1 kernel: [<ffffffffa0bc619c>] ldlm_lock_remove_from_lru_check+0x7c/0x1a0 [ptlrpc]
Mar 20 00:50:55 foxtrot1 kernel: [<ffffffffa0be5d57>] ldlm_prepare_lru_list+0x257/0x480 [ptlrpc]
Mar 20 00:50:55 foxtrot1 kernel: [<ffffffffa0be3d70>] ? ldlm_iter_helper+0x20/0x20 [ptlrpc]
Mar 20 00:50:55 foxtrot1 kernel: [<ffffffffa0beadb1>] ldlm_cancel_lru+0x61/0x170 [ptlrpc]
Mar 20 00:50:55 foxtrot1 kernel: [<ffffffffa0bfe109>] ldlm_cli_pool_recalc+0x249/0x260 [ptlrpc]
Mar 20 00:50:55 foxtrot1 kernel: [<ffffffffa0bfe767>] ldlm_pool_recalc+0x107/0x1d0 [ptlrpc]
Mar 20 00:50:55 foxtrot1 kernel: [<ffffffffa0c0017c>] ldlm_pools_recalc+0x21c/0x3d0 [ptlrpc]
Mar 20 00:50:55 foxtrot1 kernel: [<ffffffffa0c003c5>] ldlm_pools_thread_main+0x95/0x330 [ptlrpc]
Mar 20 00:50:55 foxtrot1 kernel: [<ffffffff810c4ec0>] ? wake_up_state+0x20/0x20
Mar 20 00:50:55 foxtrot1 kernel: [<ffffffffa0c00330>] ? ldlm_pools_recalc+0x3d0/0x3d0 [ptlrpc]
Mar 20 00:50:55 foxtrot1 kernel: [<ffffffff810b052f>] kthread+0xcf/0xe0
Mar 20 00:50:55 foxtrot1 kernel: [<ffffffff810b0460>] ? kthread_create_on_node+0x140/0x140
Mar 20 00:50:55 foxtrot1 kernel: [<ffffffff81696658>] ret_from_fork+0x58/0x90
Mar 20 00:50:55 foxtrot1 kernel: [<ffffffff810b0460>] ? kthread_create_on_node+0x140/0x140
Mar 20 00:50:55 foxtrot1 kernel: Code: 00 02 00 f0 0f c1 07 89 c2 c1 ea 10 66 39 c2 75 01 c3 55 83 e2 fe 0f b7 f2 48 89 e5 b8 00 80 00 00 eb 0d 66 0f 1f 44 00 00 f3 90 <83> e8 01 74 0a 0f b7 0f 66 39 ca 75 f1 5d c3 66 66 66 90 66 66 
Mar 20 00:51:03 foxtrot1 kernel: INFO: rcu_sched self-detected stall on CPU { 30}  (t=60001 jiffies g=32391243 c=32391242 q=296406)
Mar 20 00:51:03 foxtrot1 kernel: Task dump for CPU 30:
Mar 20 00:51:03 foxtrot1 kernel: ldlm_poold      R  running task        0  3201      2 0x00000008
Mar 20 00:51:03 foxtrot1 kernel: ffff881ff4613ec0 0000000063a8c183 ffff881fffbc3db0 ffffffff810c41d8
Mar 20 00:51:03 foxtrot1 kernel: 000000000000001e ffffffff81a1a780 ffff881fffbc3dc8 ffffffff810c7a79
Mar 20 00:51:03 foxtrot1 kernel: 000000000000000f ffff881fffbc3df8 ffffffff811372a0 ffff881fffbd01c0
Mar 20 00:51:03 foxtrot1 kernel: Call Trace:
Mar 20 00:51:03 foxtrot1 kernel: <IRQ>  [<ffffffff810c41d8>] sched_show_task+0xa8/0x110
Mar 20 00:51:03 foxtrot1 kernel: [<ffffffff810c7a79>] dump_cpu_task+0x39/0x70
Mar 20 00:51:03 foxtrot1 kernel: [<ffffffff811372a0>] rcu_dump_cpu_stacks+0x90/0xd0
Mar 20 00:51:03 foxtrot1 kernel: [<ffffffff8113a9f2>] rcu_check_callbacks+0x442/0x720
Mar 20 00:51:03 foxtrot1 kernel: [<ffffffff810f2f80>] ? tick_sched_handle.isra.13+0x60/0x60
Mar 20 00:51:03 foxtrot1 kernel: [<ffffffff81099177>] update_process_times+0x47/0x80
Mar 20 00:51:03 foxtrot1 kernel: [<ffffffff810f2f45>] tick_sched_handle.isra.13+0x25/0x60
Mar 20 00:51:03 foxtrot1 kernel: [<ffffffff810f2fc1>] tick_sched_timer+0x41/0x70
Mar 20 00:51:03 foxtrot1 kernel: [<ffffffff810b4862>] __hrtimer_run_queues+0xd2/0x260
Mar 20 00:51:03 foxtrot1 kernel: [<ffffffff810b4e00>] hrtimer_interrupt+0xb0/0x1e0
Mar 20 00:51:03 foxtrot1 kernel: [<ffffffff8169819c>] ? call_softirq+0x1c/0x30
Mar 20 00:51:03 foxtrot1 kernel: [<ffffffff810510d7>] local_apic_timer_interrupt+0x37/0x60
Mar 20 00:51:03 foxtrot1 kernel: [<ffffffff81698e0f>] smp_apic_timer_interrupt+0x3f/0x60
Mar 20 00:51:03 foxtrot1 kernel: [<ffffffff8169735d>] apic_timer_interrupt+0x6d/0x80
Mar 20 00:51:03 foxtrot1 kernel: <EOI>  [<ffffffff810cde74>] ? update_curr+0x104/0x190
Mar 20 00:51:03 foxtrot1 kernel: [<ffffffff8168da67>] ? _raw_spin_lock+0x37/0x50
Mar 20 00:51:03 foxtrot1 kernel: [<ffffffffa0bc619c>] ldlm_lock_remove_from_lru_check+0x7c/0x1a0 [ptlrpc]
Mar 20 00:51:03 foxtrot1 kernel: [<ffffffffa0be5d57>] ldlm_prepare_lru_list+0x257/0x480 [ptlrpc]
Mar 20 00:51:03 foxtrot1 kernel: [<ffffffffa0be3d70>] ? ldlm_iter_helper+0x20/0x20 [ptlrpc]
Mar 20 00:51:03 foxtrot1 kernel: [<ffffffffa0beadb1>] ldlm_cancel_lru+0x61/0x170 [ptlrpc]
Mar 20 00:51:03 foxtrot1 kernel: [<ffffffffa0bfe109>] ldlm_cli_pool_recalc+0x249/0x260 [ptlrpc]
Mar 20 00:51:03 foxtrot1 kernel: [<ffffffffa0c0017c>] ldlm_pools_recalc+0x21c/0x3d0 [ptlrpc]
Mar 20 00:51:03 foxtrot1 kernel: [<ffffffffa0c003c5>] ldlm_pools_thread_main+0x95/0x330 [ptlrpc]
Mar 20 00:51:03 foxtrot1 kernel: [<ffffffff810c4ec0>] ? wake_up_state+0x20/0x20
Mar 20 00:51:03 foxtrot1 kernel: [<ffffffffa0c00330>] ? ldlm_pools_recalc+0x3d0/0x3d0 [ptlrpc]
Mar 20 00:51:03 foxtrot1 kernel: [<ffffffff810b052f>] kthread+0xcf/0xe0
Mar 20 00:51:03 foxtrot1 kernel: [<ffffffff810b0460>] ? kthread_create_on_node+0x140/0x140
Mar 20 00:51:03 foxtrot1 kernel: [<ffffffff81696658>] ret_from_fork+0x58/0x90
Mar 20 00:51:03 foxtrot1 kernel: [<ffffffff810b0460>] ? kthread_create_on_node+0x140/0x140
Mar 20 00:51:05 foxtrot1 systemd: Started Session 3948 of user root.
Mar 20 00:51:05 foxtrot1 systemd: Starting Session 3948 of user root.
Mar 20 00:51:06 foxtrot1 systemd: Started Session 3949 of user root.
Mar 20 00:51:06 foxtrot1 systemd: Starting Session 3949 of user root.
Mar 20 00:51:31 foxtrot1 kernel: NMI watchdog: BUG: soft lockup - CPU#30 stuck for 22s! [ldlm_poold:3201]
Mar 20 00:51:31 foxtrot1 kernel: Modules linked in: mpt3sas mpt2sas raid_class scsi_transport_sas mptctl mptbase dell_rbu osc(OE) mgc(OE) lustre(OE) lmv(OE) mdc(OE) lov(OE) fid(OE) fld(OE) ksocklnd(OE) ptlrpc(OE) obdclass(OE) lnet(OE) sha512_ssse3 sha512_generic nfsv3 nfs crypto_null fscache libcfs(OE) bonding intel_powerclamp coretemp intel_rapl iosf_mbi kvm_intel iTCO_wdt iTCO_vendor_support dcdbas kvm irqbypass sg ipmi_devintf acpi_pad acpi_power_meter ipmi_si sb_edac ipmi_msghandler edac_core mei_me mei shpchp lpc_ich nfsd auth_rpcgss nfs_acl lockd grace binfmt_misc ip_tables xfs sd_mod crc_t10dif crct10dif_generic 8021q garp stp llc mrp scsi_transport_iscsi crct10dif_pclmul crct10dif_common crc32_pclmul crc32c_intel mgag200 i2c_algo_bit ghash_clmulni_intel drm_kms_helper aesni_intel syscopyarea lrw sysfillrect gf128mul
Mar 20 00:51:31 foxtrot1 kernel: sysimgblt glue_helper fb_sys_fops ablk_helper cryptd ttm dm_multipath drm ahci libahci bnx2x libata i2c_core ptp pps_core megaraid_sas ntb mdio libcrc32c wmi fjes sunrpc dm_mirror dm_region_hash dm_log dm_mod [last unloaded: cdrom]
Mar 20 00:51:31 foxtrot1 kernel: CPU: 30 PID: 3201 Comm: ldlm_poold Tainted: G           OEL ------------   3.10.0-514.el7_lustre.x86_64 #1
Mar 20 00:51:31 foxtrot1 kernel: Hardware name: Dell Inc. PowerEdge R620/0PXXHP, BIOS 2.5.4 01/22/2016
Mar 20 00:51:31 foxtrot1 kernel: task: ffff881ff4613ec0 ti: ffff881ff47d0000 task.ti: ffff881ff47d0000
Mar 20 00:51:31 foxtrot1 kernel: RIP: 0010:[<ffffffff8168da62>]  [<ffffffff8168da62>] _raw_spin_lock+0x32/0x50
Mar 20 00:51:31 foxtrot1 kernel: RSP: 0018:ffff881ff47d3cb0  EFLAGS: 00000212
Mar 20 00:51:31 foxtrot1 kernel: RAX: 0000000000004ab0 RBX: 00000000000055da RCX: 00000000000055fc
Mar 20 00:51:31 foxtrot1 kernel: RDX: 0000000000005618 RSI: 0000000000005618 RDI: ffff883fee6bb418
Mar 20 00:51:31 foxtrot1 kernel: RBP: ffff881ff47d3cb0 R08: ffff882e7bf42b90 R09: 0000000000000001
Mar 20 00:51:31 foxtrot1 kernel: R10: 000000010b885f78 R11: 0000000000000400 R12: 0000000000000000
Mar 20 00:51:31 foxtrot1 kernel: R13: 0000000000000001 R14: 000000010b885f78 R15: 0000000000000400
Mar 20 00:51:31 foxtrot1 kernel: FS:  0000000000000000(0000) GS:ffff881fffbc0000(0000) knlGS:0000000000000000
Mar 20 00:51:31 foxtrot1 kernel: CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
Mar 20 00:51:31 foxtrot1 kernel: CR2: 00007fbeb5124f88 CR3: 00000000019ba000 CR4: 00000000000407e0
Mar 20 00:51:31 foxtrot1 kernel: DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000
Mar 20 00:51:31 foxtrot1 kernel: DR3: 0000000000000000 DR6: 00000000ffff0ff0 DR7: 0000000000000400
Mar 20 00:51:31 foxtrot1 kernel: Stack:
Mar 20 00:51:31 foxtrot1 kernel: ffff881ff47d3d30 ffffffffa0be5dc2 ffff881ff47d3d48 000000000bd9af10
Mar 20 00:51:31 foxtrot1 kernel: ffffffffa0be3d70 00000000000cfae7 000000010b885f78 ffff883fee6bb418
Mar 20 00:51:31 foxtrot1 kernel: ffff883fee6bb400 000cfae7000003b4 ffff883fee6bb448 ffff881ff47d3d48
Mar 20 00:51:31 foxtrot1 kernel: Call Trace:
Mar 20 00:51:31 foxtrot1 kernel: [<ffffffffa0be5dc2>] ldlm_prepare_lru_list+0x2c2/0x480 [ptlrpc]
Mar 20 00:51:31 foxtrot1 kernel: [<ffffffffa0be3d70>] ? ldlm_iter_helper+0x20/0x20 [ptlrpc]
Mar 20 00:51:31 foxtrot1 kernel: [<ffffffffa0beadb1>] ldlm_cancel_lru+0x61/0x170 [ptlrpc]
Mar 20 00:51:31 foxtrot1 kernel: [<ffffffffa0bfe109>] ldlm_cli_pool_recalc+0x249/0x260 [ptlrpc]
Mar 20 00:51:31 foxtrot1 kernel: [<ffffffffa0bfe767>] ldlm_pool_recalc+0x107/0x1d0 [ptlrpc]
Mar 20 00:51:31 foxtrot1 kernel: [<ffffffffa0c0017c>] ldlm_pools_recalc+0x21c/0x3d0 [ptlrpc]
Mar 20 00:51:31 foxtrot1 kernel: [<ffffffffa0c003c5>] ldlm_pools_thread_main+0x95/0x330 [ptlrpc]
Mar 20 00:51:31 foxtrot1 kernel: [<ffffffff810c4ec0>] ? wake_up_state+0x20/0x20
Mar 20 00:51:31 foxtrot1 kernel: [<ffffffffa0c00330>] ? ldlm_pools_recalc+0x3d0/0x3d0 [ptlrpc]
Mar 20 00:51:31 foxtrot1 kernel: [<ffffffff810b052f>] kthread+0xcf/0xe0
Mar 20 00:51:31 foxtrot1 kernel: [<ffffffff810b0460>] ? kthread_create_on_node+0x140/0x140
Mar 20 00:51:31 foxtrot1 kernel: [<ffffffff81696658>] ret_from_fork+0x58/0x90
Mar 20 00:51:31 foxtrot1 kernel: [<ffffffff810b0460>] ? kthread_create_on_node+0x140/0x140
Mar 20 00:51:31 foxtrot1 kernel: Code: 00 02 00 f0 0f c1 07 89 c2 c1 ea 10 66 39 c2 75 01 c3 55 83 e2 fe 0f b7 f2 48 89 e5 b8 00 80 00 00 eb 0d 66 0f 1f 44 00 00 f3 90 <83> e8 01 74 0a 0f b7 0f 66 39 ca 75 f1 5d c3 66 66 66 90 66 66 
..
..

It continues to spam the logs and the server is very slow until we reboot it. We have seen this on 3 different clients now.

On a related note, could we downgrade the client to v2.8 and keep v2.9 running on the servers as a potential quick fix for this instability?

 Comments   
Comment by Andreas Dilger [ 20/Mar/17 ]

Daire, yes you should be able to downgrade some or all of the clients as long as you aren't depending on any new features/fixes in 2.9, and that would also tell us whether the problem is specific to the client or somehow related to the server.

Comment by Peter Jones [ 20/Mar/17 ]

Yang Sheng

Could you please assist with this one?

Thanks

Peter

Comment by Yang Sheng [ 21/Mar/17 ]

Hi, Daire,

Could you help to collect sysrq-t information when the issue occurred and upload entire message log.

Thanks,
YangSheng

Comment by Daire Byrne (Inactive) [ 24/Mar/17 ]

It looks like this is happening on the v2.8 client too. I have attached sysrq-txt the sysrq-t output.

Comment by Yang Sheng [ 27/Mar/17 ]

Hi, Daire,

Where is the statck trace information?

[173719.148194] Sched Debug Version: v0.11, 3.10.0-514.el7_lustre.x86_64 #1
[173719.148196] ktime                                   : 173707625.828174
[173719.148198] sched_clk                               : 173719148.193954
[173719.148199] cpu_clk                                 : 173719148.193973
[173719.148200] jiffies                                 : 4468374922
[173719.148201] sched_clock_stable()                    : 1

[173719.148203] sysctl_sched
[173719.148205]   .sysctl_sched_latency                    : 24.000000
[173719.148206]   .sysctl_sched_min_granularity            : 3.000000
[173719.148208]   .sysctl_sched_wakeup_granularity         : 4.000000
[173719.148209]   .sysctl_sched_child_runs_first           : 0
[173719.148210]   .sysctl_sched_features                   : 110203
[173719.148212]   .sysctl_sched_tunable_scaling            : 1 (logaritmic)

[173719.148215] cpu#0, 2899.755 MHz
[173719.148216]   .nr_running                    : 1
[173719.148217]   .load                          : 1024
[173719.148219]   .nr_switches                   : 148025406
.......

Thanks,
YangSheng

Comment by Daire Byrne (Inactive) [ 27/Mar/17 ]

Sorry, copy and paste fail. I've attached the full output of "echo t > /proc/sysrq-trigger" now. sysrqt.txt.gz

The client was exhibiting the soft lockup every 10 seconds so hopefully this trace caught something useful.

Comment by Yang Sheng [ 28/Mar/17 ]

Hi, Daire,

From message log:

Mar 27 09:54:29 foxtrot3 kernel: rsync           R  running task        0 39602  39601 0x0000000a
Mar 27 09:54:29 foxtrot3 kernel: ffff882feb1f1850 ffff882feb1f184c ffff883d91d182b8 ffff883ae87b78d0
Mar 27 09:54:29 foxtrot3 kernel: 00000000bdc06a87 ffff88325f294af8 ffff8823caf52018 ffff8823caf52030
Mar 27 09:54:29 foxtrot3 kernel: ffff88240a463638 ffff88240a463638 00000000000003e0 ffff88240a463630
Mar 27 09:54:29 foxtrot3 kernel: Call Trace:
Mar 27 09:54:29 foxtrot3 kernel: [<ffffffffa0a93e20>] ? cl_env_put+0x140/0x1d0 [obdclass]
Mar 27 09:54:29 foxtrot3 kernel: [<ffffffffa09a125c>] ? osc_ldlm_weigh_ast+0x11c/0x4b0 [osc]
Mar 27 09:54:29 foxtrot3 kernel: [<ffffffffa08e1674>] ? lov_io_fini+0x1f4/0x4c0 [lov]
Mar 27 09:54:29 foxtrot3 kernel: [<ffffffffa0c32c9b>] ? ldlm_prepare_lru_list+0x19b/0x480 [ptlrpc]
Mar 27 09:54:29 foxtrot3 kernel: [<ffffffffa0c32df9>] ? ldlm_prepare_lru_list+0x2f9/0x480 [ptlrpc]
Mar 27 09:54:29 foxtrot3 kernel: [<ffffffffa0c314a0>] ? ldlm_cancel_no_wait_policy+0xa0/0xa0 [ptlrpc]
Mar 27 09:54:29 foxtrot3 kernel: [<ffffffffa0c3663a>] ? ldlm_cancel_lru_local+0x1a/0x30 [ptlrpc]

Looks this thread handle ns_lock and loop for ns_unused_list, other one just waiting to spin on ns_lock. It is a serious lock collision. Looks like you use many rsync processes to copy something. Could you please use command 

lctl get_param ldlm.namespaces.*osc*.*

on client to collect information for me? As you said, the issue occurred every 10 seconds. So you can run above command use a loop and don't less than this period.

Thanks,
YangSheng

Comment by Daire Byrne (Inactive) [ 28/Mar/17 ]

So rsync may have been one of the processes running at that time but it seems like we trigger this bad client state when we do lots of unlinks. I have just reproduced this after around 30 minutes by starting up a bunch a recursive deletes across lots of directories on a single client.

# cat /tmp/dirvish.txt| xargs --verbose -n1 -P12 -iX sh -c "/bin/rm -rf X"

Once I killed the "rm" processes, the soft lockups stopped. I've attached the messages log with a sysrq-t ( messages.gz ) and also the output ( ldlm-locks.log.gz ) of this command:

while true; do echo; date; lctl get_param ldlm.namespaces.*osc*.* ;sleep 30;done >>/tmp/ldlm-locks.log

The issue exhibited at ~11:43:53 and so the ldlm locks looked like this around that time:

Tue 28 Mar 11:43:57 BST 2017
ldlm.namespaces.foxtrot-OST0000-osc-ffff881ff850a000.early_lock_cancel=1
ldlm.namespaces.foxtrot-OST0000-osc-ffff881ff850a000.lock_count=954032
ldlm.namespaces.foxtrot-OST0000-osc-ffff881ff850a000.lock_unused_count=954032
ldlm.namespaces.foxtrot-OST0000-osc-ffff881ff850a000.lru_max_age=3900000
ldlm.namespaces.foxtrot-OST0000-osc-ffff881ff850a000.lru_size=954032
ldlm.namespaces.foxtrot-OST0000-osc-ffff881ff850a000.resource_count=954032
ldlm.namespaces.foxtrot-OST0001-osc-ffff881ff850a000.early_lock_cancel=1
ldlm.namespaces.foxtrot-OST0001-osc-ffff881ff850a000.lock_count=956907
ldlm.namespaces.foxtrot-OST0001-osc-ffff881ff850a000.lock_unused_count=956907
ldlm.namespaces.foxtrot-OST0001-osc-ffff881ff850a000.lru_max_age=3900000
ldlm.namespaces.foxtrot-OST0001-osc-ffff881ff850a000.lru_size=956907
ldlm.namespaces.foxtrot-OST0001-osc-ffff881ff850a000.resource_count=956907
ldlm.namespaces.foxtrot-OST0002-osc-ffff881ff850a000.early_lock_cancel=1
ldlm.namespaces.foxtrot-OST0002-osc-ffff881ff850a000.lock_count=949760
ldlm.namespaces.foxtrot-OST0002-osc-ffff881ff850a000.lock_unused_count=949760
ldlm.namespaces.foxtrot-OST0002-osc-ffff881ff850a000.lru_max_age=3900000
ldlm.namespaces.foxtrot-OST0002-osc-ffff881ff850a000.lru_size=949760
ldlm.namespaces.foxtrot-OST0002-osc-ffff881ff850a000.resource_count=949760
ldlm.namespaces.foxtrot-OST0003-osc-ffff881ff850a000.early_lock_cancel=1
ldlm.namespaces.foxtrot-OST0003-osc-ffff881ff850a000.lock_count=948542
ldlm.namespaces.foxtrot-OST0003-osc-ffff881ff850a000.lock_unused_count=948542
ldlm.namespaces.foxtrot-OST0003-osc-ffff881ff850a000.lru_max_age=3900000
ldlm.namespaces.foxtrot-OST0003-osc-ffff881ff850a000.lru_size=948542
ldlm.namespaces.foxtrot-OST0003-osc-ffff881ff850a000.resource_count=948542
ldlm.namespaces.foxtrot-OST0004-osc-ffff881ff850a000.early_lock_cancel=1
ldlm.namespaces.foxtrot-OST0004-osc-ffff881ff850a000.lock_count=954417
ldlm.namespaces.foxtrot-OST0004-osc-ffff881ff850a000.lock_unused_count=954417
ldlm.namespaces.foxtrot-OST0004-osc-ffff881ff850a000.lru_max_age=3900000
ldlm.namespaces.foxtrot-OST0004-osc-ffff881ff850a000.lru_size=954417
ldlm.namespaces.foxtrot-OST0004-osc-ffff881ff850a000.resource_count=954417
ldlm.namespaces.foxtrot-OST0005-osc-ffff881ff850a000.early_lock_cancel=1
ldlm.namespaces.foxtrot-OST0005-osc-ffff881ff850a000.lock_count=952116
ldlm.namespaces.foxtrot-OST0005-osc-ffff881ff850a000.lock_unused_count=952116
ldlm.namespaces.foxtrot-OST0005-osc-ffff881ff850a000.lru_max_age=3900000
ldlm.namespaces.foxtrot-OST0005-osc-ffff881ff850a000.lru_size=952116
ldlm.namespaces.foxtrot-OST0005-osc-ffff881ff850a000.resource_count=952116
ldlm.namespaces.foxtrot-OST0006-osc-ffff881ff850a000.early_lock_cancel=1
ldlm.namespaces.foxtrot-OST0006-osc-ffff881ff850a000.lock_count=958151
ldlm.namespaces.foxtrot-OST0006-osc-ffff881ff850a000.lock_unused_count=958141
ldlm.namespaces.foxtrot-OST0006-osc-ffff881ff850a000.lru_max_age=3900000
ldlm.namespaces.foxtrot-OST0006-osc-ffff881ff850a000.lru_size=958141
ldlm.namespaces.foxtrot-OST0006-osc-ffff881ff850a000.resource_count=958151
ldlm.namespaces.foxtrot-OST0007-osc-ffff881ff850a000.early_lock_cancel=1
ldlm.namespaces.foxtrot-OST0007-osc-ffff881ff850a000.lock_count=947705
ldlm.namespaces.foxtrot-OST0007-osc-ffff881ff850a000.lock_unused_count=947705
ldlm.namespaces.foxtrot-OST0007-osc-ffff881ff850a000.lru_max_age=3900000
ldlm.namespaces.foxtrot-OST0007-osc-ffff881ff850a000.lru_size=947705
ldlm.namespaces.foxtrot-OST0007-osc-ffff881ff850a000.resource_count=947705
ldlm.namespaces.foxtrot-OST0008-osc-ffff881ff850a000.early_lock_cancel=1
ldlm.namespaces.foxtrot-OST0008-osc-ffff881ff850a000.lock_count=948060
ldlm.namespaces.foxtrot-OST0008-osc-ffff881ff850a000.lock_unused_count=948060
ldlm.namespaces.foxtrot-OST0008-osc-ffff881ff850a000.lru_max_age=3900000
ldlm.namespaces.foxtrot-OST0008-osc-ffff881ff850a000.lru_size=948060
ldlm.namespaces.foxtrot-OST0008-osc-ffff881ff850a000.resource_count=948060
ldlm.namespaces.foxtrot-OST0009-osc-ffff881ff850a000.early_lock_cancel=1
ldlm.namespaces.foxtrot-OST0009-osc-ffff881ff850a000.lock_count=943827
ldlm.namespaces.foxtrot-OST0009-osc-ffff881ff850a000.lock_unused_count=943827
ldlm.namespaces.foxtrot-OST0009-osc-ffff881ff850a000.lru_max_age=3900000
ldlm.namespaces.foxtrot-OST0009-osc-ffff881ff850a000.lru_size=943827
ldlm.namespaces.foxtrot-OST0009-osc-ffff881ff850a000.resource_count=943827
ldlm.namespaces.foxtrot-OST000a-osc-ffff881ff850a000.early_lock_cancel=1
ldlm.namespaces.foxtrot-OST000a-osc-ffff881ff850a000.lock_count=951377
ldlm.namespaces.foxtrot-OST000a-osc-ffff881ff850a000.lock_unused_count=951377
ldlm.namespaces.foxtrot-OST000a-osc-ffff881ff850a000.lru_max_age=3900000
ldlm.namespaces.foxtrot-OST000a-osc-ffff881ff850a000.lru_size=951377
ldlm.namespaces.foxtrot-OST000a-osc-ffff881ff850a000.resource_count=951377
ldlm.namespaces.foxtrot-OST000b-osc-ffff881ff850a000.early_lock_cancel=1
ldlm.namespaces.foxtrot-OST000b-osc-ffff881ff850a000.lock_count=950399
ldlm.namespaces.foxtrot-OST000b-osc-ffff881ff850a000.lock_unused_count=950399
ldlm.namespaces.foxtrot-OST000b-osc-ffff881ff850a000.lru_max_age=3900000
ldlm.namespaces.foxtrot-OST000b-osc-ffff881ff850a000.lru_size=950399
ldlm.namespaces.foxtrot-OST000b-osc-ffff881ff850a000.resource_count=950399
ldlm.namespaces.foxtrot-OST000c-osc-ffff881ff850a000.early_lock_cancel=1
ldlm.namespaces.foxtrot-OST000c-osc-ffff881ff850a000.lock_count=958230
ldlm.namespaces.foxtrot-OST000c-osc-ffff881ff850a000.lock_unused_count=958220
ldlm.namespaces.foxtrot-OST000c-osc-ffff881ff850a000.lru_max_age=3900000
ldlm.namespaces.foxtrot-OST000c-osc-ffff881ff850a000.lru_size=958220
ldlm.namespaces.foxtrot-OST000c-osc-ffff881ff850a000.resource_count=958230
ldlm.namespaces.foxtrot-OST000d-osc-ffff881ff850a000.early_lock_cancel=1
ldlm.namespaces.foxtrot-OST000d-osc-ffff881ff850a000.lock_count=954636
ldlm.namespaces.foxtrot-OST000d-osc-ffff881ff850a000.lock_unused_count=954624
ldlm.namespaces.foxtrot-OST000d-osc-ffff881ff850a000.lru_max_age=3900000
ldlm.namespaces.foxtrot-OST000d-osc-ffff881ff850a000.lru_size=954624
ldlm.namespaces.foxtrot-OST000d-osc-ffff881ff850a000.resource_count=954636
ldlm.namespaces.foxtrot-OST000e-osc-ffff881ff850a000.early_lock_cancel=1
ldlm.namespaces.foxtrot-OST000e-osc-ffff881ff850a000.lock_count=959028
ldlm.namespaces.foxtrot-OST000e-osc-ffff881ff850a000.lock_unused_count=959019
ldlm.namespaces.foxtrot-OST000e-osc-ffff881ff850a000.lru_max_age=3900000
ldlm.namespaces.foxtrot-OST000e-osc-ffff881ff850a000.lru_size=959019
ldlm.namespaces.foxtrot-OST000e-osc-ffff881ff850a000.resource_count=959028
ldlm.namespaces.foxtrot-OST000f-osc-ffff881ff850a000.early_lock_cancel=1
ldlm.namespaces.foxtrot-OST000f-osc-ffff881ff850a000.lock_count=956239
ldlm.namespaces.foxtrot-OST000f-osc-ffff881ff850a000.lock_unused_count=956237
ldlm.namespaces.foxtrot-OST000f-osc-ffff881ff850a000.lru_max_age=3900000
ldlm.namespaces.foxtrot-OST000f-osc-ffff881ff850a000.lru_size=956237
ldlm.namespaces.foxtrot-OST000f-osc-ffff881ff850a000.resource_count=956239
ldlm.namespaces.foxtrot-OST0010-osc-ffff881ff850a000.early_lock_cancel=1
ldlm.namespaces.foxtrot-OST0010-osc-ffff881ff850a000.lock_count=956358
ldlm.namespaces.foxtrot-OST0010-osc-ffff881ff850a000.lock_unused_count=956358
ldlm.namespaces.foxtrot-OST0010-osc-ffff881ff850a000.lru_max_age=3900000
ldlm.namespaces.foxtrot-OST0010-osc-ffff881ff850a000.lru_size=956358
ldlm.namespaces.foxtrot-OST0010-osc-ffff881ff850a000.resource_count=956358
ldlm.namespaces.foxtrot-OST0011-osc-ffff881ff850a000.early_lock_cancel=1
ldlm.namespaces.foxtrot-OST0011-osc-ffff881ff850a000.lock_count=950601
ldlm.namespaces.foxtrot-OST0011-osc-ffff881ff850a000.lock_unused_count=950601
ldlm.namespaces.foxtrot-OST0011-osc-ffff881ff850a000.lru_max_age=3900000
ldlm.namespaces.foxtrot-OST0011-osc-ffff881ff850a000.lru_size=950601
ldlm.namespaces.foxtrot-OST0011-osc-ffff881ff850a000.resource_count=950601
ldlm.namespaces.foxtrot-OST0012-osc-ffff881ff850a000.early_lock_cancel=1
ldlm.namespaces.foxtrot-OST0012-osc-ffff881ff850a000.lock_count=949506
ldlm.namespaces.foxtrot-OST0012-osc-ffff881ff850a000.lock_unused_count=949506
ldlm.namespaces.foxtrot-OST0012-osc-ffff881ff850a000.lru_max_age=3900000
ldlm.namespaces.foxtrot-OST0012-osc-ffff881ff850a000.lru_size=949506
ldlm.namespaces.foxtrot-OST0012-osc-ffff881ff850a000.resource_count=949506
ldlm.namespaces.foxtrot-OST0013-osc-ffff881ff850a000.early_lock_cancel=1
ldlm.namespaces.foxtrot-OST0013-osc-ffff881ff850a000.lock_count=946982
ldlm.namespaces.foxtrot-OST0013-osc-ffff881ff850a000.lock_unused_count=946982
ldlm.namespaces.foxtrot-OST0013-osc-ffff881ff850a000.lru_max_age=3900000
ldlm.namespaces.foxtrot-OST0013-osc-ffff881ff850a000.lru_size=946982
ldlm.namespaces.foxtrot-OST0013-osc-ffff881ff850a000.resource_count=946982
ldlm.namespaces.foxtrot-OST0014-osc-ffff881ff850a000.early_lock_cancel=1
ldlm.namespaces.foxtrot-OST0014-osc-ffff881ff850a000.lock_count=945946
ldlm.namespaces.foxtrot-OST0014-osc-ffff881ff850a000.lock_unused_count=945946
ldlm.namespaces.foxtrot-OST0014-osc-ffff881ff850a000.lru_max_age=3900000
ldlm.namespaces.foxtrot-OST0014-osc-ffff881ff850a000.lru_size=945946
ldlm.namespaces.foxtrot-OST0014-osc-ffff881ff850a000.resource_count=945946
ldlm.namespaces.foxtrot-OST0015-osc-ffff881ff850a000.early_lock_cancel=1
ldlm.namespaces.foxtrot-OST0015-osc-ffff881ff850a000.lock_count=933736
ldlm.namespaces.foxtrot-OST0015-osc-ffff881ff850a000.lock_unused_count=933736
ldlm.namespaces.foxtrot-OST0015-osc-ffff881ff850a000.lru_max_age=3900000
ldlm.namespaces.foxtrot-OST0015-osc-ffff881ff850a000.lru_size=933736
ldlm.namespaces.foxtrot-OST0015-osc-ffff881ff850a000.resource_count=933736
ldlm.namespaces.foxtrot-OST0016-osc-ffff881ff850a000.early_lock_cancel=1
ldlm.namespaces.foxtrot-OST0016-osc-ffff881ff850a000.lock_count=957240
ldlm.namespaces.foxtrot-OST0016-osc-ffff881ff850a000.lock_unused_count=935455
ldlm.namespaces.foxtrot-OST0016-osc-ffff881ff850a000.lru_max_age=3900000
ldlm.namespaces.foxtrot-OST0016-osc-ffff881ff850a000.lru_size=935455
ldlm.namespaces.foxtrot-OST0016-osc-ffff881ff850a000.resource_count=957240
ldlm.namespaces.foxtrot-OST0017-osc-ffff881ff850a000.early_lock_cancel=1
ldlm.namespaces.foxtrot-OST0017-osc-ffff881ff850a000.lock_count=943288
ldlm.namespaces.foxtrot-OST0017-osc-ffff881ff850a000.lock_unused_count=943288
ldlm.namespaces.foxtrot-OST0017-osc-ffff881ff850a000.lru_max_age=3900000
ldlm.namespaces.foxtrot-OST0017-osc-ffff881ff850a000.lru_size=943288
ldlm.namespaces.foxtrot-OST0017-osc-ffff881ff850a000.resource_count=943288
ldlm.namespaces.foxtrot-OST0018-osc-ffff881ff850a000.early_lock_cancel=1
ldlm.namespaces.foxtrot-OST0018-osc-ffff881ff850a000.lock_count=953595
ldlm.namespaces.foxtrot-OST0018-osc-ffff881ff850a000.lock_unused_count=953595
ldlm.namespaces.foxtrot-OST0018-osc-ffff881ff850a000.lru_max_age=3900000
ldlm.namespaces.foxtrot-OST0018-osc-ffff881ff850a000.lru_size=953595
ldlm.namespaces.foxtrot-OST0018-osc-ffff881ff850a000.resource_count=953595
ldlm.namespaces.foxtrot-OST0019-osc-ffff881ff850a000.early_lock_cancel=1
ldlm.namespaces.foxtrot-OST0019-osc-ffff881ff850a000.lock_count=947036
ldlm.namespaces.foxtrot-OST0019-osc-ffff881ff850a000.lock_unused_count=947036
ldlm.namespaces.foxtrot-OST0019-osc-ffff881ff850a000.lru_max_age=3900000
ldlm.namespaces.foxtrot-OST0019-osc-ffff881ff850a000.lru_size=947036
ldlm.namespaces.foxtrot-OST0019-osc-ffff881ff850a000.resource_count=947036
ldlm.namespaces.foxtrot-OST001a-osc-ffff881ff850a000.early_lock_cancel=1
ldlm.namespaces.foxtrot-OST001a-osc-ffff881ff850a000.lock_count=953487
ldlm.namespaces.foxtrot-OST001a-osc-ffff881ff850a000.lock_unused_count=953487
ldlm.namespaces.foxtrot-OST001a-osc-ffff881ff850a000.lru_max_age=3900000
ldlm.namespaces.foxtrot-OST001a-osc-ffff881ff850a000.lru_size=953487
ldlm.namespaces.foxtrot-OST001a-osc-ffff881ff850a000.resource_count=953487
ldlm.namespaces.foxtrot-OST001b-osc-ffff881ff850a000.early_lock_cancel=1
ldlm.namespaces.foxtrot-OST001b-osc-ffff881ff850a000.lock_count=950634
ldlm.namespaces.foxtrot-OST001b-osc-ffff881ff850a000.lock_unused_count=950634
ldlm.namespaces.foxtrot-OST001b-osc-ffff881ff850a000.lru_max_age=3900000
ldlm.namespaces.foxtrot-OST001b-osc-ffff881ff850a000.lru_size=950634
ldlm.namespaces.foxtrot-OST001b-osc-ffff881ff850a000.resource_count=950634
ldlm.namespaces.foxtrot-OST001c-osc-ffff881ff850a000.early_lock_cancel=1
ldlm.namespaces.foxtrot-OST001c-osc-ffff881ff850a000.lock_count=933164
ldlm.namespaces.foxtrot-OST001c-osc-ffff881ff850a000.lock_unused_count=933164
ldlm.namespaces.foxtrot-OST001c-osc-ffff881ff850a000.lru_max_age=3900000
ldlm.namespaces.foxtrot-OST001c-osc-ffff881ff850a000.lru_size=933164
ldlm.namespaces.foxtrot-OST001c-osc-ffff881ff850a000.resource_count=933164
ldlm.namespaces.foxtrot-OST001d-osc-ffff881ff850a000.early_lock_cancel=1
ldlm.namespaces.foxtrot-OST001d-osc-ffff881ff850a000.lock_count=938746
ldlm.namespaces.foxtrot-OST001d-osc-ffff881ff850a000.lock_unused_count=938746
ldlm.namespaces.foxtrot-OST001d-osc-ffff881ff850a000.lru_max_age=3900000
ldlm.namespaces.foxtrot-OST001d-osc-ffff881ff850a000.lru_size=938746
ldlm.namespaces.foxtrot-OST001d-osc-ffff881ff850a000.resource_count=938746
ldlm.namespaces.foxtrot-OST001e-osc-ffff881ff850a000.early_lock_cancel=1
ldlm.namespaces.foxtrot-OST001e-osc-ffff881ff850a000.lock_count=943896
ldlm.namespaces.foxtrot-OST001e-osc-ffff881ff850a000.lock_unused_count=943896
ldlm.namespaces.foxtrot-OST001e-osc-ffff881ff850a000.lru_max_age=3900000
ldlm.namespaces.foxtrot-OST001e-osc-ffff881ff850a000.lru_size=943896
ldlm.namespaces.foxtrot-OST001e-osc-ffff881ff850a000.resource_count=943896
ldlm.namespaces.foxtrot-OST001f-osc-ffff881ff850a000.early_lock_cancel=1
ldlm.namespaces.foxtrot-OST001f-osc-ffff881ff850a000.lock_count=954614
ldlm.namespaces.foxtrot-OST001f-osc-ffff881ff850a000.lock_unused_count=954614
ldlm.namespaces.foxtrot-OST001f-osc-ffff881ff850a000.lru_max_age=3900000
ldlm.namespaces.foxtrot-OST001f-osc-ffff881ff850a000.lru_size=954614
ldlm.namespaces.foxtrot-OST001f-osc-ffff881ff850a000.resource_count=954614
ldlm.namespaces.foxtrot-OST0020-osc-ffff881ff850a000.early_lock_cancel=1
ldlm.namespaces.foxtrot-OST0020-osc-ffff881ff850a000.lock_count=951901
ldlm.namespaces.foxtrot-OST0020-osc-ffff881ff850a000.lock_unused_count=951901
ldlm.namespaces.foxtrot-OST0020-osc-ffff881ff850a000.lru_max_age=3900000
ldlm.namespaces.foxtrot-OST0020-osc-ffff881ff850a000.lru_size=951901
ldlm.namespaces.foxtrot-OST0020-osc-ffff881ff850a000.resource_count=951901
ldlm.namespaces.foxtrot-OST0021-osc-ffff881ff850a000.early_lock_cancel=1
ldlm.namespaces.foxtrot-OST0021-osc-ffff881ff850a000.lock_count=950887
ldlm.namespaces.foxtrot-OST0021-osc-ffff881ff850a000.lock_unused_count=950887
ldlm.namespaces.foxtrot-OST0021-osc-ffff881ff850a000.lru_max_age=3900000
ldlm.namespaces.foxtrot-OST0021-osc-ffff881ff850a000.lru_size=950887
ldlm.namespaces.foxtrot-OST0021-osc-ffff881ff850a000.resource_count=950887
Comment by Daire Byrne (Inactive) [ 30/Mar/17 ]

Any updates on this? Were the last set of logs useful? We are having to reboot our clients every day now....

I don't suppose there is any chance we can downgrade the servers and client to v2.8 once it has been formatted as v2.9?

Comment by Yang Sheng [ 30/Mar/17 ]

Hi, Daire,

I just investigating the log you have attached last. It looks different than previous a little. I think this really is a issue for ns_lock usage in ldlm_lru_prepare_list(). Will give a solution shortly.

Thanks,
YangSheng

Comment by Andreas Dilger [ 31/Mar/17 ]

It loks like your client has multiple millions of locks locally, which is causing problems during lock aging or similar. 

As a workaround, rather than rebooting the clients you could run lctl set_param ldlm.namespaces.*.lru_size=clear on the clients to drop the locks and it should recover.  Another option would be to put a hard limit on the size of the client lock LRU like lctl set_param ldlm.namespaces.*.lru_size=10000 and/or reduce the maximum age for locks like lctl set_param ldlm.namespaces.*.lru_max_age=600000 (units in msec).

it looks like the core problem here is that the client isn't aggressive enough about c locks. Yang Sheng, what are your thoughts on how to fix this?

Comment by Yang Sheng [ 31/Mar/17 ]

Hi, Andreas,

I think the problem is piece of code 

....
                /* For any flags, stop scanning if @max is reached. */
                if (max && added >= max)
                        break;

                list_for_each_entry_safe(lock, next, &ns->ns_unused_list,
                                         l_lru) {
                        /* No locks which got blocking requests. */
                        LASSERT(!ldlm_is_bl_ast(lock));

                        if (no_wait && ldlm_is_skipped(lock))----A
                                /* already processed */
                                continue;

                        last_use = lock->l_last_used;
                        if (last_use == cfs_time_current())---------B
                                continue;

                        /* Somebody is already doing CANCEL. No need for this
                         * lock in LRU, do not traverse it again. */
                        if (!ldlm_is_canceling(lock))
                                break;

                        ldlm_lock_remove_from_lru_nolock(lock);
                }
                if (&lock->l_lru == &ns->ns_unused_list)
                        break;
......

It holds ns_lock and loop on ns_unused_list. It may cause lock contention with a huge amount of ns_unused_list. So we should try to reduce this period. From above code, We can see the A and B point may cause a delay. But B is almost impossible to cause a problem. The A is place may bring a long time loop if with a huge number locks. So i think one possible solution is move the lock with skip flag to tail of list then we can avoid loop them again in next time. We can do it in ldlm_cancel_no_wait_policy or in this loop to avoid acquiring ns_lock again. Does it make sense?

Thanks,
YangSheng

Comment by Daire Byrne (Inactive) [ 31/Mar/17 ]

I have taken Andreas' advice and set the following on all 3 clients that are doing the heavy ops:

lctl set_param ldlm.namespaces.*.lru_size=10000
lctl set_param ldlm.namespaces.*.lru_max_age=600000

I set the clients to work and they have been stable for an hour now while doing ~30,000 unlinks per second. I would have expected to see the issue by now so this looks like a good workaround for now - thanks!

Did this code changed between v2.8 and v2.9 because we have never seen this issue on v2.9 with the exact same configuration and workload. The only difference is that we have switched the MDT device from an external RAID to NVMe cards so there is a 4x increase in iop/s (30k -> 120k). So I suppose there is a lot more locking going on per second than we have ever achieved before which may be enough to trigger this?

Comment by Yang Sheng [ 31/Mar/17 ]

Hi, Daire,

Yes, This issue should easy reveal by heavy workload regardless 2.8 or 2.9. So this is a good chance to verify it whether be fixed.

Thanks,
YangSheng

Comment by Andreas Dilger [ 02/Apr/17 ]

Daire, if the MDT is 4x faster than before, it means that 4x as many locks will be in memory before they will be expired from the LRU due to age.

Comment by Gerrit Updater [ 03/Apr/17 ]

Yang Sheng (yang.sheng@intel.com) uploaded a new patch: https://review.whamcloud.com/26327
Subject: LU-9230 ldlm: speed up preparation for list of lock cancel
Project: fs/lustre-release
Branch: master
Current Patch Set: 1
Commit: b40347a46a320ca23bd2d34b3108061bb2bd76f2

Comment by Patrick Farrell (Inactive) [ 20/Mar/18 ]

LU-9313 describes and addresses more or less the same problem but uses a different approach.  The two approaches could probably be complimentary, though.  LU-9313 also includes a description of a simple way to reproduce the problem, which may be interesting.  (FWIW, LU-9313 has been in production at Cray customers for around a year.)

Comment by Gerrit Updater [ 17/May/18 ]

Oleg Drokin (oleg.drokin@intel.com) merged in patch https://review.whamcloud.com/26327/
Subject: LU-9230 ldlm: speed up preparation for list of lock cancel
Project: fs/lustre-release
Branch: master
Current Patch Set:
Commit: 651f2cdd2d8df1d4318f874993ab0706d16ce490

Comment by Peter Jones [ 17/May/18 ]

Landed for 2.12

Comment by Mahmoud Hanafi [ 07/Sep/18 ]

Can we get a back port to 2.10.5

Comment by Peter Jones [ 07/Sep/18 ]

Mahmoud

Please open a new ticket that refers to this one to request support help

Peter

Comment by Gerrit Updater [ 10/Sep/18 ]

Yang Sheng (ys@whamcloud.com) uploaded a new patch: https://review.whamcloud.com/33130
Subject: LU-9230 ldlm: speed up preparation for list of lock cancel
Project: fs/lustre-release
Branch: b2_10
Current Patch Set: 1
Commit: e5c0983ac7b2404c51c130420befc68057fdb4a6

Comment by Gerrit Updater [ 05/Jan/19 ]

Oleg Drokin (green@whamcloud.com) merged in patch https://review.whamcloud.com/33130/
Subject: LU-9230 ldlm: speed up preparation for list of lock cancel
Project: fs/lustre-release
Branch: b2_10
Current Patch Set:
Commit: 21f7f777172d68ce61734487e23cf237900f927d

Generated at Sat Feb 10 02:24:21 UTC 2024 using Jira 9.4.14#940014-sha1:734e6822bbf0d45eff9af51f82432957f73aa32c.