osd, kv: add debugs along the pg_log_t::dups paths.

Signed-off-by: Radoslaw Zarzynski <rzarzyns@redhat.com>
(cherry picked from commit 0a986bff372f81e7ea8e015754bb0342c4edfa87)
(cherry picked from commit b06c8ff5bcded20cd5071ed107532d8d84bcfa65)

Resolves: rhbz#2093106

diff --git a/src/kv/RocksDBStore.cc b/src/kv/RocksDBStore.cc
index 070f79a609be8f0279d3bfb2e36e1b4e60a87d47..be032b4fa862a21a98b3fbec0c9f43514a1007ae 100644 (file)
--- a/src/kv/RocksDBStore.cc
+++ b/src/kv/RocksDBStore.cc
@@ -1739,6 +1739,8 @@ void RocksDBStore::RocksDBTransactionImpl::rm_range_keys(const string &prefix,
                                                          const string &start,
                                                          const string &end)
 {
+  ldout(db->cct, 10) << __func__ << " enter start=" << start
+                    << " end=" << end << dendl;
   auto p_iter = db->cf_handles.find(prefix);
   if (p_iter == db->cf_handles.end()) {
     uint64_t cnt = db->delete_range_threshold;
@@ -1750,6 +1752,8 @@ void RocksDBStore::RocksDBTransactionImpl::rm_range_keys(const string &prefix,
       bat.Delete(db->default_cf, combine_strings(prefix, it->key()));
     }
     if (cnt == 0) {
+      ldout(db->cct, 10) << __func__ << " p_iter == end(), resorting to DeleteRange"
+                        << dendl;
       bat.RollbackToSavePoint();
       bat.DeleteRange(db->default_cf,
                      rocksdb::Slice(combine_strings(prefix, start)),
@@ -1770,6 +1774,8 @@ void RocksDBStore::RocksDBTransactionImpl::rm_range_keys(const string &prefix,
        bat.Delete(cf, it->key());
       }
       if (cnt == 0) {
+        ldout(db->cct, 10) << __func__ << " p_iter != end(), resorting to DeleteRange"
+                          << dendl;
        bat.RollbackToSavePoint();
        bat.DeleteRange(cf, rocksdb::Slice(start), rocksdb::Slice(end));
       } else {
@@ -1778,6 +1784,7 @@ void RocksDBStore::RocksDBTransactionImpl::rm_range_keys(const string &prefix,
       delete it;
     }
   }
+  ldout(db->cct, 10) << __func__ << " end" << dendl;
 }
 
 void RocksDBStore::RocksDBTransactionImpl::merge(

diff --git a/src/osd/PGLog.cc b/src/osd/PGLog.cc
index 2a4b1d1513aa71ecc5dcb973167b5ea2a1c7414b..ad6762b297341214550eac8aa4297e4d8ad532e0 100644 (file)
--- a/src/osd/PGLog.cc
+++ b/src/osd/PGLog.cc
@@ -60,6 +60,7 @@ void PGLog::IndexedLog::trim(
   set<string>* trimmed_dups,
   eversion_t *write_from_dups)
 {
+  lgeneric_subdout(cct, osd, 10) << "IndexedLog::trim s=" << s << dendl;
   ceph_assert(s <= can_rollback_to);
   if (complete_to != log.end())
     lgeneric_subdout(cct, osd, 20) << " complete_to " << complete_to->version << dendl;
@@ -153,6 +154,10 @@ void PGLog::IndexedLog::trim(
   // raise tail?
   if (tail < s)
     tail = s;
+  lgeneric_subdout(cct, osd, 20) << "IndexedLog::trim after trim"
+                                << " dups.size()=" << dups.size()
+                                << " tail=" << tail
+                                << " s=" << s << dendl;
 }
 
 ostream& PGLog::IndexedLog::print(ostream& out) const
@@ -514,6 +519,9 @@ void PGLog::merge_log(pg_info_t &oinfo, pg_log_t&& olog, pg_shard_t fromosd,
 
 // returns true if any changes were made to log.dups
 bool PGLog::merge_log_dups(const pg_log_t& olog) {
+  dout(5) << __func__
+         << " log.dups.size()=" << log.dups.size()
+         <<  "olog.dups.size()=" << olog.dups.size() << dendl;
   bool changed = false;
 
   if (!olog.dups.empty()) {
@@ -592,6 +600,10 @@ bool PGLog::merge_log_dups(const pg_log_t& olog) {
     }
   }
 
+  dout(5) << "end of " << __func__ << " changed=" << changed
+         << " log.dups.size()=" << log.dups.size()
+         << " olog.dups.size()=" << olog.dups.size() << dendl;
+
   return changed;
 }
 
@@ -722,7 +734,10 @@ void PGLog::_write_log_and_missing_wo_missing(
   const DoutPrefixProvider *dpp
   )
 {
-  // dout(10) << "write_log_and_missing, clearing up to " << dirty_to << dendl;
+  ldpp_dout(dpp, 10) << "_write_log_and_missing_wo_missing, clearing up to " << dirty_to
+                    << " dirty_to_dups=" << dirty_to_dups
+                    << " dirty_from_dups=" << dirty_from_dups
+                    << " write_from_dups=" << write_from_dups << dendl;
   if (touch_log)
     t.touch(coll, log_oid);
   if (dirty_to != eversion_t()) {
@@ -773,6 +788,8 @@ void PGLog::_write_log_and_missing_wo_missing(
   if (dirty_to_dups != eversion_t()) {
     pg_log_dup_t min, dirty_to_dup;
     dirty_to_dup.version = dirty_to_dups;
+    ldpp_dout(dpp, 10) << __func__ << " remove dups min=" << min.get_key_name()
+                      << " to dirty_to_dup=" << dirty_to_dup.get_key_name() << dendl;
     t.omap_rmkeyrange(
       coll, log_oid,
       min.get_key_name(), dirty_to_dup.get_key_name());
@@ -781,11 +798,16 @@ void PGLog::_write_log_and_missing_wo_missing(
     pg_log_dup_t max, dirty_from_dup;
     max.version = eversion_t::max();
     dirty_from_dup.version = dirty_from_dups;
+    ldpp_dout(dpp, 10) << __func__ << " remove dups dirty_from_dup="
+                      << dirty_from_dup.get_key_name()
+                      << " to max=" << max.get_key_name() << dendl;
     t.omap_rmkeyrange(
       coll, log_oid,
       dirty_from_dup.get_key_name(), max.get_key_name());
   }
 
+  ldpp_dout(dpp, 10) << __func__ << " going to encode log.dups.size()="
+                    << log.dups.size() << dendl;
   for (const auto& entry : log.dups) {
     if (entry.version > dirty_to_dups)
       break;
@@ -793,7 +815,8 @@ void PGLog::_write_log_and_missing_wo_missing(
     encode(entry, bl);
     (*km)[entry.get_key_name()] = std::move(bl);
   }
-
+  ldpp_dout(dpp, 10) << __func__ << " 1st round encoded log.dups.size()="
+                    << log.dups.size() << dendl;
   for (auto p = log.dups.rbegin();
        p != log.dups.rend() &&
         (p->version >= dirty_from_dups || p->version >= write_from_dups) &&
@@ -803,9 +826,12 @@ void PGLog::_write_log_and_missing_wo_missing(
     encode(*p, bl);
     (*km)[p->get_key_name()] = std::move(bl);
   }
+  ldpp_dout(dpp, 10) << __func__ << " 2st round encoded log.dups.size()="
+                    << log.dups.size() << dendl;
 
   if (dirty_divergent_priors) {
-    //dout(10) << "write_log_and_missing: writing divergent_priors" << dendl;
+    ldpp_dout(dpp, 10) << "write_log_and_missing: writing divergent_priors"
+                      << dendl;
     encode(divergent_priors, (*km)["divergent_priors"]);
   }
   if (require_rollback) {
@@ -816,6 +842,7 @@ void PGLog::_write_log_and_missing_wo_missing(
       log.get_rollback_info_trimmed_to(),
       (*km)["rollback_info_trimmed_to"]);
   }
+  ldpp_dout(dpp, 10) << "end of " << __func__ << dendl;
 }
 
 // static
@@ -840,6 +867,11 @@ void PGLog::_write_log_and_missing(
   set<string> *log_keys_debug,
   const DoutPrefixProvider *dpp
   ) {
+  ldpp_dout(dpp, 10) << __func__ << " clearing up to " << dirty_to
+                    << " dirty_to_dups=" << dirty_to_dups
+                    << " dirty_from_dups=" << dirty_from_dups
+                    << " write_from_dups=" << write_from_dups
+                    << " trimmed_dups.size()=" << trimmed_dups.size() << dendl;
   set<string> to_remove;
   to_remove.swap(trimmed_dups);
   for (auto& t : trimmed) {
@@ -862,7 +894,8 @@ void PGLog::_write_log_and_missing(
     clear_up_to(log_keys_debug, dirty_to.get_key_name());
   }
   if (dirty_to != eversion_t::max() && dirty_from != eversion_t::max()) {
-    //   dout(10) << "write_log_and_missing, clearing from " << dirty_from << dendl;
+    ldpp_dout(dpp, 10) << "write_log_and_missing, clearing from "
+                      << dirty_from << dendl;
     t.omap_rmkeyrange(
       coll, log_oid,
       dirty_from.get_key_name(), eversion_t::max().get_key_name());
@@ -903,6 +936,8 @@ void PGLog::_write_log_and_missing(
   if (dirty_to_dups != eversion_t()) {
     pg_log_dup_t min, dirty_to_dup;
     dirty_to_dup.version = dirty_to_dups;
+    ldpp_dout(dpp, 10) << __func__ << " remove dups min=" << min.get_key_name()
+                      << " to dirty_to_dup=" << dirty_to_dup.get_key_name() << dendl;
     t.omap_rmkeyrange(
       coll, log_oid,
       min.get_key_name(), dirty_to_dup.get_key_name());
@@ -911,11 +946,16 @@ void PGLog::_write_log_and_missing(
     pg_log_dup_t max, dirty_from_dup;
     max.version = eversion_t::max();
     dirty_from_dup.version = dirty_from_dups;
+    ldpp_dout(dpp, 10) << __func__ << " remove dups dirty_from_dup="
+                      << dirty_from_dup.get_key_name()
+                      << " to max=" << max.get_key_name() << dendl;
     t.omap_rmkeyrange(
       coll, log_oid,
       dirty_from_dup.get_key_name(), max.get_key_name());
   }
 
+  ldpp_dout(dpp, 10) << __func__ << " going to encode log.dups.size()="
+                    << log.dups.size() << dendl;
   for (const auto& entry : log.dups) {
     if (entry.version > dirty_to_dups)
       break;
@@ -923,6 +963,8 @@ void PGLog::_write_log_and_missing(
     encode(entry, bl);
     (*km)[entry.get_key_name()] = std::move(bl);
   }
+  ldpp_dout(dpp, 10) << __func__ << " 1st round encoded log.dups.size()="
+                    << log.dups.size() << dendl;
 
   for (auto p = log.dups.rbegin();
        p != log.dups.rend() &&
@@ -933,9 +975,12 @@ void PGLog::_write_log_and_missing(
     encode(*p, bl);
     (*km)[p->get_key_name()] = std::move(bl);
   }
+  ldpp_dout(dpp, 10) << __func__ << " 2st round encoded log.dups.size()="
+                    << log.dups.size() << dendl;
 
   if (clear_divergent_priors) {
-    //dout(10) << "write_log_and_missing: writing divergent_priors" << dendl;
+    ldpp_dout(dpp, 10) << "write_log_and_missing: writing divergent_priors"
+                      << dendl;
     to_remove.insert("divergent_priors");
   }
   // since we encode individual missing items instead of a whole
@@ -965,6 +1010,7 @@ void PGLog::_write_log_and_missing(
 
   if (!to_remove.empty())
     t.omap_rmkeys(coll, log_oid, to_remove);
+  ldpp_dout(dpp, 10) << "end of " << __func__ << dendl;
 }
 
 void PGLog::rebuild_missing_set_with_deletes(

diff --git a/src/osd/PGLog.h b/src/osd/PGLog.h
index 15951c4412b94241d130e87ca97e8c142e71ff03..5fe78e7845c23fbfeac112b22cf80069070dc7ed 100644 (file)
--- a/src/osd/PGLog.h
+++ b/src/osd/PGLog.h
@@ -1424,8 +1424,9 @@ public:
     std::set<std::string> *log_keys_debug = nullptr,
     bool debug_verify_stored_missing = false
     ) {
-    ldpp_dout(dpp, 20) << "read_log_and_missing coll " << ch->cid
+    ldpp_dout(dpp, 10) << "read_log_and_missing coll " << ch->cid
                       << " " << pgmeta_oid << dendl;
+    size_t total_dups = 0;
 
     // legacy?
     struct stat st;
@@ -1475,6 +1476,7 @@ public:
          }
          missing.add(oid, std::move(item));
        } else if (p->key().substr(0, 4) == std::string("dup_")) {
+         ++total_dups;
          pg_log_dup_t dup;
          decode(dup, bp);
          if (!dups.empty()) {
@@ -1667,7 +1669,9 @@ public:
        (*clear_divergent_priors) = false;
       missing.flush();
     }
-    ldpp_dout(dpp, 10) << "read_log_and_missing done" << dendl;
+    ldpp_dout(dpp, 10) << "read_log_and_missing done coll " << ch->cid
+                      << " total_dups=" << total_dups
+                      << " log.dups.size()=" << log.dups.size() << dendl;
   } // static read_log_and_missing
 
 #ifdef WITH_SEASTAR

diff --git a/src/osd/osd_types.cc b/src/osd/osd_types.cc
index e794d78a2a909f21163c5b792cad0a640d80b17d..3a92591409f4217497d5c3f6a28dd11a50b2aedd 100644 (file)
--- a/src/osd/osd_types.cc
+++ b/src/osd/osd_types.cc
@@ -5219,7 +5219,8 @@ static void _handle_dups(CephContext* cct, pg_log_t &target, const pg_log_t &oth
 {
   auto earliest_dup_version =
                target.head.version < maxdups ? 0u : target.head.version - maxdups + 1;
-  lgeneric_subdout(cct, osd, 20) << "copy_up_to/copy_after earliest_dup_version " << earliest_dup_version << dendl;
+  lgeneric_subdout(cct, osd, 20) << __func__ << " earliest_dup_version "
+                                << earliest_dup_version << dendl;
 
   for (auto d = other.dups.cbegin(); d != other.dups.cend(); ++d) {
     if (d->version.version >= earliest_dup_version) {
@@ -5249,7 +5250,9 @@ void pg_log_t::copy_after(CephContext* cct, const pg_log_t &other, eversion_t v)
   can_rollback_to = other.can_rollback_to;
   head = other.head;
   tail = other.tail;
-  lgeneric_subdout(cct, osd, 20) << __func__ << " v " << v << dendl;
+  lgeneric_subdout(cct, osd, 20) << __func__ << " v " << v
+                                << " dups.size()=" << dups.size()
+                                << " other.dups.size()=" << other.dups.size() << dendl;
   for (auto i = other.log.crbegin(); i != other.log.crend(); ++i) {
     ceph_assert(i->version > other.tail);
     if (i->version <= v) {
@@ -5261,6 +5264,9 @@ void pg_log_t::copy_after(CephContext* cct, const pg_log_t &other, eversion_t v)
     log.push_front(*i);
   }
   _handle_dups(cct, *this, other, cct->_conf->osd_pg_log_dups_tracked);
+  lgeneric_subdout(cct, osd, 20) << __func__ << " END v " << v
+                                << " dups.size()=" << dups.size()
+                                << " other.dups.size()=" << other.dups.size() << dendl;
 }
 
 void pg_log_t::copy_up_to(CephContext* cct, const pg_log_t &other, int max)
@@ -5269,7 +5275,9 @@ void pg_log_t::copy_up_to(CephContext* cct, const pg_log_t &other, int max)
   int n = 0;
   head = other.head;
   tail = other.tail;
-  lgeneric_subdout(cct, osd, 20) << __func__ << " max " << max << dendl;
+  lgeneric_subdout(cct, osd, 20) << __func__ << " max " << max
+                               << " dups.size()=" << dups.size()
+                               << " other.dups.size()=" << other.dups.size() << dendl;
   for (auto i = other.log.crbegin(); i != other.log.crend(); ++i) {
     ceph_assert(i->version > other.tail);
     if (n++ >= max) {
@@ -5280,6 +5288,9 @@ void pg_log_t::copy_up_to(CephContext* cct, const pg_log_t &other, int max)
     log.push_front(*i);
   }
   _handle_dups(cct, *this, other, cct->_conf->osd_pg_log_dups_tracked);
+  lgeneric_subdout(cct, osd, 20) << __func__ << " END max " << max
+                                << " dups.size()=" << dups.size()
+                                << " other.dups.size()=" << other.dups.size() << dendl;
 }
 
 ostream& pg_log_t::print(ostream& out) const