Ceph » RADOS

We have logs here: /a/nojha-2019-02-11_18:58:45-rados:thrash-erasure-code-wip-test-revert-distro-basic-smithi/3575122

aha:
during startup, we load pg 2.fs1, but fail to prime it from init():

2019-02-11 19:51:05.982 7f4735a22c00  0 osd.1 230 load_pgs opened 53 pgs
...
2019-02-11 19:51:05.983 7f4735a22c00 20 osd.1 230 identify_splits_and_merges 1.0 e199 to e230 pg_nums {14=8,28=18,33=28,58=38,160=48,190=58,198=68,207=78}
...
2019-02-11 19:51:05.983 7f4735a22c00 20 osd.1 230 identify_splits_and_merges 3.1fs1 e229 to e230 pg_nums {151=16,167=26,216=36,223=46,230=56}

see /a/nojha-2019-02-11_18:58:45-rados:thrash-erasure-code-wip-test-revert-distro-basic-smithi/3575122 osd.1

/a/ksirivad-2020-11-16_07:16:50-rados-wip-mgr-progress-turn-off-option-distro-basic-smithi/5630402 - no logs

/a/teuthology-2021-01-23_07:01:02-rados-master-distro-basic-gibba/5819503

/a/yuriw-2021-03-19_00:00:55-rados-wip-yuri8-testing-2021-03-18-1502-pacific-distro-basic-smithi/5978982

relevant osd.3 logs from yuriw-2021-03-19_00:00:55-rados-wip-yuri8-testing-2021-03-18-1502-pacific-distro-basic-smithi/5978982

2021-03-19T16:15:42.602+0000 7f1e7d4ea700 10 osd.3 452 split_pgs splitting pg[1.18( empty local-lis/les=379/380 n=0 ec=134/14 lis/c=379/379 les/c/f=380/380/0 sis=452) [4] r=-1 lpr=452 crt=0'0 mlcod 0'0 unknown NOTIFY mbc={}] into 1.58
2021-03-19T16:15:42.602+0000 7f1e7d4ea700 10 osd.3 452 _make_pg 1.58
2021-03-19T16:15:42.602+0000 7f1e7d4ea700  5 osd.3 pg_epoch: 452 pg[1.58(unlocked)] enter Initial
...
2021-03-19T16:15:42.609+0000 7f1e7d4ea700 10 osd.3 453 _finish_splits pg[1.58( empty local-lis/les=379/380 n=0 ec=452/14 lis/c=379/379 les/c/f=380/380/0 sis=452) [6,5] r=-1 lpr=0 crt=0'0 mlcod 0'0 unknown NOTIFY mbc={}]
2021-03-19T16:15:42.609+0000 7f1e7d4ea700 10 osd.3 pg_epoch: 452 pg[1.58( empty local-lis/les=379/380 n=0 ec=452/14 lis/c=379/379 les/c/f=380/380/0 sis=452) [6,5] r=-1 lpr=0 crt=0'0 mlcod 0'0 unknown NOTIFY mbc={}] handle_initialize
2021-03-19T16:15:42.609+0000 7f1e7d4ea700  5 osd.3 pg_epoch: 452 pg[1.58( empty local-lis/les=379/380 n=0 ec=452/14 lis/c=379/379 les/c/f=380/380/0 sis=452) [6,5] r=-1 lpr=0 crt=0'0 mlcod 0'0 unknown NOTIFY mbc={}] exit Initial 0.006560 0 0.000000
2021-03-19T16:15:42.609+0000 7f1e7d4ea700  5 osd.3 pg_epoch: 452 pg[1.58( empty local-lis/les=379/380 n=0 ec=452/14 lis/c=379/379 les/c/f=380/380/0 sis=452) [6,5] r=-1 lpr=0 crt=0'0 mlcod 0'0 unknown NOTIFY mbc={}] enter Reset
2021-03-19T16:15:42.609+0000 7f1e7d4ea700 20 osd.3 pg_epoch: 452 pg[1.58( empty local-lis/les=379/380 n=0 ec=452/14 lis/c=379/379 les/c/f=380/380/0 sis=452) [6,5] r=-1 lpr=0 crt=0'0 mlcod 0'0 unknown NOTIFY mbc={}] set_last_peering_reset 452
2021-03-19T16:15:42.609+0000 7f1e7d4ea700 10 osd.3 pg_epoch: 452 pg[1.58( empty local-lis/les=379/380 n=0 ec=452/14 lis/c=379/379 les/c/f=380/380/0 sis=452) [6,5] r=-1 lpr=452 crt=0'0 mlcod 0'0 unknown NOTIFY mbc={}] Clearing blocked outgoing recovery messages
2021-03-19T16:15:42.609+0000 7f1e7d4ea700 10 osd.3 pg_epoch: 452 pg[1.58( empty local-lis/les=379/380 n=0 ec=452/14 lis/c=379/379 les/c/f=380/380/0 sis=452) [6,5] r=-1 lpr=452 crt=0'0 mlcod 0'0 unknown NOTIFY mbc={}] Not blocking outgoing recovery messages
2021-03-19T16:15:42.609+0000 7f1e7d4ea700 10 osd.3 pg_epoch: 452 pg[1.58( empty local-lis/les=379/380 n=0 ec=452/14 lis/c=379/379 les/c/f=380/380/0 sis=452) [6,5] r=-1 lpr=452 crt=0'0 mlcod 0'0 unknown NOTIFY mbc={}] null
2021-03-19T16:15:42.609+0000 7f1e7d4ea700 15 osd.3 453 enqueue_peering_evt 1.58 epoch_sent: 452 epoch_requested: 452 NullEvt
2021-03-19T16:15:42.609+0000 7f1e7d4ea700 20 osd.3 op_wq(0) _enqueue OpSchedulerItem(1.58 PGPeeringEvent(epoch_sent: 452 epoch_requested: 452 NullEvt) prio 255 cost 10 e452)
2021-03-19T16:15:42.609+0000 7f1e7d4ea700 10 osd.3:0.register_and_wake_split_child 1.58 0x561e34601000
...
2021-03-19T16:15:42.611+0000 7f1e7d4ea700 -1 /home/jenkins-build/build/workspace/ceph-dev-new-build/ARCH/x86_64/AVAILABLE_ARCH/x86_64/AVAILABLE_DIST/centos8/DIST/centos8/MACHINE_SIZE/gigantic/release/16.1.0-945-g14d80dbf/rpm/el8/BUILD/ceph-16.1.0-945-g14d80dbf/src/osd/OSD.cc: In function 'void OSDShard::register_and_wake_split_child(PG*)' thread 7f1e7d4ea700 time 2021-03-19T16:15:42.610408+0000
/home/jenkins-build/build/workspace/ceph-dev-new-build/ARCH/x86_64/AVAILABLE_ARCH/x86_64/AVAILABLE_DIST/centos8/DIST/centos8/MACHINE_SIZE/gigantic/release/16.1.0-945-g14d80dbf/rpm/el8/BUILD/ceph-16.1.0-945-g14d80dbf/src/osd/OSD.cc: 10551: FAILED ceph_assert(p != pg_slots.end())

 ceph version 16.1.0-945-g14d80dbf (14d80dbf937b38fba622cec4b41998d0bd128816) pacific (rc)
 1: (ceph::__ceph_assert_fail(char const*, char const*, int, char const*)+0x158) [0x561e1b13475a]
 2: ceph-osd(+0x568974) [0x561e1b134974]
 3: (OSDShard::register_and_wake_split_child(PG*)+0x810) [0x561e1b26f670]
 4: (OSD::_finish_splits(std::set<boost::intrusive_ptr<PG>, std::less<boost::intrusive_ptr<PG> >, std::allocator<boost::intrusive_ptr<PG> > >&)+0x2ad) [0x561e1b26f97d]
 5: (Context::complete(int)+0xd) [0x561e1b273e0d]
 6: (OSD::ShardedOpWQ::_process(unsigned int, ceph::heartbeat_handle_d*)+0xadc) [0x561e1b258d7c]
 7: (ShardedThreadPool::shardedthreadpool_worker(unsigned int)+0x5c4) [0x561e1b8bf764]
 8: (ShardedThreadPool::WorkThreadSharded::entry()+0x14) [0x561e1b8c2404]
 9: /lib64/libpthread.so.0(+0x82de) [0x7f1ea1b2c2de]
 10: clone()

/a/yuriw-2021-03-25_20:03:40-rados-wip-yuri8-testing-2021-03-25-1042-pacific-distro-basic-smithi/5999016

https://pulpito.ceph.com/gregf-2021-06-03_20:03:04-rados-pacific-mmonjoin-leader-testing-distro-basic-smithi/6150351/

2021-07-28T09:04:05.163+0000 7fa0aef14700 20 bluestore(/var/lib/ceph/osd/ceph-1).collection(meta 0x5595b8d4f680)  r -2 v.len 0
2021-07-28T09:04:05.163+0000 7fa0aef14700 10 bluestore(/var/lib/ceph/osd/ceph-1) read meta #-1:afd56935:::osdmap.368:0# 0x0~0 = -2
2021-07-28T09:04:05.163+0000 7fa0aef14700 -1 osd.1 403 failed to load OSD map for epoch 368, got 0 bytes
2021-07-28T09:04:05.163+0000 7fa0aef14700 20 osd.1 403 advance_pg missing map 368
2021-07-28T09:04:05.163+0000 7fa0aef14700 20 osd.1 403 get_map 369 - loading and decoding 0x5595b9761700
2021-07-28T09:04:05.163+0000 7fa0ae713700 -1 /build/ceph-17.0.0-6461-g3cfb73ec/src/osd/OSD.cc: In function 'void OSDShard::register_and_wake_split_child(PG*)' thread 7fa0ae713700 time 2021-07-28T09:04:05.
157796+0000
/build/ceph-17.0.0-6461-g3cfb73ec/src/osd/OSD.cc: 10748: FAILED ceph_assert(p != pg_slots.end())

 ceph version 17.0.0-6461-g3cfb73ec (3cfb73ec2f3bd8e1d6621a767f6ab72f21d849ae) quincy (dev)
 1: (ceph::__ceph_assert_fail(char const*, char const*, int, char const*)+0x14f) [0x5595b37992c0]
 2: ceph-osd(+0xc184d2) [0x5595b37994d2]
 3: (OSDShard::register_and_wake_split_child(PG*)+0x7d0) [0x5595b388c110]
 4: (OSD::_finish_splits(std::set<boost::intrusive_ptr<PG>, std::less<boost::intrusive_ptr<PG> >, std::allocator<boost::intrusive_ptr<PG> > >&)+0x3af) [0x5595b38ad36f]
 5: (Context::complete(int)+0xd) [0x5595b38b20ed]
 6: (OSD::ShardedOpWQ::_process(unsigned int, ceph::heartbeat_handle_d*)+0x953) [0x5595b3891323]
 7: (ShardedThreadPool::shardedthreadpool_worker(unsigned int)+0x403) [0x5595b3fe0d73]
 8: (ShardedThreadPool::WorkThreadSharded::entry()+0x14) [0x5595b3fe3b94]
 9: (Thread::_entry_func(void*)+0xd) [0x5595b3fd351d]
 10: /lib/x86_64-linux-gnu/libpthread.so.0(+0x9609) [0x7fa0cb93b609]
 11: clone()

/a/kchai-2021-07-28_08:37:00-rados-wip-kefu-testing-2021-07-28-1257-distro-basic-smithi/6297932/

/a/yuriw-2021-08-06_16:31:19-rados-wip-yuri-master-8.6.21-distro-basic-smithi/6324576

Some possibly helpful hints:
1. In "my" specific instance, the pg address handed over to register_and_wake_split_child() was null.
2. The locking in the calling function (_finish_splits()) took a long time

more useful debug logging being added in https://github.com/ceph/ceph/pull/42965

Ronen Friedman wrote:

Some possibly helpful hints:
1. In "my" specific instance, the pg address handed over to register_and_wake_split_child() was null.
2. The locking in the calling function (_finish_splits()) took a long time

Can you provide a link to the failed run?

Neha Ojha wrote:

Can you provide a link to the failed run?

Trying to reproduce.

Although there was a report from Telemetry, we still need more logs (read: a reoccurance at Sepia) which, hopefully, throw some extra light as Ronen introduced more logs into the register_and_wake_split_child().

/a/yuriw-2022-09-15_17:53:16-rados-quincy-release-distro-default-smithi/7034166

I'm hitting this assertion on 16.2.11 on one of my OSDs, here's my logs:

2023-03-28T20:42:28.660+1100 7f5c81aa4700 1 ./src/osd/OSD.cc: In function 'void OSDShard::register_and_wake_split_child(PG*)' thread 7f5c81aa4700 time 2023-03-28T20:42:28.653968+1100
./src/osd/OSD.cc: 10862: FAILED ceph_assert(slot>waiting_for_split.count(epoch))

ceph version 16.2.11 (578f8e68e41b0a98523d0045ef6db90ce6f2e5ab) pacific (stable)
 1: (ceph::__ceph_assert_fail(char const*, char const*, int, char const*)+0x124) [0x558c594172ea]
 2: /usr/bin/ceph-osd(+0xac3475) [0x558c59417475]
 3: (OSDShard::register_and_wake_split_child(PG*)+0x354) [0x558c594de204]
 4: (OSD::_finish_splits(std::set<boost::intrusive_ptr<PG>, std::less<boost::intrusive_ptr<PG> >, std::allocator<boost::intrusive_ptr<PG> > >&)+0xe6) [0x558c594e1ac6]
 5: (Context::complete(int)+0x9) [0x558c5951bf19]
 6: (OSD::ShardedOpWQ::handle_oncommits(std::__cxx11::list<Context*, std::allocator<Context*> >&)+0x24) [0x558c5952d4f4]
 7: (OSD::ShardedOpWQ::_process(unsigned int, ceph::heartbeat_handle_d*)+0x256b) [0x558c59501ceb]
 8: (ShardedThreadPool::shardedthreadpool_worker(unsigned int)+0x41a) [0x558c59bafaba]
 9: (ShardedThreadPool::WorkThreadSharded::entry()+0x10) [0x558c59bb2090]
 10: /lib/x86_64-linux-gnu/libpthread.so.0(+0x7ea7) [0x7f5c9e430ea7]
 11: clone()

2023-03-28T20:42:28.668+1100 7f5c81aa4700 -1 ** Caught signal (Aborted) *
in thread 7f5c81aa4700 thread_name:tp_osd_tp

ceph version 16.2.11 (578f8e68e41b0a98523d0045ef6db90ce6f2e5ab) pacific (stable)
 1: /lib/x86_64-linux-gnu/libpthread.so.0(+0x13140) [0x7f5c9e43c140]
 2: gsignal()
 3: abort()
 4: (ceph::__ceph_assert_fail(char const*, char const*, int, char const*)+0x16e) [0x558c59417334]
 5: /usr/bin/ceph-osd(+0xac3475) [0x558c59417475]
 6: (OSDShard::register_and_wake_split_child(PG*)+0x354) [0x558c594de204]
 7: (OSD::_finish_splits(std::set<boost::intrusive_ptr<PG>, std::less<boost::intrusive_ptr<PG> >, std::allocator<boost::intrusive_ptr<PG> > >&)+0xe6) [0x558c594e1ac6]
 8: (Context::complete(int)+0x9) [0x558c5951bf19]
 9: (OSD::ShardedOpWQ::handle_oncommits(std::__cxx11::list<Context*, std::allocator<Context*> >&)+0x24) [0x558c5952d4f4]
 10: (OSD::ShardedOpWQ::_process(unsigned int, ceph::heartbeat_handle_d*)+0x256b) [0x558c59501ceb]
 11: (ShardedThreadPool::shardedthreadpool_worker(unsigned int)+0x41a) [0x558c59bafaba]
 12: (ShardedThreadPool::WorkThreadSharded::entry()+0x10) [0x558c59bb2090]
 13: /lib/x86_64-linux-gnu/libpthread.so.0(+0x7ea7) [0x7f5c9e430ea7]
 14: clone()
 NOTE: a copy of the executable, or `objdump -rdS <executable>` is needed to interpret this.

--- begin dump of recent events ---

Hello Nathan!

Do you have a log or a coredump by any chance?