From: Yingxin Cheng Date: Mon, 12 Oct 2020 05:15:56 +0000 (+0800) Subject: crimson/onode-staged-tree: proper logging and dump X-Git-Tag: v16.1.0~359^2~17 X-Git-Url: http://git-server-git.apps.pok.os.sepia.ceph.com/?a=commitdiff_plain;h=a2409e3d7ee3d57782caadd5a7ebe2eb5198e516;p=ceph.git crimson/onode-staged-tree: proper logging and dump Signed-off-by: Yingxin Cheng --- 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 f97e120444e7..c69542d88600 100644 --- a/src/crimson/os/seastore/onode_manager/staged-fltree/node.cc +++ b/src/crimson/os/seastore/onode_manager/staged-fltree/node.cc @@ -5,13 +5,20 @@ #include #include -#include +#include #include "common/likely.h" +#include "crimson/common/log.h" #include "node_extent_manager.h" #include "node_impl.h" #include "stages/node_stage_layout.h" +namespace { + seastar::logger& logger() { + return crimson::get_logger(ceph_subsys_filestore); + } +} + namespace crimson::os::seastore::onode { using node_ertr = Node::node_ertr; @@ -268,16 +275,9 @@ node_future<> InternalNode::apply_child_split( auto left_child_addr_packed = laddr_packed_t{left_child_addr}; auto right_key = right_child->impl->get_largest_key_view(); auto right_child_addr = right_child->impl->laddr(); - std::cout << "internal insert at pos(" << pos << "), " - << "left-child[" << left_key << ", 0x" - << std::hex << left_child_addr << std::dec - << "], right-child[" << right_key << ", 0x" << - std::hex << right_child_addr << std::dec << "]" << std::endl; -#if 0 - std::cout << "before insert:" << std::endl; - dump(std::cout) << std::endl; -#endif - + logger().debug("OTree::Internal::Insert: " + "pos({}), left_child({}, {:#x}), right_child({}, {:#x}) ...", + pos, left_key, left_child_addr, right_key, right_child_addr); // update pos => left_child to pos => right_child impl->replace_child_addr(pos, right_child_addr, left_child_addr); replace_track(pos, right_child, left_child); @@ -412,12 +412,16 @@ node_future> InternalNode::get_or_track_child( auto found = tracked_child_nodes.find(position); Ref this_ref = this; return (found == tracked_child_nodes.end() - ? Node::load(c, child_addr, level_tail - ).safe_then([this, position] (auto child) { - child->as_child(position, this); - return child; - }) - : node_ertr::make_ready_future>(found->second) + ? (logger().trace("OTree::Internal: load child untracked at {:#x}, pos({}), level={}", + child_addr, position, level() - 1), + Node::load(c, child_addr, level_tail + ).safe_then([this, position] (auto child) { + child->as_child(position, this); + return child; + })) + : (logger().trace("OTree::Internal: load child tracked at {:#x}, pos({}), level={}", + child_addr, position, level() - 1), + node_ertr::make_ready_future>(found->second)) ).safe_then([this_ref, this, position, child_addr] (auto child) { assert(child_addr == child->impl->laddr()); assert(position == child->parent_info().position); @@ -596,15 +600,9 @@ node_future> LeafNode::insert_value( assert(impl->is_level_tail()); } #endif - std::cout << "leaf insert at pos(" << pos << "), " - << key << ", " << value << ", " << history - << ", mstat(" << (int)mstat << ")" - << std::endl; -#if 0 - std::cout << "before insert:" << std::endl; - dump(std::cout) << std::endl; -#endif - + logger().debug("OTree::Leaf::Insert: " + "pos({}), {}, {}, {}, mstat({}) ...", + pos, key, value, history, mstat); search_position_t insert_pos = pos; auto [insert_stage, insert_size] = impl->evaluate_insert( key, value, history, mstat, insert_pos); 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 de0142680f77..f54db62c018d 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 @@ -8,6 +8,7 @@ #include "include/buffer_raw.h" +#include "crimson/common/log.h" #include "crimson/os/seastore/onode_manager/staged-fltree/node_extent_manager.h" namespace crimson::os::seastore::onode { @@ -19,7 +20,14 @@ class DummySuper final: public Super { ~DummySuper() override = default; protected: laddr_t get_root_laddr() const override { return *p_root_laddr; } - void write_root_laddr(context_t, laddr_t addr) override { *p_root_laddr = addr; } + void write_root_laddr(context_t, laddr_t addr) override { + logger().info("OTree::Dummy: update root {:#x} ...", addr); + *p_root_laddr = addr; + } + private: + static seastar::logger& logger() { + return crimson::get_logger(ceph_subsys_filestore); + } laddr_t* p_root_laddr; }; @@ -52,6 +60,7 @@ class DummyNodeExtentManager final: public NodeExtentManager { tm_future read_extent( Transaction& t, laddr_t addr, extent_len_t len) override { + logger().trace("OTree::Dummy: reading {}B at {:#x} ...", len, addr); if constexpr (SYNC) { return read_extent_sync(t, addr, len); } else { @@ -64,6 +73,7 @@ class DummyNodeExtentManager final: public NodeExtentManager { tm_future alloc_extent( Transaction& t, extent_len_t len) override { + logger().trace("OTree::Dummy: allocating {}B ...", len); if constexpr (SYNC) { return alloc_extent_sync(t, len); } else { @@ -76,6 +86,7 @@ class DummyNodeExtentManager final: public NodeExtentManager { tm_future get_super( Transaction& t, RootNodeTracker& tracker) override { + logger().trace("OTree::Dummy: get root ..."); if constexpr (SYNC) { return get_super_sync(t, tracker); } else { @@ -91,8 +102,12 @@ class DummyNodeExtentManager final: public NodeExtentManager { Transaction& t, laddr_t addr, extent_len_t len) { auto iter = allocate_map.find(addr); assert(iter != allocate_map.end()); - assert(iter->second->get_length() == len); - return tm_ertr::make_ready_future(iter->second); + auto extent = iter->second; + logger().trace("OTree::Dummy: read {}B at {:#x}", + extent->get_length(), extent->get_laddr()); + assert(extent->get_laddr() == addr); + assert(extent->get_length() == len); + return tm_ertr::make_ready_future(extent); } tm_future alloc_extent_sync( @@ -105,15 +120,23 @@ class DummyNodeExtentManager final: public NodeExtentManager { extent->set_laddr(addr); assert(allocate_map.find(extent->get_laddr()) == allocate_map.end()); allocate_map.insert({extent->get_laddr(), extent}); + logger().debug("OTree::Dummy: allocated {}B at {:#x}", + extent->get_length(), extent->get_laddr()); + assert(extent->get_length() == len); return tm_ertr::make_ready_future(extent); } tm_future get_super_sync( Transaction& t, RootNodeTracker& tracker) { + logger().debug("OTree::Dummy: got root {:#x}", root_laddr); return tm_ertr::make_ready_future( Super::URef(new DummySuper(t, tracker, &root_laddr))); } + static seastar::logger& logger() { + return crimson::get_logger(ceph_subsys_filestore); + } + std::map> allocate_map; laddr_t root_laddr = L_ADDR_NULL; }; 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 e041a68dec16..38a0afd222af 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 @@ -3,6 +3,7 @@ #pragma once +#include "crimson/common/log.h" #include "crimson/os/seastore/onode_manager/staged-fltree/node_extent_manager.h" namespace crimson::os::seastore::onode { @@ -18,7 +19,10 @@ class SeastoreSuper final: public Super { return root_addr; } void write_root_laddr(context_t c, laddr_t addr) override; - + private: + static seastar::logger& logger() { + return crimson::get_logger(ceph_subsys_filestore); + } laddr_t root_addr; TransactionManager& tm; }; @@ -46,6 +50,10 @@ class SeastoreNodeExtent final: public NodeExtent { //TODO assert(false && "not implemented"); } + private: + static seastar::logger& logger() { + return crimson::get_logger(ceph_subsys_filestore); + } //TODO: recorder }; @@ -60,40 +68,56 @@ 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); return tm.read_extents(t, addr, len - ).safe_then([](auto&& extents) { + ).safe_then([addr, len](auto&& extents) { assert(extents.size() == 1); [[maybe_unused]] auto [laddr, e] = extents.front(); + logger().trace("OTree::Seastore: read {}B at {:#x}", + e->get_length(), e->get_laddr()); + assert(e->get_laddr() == addr); + assert(e->get_length() == len); return NodeExtentRef(e); }); } tm_future alloc_extent( Transaction& t, extent_len_t len) override { + logger().debug("OTree::Seastore: allocating {}B ...", len); return tm.alloc_extent(t, addr_min, len - ).safe_then([](auto extent) { + ).safe_then([len](auto extent) { + logger().debug("OTree::Seastore: allocated {}B at {:#x}", + extent->get_length(), extent->get_laddr()); + assert(extent->get_length() == len); return NodeExtentRef(extent); }); } tm_future get_super( 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); return Super::URef(new SeastoreSuper(t, tracker, root_addr, tm)); }); } - + private: + static seastar::logger& logger() { + return crimson::get_logger(ceph_subsys_filestore); + } TransactionManager& tm; const laddr_t addr_min; }; inline void SeastoreSuper::write_root_laddr(context_t c, laddr_t addr) { + logger().info("OTree::Seastore: update root {:#x} ...", addr); root_addr = addr; auto nm = static_cast(&c.nm); nm->get_tm().write_onode_root(c.t, addr); } inline NodeExtentRef SeastoreNodeExtent::mutate(context_t c) { + logger().debug("OTree::Seastore: mutate {:#x} ...", get_laddr()); auto nm = static_cast(&c.nm); auto ret = nm->get_tm().get_mutable_extent(c.t, this); return ret->cast(); 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 6757966c0435..f9dd44d3f57c 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 @@ -3,11 +3,11 @@ #pragma once -// TODO: remove -#include #include +#include #include "common/likely.h" +#include "crimson/common/log.h" #include "node_extent_visitor.h" #include "node_impl.h" #include "stages/node_stage_layout.h" @@ -245,18 +245,24 @@ class NodeLayoutT final : public InternalNodeImpl, public LeafNodeImpl { const full_key_t& key, const value_t& value, search_position_t& insert_pos, match_stage_t& insert_stage, node_offset_t& insert_size) override { - std::cout << "INSERT start: insert_pos(" << insert_pos - << "), insert_stage=" << (int)insert_stage - << ", insert_size=" << insert_size << " ..." << std::endl; + logger().debug("OTree::Layout::Insert: begin at " + "insert_pos({}), insert_stage={}, insert_size={}B ...", + insert_pos, insert_stage, insert_size); + if (unlikely(logger().is_enabled(seastar::log_level::trace))) { + std::ostringstream sos; + dump(sos); + logger().trace("OTree::Layout::Insert: -- dump\n{}", sos.str()); + } auto ret = extent.template insert_replayable( key, value, cast_down(insert_pos), insert_stage, insert_size); -#if 0 - dump(std::cout) << std::endl; -#endif - std::cout << "INSERT done: insert_pos(" << insert_pos - << "), insert_stage=" << (int)insert_stage - << ", insert_size=" << insert_size - << std::endl << std::endl; + logger().debug("OTree::Layout::Insert: done at " + "insert_pos({}), insert_stage={}, insert_size={}B", + insert_pos, insert_stage, insert_size); + if (unlikely(logger().is_enabled(seastar::log_level::trace))) { + std::ostringstream sos; + dump(sos); + logger().trace("OTree::Layout::Insert: -- dump\n{}", sos.str()); + } validate_layout(); assert(get_key_view(insert_pos) == key); return ret; @@ -267,15 +273,23 @@ class NodeLayoutT final : public InternalNodeImpl, public LeafNodeImpl { const full_key_t& key, const value_t& value, search_position_t& _insert_pos, match_stage_t& insert_stage, node_offset_t& insert_size) override { - std::cout << "SPLIT-INSERT start: insert_pos(" << _insert_pos - << "), insert_stage=" << (int)insert_stage - << ", insert_size=" << insert_size - << std::endl; + 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()); + if (unlikely(logger().is_enabled(seastar::log_level::debug))) { + std::ostringstream sos; + dump(sos); + logger().debug("OTree::Layout::Split: -- dump\n{}", sos.str()); + } + auto& insert_pos = cast_down(_insert_pos); auto& node_stage = extent.read(); typename STAGE_T::StagedIterator split_at; bool is_insert_left; - size_t split_size = 0; + size_t split_size; + size_t target_split_size; { size_t empty_size = node_stage.size_before(0); size_t filled_kv_size = filled_size() - empty_size; @@ -350,21 +364,21 @@ class NodeLayoutT final : public InternalNodeImpl, public LeafNodeImpl { * * (TODO) Implement smarter logics to check when "double split" happens. */ - size_t target_split_size = empty_size + (filled_kv_size + insert_size) / 2; + target_split_size = empty_size + (filled_kv_size + insert_size) / 2; assert(insert_size < (node_stage.total_size() - empty_size) / 2); std::optional _is_insert_left; split_at.set(node_stage); + split_size = 0; bool locate_nxt = STAGE_T::recursively_locate_split_inserted( split_size, 0, target_split_size, insert_pos, insert_stage, insert_size, _is_insert_left, split_at); is_insert_left = *_is_insert_left; - std::cout << "located_split: split_at(" << split_at << "), insert_pos(" << insert_pos - << "), is_insert_left=" << is_insert_left - << ", estimated_split_size=" << split_size - << "(target=" << target_split_size - << ", current=" << filled_size() - << ")" << std::endl; + logger().debug("OTree::Layout::Split: -- located " + "split_at({}), insert_pos({}), is_insert_left={}, " + "split_size={}B(target={}B, current={}B)", + split_at, insert_pos, is_insert_left, + split_size, target_split_size, filled_size()); // split_size can be larger than target_split_size in strategy B // assert(split_size <= target_split_size); if (locate_nxt) { @@ -384,9 +398,9 @@ class NodeLayoutT final : public InternalNodeImpl, public LeafNodeImpl { // right node: append [start(append_at), insert_pos) STAGE_T::template append_until( append_at, right_appender, insert_pos, insert_stage); - std::cout << "append-insert right: insert_pos(" << insert_pos - << "), insert_stage=" << (int)insert_stage - << " ..." << std::endl; + logger().debug("OTree::Layout::Split: -- right appended until " + "insert_pos({}), insert_stage={}, insert/append the rest ...", + insert_pos, insert_stage); // right node: append [insert_pos(key, value)] bool is_front_insert = (insert_pos == position_t::begin()); bool is_end = STAGE_T::template append_insert( @@ -394,7 +408,7 @@ class NodeLayoutT final : public InternalNodeImpl, public LeafNodeImpl { is_front_insert, insert_stage, p_value); assert(append_at.is_end() == is_end); } else { - std::cout << "append right ..." << std::endl; + logger().debug("OTree::Layout::Split: -- right appending ..."); } // right node: append (insert_pos, end) @@ -403,32 +417,40 @@ class NodeLayoutT final : public InternalNodeImpl, public LeafNodeImpl { append_at, right_appender, pos_end, STAGE); assert(append_at.is_end()); right_appender.wrap(); - right_impl.dump(std::cout) << std::endl; + if (unlikely(logger().is_enabled(seastar::log_level::debug))) { + std::ostringstream sos; + right_impl.dump(sos); + logger().debug("OTree::Layout::Split: -- right node dump\n{}", sos.str()); + } right_impl.validate_layout(); // mutate left node if (is_insert_left) { - std::cout << "trim-insert left: insert_pos(" << insert_pos - << "), insert_stage=" << (int)insert_stage - << " ..." << std::endl; + logger().debug("OTree::Layout::Split: -- left trim/insert at " + "insert_pos({}), insert_stage={} ...", + insert_pos, insert_stage); p_value = extent.template split_insert_replayable( split_at, key, value, insert_pos, insert_stage, insert_size); assert(get_key_view(_insert_pos) == key); } else { - std::cout << "trim left ..." << std::endl; + logger().debug("OTree::Layout::Split: -- left trim ..."); assert(right_impl.get_key_view(_insert_pos) == key); extent.split_replayable(split_at); } - dump(std::cout) << std::endl; + if (unlikely(logger().is_enabled(seastar::log_level::debug))) { + std::ostringstream sos; + dump(sos); + logger().debug("OTree::Layout::Split: -- left node dump\n{}", sos.str()); + } validate_layout(); assert(p_value); auto split_pos = normalize(split_at.get_pos()); - std::cout << "SPLIT-INSERT done: split_pos(" << split_pos - << "), insert_pos(" << _insert_pos - << "), insert_stage=" << (int)insert_stage - << ", insert_size=" << insert_size - << std::endl << std::endl; + logger().info("OTree::Layout::Split: done at " + "insert_pos({}), insert_stage={}, insert_size={}B, split_at({}), " + "is_insert_left={}, split_size={}B(target={}B)", + _insert_pos, insert_stage, insert_size, split_pos, + is_insert_left, split_size, target_split_size); assert(split_size == filled_size()); return {split_pos, is_insert_left, p_value}; } @@ -510,6 +532,10 @@ class NodeLayoutT final : public InternalNodeImpl, public LeafNodeImpl { return ret; } + static seastar::logger& logger() { + return crimson::get_logger(ceph_subsys_filestore); + } + extent_t extent; }; diff --git a/src/crimson/os/seastore/onode_manager/staged-fltree/node_layout_replayable.h b/src/crimson/os/seastore/onode_manager/staged-fltree/node_layout_replayable.h index 158094cbec4a..e26225a3a1cd 100644 --- a/src/crimson/os/seastore/onode_manager/staged-fltree/node_layout_replayable.h +++ b/src/crimson/os/seastore/onode_manager/staged-fltree/node_layout_replayable.h @@ -3,9 +3,6 @@ #pragma once -// TODO: remove -#include - #include "node_extent_mutable.h" #include "stages/node_stage.h" #include "stages/stage.h" diff --git a/src/test/crimson/seastore/onode_tree/test_staged_fltree.cc b/src/test/crimson/seastore/onode_tree/test_staged_fltree.cc index 70658c3ae132..f6d34edf873a 100644 --- a/src/test/crimson/seastore/onode_tree/test_staged_fltree.cc +++ b/src/test/crimson/seastore/onode_tree/test_staged_fltree.cc @@ -472,8 +472,8 @@ class TestTree { size_t onode_size) { return seastar::async([this, range_2, range_1, range_0, onode_size] { tree.mkfs(t).unsafe_get0(); - logger().info("\n---------------------------------------------" - "\nbefore leaf node split:\n"); + //logger().info("\n---------------------------------------------" + // "\nbefore leaf node split:\n"); auto keys = build_key_set(range_2, range_1, range_0); for (auto& key : keys) { auto& value = onodes.create(onode_size); @@ -481,9 +481,9 @@ class TestTree { } assert(tree.height(t).unsafe_get0() == 1); assert(!tree.test_is_clean()); - std::ostringstream oss; - tree.dump(t, oss); - logger().info("\n{}\n", oss.str()); + //std::ostringstream oss; + //tree.dump(t, oss); + //logger().info("\n{}\n", oss.str()); }); } @@ -491,8 +491,8 @@ class TestTree { const std::vector& keys, const std::vector& values) { return seastar::async([this, keys, values] { tree.mkfs(t).unsafe_get0(); - logger().info("\n---------------------------------------------" - "\nbefore leaf node split:\n"); + //logger().info("\n---------------------------------------------" + // "\nbefore leaf node split:\n"); assert(keys.size() == values.size()); auto key_iter = keys.begin(); auto value_iter = values.begin(); @@ -503,9 +503,9 @@ class TestTree { } assert(tree.height(t).unsafe_get0() == 1); assert(!tree.test_is_clean()); - std::ostringstream oss; - tree.dump(t, oss); - logger().info("\n{}\n", oss.str()); + //std::ostringstream oss; + //tree.dump(t, oss); + //logger().info("\n{}\n", oss.str()); }); } @@ -523,7 +523,7 @@ class TestTree { std::ostringstream oss; tree_clone.dump(t_clone, oss); - logger().info("\n{}\n", oss.str()); + logger().info("dump new root:\n{}\n", oss.str()); assert(tree_clone.height(t_clone).unsafe_get0() == 2); for (auto& [k, v, c] : insert_history) { @@ -887,9 +887,9 @@ class DummyChildPool { }); }); }).safe_then([this] { - std::ostringstream oss; - p_btree->dump(t(), oss); - logger().info("\n{}\n", oss.str()); + //std::ostringstream oss; + //p_btree->dump(t(), oss); + //logger().info("\n{}\n", oss.str()); return p_btree->height(t()); }).safe_then([](auto height) { assert(height == 2); @@ -912,7 +912,7 @@ class DummyChildPool { pool_clone.get_context(), key, pool_clone.splitable_nodes).unsafe_get0(); std::ostringstream oss; pool_clone.p_btree->dump(pool_clone.t(), oss); - logger().info("\n{}\n", oss.str()); + logger().info("dump new root:\n{}\n", oss.str()); assert(pool_clone.p_btree->height(pool_clone.t()).unsafe_get0() == 3); }); }