[LU-11125] ofd_create_hdl() destroys_in_progress already cleared

• Type: Bug
• Resolution: Fixed
• Priority: Major
• Fix Version/s: Lustre 2.12.0, Lustre 2.10.6
• Affects Version/s: Lustre 2.10.4
• Labels: llnl
• Environment: lustre-2.10.4_1.chaos-1.ch6.x86_64 servers ; RHEL 7.5 ; DNE1 file system
• Severity: 3
• Assignee: Mikhail Pershin
• Reporter: Olaf Faaland

Description

Servers were restarted and appeared to recover normally.  They briefly appeared to be handling the same (heavy) workload from before they were powered off, then started logging the "system was overloaded" message.  The kernel then reported several stacks like this:

INFO: task ll_ost00_007:108440 blocked for more than 120 seconds.
"echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
ll_ost00_007 D ffff8ba4dc35bf40 0 108440 2 0x00000080
Call Trace:
[<ffffffffaad38919>] schedule_preempt_disabled+0x39/0x90
[<ffffffffaad3654f>] __mutex_lock_slowpath+0x10f/0x250
[<ffffffffaad357f2>] mutex_lock+0x32/0x42
[<ffffffffc1669afb>] ofd_create_hdl+0xdcb/0x2090 [ofd]
[<ffffffffc1322007>] ? lustre_msg_add_version+0x27/0xa0 [ptlrpc]
[<ffffffffc132235f>] ? lustre_pack_reply_v2+0x14f/0x290 [ptlrpc]
[<ffffffffc1322691>] ? lustre_pack_reply+0x11/0x20 [ptlrpc]
[<ffffffffc138653a>] tgt_request_handle+0x92a/0x1370 [ptlrpc]
[<ffffffffc132db5b>] ptlrpc_server_handle_request+0x23b/0xaa0 [ptlrpc]
[<ffffffffc132b26b>] ? ptlrpc_wait_event+0xab/0x350 [ptlrpc]
[<ffffffffaa6d5c32>] ? default_wake_function+0x12/0x20
[<ffffffffaa6cb01b>] ? __wake_up_common+0x5b/0x90
[<ffffffffc1331c70>] ptlrpc_main+0xae0/0x1e90 [ptlrpc]
[<ffffffffc1331190>] ? ptlrpc_register_service+0xe30/0xe30 [ptlrpc]
[<ffffffffaa6c0ad1>] kthread+0xd1/0xe0
[<ffffffffaa6c0a00>] ? insert_kthread_work+0x40/0x40
[<ffffffffaad44837>] ret_from_fork_nospec_begin+0x21/0x21
[<ffffffffaa6c0a00>] ? insert_kthread_work+0x40/0x40

 And lustre began reporting:
LustreError: 108448:0:(ofd_dev.c:1627:ofd_create_hdl()) lquake-OST0003:[27917288460] destroys_in_progress already cleared

 

Issue Links

• is related to: LU-11399 use separate locks for orphan destroy and objects re-create at OFD

Comments

[Gerrit Updater]

Oleg Drokin ([e-mail]) merged in patch https://review.whamcloud.com/32985/
Subject: LU-11125 ofd: decrease message level
Project: fs/lustre-release
Branch: master
Current Patch Set:
Commit: c25c4d60ac5fbede50a41da12f91de6e402b3c68

[Gerrit Updater]

Mike Pershin ([e-mail]) uploaded a new patch: https://review.whamcloud.com/32985
Subject: LU-11125 ofd: decrease message level
Project: fs/lustre-release
Branch: master
Current Patch Set: 1
Commit: 68c740bcc319d019ec545eb50f25417a4bd9f7a9

[Mikhail Pershin]

Olaf, this message is not an error so it can be just made less noisy as first step and then I will create new improvement ticket to investigate this area thoughtfully to lower contention on that mutex during OST recovery

[Olaf Faaland]

Hello Mikhail, have you learned anything more of interest?  Thanks.

[Mikhail Pershin]

It still may indicate the problem there, there are two different operations are possible on OST restart - MDT initiates orphan destroys, but also new precreates may be initiated by write replays. Both uses the same mutex 'os_create_lock' though one process destroys non-used objects and other creates new objects. That causes high contention on that mutex exactly on OST restart and I am checking now is that possible to separate locking for both processes. That would relieve load on that mutex.

[Olaf Faaland]

Thank you for the explanation.

It seems the problem is in that long orphan destroy, something was blocking it for quite a time. That can be just result of overall high load upon OST restart

It sounds like destroys_in_progress should be a CDEBUG message, since it can occur under normal operating conditions.

 

[Mikhail Pershin]

That message - "destroys_in_progress already cleared" - related just to MDT->OST reconnects and may happen when MDT reconnects due to some reasons but OST is still performing orphan destroys from previous connect. I see in logs in description this:

00002000:00020000:9.0:1530842274.090444:0:102598:0:(ofd_dev.c:1627:ofd_create_hdl()) lquake-OST0002:[28991030285] destroys_in_progress already cleared
00000100:00000400:8.0:1530842274.090453:0:102596:0:(service.c:2114:ptlrpc_server_handle_request()) @@@ Request took longer than estimated (755:203s); client may timeout.  req@ffff8bb9b7e93850 x1605203337942624/t0(0) o5->lquake-MDT0003-mdtlov_UUID@172.19.1.114@o2ib100:296/0 lens 432/400 e 0 to 0 dl 1530842071 ref 1 fl Complete:/0/0 rc 0/0

Looks like second thread [102598] was waiting for the first [102596] to complete OST_CREATE request with orphan destroys. And that first one took quite long time. It seems the problem is in that long orphan destroy, something was blocking it for quite a time. That can be just result of overall high load upon OST restart

[Olaf Faaland]

I am going to attempt to re-create this without the complication of the Lustre 2.11 arm system mounting the file system.

[Olaf Faaland]

I was mistaken about OST0002 being rebooted a second time.  The file system was restarted just once, and the symptoms described here were seen after they came up and completed recovery.

 

[Olaf Faaland]

Mike, at the time several IORs were running and they all appeared not to resume progress after recovery completed.  ltop was showing no activity on the file system, and the IORs were not finishing at the expected pace.

Later, the problem seemed to resolve itself - all but one of the IORs completed successfully, but several took 10-20 times longer than they should have.  I'm looking into that now to get more information.

One compute node crashed, but due to an unrelated problem we have neither the stack nor the crash dump.  We're looking into that problem as well.

 

 

 

[Mikhail Pershin]

Olaf, are there any other bad effects except stack dumps and LustreError messages? Do OSTs works normal after all? You mentioned that OST0002 was rebooted, was that because of this issue or planned restart?