|
Oleg will dig into this one
|
|
So, looking into it from a simple angle:
The timeout set is determined by ldlm_get_enq_timeout() an that function is remarcably simple:
timeout = min_t(int, at_max, timeout + (timeout >> 1));
So we take whatever at_timeout is ( timeout = at_get(ldlm_lock_to_ns_at(lock)) ) and then pick the maxumum of 150% of it or at_max.
Even if timeout is for some miracle negative, taht would be caught by next step:
return max(timeout, ldlm_enqueue_min);
So we'll choose the bigger one of at_max or default value of ldlm_enqueue_min which is 100 (unless you override that with a module param which you probably don't).
Overall all lock timeout increases go through __ldlm_add_waiting_lock that has a second parameter of seconds. It's pretty easy to add a check there to ensure we are not filing any outrageous timeouts anyway (which I suspect we don't).
The next step here is in the actual lock timeout function waiting_locks_callback().
There before we actually evict the lock, we make a check if it's currently "busy" with ldlm_lock_busy().
Checking the function, it calls hpreq_lock_match. Now at least in case of MDT there's no hpreq handler registered there, so the only way for it to trigger is if the request is cancel and it's stuck in the queue somehow. Now if this does indeed happen, we are in a much bigger trouble here because the client did send a cancel and it's actually sitting right at the server for thousands of seconds unable to be processed? Does not sound too plausible, I guess.
We probably can debug this by adding a "prolonged" counter or printign a warnong when the lock was prolonged past original timeout for way too long.
I imagine, one more possible venue here is if we got a group lock here in the list, it would stop all waiting list processing, which sounds like a bug, but you are unlikely to have those?
Or if a lock with a very long timeout has landed on the list somehow, it would prevent the list from being processed until it's time hits. This is probably artefact of old times when lock timeout time was fixed and we did not want to iterate through tons of locks in the list asuming they are in mostly time-ordered order.
Perhaps adding an extra debug at
if (cfs_time_after(lock->l_callback_timeout,
cfs_time_current()) ||
(lock->l_req_mode == LCK_GROUP))
break;
to make sure that lock->l_callback_timeout is not say more than X*at_max in the future just in case would be good too.
Now, when you do see the timeouts, do you know if the node that was evicted was actually alive at the time, by any chance?
Do you have a system where we can try above mentioned debug to better narrow down the culprit (also would you like me to compose a patch?)
|
|
What is a "group lock"?
Many, many mdt theads get stuck. I rather suspect that in most cases the client nodes are alive, but I can't say that I have hard proof of that.
Yes, please do make a patch. We can install it on the production MDS without too much delay (At worst we install it and wait for the next reboot. At best they let me reboot the MDS sooner onto the debug version.)
|
|
After another look through the code, I discovered that l_last_activity that is used to print that scary thousands of second number is only updated on lock enqueue, but not when we send the blocking AST, so the big number might be a red herring.
As for stuck MDT threads, if the lock cancel was not delivered, it's only natural that everybody with conflicting locks was waiting for the cancel. The bigger question then is why the cancel is not coming assuming the client is alive?
|
|
Just as a note since ORNL switched to 2.4 clients we are also seeing this as well.
|
|
Sorry, the 1200 second warning is from lustre. We frequently see the lustre watchdog tripped and complain that "Service thread pid X was inactive for 1200.00s".
Are you saying that l_last_activity is completely uninitialized, or that it will be a cummulative number? Either way, lets get a fix for that. At least we'll start moving in the direction of understanding what is going on.
|
|
l_last_activity is initialiized when the lock is requested (also when converted). So it really shows how long that lock was alive. We probably should also init it every time we send something to the client so that it shows sensical numbers at other times.
The 1200 seconds "inactivity" timeout is well explainable. it's due to ldlm enqueue timeout defined as ldlm_get_enq_timeout(lock) * 2 (== at_max * 2) in ldlm_completion_ast.
Chances are 600 seconds before the inactivity timer there's some lock timeout and client eviciton, then another one shortly around the inactivity timeout hit? E.g. because there were two locks (from different clients) that somehow could not be canceled?
|
|
No, I don't see evictions or timeouts 600s before the inactivity timeout.
It does seem common for either a "lock callback timer expired after 1200s: evicting client" or a "lock timed out (enqueued at X, 1200s ago)" at the beginning of a bunch of 1200s inactivity warnings.
|
|
Ok, I uploaded http://review.whamcloud.com/9127 that I tested lightly here.
It fixes lock eviction message to actually specify how long was the wait since sending the RPC.
Adds a few timeout checks just in case (I see some refresh calls from e.g. ofd may not use at_max.
Prints number of busy lock prolongations (a bit hackish, only for ibit locks - i.e. MDS)
This only makes sense to install on servers, primarily mds. Though I tested and clients don't die either in case you install it there by mistake too.
I imagine it would be interesting to run with this and once the first 1200 timeout hits, have a log of this timeout + preceeding hour of messages.
|
Ok, I uploaded http://review.whamcloud.com/9127 that I tested lightly here.
Great, thanks! I'll pull that in and see how quickly I can get the admins to install it. Maybe that will help us start to see where the real problems lie.
|
|
A quick follow on question based on stuff in LU-4570 - are all/most timed out locks reported on MDT (with corresponding client eviction) happen to have PR/PR mode? Mostly same fid? If so, are there any errors reported on cient side coming from dir.c or otherwise hinting at readdir failures?
|
|
Well, yes, they are mostly PR/PR. But there are a few CR/CR in there as well. But that also was true going back a year when we were running 2.1. The server doesn't mention fids, so I wouldn't know.
I don't recall what was happening on the clients, I'll keep an eye our for that the next time I see a problem.
Frankly I'm beginning to expect that ldiskfs caching is the root of our troubles, as it has been in the past. Something lustre related is definitely badly fragmenting memory on the servers. If we leave zone_reclaim_mode=1 (the default), the zone reclaim code goes out to lunch for tens of minutes, and possibly hours, making the servers unusable. If we set zone_reclaim_mode=1 then we fragment and exhaust all of the memory on the node, causing order:2 atomic allocation failures in the mlx4 (10GigE mellanox) driver. That driver doesn't handle failed allocations reliably which leaves the node in a bad state.
Of course, I'm making a bit of a guess about why the zone reclaim is such a problem based on my observations of the system with zone_reclaim_mode=0. There could be something else going on there.
But I don't really know if the memory problems that I am hunting now are the same root of all of our problems, or just one problem among many.
|
|
fid will be visible as resource id.
|
|
per export lock callback AT: http://review.whamcloud.com/#/c/9336/
|
|
The symptoms of this bug returned today, where MDT service thread sleep for 1200 seconds, and clients get evicted for expired lock callback timers after several thousand seconds.
In desperation, I disabled adaptive timeouts and set the static OBD timeout to 15 seconds. This triggered a few thousand evictions for expired lock callback timers, and all threads stuck in ldlm_completion_ast() got unstuck. Here is some console output following the change:
|
|
So with all your locks evisted being PR locks just like in LU-4570, let's try to isolate how come readdir locks are so stubborn.
Next time you see a "refused reconnection, still busy with X RPCs" message, please do a sysrq-t on that client node to see what is it doing.
If you can pull off sysrq-t on the MDT to ensure that mdt_rdpg_ threads are not stuck somewhere - that would be great as well.
My suspicion is there's some path on a client that forgets to release a reference to a matched lock (and the lock happening to be PR lock at all times somehow) and then it's never cancelled. I tried to review the code and I do not see anything, though. Likely happens on a failure path of some sort, so only triggers if you have other problems (And I see you also have client evictions for inactivity and what not).
It's interesting that over at ORNL after applying lu4008 and lu4719 patches, similar symptoms went away, though not entirely clear why. So it still might be worth your while to pull in those patches.
|
|
The fix for the very-wrong timeouts in console messages was part of a larger debug patch that is not intended for landing. The timeout fix should be broken out into its own patch and landed.
|
|
Attaching sysrq-t output for client that was being refused reconnection, and for the MDS. The problem with many MDS service threads getting stuck in ldlm_completion_ast() happened again today on two of our lustre clusters. We rebooted the MDS nodes to recover.
|
|
As I just commented in LU-4584 - Is there any chance you can drop patch for lu-3338 from your tree and see if the issue is still there?
With ldlm resends not properly detected you can see this sort of behavior where clients are not dropping locks (that they do not have really) and get timed out.
And the resends are happening because the clients provide too small of a buffer.
If the patch removal is too hard, at least try to increase the minimal allocation size some more. I know it would result in harder work for kernel during allocations and such, but before we tackle this resending detection to be bullet proof, I am interested in seeing the results with resends totally eliminated.
|
As I just commented in LU-4584 - Is there any chance you can drop patch for lu-3338 from your tree and see if the issue is still there?
Oleg, I don't think that is likely. We need that. To take it out, you would need to provide us with a fix that works as well.
|
|
Chris have you tried http://review.whamcloud.com/#/c/10230? That patch addressed the issue of early replies ignoring at_max.
|
|
James, that is on my list of things to try. It will be another things that helps us make sense of what is going on by having saner numbers, but I suspect it won't address our root issue(s). There are so many issues though, it is sometimes hard to see the forest for the trees.
|
|
I think this is like several issues in one.
First we have those undesirable lock evictions that are likely due to LU-4584 / LU-2827 and then once that condition hits the too long timeout due to LU-4578 would also become an issue.
|
|
There is also LU-5116 which I saw a few times in testing as well. The patch for that ticket does even solve all the issues 
|
|
I extracted timeout fixes to http://review.whamcloud.com/10601
My testing seems to show it works.
Without patch:
and with the patch that becomes:
|
|
Landed for 2.6
|
Generated at Sat Feb 10 01:44:00 UTC 2024 using Jira 9.4.14#940014-sha1:734e6822bbf0d45eff9af51f82432957f73aa32c.
sysrq-t.catalyst141.client.txt