|
Just as reported in LU-2576, the processes will wake up and make progress if a sysadmin issues:
|
|
Hi, Chris
- Is the fix of
LU-2909 also applied?
- Is there any lli_write_mutex changes in your branch, like
LU-3261?
- What's the 'cur_dirty_bytes' & 'max_dirty_mb' of each OSC? (this can be checked by the OSC proc file)
- What's the 'dirty_expire_centisecs' of your system? Is the thread being stuck longer than 'dirty_expire_centisecs' (30 seconds by defatult)?
Thanks.
|
Is the fix of LU-2909 also applied?
I pointed you to the exact tag that we are running. Our patches in the branch are clearly based at 2.4.0-RC1. So yes, of course we have that fix applied. You guys applied it.
Is there any lli_write_mutex changes in your branch, like LU-3261?
Again, see the tag that I included in the bug report. This branch does not include any experimental work to improve the LU-1669 problem, which is what Prakash was talking about in LU-3261. I also ran:
and it did not report any results, so no direct changes that I am aware of.
What's the 'cur_dirty_bytes' & 'max_dirty_mb' of each OSC? (this can be checked by the OSC proc file)
max_dirty_mb is 32 for all OSC. I didn't get cur_dirty_bytes. I did capture dump_page_cache. See attached. Keep in mind that BG/Q is ppc64, and pages are 64K.
Looks like there were 7129 dirty pages. At 64K each, that is 456,256 KiB. There are 16 OSTs, so on average there there were 28,516 KiB dirty. It seems pretty likely that some of the OSTs were at the max_dirty_mb limit.
What's the 'dirty_expire_centisecs' of your system? Is the thread being stuck longer than 'dirty_expire_centisecs' (30 seconds by defatult)?
3000
|
|
And yes, the threads are stuck for much, much longer than the 30 second dirty_export_centiseconds value. As I said, they appear to be stuck indefinitely. My guess is that they will never make progress without external intervention. They appeared to be stuck for at least 2 hours before I intervened by triggering drop_caches.
|
|
A "sync" command on the command line also successfully clears the outstanding dirty data.
Here is cur_dirty_bytes for one of the clients that is hanging on write:
The dirty data is actually pretty evenly spread. There were 512 files being written through this client at the time of the hang.
I also note that the flush-lustre-1 thread is waking up regularly, but does not seem to result in any of the dirty data being written. I enabled full lustre debugging watched flush-lustre-1 run for a bit in top, and then dumped the lustre log. See attached file rzuseqio14_lustre_log.txt . The flush-lustre-1 process was PID 10295 at the time of the log dump.
I haven't stepped through the code and logs long enough yet to understand why it is doing so much but failing to trigger the sending of the dirty data.
|
|
The log (rzuseqio14_lustre_log.txt) shows that ll_writepages() didn't trigger any dirty flush at all:
...
00000008:00000001:21.0:1369956379.455717:3872:10295:0:(osc_io.c:611:osc_io_fsync_start()) Process entered
00000008:00000001:21.0:1369956379.455724:4368:10295:0:(osc_cache.c:2914:osc_cache_writeback_range()) Process entered
00000008:00000020:21.0:1369956379.455732:4368:10295:0:(osc_cache.c:3010:osc_cache_writeback_range()) obj c0000002eacf46e0 ready 0|-|- wr 15|-|- rd 0|- cache page out.
00000008:00000001:21.0:1369956379.455744:4496:10295:0:(osc_cache.c:3011:osc_cache_writeback_range()) Process leaving (rc=0 : 0 : 0)
...
I think these dirty pages are supposed to be on the oo_urgent_exts, but seems they were not on either oo_hp_exts or oo_urgent_exts. Jinshan, any idea how this could happen?
|
|
Obviously there existed an active extent so that osc_io_fsync_start() didn't move it into urgent list.
Hi Chris, just to clarify, both `echo 3 > drop_caches' and sync will trigger it out of hang state?
|
|
It looks like this issue can only be seen on ppc clients, so let's drop the priority to not block 2.4 release while we're working on it.
|
Hi Chris, just to clarify, both `echo 3 > drop_caches' and sync will trigger it out of hang state?
Yes, that is correct.
It looks like this issue can only be seen on ppc clients, so let's drop the priority to not block 2.4 release while we're working on it.
I disagree. Just because we discovered it on ppc clients doesn't mean it is a ppc-only problem.
|
|
Hi Chris, if you see this issue again, try if `echo 1 > drop_caches' can also release the hang state. Also it will be helpful to check how much grants are there at the corresponding osc.
|
|
here is another global dirty page parameter: obd_dirty_pages and obd_max_dirty_pages. Can you please check it as well?
|
|
Chris, how frequent are the hangs, and how many systems does this affect? We've had several days of SWL runs on recent Lustre tags without seeing anything similar on x86_64 clients. While I don't want to minimize the importance of this issue, the main question is whether this problem is serious and widespread enough that it needs to block 2.4.0 from being released to any users, or whether it is possible to fix this after the 2.4.0 release?
LLNL will be running a patched version of Lustre regardless of whether this bug is fixed before 2.4.0 or afterward, so if this is more prevalent with PPC clients or ZFS servers it will not affect a majority of Lustre users. Also, by making Lustre 2.4.0 available to a wider user base the 2.4.0 code will get more testing and fixes, which helps LLNL as well. This bug is the only one holding the 2.4.0 release at this point, so we'd really prefer to drop it from the blockers list and release 2.4.0.
|
|
Andreas
I just gave Chris a call and he agrees that, while this may not necessarily be a PPC issue, that the amount of testing elsewhere demonstrates that this is a rare issue to hit and one that we can defer to 2.4.1.
Peter
|
|
Where would I find those?
Here's what I found in proc:
|
Chris, how frequent are the hangs, and how many systems does this affect?
Like Peter said, I don't particularly care about if this problem gets fixed in 2.4.0. But it is a very frequent problem. In fact, it may have never been fixed like we thought a few months ago. I've learned that a sysadmins was running "echo 3 > /proc/sys/vm/drop_caches" to get around the problem. But I was not aware that it was still a problem.
It affects all of our production systems that are running pre-2.4. Of course, we're only doing that on BG/Q systems with ZFS.  I just don't want to call this a ppc issue until we understand it better. I kind of suspect that it has more to do with the scale of simultaneous writers or something, rather than being endianness or page size related. I could be wrong. Too soon to say, really.
|
|
Chris, I'm just on my phone so can't verify, but I believe the parameters Jinshan is referencing are global parameters in llite or at the top level.
|
|
This is from the same useqio16 node as last Friday. Still hung in the same place after the full weekend. The obd_dirty_pages number exactly matches the sum of the 16 cur_dirty_bytes numbers (keeping in mind that pages are 64K on this platform): 459,341,824 bytes.
|
|
Any ideas?
|
|
Chirs, I was looking at related code these days, but didn't find any clue so far. btw, were there many truncate operations?
|
|
I can take a look at this issue if it's okay for you guys.
|
|
Yes please Jinshan!
|
|
Please apply patch: http://review.whamcloud.com/6554 to your tree to print accurate information when this problem happens. I tend to suspect a wakeup is missed somewhere but need to verify.
|
|
Ok, I'll apply that and get the info.
But there certainly seems to be an additional problem here. The Lustre client seems to be rather poorly integrated with the kernel's way of doing things. The kernel is clearly trying to write out these dirty pages, and Lustre is completely ignores the kernel. That is Bad. I would like to see that problem fixed as well.
|
|
Hi Chris, not sure I understand. You mean the dirty page won't be written back if EDQUOT is returned? Actually in vvp_io_commit_write(), if EDQUOT is seen, Lustre will try to write the page in sync mode.
|
|
I don't know what EDQUOT is, so no. I am referring to the kernel's normal BDI mechanism for regularly pushing dirty to disk. The calls are being made into Lustre, but Lustre decides to ignore them. I don't understand the whole call stack yet (by a long shot), but clearly the kernel's normal mechanisms get the Lustre code into osc_cache_writeback_range, where it notes that dirty pages exist. However, lustre chooses to do absolutely nothing with that information, rather than obeying the kernel's request to write out the dirty pages. That has got to have all kinds of bad implications for low memory situations on nodes. And not too surprising, we have all kinds of memory problems with the new Lustre client.
|
|
Do you mean the call path of ->writepage()? In this case, it will mark the dirty page as urgent and then wait for it to be written ll_writepage().
Yes, I agree that the current client has problem of memory and performance, and I will give you an explanation soon.
|
|
Jinshan, your patch does hit ten minutes after the hang. Here are the 6 lines that popped out on the console from one of the clients:
You patch seems to keep data flowing. But with 10 minute pauses here and there, of course.
Do you understand how to fix this, then?
Also, be aware that we are using the following settings on our BG/Q clients:
|
|
About the cache, another useful information would be:
lctl get_param osc.*.osc_cached_mb
so that I know how busy it is.
|
|
Apparently I should have adjusted cl_dirty in osc_unreserve_grant() as well, working on a patch...
|
|
Can you please try patch set 2 of http://review.whamcloud.com/6554?
|
|
Yes, I'll try it out. Thanks, Jinshan.
|
|
The problem seems to have disappeared with Patch Set 2 in place.
But now write performance is unacceptably bad. Four BG/Q clients are only pushing a total of around 720 MB/s (180MB/S each). That number should be closer to 1GB/s per client.
|
|
this patch should have nothing to do with the performance. Maybe you can try to roll back to unpatched version and see if it's due to env settings. Of course, we can simplify the problem by using dd to check performance.
If you can still see the performance drop, please try to collect a log with D_CACHE enable (lctl set_param debug=cache), I will take a look to make sure it's in the correct path.
|
|
I double checked, and I am certain that the patch is the only difference. FYI, I've moved to Lustre version 2.4.0-RC2_2chaos on both clients and servers.
Without the patch, I see write throughput burst to 4.4GB/s intially (as seen in ltop), and then taper off to a fairly constant rate in the low 3GB/s range.
With the patch, I see 720 MB/s. (These are aggregate throughput for 4 BG/Q clients.)
Keep in mind that our tree has the unstable page tracking changes. I don't know if there is a relation there or not, but you should be aware.
Without your patch, at the beginning of an IOR write phase, you might see something like this:
And that seems fairly normal.
But with patch set 2 of 6554 applied I see these bogus numbers:
I'm guessing that those large numbers are simply an arithmetic problem, where we're allowing the number to become negative. That somehow results in very slow write throughput, perhaps because all operations are not completely synchronous?
|
|
ah yes, indeed. The dirty bytes are actually negative numbers. I'll check it.
|
|
I found the problem. Working on a patch.
|
|
Will you please try patch set 3 and see if it helps.
|
|
Performance (and presumably the negative number) problem is gone, but it is still hanging for ten minutes like with patch one. I'll get post some info tomorrow.
|
|
Here's output from one of the debug messages before I leave for the day:
|
|
This is awkward - I thought it must be sleeping for LRU slots while holding some dirty pages. The problem is obvious: cl_dirty couldn't be deducted for some reason, one possible reason would the ptlrpc threads were blocked somewhere so brw_interpret couldn't be called, or the processes are waiting for something while holding active osc_extents. Can you please take a look at backtrace of running processes and tell me if there exists any other process is blocking on something?
Also, I worked out patch set 4 which dumps the extent tree when this problem happens. This can help us isolate the root cause.
|
|
See new attachment rzuseqio15_console.txt.bz2. It shows backtraces from all processes after a hang began, and then the messages that were printed by patch set 4.
|
|
Can you please try patch set 5?
|
|
Will do.
|
|
I have been running the reproducer, and haven't had a single hang yet with patch set 5 applied. I will leave it running over night.
|
|
No news assumes good news, no?
If this patch can survive, can you please do me a favor to roll back this patch, make the hang happen, and collect logs when doing `echo 3 > drop_caches', I don't understand why this can make it go forward?
|
|
Yes, I haven't been able to reproduce the problem again. Performance is in the accepatble range.
I should be able to get that log tomorrow.
|
|
See the attached rzuseq*_drop_caches.bz2 files. When I got a write hange, I enabled full lustre debugging, issued an 'echo 2 > drop_caches', and waited a few seconds, and then dumped the logs on all four clients.
Hopefully there is something useful in there.
|
|
Hi Chris, can you please try the last patch set? If this works, I will land it into master.
|
|
I took a look at the log but unfortunately I didn't find anything interesting.
For example, for log rzuseqio15_drop_caches.txt, obviously process 15336 is the drop_caches process and 15302 is flush process. So I tried to dig activities other than these two processes by:
[jinxiong@intel tmp]$ cat rzuseqio15_drop_caches.txt |grep -v '15336:' |grep -v ':15302:' |grep cl_io
[jinxiong@intel tmp]$
but nothing is printed out. I don't know why this can happen because the pages are already existing but no process is related to them. It will be helpful to figure out which process was stuck before dropping caches.
The purpose of doing this is to fully understand why dropping cache can make the hung process go forward. Though we can fix the problem by latest patch, it's really bad if we don't understand a code path clearly.
|
|
It takes quite a while to run drop_caches. I fear that getting the log of the stuck processes will be quite difficult with the other threads swamping the logs. But I'll keep this as a background task when I have time.
In the mean time, I'll update to the latest patch.
|
|
Jinshan, testing of change 6554 patch set 7 went well. No failures, and no new performance problems noted.
The commit message will need to be rewritten before landing.
|
|
patch landed for 2.5
|
Generated at Sat Feb 10 01:33:43 UTC 2024 using Jira 9.4.14#940014-sha1:734e6822bbf0d45eff9af51f82432957f73aa32c.
rzuseqio13_drop_caches.txt.bz2
rzuseqio14_drop_caches.txt.bz2