Make the Trace object itself lazy

Make start optional and explicit.

5 files changed, 67 insertions, 30 deletions

diff --git a/searchlib/src/tests/engine/searchapi/searchapi_test.cpp b/searchlib/src/tests/engine/searchapi/searchapi_test.cpp
index 2f2cf4f22e5..28c90dd18ca 100644
--- a/searchlib/src/tests/engine/searchapi/searchapi_test.cpp
+++ b/searchlib/src/tests/engine/searchapi/searchapi_test.cpp
@@ -228,36 +228,37 @@ TEST("convertFromReply") {
     }
 }
 
-void verify(vespalib::stringref expected, const vespalib::Slime & slime) {
+void verify(vespalib::stringref expected, const vespalib::Slime * slime) {
     vespalib::Slime expectedSlime;
     vespalib::slime::JsonFormat::decode(expected, expectedSlime);
-    EXPECT_EQUAL(expectedSlime, slime);
+    if (slime) {
+        EXPECT_EQUAL(expectedSlime, *slime);
+    } else {
+        EXPECT_TRUE(expected.empty());
+    }
 }
 
 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());
+    verify("", t.getSlime());
+    t.start(0);
     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 +270,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..b7ebab79e47 100644
--- a/searchlib/src/vespa/searchlib/engine/packetconverter.cpp
+++ b/searchlib/src/vespa/searchlib/engine/packetconverter.cpp
@@ -74,7 +74,8 @@ 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()));
+    // 3 is the minimum level required for backend tracing.
+    request.setTraceLevel(search::fef::indexproperties::trace::Level::lookup(request.propertiesMap.modelOverrides()), 3);
 }
 
 void
diff --git a/searchlib/src/vespa/searchlib/engine/request.h b/searchlib/src/vespa/searchlib/engine/request.h
index 733043b0e4e..05f6901d2e4 100644
--- a/searchlib/src/vespa/searchlib/engine/request.h
+++ b/searchlib/src/vespa/searchlib/engine/request.h
@@ -30,7 +30,11 @@ public:
 
     bool should_drop_sort_data() const;
 
-    Request & setTraceLevel(uint32_t level) { _trace.setLevel(level); return *this; }
+    Request & setTraceLevel(uint32_t level, uint32_t minLevel) {
+        _trace.setLevel(level);
+        _trace.start(minLevel);
+        return *this;
+    }
 
     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..c9e3a39daa4 100644
--- a/searchlib/src/vespa/searchlib/engine/trace.cpp
+++ b/searchlib/src/vespa/searchlib/engine/trace.cpp
@@ -10,30 +10,49 @@ RelativeTime::RelativeTime(std::unique_ptr<Clock> clock)
       _clock(std::move(clock))
 {}
 
-namespace {
+void
+Trace::constructObject() {
+    _trace = std::make_unique<vespalib::Slime>();
+    _root = & _trace->setObject();
+}
 
-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::constructTraces() {
+    _traces = &_root->setArray("traces");
 }
 
+void
+Trace::lazyConstruct(uint32_t level) {
+    if (shouldTrace(level) && !_trace) {
+        constructObject();
+        constructTraces();
+    }
 }
+
 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) && !_trace) {
+        constructObject();
+        _root->setString("start_time_utc", _relativeTime.timeOfDawn().toString());
+        constructTraces();
+    }
+}
+
 Trace::~Trace() = default;
 
 Trace::Cursor &
 Trace::createCursor(vespalib::stringref name) {
-    Cursor & trace = _traces.addObject();
+    lazyConstruct(_level);
+    Cursor & trace = _traces->addObject();
     addTimeStamp(trace);
     trace.setString("tag", name);
     return trace;
@@ -41,6 +60,7 @@ Trace::createCursor(vespalib::stringref name) {
 
 Trace::Cursor *
 Trace::maybeCreateCursor(uint32_t level, vespalib::stringref name) {
+    lazyConstruct(level);
     return shouldTrace(level) ? & createCursor(name) : nullptr;
 }
 
@@ -48,7 +68,8 @@ void
 Trace::addEvent(uint32_t level, vespalib::stringref event) {
     if (!shouldTrace(level)) { return; }
 
-    Cursor & trace = _traces.addObject();
+    lazyConstruct(level);
+    Cursor & trace = _traces->addObject();
     addTimeStamp(trace);
     trace.setString("event", event);
 }
@@ -59,12 +80,14 @@ Trace::addTimeStamp(Cursor & trace) {
 }
 
 void Trace::done() {
-    _root.setDouble("duration_ms", _relativeTime.timeSinceDawn()/1000000.0);
+    if (!_root) { return; }
+
+    _root->setDouble("duration_ms", _relativeTime.timeSinceDawn()/1000000.0);
 }
 
 vespalib::string
 Trace::toString() const {
-    return _trace->toString();
+    return _trace ? _trace->toString() : "";
 }
 
 }
diff --git a/searchlib/src/vespa/searchlib/engine/trace.h b/searchlib/src/vespa/searchlib/engine/trace.h
index 41f2c608615..78832733f71 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,20 @@ public:
     void done();
 
     vespalib::string toString() const;
-    Cursor & getRoot() const { return _root; }
-    vespalib::Slime & getSlime() const { return *_trace; }
+    Cursor * getRoot() const { return _root; }
+    vespalib::Slime * getSlime() const { return _trace.get(); }
     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:
+    void constructObject();
+    void constructTraces();
+    void lazyConstruct(uint32_t level);
     void addTimeStamp(Cursor & trace);
     std::unique_ptr<vespalib::Slime> _trace;
-    Cursor              & _root;
-    Cursor              & _traces;
+    Cursor              * _root;
+    Cursor              * _traces;
     const RelativeTime  & _relativeTime;
     uint32_t              _level;
 };