Merge pull request #8771 from vespa-engine/balder/lazy-trace

Make the Trace object itself lazy

5 files changed, 66 insertions, 31 deletions

diff --git a/searchlib/src/tests/engine/searchapi/searchapi_test.cpp b/searchlib/src/tests/engine/searchapi/searchapi_test.cpp
index 2f2cf4f22e5..ed103bf501c 100644
--- a/searchlib/src/tests/engine/searchapi/searchapi_test.cpp
+++ b/searchlib/src/tests/engine/searchapi/searchapi_test.cpp
@@ -237,27 +237,25 @@ void verify(vespalib::stringref expected, const vespalib::Slime & slime) {
 TEST("verify trace") {
     RelativeTime clock(std::make_unique<CountingClock>(fastos::TimeStamp::fromSec(1500000000), 1700000L));
     Trace t(clock);
-    verify("{"
-           "    traces: ["
-           "    ],"
-           "    start_time_utc: '2017-07-14 02:40:00.000 UTC'"
-           "}",
-           t.getSlime());
+    EXPECT_FALSE(t.hasTrace());
+    t.start(0);
+    EXPECT_TRUE(t.hasTrace());
     t.createCursor("tag_a");
     verify("{"
+           "    start_time_utc: '2017-07-14 02:40:00.000 UTC',"
            "    traces: ["
            "        {"
            "            tag: 'tag_a',"
            "            timestamp_ms: 1.7"
            "        }"
-           "    ],"
-           "    start_time_utc: '2017-07-14 02:40:00.000 UTC'"
+           "    ]"
            "}",
            t.getSlime());
     Trace::Cursor & tagB = t.createCursor("tag_b");
     tagB.setLong("long", 19);
     t.done();
     verify("{"
+           "    start_time_utc: '2017-07-14 02:40:00.000 UTC',"
            "    traces: ["
            "        {"
            "            tag: 'tag_a',"
@@ -269,7 +267,6 @@ TEST("verify trace") {
            "            long: 19"
            "        }"
            "    ],"
-           "    start_time_utc: '2017-07-14 02:40:00.000 UTC',"
            "    duration_ms: 5.1"
            "}",
            t.getSlime());
diff --git a/searchlib/src/vespa/searchlib/engine/packetconverter.cpp b/searchlib/src/vespa/searchlib/engine/packetconverter.cpp
index c35ce9ded05..863c204f26c 100644
--- a/searchlib/src/vespa/searchlib/engine/packetconverter.cpp
+++ b/searchlib/src/vespa/searchlib/engine/packetconverter.cpp
@@ -1,7 +1,6 @@
 // Copyright 2017 Yahoo Holdings. Licensed under the terms of the Apache 2.0 license. See LICENSE in the project root.
 
 #include "packetconverter.h"
-#include <vespa/searchlib/fef/indexproperties.h>
 
 #include <vespa/log/log.h>
 LOG_SETUP(".engine.packetconverter");
@@ -74,7 +73,6 @@ PacketConverter::toSearchRequest(const QUERYX &packet, SearchRequest &request)
     request.location        = packet._location;
     request.stackItems      = packet._numStackItems;
     request.stackDump.assign( packet._stackDump.begin(), packet._stackDump.end());
-    request.setTraceLevel(search::fef::indexproperties::trace::Level::lookup(request.propertiesMap.modelOverrides()));
 }
 
 void
diff --git a/searchlib/src/vespa/searchlib/engine/request.h b/searchlib/src/vespa/searchlib/engine/request.h
index 733043b0e4e..ab46b5d40fe 100644
--- a/searchlib/src/vespa/searchlib/engine/request.h
+++ b/searchlib/src/vespa/searchlib/engine/request.h
@@ -30,7 +30,10 @@ public:
 
     bool should_drop_sort_data() const;
 
-    Request & setTraceLevel(uint32_t level) { _trace.setLevel(level); return *this; }
+    void setTraceLevel(uint32_t level, uint32_t minLevel) const {
+        _trace.setLevel(level);
+        _trace.start(minLevel);
+    }
 
     Trace & trace() const { return _trace; }
 private:
diff --git a/searchlib/src/vespa/searchlib/engine/trace.cpp b/searchlib/src/vespa/searchlib/engine/trace.cpp
index ba92902d2fd..f9564846104 100644
--- a/searchlib/src/vespa/searchlib/engine/trace.cpp
+++ b/searchlib/src/vespa/searchlib/engine/trace.cpp
@@ -10,30 +10,38 @@ RelativeTime::RelativeTime(std::unique_ptr<Clock> clock)
       _clock(std::move(clock))
 {}
 
-namespace {
-
-Trace::Cursor &
-createRoot(vespalib::Slime & slime, const RelativeTime & relativeTime) {
-    Trace::Cursor & root = slime.setObject();
-    root.setString("start_time_utc", relativeTime.timeOfDawn().toString());
-    return root;
+void
+Trace::constructObject() const {
+    _trace = std::make_unique<vespalib::Slime>();
+    _root = & _trace->setObject();
 }
 
+void
+Trace::constructTraces() const {
+    _traces = & root().setArray("traces");
 }
+
 Trace::Trace(const RelativeTime & relativeTime, uint32_t level)
-    : _trace(std::make_unique<vespalib::Slime>()),
-      _root(createRoot(*_trace, relativeTime)),
-      _traces(_root.setArray("traces")),
+    : _trace(),
+      _root(nullptr),
+      _traces(nullptr),
       _relativeTime(relativeTime),
       _level(level)
 {
 }
 
+void
+Trace::start(int level) {
+    if (shouldTrace(level) && !hasTrace()) {
+        root().setString("start_time_utc", _relativeTime.timeOfDawn().toString());
+    }
+}
+
 Trace::~Trace() = default;
 
 Trace::Cursor &
 Trace::createCursor(vespalib::stringref name) {
-    Cursor & trace = _traces.addObject();
+    Cursor & trace = traces().addObject();
     addTimeStamp(trace);
     trace.setString("tag", name);
     return trace;
@@ -48,7 +56,7 @@ void
 Trace::addEvent(uint32_t level, vespalib::stringref event) {
     if (!shouldTrace(level)) { return; }
 
-    Cursor & trace = _traces.addObject();
+    Cursor & trace = traces().addObject();
     addTimeStamp(trace);
     trace.setString("event", event);
 }
@@ -59,12 +67,14 @@ Trace::addTimeStamp(Cursor & trace) {
 }
 
 void Trace::done() {
-    _root.setDouble("duration_ms", _relativeTime.timeSinceDawn()/1000000.0);
+    if (!hasTrace()) { return; }
+
+    root().setDouble("duration_ms", _relativeTime.timeSinceDawn()/1000000.0);
 }
 
 vespalib::string
 Trace::toString() const {
-    return _trace->toString();
+    return hasTrace() ? slime().toString() : "";
 }
 
 }
diff --git a/searchlib/src/vespa/searchlib/engine/trace.h b/searchlib/src/vespa/searchlib/engine/trace.h
index 41f2c608615..e5fea4f2b7f 100644
--- a/searchlib/src/vespa/searchlib/engine/trace.h
+++ b/searchlib/src/vespa/searchlib/engine/trace.h
@@ -57,6 +57,12 @@ public:
     ~Trace();
 
     /**
+     * Will add start timestamp if level is high enough
+     * @param level
+     */
+    void start(int level);
+
+    /**
      * Will give you a trace entry. It will also add a timestamp relative to the creation of the trace.
      * @param name
      * @return a Cursor to use for further tracing.
@@ -76,17 +82,38 @@ public:
     void done();
 
     vespalib::string toString() const;
-    Cursor & getRoot() const { return _root; }
-    vespalib::Slime & getSlime() const { return *_trace; }
+    bool hasTrace() const { return static_cast<bool>(_trace); }
+    Cursor & getRoot() const { return root(); }
+    vespalib::Slime & getSlime() const { return slime(); }
     bool shouldTrace(uint32_t level) const { return level <= _level; }
     uint32_t getLevel() const { return _level; }
     Trace & setLevel(uint32_t level) { _level = level; return *this; }
     const RelativeTime & getRelativeTime() const { return _relativeTime; }
 private:
+    vespalib::Slime & slime() const {
+        if (!hasTrace()) {
+            constructObject();
+        }
+        return *_trace;
+    }
+    Cursor & root() const {
+        if (!hasTrace()) {
+            constructObject();
+        }
+        return *_root;
+    }
+    Cursor & traces() const {
+        if (!_traces) {
+            constructTraces();
+        }
+        return *_traces;
+    }
+    void constructObject() const;
+    void constructTraces() const;
     void addTimeStamp(Cursor & trace);
-    std::unique_ptr<vespalib::Slime> _trace;
-    Cursor              & _root;
-    Cursor              & _traces;
+    mutable std::unique_ptr<vespalib::Slime> _trace;
+    mutable Cursor              * _root;
+    mutable Cursor              * _traces;
     const RelativeTime  & _relativeTime;
     uint32_t              _level;
 };