From 8a9c1b57d9fbf537a2a7283539bb0dc81dc42b10 Mon Sep 17 00:00:00 2001 From: NitzanMordhai Date: Wed, 28 Sep 2022 13:36:23 +0000 Subject: [PATCH] OSD: Adding debugging messages to identify deadlock during OSD start The OSD log won't show many messages during the consume map, moving OSDmap services from header files and adding more debug messages. Signed-off-by: Nitzan Mordechai (cherry picked from commit 575034565ca498ee9f859bef06bde8e3a6ddd9b3) --- src/osd/OSD.cc | 68 +++++++++++++++++++++++++++++++++++++++++++++++--- src/osd/OSD.h | 35 +++----------------------- 2 files changed, 68 insertions(+), 35 deletions(-) diff --git a/src/osd/OSD.cc b/src/osd/OSD.cc index 267aa031d3d6f..8d95013542769 100644 --- a/src/osd/OSD.cc +++ b/src/osd/OSD.cc @@ -353,12 +353,18 @@ void OSDService::identify_splits_and_merges( set> *split_children, set> *merge_pgs) { + dout(20) << __func__ << " " << pgid << " e" << old_map->get_epoch() + << " to e" << new_map->get_epoch() << dendl; if (!old_map->have_pg_pool(pgid.pool())) { + dout(20) << __func__ << " " << pgid << " pool " << pgid.pool() + << " does not exist in old map" << dendl; return; } int old_pgnum = old_map->get_pg_num(pgid.pool()); auto p = osd->pg_num_history.pg_nums.find(pgid.pool()); if (p == osd->pg_num_history.pg_nums.end()) { + dout(20) << __func__ << " " << pgid << " pool " << pgid.pool() + << " has no history" << dendl; return; } dout(20) << __func__ << " " << pgid << " e" << old_map->get_epoch() @@ -559,6 +565,51 @@ void OSDService::activate_map() agent_cond.notify_all(); } +OSDMapRef OSDService::get_nextmap_reserved() { + std::lock_guard l(pre_publish_lock); + + epoch_t e = next_osdmap->get_epoch(); + + std::map::iterator i = + map_reservations.insert(std::make_pair(e, 0)).first; + i->second++; + dout(20) << __func__ << " map_reservations: " << map_reservations << dendl; + return next_osdmap; +} + +/// releases reservation on map +void OSDService::release_map(OSDMapRef osdmap) { + std::lock_guard l(pre_publish_lock); + dout(20) << __func__ << " epoch: " << osdmap->get_epoch() << dendl; + std::map::iterator i = + map_reservations.find(osdmap->get_epoch()); + ceph_assert(i != map_reservations.end()); + ceph_assert(i->second > 0); + if (--(i->second) == 0) { + map_reservations.erase(i); + } + if (pre_publish_waiter) { + dout(20) << __func__ << " notify all." << dendl; + pre_publish_cond.notify_all(); + } +} + +/// blocks until there are no reserved maps prior to next_osdmap +void OSDService::await_reserved_maps() { + std::unique_lock l{pre_publish_lock}; + dout(20) << __func__ << " epoch:" << next_osdmap->get_epoch() << dendl; + + ceph_assert(next_osdmap); + pre_publish_waiter++; + pre_publish_cond.wait(l, [this] { + auto i = map_reservations.cbegin(); + return (i == map_reservations.cend() || + i->first >= next_osdmap->get_epoch()); + }); + pre_publish_waiter--; + dout(20) << __func__ << " done " << pre_publish_waiter << dendl; +} + void OSDService::request_osdmap_update(epoch_t e) { osd->osdmap_subscribe(e, false); @@ -1045,6 +1096,8 @@ float OSDService::compute_adjusted_ratio(osd_stat_t new_stat, float *pratio, void OSDService::send_message_osd_cluster(int peer, Message *m, epoch_t from_epoch) { + dout(20) << __func__ << " " << m->get_type_name() << " to osd." << peer + << " from_epoch " << from_epoch << dendl; OSDMapRef next_map = get_nextmap_reserved(); // service map is always newer/newest ceph_assert(from_epoch <= next_map->get_epoch()); @@ -1069,6 +1122,7 @@ void OSDService::send_message_osd_cluster(int peer, Message *m, epoch_t from_epo void OSDService::send_message_osd_cluster(std::vector>& messages, epoch_t from_epoch) { + dout(20) << __func__ << " from_epoch " << from_epoch << dendl; OSDMapRef next_map = get_nextmap_reserved(); // service map is always newer/newest ceph_assert(from_epoch <= next_map->get_epoch()); @@ -1093,6 +1147,8 @@ void OSDService::send_message_osd_cluster(std::vector>& } ConnectionRef OSDService::get_con_osd_cluster(int peer, epoch_t from_epoch) { + dout(20) << __func__ << " to osd." << peer + << " from_epoch " << from_epoch << dendl; OSDMapRef next_map = get_nextmap_reserved(); // service map is always newer/newest ceph_assert(from_epoch <= next_map->get_epoch()); @@ -1115,6 +1171,8 @@ ConnectionRef OSDService::get_con_osd_cluster(int peer, epoch_t from_epoch) pair OSDService::get_con_osd_hb(int peer, epoch_t from_epoch) { + dout(20) << __func__ << " to osd." << peer + << " from_epoch " << from_epoch << dendl; OSDMapRef next_map = get_nextmap_reserved(); // service map is always newer/newest ceph_assert(from_epoch <= next_map->get_epoch()); @@ -1984,6 +2042,7 @@ void OSDService::prune_sent_ready_to_merge(const OSDMapRef& osdmap) dout(10) << __func__ << " " << *i << dendl; i = sent_ready_to_merge_source.erase(i); } else { + dout(20) << __func__ << " exist " << *i << dendl; ++i; } } @@ -8925,7 +8984,7 @@ void OSD::consume_map() { ceph_assert(ceph_mutex_is_locked(osd_lock)); auto osdmap = get_osdmap(); - dout(7) << "consume_map version " << osdmap->get_epoch() << dendl; + dout(20) << __func__ << " version " << osdmap->get_epoch() << dendl; /** make sure the cluster is speaking in SORTBITWISE, because we don't * speak the older sorting version any more. Be careful not to force @@ -8935,11 +8994,10 @@ void OSD::consume_map() derr << __func__ << " SORTBITWISE flag is not set" << dendl; ceph_abort(); } - service.pre_publish_map(osdmap); service.await_reserved_maps(); service.publish_map(osdmap); - + dout(20) << "consume_map " << osdmap->get_epoch() << " -- publish done" << dendl; // prime splits and merges set> newly_split; // splits, and when set> merge_pgs; // merge participants, and when @@ -10784,8 +10842,10 @@ void OSDShard::identify_splits_and_merges( set> *merge_pgs) { std::lock_guard l(shard_lock); + dout(20) << __func__ << " " << pg_slots.size() << " slots" << dendl; if (shard_osdmap) { for (auto& i : pg_slots) { + dout(20) << __func__ << " slot pgid:" << i.first << "slot:" << i.second.get() << dendl; const spg_t& pgid = i.first; auto *slot = i.second.get(); if (slot->pg) { @@ -10802,6 +10862,8 @@ void OSDShard::identify_splits_and_merges( } } } + dout(20) << __func__ << " " << split_pgs->size() << " splits, " + << merge_pgs->size() << " merges" << dendl; } void OSDShard::prime_splits(const OSDMapRef& as_of_osdmap, diff --git a/src/osd/OSD.h b/src/osd/OSD.h index 571ac99c57da8..cf1c84403131c 100644 --- a/src/osd/OSD.h +++ b/src/osd/OSD.h @@ -196,40 +196,11 @@ public: std::map map_reservations; /// gets ref to next_osdmap and registers the epoch as reserved - OSDMapRef get_nextmap_reserved() { - std::lock_guard l(pre_publish_lock); - epoch_t e = next_osdmap->get_epoch(); - std::map::iterator i = - map_reservations.insert(std::make_pair(e, 0)).first; - i->second++; - return next_osdmap; - } + OSDMapRef get_nextmap_reserved(); /// releases reservation on map - void release_map(OSDMapRef osdmap) { - std::lock_guard l(pre_publish_lock); - std::map::iterator i = - map_reservations.find(osdmap->get_epoch()); - ceph_assert(i != map_reservations.end()); - ceph_assert(i->second > 0); - if (--(i->second) == 0) { - map_reservations.erase(i); - } - if (pre_publish_waiter) { - pre_publish_cond.notify_all(); - } - } + void release_map(OSDMapRef osdmap); /// blocks until there are no reserved maps prior to next_osdmap - void await_reserved_maps() { - std::unique_lock l{pre_publish_lock}; - ceph_assert(next_osdmap); - pre_publish_waiter++; - pre_publish_cond.wait(l, [this] { - auto i = map_reservations.cbegin(); - return (i == map_reservations.cend() || - i->first >= next_osdmap->get_epoch()); - }); - pre_publish_waiter--; - } + void await_reserved_maps() ; OSDMapRef get_next_osdmap() { std::lock_guard l(pre_publish_lock); return next_osdmap; -- 2.39.5