diff options
author | Tor Egge <Tor.Egge@online.no> | 2023-02-09 12:11:13 +0100 |
---|---|---|
committer | Tor Egge <Tor.Egge@online.no> | 2023-02-09 12:11:13 +0100 |
commit | 32389d080e73db62161e5ea3e15ac28e8db556c6 (patch) | |
tree | 655d7a4acb3cf9c3b3a6a1f5c430714cdca785b5 /searchcore | |
parent | 5c5a79813ea6d6d57326f82145816200b8a41622 (diff) |
Log time used for reconfig.
Diffstat (limited to 'searchcore')
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 |