From ee29963503567d3d7e2afbe012585df4b93054ed Mon Sep 17 00:00:00 2001 From: Yingxin Cheng Date: Sun, 11 Apr 2021 23:58:02 +0800 Subject: [PATCH] crimson/onode-staged-tree: improve logs Signed-off-by: Yingxin Cheng --- .../onode_manager/staged-fltree/node.cc | 30 ++++++++++++------- .../staged-fltree/node_extent_manager/dummy.h | 4 +-- .../node_extent_manager/seastore.cc | 2 +- .../node_extent_manager/seastore.h | 4 +-- .../onode_manager/staged-fltree/node_layout.h | 9 +++--- 5 files changed, 30 insertions(+), 19 deletions(-) diff --git a/src/crimson/os/seastore/onode_manager/staged-fltree/node.cc b/src/crimson/os/seastore/onode_manager/staged-fltree/node.cc index 0a682098bc0..4f1bd74ca81 100644 --- a/src/crimson/os/seastore/onode_manager/staged-fltree/node.cc +++ b/src/crimson/os/seastore/onode_manager/staged-fltree/node.cc @@ -385,7 +385,10 @@ void Node::test_make_destructable( node_future<> Node::mkfs(context_t c, RootNodeTracker& root_tracker) { return LeafNode::allocate_root(c, root_tracker - ).safe_then([](auto ret) { /* FIXME: discard_result(); */ }); + ).safe_then([](auto ret) { + logger().info("OTree::Node::Mkfs: allocated root {}", + ret->get_name()); + }); } node_future> Node::load_root(context_t c, RootNodeTracker& root_tracker) @@ -397,6 +400,8 @@ node_future> Node::load_root(context_t c, RootNodeTracker& root_tracke return Node::load(c, root_addr, true ).safe_then([c, _super = std::move(_super), &root_tracker](auto root) mutable { + logger().trace("OTree::Node::LoadRoot: loaded {}", + root->get_name()); assert(root->impl->field_type() == field_type_t::N0); root->as_root(std::move(_super)); std::ignore = c; // as only used in an assert @@ -431,6 +436,8 @@ node_future<> Node::upgrade_root(context_t c) return InternalNode::allocate_root(c, impl->level(), impl->laddr(), std::move(super) ).safe_then([this](auto new_root) { as_child(search_position_t::end(), new_root); + logger().info("OTree::Node::UpgradeRoot: upgraded from {} to {}", + get_name(), new_root->get_name()); }); } @@ -740,15 +747,15 @@ node_future> InternalNode::get_or_track_child( auto found = tracked_child_nodes.find(position); Ref this_ref = this; return (found == tracked_child_nodes.end() - ? (logger().trace("OTree::Internal: load child untracked at {:#x}, pos({}), level={}", - child_addr, position, level() - 1), - Node::load(c, child_addr, level_tail + ? (Node::load(c, child_addr, level_tail ).safe_then([this, position] (auto child) { child->as_child(position, this); + logger().trace("OTree::Internal::GetTrackChild: loaded child untracked {} at pos({})", + child->get_name(), position); return child; })) - : (logger().trace("OTree::Internal: load child tracked at {:#x}, pos({}), level={}", - child_addr, position, level() - 1), + : (logger().trace("OTree::Internal::GetTrackChild: loaded child tracked {} at pos({})", + found->second->get_name(), position), node_ertr::make_ready_future>(found->second)) ).safe_then([this_ref, this, position, child_addr] (auto child) { assert(child_addr == child->impl->laddr()); @@ -1024,15 +1031,16 @@ node_future> LeafNode::insert_value( assert(impl->is_level_tail()); } #endif - logger().debug("OTree::Leaf::Insert: " - "pos({}), {}, {}, {}, mstat({}) ...", - pos, key, vconf, history, mstat); + logger().debug("OTree::Leaf::InsertValue: insert {} " + "with insert_key={}, insert_value={}, insert_pos({}), " + "history={}, mstat({}) ...", + get_name(), key, vconf, pos, history, mstat); search_position_t insert_pos = pos; auto [insert_stage, insert_size] = impl->evaluate_insert( key, vconf, history, mstat, insert_pos); auto free_size = impl->free_size(); if (free_size >= insert_size) { - // insert + // proceed to insert on_layout_change(); impl->prepare_mutate(c); auto p_value_header = impl->insert(key, vconf, insert_pos, insert_stage, insert_size); @@ -1051,6 +1059,8 @@ node_future> LeafNode::insert_value( }).safe_then([this_ref, this, c, &key, vconf, insert_pos, insert_stage=insert_stage, insert_size=insert_size](auto fresh_right) mutable { auto right_node = fresh_right.node; + logger().info("OTree::Leaf::InsertValue: proceed split {} to fresh {} ...", + get_name(), right_node->get_name()); // no need to bump version for right node, as it is fresh on_layout_change(); impl->prepare_mutate(c); diff --git a/src/crimson/os/seastore/onode_manager/staged-fltree/node_extent_manager/dummy.h b/src/crimson/os/seastore/onode_manager/staged-fltree/node_extent_manager/dummy.h index e737ffa55c7..ad86a3df610 100644 --- a/src/crimson/os/seastore/onode_manager/staged-fltree/node_extent_manager/dummy.h +++ b/src/crimson/os/seastore/onode_manager/staged-fltree/node_extent_manager/dummy.h @@ -27,7 +27,7 @@ class DummySuper final: public Super { protected: laddr_t get_root_laddr() const override { return *p_root_laddr; } void write_root_laddr(context_t, laddr_t addr) override { - logger().info("OTree::Dummy: update root {:#x} ...", addr); + logger().debug("OTree::Dummy: update root {:#x} ...", addr); *p_root_laddr = addr; } private: @@ -175,7 +175,7 @@ class DummyNodeExtentManager final: public NodeExtentManager { tm_future get_super_sync( Transaction& t, RootNodeTracker& tracker) { - logger().debug("OTree::Dummy: got root {:#x}", root_laddr); + logger().trace("OTree::Dummy: got root {:#x}", root_laddr); return tm_ertr::make_ready_future( Super::URef(new DummySuper(t, tracker, &root_laddr))); } diff --git a/src/crimson/os/seastore/onode_manager/staged-fltree/node_extent_manager/seastore.cc b/src/crimson/os/seastore/onode_manager/staged-fltree/node_extent_manager/seastore.cc index 24286f8b584..ab4e48303a6 100644 --- a/src/crimson/os/seastore/onode_manager/staged-fltree/node_extent_manager/seastore.cc +++ b/src/crimson/os/seastore/onode_manager/staged-fltree/node_extent_manager/seastore.cc @@ -51,7 +51,7 @@ static DeltaRecorderURef create_replay_recorder( void SeastoreSuper::write_root_laddr(context_t c, laddr_t addr) { - logger().info("OTree::Seastore: update root {:#x} ...", addr); + logger().debug("OTree::Seastore: update root {:#x} ...", addr); root_addr = addr; auto nm = static_cast(&c.nm); nm->get_tm().write_onode_root(c.t, addr); diff --git a/src/crimson/os/seastore/onode_manager/staged-fltree/node_extent_manager/seastore.h b/src/crimson/os/seastore/onode_manager/staged-fltree/node_extent_manager/seastore.h index 9e21d1ef8aa..5adb708c8cc 100644 --- a/src/crimson/os/seastore/onode_manager/staged-fltree/node_extent_manager/seastore.h +++ b/src/crimson/os/seastore/onode_manager/staged-fltree/node_extent_manager/seastore.h @@ -74,7 +74,7 @@ class SeastoreNodeExtentManager final: public NodeExtentManager { tm_future read_extent( Transaction& t, laddr_t addr, extent_len_t len) override { - logger().debug("OTree::Seastore: reading {}B at {:#x} ...", len, addr); + logger().trace("OTree::Seastore: reading {}B at {:#x} ...", len, addr); return tm.read_extent(t, addr, len ).safe_then([addr, len](auto&& e) { logger().trace("OTree::Seastore: read {}B at {:#x}", @@ -116,7 +116,7 @@ class SeastoreNodeExtentManager final: public NodeExtentManager { Transaction& t, RootNodeTracker& tracker) override { logger().trace("OTree::Seastore: get root ..."); return tm.read_onode_root(t).safe_then([this, &t, &tracker](auto root_addr) { - logger().debug("OTree::Seastore: got root {:#x}", root_addr); + logger().trace("OTree::Seastore: got root {:#x}", root_addr); return Super::URef(new SeastoreSuper(t, tracker, root_addr, tm)); }); } diff --git a/src/crimson/os/seastore/onode_manager/staged-fltree/node_layout.h b/src/crimson/os/seastore/onode_manager/staged-fltree/node_layout.h index 7ef4b84c465..047dd4cac91 100644 --- a/src/crimson/os/seastore/onode_manager/staged-fltree/node_layout.h +++ b/src/crimson/os/seastore/onode_manager/staged-fltree/node_layout.h @@ -359,10 +359,8 @@ class NodeLayoutT final : public InternalNodeImpl, public LeafNodeImpl { assert(_right_impl.field_type() == FIELD_TYPE); auto& right_impl = dynamic_cast(_right_impl); logger().info("OTree::Layout::Split: begin at " - "insert_pos({}), insert_stage={}, insert_size={}B, " - "{:#x}=>{:#x} ...", - _insert_pos, insert_stage, insert_size, - laddr(), right_impl.laddr()); + "insert_pos({}), insert_stage={}, insert_size={}B ...", + _insert_pos, insert_stage, insert_size); if (unlikely(logger().is_enabled(seastar::log_level::debug))) { std::ostringstream sos; dump(sos); @@ -591,6 +589,9 @@ class NodeLayoutT final : public InternalNodeImpl, public LeafNodeImpl { void replace_child_addr( const search_position_t& pos, laddr_t dst, laddr_t src) override { if constexpr (NODE_TYPE == node_type_t::INTERNAL) { + logger().debug("OTree::Layout::ReplaceChildAddr: " + "update from {:#x} to {:#x} at pos({}) ...", + src, dst, pos); const laddr_packed_t* p_value; if (pos.is_end()) { assert(is_level_tail()); -- 2.39.5