Ceph » bluestore

Dan van der Ster wrote:

We've just seen this crash in the wild running 15.2.14. Maybe a dup of #50788?

I'm pretty sure it is...

Aren't there any indications of a recent PG split?

Igor Fedotov wrote:

Dan van der Ster wrote:

We've just seen this crash in the wild running 15.2.14. Maybe a dup of #50788?

I'm pretty sure it is...

Aren't there any indications of a recent PG split?

Not recently AFAIK... we have nopgchange set on all the pools.

More context: the cluster was upgraded from 14.2.20 to 15.2.14 two weeks ago. We've never seen this before today; it happened only once on only this OSD so far.

In frame 7 I can print the Onode. Some of the vals look quite strange (but I don't know if that's normal):

(gdb) f
#7  ~intrusive_ptr (this=0x55aa49c74c20, __in_chrg=<optimized out>)
    at /usr/src/debug/ceph-15.2.14/build/boost/include/boost/smart_ptr/intrusive_ptr.hpp:98
98            if( px != 0 ) intrusive_ptr_release( px );
(gdb) list
93            if( px != 0 ) intrusive_ptr_add_ref( px );
94        }
95    
96        ~intrusive_ptr()
97        {
98            if( px != 0 ) intrusive_ptr_release( px );
99        }
100    
101    #if !defined(BOOST_NO_MEMBER_TEMPLATES) || defined(BOOST_MSVC6_MEMBER_TEMPLATES)
102    
(gdb) p px
$11 = (BlueStore::Onode *) 0x55aa7ea2b440
(gdb) p *px
$12 = {nref = {<std::__atomic_base<int>> = {static _S_alignment = 4, _M_i = 1024138560}, 
    static is_always_lock_free = true}, c = 0x200, oid = {hobj = {static POOL_META = -1, 
      static POOL_TEMP_START = -2, oid = {
        name = <error reading variable: Cannot access memory at address 0x55aaffffffe7>}, 
      snap = {val = 8295752894954156584}, hash = 543712117, max = 102, 
      nibblewise_key_cache = 544370464, hash_reverse_bits = 1701996900, pool = 521610949731, 
      nspace = "cta-cristina", key = ""}, generation = 18446744073709551615, shard_id = {
      id = -1 '\377', static NO_SHARD = {id = -1 '\377', 
        static NO_SHARD = <same as static member of an already seen type>}}, max = false, 
    static NO_GEN = 18446744073709551615}, key = "", 
  lru_item = {<boost::intrusive::generic_hook<(boost::intrusive::algo_types)0, boost::intrusive::list_node_traits<void*>, boost::intrusive::member_tag, (boost::intrusive::link_mode_type)1, (boost::intrusive::base_hook_type)0>> = {<boost::intrusive::list_node<void*>> = {next_ = 0x0, 
        prev_ = 0x0}, <boost::intrusive::hook_tags_definer<boost::intrusive::generic_hook<(boost::intrusive::algo_types)0, boost::intrusive::list_node_traits<void*>, boost::intrusive::member_tag, (boost::intrusive::link_mode_type)1, (boost::intrusive::base_hook_type)0>, 0>> = {<No data fields>}, <No data fields>}, <No data fields>}, onode = {nid = 0, size = 0, 
    attrs = std::map with 0 elements, 
    extent_map_shards = std::vector of length 0, capacity 0, expected_object_size = 0, 
    expected_write_size = 0, alloc_hint_flags = 0, flags = 0 '\000'}, exists = false, 
  cached = false, pinned = {_M_base = {static _S_alignment = 1, _M_i = false}, 
    static is_always_lock_free = true}, extent_map = {onode = 0x55aa7ea2b440, 
    extent_map = {<boost::intrusive::set_impl<boost::intrusive::bhtraits<BlueStore::Extent, boost::intrusive::rbtree_node_traits<void*, true>, (boost::intrusive::link_mode_type)1, boost::intrusive::dft_tag, 3>, void, void, unsigned long, true, void>> = {<boost::intrusive::bstree_impl<boost::intrusive::bhtraits<BlueStore::Extent, boost::intrusive::rbtree_node_traits<void*, true>, (boost::intrusive::link_mode_type)1, boost::intrusive::dft_tag, 3>, void, void, unsigned long, true, (boost::intrusive::algo_types)5, void>> = {<boost::intrusive::bstbase<boost::intrusive::bhtraits<BlueStore::Extent, boost::intrusive::rbtree_node_traits<void*, true>, (boost::intrusive::link_mode_type)1, boost::intrusive::dft_tag, 3>, void, void, true, unsigned long, (boost::intrusive::algo_types)5, void>> = {<boost::intrusive::bstbase_hack<boost::intrusive::bhtraits<BlueStore::Extent, boost::intrusive::rbtree_node_traits<void*, true>, (boost::intrusive::link_mode_type)1, boost::intrusive::dft_tag, 3>, void, void, true, unsigned long, (boost::intrusive::algo_types)5, void>> = {<boost::intrusive::detail::size_holder<true, unsigned long, void>> = {
                static constant_time_size = <optimized out>, 
                size_ = 0}, <boost::intrusive::bstbase2<boost::intrusive::bhtraits<BlueStore::Extent, boost::intrusive::rbtree_node_traits<void*, true>, (boost::intrusive::link_mode_type)1, boost::intrusive::dft_tag, 3>, void, void, (boost::intrusive::algo_types)5, void>> = {<boost::intrusive::detail::ebo_functor_holder<boost::intrusive::tree_value_compare<BlueStore::Extent*, std::less<BlueStore::Extent>, boost::move_detail::identity<BlueStore::Extent>, bool, true>, void, false>> = {<boost::intrusive::tree_value_compare<BlueStore::Extent*, std::less<BlueStore::Extent>, boost::move_detail::identity<BlueStore::Extent>, bool, true>> = {<boost::intrusive::detail::ebo_functor_holder<std::less<BlueStore::Extent>, void, false>> = {<std::less<BlueStore::Extent>> = {<std::binary_function<BlueStore::Extent, BlueStore::Extent, bool>> = {<No data fields>}, <No data fields>}, <No data fields>}, <No data fields>}, <No data fields>}, <boost::intrusive::bstbase3<boost::intrusive::bhtraits<BlueStore::Extent, boost::intrusive::rbtree_node_traits<void*, true>, (boost::intrusive::link_mode_type)1, boost::intrusive::dft_tag, 3>, (boost::intrus---Type <return> to continue, or q <return> to quit---
ive::algo_types)5, void>> = {static safemode_or_autounlink = <optimized out>, 
                  static stateful_value_traits = <optimized out>, 
                  static has_container_from_iterator = <optimized out>, 
                  holder = {<boost::intrusive::bhtraits<BlueStore::Extent, boost::intrusive::rbtree_node_traits<void*, true>, (boost::intrusive::link_mode_type)1, boost::intrusive::dft_tag, 3>> = {<boost::intrusive::bhtraits_base<BlueStore::Extent, boost::intrusive::compact_rbtree_node<void*>*, boost::intrusive::dft_tag, 3>> = {<No data fields>}, 
                      static link_mode = boost::intrusive::safe_link}, 
                    root = {<boost::intrusive::compact_rbtree_node<void*>> = {parent_ = 0x0, 
                        left_ = 0x55aa7ea2b540, 
                        right_ = 0x55aa7ea2b540}, <No data fields>}}}, <No data fields>}, <No data fields>}, <No data fields>}, static constant_time_size = true, 
          static stateful_value_traits = <optimized out>, 
          static safemode_or_autounlink = true}, 
        static constant_time_size = true}, <No data fields>}, 
    spanning_blob_map = std::map with 0 elements, 
    shards = std::vector of length 0, capacity 0, inline_bl = {_buffers = {_root = {
          next = 0x55aa7ea2b5c0}, _tail = 0x55aa7ea2b5c0}, 
      _carriage = 0x55a9f17a8d90 <ceph::buffer::v15_2_0::list::always_empty_bptr>, _len = 0, 
      _num = 0, static always_empty_bptr = {_raw = 0x0, _off = 0, _len = 0}}, 
    needs_reshard_begin = 0, needs_reshard_end = 0}, 
  flushing_count = {<std::__atomic_base<int>> = {static _S_alignment = 4, _M_i = 0}, 
    static is_always_lock_free = true}, waiting_count = {<std::__atomic_base<int>> = {
      static _S_alignment = 4, _M_i = 0}, static is_always_lock_free = true}, 
  flush_lock = {<std::__mutex_base> = {_M_mutex = {__data = {__lock = 0, __count = 0, 
          __owner = 0, __nusers = 0, __kind = 0, __spins = 0, __elision = 0, __list = {
            __prev = 0x0, __next = 0x0}}, __size = '\000' <repeats 39 times>, 
        __align = 0}}, <No data fields>}, flush_cond = {_M_cond = {__data = {__lock = 1, 
        __futex = 0, __total_seq = 18446744073709551615, __wakeup_seq = 0, __woken_seq = 0, 
        __mutex = 0x0, __nwaiters = 0, __broadcast_seq = 0}, 
      __size = "\001\000\000\000\000\000\000\000\377\377\377\377\377\377\377\377", '\000' <repeats 31 times>, __align = 1}}}
(gdb) 

E.g. down in frame 5, `c` has address 0x200 ?!!

(gdb) f
#5  BlueStore::Onode::put (this=0x55aa7ea2b440)
    at /usr/src/debug/ceph-15.2.14/src/os/bluestore/BlueStore.cc:3588
3588          ocs->lock.lock();
(gdb) list
3583        ocs->lock.lock();
3584        // It is possible that during waiting split_cache moved us to different OnodeCacheShard.
3585        while (ocs != c->get_onode_cache()) {
3586          ocs->lock.unlock();
3587          ocs = c->get_onode_cache();
3588          ocs->lock.lock();
3589        }
3590        bool need_unpin = pinned;
3591        pinned = pinned && nref > 2; // intentionally use > not >= as we have
3592                                     // +1 due to pinned state
(gdb) p c
$16 = (BlueStore::Collection *) 0x200
(gdb) p *c
Cannot access memory at address 0x200

according to https://lists.ceph.io/hyperkitty/list/ceph-users@ceph.io/message/PPWIFPEI3EVBU3GQYYO6ABGF23WR5SGZ/ this is not resolved yet, could this be reopened, please?

4) Quincy case from Telemetry: https://tracker.ceph.com/issues/56382

We have almost daily crashes on our octopus cluster, which are also reported via telemetry, which look like this bug, could you confirm that these are the same, or if you need more information, just ask. I'm really waiting on a patch for this:

{
    "backtrace": [
        "(()+0x12980) [0x7f269ac06980]",
        "(ceph::buffer::v15_2_0::ptr::release()+0x26) [0x55fc3e524206]",
        "(BlueStore::Onode::put()+0x1c1) [0x55fc3e192a71]",
        "(std::_Rb_tree<boost::intrusive_ptr<BlueStore::Onode>, boost::intrusive_ptr<BlueStore::Onode>, std::_Identity<boost::intrusive_ptr<BlueStore::Onode> >, std::less<boost::intrusive_ptr<BlueStore::Onode> >, std::allocator<boost::intrusive_ptr<BlueStore::Onode> > >::_M_erase(std::_Rb_tree_node<boost::intrusive_ptr<BlueStore::Onode> >*)+0x2d) [0x55fc3e248a0d]",
        "(std::_Rb_tree<boost::intrusive_ptr<BlueStore::Onode>, boost::intrusive_ptr<BlueStore::Onode>, std::_Identity<boost::intrusive_ptr<BlueStore::Onode> >, std::less<boost::intrusive_ptr<BlueStore::Onode> >, std::allocator<boost::intrusive_ptr<BlueStore::Onode> > >::_M_erase(std::_Rb_tree_node<boost::intrusive_ptr<BlueStore::Onode> >*)+0x1b) [0x55fc3e2489fb]",
        "(BlueStore::TransContext::~TransContext()+0x124) [0x55fc3e248b54]",
        "(BlueStore::_txc_finish(BlueStore::TransContext*)+0x4b8) [0x55fc3e1d01b8]",
        "(BlueStore::_txc_state_proc(BlueStore::TransContext*)+0x24c) [0x55fc3e1d1b7c]",
        "(BlueStore::_kv_finalize_thread()+0x48c) [0x55fc3e21b58c]",
        "(BlueStore::KVFinalizeThread::entry()+0xd) [0x55fc3e24d09d]",
        "(()+0x76db) [0x7f269abfb6db]",
        "(clone()+0x3f) [0x7f269999b61f]" 
    ],
    "ceph_version": "15.2.17",
    "crash_id": "2022-10-21T16:26:38.286992Z_ba5ffc75-58c3-45fc-9cda-950256b5efca",
    "entity_name": "osd.127",
    "os_id": "ubuntu",
    "os_name": "Ubuntu",
    "os_version": "18.04.6 LTS (Bionic Beaver)",
    "os_version_id": "18.04",
    "process_name": "ceph-osd",
    "stack_sig": "b2e4aac01a4b8acbb3878c39b0f5b1269edcccb6a90435e54b6958716a9e703e",
    "timestamp": "2022-10-21T16:26:38.286992Z",
    "utsname_hostname": "ceph-osd08",
    "utsname_machine": "x86_64",
    "utsname_release": "5.4.0-107-generic",
    "utsname_sysname": "Linux",
    "utsname_version": "#121~18.04.1-Ubuntu SMP Thu Mar 24 17:21:33 UTC 2022" 
}

Hi Sven,

Thanks for reporting telemetry! The issue you reported is tracked in https://tracker.ceph.com/issues/56200, which is marked as a duplicate to this tracker (https://tracker.ceph.com/issues/53002), so indeed they are the same.
Looks like the Octopus backport is already merged, but there is another PR (https://github.com/ceph/ceph/pull/47702) which is still under review and not yet merged to main.

Regards,
Yaarit

(gdb) bt
#0 0x00007fc82cdb64aa in tc_newarray () from /lib64/libtcmalloc.so.4
#1 0x000055f6876050ba in ceph::buffer::v15_2_0::ptr_node::create<ceph::buffer::v15_2_0::ptr_node const&> ()
at /usr/src/debug/ceph-15.2.13-branch_2212260918.el8.x86_64/src/include/buffer.h:411
#2 ceph::buffer::v15_2_0::list::append (this=this@entry=0x55f6b308ceb8, bl=...) at /usr/src/debug/ceph-15.2.13-branch_2212260918.el8.x86_64/src/common/buffer.cc:1424
#3 0x000055f687150491 in ceph::encode (bl=..., s=...) at /usr/src/debug/ceph-15.2.13-branch_2212260918.el8.x86_64/src/include/encoding.h:282
#4 ceph::os::Transaction::encode (this=this@entry=0x7fc8039c7440, bl=...) at /usr/src/debug/ceph-15.2.13-branch_2212260918.el8.x86_64/src/os/Transaction.h:1267
#5 0x000055f687137698 in ceph::os::encode (features=0, bl=..., c=...) at /usr/src/debug/ceph-15.2.13-branch_2212260918.el8.x86_64/src/os/Transaction.h:1293
#6 ReplicatedBackend::generate_subop (this=0x55f6956f8180, soid=..., at_version=..., tid=10598176, reqid=..., pg_trim_to=..., min_last_complete_ondisk=..., new_temp_oid=...,
discard_temp_oid=..., log_entries=..., hset_hist=std::optional<pg_hit_set_history_t> [no contained value], op_t=..., peer=..., pinfo=...)
at /usr/src/debug/ceph-15.2.13-branch_2212260918.el8.x86_64/src/osd/ReplicatedBackend.cc:968
#7 0x000055f687138188 in ReplicatedBackend::issue_op (this=0x55f6956f8180, soid=..., at_version=..., tid=<optimized out>, reqid=..., pg_trim_to=..., min_last_complete_ondisk=...,
new_temp_oid=..., discard_temp_oid=..., log_entries=..., hset_hist=..., op=<optimized out>, op_t=...)
at /usr/src/debug/ceph-15.2.13-branch_2212260918.el8.x86_64/src/osd/ReplicatedBackend.cc:1028
#8 0x000055f68713ad14 in ReplicatedBackend::submit_transaction (this=0x55f6956f8180, soid=..., delta_stats=..., at_version=..., _t=..., trim_to=..., min_last_complete_ondisk=...,
_log_entries=std::vector of length 1, capacity 1 = {...}, hset_history=std::optional<pg_hit_set_history_t> [no contained value], on_all_commit=0x55f6bfd47360, tid=10598176,
reqid=..., orig_op=...) at /usr/include/c++/8/ext/aligned_buffer.h:76
#9 0x000055f686f07ce0 in PrimaryLogPG::issue_repop (this=0x55f6961c4000, repop=0x55f696e73980, ctx=0x55f6dc76d200)
at /usr/src/debug/ceph-15.2.13-branch_2212260918.el8.x86_64/src/osd/PeeringState.h:2292
#10 0x000055f686f64c5a in PrimaryLogPG::execute_ctx (this=0x55f6961c4000, ctx=<optimized out>)
at /usr/src/debug/ceph-15.2.13-branch_2212260918.el8.x86_64/src/osd/PrimaryLogPG.cc:4166
#11 0x000055f686f69004 in PrimaryLogPG::do_op (this=0x55f6961c4000, op=...) at /usr/src/debug/ceph-15.2.13-branch_2212260918.el8.x86_64/src/osd/PrimaryLogPG.cc:2381
#12 0x000055f686f76585 in PrimaryLogPG::do_request (this=0x55f6961c4000, op=..., handle=...) at /usr/src/debug/ceph-15.2.13-branch_2212260918.el8.x86_64/src/osd/PrimaryLogPG.cc:1779
#13 0x000055f686df35d9 in OSD::dequeue_op (this=this@entry=0x55f692652000, pg=..., op=..., handle=...)
at /usr/src/debug/ceph-15.2.13-branch_2212260918.el8.x86_64/src/osd/OSD.cc:9754
#14 0x000055f68705b378 in ceph::osd::scheduler::PGOpItem::run (this=<optimized out>, osd=0x55f692652000, sdata=<optimized out>, pg=..., handle=...)
at /usr/src/debug/ceph-15.2.13-branch_2212260918.el8.x86_64/src/osd/PG.h:627
#15 0x000055f686e0ff4b in ceph::osd::scheduler::OpSchedulerItem::run (handle=..., pg=..., sdata=<optimized out>, osd=<optimized out>, this=0x7fc8039c83b0)
at /usr/include/c++/8/bits/unique_ptr.h:345
#16 OSD::ShardedOpWQ::_process (this=<optimized out>, thread_index=<optimized out>, hb=<optimized out>)
at /usr/src/debug/ceph-15.2.13-branch_2212260918.el8.x86_64/src/osd/OSD.cc:10788
#17 0x000055f687465644 in ShardedThreadPool::shardedthreadpool_worker (this=0x55f692652a28, thread_index=11)
at /usr/src/debug/ceph-15.2.13-branch_2212260918.el8.x86_64/src/common/WorkQueue.cc:311
#18 0x000055f6874682a4 in ShardedThreadPool::WorkThreadSharded::entry (this=<optimized out>) at /usr/src/debug/ceph-15.2.13-branch_2212260918.el8.x86_64/src/common/WorkQueue.h:715
#19 0x00007fc82c26014a in start_thread () from /lib64/libpthread.so.0
#20 0x00007fc82b3c9dc3 in clone () from /lib64/libc.so.6

ceph_version 15.2.13
We've just seen some crash running 15.2.13