Log time used for reconfig.

4 files changed, 27 insertions, 5 deletions

diff --git a/searchcore/src/vespa/searchcore/proton/server/document_db_reconfig.cpp b/searchcore/src/vespa/searchcore/proton/server/document_db_reconfig.cpp
index f0d028f924f..580a43b98c1 100644
--- a/searchcore/src/vespa/searchcore/proton/server/document_db_reconfig.cpp
+++ b/searchcore/src/vespa/searchcore/proton/server/document_db_reconfig.cpp
@@ -5,9 +5,11 @@
 
 namespace proton {
 
-DocumentDBReconfig::DocumentDBReconfig(std::unique_ptr<DocumentSubDBReconfig> ready_reconfig_in,
+DocumentDBReconfig::DocumentDBReconfig(vespalib::steady_time start_time,
+                                       std::unique_ptr<DocumentSubDBReconfig> ready_reconfig_in,
                                        std::unique_ptr<DocumentSubDBReconfig> not_ready_reconfig_in)
-    : _ready_reconfig(std::move(ready_reconfig_in)),
+    : _start_time(start_time),
+      _ready_reconfig(std::move(ready_reconfig_in)),
       _not_ready_reconfig(std::move(not_ready_reconfig_in))
 {
 }
diff --git a/searchcore/src/vespa/searchcore/proton/server/document_db_reconfig.h b/searchcore/src/vespa/searchcore/proton/server/document_db_reconfig.h
index d35a2211397..9462c018cc2 100644
--- a/searchcore/src/vespa/searchcore/proton/server/document_db_reconfig.h
+++ b/searchcore/src/vespa/searchcore/proton/server/document_db_reconfig.h
@@ -1,6 +1,7 @@
 // Copyright Yahoo. Licensed under the terms of the Apache 2.0 license. See LICENSE in the project root.
 #pragma once
 
+#include <vespa/vespalib/util/time.h>
 #include <memory>
 
 namespace proton {
@@ -23,14 +24,17 @@ class DocumentSubDBReconfig;
  */
 class DocumentDBReconfig {
 private:
+    vespalib::steady_time _start_time;
     std::unique_ptr<DocumentSubDBReconfig> _ready_reconfig;
     std::unique_ptr<DocumentSubDBReconfig> _not_ready_reconfig;
 
 public:
-    DocumentDBReconfig(std::unique_ptr<DocumentSubDBReconfig> ready_reconfig_in,
+    DocumentDBReconfig(vespalib::steady_time start_time,
+                       std::unique_ptr<DocumentSubDBReconfig> ready_reconfig_in,
                        std::unique_ptr<DocumentSubDBReconfig> not_ready_reconfig_in);
     ~DocumentDBReconfig();
 
+    vespalib::steady_time start_time() const noexcept { return _start_time; }
     const DocumentSubDBReconfig& ready_reconfig() const noexcept { return *_ready_reconfig; }
     DocumentSubDBReconfig& ready_reconfig() noexcept { return *_ready_reconfig; }
     const DocumentSubDBReconfig& not_ready_reconfig() const noexcept { return *_not_ready_reconfig; }
diff --git a/searchcore/src/vespa/searchcore/proton/server/documentdb.cpp b/searchcore/src/vespa/searchcore/proton/server/documentdb.cpp
index a217e3b719e..bc215b2dd70 100644
--- a/searchcore/src/vespa/searchcore/proton/server/documentdb.cpp
+++ b/searchcore/src/vespa/searchcore/proton/server/documentdb.cpp
@@ -435,6 +435,7 @@ DocumentDB::applyConfig(DocumentDBConfig::SP configSnapshot, SerialNum serialNum
         return;
     }
 
+    auto start_time = vespalib::steady_clock::now();
     DocumentDBConfig::ComparisonResult cmpres;
     Schema::SP oldSchema;
     int64_t generation = configSnapshot->getGeneration();
@@ -468,8 +469,8 @@ DocumentDB::applyConfig(DocumentDBConfig::SP configSnapshot, SerialNum serialNum
         commit_result = _feedHandler->storeOperationSync(op);
         sync(op.getSerialNum());
     }
+    bool elidedConfigSave = equalReplayConfig && tlsReplayDone;
     {
-        bool elidedConfigSave = equalReplayConfig && tlsReplayDone;
         forceCommitAndWait(*_feedView.get(), elidedConfigSave ? serialNum : serialNum - 1, std::move(commit_result));
     }
     _subDBs.complete_prepare_reconfig(*prepared_reconfig, serialNum);
@@ -513,6 +514,20 @@ DocumentDB::applyConfig(DocumentDBConfig::SP configSnapshot, SerialNum serialNum
     if (_subDBs.getReprocessingRunner().empty()) {
         _subDBs.pruneRemovedFields(serialNum);
     }
+    auto prepare_start_time = prepared_reconfig->start_time();
+    prepared_reconfig.reset();
+    auto end_time = vespalib::steady_clock::now();
+    auto state_string = DDBState::getStateString(_state.getState());
+    auto config_state_string = DDBState::getConfigStateString(_state.getConfigState());
+    vespalib::string saved_string(elidedConfigSave ? "no" : "yes");
+    LOG(info, "DocumentDB(%s): Applied config, state=%s, config_state=%s, saved=%s, serialNum=%" PRIu64 ", %.3fs of %.3fs in write thread",
+        _docTypeName.toString().c_str(),
+        state_string.c_str(),
+        config_state_string.c_str(),
+        saved_string.c_str(),
+        serialNum,
+        vespalib::to_s(end_time - start_time),
+        vespalib::to_s(end_time - prepare_start_time));
 }
 
 void
diff --git a/searchcore/src/vespa/searchcore/proton/server/documentsubdbcollection.cpp b/searchcore/src/vespa/searchcore/proton/server/documentsubdbcollection.cpp
index 73f90df11ab..fe2da98e9d8 100644
--- a/searchcore/src/vespa/searchcore/proton/server/documentsubdbcollection.cpp
+++ b/searchcore/src/vespa/searchcore/proton/server/documentsubdbcollection.cpp
@@ -253,9 +253,10 @@ DocumentSubDBCollection::pruneRemovedFields(SerialNum serialNum)
 std::unique_ptr<DocumentDBReconfig>
 DocumentSubDBCollection::prepare_reconfig(const DocumentDBConfig& new_config_snapshot, const DocumentDBConfig& old_config_snapshot, const ReconfigParams& reconfig_params, std::optional<SerialNum> serial_num)
 {
+    auto start_time = vespalib::steady_clock::now();
     auto ready_reconfig = getReadySubDB()->prepare_reconfig(new_config_snapshot, old_config_snapshot, reconfig_params, serial_num);
     auto not_ready_reconfig = getNotReadySubDB()->prepare_reconfig(new_config_snapshot, old_config_snapshot, reconfig_params, serial_num);
-    return std::make_unique<DocumentDBReconfig>(std::move(ready_reconfig), std::move(not_ready_reconfig));
+    return std::make_unique<DocumentDBReconfig>(start_time, std::move(ready_reconfig), std::move(not_ready_reconfig));
 }
 
 void