[LU-2455] lctl ping takes too long to timeout

• Status: Resolved
• Project: Lustre
• Affects Version/s: Lustre 2.1.2
• Type: Bug
• Priority: Minor
• Reporter: Shuichi Ihara (Inactive)
• Assignee: Bruno Faccini (Inactive)
• Resolution: Incomplete
• Severity: 3

Description

lctl ping in theory takes a timeout parameter, with the default timeout being 1 second. In practice, however, the timeout can be significantly longer. It appears that it changes the timeout to 60s if it needs to UNLINK. Is there any way to eliminate this or is it mandatory that if there is an error, pings could take up to 60s? As it is now, the timeout is not very useful.

Comments

[Peter Jones]

Bruno

Could you please advise on this one?

Thanks

Peter

[Bruno Faccini (Inactive)]

I am afraid that's the way it is coded in lnet_ping() routine, and this stands for both the 60s time-out value and the automatic wait/retry with such time-out.

BTW, can you provide "lctl ping" output and also if possible enable "echo +neterror +net > /proc/sys/lnet/[debug,print]" when you get this kind of error/situation ?? This will help me to definitely confirm the responsible code path in the sources.

[Kit Westneat (Inactive)]

Here's the relevant dk output, I'll attach the full dk:

00000400:00000200:0.0:1355245748.810589:0:5818:0:(lib-move.c:2705:LNetGet()) LNetGet -> 12345-10.10.10.179@tcp1
00000800:00000200:0.0:1355245748.810605:0:5818:0:(socklnd_cb.c:947:ksocknal_send()) sending 0 bytes in 0 frags to 12345-10.10.10.179@tcp1
00000800:00000200:0.0:1355245748.810810:0:5818:0:(socklnd.c:199:ksocknal_find_peer_locked()) got peer [ffff88002ee574c0] -> 12345-10.10.10.179@tcp1 (2)
00000800:00000200:0.1F:1355245748.810818:0:5818:0:(socklnd.c:199:ksocknal_find_peer_locked()) got peer [ffff88002ee574c0] -> 12345-10.10.10.179@tcp1 (2)
00000400:00000200:0.0:1355245749.810695:0:5818:0:(api-ni.c:1800:lnet_ping()) poll 0(-1 -1)
00000400:00000200:0.0:1355245749.810710:0:5818:0:(lib-md.c:69:lnet_md_unlink()) Queueing unlink of md ffff88003916cdc0
00000400:00000200:0.0:1355245769.826898:0:5818:0:(api-ni.c:1800:lnet_ping()) poll 1(4 0) unlinked

If I am reading it right, the ping times out correctly after 1s, but then the unlinking takes 20s.

Here is how I reproduced it:
[root@traiana-mds0 ~]# iptables -A OUTPUT -p tcp --destination-port 988 -j DROP
[root@traiana-mds0 ~]# /usr/bin/time lctl ping 10.10.10.179@tcp1 1
failed to ping 10.10.10.179@tcp1: Input/output error
0.00user 0.00system 0:21.00elapsed 0%CPU (0avgtext+0avgdata 2768maxresident)k
0inputs+0outputs (0major+214minor)pagefaults 0swaps

On an IB network, we have seen it take over 50s.

[Kit Westneat (Inactive)]

full dk from the time period of the ping

[Bruno Faccini (Inactive)]

Unlink will occur asynchronously ("lnet_md_unlink()) Queueing unlink") because at least one msg may still references it.

And the way/timing for msgs to be terminated/discarded seems NAL dependent, so this may explain the differences you've seen.

Will try to fully explain that using your reproducing method.

[Kit Westneat (Inactive)]

I guess the problem is that it's difficult to put a timeout on a TCP connect operation. That appears to be what is blocking for 20s. It's too bad that there is no way to handle the cleanup in the background, and return to userspace before the connect times out. I saw that the MD is created with auto-unlink enabled, but there doesn't appear to be a corresponding "autofree" for the event queue, is that correct?

Would it be possible to add an event handler callback that would do the cleanup? That way the lnet_ping code could enqueue the unlink and then return an error immediately. It's probably not that straightforward I suppose.