From: Radoslaw Zarzynski Date: Mon, 11 Jul 2022 14:30:34 +0000 (+0000) Subject: osd, kv: add debugs along the pg_log_t::dups paths. X-Git-Url: http://git.apps.os.sepia.ceph.com/?a=commitdiff_plain;h=66cb3ce1e52d64001bbba172e48a841ea8b29831;p=ceph.git osd, kv: add debugs along the pg_log_t::dups paths. Signed-off-by: Radoslaw Zarzynski (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 070f79a609be8..be032b4fa862a 100644 --- 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 2a4b1d1513aa7..ad6762b297341 100644 --- a/src/osd/PGLog.cc +++ b/src/osd/PGLog.cc @@ -60,6 +60,7 @@ void PGLog::IndexedLog::trim( set* 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 *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 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 15951c4412b94..5fe78e7845c23 100644 --- a/src/osd/PGLog.h +++ b/src/osd/PGLog.h @@ -1424,8 +1424,9 @@ public: std::set *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 e794d78a2a909..3a92591409f42 100644 --- 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