[LU-13072] High OSS load due to possible deadlock w/ ofd_create_hdl and ofd_quotactl backtraces

• Status: Resolved
• Project: Lustre
• Affects Version/s: Lustre 2.12.3
• Type: Bug
• Priority: Major
• Reporter: Stephane Thiell
• Assignee: Yang Sheng
• Resolution: Fixed

Environment

lustre-2.12.3_4_g142b4d4-1.el7.x86_64 3.10.0-957.27.2.el7_lustre.pl2.x86_64 MOFED 4.7

• Severity: 3

Description

We found an OSS on Fir (2.12.3_4) heavily loaded and with threads hung this morning. This started during last night. We took a crash dump that I uploaded to the FTP as vmcore_fir-io8-s1_2019-12-12-07-42-58 along with kernel-debuginfo (kernel-debuginfo-3.10.0-957.27.2.el7_lustre.pl2.x86_64.rpm and kernel-debuginfo-common-x86_64-3.10.0-957.27.2.el7_lustre.pl2.x86_64.rpm).

The last messages on the console before the crash dump were:

[264018.187097] LNet: Service thread pid 33911 was inactive for 1200.94s. The thread might be hung, or it might only be slow and will resume later. Dumping the stack trace for debugging purposes:
[264018.204204] LNet: Skipped 1 previous similar message
[264018.209269] Pid: 33911, comm: ll_ost03_106 3.10.0-957.27.2.el7_lustre.pl2.x86_64 #1 SMP Thu Nov 7 15:26:16 PST 2019
[264018.219804] Call Trace:
[264018.222354]  [<ffffffffc155deb3>] ofd_create_hdl+0xcb3/0x20e0 [ofd]
[264018.228754]  [<ffffffffc0f5036a>] tgt_request_handle+0xaea/0x1580 [ptlrpc]
[264018.235831]  [<ffffffffc0ef724b>] ptlrpc_server_handle_request+0x24b/0xab0 [ptlrpc]
[264018.243637]  [<ffffffffc0efabac>] ptlrpc_main+0xb2c/0x1460 [ptlrpc]
[264018.250067]  [<ffffffffa7ac2e81>] kthread+0xd1/0xe0
[264018.255066]  [<ffffffffa8177c24>] ret_from_fork_nospec_begin+0xe/0x21
[264018.261642]  [<ffffffffffffffff>] 0xffffffffffffffff
[264018.266754] LustreError: dumping log to /tmp/lustre-log.1576165038.33911
[264126.221225] LNet: Service thread pid 34617 was inactive for 200.36s. The thread might be hung, or it might only be slow and will resume later. Dumping the stack trace for debugging purposes:
[264126.238268] Pid: 34617, comm: ll_ost03_111 3.10.0-957.27.2.el7_lustre.pl2.x86_64 #1 SMP Thu Nov 7 15:26:16 PST 2019
[264126.248785] Call Trace:
[264126.251360]  [<ffffffffc02c3085>] wait_transaction_locked+0x85/0xd0 [jbd2]
[264126.258376]  [<ffffffffc02c3368>] add_transaction_credits+0x268/0x2f0 [jbd2]
[264126.265544]  [<ffffffffc02c35e1>] start_this_handle+0x1a1/0x430 [jbd2]
[264126.272211]  [<ffffffffc02c3a93>] jbd2__journal_start+0xf3/0x1f0 [jbd2]
[264126.278951]  [<ffffffffc131b309>] __ldiskfs_journal_start_sb+0x69/0xe0 [ldiskfs]
[264126.286491]  [<ffffffffc1312ad3>] ldiskfs_acquire_dquot+0x53/0xb0 [ldiskfs]
[264126.293573]  [<ffffffffa7cb026a>] dqget+0x3fa/0x450
[264126.298588]  [<ffffffffa7cb1074>] dquot_get_dqblk+0x14/0x1f0
[264126.304371]  [<ffffffffc143c6d5>] osd_acct_index_lookup+0x235/0x480 [osd_ldiskfs]
[264126.311997]  [<ffffffffc13a380d>] lquotactl_slv+0x27d/0x9d0 [lquota]
[264126.318488]  [<ffffffffc1556a3c>] ofd_quotactl+0x13c/0x380 [ofd]
[264126.324630]  [<ffffffffc0f5036a>] tgt_request_handle+0xaea/0x1580 [ptlrpc]
[264126.331681]  [<ffffffffc0ef724b>] ptlrpc_server_handle_request+0x24b/0xab0 [ptlrpc]
[264126.339496]  [<ffffffffc0efabac>] ptlrpc_main+0xb2c/0x1460 [ptlrpc]
[264126.345912]  [<ffffffffa7ac2e81>] kthread+0xd1/0xe0
[264126.350926]  [<ffffffffa8177c24>] ret_from_fork_nospec_begin+0xe/0x21
[264126.357490]  [<ffffffffffffffff>] 0xffffffffffffffff
[264126.362604] LustreError: dumping log to /tmp/lustre-log.1576165146.34617
[264136.461417] Pid: 34429, comm: ll_ost03_110 3.10.0-957.27.2.el7_lustre.pl2.x86_64 #1 SMP Thu Nov 7 15:26:16 PST 2019
[264136.471940] Call Trace:
[264136.474507]  [<ffffffffc02c3085>] wait_transaction_locked+0x85/0xd0 [jbd2]
[264136.481514]  [<ffffffffc02c3368>] add_transaction_credits+0x268/0x2f0 [jbd2]
[264136.488699]  [<ffffffffc02c35e1>] start_this_handle+0x1a1/0x430 [jbd2]
[264136.495351]  [<ffffffffc02c3a93>] jbd2__journal_start+0xf3/0x1f0 [jbd2]
[264136.502103]  [<ffffffffc131b309>] __ldiskfs_journal_start_sb+0x69/0xe0 [ldiskfs]
[264136.509629]  [<ffffffffc1312ad3>] ldiskfs_acquire_dquot+0x53/0xb0 [ldiskfs]
[264136.516725]  [<ffffffffa7cb026a>] dqget+0x3fa/0x450
[264136.521728]  [<ffffffffa7cb1074>] dquot_get_dqblk+0x14/0x1f0
[264136.527514]  [<ffffffffc143c6d5>] osd_acct_index_lookup+0x235/0x480 [osd_ldiskfs]
[264136.535127]  [<ffffffffc13a380d>] lquotactl_slv+0x27d/0x9d0 [lquota]
[264136.541618]  [<ffffffffc1556a3c>] ofd_quotactl+0x13c/0x380 [ofd]
[264136.547746]  [<ffffffffc0f5036a>] tgt_request_handle+0xaea/0x1580 [ptlrpc]
[264136.554806]  [<ffffffffc0ef724b>] ptlrpc_server_handle_request+0x24b/0xab0 [ptlrpc]
[264136.562610]  [<ffffffffc0efabac>] ptlrpc_main+0xb2c/0x1460 [ptlrpc]
[264136.569039]  [<ffffffffa7ac2e81>] kthread+0xd1/0xe0
[264136.574042]  [<ffffffffa8177c24>] ret_from_fork_nospec_begin+0xe/0x21
[264136.580632]  [<ffffffffffffffff>] 0xffffffffffffffff
[264136.585737] LustreError: dumping log to /tmp/lustre-log.1576165156.34429
[264349.590511] SysRq : Trigger a crash

Attaching:

• vmcore-dmesg-txt as vmcore-dmesg_fir-io8-s1_2019-12-12-07-42-58.txt
• output of "foreach bt" as foreach_bt_fir-io8-s1_2019-12-12-07-42-58.txt

We restarted the OSS and a few OSTs couldn't complete their recovery (stuck at 0s) but a manual abort_recovery did work.

Thanks,
Stephane

Comments

[Peter Jones]

Yang Sheng

Could you please advise

Thanks

Peter

[Oleg Drokin]

PID: 66168  TASK: ffff8912f5c68000  CPU: 0   COMMAND: "jbd2/md2-8"
 #0 [ffff8912f34cfc08] __schedule at ffffffffa816aa72
 #1 [ffff8912f34cfc98] schedule at ffffffffa816af19
 #2 [ffff8912f34cfca8] jbd2_journal_commit_transaction at ffffffffc02c62bc [jbd2]
 #3 [ffff8912f34cfe48] kjournald2 at ffffffffc02cce89 [jbd2]
 #4 [ffff8912f34cfec8] kthread at ffffffffa7ac2e81
 #5 [ffff8912f34cff50] ret_from_fork_nospec_begin at ffffffffa8177c24

So jbd is commiting a transaction and it takes a long time so nobody else can start a new transaction for a long time. I also see many other threads waiting on IO including debugfs that I presume reads from the same device? but also many ost io threads. If there's a lot of IO contention it's somewhat understandable that IO is slow including slow transaction commits that impacts things like starting new transactions.

[Yang Sheng]

Hi, Stephane,

After investigating, I think this issue should relate to some storage issue. The all of ofd_create_hdl threads were block by wait_transaction_locked. The ofd_quotactl also same blocked on wait_transaction_locked. They are waiting to start a new trans. The transaction was block by

PID: 67875  TASK: ffff891241b65140  CPU: 9   COMMAND: "ll_ost_io01_019"
 #0 [ffff891241e2f8e8] __schedule at ffffffffa816aa72
 #1 [ffff891241e2f978] schedule at ffffffffa816af19
 #2 [ffff891241e2f988] osd_trans_stop at ffffffffc140fe75 [osd_ldiskfs]
 #3 [ffff891241e2fa40] ofd_trans_stop at ffffffffc1569c75 [ofd]
 #4 [ffff891241e2fa50] ofd_commitrw_write at ffffffffc1570c34 [ofd]
 #5 [ffff891241e2fad8] ofd_commitrw at ffffffffc157510c [ofd]
 #6 [ffff891241e2fb58] tgt_brw_write at ffffffffc0f5460b [ptlrpc]
 #7 [ffff891241e2fcd0] tgt_request_handle at ffffffffc0f5036a [ptlrpc]
 #8 [ffff891241e2fd58] ptlrpc_server_handle_request at ffffffffc0ef724b [ptlrpc]
 #9 [ffff891241e2fdf8] ptlrpc_main at ffffffffc0efabac [ptlrpc]
#10 [ffff891241e2fec8] kthread at ffffffffa7ac2e81
#11 [ffff891241e2ff50] ret_from_fork_nospec_begin at ffffffffa8177c24

The thread was waiting some data to write out. It is waiting for a few threads like:

PID: 67874  TASK: ffff891241b64100  CPU: 42  COMMAND: "ll_ost_io02_019"
 #0 [ffff891241e2b4a8] __schedule at ffffffffa816aa72
 #1 [ffff891241e2b538] schedule at ffffffffa816af19
 #2 [ffff891241e2b548] bitmap_startwrite at ffffffffa7f9cc65
 #3 [ffff891241e2b5c8] add_stripe_bio at ffffffffc1383471 [raid456]
 #4 [ffff891241e2b628] raid5_make_request at ffffffffc1388db4 [raid456]
 #5 [ffff891241e2b710] md_handle_request at ffffffffa7f8fa30
 #6 [ffff891241e2b780] md_make_request at ffffffffa7f8fb99
 #7 [ffff891241e2b7a8] generic_make_request at ffffffffa7d46e37
 #8 [ffff891241e2b800] submit_bio at ffffffffa7d470e0
 #9 [ffff891241e2b858] osd_submit_bio at ffffffffc14255ac [osd_ldiskfs]
#10 [ffff891241e2b868] osd_do_bio at ffffffffc1427925 [osd_ldiskfs]
#11 [ffff891241e2b9d0] osd_write_commit at ffffffffc142820c [osd_ldiskfs]
#12 [ffff891241e2ba50] ofd_commitrw_write at ffffffffc157121e [ofd]
#13 [ffff891241e2bad8] ofd_commitrw at ffffffffc157510c [ofd]
#14 [ffff891241e2bb58] tgt_brw_write at ffffffffc0f5460b [ptlrpc]
#15 [ffff891241e2bcd0] tgt_request_handle at ffffffffc0f5036a [ptlrpc]
#16 [ffff891241e2bd58] ptlrpc_server_handle_request at ffffffffc0ef724b [ptlrpc]
#17 [ffff891241e2bdf8] ptlrpc_main at ffffffffc0efabac [ptlrpc]
#18 [ffff891241e2bec8] kthread at ffffffffa7ac2e81
#19 [ffff891241e2bf50] ret_from_fork_nospec_begin at ffffffffa8177c24

They were running on /dev/md2 and looks like this is a software raid6 device. I suggest you should investigate write performance for this device to measure whether it is slowly than other.

Thanks,
YangSheng

[Stephane Thiell]

Hi YangSheng,

Thank you very much for your time on this, I really appreciate it.  After the reboot, all OSTs came back online and everything was fine on all targets, even on /dev/md2. I wonder if this could be some kind of mdraid deadlock of some sort, or perhaps a very transient slowdown of a raid6 array.

Stephane

[Yang Sheng]

Hi, Stephane,

I have investigated all of thread carefully. I cannot find any clue for deadlock. I suggest you can collect disk io info(like iostat) while this issue be hit again. Then compare it with normal data(collect without this issue) to determine whether it is a storage problem.

Thanks,
YangSheng

[Stephane Thiell]

Hi YangSheng,

Thanks, next time I'll try to collect disk I/O info, that's a great idea indeed. But so far, this OST has been running fine since this event.

Best,

Stephane

[Yang Sheng]

Please reopen it while hit again.