|
Actually, it looks like the MDT evicts both the client on which the file was created and the client that is running robinhood (changelog client).
Here is an example. The players are:
- 172.16.66.4@tcp - Lustre client on which I ran "touch foo"
- 172.16.66.5@tcp - Lustre client on which I ran "rm foo"
- 172.16.66.30@tcp - Lustre client which is consuming changelogs (it is running robinhood)
- 172.20.20.201@o2ib500 - Lustre MDS
So I start by doing "rm foo" on 172.16.66.5@tcp:
Lets follow that RPC over to the MDS on 172.20.20.201@o2ib500:
So the MDS node immediately turns around and creates 6 RPCs, 3 for 172.16.66.4@tcp, 1 for 172.16.66.5@tcp, and 2 for 172.16.66.30@tcp. Those RPCs all appear to complete in very little time.
Shortly after that, the server receives LDLM_CANCEL rpcs from both 172.16.66.4@tcp (the client where the file was originally created) and 172.16.66.30@tcp (the robinhood client node).
Here is the 172.16.66.4@tcp client handling the three LDLM_BL_CALLBACK callbacks. For whatever reason, it only seems to result in a single LDLM_CANCEL back to the server. Is that a problem?
But the client seems to think its work is done, because the only rpcs I see it sending to the server over the next 100 seconds are the normal OBD_PING aliveness checks.
The server is clearly not satisfied, because later after the 100 second timeout it evicts both 172.16.66.4@tcp and 172.16.66.30@tcp. He is the server doing that:
Note that the "timer expired after" numbers are bogus (which we recognized in LU4579). If you check the timestamps you'll see that it really is 100 seconds after the lock cancel was issued.
After the evictions the server can finally reply to the initial unlink rpc:
This info was gathered on production systems, so I've selected key info that I thought was relevant. I will also attach the full logs, in case anyone wants to sort through and look for something else.
|
|
This won't be terribly surprising, but here is the back trace from the mdt thread that handled the initial unlink-related RPC. This backtrace was taken during the middle of the 100s waiting period:
But this also happens to be a common stack trace from hundreds of threads on our MDS nodes when they go unresponsive for hours at a time. So I am keen to get to understand this problem soon in case it turns out to be related to our wider production Lustre problems.
|
|
Hello Chris,
It is unclear for me if RobinHood's presence is required to reproduce? I presume RobinHood and ChangeLog usage are enabled by default on your production systems but it would help if we can determine if RobinHood's has any impact for this issue.
|
|
I am also trying to find/set-up a similar platform to run your reproducer there.
|
|
I don't know yet if a changelog consumer is a requirement either. I haven't been able to reproduce this problem yet in our testbed, which is both smaller and doesn't have a changelog user.
But I was hoping that someone could explain to me how lustre's protocol is expected to work. Since I have a great reproducer, I'm happy to investigate any point where the protocol is not behaving as expected.
For instance, could someone explain what else the server might be needed from the clients? The clients have each sent a LDLM_CANCEL...is that not sufficient? Are the clients failing to do something, or did the server just fail to correctly associate those cancels with the outstanding rpc? Are the number of RPCs generated earlier in the sequence as expected? Does three LDLM_BL_CALLBACKs for the node where the file was created and two more for the node running the changelog client make sense? What are their purpose?
|
|
I think it is likely that the multiple LDLM_CANCEL answers from the Clients have been packed in the same/single RPC.
And I think multiple LDLM_BL_CALLBACKs can be sent by MDS for different Inode-bits beeing locked.
But to definitely validate these assumptions I need more/full traces.
So, could it be possible that you enable both rpctrace and dlmtrace on Clients and Server/MDS sides, also set /proc/sys/lustre/dump_on_eviction (works only on Clients I think, so you will need to "lctl dk" on MDS) and also may be grow the debug-log buffer size, in order to get all traces after running your reproducer again? Or may be you already have this in the full logs you promised to attach ?
BTW, the "rc -22/-22" during one of the LDLM_BL_CALLBACK you posted looks also suspicious.
|
|
Doh! I definitely uploaded the logs to some ticket, but I must have accidentally attached them to the wrong one. Here the are in the right place.
|
I think it is likely that the multiple LDLM_CANCEL answers from the Clients have been packed in the same/single RPC.
Ah, is that perhaps what this shows?
|
|
See the attached file "client_log_20140206.txt".
I can't get more detailed logs from the MDS right now because it is too heavily loaded to make higher debugging level practical.
But the new client log is from the client where I created a file named "foo". I did the "rm foo" on another client. This time I added "rpctrace dlmtrace vfstrace" to the log level on the client. dlmtrace is new in this log. With that, you can see better where the -22 comes from on the client.
|
|
No, this trace means that 1 RPC has been handled by ptlrpcd #3 and stolen from partner #2, the packed requests will appear in the "CDEBUG(D_DLMTRACE, "%d locks packed\n", packed);" msg/trace from ldlm_cancel_pack().
|
|
BTW, in the last Client (the node doing the "touch") log you attached, there is only one ldlm_cancel_pack() trace reporting a single LDLM_CANCEL RPC to be sent back to MDS. And it concerns only 2 of the LDLM_BL_CALLBACKs sent by the Server for the same lock/handle ffff8801f8c5e200/0x6aff086a1c937ce8, as identified by the Client.
And the -22/-EINVAL is for the 3rd LDLM_BL_CALLBACK and it concerns an other handle (0x6aff086a1c937ce1) that the Client can't find the corresponding lock :
Going up in the log we can see the following traces sequence for 0x6aff086a1c937ce1 (failing) handle :
and then in immediate continuation the traces sequence for the "valid" handle (still within the same "touch" process context) :
So it looks like the Server/MDS sent a ELDLM_LOCK_ABORTED, but was still expecting the Client to cancel it when Client found it not necessary ?
Will dig more into the source code to find if/why this can happen. But in the mean-time, can you help to find the differences/patches between Client and Server versions you run?
|
But in the mean-time, can you help to find the differences/patches between Client and Server versions you run?
We mirror our branches on github. See http://github.com/chaos/lustre. Both of the mentioned tags, 2.4.0-19chaos and 2.4.0-21chaos, are on the 2.4.0-llnl branch.
|
|
The diffs between 2.4.0-19chaos and 2.4.0-21chaos are :
And I did not found anything in these changes that may indicate any incompatibility between Clients running 2.4.0-19chaos and Servers running 2.4.0-21chaos.
I am now investigating the ELDLM_LOCK_ABORTED reason/handling in the code.
|
|
from 172.20.20.201@o2ib500.log (MDS log)
00010000:00020000:8.1:1391563589.283179:0:0:0:(ldlm_lockd.c:391:waiting_locks_callback()) ### lock callback timer expired after 302s: evicting client at 172.16.66.4@tcp ns: mdt-fsv-MDT0000_UUID lock: ffff880f17f60200/0xf70254b1ce2bd28a lrc: 3/0,0 mode: CR/CR res: 8589983111/32 bits 0x8 rrc: 3 type: IBT flags: 0x20 nid: 172.16.66.4@tcp remote: 0x1dfa39e9c64af6c1 expref: 2469 pid: 17054 timeout: 4759057840 lvb_type: 3
the problem lock's bits is 0x8 (MDS_INODELOCK_LAYOUT), its lvb_type is 3 (LVB_T_LAYOUT), it's something about layout lock issue here.
|
|
Thanks Bobi to have a look on the Server side/trace when I only focused on Client side and in client_log_20140206.txt log until now ... But anyway it is not really helpful too since it is the only trace about this particular lock in both Client and Server logs.
So we are stuck here and as we discussed I started to build a platform to try to reproduce with full debug enabled. And see if problem is related to large striping layout, as we suspect actually, or anything else.
|
|
I builded a configuration to allow me 48 stripe count on zfs, with robinhood, but I am unable to reproduce at the moment…
I wonder if you could try to configure LDLM/RPC traces with a big debug buffer on your MDS, with dump_on_evict set on Clients, and re-run the reproducer during some quiet period to allow to get detailled traces for both sides ?
|
|
Finally I have been able to reproduce locally, and running with Lustre 2.4.0-RC2 only !! So I have the full traces for both MDS and Clients sides.
1st analysis indicates that the lock causing the evict is one that has been created thru mdt_intent_lock_replace() to replace an older one, and it seems to lead to a lock being replicated for some reason :
More to come.
|
|
Hi Bruno,
Good job reproducing it local side.
"And the -22/-EINVAL is for the 3rd LDLM_BL_CALLBACK and it concerns an other handle (0x6aff086a1c937ce1) that the Client can't find the corresponding lock " - Usually this means that the lock has already been canceled from the client side. This is a normal race.
|
and running with Lustre 2.4.0-RC2 only
Just FYI, 2.4.0-RC2 and 2.4.0 tag the same commit.
Are you suggesting that later 2.4.X tags do not have this problem?
|
|
Chris: No, I just wanted to indicate that according to our/internal tag's nomenclature, I was able to reproduce with the latest 2.4.0-RC2 build running on both Client/Server sides. I will try to reproduce with later 2.4.1-RC2/2.4.2-RC2 versions and let you know.
Jinshan: Ok, for the -22/EINVAL result due to the "normal" race. But concerning the problem and after more local reproducer traces analysis, it looks like on the Server side we are able to deal-with/create 2 identical IBITs locks/handles for the same Client/remote, but then the Client only answer to one during Blocking-AST/Cancel process and simply trashes the other, which seems to lead to this situation when later the Server evicts the Client due to no answer for the 2nd lock.
Does this sound as an already known issue to you ?
|
|
I think you guys only use the -RC2 nomenclature while it is a release candidate, and then drop the -RC2 when the real release is done. There is no reason to keep using the release candidate number when the release is finished.
|
|
More Lustre debug traces analysis seems to indicate that the "orphan" lock on the MDS causing the Client eviction is the one from the 1st open request and acquired via mdt_reint_internal()/mdt_reint_rec()/mdt_reint_open()/mdt_object_open_lock() when the "successfully" canceled one is from the 2nd/reconstructed open request via mdt_reint_internal()/mdt_check_resent()/mdt_reconstruct_open()/mdt_reint_open()/mdt_object_open_lock().
Strange is that it should have been fixed with patch http://review.whamcloud.com/8142 from LU-4179 that is already integrated … Or may be its test "if (lustre_handle_is_used(&lhc->mlh_reg_lh))" does not cover all cases or the Client should have set MSG_REPLAY ?
Also, I need to find what is the reason of the reconstruct open situation.
|
|
The reason of the resend (only, but no replay) from the Client is because the 1st reply from the Server has been truncated, due to a reply buffer of only 2048 bytes being reserved when the answer (including the layout for a 48 stripe width) required length was 2232 bytes.
|
|
I am looking for a possible fix (Client to ask for replay upon open reply truncate?), and also a possible work-around (like to grow the "default" reply buffer?).
And also to exercise the reproducer on b2_5/master.
|
|
I did not read through the whole discussion, but if the client resends RPC with open lock request, and server should return the original one. If you see two locks there, something might be wrong IMHO.
Hmm, you might need http://review.whamcloud.com/#/c/8642/ from LU-4403, especially if 8142 is already integrated.
|
|
Hi Bruno,
The patch 8142 only applied to open by name path. The same fix has to be applied to mdt_open_by_fid_lock() code path as well. Will you please create a patch for it?
Jinshan
|
|
Di: thanks to point on LU-4403/Change #8642, I will give it a try but I already wonder if it can really fix our problem here, since it does not change mdt_intent_fixup_resent() behavior in the case of open_lock and then the uninitialized "ibits" variable will be indeed zeroed by mdt_object_open_lock() during its 1st usage.
Jinshan: I created patch to reproduce Change #8142 from LU-4179 in mdt_open_by_fid_lock(), it is at http://review.whamcloud.com/9342. But I also wonder if it could be the fix for this problem since in my reproducer debug logs I always see open requests with file-name provided and indeed no mdt_open_by_fid_lock() traces.
Chris: what was the reason for running with 2.4.0-21chaos on Servers that include patch from LU-4179 ? Did you encounter the MDS LBUG that patch fixed before ?
Last, I pushed patch http://review.whamcloud.com/9326 to give a try to my own thought that Client should ask for replay if a truncate occurs during open and request is resent.
|
|
Yes, we pulled that in because our MDS crashed with the same assertion and stack as LU-4179.
|
|
Some more results/facts :
_ reproducer triggers the problem on the latest b2_4 (ie, 2.4.2-RC2 + latest patches) and b2_5 builds. Will also try with latest master but I suspect problem will also be there.
_ change #9342, where I simply reproduced the new controls and behavior to to skip open_lock upon resend in mdt_reint_open() (by patch #8142 for LU-4172) but now in mdt_open_by_fid_lock(), fails in auto-tests. Seems to cause setstripe failures ... So need some rework and not just simply to mimic patch #8142.
_ I abandonned change #9326, because after more analysis of the replay mechanisms, I found this way to be wrong. The resend mechanisms are ok (with patch #8142 from LU-4179!! but need also #8642 from LU-4403??) and should be able to handle this scenario, so the problem must be somewhere else (lock hashing/lookup, …).
_ I had a discussion with Johann on this and now I am working on a debug patch to allow more infos to be printed upon resend during 1st lock retrieval with hash-mechanism that seem to fail, and also during 2nd/excess lock blocking-callback that seem also to fail (Client must answer, even return error) …
|
|
According to more reproducer simplification (no more RobinHood required, now made only of "dd" command to create a 48-stripes file and a "file" command in a raw on a same node and then "rm" from an other node) and more debug trace analysis, it definitely seems that, as already indicated before, things start to go wrong when a 2nd lock is enqueued on Server upon truncate+resend, and then there are 2 possible reasons to explain why 1st lock is not found/lookup :
_ 1st lock has not been hashed, or been unhashed
_ hashing mechanism is buggy
I pushed a debug patch at http://review.whamcloud.com/9421, that will help to find the real cause now.
Also interesting, I have not been able to reproduce with latest master at this time ….
|
|
Latest news, and not of lower interest, for this ticket :
_ finally I have been able to reproduce with latest master !!!
_ I have been able to reproduce the problem running with a b2_4 build including my debug patch, and I am now analyzing the traces. 1st constatation already is that the hashing mechanism is working and is not causing the problem. More to come.
|
|
BTW, more indeep analysis of the Lustre debug logs generated by my debug patch, seems that the fact the old/1st lock is not found during hash lookup is due to the new lock already being hashed !! Will try to push a new patch/fix proposal where new_lock hashing will be deferred, or a way to find the old one during lookup if the new one is found 1st ...
|
|
So, thanks to my additional debug traces from #9421!, the fact that the 1st/original lock is not found upon resend handling on Server, is due to the early new lock create+hash in ldlm_handle_enqueue0() that the cfs_hash_lookup() call in mdt_intent_fixup_resent() returns instead of the 1st/old one.
I will try to develop a fix where mdt_intent_fixup_resent() uses cfs_hash_for_each_key() intead and with a callback that will simply return ok if the current/hashed lock is not new_lock, to allow the old/resent lock, if any, to be looked-up.
|
|
New patch/fix attempt that implement previous comment solution is at http://review.whamcloud.com/9488.
|
|
With patch-set #3 of #9488, running the reproducer I triggered the crash/LBUG tracked in LU-4403 !! :
This is because the lock (created or not) is expected to have at least a reference when leaving mdt_reint_open().
But fix from LU-4403 will not help since running with latest master version that include it, I reproduced the lock replication during truncate/resend scenario. This may be because it seems to be intended to handle pure/only MDS_OPEN_LOCK case.
So, after discussing this with Johann again, starting with patch-set #4, I take a reference now on old lock found to be resent.
|
|
My local+intensive tests of patch-set #5 and running the reproducer are successful!
Actually I take/restore the required reference on old/orig lock now found upon truncate/resend (thus avoiding a new/duplicate lock to be created and the 1st one to become orphan leading to the evict during blocking-AST process) with ldlm_lock_addref(). But may be more checks need to be done vs racing (cancel?) access ?? Will see how full auto-tests run.
Di, if I want to write a master version of this patch, actually I will need to remove (change?) your very restrictive test in patch for LU-4403 to also skip a new lock creation for layout_lock upon resend, what do you think ??
|
|
Auto-tests of #9488 p-s #5 have been successful too. So even if patch still needs to be reviewed I am pretty confident that it solves the original problem.
I may push a new version of patch with more protection vs simultaneous actions/race, that may be based on ldlm_revalidate_lock_handle() usage instead ldlm_lock_addref() to restore the reference on lock.
And to fit with patch #8642/#8680 for LU-4803 from Di, I may simply add a new test to allow lookup also for layout_lock (new_lock->l_policy_data.l_inodebits.bits & MDS_INODELOCK_LAYOUT) and not only open_lock.
|
|
Di, after I had more indeep look into the source code, I don't think I can check for MDS_INODELOCK_LAYOUT in mdt_intent_fixup_resent(), because the decision to add layout to open is made down/later in mdt_object_open_lock()/try_layout ...
BTW, the check/filter "if ((opcode != MDT_IT_OPEN) || (opcode == MDT_IT_OPEN && info->mti_spec.sp_cr_flags & MDS_OPEN_LOCK))" you added in patch (#8642/b2_4 and #8680/master) for LU-4403, is only an optimization attempt to save un-necessary hash lookups upon resend, but the problem/scenario discovered as part of this/LU-4584 ticket seems to indicate it is wrong, what do you think ??
According to this, my patch version for master branch is at http://review.whamcloud.com/9764. Since it is master patch version where patch for LU-4403 has already landed, I had to remove its too restrictive optimization to allow implicit layout_lock upon open handling upon resend. But I left its [un]lock_res_and_lock() protection it introduced, even if I am not convinced it is required in this case.
|
|
We are seeing consistent evictions with 2.5 clients when running a shared-file IOR (stripe count 64). I'm seeing some similar messages in our client logs:
Is the re-send due to LLNL's client-side optimization to avoid vmallocs, or something else? If it is, with only 64 stripes I don't think a re-send is necessary. But I need to do some more analysis and get traces with RPCTRACE enabled.
Bruno - is the patch ready for reviewers and possible landing, or is more work still needed?
Chris - have you guys tried out this patch?
|
Chris - have you guys tried out this patch?
No, I have been waiting for patch to get closer to final form. It sounds like we are close.
|
|
Apparently this is a dup of lu2827, there's even a testcase in http://review.whamcloud.com/#/c/6000/ that we should use along with this proposed patch to ensure it works as expected
|
|
btw Vitaly advises that he's almost done creating a proper patch for this issue (in LU-2827) and will upload it as soon as it passes internal inspections at Xyratex.
|
|
Matt: Yes, b2_4/master patches were ready for reviewers, which finally and very recently happened ...
Chris: may be I made it not clear enough, but it is now about a month that patch #9488-5 works and fixes your problem with no regression in b2_4. And this applies for master patch too.
Oleg: Sorry, I had no idea of parallel work at Xyratex... BTW, LU-2827 has not been updated/commented since 29/Apr/13 !! Ok, I will add a test-case to my master patch #9764, inspired by #6000/#5978-3 from LU-2827 but may be also with more specific stuff to reproduce the resend scenario for this LU-4584 ticket. Again, I may have not been clear enough in my previous updates, but both my patches for b2_4 and master work against Chris solid/permanent reproducer and with no regression found by auto-tests.
|
|
I tested both your b2_4 patch with 2.4 and your master patch with b2_5. Both times my MDS went up in flames. I'm in the process to ask the admins for the logs of the event.
|
|
here is the stack trace resulting from this patch. I named the log inflames.log
|
may be I made it not clear enough, but it is now about a month that patch
That was fairly clear. And I really appreciate your work!
But I'm not really ready to take a patch for code that I don't understand and run it in production until it has, at a minimum, gone through the code review process and is on its way to landing.
|
|
I have a since single shared file IOR job that duplicate this problem. I turned on all debugging and pushed the logs to ftp.whamcloud.com/uploads/LU-4584/LU-4584.log.gz. Hope this helps.
|
|
Uploaded clients debug logs to ftp.whamcloud.com/uploads/LU-4584/client-run1
|
|
The syslogs and nid mapping have also been uploaded to uploads/LU-4584/console-20140409
|
|
Did the logs shine light on this problem?
|
|
James, I am sorry but I am puzzled with the latest infos you uploaded.
I 1st thought that they were intended to document, as you indicated you will!, one occurrence of the following LBUG you triggered when running with my patch :
and that was shown within the inflames.log file you attached to this ticket.
But in fact, I understand that it is certainly an other problem, but then I need some help/highlights :
_ you commented "I have a since single shared file IOR job that duplicate this problem.", but what problem exactly? The original one for this ticket? The LBUG?
_ did you trigger it also when running with my patch ?
_ what is the main symptom? I don't find any LBUG in all logs, only tons of Clients evictions ...
_ can you provide Servers logs for the same timing period ?
I am also still very interested to get the logs for the LBUG, can you provide them finally ?
|
|
LU-4963 has been marked as duplicate of the ticket so i'll report things here
I have uploaded logs from client caught just after crash (dlmtrace)
ftp.whamcloud.com/uploads/LU-4963/lustre-client-2.4.1-6.cyfronet.log.gz
The problem described in LU-4963 occurs for either 2.5.1 and 2.4.x clients
|
|
Looking at the logs I noticed the source of our problems is the value of the at_max. So with a JIRA search I found LU-4578 and tried the patch for that ticket and lo and behold my single shared file failures went away. So for the people experiencing this problem please try patch http://review.whamcloud.com/#/c/9100 and post your results.
|
|
Lucasz: I am working on the trace you provided and will let you know if I can confirm this is the same problem or not.
James: thanks for the details on what you have found. But again, can you provide the logs from the LBUG occurence?
Also, since both tickets (and their patches!) are highly related, I tried running the reproducer of this LU-4584 ticket against latest build #23312 from ticket/Gerrit-change LU-2827/#5978-8. But the MDS just hit the LASSERT(lock->l_granted_mode != lock->l_req_mode) that the change introduced in ldlm_process_inodebits_lock().
In fact, I did not have to run the full (create+touch+rm) reproducer scenario since the MDS crashed during the file creation !!...
The platform I used was made of one MDS, 2 OSSs with a total of 154 OSTs, and a full default striping...
I will try to investigate crash-dump and debug-logs to understand/qualify what went wrong.
|
|
I did more testing last night and found that the patch from LU-4578 only helped reduce the occurrence of this bug. It still happened but much less. The new reproducer I use is
aprun -n 112 /lustre/sultan/scratch/jsimmons/simul -d /lustre/sultan/scratch/jsimmons/test_simul
were test_simul is striped at 56. This fails consistently for me.
Sorry Bruno I haven't got back to you about the patch. We dropped testing in recently but should give it another try.
|
|
I am a little worried that we are taking the wrong approach on this issue. I don't fully understand what you guys are working on, so maybe my concern is misplaced.
Folks keep talking about this problem along the lines of "if a message is lost, we are not handling that situation correctly". But that is not the situation in this ticket, to the best of my knowledge. The issue in this ticket is 100% reliable. If a message is getting "lost" every single time I run this test, then clearly that is itself a bug that needs to be worked in Lustre. That would also be the primary issue that needs to be worked under this ticket.
It would also be good to respond quickly and correctly to lost message situations, but that sounds like a somewhat separate issue.
|
|
Hello Chris,
I completely agree with you when you say that this ticket does not address a message lost issue. The problem here is only about to correctly handle the situation of an open request/message reply from the Server that is truncated (because due to striping layout/lvb does not feet into reply buffer) and same request to be resent by the Client, which ends up to a replicated layout-lock on Server and finally to the eviction upon blocking callback processing.
My b2_4 patch #9488, has successfully passed auto-tests and 3 positive reviews, but a -ve one from James since he experienced a MDS LBUG when he integrated it. I am waiting for him to provide me with the necessary infos to allow me to find what wnet wrong.
Also, since it was discovered that a similar work is on-going as part of LU-2827, and a more generic patch to also address other intent locks cases being developed, I decided to run your reproducer against it but I triggered a MDS LASSERT(lock->l_granted_mode != lock->l_req_mode) that the change introduced in ldlm_process_inodebits_lock(). I am currently working on the crash-dump from this LASSERT.
|
|
I was just cross referencing to another ticket which seemed to help ease the pain. The description to me was kind of loose so I figured it was a umbrella to all things lock and AST breakage. Also I had to get something going for the users to be able to test on. Now that I have a seems stable system I can focus again on this work which will be applied to my smaller testbed. Yes that patch is not a cure all. Now that we have LU-2827 as well which patch to I test? Will both of the works be combined and under which ticket?
|
|
James, could you clarify whether or not patch 9488 is introducing a new problem in your testing? If the problems you are seeing are unrelated to that patch, please clear your -1 review.
|
|
Last time I tested it my MDS oops. Removed the patch and the oops went away. From Oleg's comments this patch will not be landed to master since a more generic solution needs to be developed.
|
|
James, the more generic solution is addressed by the current state/patch-set #8 of patch for LU-2827, and it should not be combined with my Change #9488 for this ticket.
BTW, and as I already reported here and in LU-2827, when testing LU-2827 patch against the reproducer from Chris for this ticket, I triggered a MDS LASSERT(lock->l_granted_mode != lock->l_req_mode) that has been introduced in ldlm_process_inodebits_lock()... This LASSERT may have to simply be removed, but we need to confirm this.
|
|
Chris, so now that we see why there are resends not in the face of lost packets, I have another question.
Do you carry patch for LU-3338 or something of the similar nature? My looking at your chaos tree seems to imply this even though I don't see the exact commit.
This would potentially explain why you seems to be hittign this in 2.4 code. (2.5 and it's additional layout lock payload seems to add a similar failure mode, but you need to have 2.5 servers and 2.5 clients for this).
Any chance you can disable the patch and see if it help you?
|
|
Oleg,
Sorry to interfere, and may be I did not make it enough clear, but you may have missed that I already indicated that Chris reproducer also triggers the described problem scenario on homogeneous b2_5/master Servers/Client platforms.
|
|
I think James already verified that while 2.5/2.5 triggers due to layout lock (and increased request sizes from that I imagine), 2.4/2.4 and 2.4/2.5 does not trigger any ill effects.
|
|
Oleg, sorry, my 1st answer against your LU-3338 submission had the wrong/reverse meaning, I should have pointed you again about the fact that the reproducer also triggers when running with an homogeneous b2_4 and 2.4.0-RC2 Servers/Client platforms!! So I don't think LU-3338 could be suspected here, even if I agree it can raise its possibility to occur. BTW, and I have detailed this above, during my attempt to reproduce locally I saw that the reply buffer size allocated on Client was 2K where a 46 striping layout can not feet. So the truncate and then the problem will occur anyway when the reply buffer is less than the need for the layout size.
|
Do you carry patch for LU-3338 or something of the similar nature? My looking at your chaos tree seems to imply this even though I don't see the exact commit.
Yes. It is probably the one that begins the first line of its commit comment with "LU-3338". 
|
|
Chris, have you been able to check Oleg's proposal to run without patch from LU-3338 ?
On the other hand, I have submitted an add-on patch (http://review.whamcloud.com/10378, to handle the layout-lock case you trigger here) to the "generic" one (http://review.whamcloud.com/5978/) handling resends from LU-2827, both patches should fix the specific issue you reported in this ticket.
|
|
Currently I'm in the middle of my 24 hour test shot window and I have some interesting results. First the problem I reported here happened with 2.4 servers without any patches from this ticket or LU-2827 with 2.5 clients. We had two 2.4 file systems of the same OST count (1008) but the OST size were different. The production file system OST are 14TB in size and the test file system OST is 255GB in size. The problems only showed up on the small OSTs so far. I placed the vmcore and dmesg at
ftp.whamcloud.com/uploads/LU-4584. All the involved files end in *--20-5-2014.
|
|
James,
Thanks to provide these infos, but to allow vmcore analysis, I need also the associated vmlinux binary (or better the 2x kernel-debuginfo[-common] RPMs) and the Lustre modules (ie, lustre-modules or better lustre-debuginfo RPM).
Also, am I right if I understand, from your last comment, that you had these occurrences of
LBUG/Assert on a platform made of 2.4 Servers and 2.5 Clients, none of them having any of the patches from this/LU-4584 nor LU-2827 tickets?
|
|
Yes this showed up with 2.4 servers and 2.5 clients without any patches. I uploaded all the debuginfo rpms to the same ftp spot. Now you will be able to look at the core dumps. If you need anything else let me know. Thank you.
|
|
James, it sounds like your assertion is unrelated to this ticket, LU-4584. Could you please start a separate ticket for that?
|
|
Yes it is looking like this assertion is not related to this ticket. Waiting on feedback from Bruno and/or Oleg about the results of the core dump. Then it will most likely be moved to its own ticket.
|
|
James,
According to crash dump analysis, the LBUG occurs during resend+reconstruct_open. But since there are only a few Lustre debug traces available (only default traces enabled ...), to affirm this, I can only rely on the latest traces of each (because there are a bunch of mdt threads triggering this same LBUG at almost the same time...) concerned thread like following :
and all their similar threads looking as following :
So this looks like the same kind of issue, even if the symptom is different (LBUG vs eviction), that has been reported starting with this ticket, likely to be caused by some large striping/layout.
BTW, my patch (#9488) from this ticket or both (#5978, #10378) from LU-2827 should fix this ...
|
|
Thank you for looking at our logs. I have tried the #9488 patch and also #5978 but it did not help. I have not tried the#5978 and #10378 together yet. That is next on the agenda.
|
|
James,
If you run a new test session, that would be very helpful if you do it with full Lustre debug traces enabled, at least on Client-side and with additional rpctrace+dlmtrace on Server/MDS side. Full traces on both-sides would be a must. Then if you reproduce the LBUG, crash-dump analysis will be much easier whith associated full debug traces reading. You may also set panic_on_lbug to 1 on MDS side to reduce MDS crash-dump/debug-traces content to the minimum required volume of informations, and both dump_on_[timeout,eviction] on Client-side too, in order to ensure debug log buffer will be saved and preserved automatically when possible.
|
|
Got a nice lockup with a ls to a directory containing a single shared file. I did a full lctl set_param debug=+all. You can find the logs at
ftp.whamcloud.com/uploads/LU-2827/client-lockup-2-6-2014.log
ftp.whamcloud.com/uploads/LU-2827/server-lockup-2-6-2014.log
For the client it has multiple file systems mounted so filter for atlastds which is the 2.5 file system.
|
|
Thanks James, but can you also provide me with the dmesg/syslog messages/stacks that should have been displayed indicating the lockup ?
This will greatly help me to faster point interesting sequences in these logs.
Also, I did not find any eviction trace in these logs.
|
|
With the two patches from LU-2827 I don't get client evictions any more. Just pure lock ups. I end up having to kill the job or in the case of the ls test killing the ssh session. The logs were not to verbose on either side but here is what I got. Hope it helps
From the client side
2014-06-02T09:19:38.010961-04:00 c0-0c0s6n1 Lustre: 15326:0:(client.c:1908:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1401714172/real 1401714172] req@ffff88014aca5400 x1469570034748356/t0(0) o36->atlastds-MDT0000-mdc-ffff8801491a7800@10.36.226.79@o2ib:12/10 lens 496/3880 e 12 to 1 dl 1401715177 ref 2 fl Rpc:IX/0/ffffffff rc 0/-1
2014-06-02T09:19:38.011028-04:00 c0-0c0s6n1 Lustre: atlastds-MDT0000-mdc-ffff8801491a7800: Connection to atlastds-MDT0000 (at 10.36.226.79@o2ib) was lost; in progress operations using this service will wait for recovery to complete
2014-06-02T09:19:38.140645-04:00 c0-0c0s6n1 Lustre: atlastds-MDT0000-mdc-ffff8801491a7800: Connection restored to atlastds-MDT0000 (at 10.36.226.79@o2ib)
MDS side
Jun 2 09:12:47 atlas-tds-mds1 kernel: [323268.180954] Lustre: 16989:0:(service.c:1349:ptlrpc_at_send_early_reply()) @@@ Couldn't add any time (5/5), not sending early reply
Jun 2 09:12:47 atlas-tds-mds1 kernel: [323268.180956] req@ffff8807e3f53400 x1469570034748356/t0(0) o36->c4edc84a-1bf9-d28e-6029-43f8715edbaf@13@gni2:0/0 lens 496/3128 e 12 to 0 dl 1401714772 ref 2 fl Interpret:/0/0 rc 0/0
Jun 2 09:15:22 atlas-tds-mds1 kernel: [323423.238665] Lustre: lock timed out (enqueued at 1401714172, 750s ago)
Jun 2 09:19:37 atlas-tds-mds1 kernel: [323678.373844] Lustre: atlastds-MDT0000: Client c4edc84a-1bf9-d28e-6029-43f8715edbaf (at 13@gni2) reconnecting
Jun 2 13:25:36 atlas-tds-mds1 kernel: [338442.226261] Lustre: 17228:0:(service.c:1349:ptlrpc_at_send_early_reply()) @@@ Couldn't add any time (5/5), not sending early reply
Jun 2 13:25:36 atlas-tds-mds1 kernel: [338442.226262] req@ffff8807e2c4ac00 x1469570037379276/t0(0) o101->c9bf7a8c-2264-2712-4013-110119f32786@12@gni2:0/0 lens 584/3384 e 12 to 0 dl 1401729941 ref 2 fl Interpret:/0/0 rc 0/0
Jun 2 13:28:11 atlas-tds-mds1 kernel: [338597.286986] Lustre: lock timed out (enqueued at 1401729341, 750s ago)
Jun 2 13:32:26 atlas-tds-mds1 kernel: [338852.487432] Lustre: atlastds-MDT0000: Client c9bf7a8c-2264-2712-4013-110119f32786 (at 12@gni2) reconnecting
Jun 2 13:49:11 atlas-tds-mds1 kernel: [339857.980604] Lustre: atlastds-MDT0000: Client c9bf7a8c-2264-2712-4013-110119f32786 (at 12@gni2) reconnecting
Jun 2 14:05:56 atlas-tds-mds1 kernel: [340863.498596] Lustre: atlastds-MDT0000: Client c9bf7a8c-2264-2712-4013-110119f32786 (at 12@gni2) reconnecting
Jun 2 14:16:12 atlas-tds-mds1 kernel: [341478.913322] LNetError: 12708:0:(o2iblnd_cb.c:3012:kiblnd_check_txs_locked()) Timed out tx: tx_queue, 20 seconds
Jun 2 14:16:12 atlas-tds-mds1 kernel: [341478.924224] LNetError: 12708:0:(o2iblnd_cb.c:3075:kiblnd_check_conns()) Timed out RDMA with 10.36.230.231@o2ib200 (50): c: 0, oc: 0, rc: 63
Jun 2 14:16:13 atlas-tds-mds1 kernel: [341479.913856] LNetError: 12708:0:(o2iblnd_cb.c:3012:kiblnd_check_txs_locked()) Timed out tx: tx_queue, 21 seconds
Jun 2 14:16:13 atlas-tds-mds1 kernel: [341479.924903] LNetError: 12708:0:(o2iblnd_cb.c:3012:kiblnd_check_txs_locked()) Skipped 1 previous similar message
Jun 2 14:16:13 atlas-tds-mds1 kernel: [341479.935921] LNetError: 12708:0:(o2iblnd_cb.c:3075:kiblnd_check_conns()) Timed out RDMA with 10.36.230.233@o2ib200 (51): c: 0, oc: 0, rc: 63
Jun 2 14:16:13 atlas-tds-mds1 kernel: [341479.949351] LNetError: 12708:0:(o2iblnd_cb.c:3075:kiblnd_check_conns()) Skipped 1 previous similar message
Jun 2 14:22:41 atlas-tds-mds1 kernel: [341868.934059] Lustre: atlastds-MDT0000: Client c9bf7a8c-2264-2712-4013-110119f32786 (at 12@gni2) reconnecting
|
|
James, I think that you said you needed 48 OSTs to trigger the buffer resize case. Is that all? We have a system with 48 OSTs that does not see this issue.
|
|
Did you set the default stripe size to 48?
|
|
We certainly only needed to stripe over 48 OSTs, as stated in this ticket's Description section.
|
|
James,
According to the latest dmsg/syslog msgs you provided, I tried to navigate in your 2 last Client+Server logs in detail and here is what I can tell :
_ log uploads/LU-2827/client-lockup-2-6-2014.log, starts at 10:33:06 and ends at 13:17:11, if I correctly match with your time-zone.
_ log uploads/LU-2827/server-lockup-2-6-2014.log starts at 13:15:37 and ends at 13:16:08. And it is only containing 61734 lines, and I wonder if you raised the debug log buffer size there ?
_ so according to this I have been only able to work on transaction-id x1469570037379276 from the syslog msgs you pointed, and I already lack the end of its processing at both Client and Server side. But I can see that the request that caused it to be sent from the Client is :
at around 13:15:41.
_ then nothing else can be found about these lock-request/transaction-id in Client's log remaining 1:30s of traces.
_ on Server side we can find its handling start with the following traces :
that shows parent's/dir [0x200000400:0x2:0x0] locks have been granted, child/file [0x200000401:0xd7:0x0] is blocked, and then nothing else happen for these fids/locks in Server's remaining 27s of log/traces. Which seems to indicate that any of the conflicting locks already had a blocking-AST sent before and did not cancel it at this time.
_ Also, I can't find in these logs, even if they do not cover the whole story, any truncate/resend situation that is being handled and modified by both patches being worked as part of this/LU-4584 and LU-2827 tickets. Only left possibility would be that truncate/resend occurred before but with an other Client accessing the same file ...
But it seems to me that this new lockup problem (vs previous evictions and LBUG) looks more as something different, and I wonder if it could be tracked as part of a new ticket.
|
|
Yes, please move that discussion to a new ticket.
|
|
Something is really broken in 2.5 which might be independent of this patch. At this point I don't know. Only data will provide the needed evidence. So I tried the next step and moved to the latest 2.5.59 with the LU-2827 patches to see what the difference is. Well it was back to good old fashion client evictions so I setup debugging to collect data and guess what happened? When set debug=+all on the clients all the evictions went away. So we have a very nasty race condition causing this problem. Next step is ust collecting rpctrace and ldlm from the clients only. Maybe the race will still be there.
|
|
I collected data for the evictions I'm seeing from two different test runs. The clients enabled rpctrace+dlmtrace for extra info. The logs are uploaded to ftp.whamcloud.com/uploads/LU-4584/20140609-run1.tbz and 20140609-run2.tbz.
|
|
Any insight gained from the logs?
|
|
James, sorry I was out, but now back. Will give you feedback soon on these new logs analysis.
|
|
James,
Within your last uploaded sets of logs (20140609-run[1,2].tbz), I only find a bunch of OSTs/Extend locks related evictions.
Looks like the OST, upon a full extent PW lock request, has requested multiple granted+conflicting PR locks to be released from the same Client. Client seems to have correctly handled the requests, but OST does not seem to receive the confirmation that locks have been canceled, hence the evictions.
I can't fully confirm that Client has effectively sent the replies over the wire since the rpctrace does not seem to be enabled on the concerned Client.
BTW, this definitelly confirms that this needs to be addressed in an other ticket since there is no relation to the resend mechanism that is concerned/fixed in both LU-2827 and this ticket.
|
|
Can you open the ticket since you will be able to describe the problem far better than I can
|
|
I just created LU-5225 to track this specific scenario.
James, can you update it with any interesting detail you think please?
|
|
So now that the unrelated issue being tracked for ORNL has moved to LU-5225 and the patches from LU-2827 have landed to master, can this issue be marked as a duplicate of LU-2827?
|
So now that the unrelated issue being tracked for ORNL has moved to LU-5225 and the patches from LU-2827 have landed to master, can this issue be marked as a duplicate of LU-2827?
First, can we get an explanation of how that fixes this problem, and then a clear list of the patch(es) I need to apply to b2_4?
|
|
Prior to patch from this ticket and/or LU-2827, there was a bug (new lock early creation causing itself instead of 1st to be found during lookup!) during Server handling of resent requests causing the 1st/old one to become orphaned and replicated.
It has been decided that patch(es) from LU-2827 will be used to fix this issue because more generic and handling all cases, mainly by detecting resent case earlier and avoiding unnecessary new lock creation.
I am presently porting+testing a b2_4 backport of LU-2827 patches and will provide updates asap.
|
|
Why are messages being resent?
|
|
Because Client's reply buffer was not big enough to receive 1st Server's reply including LVB/layout due to default/large striping.
|
|
Merged b2_4 backport of both #5978 and #10378 master changes from LU-2827, is at http://review.whamcloud.com/10902.
|
|
BTW, I forgot to indicate here that my b2_4 patch/back-port for LU-2827 (http://review.whamcloud.com/10902) has still some problem and needs some re-work, because MDS bombs with "(ldlm_lock.c:851:ldlm_lock_decref_internal_nolock()) ASSERTION( lock->l_readers > 0 ) failed" when running LLNL reproducer from LU-4584 or recovery-small/test_53 in auto-tests.
More to come, crash-dump is under investigations, but we still can use http://review.whamcloud.com/9488 as a fix for b2_4.
|
|
Just finished a test shot with Cray 2.5 clients to see if the client evicts stopped. Their default client which is some 2.5 version with many many patches lacked the LU-2827 and LU-4861 patches I founded that helped with 2.5.2. So I applied patches from LU-2827 and LU-4861 but still had client evicts. I collected the logs from the server side and have placed them here:
ftp.whamcloud.com/uploads/LU-4584/atlas2_testshot_Jul_29_2014_debug_logs.tar.gz
|
|
James, can you share the patch stack you are using? That might help us figure out if you are reporting the same issue or something else. And if it isn't exactly the same issue, we really need to get you to report it in another ticket.
|
|
It was my bad. The last test shot we used our 2.4 production file system which didn't have the patch from here. So the above breakage is expected. We are in the process of testing this at larger scale (500 nodes) production machine. Yes ORNL has created a public git tree
https://github.com/ORNL-TechInt/lustre
So people can examine our special sauce.
|
|
I have been testing with the LU-4584 patch and I'm still seeing client evictions. Could it be possible to get the LU-2827 patch working on 2.4
|
|
FYI, we put the LU-4584 patch into production, and it didn't take too long before we hit the assertion that James reported. I opened LU-5525 for that bug.
I am beginning to suspect that the patch either did cause the assertion, or made the assertion more common.
|
|
Could you please provide an explanation of what operations will not be fixed by the LU-4584 patch, as compared with the more general LU-2827 fix?
|
|
I have several different reproducers of this problem. What I found what LU-4584 address some of the reproducers but not all of them. The patch for LU-2827 addressed more of my reproducers but I still had client evictions.
|
|
Yes, that was my belief. I would like Intel to enumerate the failure modes that users can expect to be fixed, and those that will not be fixed by LU-4584.
|
|
patch http://review.whamcloud.com/#/c/9488/ fixed to eliminate the assertion in mdt_intent_lock_replace() now.
Also 2.4 deployments would need to carry patch http://review.whamcloud.com/6511 from LU-3428. This should address all related woes in b2_4. 2.6+ will be fixed by patches from LU-2827 and friends. As for 2.5 I think we'll still move with -2827 as the more generic solution.
|
|
Ok, I will give those patches a try.
We are planning to try to move to b2_5 in less than 2 months, so we'll need the LU-2827 solution for b2_5 as soon as possible.
|
|
For -2827, we have:
LU-2827 itself http://review.whamcloud.com/5978 and http://review.whamcloud.com/#/c/10378
LU-5266 http://review.whamcloud.com/10903
LU-5496 http://review.whamcloud.com/11469 and http://review.whamcloud.com/#/c/11644
LU-5579 http://review.whamcloud.com/#/c/11839/
and the final nail in this bug LU-5530: http://review.whamcloud.com/#/c/11841/1
Some of those patches are not picking cleanly into b2_5, but I know James Simmons from ORNL ported them. All of this is now in testing after which they hopefully will publish their tree with backports.
Or another easy way to get rid of all of these problems (occuring as frequently, at least, sicne resend might also happen if a reply from server was genuinely lost on the network) is to drop LU-3338 patch, that is not part of standard b2_5 (only landed to b2_6)
|
|
Actually our Cray clients don't have the LU-3338 patch and the problems of LU-5530 still showed up. So these patches are still needed. We plan to do a full scale test shot Tuesday next week with all the above patches plus a few others. If it goes well we will leave this system running 2.5 clients and 2.5 servers.
We still need this work due to another file system running at the lab that will be stuck at 2.4 for the time being but some of our clients will be moving to 2.5 so these problems will show up.
|
|
re 1.8 clients - since they don't know about wide striping, they hit this because their buffers are not large enough anyway, I suspect, when you have enough stripes.
The patches are needed regardless of course because the bugs are real during resends. It's just the resends used to be rare and only in the face of lost messages.
|
|
Chris did you try the patch set for 2.4? If you did was their positive results?
|
|
We won't know until it is installed on larger systems.
|
|
I have been testing the b2_4 version of the LU-4584 patch and I see this:
LustreError: 4012:0:(ldlm_resource.c:1445:ldlm_resource_dump()) — Resource: [0xdeaf:0x0:0x0].0 (ffff88020290da80) refcount = 2
Its my simul job struggling.
|
|
No updates in ticket since sites have upgraded to newer releases.
|
Generated at Sat Feb 10 01:44:02 UTC 2024 using Jira 9.4.14#940014-sha1:734e6822bbf0d45eff9af51f82432957f73aa32c.
172.16.66.4@tcp.log.bz2
client_log_20140206.txt