|
Adding to the original description, the clients and filesystem function normally otherwise and is performant. Other I/O, different from what is outlined above, is normal. IOR benchmark runs are successful and performant.
|
|
The errors are easier to trigger when the OSTs selected in the 4 to 8 way OST stripe are on the same OSS or OSS pair.
|
|
Jeff, to clarify your description of the write workload:
- you repeatedly wrote "2MB strides", but the error messages showed 4MB write sizes? Is it sometimes 2MB and sometimes 4MB?
- when you write "job" are they actually separate tasks writing independently to the same file at specific stride offsets (i.e. they may become significantly out-of-sync), or are these "threads" in an MPI program that are writing to a single shared file?
At most levels this probably doesn't make a difference, but I'm wondering if the jobs are independent executables running against the same output file if they may be less synchronized than if there are multiple threads from the same program writing to the file together (which would result in more merges on the client instead of "random" IO).
Making an observation, the combination of the 2MB strided writes and the 1MB OST stripe would result in a significant number of objects per file which scales up as the number of files and concurrent writers increases. Perhaps there is a trigger (I’m spitballing).
Lustre doesn't allocate objects for different "chunks" of the file, per se, unlike Ceph which allocates an "object" for each 32MB of the file or similar. There is exactly one OST object for each of the "stripe_count" parts of a file. In your description above, the stripe_count is 4 or 8. Writes are round-robined across the objects file by file offset, but Lustre does not create new "objects" for the file as it grows larger (excluding PFL/SEL which still has file layouts that are relatively static).
A single 600GB file is written to by 128 jobs in a 2MB strided write format. The 128 jobs are spread across two Lustre client nodes.
| |
Start 1 |
Start 2 |
Start 3 |
Start 4 |
Start Last |
| job0 |
0b |
256MB |
512MB |
768MB |
556794MB |
| job1 |
2MB |
258MB |
514MB |
770MB |
556796MB |
| job2 |
4MB |
260MB |
518MB |
772MB |
556798MB |
| : |
: |
: |
: |
: |
: |
| job127 |
254MB |
510MB |
766MB |
1022MB |
556800MB |
The file is written with Lustre stripe options of 4-8 OSTs and a stripe_size of 1MB.
In this case, with an 8-stripe file, the 0-1MB, 8-9MB, 16-17MB, ... chunks would be written to stripe0; 1-2MB, 9-10MB, 18-19MB, ... chunks would be written to stripe1, etc. Having the threads writing 2MB interleaved chunks to a file with stripe_size=1MB is certainly sub-optimal, depending on how the "jobs" are distributed across the nodes. Using stripe_size=2MB would at least cut the IO/lock contention in half.
|
|
I wondered the same thing. I'm trying to ascertain where the 4MB writes are coming from. They are 2MB but I haven't dug deep into the application to find where the 4MB IO is.
"Job" is an independent separate task writing to the same file at the stride offsets described. No MPI involved.
Thanks for clarifying the objects. I figured the size mismatch of the file striping and and strided writes might have triggered a new object per job.
I may move this to test to AWS to get enough scale to trigger the error where I can dump the debug buffer at all end points and try to sort this out. It's far too infrequent at the scale of my testbed to catch it.
|
I wondered the same thing. I'm trying to ascertain where the 4MB writes are coming from. They are 2MB but I haven't dug deep into the application to find where the 4MB IO is.
I looked into the code and it is varying the IO and offset sizes in order to trigger the issue being seen in an application that can't be modified. The application performs 2MB strided writes as originally reported. The testbed code, written to try and trigger the issue for diagnosis, writes varied sized IO and offsets in order to accomplish that.
That being said, according to the included error messages, the error triggers on other stride sizes than 2MB.
|
|
I just triggered the issue. It occurred on one node, shortly after an OSS remount and recovery. Recovery had completed and IO from clients had started. My guess is that the burst of activity from 18 nodes all releasing IO at once somehow exposed what it usually takes 60+ nodes to start to see.
I converted human-readable timestamps from dmesg/messages to epoch time to help line events with Lustre debug logs.
Application:
Client:
Client Lustre Debug:
OSS:
OSS Lustre Debug: <<<<Attached as gzip file, too large to post as textblock**
MDS:
Quiet, no log entries at this time (var/log/messages, dmesg)
MDS Lustre Debug:
|
|
What's interesting in the client and OSS logs here is two things (the MDS logs show nothing of interest):
- the client is evicted @1579118407 by OST0001 with a lock timeout message for a callback that is 99s old
- the client debug log @1579118406 (1s earlier) shows that it is just reconnecting this same import ({UUID=b2aa93cc-306c-345d-b999-acf8e974b6eb}}) to this target after being idle for some time, so it shouldn't have had an active lock on any object for that OST at the time it disconnected.
I haven't traced the whole lock request/callback/idle disconnect/reconnect through the logs yet (not sure how far back the client and server Lustre debug logs go, whether they would still contain the original request from 100s earlier), but it at least seems like this is related? I've previously asked to set llite.*.idle_timeout=0 on the clients to eliminate idle disconnect/reconnect as a source of problems, and in theory that has been eliminated as the root cause, but once again it is showing up here as a potential trigger for the problem (the "connect idle client just before the error was hit" situation was also seen in other logs).
Jeff, if you can reproduce this with some specific frequency (though I understand it is not easy, we haven't been able to hit it at all), could you please run lctl set_param -P llite.*.idle_timeout=0 on the MGS, and wait a few seconds before verifying on the clients that lctl get_param llite.*.idle_timeout returns 0 before trying to reproduce again.
My speculation is that (somehow) the idle disconnect is leaving the client with some stale lock handles on the server import (or similar, maybe after recovery?) that eventually get an LDLM_CP_CALLBACK=105 from the OSS but the client doesn't even get the RPC since it is disconnected? Possibly the OSS/DLM need to consider if the client has idle disconnected that it doesn't have any outstanding locks on its side?
The GRANT messages appear to be a byproduct of the client eviction (40s earlier), and while potentially annoying I don't think they are in any way causing this problem to be hit. It is the eviction itself that is causing the short write/EIO to be seen on the client.
|
|
Oh, nm. I now see that the idle connection message in the client debug log was for OST0000, not OST0001 where the client was evicted. That likely eliminates the "idle disconnect" is the root of the problem theory. This will need further digging into the client and OSS debug logs to see if the client got the original LDLM_CP_CALLBACK message or not, and/or why it didn't reply in a timely manner.
|
|
I added the full OSS Lustre debug logs for the OSS and Client with the triggered error.
Client: palpatine20-lustredbg.txt.gz
OSS: testbed01-oss00-lustredbg-FULL.txt.gz
|
|
Hi Jeff, thanks for the debug logs. I looked through the logs for the relevant information related to this client, but unfortunately it looks like they are captured at the default debug level and do not contain the rpctrace and dlmtrace log messages needed to trace the cause of the client eviction. The server evicted the client at 1579118407.432055 after 99s waiting for the lock callback, and the client noticed this at 1579118408.371668, but looking in the client logs 99s earlier there is nothing of interest for OST0001:
Similarly, 99s earlier in the server logs there is just business as usual, committing transactions in the background, but no details about what is actually being sent over the network:
We are also trying to reproduce this locally, but any chance you could try to reproduce this again there with "lctl set_param debug='+rpctrace +dlmtrace'" on both the client and server, and increasing the size of the debug buffers to hold enough information to debug it, like "lctl set_param debug_mb=32768" or similar (32GB, assuming the client and server have enough RAM)?
|
|
I'm on it. Don't know how long it will take to reproduce, hopefully I'll get lucky.
|
|
Managed to capture another occurrence. This time occurring on three clients at roughly the same time. Due to size of the Lustre debug files I cut everything down to a ten second window. If more is needed, like prior to the ten second window, I can generate more files to upload.
In the uploaded files there is a lustrelog_X file and messages_X file for machines:
mds00, oss00 and oss01
clients: r4i5n12, r4i6n3 and r4i6n5.
The first occurrence of the partial writes occur at:
r4i5n12: walltime: Jan 29 20:48:59 / epoch: 1580330939
r4i6n3: walltime: Jan 29 20:50:02 / epoch: 1580331122
r4i6n5: walltime: Jan 29 20:48:49 / epoch: 1580330929
rpctrace and dlmtrace are enabled in the Lustre logging.
All of the output and log files are ten second windows, epoch: 1580330930-1580330939.
mds00: lustrelog_mds00_158033093x.txt.gz
oss00: lustrelog_oss00_158033093x.txt.gz messages_oss00_158033093x.txt.gz
oss01: lustrelog_oss01_158033093x_A.txt.gz lustrelog_oss01_158033093x_B.txt.gz messages_oss01_158033093x.txt.gz
client-r4i5n12: lustrelog_r4i5n12_158033093x.txt.gz messages_r4i5n12_158033093x.txt.gz
client-r4i6n3: lustrelog_r4i6n3_158033093x.txt.gz messages_r4i6n3_158033093x.txt.gz
client-r4i6n5: lustrelog_r4i6n5_158033093x.txt.gz messages_r4i6n5_158033093x.txt.gz
|
|
Jeff, I haven't had a chance to look at the logs yet, but if is the same as previous failures, I will need the OSS logs from 100s before the clients are evicted (from the time the eviction message is printed on the OSS console).
|
|
They're quite large. What's the max upload here? I can place them on a public share and add the link here.
|
|
That would work - or else you could use the Whamcloud write-only FTP site if you want to ensure that it is only Whamcloud people who get access to them (I can post details)
|
|
Nothing confidential. Post or email me ftp details, just sounds easier.
|
|
Sometimes the diagnostic data collected as part of Lustre troubleshooting is too large to be attached to a JIRA ticket. For these cases, Whamcloud provides an anonymous write-only FTP upload service. In order to use this service, you'll need an FTP client (e.g. ncftp, ftp, etc.) and a JIRA issue. Use the 'uploads' directory and create a new subdirectory using your Jira issue as a name.
In the following example, there are three debug logs in a single directory and the JIRA issue LU-4242 has been created. After completing the upload, please update the relevant issue with a note mentioning the upload, so that our engineers know where to find your logs.
$ ls -lh
total 333M
rw-rr- 1 mjmac mjmac 98M Feb 23 17:36 mds-debug
rw-rr- 1 mjmac mjmac 118M Feb 23 17:37 oss-00-debug
rw-rr- 1 mjmac mjmac 118M Feb 23 17:37 oss-01-debug
$ ncftp ftp.whamcloud.com
NcFTP 3.2.2 (Sep 04, 2008) by Mike Gleason (http:Connecting to 99.96.190.235...
(vsFTPd 2.2.2)
Logging in...
Login successful.
Logged in to ftp.whamcloud.com.
ncftp / > cd uploads
Directory successfully changed.
ncftp /uploads > mkdir LU-4242
ncftp /uploads > cd LU-4242
Directory successfully changed.
ncftp /uploads/LU-4242 > put *
mds-debug: 97.66 MB 11.22 MB/s
oss-00-debug: 117.19 MB 11.16 MB/s
oss-01-debug: 117.48 MB 11.18 MB/s
ncftp /uploads/LU-4242 >
Please note that this is a WRITE-ONLY FTP service, so you will not be able to see (with ls) the files or directories you've created, nor will you (or anyone other than Whamcloud staff) be able to see or read them.
|
|
Uploaded to WC FTP per instructions.
|
|
What I observed one eviction case between client r4i5n12 and oss01 (OST0006), the client's clock contains 14 seconds earlier than that of oss01
After oss01 sending the blocking RPC, the client hasn't f handle finished the blocking AST (lock cancel has been done, but does not reply to oss01 immediately) before the oss01 timed out waiting for the bl AST reply and evicted the client.
|
|
Bobijam, is there any record of the OSS sending the blocking AST callback to the client for that lock handle in either the client or server logs?
|
|
Andreas,
yes, the client log records appears in r4i5n12.log, and OSS logs in oss01_20200129_2046_03.log and oss01_20200129_2046_04.log
The problem seems to be in the client, after receiving the blocking request from OSS, it cancel the lock locally, and after that the records show that other ldlm_cb threads starting handle other blocking requests. The one thing I noticed is that before the client got evicted due to the designated lock, the lock has been matched/used for IO, that could possibly explained why the lock cannot be cancelled right away.
|
|
Bobijam, thanks for finding this information. This makes sense given the symptoms seen, but now we need to find why the client was evicted.
When a client gets a blocking AST callback, it still needs to flush all of the dirty pages under that lock before the lock can be cancelled, so that may prevent the client from cancelling the lock immediately.
However, the client does need to reply to the OST for the blocking AST so that the OSS knows the AST was received. If not, the OSS should try to resend the AST at least once in case it was lost. After that, the client can continue to submit write RPCs under that lock handle to prolong the lock timeout on the server, since the server knows it might have a lot of data to flush. When the server gets the BRW RPCs with that lock handle embedded, they should be processed by the high priority RPC queue, and the OSS should update the lock timer so that the client is not evicted as long as it continues to send more writes.
However, the client should not continue to add more dirty pages to the lock, since that is starving other clients from getting the lock.
If things are working properly, the logs should show BRW RPCs being generated on the client for that OST object almost immediately, and the OSS processing them and prolonging the DLM lock timeout. Once all of the dirty pages under that lock are flushed, then the client should send an LDLM_CANCEL RPC to the OSS.
One of several things could be happening:
- the client is adding new pages to the lock, instead of checking the CBPENDING flag and blocking the IO thread. This would prevent the client from cancelling the lock, though the BRW RPCs + lock handle should still cause the lock to be prolonged on the server
- the client did not send BRW RPCs, so the lock was not prolonged
- the client did send BRW RPCs, but they didn't contain the LDLM lock handle that allows the RPC to get into the high-priority RPC queue on the OSS, and the server-side lock to be prolonged
- the client did send the BRW RPCs properly, but they were not processed properly by the OSS to prolong the lock
- the client did not try to send the LDLM_CANCEL when all of the dirty pages were written
- the client tried to send the LDLM_CANCEL RPC, but it was not sent from the client because of max_rpcs_in_flight (shouldn't happen for LDLM RPCs), or IB credits limitation
- the client sent the LDLM_CANCEL RPC, but it was not processed properly/timely on the OSS.
To track this down, it makes sense to find all of the logs that mention the lock handle on the client 0x507863eddeba3639 and/or server (0xdc8659a15ab03659 (these both refer to the same lock). Looking at the logs shown above, it seems like things are mostly working OK. The client has the right flags set on the lock 0x429400000000:
It isn't clear to me if try_to_add_extent_for_io() and osc_extent_make_ready() are for new IO, or if this is flushing existing dirty pages? This is happening 100s after the blocking callback was sent, so it is surprising that the client wouldn't have finished flushing 1-5MB of dirty pages yet and cancelled the lock? The CANCELING flag is set, which means the client is at least trying to cancel it. Did that RPC not get sent (maybe it is blocked on the client), or maybe the cancel was piggy-backed into another RPC as an ELC request, but that RPC is not high priority, and is now stuck on the OSS?
|
|
Attached client.txt and oss.txt files, which is the result of the grep of the designed lock handle in client and oss01 logs.
The lock was added to LRU list before the blocking AST was coming, after ldlm_cli_cancel_local() I don't see the reply either on client side or on the oss side.
|
|
Additional information:
- There appears to be some
server-side client-side persistence when the issue is triggered.
- A client that encounters the issue has a high probability of encountering the issue again.
- This likelihood of encountering the issue again seems to favor a previously impacted client. A reboot of the client appears to clear the issue.
There are no unique features that would explain why a specific client encounters the issue more frequently (same config, kernel, client, slurm job parameters, etc).
This may be coincidental but seems worth pointing out what has been observed.
(edited to change flip the assertions to client-sticky as opposed to server-sticky)
|
|
After checking the similar ldlm_handle_bl_callback messages in the logs of HP-259, the after ldlm_cli_cancel_local(), the client should flush the dirty data, but the time gap between the cancel locally and try_to_add_extent_for_io() is 99 seconds, while the reproducer3-2020-01-31 client log in HP-259 shows that client at most took around 10 seconds to start the flush and the lock blocking ast handling can be finished and replied to OSS before the timeout set by the OSS.
My speculation is that the client is busy sending RPCs, so that the flush requests cannot be sent out to OSS timely, I think increase the osc.*. max_rpcs_in_flight would decrease the chance of this error.
|
|
We've seen the errors with max_rpcs_in_flight at 8 and at 32.
Question: Is there a value you'd like to see run, or you think has a high probability of not triggering the issue?
There are lnet routers in the client->server path of some instances of the event. o2ib-client / socklnd-server.
The issue is seen on single lnet configurations. All socklnd or all o2ibd.
Question: Are the failed flush requests the partial writes we're seeing? Or is there more to this issue where the partial writes are another part of a larger or different issue?
|
My speculation is that the client is busy sending RPCs, so that the flush requests cannot be sent out to OSS timely, I think increase the osc.*.max_rpcs_in_flight would decrease the chance of this error.
I don't think that increasing osc.*.max_rpcs_in_flight can be a permanent solution to the problem, since more RPCs in flight per OST may not speed up the IO processing on the OSS (e.g. other threads on the same client, and threads on other clients will also have lots of RPCs in flight, so there is going to be contention for processing all of the RPCs on the OSS). As long as the client is sending any BRW RPCs with the contended DLM lock handle (and they are being processed by the OST) it should be enough to refresh the lock timer on the OSS, so the client shouldn't be evicted.
One possibility that we might consider is including the lock cancellation in the ELC buffer as part of the last BRW RPC? That would reduce the RPC count, and ensure that the lock cancel is processed as quickly as possible, but would need some special handling on the OSS to avoid canceling the lock before the BRWs are processed, maybe a refcount on the lock on the OSS for each BRW in the pending queue, in case the BRW RPCs are processed out of order?
|
|
so I checked the logs and I came to a similar conclusion as Bobijam:
We have a bunch of dirty extents. a cancel request comes we try to shuffle it out, but there are a lot of other cancel activity ongoing so we sit and wait for our turn.
what does
lctl get_param osc.*.max_dirty_mb
show?
If we have like 1G in there, then even at 32 RPCs at 4M per RPC it will take up to 8 full trips to completely clean that out (more if you have 1M RPCs). Throw in any sort of a slowdown anywhere and the time gets longer.
We see clearly from the logs this request was initiated after another one completed xid 1656993038008544 - I see the completion message in the logs but not the start time so either it took longer than 100 seconds or there was some message drop for the logs.
Checking nearby messages seems the sending xids vs completions are several thousands apart though some other IO also completes fast in parallel.
So if there's a problem with a "logjam" on the server side where our io RPCs are stuck behind other IO RPCs then even 32 might not be enough. I know it's sort of hard but settign the max_rpcs_in_flight to something like 1024 to ensure there's never any waiting client side for any sending might be the ultimate test here. (of course normally it's not a great idea to go that high because you can overwhelm the server side, but in this case as we suspect there's some sort of struggling with making RPCs out it might be an interesting experiment)
|
|
So, my comment is the same as previously - if we set max_rpcs_in_flight=1024 that would get more RPCs from this client into the server queue, but also more from every other client, and not get us further ahead of the problem (disk bandwidth is not able to keep up with short-term demand). It may actually make things worse, if the queues are very deep with "normal" write RPCs, then we have a harder time to get high-priority writes processed quickly.
Are the LDLM_CANCEL RPCs being blocked? That definitely shouldn't be subject to max_rpcs_in_flight, if that is currently the case. Also, is there something blocking the LDLM_CANCEL RPCs being processed on the server? I believe I'd suggested to increase ldlm_canceld threads on the OSS, but if eg. they get blocked on disk IO for some reason (eg. update LVB?) then that would also be a problem.
|
|
FWIW, I've seen this occur on bonded 40GbE socklnd (not multi-rail) and Inifniband (o2ibd). I wondered if Eth interrupt service getting long might have played a factor but seeing it on IB rules that out.
Would setting higher values for ptlrpc:ldlm_num_threads help? Or, does that dynamically increase on demand?
|
|
Jeff, the tread count is dynamic, but current max is only 32. I think increasing this on the server might reduce the logjam for the cancel RPCs, though it wasn't a total solution on the other test system. The real issue is if we change parameters, there has to be some way to verify that this reduces the frequency of the problem, and it wasn't clear to me how consistently you can reproduce it? If it is easy/100% then we can experiment, but if only occasionally it is hit then it will be hard (or very lengthy) to know if the change fixes the problem.
|
|
I think I can iterate on this somewhat. The prevailing question seems to be.....is this being considered a bug or more application tuning? Throughout this thread it appears that Lustre is doing what it is supposed to but timeouts or misses are occurring.
Also, does the missed cancel and failed flush result in what the reproducer sees as partial writes? I'm trying to tie this back to application side perception of the condition.
|
|
IMHO, this is clearly in the realm of Lustre not doing what it is supposed to. While it can't make the storage run faster for this workload, it should accept the IO at the speed that the storage runs and allow it to eventually finish. When the lock times out, the (seemingly unresponsive from OSS point of view) client is evicted an this results in pending IO from the client being errored out. That results in the partial writes seen by the application.
|
|
there is a logic to prolong locks on OST, probably we should extend that to the clients?
|
|
adilger I think you are missing that the server side lock prolong logic only works when we have IO RPCs in the server queue. When the client did not send them yet the prolong logic does not work.
Sure we can try to throttle client side (by e.g. decreasing max_dirty_mb) but it will degrade performance in some other cases.
bzzz But how do you let server know the client wants to prolong a lock? another rpc to get stuck in some queue?
|
|
Currently the testbed is:
osc.*.max_dirty_mb = 2000
osc.*.max_rpcs_in_flight = 8
Retesting with:
osc.*.max_rpcs_in_flight = 256
(it rejects attempts to set to 1024)
|
|
hm, indeed it looks like max rpcs in flight has a hard limit at 512.
Any news from the testing?
|
|
So far no failures. I'll post to ftp and add links with logs and debug outputs when it's triggered.
lctl errors on any attempt to set osc.*.max_rpcs_in_flight higher than 256. 256 is the highest allowed value.
Fails as well when going direct to sysfs and setting it directly:
# echo 512 > /sys/fs/lustre/osc/testbed1-OST0000-osc-ffff98b1d3b98800/max_rpcs_in_flight
-bash: echo: write error: Numerical result out of range
|
|
Oleg Drokin (green@whamcloud.com) uploaded a new patch: https://review.whamcloud.com/37468
Subject: LU-13131 osc: Always send all HP RPCs requests
Project: fs/lustre-release
Branch: b2_12
Current Patch Set: 1
Commit: f9d9628671ba8dbbe0b83143c7b28f457cb70217
|
|
this is really strange:
Anyway, I just added a patch that I think should help with the problem you are observing by making sure all IO resulting from lock blocking is submitted at all times (but we need to wait until sanity testing passes before I can recommend you to give it a try).
|
|
Oleg, is the https://review.whamcloud.com/37468 patch client side only or applied to both client and server?
|
|
It's a client-only patch.
|
|
Andreas Dilger (adilger@whamcloud.com) uploaded a new patch: https://review.whamcloud.com/37479
Subject: LU-13131 osc: remove redundant osc_list() helper
Project: fs/lustre-release
Branch: master
Current Patch Set: 1
Commit: 7ac203b2da83356f2ad7ec9080a56710623278f9
|
|
Testing patched 2.12 client. Reproducer lasts longer but the partial write still occurs as does client eviction. Once client experiences error, subsequent errors occur more frequently on that specific client. Will be posting debug logs from client and OSS soon.
|
|
how about the max_rpcs_in_flight at 256, did that help?
|
|
btw can you please produce full server-client logs with the patch in place? In theory it should be helping with this problem so I wonder if there's a gap somewhere so not all RPCs are sent as expected
|
|
@Oleg max_rpcs_in_flight=256 without patch did not help. max_rpcs_in_flight=256 with patch made the failures look different but still ended up with partial writes.
Trying to trigger again and capture in logs on both sides. Missed it the first time.
|
|
Partial write errors on multiple clients. This is using patched client with (7f7545a) patch.
Trace taken on clients, MDS and OSS nodes. Logs uploaded to ftp.whamcloud.com/uploads in a new subdir under this LU's directory. (1.97GB compressed)
This run was performed with LU-13131 patch (7f7545a) applied to 2.12.3 clients.
Server-side: Lustre 2.12.2 / ZFS 0.7.13
max_rpcs_in_flight=256 , ldlm.services.*.threads_max=2048 228 clients active on two OSS nodes, four OSTs each.
You'll see in the logs that the numbers of evictions has decreased. However, there is still significant occurrences of tgt_grant mismatches on the OSS side, as well as the partial writes are still seen by the client. It appears that the grants are not properly handled or reconciled during or after an eviction.....and as I mentioned....the partial writes are still seen.
|
|
Additional error traces and detailed config data (lnetctl, lctl, procfs, sysfs) uploaded to WC ftp site.
|
|
ok, so this time the trace changed significantly. The timeline is like this:
In r4i5n6.log.xz:
process 5932 "write-single" gets PW lock (ost handle 0xb79351ea101047c8) at 1581483476.935037
and keeps it locked while it does something.
2 seconds later a BL callback comes, but there's no activity from process itself for another 150 seconds (when eviction happens).
Since we only have RPC level tracing and not VFS or other deeper levels there's not enough information to see what was actually happening with that process in-between that necessitated such long lock holding.
I would think that there was a page-unaligned write that caused a read RPC that could not be sent, but it seems all writes are aligned on a multimegabyte boundary, so that cannot be it. Did the client run out of grant/quota causing sync write RPC that then got stuck in the outgoing queue behind some other RPCs and because it's not registered in the cache so cannot be prioritized for sending on blockinglock callback.
This is why I typically prefer logs to be gathered at -1 level when possible - so that all the data is there should it be needed even though the logs do grow up quite a bit.
|
|
Reproducer running with -1 logging, started this morning. Will post when logs are captured and uploaded.
|
|
aeonjeff could you please share details of the configuration you are using to reproduce this issue? # of MDS/MDY/OSS/OST/clients? Thanks!
|
|
1MDS, 1MDT, 2OSS, 8OST (4 per OSS), 228 clients.
|
|
> 1MDS, 1MDT, 2OSS, 8OST (4 per OSS), 228 clients.
Thanks Jeff!
|
|
Starting FTP upload of -1 logs taken yesterday as Oleg asked.
|
|
Oleg Drokin (green@whamcloud.com) merged in patch https://review.whamcloud.com/37479/
Subject: LU-13131 osc: remove redundant osc_list() helper
Project: fs/lustre-release
Branch: master
Current Patch Set:
Commit: 2cb7eb3bb65398368fc934e6cc4483ee6c331d45
|
|
something is very strange with your logs. the -1 logs from the clients are only 33M big and don't actually have the eviction event in them.
Were you not using debug_daemon when collecting?
|
|
Oleg,
The client logs are -1 level Lustre debug logs. Each one was uploaded as a xz compressed text log file at maximum compression.  Uncompressed size is ~1.2GB each. Below is the first 50 lines of the uncompressed log file:
|
|
Well, the logs are at -1 level indeed, but there are gaps in them.
For example the very first lock eviction, if we grep for the handle in all the logs, we get:
So basically neither clients nor servers have nay records of it other than server has the eviction record.
If we check second evicted lock handle (cbbeb26a5a7afac0), it's seen in the server logs more, but it's again totally absent in client logs.
So in order to have whole consistent logs, debug_daemon needs to be used to avoid any gaps in logs.
|
|
New logs uploaded to WC ftp. The debug_daemon method was used. One small complication, the clients are stateless (no local disk) so the size wasn't unlimited. Set for 32GB. The debug_daemon coughed up overflow and other errors periodically. I know at least one partial write/eviction sequence is captured but I don't know if anything was dropped by debug_daemon as it appeared to have issues keeping up with the output level at times.
|
|
typically a good way to combat debug daemon overflows is by increasing debug_mb setting.
I'll check the logs to see what was captured
|
|
The clients are stateless. The ability to increase debug_mb is ram limited.
|
|
where are the logs going to? some slow network filesystem?
with decently fast local storage I never had a need to increase debug_mb beyond 2048. if it goes to local ramdisk then you can keep debug_mb smaller so tmpfs could adsorb more data I guess.
I checked the first couple of handles from eviction logs and no matches in the client logs it seems?
|
|
There is no network storage destination. The debug file is written to tmpfs on a stateless (diskless) client.
We'll adjust debug_mb down to 2048 and try to trigger a stop of the reproducer when the first instance of partial writes are seen on the client side as a way to reduce noise and get more potent debug content.
Can you provide any example of the message strings you are looking for? I want to make sure the debug output I upload contains some semblance of what you're looking for so your time isn't wasted assessing debug output that doesn't contain some actionable data.
|
|
Would it be of any value to spin up an LFS in AWS with enough clients to trigger the reproducer error and just provide access to assess? I've considered this but I won't go through the process deploying it if you don't find any value in it.
|
|
if you can organize a reproducer instance we can directly access, that would be great!
|
|
While we look to creating a public access reproducer, a new batch of logs have been uploaded to WC FTP, subdir contains date string 20200228.
|
- Is there a release slated to incorporate change 37468 (HP RPCs)?
- Are there any debug message types we can disable or suppress in order to save space for messages pertinent to tracing this issue?
|
|
I checked the logs provided and unfortunately the log daemon writes cannot keep up with the amount of logs generated and as the result dropped a lot of messages, including the ones we are interested in.
I guess we need to find an alternative way or drop the message level so. The goal is to ensure this sort of message does not appear in client logs: "debug daemon buffer overflowed; discarding 10% of pages"
how about this debug level I wonder, if it does not help, try removing info from the list please.
"inode super cache info warning other page dlmtrace error emerg rpctrace vfstrace console"
|
|
Oleg Drokin (green@whamcloud.com) uploaded a new patch: https://review.whamcloud.com/37918
Subject: LU-13131 osc: Make sure we don't accidentally deprioritize hp requests
Project: fs/lustre-release
Branch: b2_12
Current Patch Set: 1
Commit: 290c26e72e8d23491e4c80c1c313b8bdec532df8
|
|
Uploaded a new debug capture. Directory name contains string '20200312'. Looks like a clean capture of a client partial write sequence with a good amount of lead up.
|
|
Thank you for the log. Here's the culprit:
So basically osc_queue_async_io is called with ldlm lock held, gets stuck in osc_enter_cache because we don't have any free grant or memory allowance and we need to wait until an RPC arrives with more grant or frees up some previously dirty page.
Meanwhile this lock becomes contended and server wants it back, but we cannot release it -> timeout passes and the client is evicted.
In the past we handled this by doing sync IO in this case to ensure nothing is stuck. Time to see why that code was reworked, I guess.
|
|
Oleg Drokin (green@whamcloud.com) uploaded a new patch: https://review.whamcloud.com/37967
Subject: LU-13131 osc: Make sure we don't accidentally deprioritize hp requests
Project: fs/lustre-release
Branch: master
Current Patch Set: 1
Commit: c45facd0431cedf39095259dc06b4385db237850
|
|
Oleg,
A few questions:
- Is the https://review.whamcloud.com/37967 patch a further cleanup on the previous high priority requests patch or does it address the lock/grant/eviction sequence you saw in the most recent log upload?
- Do you think the lock/grant/eviction sequence you identified in the recent log upload is a client-side issue? If so, would it be addressed by any of the work done here by Neil Brown and James Simons? [https://review.whamcloud.com/#/c/37605/7/lustre/osc/osc_cache.c
]
- Given that you have seen the event sequence is there anything that can be done in the interim while a fix is developed to avoid hitting the issue? Tuning, etc?
|
|
Oleg Drokin (green@whamcloud.com) uploaded a new patch: https://review.whamcloud.com/37992
Subject: LU-13131 osc: Do not wait for grants for too long
Project: fs/lustre-release
Branch: b2_12
Current Patch Set: 1
Commit: 70c2685ca21b63558eef3c7f25ba12cf46c8e835
|
|
37967 patch is a port of 37918 to master. It is a further fix on top of 37479 (it can arise separately too, but 37479 is more likely to hit first masking this other issue, you did not hit it in your testing it appears based on your logs but please include it now just in case).
the locking eviction is definitely a client-side issue promoted by slow response of OSTs to IO requests. I just made a patch 37992 to address this potentially excess waiting that I'd like you to try and see if it helps in your case. I am cautiously optimistic that's going to be the end of it, but it was quite a deep rabbit hole so who knows if another level of effects would be unearthed after this patch (in which case please collect additional logs).
|
|
Okay, to be clear, apply 37967, 37479 and 37992 then retest?
|
|
No, please apply 37479, 37918 and 37922
|
|
Apply 37468 as well? Or does 37918 supersede 37468?
|
|
Oh, sorry. I mean 37468 37918 and 37922
37479 is not a fix, just a cleanup. I keep getting it mixed up with 37468 unfortunately
|
|
Oleg Drokin (green@whamcloud.com) merged in patch https://review.whamcloud.com/37967/
Subject: LU-13131 osc: Make sure we don't accidentally deprioritize extents
Project: fs/lustre-release
Branch: master
Current Patch Set:
Commit: f1c55f97d2d4b21fe87031b2bddfb9813f7df488
|
|
Oleg Drokin (green@whamcloud.com) uploaded a new patch: https://review.whamcloud.com/38057
Subject: LU-13131 osc: Always send all HP RPCs requests
Project: fs/lustre-release
Branch: master
Current Patch Set: 1
Commit: 8eb6963fd1b37b59d26680c3646b6dd436a5eb86
|
|
aeonjeff
Do you have a sense as to when you will be able to run the next round of tests?
Peter
|
|
Gathering logs now to upload from a run with patches applied. Logged (failed) run has two client partial write failures and evictions. Will comment again when uploaded.
|
|
Latest logs uploading to a subdir with 20200325 date string in the name. This run was performed with all available patches applied as of 20200325. Upload should be complete within an hour or so from now. Logs are ~8GB xz compressed.
|
|
Oleg Drokin (green@whamcloud.com) uploaded a new patch: https://review.whamcloud.com/38114
Subject: LU-13131 osc: Ensure sync IO is high-priority for blocked locks
Project: fs/lustre-release
Branch: b2_12
Current Patch Set: 1
Commit: 81c3ccfd2e27544660056789d2a4b39f889db73b
|
|
Thank you for the logs.
I see we needed some more gymnastics with the sync IO to ensure it actually is sent when we are out of grant instead of just sitting there in the queue.
Can you please add the 38114 patch on top of all the other patches you already have and give that a try? Thanks.
|
|
New logs uploaded, subdir named with date string 20200403.
Partial write still occurs. However, what appears to be a large issue is the after effects of hitting the issue. The client never recovers. Once the issue occurs the grant accounting becomes fouled and never resolves itself. The partial write and eviction create an i/o error for outstanding commands but once the issue presents and the grant accounting is fouled that never recovers and causes endless failures from that point forward.
|
|
Oleg Drokin (green@whamcloud.com) merged in patch https://review.whamcloud.com/38057/
Subject: LU-13131 osc: Always send all HP RPCs requests
Project: fs/lustre-release
Branch: master
Current Patch Set:
Commit: 0f1743916be6605fcd8f57993d6ce7d8d06ce12c
|
|
Oleg Drokin (green@whamcloud.com) uploaded a new patch: https://review.whamcloud.com/38164
Subject: LU-13131 osc: WIP Experimental! Always send sync writes as highprio
Project: fs/lustre-release
Branch: b2_12
Current Patch Set: 1
Commit: 78d06c437d3184f18b1f9002c370212425d60fd9
|
|
Thank you for this new set of logs, it's puzzling in the sense that the last patch actually did not do anything (so the RPC that was supposed to be sent as high priority is not sent like that anyway.), I am not sure why you seem to have problems with grant recovery, how reproducible was that?
It's a bit puzzling why the patch actually did not work, I wonder if IO region is covered by multipe locks (there are two big offset difference in locks in use in a single io).
Determining all of the potential locks that a region might be covered under when we are out of grant seems to be a bit less trivial than I hoped. As a simple proof of concept we can issue all "out of grant" locks - the patch to try this approach is https://review.whamcloud.com/38164 - while I am thinking how to better tackle this, perhaps it would be great if you can verify it actually help as much as I hope it should. Thank you.
|
|
So far the test patch results in a clean reproducer run. For expediency a smaller number of clients were used. Scaling up clients to levels of previous runs. Stay tuned, but so far the test only patch runs clean.
|
|
Reproducer run of 222 client nodes was successful using the new test patch. Whatever you tweaked in that patch definitely made a positive difference.
|
|
thank you for confirmation.
|
|
Oleg Drokin (green@whamcloud.com) merged in patch https://review.whamcloud.com/37918/
Subject: LU-13131 osc: Make sure we don't accidentally deprioritize hp requests
Project: fs/lustre-release
Branch: b2_12
Current Patch Set:
Commit: 56919f42d1814896148b13222a60b83c7b2db2fa
|
|
Oleg,
37918 is a patch already included since mid-March. Is there anything new since we reported that your test patch passed without partial write and grant errors? I want to be sure I didn't miss something.
|
|
You are on the current set of patches. I am still working on 38164 patch replacement that actually looks at all locks that cover an extent.
|
|
Oleg Drokin (green@whamcloud.com) uploaded a new patch: https://review.whamcloud.com/38283
Subject: LU-13131 osc: Do not wait for grants for too long
Project: fs/lustre-release
Branch: master
Current Patch Set: 1
Commit: 294cbdb8c9241b867468bd713eb2675bc520d489
|
|
I think I have a new patch for you to try. If you can back out last two patches: 38114 that you had and 38164 and then reapply current version of 38114 - that should be the proper way of implementing it.
If you can give that a try, that would be appreciated.
|
|
70 node reproducer run triggered the typical partial write and grant errors. Debug and associated logs uploaded to 2020421 subdirectory.
Patch set used:
37468 – always allow high priority RPCs through (KEEP)
37479 – just cleanup, no functional change (KEEP)
37918 – don’t deprioritize high priority RPCs (KEEP)
37992 – for 5 second (KEEP)
38114 – if any locked pages are waiting for a callback, make the whole extent high priority (LATEST 38114)
|
|
Hm, the logs don't actually contain "the event", the eviction is there, but the lock and process that held it only appear at the moment of eviction for both evicted locks so it seems for whatever reason the log buffer overflowed and dropped some data. I also tried searching for "forced sync i/o" (precursor to the case we have at hand with current patches) and all occurrences of that happened after eviction too.
How to gauge usefulness of logs: when you see an eviction message in server logs like this:
take the hex number after "remote:" and discard leading 0x (so in out case it would be 78c91a7ff8305a07) and then grep client debug logs for it. You should have two clusters of hits with timestamps ~100 seconds apart. This means you caught both sides of the needed data. if you only see it clustered in one spot (like with the latest set of logs) - that means one side is missing.
I think it would be best if you also try to collect the logs immediately after you see eviction message in server logs, currently your clients seem to be running for considerable time after the eviction which unevenly discards portions of older (useful) logs sometimes resulting in such gaps.
|
|
FYI: due to space and stateless client constraints the info messages were disabled, in case you are looking to those for context.
|
|
the messages I am interested in are not INFO, mostly CACHE, RPC and DLM
|
|
New traces uploaded, dated 20200424. Same patch set as 20200421.
|
|
Thank you. These are the good traces, they show the problem clearly:
When we are preparing to send a sync RPC - the lock is not yet contended so we send it with urgent priority and the RPC gets stuck in the queue. When a blocking callback arrives it sees the lock is busy and waits until it returns, which is obviously does not in time.
The original PoC code sidestepped that by always sendign such requests as high-priority so the situation never arose.
Let's see if I can have a good way to handle that.
|
|
Oleg Drokin (green@whamcloud.com) uploaded a new patch: https://review.whamcloud.com/38453
Subject: LU-13131 osc: Ensure immediate departure of sync write pages
Project: fs/lustre-release
Branch: master
Current Patch Set: 1
Commit: 6d4bb849704dd7a9f63d8d5f9dbf1d426c464b4f
|
|
I refreshed patches 37992 and 38114 and it would be great if you could give them a try again. Thank you.
|
|
Refreshed patches appeared to work at ~70 clients and then failed when scaled up to ~200 clients.
Logs uploaded to ftp, named 20200505
|
|
thank you forthis additional testing pouring through the logs I noticed something I sort of ignored before - the timeout in osc_enter_cache_try is actually for a single waiting period in a potentially unlimited while loop so if you have a bunch of RPCs returning the timeout keeps renewing.
This code was reworked in master with patch https://review.whamcloud.com/37605 (not directly applicable to b2_12) that ensures timeout is global for the duraction of that function. Conversion to longer timeout made it reappear in your testing because your relatively longer RPCs have more chances to return under the new timeout values and restart the timer.
I'll try to port over relevant stuff from patch 37605 to b2_12
|
|
Oleg Drokin (green@whamcloud.com) uploaded a new patch: https://review.whamcloud.com/38610
Subject: LU-13131 osc: Ensure immediate departure of sync write pages
Project: fs/lustre-release
Branch: b2_12
Current Patch Set: 1
Commit: 01a0892ffeac3bf668c63b0d51d5decbed5a17c4
|
|
I have all the relevant patches pulled into b2_12-next branch in our git repo and it would be great if you can give that a try. Thanks!
|
|
Oleg Drokin (green@whamcloud.com) merged in patch https://review.whamcloud.com/38283/
Subject: LU-13131 osc: Do not wait for grants for too long
Project: fs/lustre-release
Branch: master
Current Patch Set:
Commit: 1eee11c75ca13745d083410e1ced3a1a8b088ee9
|
|
Oleg Drokin (green@whamcloud.com) merged in patch https://review.whamcloud.com/38453/
Subject: LU-13131 osc: Ensure immediate departure of sync write pages
Project: fs/lustre-release
Branch: master
Current Patch Set:
Commit: 13b7cf4fabdd55977b68eb856bfdc82f0a349e73
|
|
Oleg Drokin (green@whamcloud.com) uploaded a new patch: https://review.whamcloud.com/38672
Subject: LU-13131 osc: Do not wait for grants for too long
Project: fs/lustre-release
Branch: b2_12
Current Patch Set: 1
Commit: 319b13d947a6c7a5f8d77813804b6a0721e80b27
|
|
All patches landed for 2.14. aeonjeff we're still keen to get your report back on the effectiveness of the fixes in your testing
|
|
So far the latest patch set has run the reproducer very stable over two days. First runs at 70 clients, subsequent runs at 200+ clients. Have never seen this level of stability running the reproducer. Gathering more nodes to scale up higher but this is looking good.
|
|
Thanks for the update Jeff - this is encouraging news.
|
|
Thank you for the update, great to hear that.
|
|
Oleg Drokin (green@whamcloud.com) merged in patch https://review.whamcloud.com/37468/
Subject: LU-13131 osc: Always send all HP RPCs requests
Project: fs/lustre-release
Branch: b2_12
Current Patch Set:
Commit: 05dc36b07fc1ac40988f7994cd37cd239d9a8986
|
|
Overnight runs of 300+ client nodes. Never failed. Stick a fork in it, this one's done. #bravo
|
|
Nice! 
|
|
Oleg Drokin (green@whamcloud.com) merged in patch https://review.whamcloud.com/38672/
Subject: LU-13131 osc: Do not wait for grants for too long
Project: fs/lustre-release
Branch: b2_12
Current Patch Set:
Commit: 0dda74eec7a29c98c7b6ee9a99e54c7dbefcabca
|
|
Oleg Drokin (green@whamcloud.com) merged in patch https://review.whamcloud.com/38610/
Subject: LU-13131 osc: Ensure immediate departure of sync write pages
Project: fs/lustre-release
Branch: b2_12
Current Patch Set:
Commit: 0c6454503e1fede795d9b094ee92c91f4290924b
|
Generated at Sat Feb 10 02:58:38 UTC 2024 using Jira 9.4.14#940014-sha1:734e6822bbf0d45eff9af51f82432957f73aa32c.
client.txt
lustrelog_mds00_158033093x.txt.gz