Details
-
Bug
-
Resolution: Unresolved
-
Blocker
-
None
-
Lustre 2.12.0
-
None
-
CentOS 7.6, Lustre 2.12.0, 3.10.0-957.1.3.el7_lustre.x86_64
-
3
-
9223372036854775807
Description
We upgraded our cluster Sherlock to Lustre 2.12 yesterday and put Fir (Lustre 2.12 servers) into production yesterday but this morning, the filesystem is unusable due to a super high load of ldlm threads on the MDS servers.
I can see plenty of these on the MDS:
[Wed Feb 6 09:19:25 2019][1695265.110496] LNet: Service thread pid 35530 was inactive for 350.85s. The thread might be hung, or it might only be slow and will resume later. Dumping the stack trace for debugging purposes: [Wed Feb 6 09:19:25 2019][1695265.127609] Pid: 35530, comm: mdt02_024 3.10.0-957.1.3.el7_lustre.x86_64 #1 SMP Fri Dec 7 14:50:35 PST 2018 [Wed Feb 6 09:19:25 2019][1695265.137522] Call Trace: [Wed Feb 6 09:19:25 2019][1695265.140184] [<ffffffffc0e3a0bd>] ldlm_completion_ast+0x63d/0x920 [ptlrpc] [Wed Feb 6 09:19:25 2019][1695265.147339] [<ffffffffc0e3adcc>] ldlm_cli_enqueue_local+0x23c/0x870 [ptlrpc] [Wed Feb 6 09:19:25 2019][1695265.154723] [<ffffffffc15164ab>] mdt_object_local_lock+0x50b/0xb20 [mdt] [Wed Feb 6 09:19:25 2019][1695265.161731] [<ffffffffc1516b30>] mdt_object_lock_internal+0x70/0x3e0 [mdt] [Wed Feb 6 09:19:25 2019][1695265.168906] [<ffffffffc1517d1a>] mdt_getattr_name_lock+0x90a/0x1c30 [mdt] [Wed Feb 6 09:19:25 2019][1695265.176002] [<ffffffffc151fbb5>] mdt_intent_getattr+0x2b5/0x480 [mdt] [Wed Feb 6 09:19:25 2019][1695265.182750] [<ffffffffc151ca18>] mdt_intent_policy+0x2e8/0xd00 [mdt] [Wed Feb 6 09:19:25 2019][1695265.189403] [<ffffffffc0e20ec6>] ldlm_lock_enqueue+0x366/0xa60 [ptlrpc] [Wed Feb 6 09:19:25 2019][1695265.196349] [<ffffffffc0e498a7>] ldlm_handle_enqueue0+0xa47/0x15a0 [ptlrpc] [Wed Feb 6 09:19:25 2019][1695265.203643] [<ffffffffc0ed0302>] tgt_enqueue+0x62/0x210 [ptlrpc] [Wed Feb 6 09:19:25 2019][1695265.210001] [<ffffffffc0ed735a>] tgt_request_handle+0xaea/0x1580 [ptlrpc] [Wed Feb 6 09:19:25 2019][1695265.217133] [<ffffffffc0e7b92b>] ptlrpc_server_handle_request+0x24b/0xab0 [ptlrpc] [Wed Feb 6 09:19:25 2019][1695265.225045] [<ffffffffc0e7f25c>] ptlrpc_main+0xafc/0x1fc0 [ptlrpc] [Wed Feb 6 09:19:25 2019][1695265.231563] [<ffffffffadcc1c31>] kthread+0xd1/0xe0 [Wed Feb 6 09:19:25 2019][1695265.236657] [<ffffffffae374c24>] ret_from_fork_nospec_begin+0xe/0x21 [Wed Feb 6 09:19:25 2019][1695265.243306] [<ffffffffffffffff>] 0xffffffffffffffff [Wed Feb 6 09:19:25 2019][1695265.248518] LustreError: dumping log to /tmp/lustre-log.1549473603.35530
On Fir, we have two Lustre 2.12 MDS, fir-md1-s1 and fir-md1-s2, each with 2 MDTs. I dumped the current tasks using sysrq to the console and I'm attaching the full console log for both MDS servers. The servers don't crash but lead to unsable/blocking clients,however from time to time we can access the filesystem. Any help would be appreciated. Thanks!
Stephane
Attachments
Issue Links
- duplicates
-
-
- Open
-
Activity
This issue should probably be reopen because we just seen it with 2.12.3 RC1. After a client announced itself with a @tcp NID, it was very hard to remove it from Lustre. We had to evict the bogus tcp nid + use lnetctl peer del --prim_nid.
And it didn't even work the first time:
[root@fir-md1-s1 fir-MDT0000]# lnetctl peer show --nid 10.10.117.42@tcp
peer:
- primary nid: 10.10.117.42@tcp
Multi-Rail: True
peer ni:
- nid: 10.9.117.42@o2ib4
state: NA
- nid: 10.10.117.42@tcp
state: NA
[root@fir-md1-s1 fir-MDT0000]# lnetctl peer del --prim_nid 10.10.117.42@tcp
[root@fir-md1-s1 fir-MDT0000]# lnetctl peer show --nid 10.10.117.42@tcp
peer:
- primary nid: 10.10.117.42@tcp
Multi-Rail: False
peer ni:
- nid: 10.10.117.42@tcp
state: NA
See, it removed the good one (o2ib4)!
With a combination of eviction + peer deletion, it worked:
[root@fir-md1-s1 fir-MDT0000]# cat exports/10.10.117.42@tcp/uuid
2f0c7362-5db5-a6c6-08eb-fa16109cc0f9
[root@fir-md1-s1 fir-MDT0000]# echo 2f0c7362-5db5-a6c6-08eb-fa16109cc0f9 > evict_client
[root@fir-md1-s1 fir-MDT0000]# lnetctl peer del --prim_nid 10.10.117.42@tcp
[root@fir-md1-s1 fir-MDT0000]# lnetctl peer show --nid 10.9.117.42@o2ib4
peer:
- primary nid: 10.9.117.42@o2ib4
Multi-Rail: True
peer ni:
- nid: 10.9.117.42@o2ib4
state: NA
[root@fir-md1-s1 fir-MDT0000]# ls exports| grep tcp
[root@fir-md1-s1 fir-MDT0000]#
This is a problem, we have IB only routers and no tcp network/route defined on the servers, I don't know why Lustre does accept it at all. Also, the ldlm_bl thread at 100% is also still a problem:
$ top PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND 40268 root 20 0 0 0 0 S 100.0 0.0 114:45.76 ldlm_bl_06 16505 root 20 0 164284 4424 1548 R 22.2 0.0 0:00.04 top 35331 root 20 0 0 0 0 S 5.6 0.0 100:37.82 kiblnd_sd_03_03 35333 root 20 0 0 0 0 S 5.6 0.0 0:48.41 lnet_discovery
I'm feeling hesitant of dumping the tasks right now, as the filesystem is heavily used.
Yes I confirm that when we get rid of all bogus clients and restart all Lustre servers, everything is back to normal. The servers don't recover by themselves so a full restart is required apparently. Other Lustre servers running 2.8 or 2.10 are not affected. Please feel free to mark this one as duplicate of LU-11888. I also opened LU-11937 to find out why in some case a NID with tcp0 is loaded on the clients.
Thanks!
Stephane
Ah! Just after submitting this ticket and attaching the different files, I just noticed that a possible issue could be that we do have (again) one client having a NID using @tcp leading to unusable servers.
For example, from lustre-log.1549473603.35530:
@@@ Request sent has failed due to network error: [sent 1549473603/real 1549473603] req@ffff912521032d00 x1623682053684704/t0(0) o106->fir-MDT0002@10.10.114.10@tcp:15/16 lens 296/280 e 0 to 1 dl 1549473614 ref 1 fl Rpc:eX/2/ffffffff rc -11/-1 lib-move.clnet_handle_find_routed_pathno route to 10.10.114.10@tcp from <?>
All our Lustre servers are exclusively IB. If this is the cause of the issue, this could be a duplicate of my previous ticket LU-11888.
I'll investigate and get rid of this bad node and then confirm or not.
Best,
Stephane
This is the task that was in an endless loop:
I'm attaching the full task dump when this was happening as fir-md1-s1_20191022.log
We have restarted the MGS. Unmounting it made the server unresponsive.