]> git-server-git.apps.pok.os.sepia.ceph.com Git - ceph.git/commitdiff
crimson/onode-staged-tree: proper logging and dump
authorYingxin Cheng <yingxin.cheng@intel.com>
Mon, 12 Oct 2020 05:15:56 +0000 (13:15 +0800)
committerYingxin Cheng <yingxin.cheng@intel.com>
Tue, 1 Dec 2020 04:50:54 +0000 (12:50 +0800)
Signed-off-by: Yingxin Cheng <yingxin.cheng@intel.com>
src/crimson/os/seastore/onode_manager/staged-fltree/node.cc
src/crimson/os/seastore/onode_manager/staged-fltree/node_extent_manager/dummy.h
src/crimson/os/seastore/onode_manager/staged-fltree/node_extent_manager/seastore.h
src/crimson/os/seastore/onode_manager/staged-fltree/node_layout.h
src/crimson/os/seastore/onode_manager/staged-fltree/node_layout_replayable.h
src/test/crimson/seastore/onode_tree/test_staged_fltree.cc

index f97e120444e740db3ebc20788e8a0873a5e9f259..c69542d88600fe6f1a88b6cf93c489bad679d37b 100644 (file)
@@ -5,13 +5,20 @@
 
 #include <cassert>
 #include <exception>
-#include <iostream>
+#include <sstream>
 
 #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<Ref<Node>> InternalNode::get_or_track_child(
   auto found = tracked_child_nodes.find(position);
   Ref<InternalNode> 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<Ref<Node>>(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<Ref<Node>>(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<Ref<tree_cursor_t>> 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);
index de0142680f77c5089ee1dd29ea68063ce262fed9..f54db62c018d2419aaa20ded35961f9c69fa7895 100644 (file)
@@ -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<NodeExtentRef> 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<NodeExtentRef> 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<Super::URef> 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<NodeExtentRef>(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<NodeExtentRef>(extent);
   }
 
   tm_future<NodeExtentRef> 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<NodeExtentRef>(extent);
   }
 
   tm_future<Super::URef> get_super_sync(
       Transaction& t, RootNodeTracker& tracker) {
+    logger().debug("OTree::Dummy: got root {:#x}", root_laddr);
     return tm_ertr::make_ready_future<Super::URef>(
         Super::URef(new DummySuper(t, tracker, &root_laddr)));
   }
 
+  static seastar::logger& logger() {
+    return crimson::get_logger(ceph_subsys_filestore);
+  }
+
   std::map<laddr_t, Ref<DummyNodeExtent>> allocate_map;
   laddr_t root_laddr = L_ADDR_NULL;
 };
index e041a68dec168608792a9ff29ba188c236be9365..38a0afd222afebc18cc9259297cdadc75e920ed1 100644 (file)
@@ -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<NodeExtentRef> 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<SeastoreNodeExtent>(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<NodeExtentRef> alloc_extent(
       Transaction& t, extent_len_t len) override {
+    logger().debug("OTree::Seastore: allocating {}B ...", len);
     return tm.alloc_extent<SeastoreNodeExtent>(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<Super::URef> 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<SeastoreNodeExtentManager*>(&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<SeastoreNodeExtentManager*>(&c.nm);
   auto ret = nm->get_tm().get_mutable_extent(c.t, this);
   return ret->cast<SeastoreNodeExtent>();
index 6757966c0435a6115b9186e25be1318ef3229f0a..f9dd44d3f57c624f9e449d2bcae5ee891e4b267f 100644 (file)
@@ -3,11 +3,11 @@
 
 #pragma once
 
-// TODO: remove
-#include <iostream>
 #include <ostream>
+#include <sstream>
 
 #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_TYPE>& 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_TYPE>(
         key, value, cast_down<STAGE>(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_TYPE>& 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<STAGE>(_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<bool> _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<KEY_TYPE>(
           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<KEY_TYPE>(
@@ -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<KEY_TYPE>(
           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;
 };
 
index 158094cbec4aaab037c4b3c3693e3db82869b989..e26225a3a1cd62c90d1816d9bb6f9e733436cdf3 100644 (file)
@@ -3,9 +3,6 @@
 
 #pragma once
 
-// TODO: remove
-#include <iostream>
-
 #include "node_extent_mutable.h"
 #include "stages/node_stage.h"
 #include "stages/stage.h"
index 70658c3ae132b7709472015499a2632c3fb9d7b2..f6d34edf873a9c0060ecf6ddee66a9c9b2aa15a1 100644 (file)
@@ -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<ghobject_t>& keys, const std::vector<const onode_t*>& 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);
     });
   }