Ceph » CephFS

Had no joy reproducing with mds_auto_repair more recently (on diff. test nodes), but did manage on a vstart cluster against master with the attached .sh running in a loop, a client with debug output turned off, and the following settings:

        mds cache size = 100                                                    
        mds cache log max segments = 2                                          
        mds cache log events per segment = 1                                    
        mds cache verify backtrace = 1      

The attached log is the last part of a much longer log.

Notes:

Segment that has the unwanted item_dirty is seq 170750                                                                      

2015-01-14 14:50:36.996372 7f71e5197700  1 mds.0.1 asok_command: flush journal (starting...)

2015-01-14 14:50:36.998726 7f71e5197700  7 mds.0.log _prepare_new_segment seq 170750

*** this is the msgr thread, starting a new segment just after the one that the asok thread created *** 

cap release on 1000000548c, which is AKA /testdir2/file57                          
testdir2 is 10000005452                                                            

2015-01-14 14:50:37.360868 7f71e3994700 10 mds.0.log submit_entry also starting new segment: last = 170750/222043046, event seq = 170961

2015-01-14 14:50:38.702326 7f71e5197700  5 mds.0.1 _command_flush_journal: beginning segment expiry

2015-01-14 14:50:38.702352 7f71e5197700  6 mds.0.journal LogSegment(170750/222043046).try_to_expire
2015-01-14 14:50:38.702360 7f71e5197700  6 mds.0.journal LogSegment(170750/222043046).try_to_expire success
2015-01-14 14:50:38.702363 7f71e5197700 10 mds.0.log try_expire expired segment 170750/222043046
2015-01-14 14:50:38.702367 7f71e5197700  5 mds.0.log _expired segment 170750/222043046, 212 events 

The testdir2/file57 gets marked clean here:                                     

2015-01-14 14:50:41.259444 7f71e118f700 15 mds.0.cache.dir(10000005452)  dir 1277 >= inode 1208 now clean [inode 1000000548c [2,head] /testdir2/file57 auth v1208 s=0 n(v0 1=1+0) (iversion lock) | ptrwaiter=0 request=0 lock=0 caps=0 dirtyparent=0 dirty=1 authpin=0 0x6d29c20]
2015-01-14 14:50:41.259452 7f71e118f700 10 mds.0.cache.ino(1000000548c)  mark_clean [inode 1000000548c [2,head] /testdir2/file57 auth v1208 s=0 n(v0 1=1+0) (iversion lock) | ptrwaiter=0 request=0 lock=0 caps=0 dirtyparent=0 dirty=1 authpin=0 0x6d29c20]
2015-01-14 14:50:41.259464 7f71e118f700 10 mds.0.cache.den(10000005452 file57)  mark_clean [dentry #1/testdir2/file57 [2,head] auth (dversion lock) v=1208 inode=0x6d29c20 | request=0 lock=0 inodepin=0 dirty=1 authpin=0 0x78ee240]

2015-01-14 14:50:41.273594 7f71e5197700  5 mds.0.1 _command_flush_journal: expiry complete, expire_pos/trim_pos is now d01beba/d000000

2015-01-14 14:50:41.273622 7f71e5197700 10 mds.0.log _trim_expired_segments trimming expired 170750/0xd3c1ba6

So the weird thing is that as far as I can tell mark_clean is getting called for the only file that was operated on during the problematic segment's lifetime, and yet the item is still in the dirty_dentries list.

My wip-10368-repro branch has some extra debugging, but so far I haven't seen the bug reproduce while the extra debugging was live :-/

https://github.com/ceph/ceph/pull/4116

This certainly needs to go into hammer as well, but I'm not quite brave enough to do an insta-cherry-pick. :)

By sheer coincidence, I've hit this issue again, while no journal flushes were running at all, and much more reproducibly. I think we may have a more fundamental issue with MDLog completions (that call mark_dirty on things) getting called after MDLog has decided to expire a segment. The decision to expire a segment is made by directly checking the safe_pos of journaller, whereas the completions have to travel through a finisher. We might need to send safe_pos updates via the same finisher to ensure ordering.

Finally merged to master by commit:b25e9e130bffed82ae5dda08449ea440fe6c485c