Ceph

Sage,
Yes, I am able to reproduce this following the steps you suggested. But, this time I am hitting the issue in _collection_add though but with the same root cause. Here is the backtrace I am able to retrieve.

(gdb) bt
#0 0x00007ffff5a34f77 in GI_raise (sig=sig@entry=6) at ../nptl/sysdeps/unix/sysv/linux/raise.c:56
#1 0x00007ffff5a385e8 in _GI_abort () at abort.c:90
#2 0x00007ffff63406e5 in __gnu_cxx::_verbose_terminate_handler() () from /usr/lib/x86_64-linux-gnu/libstdc++.so.6
#3 0x00007ffff633e856 in ?? () from /usr/lib/x86_64-linux-gnu/libstdc++.so.6
#4 0x00007ffff633e883 in std::terminate() () from /usr/lib/x86_64-linux-gnu/libstdc++.so.6
#5 0x00007ffff633eaae in _cxa_throw () from /usr/lib/x86_64-linux-gnu/libstdc++.so.6
#6 0x0000000000a6b842 in ceph::_ceph_assert_fail (assertion=assertion@entry=0xb5af77 "0", file=file@entry=0xc0001b "common/lockdep.cc", line=line@entry=194,
func=func@entry=0xc001c0 <lockdep_will_lock(char const*, int)::__PRETTY_FUNCTION> "int lockdep_will_lock(const char*, int)") at common/assert.cc:77
#7 0x0000000000ae0e1f in lockdep_will_lock (name=0xba4205 "CollectionIndex::access_lock", id=<optimized out>) at common/lockdep.cc:194
#8 0x0000000000663cb4 in RWLock::get_write (this=0x1eec648) at ./common/RWLock.h:70
#9 0x0000000000876731 in WLocker (lock=..., this=<synthetic pointer>) at ./common/RWLock.h:104
#10 FileStore::lfn_link (this=this@entry=0x1f26000, c=..., newcid=..., o=..., newoid=...) at os/FileStore.cc:383
#11 0x000000000088e8fb in FileStore::_collection_add (this=this@entry=0x1f26000, c=..., oldcid=..., o=..., spos=...) at os/FileStore.cc:4672
#12 0x0000000000891cae in FileStore::_do_transaction (this=this@entry=0x1f26000, t=..., op_seq=op_seq@entry=409, trans_num=trans_num@entry=0, handle=handle@entry=0x0) at os/FileStore.cc:2397
#13 0x0000000000894919 in FileStore::_do_transactions (this=0x1f26000, tls=..., op_seq=409, handle=<optimized out>) at os/FileStore.cc:1948
#14 0x00000000008aac40 in JournalingObjectStore::journal_replay (this=this@entry=0x1f26000, fs_op_seq=<optimized out>) at os/JournalingObjectStore.cc:86
#15 0x0000000000880cb5 in FileStore::mount (this=0x1f26000) at os/FileStore.cc:1530
#16 0x000000000060aeca in OSD::do_convertfs (store=store@entry=0x1f26000) at osd/OSD.cc:1349
#17 0x00000000005f53b7 in main (argc=<optimized out>, argv=<optimized out>) at ceph_osd.cc:446
(gdb) f 10
#10 FileStore::lfn_link (this=this@entry=0x1f26000, c=..., newcid=..., o=..., newoid=...) at os/FileStore.cc:383
383 RWLock::WLocker l2((index_new.index)->access_lock);
(gdb) l
378 return r;
379 }
380 if (!exist)
381 return ENOENT;
382
383 RWLock::WLocker l2((index_new.index)>access_lock);
384
385 r = index_new->lookup(newoid, &path_new, &exist);
386 if (r < 0) {
387 assert(!m_filestore_fail_eio || r != EIO);
(gdb) p c
$1 = {static META_COLL = {static META_COLL = <same as static member of an already seen type>, str = {static npos = <optimized out>,
M_dataplus = {<std::allocator<char>> = {<_gnu_cxx::new_allocator<char>> = {<No data fields>}, <No data fields>}, M_p = 0x1ec8658 "meta"}}}, str = {static npos = <optimized out>,
_M_dataplus = {<std::allocator<char>> = {<_gnu_cxx::new_allocator<char>> = {<No data fields>}, <No data fields>}, M_p = 0x1f7ab28 "0.5_TEMP"}}}
(gdb) p newcid
$2 = {static META_COLL = {static META_COLL = <same as static member of an already seen type>, str = {static npos = <optimized out>,
_M_dataplus = {<std::allocator<char>> = {<_gnu_cxx::new_allocator<char>> = {<No data fields>}, <No data fields>}, M_p = 0x1ec8658 "meta"}}}, str = {static npos = <optimized out>,
_M_dataplus = {<std::allocator<char>> = {<_gnu_cxx::new_allocator<char>> = {<No data fields>}, <No data fields>}, M_p = 0x1edfb58 "0.5_head"}}}
(gdb) p index_new
$3 = {index = 0x1eec640}
(gdb) p index_old
$4 = {index = 0x1eecc80}
(gdb) p index_old.index
$5 = (CollectionIndex *) 0x1eecc80
(gdb) p index_new.index
$6 = (CollectionIndex *) 0x1eec640
(gdb) p *index_new.index
$7 = {_vptr.CollectionIndex = 0xf0fcd0 <vtable for HashIndex+16>, access_lock = {_vptr.RWLock = 0xeffe10 <vtable for RWLock+16>, L = {_data = {__lock = 0, _nr_readers = 0, __readers_wakeup = 0, _
__nr_readers_queued = 0, __nr_writers_queued = 0, __writer = 0, __shared = 0, __pad1 = 0, __pad2 = 0, __flags = 0}, __size = '\000' <repeats 55 times>, __align = 0}, name = 0xba4205 "Collec
static FLAT_INDEX_TAG = 0, static HASH_INDEX_TAG = 1, static HASH_INDEX_TAG_2 = 2, static HOBJECT_WITH_POOL = 3}
(gdb) p *index_old.index
$8 = {_vptr.CollectionIndex = 0xf0fcd0 <vtable for HashIndex+16>, access_lock = {_vptr.RWLock = 0xeffe10 <vtable for RWLock+16>, L = {_data = {__lock = 0, _nr_readers = 1, __readers_wakeup = 0, _
__nr_readers_queued = 0, __nr_writers_queued = 0, __writer = 0, __shared = 0, __pad1 = 0, __pad2 = 0, __flags = 0}, __size = "\000\000\000\000\001", '\000' <repeats 50 times>, __align = 429
name = 0xba4205 "CollectionIndex::access_lock", id = 52}, static FLAT_INDEX_TAG = 0, static HASH_INDEX_TAG = 1, static HASH_INDEX_TAG_2 = 2, static HOBJECT_WITH_POOL = 3}
(gdb) p newcid.c.to_str().c_str()
There is no member or method named c.
(gdb) p newcid.to_str().c_str()
Cannot evaluate function - may be inlined
(gdb) p newcid.to_str()
Cannot evaluate function -- may be inlined
(gdb) p newcid.str
$9 = {static npos = <optimized out>, _M_dataplus = {<std::allocator<char>> = {<_gnu_cxx::new_allocator<char>> = {<No data fields>}, <No data fields>}, M_p = 0x1edfb58 "0.5_head"}}
(gdb) p c.str
$10 = {static npos = <optimized out>, _M_dataplus = {<std::allocator<char>> = {<_gnu_cxx::new_allocator<char>> = {<No data fields>}, <No data fields>}, _M_p = 0x1f7ab28 "0.5_TEMP"}}

So, as I suspected, it is happening in the lfn_link() while accessing the WLock.
As you can see, the two index objects (and the CollectionIndex* they are holding) are different. But, the CollectionIndex object they contains are the same copy.

So, as index objects are different there will not be any deadlock here and I saw without lockdep enabled pgs are becoming active+clean again.

Now, I think with lockdep = 1, the assert we are getting as a result of a logical bug in lockdep logic. Here is the faulty logic I think

1. lockdep_register() will always give the same id for the same lockname (here it is 52).
2. Now, in lfn_link(), the reader lock on the same id 52 is taken first.
3. Again, on a different index object but in the same lock id (52) it is trying to acquire write lock without releasing the RLock
4. lockdep_will_lock() is checking against threaded and the lock id. But, here lock ids are same (even though for different object instance) for the same thread and it is giving assert().

Please let me know if my understanding is wrong.

The fix Sam suggested is to name the CollectionIndex lock based on the collection names. This will make lockdep happy.
Here is the pull request for the fix.

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