|
John
Could you please investigate?
Thanks
Peter
|
|
Quick update. I first throught that the errors were gone but actually no...
MDS:
Robinhood client:
|
|
Hi Stephane,
Could you post the output of lctl get_param 'mdd.*.changelog*' on the MDS?
|
|
Hi John,
The frequency of the errors is varying but doesn't look that bad today (Aug 27) as there has been only a single error reported so far:
Let me know what you think...
Thanks!
Stephane
|
|
We're also seeing this problem at NCI. Filesystem is Lustre 2.10.4, DNE, MDTs are ZFS, mdt usage is ~33% full.
We've found it can be provoked reliably by running a 4-thread (or more) mdtest targeting a single MDS, from a single client.
Possibly it only occurs under high MDS load.
robinhood log:
mds changelog params:
|
|
We're seeing the same on 4 different file systems that are running 2.10.5. Robinhood reports errors about clearing the changelogs and MDS reports the same errors as above. We do have Robinhood scans running simultaneously, so it's possible the scan load is a contributing factor.
Interestingly, we are able to clear the logs by hand.
lfs changelog_clear fsname-MDT0000 cl1 0
This is probably a red herring, but I do find it odd that the Lustre MDS logs all refer to fsname-MD*D*0000 vs. all other references to fsname-MD*T*0000. Hopefully just a difference in nomenclature that doesn't result in code issues.
|
|
Shawn, could enable trace and ioctl (lctl set_param debug="+trace ioctl") and capture the lustre debug logs from the MDT when this occurs?
|
|
It's possible that this is due to LU-11426 but I don't know how likely that is.
|
|
Mike
What do you advise with this one?
Peter
|
|
Note: MDS is now running Lustre 2.10.6
This has started to impact us again and it looks like that due to that issue, Robinhood cannot keep up anymore:
Robinhood logs:
|
|
Sigh. So the special changelog character device is not scaling as well 
|
|
IMO this is not an issue with the changelog character device. Looking at the code, enabling ioctl debug as John advised would really help:
At least that way we can see what lustre thinks is happening.
|
|
Hello Quentin!
Thanks for the feedback. I tried that, but something is weird...
FYI oak-md1-s2 is running oak-MDT0000 on Lustre 2.10.6 and I set the requested debug flags:
Now, an occurrence is seen on the Robinhood server:
corresponding epoch timestamp is 1547747135
around this time on the MDS... almost no logs for several seconds, just some watchdog.c:120:lcw_cb() messages, like if logging were somewhat blocked at that time...
no logs from 1547747072 to 1547747137? something's wrong
dk file attached as dk.1547747365.gz
Another occurence:
That's epoch timestamp 1547747394
On the MDS, there are some "missing" logs at that time:
no logs from 1547747376 to 1547747537?
dk file attached as dk.1547747668.gz
The rest of the time, debug_kernel logging seems OK and we got several messages / sec. Am I missing something obvious? Could this be related to this issue? Thanks!!
Stephane
|
|
Some additional info: I have never seen the "out of range" CDEBUG message from mdd_changelog_clear(), but as you can see in the attached dk files, there is a lot of calls to llog_changelog_cancel_cb ending with:
However timestamps are not matching the errors on the robinhood client.
If anyone has any other idea to try, let me know.
|
|
Hello Stephane,
I don't think the llog_changelog_cancel_cb() entries ending with "rc=1" are faulty ones. I read a bit of code in obdclass/llog.c and it might just be that "1" indicates a record was deleted (or something like that).
Did you notice how there is no "Process entered" logging entry for mdd_changelog_clear() in your dk files? Only "Process leaving"... Also, the fact there is not a return code associated with the message means the function went through the EXIT macro, which is not in the code path that prints the intial error message you reported: Failure to clear the changelog for user 1: -22.
Other than that, the missing logs part sure is scary! Haven't been able to figure it out an explanation for it... yet.
|
|
Hey Quentin, after several unsuccessful attempts because each time some debug logs were missing, I was finally able to catch an occurrence (just now) of Failure to clear the changelog for user 1: -22 when debug enabled on the MDS in production. The result is:
Note that there is an out of range error indeed!
Full 1-min long log attached as dk.1547828521.gz if needed.
Thanks!
Stephane
|
|
By the way, about the missing DK logs:
This happens occasionally, I've seen it due to two issues:
1. Immediately after a thread wakes, its dk log messages do not always make it to the buffer. I am not sure why this is, but I've seen it repeatedly.
2. debug_mb is divided in to separate per CPU buffers, and so if you have a lot of CPUs, it's easy for individual debug buffers to get pretty small and then be overrun. (For example, a KNL system with ~550 MB debug_mb would have approximately 2 MB of buffer for each CPU.)
|
|
(Thanks Patrick for the info, that makes sense!)
Regarding our current changelog clear errors, I just got the same errors on a brand new Lustre 2.12.0 system with DNE. I can see the error on all MDTs:
client:
|
|
I just realised I read the logs wrong! I thought lustre was refusing to clear a record "in the future", but it is actually refusing to clear an "already cleared" one.
Is it possible there are several processes feeding from the same changelog reader? Clearing records in parallel, out of order?
|
|
Thanks, this is useful and made me think of LU-11426. We do have a single Robinhood instance per filesystem, no other changelog reader. We see the problem on two different systems using Robinhood one based on 2.10 (Oak) and a new one based on 2.12 (Fir), each time on all MDTs.
|
|
So this also affects 2.12 - can we get that added to the affects/versions?
We are in a bind on a couple filesystems now, and were contemplating updating, but no point.
Scott
|
|
To be complete - I checked our version. This definitely affects 2.10.6 too.
|
|
Note this taking out our production file system at ORNL!!! Anything to try yet.
|
|
is that possible to collect and attach changelog_users itself? If bottom fs is ldiskfs it can be mounted as ldiskfs to some mountpoint and then there is 'changelog_users' in the root directory. Run llog_reader on it:
Please, provide output from that llog_reader, then note that it is the llog catalog and real records are located in paths of catalog records, in the example above it is 'O/1/d6/6'. Please attach file from the path of latest record, if there are many, for analysis . You can run llog_reader on it as well:
That would be very useful to get these llogs when that problem occurs, so we can check what is in llog at that point.
|
|
to clear all changelogs try the following:
# lctl get_param mdd.*.changelog_users
check 'current index' and 'user index' in the output, then
lfs changelog_cleanup <fsname>-MDT0000 cl1 0
to clear all llogs, after that check again 'changelog_users', 'current index' should be equal to 'index' of user that means all records are gone.
|
|
Mikhail,
The filesystem that James is referencing is in production at the moment with limited downtime availability to try the above recommendations. We do have a test system that is a smaller scale to the production one, but without the scale we have been unable to reproduce the issue there. In an effort to stop this from happening, we attempted to de-register the changelog user on all 4 of the MDSs. The consumer in this instance is intended to be robinhood but we have not been running it until we can try to sort this out. The lustre version is 2.11 running on rhel7.6 servers and the MDTs and OSTs are zfs.
-Philip
|
|
Philip, it doesn't require downtime actually and can be done on running system, if you have access to server fs you can mount it locally as ldiskfs or zfs and read local data. For zfs that is zfs mount <dataset> I think
|
|
We were able to produce some of these errors on the TDS while hammering the FS with mdtest. We were getting messages like those described
2019/03/28 10:24:53 robinhood@f2-util01[373768/6] ChangeLog | ERROR: llapi_changelog_clear("f2-tds-MDT0000", "cl1", 5425145) returned -22
2019/03/28 10:24:53 robinhood@f2-util01[373768/6] EntryProc | Error -22 performing callback at stage STAGE_CHGLOG_CLR.
2019/03/28 10:24:53 robinhood@f2-util01[373768/6] llapi | cannot purge records for 'cl1'
2019/03/28 10:24:53 robinhood@f2-util01[373768/6] ChangeLog | ERROR: llapi_changelog_clear("f2-tds-MDT0000", "cl1", 5425146) returned -22
2019/03/28 10:24:53 robinhood@f2-util01[373768/6] EntryProc | Error -22 performing callback at stage STAGE_CHGLOG_CLR.
2019/03/28 10:26:47 robinhood@f2-util01[373768/9] llapi | cannot purge records for 'cl1'
2019/03/28 10:26:47 robinhood@f2-util01[373768/9] ChangeLog | ERROR: llapi_changelog_clear("f2-tds-MDT0000", "cl1", 5470278) returned -22
2019/03/28 10:26:47 robinhood@f2-util01[373768/9] EntryProc | Error -22 performing callback at stage STAGE_CHGLOG_CLR.
2019/03/28 10:26:47 robinhood@f2-util01[373768/9] llapi | cannot purge records for 'cl1'
2019/03/28 10:26:47 robinhood@f2-util01[373768/9] ChangeLog | ERROR: llapi_changelog_clear("f2-tds-MDT0000", "cl1", 5470276) returned -22
2019/03/28 10:26:47 robinhood@f2-util01[373768/9] EntryProc | Error -22 performing callback at stage STAGE_CHGLOG_CLR.
2019/03/28 10:26:47 robinhood@f2-util01[373768/9] llapi | cannot purge records for 'cl1'
2019/03/28 10:26:47 robinhood@f2-util01[373768/9] ChangeLog | ERROR: llapi_changelog_clear("f2-tds-MDT0000", "cl1", 5470277) returned -22
2019/03/28 10:26:47 robinhood@f2-util01[373768/9] EntryProc | Error -22 performing callback at stage STAGE_CHGLOG_CLR.
I waited around for some of these to stack up a bit and then mounted the MDT. This is all that is showing in changelog_users which seems correct as it was mostly caught up when I halted things.
[root@f2-tds-mds1 10:39:00][mdt0]# llog_reader changelog_users
rec #1 type=1064553b len=64 offset 8192
Header size : 8192
Time : Tue Mar 26 11:58:06 2019
Number of records: 1
Target uuid :
-----------------------
#01 (064)id=[0x4a:0x1:0x0]:0 path=oi.1/0x1:0x4a:0x0
I did grab the records referenced just in case it had something interesting.
[root@f2-tds-mds1 10:44:12][mdt0]# llog_reader oi.1/0x1\:0x4a\:0x0
rec #1 type=10670000 len=40 offset 8192
Header size : 8192
Time : Thu Mar 28 08:48:52 2019
Number of records: 1
Target uuid :
-----------------------
#01 (040)changelog_user record id:0x0
And just for completeness, I grabbed what was is in the changelog_catalog
[root@f2-tds-mds1 10:47:51][mdt0]# llog_reader changelog_catalog
Bit 1 of 6 not set
Bit 2 of 6 not set
Bit 3 of 6 not set
Bit 4 of 6 not set
Bit 5 of 6 not set
Bit 6 of 6 not set
Bit 7 of 6 not set
Bit 8 of 6 not set
Bit 9 of 6 not set
Bit 10 of 6 not set
Bit 11 of 6 not set
Bit 12 of 6 not set
Bit 13 of 6 not set
Bit 14 of 6 not set
Bit 15 of 6 not set
Bit 16 of 6 not set
Bit 17 of 6 not set
Bit 18 of 6 not set
Bit 19 of 6 not set
Bit 20 of 6 not set
Bit 21 of 6 not set
Bit 22 of 6 not set
Bit 23 of 6 not set
Bit 24 of 6 not set
Bit 25 of 6 not set
Bit 26 of 6 not set
Bit 27 of 6 not set
Bit 28 of 6 not set
Bit 29 of 6 not set
Bit 30 of 6 not set
Bit 31 of 6 not set
Bit 32 of 6 not set
Bit 33 of 6 not set
Bit 34 of 6 not set
Bit 35 of 6 not set
Bit 36 of 6 not set
Bit 37 of 6 not set
Bit 38 of 6 not set
Bit 39 of 6 not set
Bit 40 of 6 not set
Bit 41 of 6 not set
Bit 42 of 6 not set
Bit 43 of 6 not set
Bit 44 of 6 not set
Bit 45 of 6 not set
Bit 46 of 6 not set
Bit 47 of 6 not set
Bit 48 of 6 not set
Bit 49 of 6 not set
Bit 50 of 6 not set
Bit 51 of 6 not set
Bit 52 of 6 not set
Bit 53 of 6 not set
Bit 54 of 6 not set
Bit 55 of 6 not set
Bit 56 of 6 not set
Bit 57 of 6 not set
Bit 58 of 6 not set
Bit 59 of 6 not set
Bit 60 of 6 not set
Bit 61 of 6 not set
Bit 62 of 6 not set
Bit 63 of 6 not set
Bit 64 of 6 not set
Bit 65 of 6 not set
Bit 66 of 6 not set
Bit 67 of 6 not set
Bit 68 of 6 not set
Bit 69 of 6 not set
Bit 70 of 6 not set
Bit 71 of 6 not set
Bit 72 of 6 not set
Bit 73 of 6 not set
Bit 74 of 6 not set
Bit 75 of 6 not set
Bit 76 of 6 not set
Bit 77 of 6 not set
Bit 78 of 6 not set
Bit 79 of 6 not set
Bit 80 of 6 not set
Bit 81 of 6 not set
Bit 82 of 6 not set
Bit 83 of 6 not set
Bit 84 of 6 not set
Bit 85 of 6 not set
Bit 86 of 6 not set
Bit 87 of 6 not set
Bit 88 of 6 not set
rec #89 type=1064553b len=64 offset 13824
rec #90 type=1064553b len=64 offset 13888
rec #91 type=1064553b len=64 offset 13952
rec #92 type=1064553b len=64 offset 14016
rec #93 type=1064553b len=64 offset 14080
rec #94 type=1064553b len=64 offset 14144
Header size : 8192
Time : Tue Mar 26 11:58:06 2019
Number of records: 6
Target uuid :
-----------------------
#89 (064)id=[0xaf:0x1:0x0]:0 path=oi.1/0x1:0xaf:0x0
#90 (064)id=[0xb0:0x1:0x0]:0 path=oi.1/0x1:0xb0:0x0
#91 (064)id=[0xb1:0x1:0x0]:0 path=oi.1/0x1:0xb1:0x0
#92 (064)id=[0xb2:0x1:0x0]:0 path=oi.1/0x1:0xb2:0x0
#93 (064)id=[0xb3:0x1:0x0]:0 path=oi.1/0x1:0xb3:0x0
#94 (064)id=[0xb4:0x1:0x0]:0 path=oi.1/0x1:0xb4:0x0
If helpful, I can also provide what is in the records referenced there.
-Philip
|
|
Philip, that can be late but maybe you have also lustre debug log? The debug from mdd_changelog_clear() is needed similar to one provided by Stephane above:
00000004:00000001:12.0:1547828517.194681:0:4204:0:(mdd_device.c:1491:mdd_changelog_clear_cb()) Process entered
00000004:00000080:12.0:1547828517.194681:0:4204:0:(mdd_device.c:1508:mdd_changelog_clear_cb()) Request 5796171010 out of range: 5796171012
make sure that there is 'ioctl' debug level on server with lctl get_param debug and set it if needed with lctl set_param debug=+ioctl
Debug log can be collected when this issue happens with lctl dk > <debuglogname>
|
|
At the moment can you also check the last changelog entries? in path=oi.1/0x1:0xb4:0x0
|
|
It looks like the ioctl debug flag is already set. I've uploaded the dk output. Also attached is the output from the oi.1/0x1:0xb4:0x0 path.
-Philip
dk_ornl_20190328.gz
f2_llog_reader_20190328.gz
|
|
Philip, I've checked debug log output, it is too late, there are no needed messages, if you will be able to catch the moment when -22 error will happens, try to get debug log again if possible
|
|
No worries. I'll start up the traffic again to try to catch it when it happens. Report back soon.
-Philip
|
|
Grabbed the output as soon as I started seeing them. I have the FS stopped if you need me to grab anything else.
-Philip
dk_ornl_20190328_1216.gz
|
|
Philip, I have needed log, thanks, check please that llog:
processing log [0xd8:0x1:0x0]:0 at index 106 of catalog [0x5:0xa:0x0]
I think it is oi.1/0x1:0xd8:0x0 not sure about exact path though, you can check it at index 106 of changelog_catalog
Can you grab that plain llog and attach it here? Better as llog, not llog_reader output
|
|
in context of this issue, does anyone see any other bad things with changelogs except these messages? Does it really cause growing changelogs? From what I see so far that is just valid race between requests to clear changelogs when they are re-ordered, possibly being inflight. So first request clears more records and then there can be late request which wants to clear lower records which are cleared already. I'd say this valid case and it is just too loud saying 'Failure to clean llogs'. I think that will be OK just to exit with no error if such situation happens. And changelog should still be cleared as expected and don't grow up, moreover this error indicates that llog is being cleared regularly and that is just concurrent attempts to clear it.
|
|
Yes, our changelog grows without bound.
Scott
|
|
Scott, could you provice output of lctl get_param mdd.*.changelog* from MDT? And just to be sure, are you using robinhood to manage changelogs?
|
|
Mikhail,
Here is the requested llog.
ornl_0x1_0xd8_0x0.gz
|
|
If I am understanding things correctly, then I agree with Scott's statement, unless the changelog_size does not actually indicate the size of the changelog. On our production filesystem, after changelog issues bit us in another way we de-registered the changelog users. Poking around a bit more, it doesn't look like the changelog user was completely cleaned up as initially I attempted to register again to manually run the changelog_clear and then try to de-register again as a test. It did not look like that user was cleaned up completely either. I could just as well be misunderstanding things and if so please correct me. This is the output of that lctl get_param mdd..changelog from one of the production MDSs.
[root@f2-mds1 06:56:14][~]# lctl get_param mdd.*.changelog*
mdd.f2-MDT0000.changelog_deniednext=60
mdd.f2-MDT0000.changelog_gc=0
mdd.f2-MDT0000.changelog_mask=
MARK CREAT MKDIR HLINK SLINK MKNOD UNLNK RMDIR RENME RNMTO OPEN CLOSE LYOUT TRUNC SATTR XATTR HSM MTIME CTIME ATIME MIGRT FLRW RESYNC GXATR NOPEN
mdd.f2-MDT0000.changelog_max_idle_indexes=2097446912
mdd.f2-MDT0000.changelog_max_idle_time=2592000
mdd.f2-MDT0000.changelog_min_free_cat_entries=2
mdd.f2-MDT0000.changelog_min_gc_interval=3600
mdd.f2-MDT0000.changelog_size=10333280
mdd.f2-MDT0000.changelog_users=
current index: 677996307
ID index (idle seconds)
I would be glad to assist with any testing you might need to try to get this to resolution.
-Philip
|
|
I am away from systems on travel until next week.
For us, absolutely positive the changelog was not being cleared.
We definitely saw this while using Robinhood. I don't know if we have logs handy, as we had to not use Robinhood on affected filesystems because if this. We may have one we can test on, I will try to get information next week.
Scott
|
|
Mikhail,
I work with Scott. We monitor the changelog sizes on all of our lustre file systems via mdd.*.changelog_size.
Here's the output of changelog_size for that MDT:
mdd.scratch-MDT0000.changelog_size=23117357872
This is a scratch file system for a cluster we're waiting to put into production. The policy engine is necessary for this use case. We could work around it for a period of time and that's one of the plans we're considering right now. The other is to just recreate the file system with 2.10.3.
Jesse
[edit] Log attached to this issue as lu-11205-ssec.log.gz
|
|
Jesse, I see, and how many changelog users do you have registered?
|
|
One:
=============
lctl get_param mdd.scratch-MDT0000.changelog_users
mdd.scratch-MDT0000.changelog_users=
current index: 177784403
ID index
cl3 848659
|
|
Jesse, I see, but re-registered many times, probably that is the reason, I will do more investigation in that area
|
|
I think deregistering and registering the new user was an attempt to debug this issue. It's been a few months so I don't recall for sure.
I have another file system on 2.10.6 that I will test with. I didn't configure robinhood for it yet or register a changelog user. I'll let you know the results yet this afternoon.
Let me know if there's any other information or debugging i can provide.
|
|
Changelogs in Lustre 2.10.3 are not usable (see LU-10680 for example). We use 2.10.6 and while we see a lot of these messages (Failure to clear the changelog for user 1), changelogs seem to work most of the time. Sometimes the Robinhood reader will hang and the node needs to be restarted (or Lustre remounted). This happens a lot more with 2.12 for us but that's perhaps because we have more MDTs also. I haven't been able to do a new report for that yet, and because each time remounting the robinhood client(s) seem to fix the issue for some time, it's not that critical.
|
|
Mikhail,
Hold off on further investigation of our issue at SSEC. It looks like it's just a simple FSNAME-MDT conflict.
The name-MDT combination our new file system and-about-to-be-replaced file system is the same. I'll move the new file system to a different robinhood server and expect it'll be fine. It's that damn 8 character limit stifling our creativity 
I think we reported this as affecting 2.10.6 - that may be incorrect. I can follow up next week after we see how the changelog processor works over the weekend.
Stephane,
We're processing the changelogs for two 2.10.3 file systems and while we do see the a few instances of llapi_changelog_clear returning -22 on those file systems per day I don't see any corresponding connectivity issues. This particular policy engine server is under quite a bit of pressure as well.
Jesse
|
|
Jesse, in 2.10.3, if I remember correctly, there is a changelogs garbage collector that is enabled by default and is broken due to an uninitialized variable, so if for any reasons you don't consume your changelogs quickly enough and triggers the GC, your MDS is likely to crash.
|
|
James Simmons (uja.ornl@yahoo.com) uploaded a new patch: https://review.whamcloud.com/35013
Subject: LU-11205 test: reproducer for clearing a range of changelog records
Project: fs/lustre-release
Branch: master
Current Patch Set: 1
Commit: 19286970d329e78f474da2d0f61e36d5e988a3d9
|
|
Created a reproducer. Locally I see the same errors as reported here.
|
|
I sat down and investigated this issue. I can see the logs can be properly cleared if the right variables are used for indexing. For example:
lctl get_param -n mdd.lustre-MDT0000.changelog_users
current index: 98306
ID index (idle seconds)
cl2 32769 (702)
The index (32769) never changes until after lfs changelog clear is called. So if you want to clear a range of changelogs you look at "current index" to get the upper bound for clearing. When I did that the change logs were cleared as they should be and index was set to this new lower bound. You can review
https://review.whamcloud.com/#/c/35013/
to see how I got this to work. After I figured this out the question become is reading "current index" the right approach. From reading the robin hood code it looks like its using the logs read from llapi_changelog_recv() to determine the upper bound. I haven't tried that case in my sanity test but lfs changelog $FSNAME-MTD0000 32769 shows the correct information. I can update the test but to me this is looking like a robin hood bug.
|
|
> From reading the robin hood code it looks like its using the logs read from llapi_changelog_recv() to determine the upper bound
This is the only way for robinhood, and pretty much anything that processes changelog. The "current index" approach works well in tests but you really only want to dismiss changelog records you actually processed, and this rarely coincides with the value in "current index" (at least not on active filesystems).
IMO, out of order changelog records look like the ideal suspects.
|
|
In the HPE DMF 7 Lustre changelog reader we do something similar: only clear records up to the point where we're absolutely certain, in the presence of out-of-order and outright missing records, that we're not clearing valid changelog records that we yet have to process. Something similar, with slightly more relaxed constraints applies to restarting reading the changelog.
|
|
Currently I'm trying to get a grasp of what is going on and this is new area of Lustre for me. The reason I'm looking into this is that its been many months with no progress and we have a production system that is losing 3% of its MDT disk space per week. I will look to updating the test to use lfs changelog $FNAME-MDTXXXX since that is using llapi_changelog_recv(). From their I will need to think what level of the software stack this needs to resolved at. Looking at the problem at this current level of understanding this does not look like a kernel side solution. User land should never expect guaranteed sequential data IMNSHO. Now the question is should this be handled by llapi_changelog_recv() or in the external application.
|
|
I for one would prefer if the char device could handle this complexity. I expect there is one – good – way to handle this, and I do not see any reason to leave it to applications or the llapi to do the reordering. If there are different possible tradeoffs, then maybe the llapi (but definitely not the applications themselves).
|
|
I just can't see this being completely resolved in the kernel code but lets consider the cases.
One approach is if a record is not sequential then the char device just blocks until the next proper record comes. The limitation to this approach is that it would require that missing record to exist which might not be the case. The char device could send a request to resend and if the record doesn't exist return -EEXIST. Does that really handle this case? The question is how large can the gap be? The code would have to handle the case the record does show up after the -EEXIST is already reported. This approach could be server side as well. Again we might have a case in which a record shows up pretty late.
Another approach for resolving the out of order issue we would have to cache the records as they come so they can be sorted. This again could be done server side or client side. This would require some blocking until some amount is collected so it could be sorted. The question again is how far apart are the changelog record gaps? Do we wait until CDEV_CHLG_MAX_PREFETCH or does that need to go up? Also the same issue exist if a record just doesn't exist. Or the record just comes really late.
Lastly this handling as described above could be done in llapi_changelog_recv(). Same issues again, mind you like this approach the most.
|
|
I'm pretty certain the missing records are an issue with the char device code not returning them to userspace despite them being present in the on-disk changelog. See the writeup in LU-11581.
|
|
Ah, that is what I was looking for. It wasn't clear if the records were never coming or coming late. So the mdd layer actually drops the out of order records so the char device never sees those records. Still points out the issue of gaps, which could still happen, needs to be handled. Also how large is the out of order, 16, 1024, 64K, 1GB of records?
|
|
To clarify for the dropped records, as far as I can tell it is the char device code that drops them somehow. I base this on not seeing this issue when using pre-char-device code. In my experience out-of-order sequences are typically small, with the most common occurrence being two records in inverse order. I don't think I have ever seen sequences that didn't resolve within a few tens of records. For DMF 7 we default to assuming a record was dropped rather than out of order if we get 1000 records further along and still haven't seen it. At present I know of no cases where that heuristic failed.
|
|
I think I see what the bug is in the char device. Need to play with it a bit to come up with a solution to the dropped records.
|
|
I wrote a toy changelog reader that I think reproduces the bug described here.
With a lustre file system mounted at /mnt/lustre, one MDT named lustre-MDT0000, and a changelog client registered on that MDT:
The expected output looks something like:
|
|
Excellent. I see the reproducer. Will give it a try today. Thank you.
|
|
There are some kernel-side CDEBUG(D_IOCTL) that may provide useful information if enabled.
|
|
Quentin what licence do you want for your changelog reader and who is the copyright holder?
|
|
Er, whatever Lustre uses those days is fine. GPLv2?
I wrote the code, during working hours. In French law, I believe I hold "parental" rights to the work (so I can ask to have my name associated with it) and my employer – CEA – holds the copyright.
So, GPLv2 header + "author: Quentin Bouget <quentin.bouget@cea.fr>" + "Copyright (c) 2019 Commissariat a l'energie atomique et aux energies alternatives".
|
|
So I have been trying your changelog_reader and find the problem is very rare. I saw it only after 250K file creation and then deletion. To really reproduce this I might need to inject an out of order condition manually in the mdd layer.
|
|
Are you doing file creation/deletion on multiple nodes at the same time? In my experience that helps induce these problems.
|
|
Having looked at this issue for the first time, my theory is definitely that this relates to out-of-order Changelog records:
- records are A, C, B in the log
- client processes A, C
- client cancels records up to C
- server records C as cur_endrec
- client processes B
- client cancels record B, which fails and returns -EINVAL because B < C
- client is stuck trying to cancel record B forever, Changelog never shrinks
My understanding of the out-of-order record problem is that the "out of orderness" is only within a single journal transaction, because two (or more) threads allocate transaction handles, then get a slot in the Changelog, but their RPC processing finished in a different order in which they allocated a slot in the Changelog file. So, it shouldn't be possible to have records like "A, F, E, D, B, C" that are not within the same disk transaction, so they should either all be committed before an MDS crash, or not at all. My estimate is that the upper limit for misordered records is likely the number of MDS threads running (possibly limited by the number of cores on the MDS), since there can't be more active RPCs than this within one transaction that might race with each other.
That means it should be reasonable to reorder the records in the kernel or llapi so that they are in order to the application (not every application should have to handle this itself), and correspondingly it needs to drop the cancel for lower-numbered records that have been reordered until the later ones have been processed, or it would be possible to lose the higher-numbered records which appear earlier in the Changelog if there was a crash during processing. If the records are always presented to the application in order, there should never be a case where a higher-numbered record is cancelled without processing the lower-numbered one, as that would be broken even when the records are in order on disk.
I think there are two potential workarounds for the cancellation issue, both of which could be implemented:
- Lustre just quietly accepts the cancellation of an old record (maybe within some limits) without any error, allowing RBH to continue on its merry way.
- RBH accepts that "-EINVAL" (which is not a great error, as it is too common) means that the record has already been cancelled and continue on to the next record.
Separately, there should be a fix to either the kernel or userspace Changelog processing to detect and correct slightly misordered records.
I think even if the ordering problem is fixed we would want to have one or both of the cancellation fixes to allow existing Changelogs to be processed.
|
|
I want to add my thoughts
mdd_changelog_store() fill the record index in sync way for mdd,
rec->cr.cr_index = ++mdd->mdd_cl.mc_index;
after that
llog_add()>llog_cat_add_rec>takes write semaphore and do llog_write_rec( ..LOG_NEXT_IDX..). Next index simply adds to the end of llog.
So assume we have two threads in same time, cr_index = 1 and cr_index = 2 before llog_add.
There is no any guarantee that first cr_index would be the first for llog_write_rec.
To guaranty the same transaction for reordered cr_index, we need to set cr_index after
llog_th = thandle_get_sub(env, th, ctxt->loc_handle->lgh_obj);
|
|
Hi @aboyko
This seems very promising!! I guess all Robinhood users are hitting this issue with recent versions of Lustre. It's unclear to me if it's wasting space on the MDTs, but it's definitively very confusing for Lustre sysadmins.
Are you going to submit your patch to gerrit (http://review.whamcloud.com/) so that it can be properly reviewed by others?
Thanks again!
|
|
I tried the fix from Boyko and it didn't resolve the problem
|
|
I've created a fix, submitting soon.
|
|
Alexandr Boyko (c17825@cray.com) uploaded a new patch: https://review.whamcloud.com/35650
Subject: LU-11205 mdd: process mixing changelog records
Project: fs/lustre-release
Branch: master
Current Patch Set: 1
Commit: f9f82470637f7769884a863c8ef90d79fcdfc12f
|
|
@James A Simmons, could you try the patch above? It also includes the reproducer for this issue.
|
|
Yep, setting it up right now. Thank you.
|
|
We did some testing and saw these results. Before we started robinhood to purge things we had:
lctl get_param ..changelog_size mdd.f2-tds-MDT0000.changelog_size=4711216
Afterwards we saw
lctl get_param ..changelog_size mdd.f2-tds-MDT0000.changelog_size=928368
Does this patch help resolve some of the orphan records as well that we couldn't cleanup before?
|
|
running lfs changelog clear 0 restores the changelog_size back to 4711216. There is some strange issue there but that is independent of this patch. The testing has gone very well!! Thanks Boyko.
|
|
When I tested the code posted in the review earlier today, I still saw out-of-order and lost changelog records. From this and other tests it does appear that lost changelog records are out-of-order records that are not reliably (and often reliably not) returned to userspace.
|
|
Was it better? In our testing it did make the problem go away. I wonder if the problem is less common.
|
|
It is hard to say whether it really reduces the lost records issue, as too much changed in the cluster I tested on to make it truly apples/apples.
|
|
@Olaf Weber, the patch allows clear of unordered records. The processing is different case. I do think that software should take care. Read a number of records and process it in order. In most cases it can process unordered too. We should not see unordered operation for a same file or directory cause they are synchronized by a parent lock.
|
|
LU-11426 would fix the ordering. So error -22 wouldn't happen.
|
|
Agreed that the proposed fix for LU-11426 should also resolve this.
Related to the "orphan records" that James mentioned, in my testing of this patch it did not (fully) resolve that issue: the only way I could get them to go away was to rebuild the changelog by deregistering all readers.
|
|
From my understanding of current changelog mechanism from the source code, the chagelog records will not delete if there are more than one changelog user using it.
|
|
The consensus seems to be that this can be closed as a duplicate of LU-11426
|
|
We just upgraded our Lustre 2.12 servers and the Robinhood client to 2.12.3 RC1 and we're still seeing these log messages:
Not sure about the real impact though.
|
|
Stephane, does it cause changelog growing as original issue did?
|
|
Still a problem with 2.12.3, robinhood hangs when reading the changelogs, and when this happens, an error appears on the console. I need to restart robinhood almost every day due to this problem:
Note that this isn't a problem with 2.10.8
And Mike, I don't know regarding the changelog growing issue, we had never noticed this specific problem (that doesn't mean it doesn't happen, I was concerned too about that), I think LLNL reported that at some point. Because we're DoM-ready, our MDTs are very large.
|
|
We're also seeing this with the following combination - sles11 sp4 client
> lustre-client-2.12.4-1.x86_64
> robinhood-lustre-3.1.5-1.lustre2.12.x86_64
against a 2.10.8 RHEL 7.6 server
> kernel-3.10.0-957.1.3.el7_lustre.x86_64
> kmod-lustre-2.10.8-1.el7.x86_64
> kmod-lustre-osd-ldiskfs-2.10.8-1.el7.x86_64
> lustre-2.10.8-1.el7.x86_64
> lustre-osd-ldiskfs-mount-2.10.8-1.el7.x86_64
> lustre-resource-agents-2.10.8-1.el7.x86_64
Robinhood will run fine for so long, then stop clearing changelogs:
2020/04/16 00:15:54 robinhood@bullion[14485/1] STATS | ==================== Dumping stats at 2020/04/16 00:15:54 =====================
2020/04/16 00:15:54 robinhood@bullion[14485/1] STATS | ======== General statistics =========
2020/04/16 00:15:54 robinhood@bullion[14485/1] STATS | Daemon start time: 2020/04/15 12:45:52
2020/04/16 00:15:54 robinhood@bullion[14485/1] STATS | Started modules: log_reader
2020/04/16 00:15:54 robinhood@bullion[14485/1] STATS | ChangeLog reader #0:
2020/04/16 00:15:54 robinhood@bullion[14485/1] STATS | fs_name = pgfs
2020/04/16 00:15:54 robinhood@bullion[14485/1] STATS | mdt_name = MDT0000
2020/04/16 00:15:54 robinhood@bullion[14485/1] STATS | reader_id = cl1
2020/04/16 00:15:54 robinhood@bullion[14485/1] STATS | records read = 15682180
2020/04/16 00:15:54 robinhood@bullion[14485/1] STATS | interesting records = 4444583
2020/04/16 00:15:54 robinhood@bullion[14485/1] STATS | suppressed records = 11175370
2020/04/16 00:15:54 robinhood@bullion[14485/1] STATS | records pending = 451
2020/04/16 00:15:54 robinhood@bullion[14485/1] STATS | last received: rec_id=161344242, rec_time=2020/04/16 00:15:53.691544, received at 2020/04/16 00:15:53.738479
2020/04/16 00:15:54 robinhood@bullion[14485/1] STATS | receive speed: 409.11 rec/sec, log/real time ratio: 1.00
2020/04/16 00:15:54 robinhood@bullion[14485/1] STATS | last pushed: rec_id=161343461, rec_time=2020/04/16 00:15:48.603088, pushed at 2020/04/16 00:15:53.737393
2020/04/16 00:15:54 robinhood@bullion[14485/1] STATS | push speed: 419.50 rec/sec, log/real time ratio: 1.00
2020/04/16 00:15:54 robinhood@bullion[14485/1] STATS | last committed: rec_id=161343461, rec_time=2020/04/16 00:15:48.603088, committed at 2020/04/16 00:15:53.7417
04
2020/04/16 00:15:54 robinhood@bullion[14485/1] STATS | commit speed: 419.50 rec/sec, log/real time ratio: 1.00
2020/04/16 00:15:54 robinhood@bullion[14485/1] STATS | last cleared: rec_id=161343461, rec_time=2020/04/16 00:15:48.603088, cleared at 2020/04/16 00:15:53.742430
2020/04/16 00:15:54 robinhood@bullion[14485/1] STATS | clear speed: 419.50 rec/sec, log/real time ratio: 1.00
2020/04/16 00:15:54 robinhood@bullion[14485/1] STATS | ChangeLog stats:
2020/04/16 00:15:54 robinhood@bullion[14485/1] STATS | MARK: 0, CREAT: 882918, MKDIR: 128738, HLINK: 501, SLINK: 22345, MKNOD: 0, UNLNK: 493670
2020/04/16 00:15:54 robinhood@bullion[14485/1] STATS | RMDIR: 54927, RENME: 64817, RNMTO: 0, OPEN: 0, CLOSE: 13427698, LYOUT: 78, TRUNC: 64903
2020/04/16 00:15:54 robinhood@bullion[14485/1] STATS | SATTR: 456295, XATTR: 48510, HSM: 0, MTIME: 36766, CTIME: 14, ATIME: 0, MIGRT: 0
2020/04/16 00:15:54 robinhood@bullion[14485/1] STATS | FLRW: 0, RESYNC: 0, GXATR: 0, NOPEN: 0
2020/04/16 00:15:54 robinhood@bullion[14485/1] STATS | ==== EntryProcessor Pipeline Stats ===
2020/04/16 00:15:54 robinhood@bullion[14485/1] STATS | Idle threads: 24
2020/04/16 00:15:54 robinhood@bullion[14485/1] STATS | Id constraints count: 0 (hash min=0/max=0/avg=0.0)
2020/04/16 00:15:54 robinhood@bullion[14485/1] STATS | Name constraints count: 0 (hash min=0/max=0/avg=0.0)
2020/04/16 00:15:54 robinhood@bullion[14485/1] STATS | Stage | Wait | Curr | Done | Total | ms/op |
2020/04/16 00:15:54 robinhood@bullion[14485/1] STATS | 0: GET_FID | 0 | 0 | 0 | 0 | 0.00 |
2020/04/16 00:15:54 robinhood@bullion[14485/1] STATS | 1: GET_INFO_DB | 0 | 0 | 0 | 40627 | 0.36 |
2020/04/16 00:15:54 robinhood@bullion[14485/1] STATS | 2: GET_INFO_FS | 0 | 0 | 0 | 40475 | 0.07 |
2020/04/16 00:15:54 robinhood@bullion[14485/1] STATS | 3: PRE_APPLY | 0 | 0 | 0 | 40597 | 0.00 |
2020/04/16 00:15:54 robinhood@bullion[14485/1] STATS | 4: DB_APPLY | 0 | 0 | 0 | 40597 | 0.13 | 98.15% batched (avg batch size: 28.7)
2020/04/16 00:15:54 robinhood@bullion[14485/1] STATS | 5: CHGLOG_CLR | 0 | 0 | 0 | 40627 | 0.02 |
2020/04/16 00:15:54 robinhood@bullion[14485/1] STATS | 6: RM_OLD_ENTRIES | 0 | 0 | 0 | 0 | 0.00 |
2020/04/16 00:15:54 robinhood@bullion[14485/1] STATS | DB ops: get=3538391/ins=959210/upd=2832420/rm=566905
2020/04/16 00:16:00 robinhood@bullion[14485/2] ChangeLog | Error in llapi_changelog_recv(): -5: Input/output error
2020/04/16 00:16:01 robinhood@bullion[14485/2] ChangeLog | Error in llapi_changelog_recv(): -5: Input/output error
2020/04/16 00:16:02 robinhood@bullion[14485/2] ChangeLog | Error in llapi_changelog_recv(): -5: Input/output error
2020/04/16 00:16:03 robinhood@bullion[14485/2] ChangeLog | Error in llapi_changelog_recv(): -5: Input/output error
2020/04/16 00:16:04 robinhood@bullion[14485/2] ChangeLog | Error in llapi_changelog_recv(): -5: Input/output error
2020/04/16 00:16:05 robinhood@bullion[14485/2] ChangeLog | Error in llapi_changelog_recv(): -5: Input/output error
2020/04/16 00:16:06 robinhood@bullion[14485/2] ChangeLog | Error in llapi_changelog_recv(): -5: Input/output error
but nothing untoward in the MDS logs at the same time although there was a load peak and CPUs in 'wait' (grafana plots from collectd can be attached). LNet traffic from the MDS wasn't anything particularly impressive.
The robinhood server is one of the few machines we've tested with a 2.12 client - we're still mostly 2.10.8 or 2.7 (Cray) as we've still got a 2.5.x filesystem (sonnexion) and don't want to move too far ahead with clients.
|
Generated at Sat Feb 10 02:41:52 UTC 2024 using Jira 9.4.14#940014-sha1:734e6822bbf0d45eff9af51f82432957f73aa32c.
changelog-reader.tgz