Add more trace points during (search) visitor execution

3 files changed, 32 insertions, 1 deletions

diff --git a/storage/src/vespa/storage/visiting/visitor.cpp b/storage/src/vespa/storage/visiting/visitor.cpp
index 28694185d77..9419f9e2034 100644
--- a/storage/src/vespa/storage/visiting/visitor.cpp
+++ b/storage/src/vespa/storage/visiting/visitor.cpp
@@ -656,6 +656,13 @@ Visitor::attach(std::shared_ptr<api::StorageCommand> initiatingCmd,
     }
 }
 
+bool
+Visitor::addBoundedTrace(uint32_t level, const vespalib::string &message) {
+    mbus::Trace tempTrace;
+    tempTrace.trace(level, message);
+    return _trace.add(tempTrace.getRoot());
+}
+
 void
 Visitor::handleDocumentApiReply(mbus::Reply::UP reply,
                         VisitorThreadMetrics& metrics)
@@ -970,6 +977,7 @@ Visitor::continueVisitor()
             if (isRunning()) {
                 LOG(debug, "Visitor '%s' has not been aborted", _id.c_str());
                 if (!_calledCompletedVisitor) {
+                    VISITOR_TRACE(7, "Visitor marked as complete, calling completedVisiting()");
                     _calledCompletedVisitor = true;
                     try{
                         completedVisiting(*_hitCounter);
@@ -978,6 +986,7 @@ Visitor::continueVisitor()
                             "callback.  As visitor is already complete, this "
                             "has been ignored: %s", _id.c_str(), e.what());
                     }
+                    VISITOR_TRACE(7, "completedVisiting() has finished");
 
                     // Visitor could create messages in completed visiting.
                     if (_messageSession->pending() > 0) {
diff --git a/storage/src/vespa/storage/visiting/visitor.h b/storage/src/vespa/storage/visiting/visitor.h
index bdf301a0d94..5fd16676fec 100644
--- a/storage/src/vespa/storage/visiting/visitor.h
+++ b/storage/src/vespa/storage/visiting/visitor.h
@@ -345,6 +345,17 @@ protected:
     framework::MemoryManagerInterface* _memoryManager;
 
     bool isCompletedCalled() const { return _calledCompletedVisitor; }
+
+    uint32_t traceLevel() const noexcept { return _traceLevel; }
+
+    /**
+     * Attempts to add the given trace message to the internal, memory bounded
+     * trace tree. Message will not be added if the trace is already exceeding
+     * maximum memory limits.
+     *
+     * Returns true iff message was added to internal trace tree.
+     */
+    bool addBoundedTrace(uint32_t level, const vespalib::string& message);
 public:
     Visitor(StorageComponent& component);
     virtual ~Visitor();
@@ -580,5 +591,13 @@ private:
     VisitorState transitionTo(VisitorState newState);
 };
 
+// Visitors use custom tracing logic to control the amount of memory used by
+// trace nodes. Wrap this in a somewhat more convenient macro to hide the details.
+// Can only be called by Visitor or its subclasses.
+#define VISITOR_TRACE(level, message) \
+    if (traceLevel() >= (level)) { \
+        addBoundedTrace(level, message); \
+    }
+
 } // storage
 
diff --git a/streamingvisitors/src/vespa/searchvisitor/searchvisitor.cpp b/streamingvisitors/src/vespa/searchvisitor/searchvisitor.cpp
index 8418dc81372..fa68c046aa6 100644
--- a/streamingvisitors/src/vespa/searchvisitor/searchvisitor.cpp
+++ b/streamingvisitors/src/vespa/searchvisitor/searchvisitor.cpp
@@ -190,6 +190,7 @@ SearchVisitor::SearchVisitor(StorageComponent& component,
 
 void SearchVisitor::init(const Parameters & params)
 {
+    VISITOR_TRACE(6, "About to lazily init VSM adapter");
     _attrMan.add(_documentIdAttributeBacking);
     _attrMan.add(_rankAttributeBacking);
     Parameters::ValueRef valueRef;
@@ -281,7 +282,8 @@ void SearchVisitor::init(const Parameters & params)
 
         Parameters::ValueRef queryBlob;
         if ( params.get("query", queryBlob) ) {
-            LOG(spam, "Received query blob of %zd bytes", queryBlob.size());
+            LOG(spam, "Received query blob of %zu bytes", queryBlob.size());
+            VISITOR_TRACE(9, vespalib::make_string("Setting up for query blob of %zu bytes", queryBlob.size()));
             QueryTermDataFactory addOnFactory;
             _query = search::Query(addOnFactory, search::QueryPacketT(queryBlob.data(), queryBlob.size()));
             LOG(debug, "Query tree: '%s'", _query.asString().c_str());
@@ -337,6 +339,7 @@ void SearchVisitor::init(const Parameters & params)
     } else {
         LOG(debug, "No unique specification received");
     }
+    VISITOR_TRACE(6, "Completed lazy VSM adapter initialization");
 }
 
 SearchVisitorFactory::SearchVisitorFactory(const config::ConfigUri & configUri)