Add log event for when the flush engine tries to prune a flush handler.

3 files changed, 43 insertions, 8 deletions

diff --git a/searchcore/src/vespa/searchcore/proton/common/eventlogger.cpp b/searchcore/src/vespa/searchcore/proton/common/eventlogger.cpp
index 78f73742fed..52c4899506f 100644
--- a/searchcore/src/vespa/searchcore/proton/common/eventlogger.cpp
+++ b/searchcore/src/vespa/searchcore/proton/common/eventlogger.cpp
@@ -124,6 +124,20 @@ EventLogger::flushComplete(const string &name, int64_t elapsedTimeMs,
     EV_STATE("flush.complete", jstr.toString().data());
 }
 
+void
+EventLogger::flushPrune(const string &name, SerialNum oldestFlushed)
+{
+    JSONStringer jstr;
+    jstr.beginObject();
+    jstr.appendKey("name").appendString(name);
+    jstr.appendKey("serialnum")
+            .beginObject()
+            .appendKey("oldestflushed").appendInt64(oldestFlushed)
+            .endObject();
+    jstr.endObject();
+    EV_STATE("flush.prune", jstr.toString().data());
+}
+
 namespace {
 
 void
diff --git a/searchcore/src/vespa/searchcore/proton/common/eventlogger.h b/searchcore/src/vespa/searchcore/proton/common/eventlogger.h
index 6ba8852496e..c5d0d878924 100644
--- a/searchcore/src/vespa/searchcore/proton/common/eventlogger.h
+++ b/searchcore/src/vespa/searchcore/proton/common/eventlogger.h
@@ -43,6 +43,7 @@ public:
                               int64_t elapsedTimeMs,
                               const string &outputPath,
                               size_t outputPathElems);
+    static void flushPrune(const string &name, SerialNum oldestFlushed);
     static void loadAttributeStart(const vespalib::string &subDbName, const vespalib::string &attrName);
     static void loadAttributeComplete(const vespalib::string &subDbName,
                                       const vespalib::string &attrName, int64_t elapsedTimeMs);
diff --git a/searchcore/src/vespa/searchcore/proton/flushengine/flushengine.cpp b/searchcore/src/vespa/searchcore/proton/flushengine/flushengine.cpp
index 4866ec0d710..490e31f6fd4 100644
--- a/searchcore/src/vespa/searchcore/proton/flushengine/flushengine.cpp
+++ b/searchcore/src/vespa/searchcore/proton/flushengine/flushengine.cpp
@@ -22,17 +22,23 @@ namespace proton {
 
 namespace {
 
-search::SerialNum
-findOldestFlushedSerial(const IFlushTarget::List &lst, const IFlushHandler &handler)
+std::pair<search::SerialNum, vespalib::string>
+findOldestFlushedTarget(const IFlushTarget::List &lst, const IFlushHandler &handler)
 {
-    search::SerialNum ret(handler.getCurrentSerialNumber());
-    for (const IFlushTarget::SP & target : lst) {
+    search::SerialNum oldestFlushedSerial = handler.getCurrentSerialNumber();
+    vespalib::string oldestFlushedName = "null";
+    for (const IFlushTarget::SP &target : lst) {
         if (target->getType() != IFlushTarget::Type::GC) {
-            ret = std::min(ret, target->getFlushedSerialNum());
+            search::SerialNum targetFlushedSerial = target->getFlushedSerialNum();
+            if (targetFlushedSerial <= oldestFlushedSerial) {
+                oldestFlushedSerial = targetFlushedSerial;
+                oldestFlushedName = target->getName();
+            }
         }
     }
-    LOG(debug, "Oldest flushed serial for '%s' is %" PRIu64 ".", handler.getName().c_str(), ret);
-    return ret;
+    LOG(debug, "Oldest flushed serial for handler='%s', target='%s': %" PRIu64 ".",
+        handler.getName().c_str(), oldestFlushedName.c_str(), oldestFlushedSerial);
+    return std::make_pair(oldestFlushedSerial, oldestFlushedName);
 }
 
 void
@@ -176,6 +182,16 @@ FlushEngine::Run(FastOS_ThreadInterface *, void *)
     prune();
 }
 
+namespace {
+
+vespalib::string
+createName(const IFlushHandler &handler, const vespalib::string &targetName)
+{
+    return (handler.getName() + "." + targetName);
+}
+
+}
+
 bool
 FlushEngine::prune()
 {
@@ -189,7 +205,11 @@ FlushEngine::prune()
     }
     for (const auto &handler : toPrune) {
         IFlushTarget::List lst = handler->getFlushTargets();
-        handler->flushDone(findOldestFlushedSerial(lst, *handler));
+        auto oldestFlushed = findOldestFlushedTarget(lst, *handler);
+        if (LOG_WOULD_LOG(event)) {
+            EventLogger::flushPrune(createName(*handler, oldestFlushed.second), oldestFlushed.first);
+        }
+        handler->flushDone(oldestFlushed.first);
     }
     return true;
 }