Merge pull request ceph#61365 from Matan-B/wip-matanb-snapmapper-logs

osd/SnapMapper: Improve logging

Author: SrinivasaBharath

src/osd/PG.cc

@@ -514,6 +514,8 @@ void PG::finish_recovery_op(const hobject_t& soid, bool dequeue)
 
 void PG::split_into(pg_t child_pgid, PG *child, unsigned split_bits)
 {
+  dout(10) << __func__ << " split_bits " << split_bits << dendl;
+
   recovery_state.split_into(child_pgid, &child->recovery_state, split_bits);
 
   child->update_snap_mapper_bits(split_bits);

src/osd/SnapMapper.cc

@@ -24,7 +24,7 @@
 #define dout_context cct
 #define dout_subsys ceph_subsys_osd
 #undef dout_prefix
-#define dout_prefix *_dout << "snap_mapper."
+#define dout_prefix *_dout << "snap_mapper "
 
 using std::make_pair;
 using std::map;
@@ -205,6 +205,20 @@ int OSDriver::get_next_or_current(
 }
 #endif // WITH_SEASTAR
 
+  SnapMapper::SnapMapper(
+    CephContext* cct,
+    MapCacher::StoreDriver<std::string, ceph::buffer::list> *driver,
+    uint32_t match,  ///< [in] pgid
+    uint32_t bits,   ///< [in] current split bits
+    int64_t pool,    ///< [in] pool
+    shard_id_t shard ///< [in] shard
+    )
+    : cct(cct), backend(driver), mask_bits(bits), match(match), pool(pool),
+      shard(shard), shard_prefix(make_shard_prefix(shard)) {
+    dout(10) << *this << __func__ << dendl;
+    update_bits(mask_bits);
+  }
+
 string SnapMapper::get_prefix(int64_t pool, snapid_t snap)
 {
   static_assert(sizeof(pool) == 8, "assumed by the formatting code");
@@ -483,13 +497,31 @@ void SnapMapper::set_snaps(
   backend.set_keys(to_set, t);
 }
 
+void SnapMapper::update_bits(
+  uint32_t new_bits)  ///< [in] new split bits
+{
+    dout(20) << *this << __func__ << " new_bits: " << new_bits << dendl;
+    mask_bits = new_bits;
+    std::set<std::string> _prefixes = hobject_t::get_prefixes(
+      mask_bits,
+      match,
+      pool);
+    prefixes.clear();
+    for (auto i = _prefixes.begin(); i != _prefixes.end(); ++i) {
+      prefixes.insert(shard_prefix + *i);
+    }
+    dout(20) << *this <<__func__ << " prefix updated" << dendl;
+
+    reset_prefix_itr(CEPH_NOSNAP, "update_bits");
+  }
+
 int SnapMapper::update_snaps(
   const hobject_t &oid,
   const set<snapid_t> &new_snaps,
   const set<snapid_t> *old_snaps_check,
   MapCacher::Transaction<std::string, ceph::buffer::list> *t)
 {
-  dout(20) << __func__ << " " << oid << " " << new_snaps
+  dout(20) << *this << __func__ << " " << oid << " " << new_snaps
 	   << " was " << (old_snaps_check ? *old_snaps_check : set<snapid_t>())
 	   << dendl;
   ceph_assert(check(oid));
@@ -536,7 +568,7 @@ void SnapMapper::add_oid(
     object_snaps out;
     int r = get_snaps(oid, &out);
     if (r != -ENOENT) {
-      derr << __func__ << " found existing snaps mapped on " << oid
+      derr << *this << __func__ << " found existing snaps mapped on " << oid
 	   << ", removing" << dendl;
       ceph_assert(!cct->_conf->osd_debug_verify_snaps);
       remove_oid(oid, t);
@@ -554,7 +586,7 @@ void SnapMapper::add_oid(
   }
   if (g_conf()->subsys.should_gather<ceph_subsys_osd, 20>()) {
     for (auto& i : to_add) {
-      dout(20) << __func__ << " set " << i.first << dendl;
+      dout(20) << *this << __func__ << " set " << i.first << dendl;
     }
   }
   backend.set_keys(to_add, t);
@@ -564,17 +596,17 @@ void SnapMapper::add_oid(
 void SnapMapper::reset_prefix_itr(snapid_t snap, const char *s)
 {
   if (prefix_itr_snap == CEPH_NOSNAP) {
-    dout(10) << __func__ << "::from <CEPH_NOSNAP> to <" << snap << "> ::" << s << dendl;
+    dout(10) << *this << __func__ << "::from <CEPH_NOSNAP> to <" << snap << "> ::" << s << dendl;
   }
   else if (snap == CEPH_NOSNAP) {
-    dout(10) << __func__ << "::from <"<< prefix_itr_snap << "> to <CEPH_NOSNAP> ::" << s << dendl;
+    dout(10) << *this << __func__ << "::from <"<< prefix_itr_snap << "> to <CEPH_NOSNAP> ::" << s << dendl;
   }
   else if (prefix_itr_snap == snap) {
-    dout(10) << __func__ << "::with the same snapid <" << snap << "> ::" << s << dendl;
+    dout(10) << *this << __func__ << "::with the same snapid <" << snap << "> ::" << s << dendl;
   }
   else {
     // This is unexpected!!
-    dout(10) << __func__ << "::from <"<< prefix_itr_snap << "> to <" << snap << "> ::" << s << dendl;
+    dout(10) << *this << __func__ << "::from <"<< prefix_itr_snap << "> to <" << snap << "> ::" << s << dendl;
   }
   prefix_itr_snap = snap;
   prefix_itr      = prefixes.begin();
@@ -594,7 +626,7 @@ vector<hobject_t> SnapMapper::get_objects_by_prefixes(
       pair<string, ceph::buffer::list> next;
       // access RocksDB (an expensive operation!)
       int r = backend.get_next(pos, &next);
-      dout(20) << __func__ << " get_next(" << pos << ") returns " << r
+      dout(20) << *this << __func__ << " get_next(" << pos << ") returns " << r
 	       << " " << next.first << dendl;
       if (r != 0) {
 	return out; // Done
@@ -611,18 +643,18 @@ vector<hobject_t> SnapMapper::get_objects_by_prefixes(
 	break; // Done with this prefix
       }
 
-      dout(20) << __func__ << " " << next.first << dendl;
+      dout(20) <<  *this << __func__ << " found " << next.first << dendl;
       pair<snapid_t, hobject_t> next_decoded(from_raw(next));
       ceph_assert(next_decoded.first == snap);
       ceph_assert(check(next_decoded.second));
-
       out.push_back(next_decoded.second);
+
       pos = next.first;
     }
 
     if (out.size() >= max) {
-      dout(20) << fmt::format("{}: reached max of: {} returning",
-                              __func__, out.size())
+      dout(20) << *this << fmt::format("{}: reached max of: {} returning",
+                                       __func__, out.size())
                << dendl;
       return out;
     }
@@ -634,7 +666,7 @@ std::optional<vector<hobject_t>> SnapMapper::get_next_objects_to_trim(
   snapid_t snap,
   unsigned max)
 {
-  dout(20) << __func__ << "::snapid=" << snap << dendl;
+  dout(20) << *this << __func__ << "snapid=" << snap << dendl;
 
   // if max would be 0, we return ENOENT and the caller would mistakenly
   // trim the snaptrim queue
@@ -664,7 +696,7 @@ std::optional<vector<hobject_t>> SnapMapper::get_next_objects_to_trim(
     objs = get_objects_by_prefixes(snap, max);
 
     if (unlikely(objs.size() > 0)) {
-      derr << __func__ << "::New Clone-Objects were added to Snap " << snap
+      derr << *this << __func__ << " New Clone-Objects were added to Snap " << snap
 	   << " after trimming was started" << dendl;
     }
     reset_prefix_itr(CEPH_NOSNAP, "Trim was completed successfully");
@@ -682,7 +714,7 @@ int SnapMapper::remove_oid(
   const hobject_t &oid,
   MapCacher::Transaction<std::string, ceph::buffer::list> *t)
 {
-  dout(20) << __func__ << " " << oid << dendl;
+  dout(20) << *this << __func__ << " " << oid << dendl;
   ceph_assert(check(oid));
   return _remove_oid(oid, t);
 }
@@ -691,7 +723,7 @@ int SnapMapper::_remove_oid(
   const hobject_t &oid,
   MapCacher::Transaction<std::string, ceph::buffer::list> *t)
 {
-  dout(20) << __func__ << " " << oid << dendl;
+  dout(20) << *this << __func__ << " " << oid << dendl;
   object_snaps out;
   int r = get_snaps(oid, &out);
   if (r < 0)
@@ -707,7 +739,7 @@ int SnapMapper::_remove_oid(
   }
   if (g_conf()->subsys.should_gather<ceph_subsys_osd, 20>()) {
     for (auto& i : to_remove) {
-      dout(20) << __func__ << "::rm " << i << dendl;
+      dout(20) << *this << __func__ << "::rm " << i << dendl;
     }
   }
   backend.remove_keys(to_remove, t);
@@ -739,7 +771,7 @@ void SnapMapper::update_snap_map(
       i.soid,
       _t);
     if (r)
-      dout(20) << __func__ << " remove_oid " << i.soid << " failed with " << r << dendl;
+      dout(20) << *this << __func__ << " remove_oid " << i.soid << " failed with " << r << dendl;
     // On removal tolerate missing key corruption
     ceph_assert(r == 0 || r == -ENOENT);
   } else if (i.is_update()) {
@@ -750,7 +782,7 @@ void SnapMapper::update_snap_map(
     try {
       decode(snaps, p);
     } catch (...) {
-      dout(20) << __func__ << " decode snaps failure on " << i << dendl;
+      dout(20) << *this << __func__ << " decode snaps failure on " << i << dendl;
       snaps.clear();
     }
     std::set<snapid_t> _snaps(snaps.begin(), snaps.end());

src/osd/SnapMapper.h

@@ -122,6 +122,8 @@ class OSDriver : public MapCacher::StoreDriver<std::string, ceph::buffer::list>
 class SnapMapper : public Scrub::SnapMapReaderI {
   friend class MapperVerifier; // unit-test support
   friend class DirectMapper; // unit-test support
+  friend std::ostream& operator<<(std::ostream &lhs, const SnapMapper &sm);
+
 public:
   CephContext* cct;
   struct object_snaps {
@@ -329,28 +331,12 @@ class SnapMapper : public Scrub::SnapMapReaderI {
     uint32_t bits,   ///< [in] current split bits
     int64_t pool,    ///< [in] pool
     shard_id_t shard ///< [in] shard
-    )
-    : cct(cct), backend(driver), mask_bits(bits), match(match), pool(pool),
-      shard(shard), shard_prefix(make_shard_prefix(shard)) {
-    update_bits(mask_bits);
-  }
+    );
 
   /// Update bits in case of pg split or merge
   void update_bits(
     uint32_t new_bits  ///< [in] new split bits
-    ) {
-    mask_bits = new_bits;
-    std::set<std::string> _prefixes = hobject_t::get_prefixes(
-      mask_bits,
-      match,
-      pool);
-    prefixes.clear();
-    for (auto i = _prefixes.begin(); i != _prefixes.end(); ++i) {
-      prefixes.insert(shard_prefix + *i);
-    }
-
-    reset_prefix_itr(CEPH_NOSNAP, "update_bits");
-  }
+    );
 
   const std::set<std::string>::iterator get_prefix_itr() {
     return prefix_itr;
@@ -414,4 +400,14 @@ class SnapMapper : public Scrub::SnapMapReaderI {
 WRITE_CLASS_ENCODER(SnapMapper::object_snaps)
 WRITE_CLASS_ENCODER(SnapMapper::Mapping)
 
+inline std::ostream& operator<<(std::ostream& os, const SnapMapper& sm)
+{
+  os << fmt::format(" [pg_id:{:x}, match:{}, mask_bits:{}, "
+                    "last_key_checked:{}, pool:{}, shard:{}, "
+                    "shard_prefix: {}, prefixes: {}] ",
+                    sm.match, sm.match, sm.mask_bits, sm.last_key_checked,
+                    sm.pool, sm.shard.id, sm.shard_prefix, sm.prefixes);
+  return os;
+}
+
 #endif