log performance events in separate thread

6 files changed, 60 insertions, 16 deletions

diff --git a/searchcore/src/vespa/searchcore/fdispatch/common/queryperf.cpp b/searchcore/src/vespa/searchcore/fdispatch/common/queryperf.cpp
index 466df61f8d0..a0cc89d15c6 100644
--- a/searchcore/src/vespa/searchcore/fdispatch/common/queryperf.cpp
+++ b/searchcore/src/vespa/searchcore/fdispatch/common/queryperf.cpp
@@ -5,6 +5,43 @@
 #include <vespa/log/log.h>
 LOG_SETUP(".queryperf");
 
+namespace {
+
+struct MyLogTask : vespalib::Executor::Task {
+    uint32_t queueLen;
+    uint32_t activeCnt;
+    uint32_t queryCnt;
+    uint32_t dropCnt;
+    uint32_t timeoutCnt;
+    double avgQueryTime;
+    MyLogTask(uint32_t queueLen_in,
+              uint32_t activeCnt_in,
+              uint32_t queryCnt_in,
+              uint32_t dropCnt_in,
+              uint32_t timeoutCnt_in,
+              double avgQueryTime_in)
+        : queueLen(queueLen_in),
+          activeCnt(activeCnt_in),
+          queryCnt(queryCnt_in),
+          dropCnt(dropCnt_in),
+          timeoutCnt(timeoutCnt_in),
+          avgQueryTime(avgQueryTime_in)
+    {
+    }
+    void run() override {
+        EV_VALUE("queued_queries",   queueLen);
+        EV_VALUE("active_queries",   activeCnt);
+        EV_COUNT("queries",          queryCnt);
+        EV_COUNT("dropped_queries",  dropCnt);
+        EV_COUNT("timedout_queries", timeoutCnt);
+        if (avgQueryTime > 0.0) {
+            EV_VALUE("query_eval_time_avg_s", avgQueryTime);
+        }
+    }
+};
+
+} // namespace <unnamed>
+
 FastS_QueryPerf::FastS_QueryPerf()
     : queueLen(0),
       activeCnt(0),
@@ -28,19 +65,20 @@ FastS_QueryPerf::reset()
     timeoutCnt = 0;
 }
 
-void
-FastS_QueryPerf::log()
+vespalib::Executor::Task::UP
+FastS_QueryPerf::make_log_task()
 {
-    EV_VALUE("queued_queries",   queueLen);
-    EV_VALUE("active_queries",   activeCnt);
-    EV_COUNT("queries",          queryCnt);
-    EV_COUNT("dropped_queries",  dropCnt);
-    EV_COUNT("timedout_queries", timeoutCnt);
+    double avgQueryTime = 0.0;
     if (queryCnt > _lastQueryCnt) {
-        double avgQueryTime = (queryTime - _lastQueryTime)
-                              / ((double)(queryCnt - _lastQueryCnt));
-        EV_VALUE("query_eval_time_avg_s", avgQueryTime);
+        avgQueryTime = (queryTime - _lastQueryTime)
+                       / ((double)(queryCnt - _lastQueryCnt));
     }
     _lastQueryCnt  = queryCnt;
     _lastQueryTime = queryTime;
+    return std::make_unique<MyLogTask>(queueLen,
+                                       activeCnt,
+                                       queryCnt,
+                                       dropCnt,
+                                       timeoutCnt,
+                                       avgQueryTime);
 }
diff --git a/searchcore/src/vespa/searchcore/fdispatch/common/queryperf.h b/searchcore/src/vespa/searchcore/fdispatch/common/queryperf.h
index c4f20bc3cef..ee31a8e58b2 100644
--- a/searchcore/src/vespa/searchcore/fdispatch/common/queryperf.h
+++ b/searchcore/src/vespa/searchcore/fdispatch/common/queryperf.h
@@ -3,6 +3,7 @@
 #pragma once
 
 #include <cstdint>
+#include <vespa/vespalib/util/executor.h>
 
 struct FastS_QueryPerf
 {
@@ -20,7 +21,7 @@ struct FastS_QueryPerf
      * prepare the object for reuse logging wise.
      **/
     void reset();
-    void log();
+    vespalib::Executor::Task::UP make_log_task();
 
 private:
     uint32_t _lastQueryCnt;
diff --git a/searchcore/src/vespa/searchcore/fdispatch/program/fdispatch.cpp b/searchcore/src/vespa/searchcore/fdispatch/program/fdispatch.cpp
index d9f2b4ecd4f..b68566c3c9b 100644
--- a/searchcore/src/vespa/searchcore/fdispatch/program/fdispatch.cpp
+++ b/searchcore/src/vespa/searchcore/fdispatch/program/fdispatch.cpp
@@ -92,6 +92,7 @@ Fdispatch::~Fdispatch()
 
     LOG(debug, "Will close threadpool");
     _mypool->Close();
+    _executor.shutdown().sync();
     LOG(debug, "Has closed threadpool");
     _transportServer.reset();
     _engineAdapter.reset();
@@ -194,7 +195,8 @@ Fdispatch::CheckTempFail()
  * Set up stuff as specified in the fdispatch-rc-file.
  */
 Fdispatch::Fdispatch(const config::ConfigUri &configUri)
-    : _mypool(),
+    : _executor(1, 128 * 1024),
+      _mypool(),
       _engineAdapter(),
       _transportServer(),
       _componentConfig(),
@@ -391,7 +393,7 @@ Fdispatch::Init()
 void
 Fdispatch::logPerformance()
 {
-    _nodeManager->logPerformance();
+    _nodeManager->logPerformance(_executor);
 }
 
 uint32_t
diff --git a/searchcore/src/vespa/searchcore/fdispatch/program/fdispatch.h b/searchcore/src/vespa/searchcore/fdispatch/program/fdispatch.h
index a0294e22655..6cfb4bfb5a1 100644
--- a/searchcore/src/vespa/searchcore/fdispatch/program/fdispatch.h
+++ b/searchcore/src/vespa/searchcore/fdispatch/program/fdispatch.h
@@ -11,6 +11,7 @@
 #include <vespa/config/helper/configfetcher.h>
 #include <vespa/vespalib/net/simple_component_config_producer.h>
 #include <vespa/vespalib/util/random.h>
+#include <vespa/vespalib/util/threadstackexecutor.h>
 
 class FastS_NodeManager;
 class FastS_fdispatch_RPC;
@@ -62,6 +63,7 @@ private:
     Fdispatch(const Fdispatch &);
     Fdispatch& operator=(const Fdispatch &);
 
+    vespalib::ThreadStackExecutor           _executor;
     std::unique_ptr<FastOS_ThreadPool>      _mypool;
     std::unique_ptr<EngineAdapter>          _engineAdapter;
     std::unique_ptr<TransportServer>        _transportServer;
diff --git a/searchcore/src/vespa/searchcore/fdispatch/search/nodemanager.cpp b/searchcore/src/vespa/searchcore/fdispatch/search/nodemanager.cpp
index 4b272a615a6..302f92cef39 100644
--- a/searchcore/src/vespa/searchcore/fdispatch/search/nodemanager.cpp
+++ b/searchcore/src/vespa/searchcore/fdispatch/search/nodemanager.cpp
@@ -391,7 +391,7 @@ FastS_NodeManager::getChildInfo()
 
 
 void
-FastS_NodeManager::logPerformance()
+FastS_NodeManager::logPerformance(vespalib::Executor &executor)
 {
     _queryPerf.reset();
     FastS_DataSetCollection *dsc = GetDataSetCollection();
@@ -403,7 +403,7 @@ FastS_NodeManager::logPerformance()
     }
 
     dsc->subRef();
-    _queryPerf.log();
+    executor.execute(_queryPerf.make_log_task());
 }
 
 
diff --git a/searchcore/src/vespa/searchcore/fdispatch/search/nodemanager.h b/searchcore/src/vespa/searchcore/fdispatch/search/nodemanager.h
index e0396b46748..77d4482fba7 100644
--- a/searchcore/src/vespa/searchcore/fdispatch/search/nodemanager.h
+++ b/searchcore/src/vespa/searchcore/fdispatch/search/nodemanager.h
@@ -8,6 +8,7 @@
 #include <vespa/searchcore/fdispatch/common/queryperf.h>
 #include <vespa/vespalib/net/simple_component_config_producer.h>
 #include <vespa/config/subscription/configuri.h>
+#include <vespa/vespalib/util/executor.h>
 #include <mutex>
 
 using vespa::config::search::core::PartitionsConfig;
@@ -92,7 +93,7 @@ public:
      * log query performance. This method should only be invoked from
      * the FNET thread.
      **/
-    void logPerformance();
+    void logPerformance(vespalib::Executor &executor);
 
     void CheckEvents(FastS_TimeKeeper *timeKeeper); // invoked by FNET thread
 };