Alex
I think that it is best that you comment on this one
Peter
could you please grab all the stacks once this happens? (echo t >/proc/sysrq-trigger) notice the process got stuck in dbuf_read() -> zio_wait() which is ZFS's internal path to read a block.
hmm, probably I was too speedy.. I guess for a reason one of the llogs (changelog or hsm action log) is huge.. Chris, would you mind for provide debug logs to see what's hapenning exactly?
Alex, what exactly to the llogs do? is there some docs that explain them at a high level?
I've seen something similar, if not the same, on our test systems. In that case, it appeared like the mount process was making forward process, just at an abysmal rate. The disks were not fully utilized, but they were continuously doing reads originating from the mount.lustre process. Without really understanding how llogs fit into the bigger picture, it seemed like there were simply "a lot" of logs that it needed to process, and doing so was really slow since it is a serial single threaded process limited by reads to the disk. I could be wrong, but that's just how it appeared from the outside; I never verified this with the source code though.
How would change logs play into this? Does that mean running robinhood might be affecting the time it takes to mount?
I'm asking for log to understand which specific llog the system was reading. unless you're using HSM, this should be changelogs - basically a log of all the changes (including opens) - so 3rd party tools (like robinhood) can watch the activity. the important bit here is that the records are supposed to be cancelled in seconds by the consumer. so it might be a bug in our cancellation code or the consumer wasn't acting quickly enough. it would be interesting to learn the size of actual llogs the system was processing - see llog_reader utility.
yet another thing I noticed is that the system was trying to resolve FID to dnode, which seem to be an issue in the other cases as well. I wonder wether Brian''s idea to prefetch ZAP could help.
the important bit here is that the records are supposed to be cancelled in seconds by the consumer.
AFAIK, this is not the case for our file systems using the changelogs. Often, robinhood is not able to read changelogs at the rate they are being created. As a result, changelogs tend to accumulate on a system and eventually get consumed when user activity dies down, allowing for the changelog consumer to "catch up". So, if the accumulation of "a lot" of changelogs causes the mount to take a significant amount of time to complete, I'm not sure we'll be able to keep using that feature for the time being.
EDIT: And I just want to make sure it's clear.. By "eventually get consumed", I mean possibly weeks later; not seconds as you said. This is especially so when we first start using robinhood on an existing filesystem. It can take weeks to fully traverse the filesystem and populate the database with the initial state, meanwhile changelogs get created and are not consumed until the initial filesystem scan completes.
it would be interesting to learn the size of actual llogs the system was processing - see llog_reader utility.
I'll try and get some real data regarding the llogs and push it your way, I need to look into some other issues first though.
OK, if there is no very strong need in the changelogs, I'd recommend to turn it off. another reason is that currently the llog is protected with a single mutex serializing all the modifications (no totally, but to some extent). in general, it seems that due to COW nature of ZFS small modifications (like with OI and llogs) lead to significant fragmentation which in turn makes subsequent reads quite expensive. so something like zap_prefetch() Brian suggested should be use in more cases.. llog can be another one.
OK, if there is no very strong need in the changelogs, I'd recommend to turn it off.
But we do have a strong need for it. Our admins have been trying to lean more heavily on using robinhood for certain things, but if it is going to take hours to mount as a result of using robinhood, we'll have to seriously reconsider its usage.
OK, the both clarifications are very important. I'd hope that relatively small changes to prefetch stuff can improve significantly, but I'm going to look at the llog code to check couple ides. thanks.
Can you please explain why the changelog llog needs to be walked at filesystem mount time, blocking all access to the filesystem until that is complete?
there is no strong requirement to do this in the context of mount, we can do this in background. to my knowledge that never was an issue because usually the number of alive records in the catalog is very small. then the whole process seem to be badly affected by slow OI population (that issue with FID->dnode and cache misses in ZAP). I'll make a patch, but it will take a bit as the locking is tricky here.
http://review.whamcloud.com/10308 – I can't ask you to test the patch immediately though.
Alex, just to give you some more context. Our admin has decided to turn off robinhood on the particular filesystem that we're seeing the most issues on, with the feeling that it is has been the cause for some of our grief. According to our calculations, it would have take just over a month to complete the initial scan of the filesystem; it has over 700 million files it it currently.
That's not a good feeling to have to ditch a "feature" because it doesn't actually work when we try to use it on a production filesystem. He tried to deregister the changelog user on the MDS, letting it run over night, and it still has not completed. Is the deregister process essentially the same as what is going on at mount time?
Also, there were over 400 million changelogs entries at the point that we tried to stop and deregister the changelog user; so definitely not a "very small" amount.
then the whole process seem to be badly affected by slow OI population (that issue with FID->dnode and cache misses in ZAP).
I can see why you might think that, but I'm not sure I buy it. For a large filesystem, I don't see why you can have a reasonable expectation to get a large percentage of cache hits for the initial scan; you'll probably be pulling in information for files that haven't be touched recently which will come from disk. Whereas, changelog entries will accumulate for "new" files, so I'd expect much better cache hit rates there. Thus, at least during the initial scan of a heavily utilized filesystem, I'd expect the changelogs to accumulate much faster than the rate which robinhood can traverse the FS.
Prakash, we do not scan all the entries, at mount we scan only the headers of the plain llogs which contain actual changelog entries. given a plain llog contains upto 64K, we'd need to touch 400M/64K=~6.1K records in the catalog at mount.
"a touch" means FID->dnode lookup, taking dnode, then 8K read from that dnode.
given a plain llog contains upto 64K, we'd need to touch 400M/64K=~6.1K records in the catalog at mount.
Ah, I see! So that means roughly 6.1K random 64K reads? Why does it need to read the llogs in the first place? I can't seem to remember exactly what purpose they serve.\
"a touch" means FID->dnode lookup, taking dnode, then 8K read from that dnode.
Why the 8K read?
actually I wrote that in the first try to reply, but removed. but I'm happy you asked 
so, we do have a notion of "llog" - basically a relatively small object containing a header (8K) and up to 64K records. the idea is to be able to be able to reclaim space when some fraction of records is consumed. with a single object that would be an issue given not every disk filesystem provides a way to punch (deallocate) space in a middle of object.
now to be able to add >64K records we add a catalog, which is essentially a log containing pointers to those "plain" logs (which in turn stores actual records, like changelog records, unlink records, etc).
when some record is being cancelled we drop a bit in the header. once all the records in a llog are cancelled, we can destroy this llog and cancel the corresponding record in the catalog. for the few reasons, this process of cancellation/destroy isn't atomic, it's done in couple different transactions. this can lead to "leaked" llogs which contains no useful records but consume space. and to clean them we used to scan the catalog at the beginning, checking all the headers and removing empty plain llogs. this is exactly what was happening in the backtrace you provided.
as said before, there is no strong need to do this at initialization, but that never was an issue (to my knowledge at least), because: 1) the number of entries to scan is usually very small, just few - because the records are consumed quickly 2) *probably* higher cost for random I/O with ZFS, though I can't say I totally disagree with your argument on a cold cache.
backport this patch and two dependent fixes to b2_4:
http://review.whamcloud.com/#/c/11331/
http://review.whamcloud.com/#/c/11332/
http://review.whamcloud.com/#/c/11333/
Not only do we need a fix for b2_4, more specifically we need a fix for b2_4 that is compatible with Patch Set 7 of change 9488 from LU-4584. That was the officially designated fix for that bug on b2_4, so we will need patches compatible with that.
Chris, these three patches and the patch from LU-4584 are independent, they can be applied without any conflict.
Hmmm, so they are. My bad. I'm not sure what I was trying to pull last Wednesday, but it must have been the wrong thing.
Thanks!
FYI, the landing on master seems to have introduced a regression in changelog functionality: LU-5859.
Patch was landed to master for 2.7.0.