Steal the traces explicit and force moving of traces. Also hide access to the root.

21 files changed, 72 insertions, 77 deletions

diff --git a/messagebus/src/vespa/messagebus/routable.h b/messagebus/src/vespa/messagebus/routable.h
index dbae90c9aa1..37b15199f45 100644
--- a/messagebus/src/vespa/messagebus/routable.h
+++ b/messagebus/src/vespa/messagebus/routable.h
@@ -24,9 +24,9 @@ namespace mbus {
  */
 class Routable {
 private:
-    Context   _context;
-    CallStack _stack;
-    Trace     _trace;
+    Context       _context;
+    CallStack     _stack;
+    mutable Trace _trace;
 
 public:
     /**
@@ -90,6 +90,7 @@ public:
      * @return Trace object
      */
     Trace &getTrace() { return _trace; }
+    Trace && steal_trace() const { return std::move(_trace); }
 
     /**
      * Access the Trace object for this Routable. The Trace is part of the
diff --git a/messagebus/src/vespa/messagebus/routing/routingnode.cpp b/messagebus/src/vespa/messagebus/routing/routingnode.cpp
index cc8dd236428..5a70f510dcc 100644
--- a/messagebus/src/vespa/messagebus/routing/routingnode.cpp
+++ b/messagebus/src/vespa/messagebus/routing/routingnode.cpp
@@ -184,7 +184,7 @@ RoutingNode::setReply(Reply::UP reply)
 {
     if (reply) {
         _shouldRetry = _resender != nullptr && _resender->shouldRetry(*reply);
-        _trace.addChild(std::move(reply->getTrace()));
+        _trace.addChild(reply->steal_trace());
     }
     _reply = std::move(reply);
 }
diff --git a/messagebus/src/vespa/messagebus/sendproxy.cpp b/messagebus/src/vespa/messagebus/sendproxy.cpp
index 9d8bcb965d6..ff514f788cd 100644
--- a/messagebus/src/vespa/messagebus/sendproxy.cpp
+++ b/messagebus/src/vespa/messagebus/sendproxy.cpp
@@ -55,7 +55,7 @@ SendProxy::handleReply(Reply::UP reply)
         }
         trace.clear();
     } else if (trace.getLevel() > 0) {
-        trace.addChild(std::move(reply->getTrace()));
+        trace.addChild(reply->steal_trace());
         trace.normalize();
     }
     reply->swapState(*_msg);
diff --git a/persistence/src/vespa/persistence/spi/context.h b/persistence/src/vespa/persistence/spi/context.h
index 8c31439ee75..a1cb9e68f31 100644
--- a/persistence/src/vespa/persistence/spi/context.h
+++ b/persistence/src/vespa/persistence/spi/context.h
@@ -76,6 +76,7 @@ public:
         return _readConsistency;
     }
 
+    vespalib::Trace && steal_trace() { return std::move(_trace); }
     vespalib::Trace& getTrace() { return _trace; }
     const vespalib::Trace& getTrace() const { return _trace; }
 
diff --git a/storage/src/vespa/storage/distributor/operations/external/getoperation.cpp b/storage/src/vespa/storage/distributor/operations/external/getoperation.cpp
index 3adc8d731ee..c72e5731a59 100644
--- a/storage/src/vespa/storage/distributor/operations/external/getoperation.cpp
+++ b/storage/src/vespa/storage/distributor/operations/external/getoperation.cpp
@@ -144,7 +144,7 @@ GetOperation::onReceive(DistributorMessageSender& sender, const std::shared_ptr<
 
     LOG(debug, "Received %s", msg->toString(true).c_str());
 
-    _msg->getTrace().addChild(std::move(getreply->getTrace()));
+    _msg->getTrace().addChild(getreply->steal_trace());
     bool allDone = true;
     for (auto& response : _responses) {
         for (uint32_t i = 0; i < response.second.size(); i++) {
diff --git a/storage/src/vespa/storage/distributor/operations/external/twophaseupdateoperation.cpp b/storage/src/vespa/storage/distributor/operations/external/twophaseupdateoperation.cpp
index 68738e0b296..4deaf0b23f3 100644
--- a/storage/src/vespa/storage/distributor/operations/external/twophaseupdateoperation.cpp
+++ b/storage/src/vespa/storage/distributor/operations/external/twophaseupdateoperation.cpp
@@ -646,7 +646,7 @@ TwoPhaseUpdateOperation::satisfiesUpdateTimestampConstraint(api::Timestamp ts) c
 void
 TwoPhaseUpdateOperation::addTraceFromReply(const api::StorageReply& reply)
 {
-    _trace.addChild(std::move(reply.getTrace()));
+    _trace.addChild(reply.steal_trace());
 }
 
 void
diff --git a/storage/src/vespa/storage/distributor/operations/external/visitoroperation.cpp b/storage/src/vespa/storage/distributor/operations/external/visitoroperation.cpp
index 85bf397ebbc..616fd312723 100644
--- a/storage/src/vespa/storage/distributor/operations/external/visitoroperation.cpp
+++ b/storage/src/vespa/storage/distributor/operations/external/visitoroperation.cpp
@@ -171,7 +171,7 @@ VisitorOperation::onReceive(
 {
     api::CreateVisitorReply& reply = static_cast<api::CreateVisitorReply&>(*r);
 
-    _trace.add(reply.getTrace());
+    _trace.add(reply.steal_trace());
 
     SentMessagesMap::iterator iter = _sentMessages.find(reply.getMsgId());
     assert(iter != _sentMessages.end());
diff --git a/storage/src/vespa/storage/distributor/persistencemessagetracker.cpp b/storage/src/vespa/storage/distributor/persistencemessagetracker.cpp
index c3598e7add5..584cb379400 100644
--- a/storage/src/vespa/storage/distributor/persistencemessagetracker.cpp
+++ b/storage/src/vespa/storage/distributor/persistencemessagetracker.cpp
@@ -22,6 +22,7 @@ PersistenceMessageTrackerImpl::PersistenceMessageTrackerImpl(
       _reply(std::move(reply)),
       _manager(link),
       _revertTimestamp(revertTimestamp),
+      _trace(_reply->getTrace().getLevel()),
       _requestTimer(link.getClock()),
       _n_persistence_replies_total(0),
       _n_successful_persistence_replies(0),
@@ -163,25 +164,18 @@ PersistenceMessageTrackerImpl::addBucketInfoFromReply(
             bucket.toString().c_str(),
             bucketInfo.toString().c_str(),
             node);
-        _remapBucketInfo[bucket].push_back(
-                BucketCopy(_manager.getUniqueTimestamp(),
-                           node,
-                           bucketInfo));
+        _remapBucketInfo[bucket].emplace_back(_manager.getUniqueTimestamp(), node, bucketInfo);
     } else {
         LOG(debug, "Bucket %s: Received bucket info %s from node %d",
             bucket.toString().c_str(),
             bucketInfo.toString().c_str(),
             node);
-        _bucketInfo[bucket].push_back(
-                BucketCopy(_manager.getUniqueTimestamp(),
-                           node,
-                           bucketInfo));
+        _bucketInfo[bucket].emplace_back(_manager.getUniqueTimestamp(), node, bucketInfo);
     }
 }
 
 void
-PersistenceMessageTrackerImpl::logSuccessfulReply(uint16_t node, 
-                                              const api::BucketInfoReply& reply) const
+PersistenceMessageTrackerImpl::logSuccessfulReply(uint16_t node, const api::BucketInfoReply& reply) const
 {
     LOG(spam, "Bucket %s: Received successful reply %s",
         reply.getBucketId().toString().c_str(),
@@ -292,9 +286,7 @@ PersistenceMessageTrackerImpl::updateFromReply(
         api::BucketInfoReply& reply,
         uint16_t node)
 {
-    if ( ! reply.getTrace().isEmpty()) {
-        _trace.addChild(reply.getTrace().getRoot());
-    }
+    _trace.addChild(reply.steal_trace());
 
     if (reply.getType() == api::MessageType::CREATEBUCKET_REPLY) {
         handleCreateBucketReply(reply, node);
diff --git a/storage/src/vespa/storage/distributor/persistencemessagetracker.h b/storage/src/vespa/storage/distributor/persistencemessagetracker.h
index 4392aa1fc30..cf9f4017eda 100644
--- a/storage/src/vespa/storage/distributor/persistencemessagetracker.h
+++ b/storage/src/vespa/storage/distributor/persistencemessagetracker.h
@@ -73,7 +73,7 @@ private:
     DistributorComponent& _manager;
     api::Timestamp _revertTimestamp;
     std::vector<BucketNodePair> _revertNodes;
-    mbus::TraceNode _trace;
+    mbus::Trace _trace;
     framework::MilliSecTimer _requestTimer;
     uint32_t _n_persistence_replies_total;
     uint32_t _n_successful_persistence_replies;
diff --git a/storage/src/vespa/storage/persistence/filestorage/filestormanager.cpp b/storage/src/vespa/storage/persistence/filestorage/filestormanager.cpp
index a21cdb9579d..54c1c7606b2 100644
--- a/storage/src/vespa/storage/persistence/filestorage/filestormanager.cpp
+++ b/storage/src/vespa/storage/persistence/filestorage/filestormanager.cpp
@@ -676,7 +676,7 @@ FileStorManager::onInternal(const shared_ptr<api::InternalCommand>& msg)
         spi::Context context(msg->getLoadType(), msg->getPriority(), msg->getTrace().getLevel());
         shared_ptr<DestroyIteratorCommand> cmd(std::static_pointer_cast<DestroyIteratorCommand>(msg));
         _provider->destroyIterator(cmd->getIteratorId(), context);
-        msg->getTrace().addChild(std::move(context.getTrace()));
+        msg->getTrace().addChild(context.steal_trace());
         return true;
     }
     case ReadBucketList::ID:
diff --git a/storage/src/vespa/storage/persistence/persistenceutil.cpp b/storage/src/vespa/storage/persistence/persistenceutil.cpp
index d41ec4e88d6..9a7107fb583 100644
--- a/storage/src/vespa/storage/persistence/persistenceutil.cpp
+++ b/storage/src/vespa/storage/persistence/persistenceutil.cpp
@@ -93,7 +93,7 @@ MessageTracker::sendReply() {
               _msg->toString(true).c_str(), vespalib::to_s(duration));
     }
     if (hasReply()) {
-        getReply().getTrace().addChild(std::move(_context.getTrace()));
+        getReply().getTrace().addChild(_context.steal_trace());
         if (_updateBucketInfo) {
             if (getReply().getResult().success()) {
                 _env.setBucketInfo(*this, _bucketLock->getBucket());
@@ -105,7 +105,7 @@ MessageTracker::sendReply() {
         LOG(spam, "Sending reply up: %s %" PRIu64, getReply().toString().c_str(), getReply().getMsgId());
         _replySender.sendReplyDirectly(std::move(_reply));
     } else {
-        _msg->getTrace().addChild(std::move(_context.getTrace()));
+        _msg->getTrace().addChild(_context.steal_trace());
     }
 }
 
diff --git a/storage/src/vespa/storage/storageserver/communicationmanager.cpp b/storage/src/vespa/storage/storageserver/communicationmanager.cpp
index 6ad5410765f..c89d88d86ef 100644
--- a/storage/src/vespa/storage/storageserver/communicationmanager.cpp
+++ b/storage/src/vespa/storage/storageserver/communicationmanager.cpp
@@ -583,7 +583,7 @@ CommunicationManager::sendCommand(
             cmd->setContext(mbus::Context(msg->getMsgId()));
             cmd->setRetryEnabled(false);
             cmd->setTimeRemaining(msg->getTimeout());
-            cmd->setTrace(vespalib::Trace(msg->getTrace()));  //TODO Refactor so that we can move instead
+            cmd->setTrace(std::move(msg->getTrace()));
             sendMessageBusMessage(msg, std::move(cmd), address.getRoute());
         }
         break;
@@ -596,7 +596,7 @@ CommunicationManager::sendCommand(
 
         if (mbusMsg) {
             MBUS_TRACE(msg->getTrace(), 7, "Communication manager: Converted OK");
-            mbusMsg->setTrace(vespalib::Trace(msg->getTrace())); //TODO Refactor so that we can move instead
+            mbusMsg->setTrace(std::move(msg->getTrace()));
             mbusMsg->setRetryEnabled(false);
 
             {
diff --git a/storage/src/vespa/storage/visiting/memory_bounded_trace.cpp b/storage/src/vespa/storage/visiting/memory_bounded_trace.cpp
index bfa4c2aa07d..05bb026f238 100644
--- a/storage/src/vespa/storage/visiting/memory_bounded_trace.cpp
+++ b/storage/src/vespa/storage/visiting/memory_bounded_trace.cpp
@@ -6,7 +6,7 @@
 namespace storage {
 
 MemoryBoundedTrace::MemoryBoundedTrace(size_t softMemoryUpperBound)
-    : _node(),
+    : _trace(),
       _currentMemoryUsed(0),
       _omittedNodes(0),
       _omittedBytes(0),
@@ -14,35 +14,32 @@ MemoryBoundedTrace::MemoryBoundedTrace(size_t softMemoryUpperBound)
 {
 }
 
-namespace {
-
-size_t
-computeTraceTreeMemoryUsage(const mbus::TraceNode& node)
+bool
+MemoryBoundedTrace::add(const mbus::TraceNode& node)
 {
-    if (node.isLeaf()) {
-        return node.getNote().size();
-    }
-    size_t childSum = 0;
-    const uint32_t childCount = node.getNumChildren();
-    for (uint32_t i = 0; i < childCount; ++i) {
-        childSum += computeTraceTreeMemoryUsage(node.getChild(i));
+    const size_t nodeFootprint = node.computeMemoryUsage();
+
+    if (_currentMemoryUsed >= _softMemoryUpperBound) {
+        ++_omittedNodes;
+        _omittedBytes += nodeFootprint;
+        return false;
     }
-    return childSum;
+    _trace.addChild(vespalib::TraceNode(node));
+    _currentMemoryUsed += nodeFootprint;
+    return true;
 }
 
-} // anon ns
-
 bool
-MemoryBoundedTrace::add(const mbus::TraceNode& node)
+MemoryBoundedTrace::add(mbus::Trace && node)
 {
-    const size_t nodeFootprint = computeTraceTreeMemoryUsage(node);
+    const size_t nodeFootprint = node.computeMemoryUsage();
 
     if (_currentMemoryUsed >= _softMemoryUpperBound) {
         ++_omittedNodes;
         _omittedBytes += nodeFootprint;
         return false;
     }
-    _node.addChild(node);
+    _trace.addChild(std::move(node));
     _currentMemoryUsed += nodeFootprint;
     return true;
 }
@@ -50,17 +47,16 @@ MemoryBoundedTrace::add(const mbus::TraceNode& node)
 void
 MemoryBoundedTrace::moveTraceTo(mbus::Trace& out)
 {
-    if (_node.isEmpty()) {
+    if (_trace.isEmpty()) {
         return;
     }
     if (_omittedNodes > 0) {
-        _node.addChild(vespalib::make_string(
+        _trace.trace(0, vespalib::make_string(
                 "Trace too large; omitted %zu subsequent trace trees "
                 "containing a total of %zu bytes",
-                _omittedNodes, _omittedBytes));
+                _omittedNodes, _omittedBytes), false);
     }
-    out.addChild(std::move(_node)); // XXX rvalue support should be added to TraceNode.
-    _node.clear();
+    out.addChild(std::move(_trace));
     _currentMemoryUsed = 0;
     _omittedNodes = 0;
     _omittedBytes = 0;
diff --git a/storage/src/vespa/storage/visiting/memory_bounded_trace.h b/storage/src/vespa/storage/visiting/memory_bounded_trace.h
index a7f8a00d6a9..2c75c809af6 100644
--- a/storage/src/vespa/storage/visiting/memory_bounded_trace.h
+++ b/storage/src/vespa/storage/visiting/memory_bounded_trace.h
@@ -23,12 +23,7 @@ public:
      * otherwise.
      */
     bool add(const mbus::TraceNode& node);
-    bool add(const mbus::Trace& trace) {
-        if (!trace.isEmpty()) {
-            return add(trace.getRoot());
-        }
-        return false;
-    }
+    bool add(mbus::Trace && trace);
 
     /**
      * Append current trace tree to the output trace node and clear internal
@@ -46,7 +41,7 @@ public:
     }
 
 private:
-    mbus::TraceNode _node;
+    mbus::Trace _trace;
     size_t _currentMemoryUsed;
     size_t _omittedNodes;
     size_t _omittedBytes;
diff --git a/storage/src/vespa/storage/visiting/visitor.cpp b/storage/src/vespa/storage/visiting/visitor.cpp
index c7825cd2e6f..9dee798de84 100644
--- a/storage/src/vespa/storage/visiting/visitor.cpp
+++ b/storage/src/vespa/storage/visiting/visitor.cpp
@@ -601,15 +601,14 @@ bool
 Visitor::addBoundedTrace(uint32_t level, const vespalib::string &message) {
     mbus::Trace tempTrace;
     tempTrace.trace(level, message);
-    return _trace.add(tempTrace);
+    return _trace.add(std::move(tempTrace));
 }
 
 void
-Visitor::handleDocumentApiReply(mbus::Reply::UP reply,
-                        VisitorThreadMetrics& metrics)
+Visitor::handleDocumentApiReply(mbus::Reply::UP reply, VisitorThreadMetrics& metrics)
 {
     if (shouldAddMbusTrace()) {
-        _trace.add(reply->getTrace()); //TODO Can it be moved ?
+        _trace.add(reply->steal_trace());
     }
 
     mbus::Message::UP message = reply->getMessage();
@@ -830,7 +829,7 @@ Visitor::onGetIterReply(const std::shared_ptr<GetIterReply>& reply,
     }
 
     if (shouldAddMbusTrace()) {
-        _trace.add(reply->getTrace()); //TODO Can it be moved ?
+        _trace.add(reply->steal_trace());
     }
 
     LOG(debug, "Continuing visitor %s.", _id.c_str());
diff --git a/storageapi/src/vespa/storageapi/messageapi/storagemessage.h b/storageapi/src/vespa/storageapi/messageapi/storagemessage.h
index 136972f67a5..f26159758b9 100644
--- a/storageapi/src/vespa/storageapi/messageapi/storagemessage.h
+++ b/storageapi/src/vespa/storageapi/messageapi/storagemessage.h
@@ -361,8 +361,8 @@ protected:
     const MessageType& _type;
     Id                 _msgId;
     std::unique_ptr<StorageMessageAddress> _address;
-    documentapi::LoadType _loadType;
-    vespalib::Trace       _trace;
+    documentapi::LoadType    _loadType;
+    mutable vespalib::Trace  _trace;
     uint32_t    _approxByteSize;
     Priority    _priority;
 
@@ -435,6 +435,7 @@ public:
     const documentapi::LoadType& getLoadType() const { return _loadType; }
     void setLoadType(const documentapi::LoadType& type) { _loadType = type; }
 
+    mbus::Trace && steal_trace() const { return std::move(_trace); }
     mbus::Trace& getTrace() { return _trace; }
     const mbus::Trace& getTrace() const { return _trace; }
 
diff --git a/vespalib/src/tests/trace/trace.cpp b/vespalib/src/tests/trace/trace.cpp
index 46ebaf95114..992317b0289 100644
--- a/vespalib/src/tests/trace/trace.cpp
+++ b/vespalib/src/tests/trace/trace.cpp
@@ -264,7 +264,7 @@ TEST("testTraceDump")
             big.addChild(TraceNode(b1));
         }
         string normal = big.toString();
-        string full = big.getRoot().toString();
+        string full = big.toString(100000);
         EXPECT_GREATER(normal.size(), 30000u);
         EXPECT_LESS(normal.size(), 32000u);
         EXPECT_GREATER(full.size(), 50000u);
diff --git a/vespalib/src/vespa/vespalib/trace/trace.cpp b/vespalib/src/vespa/vespalib/trace/trace.cpp
index df9b5111d70..be370aebbd2 100644
--- a/vespalib/src/vespa/vespalib/trace/trace.cpp
+++ b/vespalib/src/vespa/vespalib/trace/trace.cpp
@@ -32,8 +32,8 @@ Trace::trace(uint32_t level, const string &note, bool addTime)
 }
 
 string
-Trace::toString() const {
-    return _root ? _root->toString(31337) : "";
+Trace::toString(size_t limit) const {
+    return _root ? _root->toString(limit) : "";
 }
 
 string
diff --git a/vespalib/src/vespa/vespalib/trace/trace.h b/vespalib/src/vespa/vespalib/trace/trace.h
index 2931cd16829..2f70785d77d 100644
--- a/vespalib/src/vespa/vespalib/trace/trace.h
+++ b/vespalib/src/vespa/vespalib/trace/trace.h
@@ -95,15 +95,6 @@ public:
             addChild(std::move(*child._root));
         }
     }
-    //TODO This one should go away as we should prefer moving
-    void addChild(const Trace & child) {
-        if (!child.isEmpty()) {
-            addChild(TraceNode(*child._root));
-        }
-    }
-
-    //TODO This one should go away
-    const TraceNode &getRoot() const { return *_root; }
 
     bool isEmpty() const { return !_root || _root->isEmpty(); }
 
@@ -117,8 +108,12 @@ public:
      *
      * @return Readable trace string.
      */
-    string toString() const;
+    string toString(size_t limit=31337) const;
+    size_t computeMemoryUsage() const {
+        return _root ? _root->computeMemoryUsage() : 0;
+    }
 private:
+    const TraceNode &getRoot() const { return *_root; }
     TraceNode &ensureRoot();
 
     std::unique_ptr<TraceNode> _root;
diff --git a/vespalib/src/vespa/vespalib/trace/tracenode.cpp b/vespalib/src/vespa/vespalib/trace/tracenode.cpp
index 0f845ca646a..12dd51ac677 100644
--- a/vespalib/src/vespa/vespalib/trace/tracenode.cpp
+++ b/vespalib/src/vespa/vespalib/trace/tracenode.cpp
@@ -342,4 +342,17 @@ TraceNode::accept(TraceVisitor & visitor) const
     return visitor;
 }
 
+size_t
+TraceNode::computeMemoryUsage() const
+{
+    if (isLeaf()) {
+        return getNote().size();
+    }
+    size_t childSum = 0;
+    for (const TraceNode & child : _children) {
+        childSum += child.computeMemoryUsage();
+    }
+    return childSum;
+}
+
 } // namespace vespalib
diff --git a/vespalib/src/vespa/vespalib/trace/tracenode.h b/vespalib/src/vespa/vespalib/trace/tracenode.h
index 405c7d994da..7a7cdb89c69 100644
--- a/vespalib/src/vespa/vespalib/trace/tracenode.h
+++ b/vespalib/src/vespa/vespalib/trace/tracenode.h
@@ -253,6 +253,8 @@ public:
      */
     TraceVisitor & accept(TraceVisitor & visitor) const;
 
+    size_t computeMemoryUsage() const;
+
 };
 
 } // namespace vespalib