From: Matan Breizman <mbreizma@redhat.com>
Date: Wed, 10 May 2023 13:52:23 +0000 (+0000)
Subject: crimson/osd: Add logs around handling of osdmaps
X-Git-Tag: v19.0.0~986^2~5
X-Git-Url: http://git-server-git.apps.pok.os.sepia.ceph.com/?a=commitdiff_plain;h=6dfb8f2fcbe73dc3f1291f729fc7457679fc4c3c;p=ceph.git

crimson/osd: Add logs around handling of osdmaps

Signed-off-by: Matan Breizman <mbreizma@redhat.com>
---

diff --git a/src/crimson/osd/osd.cc b/src/crimson/osd/osd.cc
index dfb4f1e3e3d0..b9f96ade818e 100644
--- a/src/crimson/osd/osd.cc
+++ b/src/crimson/osd/osd.cc
@@ -997,6 +997,8 @@ seastar::future<> OSD::committed_osd_maps(version_t first,
     }
     return check_osdmap_features().then([this] {
       // yay!
+      logger().info("osd.{}: committed_osd_maps: broadcasting osdmaps up"
+                    " to {} epoch to pgs", whoami, osdmap->get_epoch());
       return pg_shard_manager.broadcast_map_to_pgs(osdmap->get_epoch());
     });
   }).then([m, this] {
diff --git a/src/crimson/osd/osd_operations/pg_advance_map.cc b/src/crimson/osd/osd_operations/pg_advance_map.cc
index 2514a0e74814..cd2ef615b417 100644
--- a/src/crimson/osd/osd_operations/pg_advance_map.cc
+++ b/src/crimson/osd/osd_operations/pg_advance_map.cc
@@ -24,7 +24,10 @@ PGAdvanceMap::PGAdvanceMap(
   ShardServices &shard_services, Ref<PG> pg, epoch_t to,
   PeeringCtx &&rctx, bool do_init)
   : shard_services(shard_services), pg(pg), to(to),
-    rctx(std::move(rctx)), do_init(do_init) {}
+    rctx(std::move(rctx)), do_init(do_init)
+{
+  logger().debug("{}: created", *this);
+}
 
 PGAdvanceMap::~PGAdvanceMap() {}
 
@@ -71,10 +74,13 @@ seastar::future<> PGAdvanceMap::start()
       });
     }
     return fut.then([this] {
+      ceph_assert(std::cmp_less_equal(*from, to));
       return seastar::do_for_each(
 	boost::make_counting_iterator(*from + 1),
 	boost::make_counting_iterator(to + 1),
 	[this](epoch_t next_epoch) {
+	  logger().debug("{}: start: getting map {}",
+	                 *this, next_epoch);
 	  return shard_services.get_map(next_epoch).then(
 	    [this] (cached_map_t&& next_map) {
 	      logger().debug("{}: advancing map to {}",
diff --git a/src/crimson/osd/pg_shard_manager.cc b/src/crimson/osd/pg_shard_manager.cc
index 03174b1df050..01dbd11c2145 100644
--- a/src/crimson/osd/pg_shard_manager.cc
+++ b/src/crimson/osd/pg_shard_manager.cc
@@ -117,6 +117,9 @@ seastar::future<> PGShardManager::broadcast_map_to_pgs(epoch_t epoch)
       local_service, epoch
     );
   }).then([this, epoch] {
+    logger().debug("PGShardManager::broadcast_map_to_pgs "
+                   "broadcasted up to {}",
+                    epoch);
     get_osd_singleton_state().osdmap_gate.got_map(epoch);
     return seastar::now();
   });
diff --git a/src/crimson/osd/shard_services.cc b/src/crimson/osd/shard_services.cc
index 647d8d6bee4a..6ec6b5cbcbef 100644
--- a/src/crimson/osd/shard_services.cc
+++ b/src/crimson/osd/shard_services.cc
@@ -349,8 +349,10 @@ OSDSingletonState::get_local_map(epoch_t e)
 {
   // TODO: use LRU cache for managing osdmap, fallback to disk if we have to
   if (auto found = osdmaps.find(e); found) {
+    logger().debug("{} osdmap.{} found in cache", __func__, e);
     return seastar::make_ready_future<local_cached_map_t>(std::move(found));
   } else {
+    logger().debug("{} loading osdmap.{} from disk", __func__, e);
     return load_map(e).then([e, this](std::unique_ptr<OSDMap> osdmap) {
       return seastar::make_ready_future<local_cached_map_t>(
 	osdmaps.insert(e, std::move(osdmap)));
@@ -370,8 +372,10 @@ seastar::future<bufferlist> OSDSingletonState::load_map_bl(
   epoch_t e)
 {
   if (std::optional<bufferlist> found = map_bl_cache.find(e); found) {
+    logger().debug("{} osdmap.{} found in cache", __func__, e);
     return seastar::make_ready_future<bufferlist>(*found);
   } else {
+    logger().debug("{} loading osdmap.{} from disk", __func__, e);
     return meta_coll->load_map(e);
   }
 }
@@ -421,12 +425,15 @@ seastar::future<> OSDSingletonState::store_maps(ceph::os::Transaction& t,
       if (auto p = m->maps.find(e); p != m->maps.end()) {
 	auto o = std::make_unique<OSDMap>();
 	o->decode(p->second);
-	logger().info("store_maps osdmap.{}", e);
+	logger().info("store_maps storing osdmap.{}", e);
 	store_map_bl(t, e, std::move(std::move(p->second)));
 	osdmaps.insert(e, std::move(o));
 	return seastar::now();
       } else if (auto p = m->incremental_maps.find(e);
 		 p != m->incremental_maps.end()) {
+	logger().info("store_maps found osdmap.{} incremental map, "
+	              "loading osdmap.{}", e, e - 1);
+	ceph_assert(std::cmp_greater(e, 0u));
 	return load_map(e - 1).then([e, bl=p->second, &t, this](auto o) {
 	  OSDMap::Incremental inc;
 	  auto i = bl.cbegin();
@@ -434,6 +441,7 @@ seastar::future<> OSDSingletonState::store_maps(ceph::os::Transaction& t,
 	  o->apply_incremental(inc);
 	  bufferlist fbl;
 	  o->encode(fbl, inc.encode_features | CEPH_FEATURE_RESERVED);
+	  logger().info("store_maps storing osdmap.{}", o->get_epoch());
 	  store_map_bl(t, e, std::move(fbl));
 	  osdmaps.insert(e, std::move(o));
 	  return seastar::now();
@@ -700,6 +708,9 @@ seastar::future<> OSDSingletonState::send_incremental_map(
   crimson::net::Connection &conn,
   epoch_t first)
 {
+  logger().info("{}: first osdmap: {} "
+                "superblock's oldest map: {}",
+                __func__, first, superblock.oldest_map);
   if (first >= superblock.oldest_map) {
     return load_map_bls(
       first, superblock.newest_map