From d2b012c883f0406e8d031b202d7c9b53e2de1236 Mon Sep 17 00:00:00 2001 From: EmelyanenkoK Date: Thu, 25 Apr 2024 18:45:39 +0300 Subject: [PATCH 1/2] Add write time stats to celldb/db_stats.txt (#972) Co-authored-by: SpyCheese --- tdutils/td/utils/Timer.cpp | 4 +++ tdutils/td/utils/Timer.h | 1 + validator/CMakeLists.txt | 2 ++ validator/db/archive-slice.cpp | 64 ++++++++-------------------------- validator/db/celldb.cpp | 22 ++++++++++-- validator/db/celldb.hpp | 25 ++++++++++--- validator/db/db-utils.cpp | 54 ++++++++++++++++++++++++++++ validator/db/db-utils.h | 33 ++++++++++++++++++ 8 files changed, 148 insertions(+), 57 deletions(-) create mode 100644 validator/db/db-utils.cpp create mode 100644 validator/db/db-utils.h diff --git a/tdutils/td/utils/Timer.cpp b/tdutils/td/utils/Timer.cpp index 0f6a7d6e..1f72fba9 100644 --- a/tdutils/td/utils/Timer.cpp +++ b/tdutils/td/utils/Timer.cpp @@ -87,4 +87,8 @@ void PerfWarningTimer::reset() { start_at_ = 0; } +double PerfWarningTimer::elapsed() const { + return Time::now() - start_at_; +} + } // namespace td diff --git a/tdutils/td/utils/Timer.h b/tdutils/td/utils/Timer.h index 18ea35d7..3e0cafbf 100644 --- a/tdutils/td/utils/Timer.h +++ b/tdutils/td/utils/Timer.h @@ -53,6 +53,7 @@ class PerfWarningTimer { PerfWarningTimer &operator=(PerfWarningTimer &&) = delete; ~PerfWarningTimer(); void reset(); + double elapsed() const; private: string name_; diff --git a/validator/CMakeLists.txt b/validator/CMakeLists.txt index a25ac7e1..20462cae 100644 --- a/validator/CMakeLists.txt +++ b/validator/CMakeLists.txt @@ -25,6 +25,8 @@ set(VALIDATOR_DB_SOURCE db/statedb.cpp db/staticfilesdb.cpp db/staticfilesdb.hpp + db/db-utils.cpp + db/db-utils.h db/package.hpp db/package.cpp diff --git a/validator/db/archive-slice.cpp b/validator/db/archive-slice.cpp index 86c2ee93..daee546b 100644 --- a/validator/db/archive-slice.cpp +++ b/validator/db/archive-slice.cpp @@ -24,6 +24,7 @@ #include "td/utils/port/path.h" #include "common/delay.h" #include "files-async.hpp" +#include "db-utils.h" namespace ton { @@ -41,16 +42,14 @@ class PackageStatistics { void record_read(double time, uint64_t bytes) { read_bytes.fetch_add(bytes, std::memory_order_relaxed); - std::lock_guard guard(read_mutex); + std::lock_guard guard(read_mutex); read_time.insert(time); - read_time_sum += time; } void record_write(double time, uint64_t bytes) { write_bytes.fetch_add(bytes, std::memory_order_relaxed); - std::lock_guard guard(write_mutex); + std::lock_guard guard(write_mutex); write_time.insert(time); - write_time_sum += time; } std::string to_string_and_reset() { @@ -64,68 +63,35 @@ class PackageStatistics { ss << "ton.pack.read.bytes COUNT : " << read_bytes.exchange(0, std::memory_order_relaxed) << "\n"; ss << "ton.pack.write.bytes COUNT : " << write_bytes.exchange(0, std::memory_order_relaxed) << "\n"; - std::multiset temp_read_time; - double temp_read_time_sum; + PercentileStats temp_read_time; { - std::lock_guard guard(read_mutex); + std::lock_guard guard(read_mutex); temp_read_time = std::move(read_time); read_time.clear(); - temp_read_time_sum = read_time_sum; - read_time_sum = 0; } - auto read_stats = calculate_statistics(temp_read_time); - ss << "ton.pack.read.micros P50 : " << read_stats[0] << - " P95 : " << read_stats[1] << - " P99 : " << read_stats[2] << - " P100 : " << read_stats[3] << - " COUNT : " << temp_read_time.size() << - " SUM : " << temp_read_time_sum << "\n"; + ss << "ton.pack.read.micros " << temp_read_time.to_string() << "\n"; - std::multiset temp_write_time; - double temp_write_time_sum; + PercentileStats temp_write_time; { - std::lock_guard guard(write_mutex); + std::lock_guard guard(write_mutex); temp_write_time = std::move(write_time); write_time.clear(); - temp_write_time_sum = write_time_sum; - write_time_sum = 0; } - auto write_stats = calculate_statistics(temp_write_time); - ss << "ton.pack.write.micros P50 : " << write_stats[0] << - " P95 : " << write_stats[1] << - " P99 : " << write_stats[2] << - " P100 : " << write_stats[3] << - " COUNT : " << temp_write_time.size() << - " SUM : " << temp_write_time_sum << "\n"; + ss << "ton.pack.write.micros " << temp_write_time.to_string() << "\n"; return ss.str(); } private: - std::atomic_uint64_t open_count; - std::atomic_uint64_t close_count; - std::multiset read_time; - std::atomic_uint64_t read_bytes; - std::multiset write_time; - std::atomic_uint64_t write_bytes; - double read_time_sum; - double write_time_sum; + std::atomic_uint64_t open_count{0}; + std::atomic_uint64_t close_count{0}; + PercentileStats read_time; + std::atomic_uint64_t read_bytes{0}; + PercentileStats write_time; + std::atomic_uint64_t write_bytes{0}; mutable std::mutex read_mutex; mutable std::mutex write_mutex; - - std::vector calculate_statistics(const std::multiset& data) const { - if (data.empty()) return {0, 0, 0, 0}; - - auto size = data.size(); - auto calc_percentile = [&](double p) -> double { - auto it = data.begin(); - std::advance(it, static_cast(std::ceil(p * double(size)) - 1)); - return *it; - }; - - return {calc_percentile(0.5), calc_percentile(0.95), calc_percentile(0.99), *data.rbegin()}; - } }; void DbStatistics::init() { diff --git a/validator/db/celldb.cpp b/validator/db/celldb.cpp index d9803cbe..294515a3 100644 --- a/validator/db/celldb.cpp +++ b/validator/db/celldb.cpp @@ -89,7 +89,7 @@ void CellDbIn::start_up() { statistics_flush_at_ = td::Timestamp::in(60.0); } cell_db_ = std::make_shared(td::RocksDb::open(path_, statistics_).move_as_ok()); - + boc_ = vm::DynamicBagOfCellsDb::create(); boc_->set_celldb_compress_depth(opts_->get_celldb_compress_depth()); @@ -155,6 +155,9 @@ void CellDbIn::store_cell(BlockIdExt block_id, td::Ref cell, td::Promi td::actor::send_closure(parent_, &CellDb::update_snapshot, cell_db_->snapshot()); promise.set_result(boc_->load_cell(cell->get_hash().as_slice())); + if (!opts_->get_disable_rocksdb_stats()) { + cell_db_statistics_.store_cell_time_.insert(timer.elapsed() * 1e6); + } } void CellDbIn::get_cell_db_reader(td::Promise> promise) { @@ -162,8 +165,9 @@ void CellDbIn::get_cell_db_reader(td::Promise> } void CellDbIn::flush_db_stats() { - auto stats = td::RocksDb::statistics_to_string(statistics_); - auto to_file_r = td::FileFd::open(path_ + "/db_stats.txt", td::FileFd::Truncate | td::FileFd::Create | td::FileFd::Write, 0644); + auto stats = td::RocksDb::statistics_to_string(statistics_) + cell_db_statistics_.to_string(); + auto to_file_r = + td::FileFd::open(path_ + "/db_stats.txt", td::FileFd::Truncate | td::FileFd::Create | td::FileFd::Write, 0644); if (to_file_r.is_error()) { LOG(ERROR) << "Failed to open db_stats.txt: " << to_file_r.move_as_error(); return; @@ -176,6 +180,7 @@ void CellDbIn::flush_db_stats() { return; } td::RocksDb::reset_statistics(statistics_); + cell_db_statistics_.clear(); } void CellDbIn::alarm() { @@ -278,6 +283,9 @@ void CellDbIn::gc_cont2(BlockHandle handle) { td::actor::send_closure(parent_, &CellDb::update_snapshot, cell_db_->snapshot()); DCHECK(get_block(key_hash).is_error()); + if (!opts_->get_disable_rocksdb_stats()) { + cell_db_statistics_.gc_cell_time_.insert(timer.elapsed() * 1e6); + } } void CellDbIn::skip_gc() { @@ -441,6 +449,14 @@ td::BufferSlice CellDbIn::DbEntry::release() { return create_serialize_tl_object(create_tl_block_id(block_id), prev, next, root_hash); } +std::string CellDbIn::CellDbStatistics::to_string() { + td::StringBuilder ss; + ss << "ton.celldb.store_cell.micros " << store_cell_time_.to_string() << "\n"; + ss << "ton.celldb.gc_cell.micros " << gc_cell_time_.to_string() << "\n"; + ss << "ton.celldb.total_time.micros : " << (td::Timestamp::now().at() - stats_start_time_.at()) * 1e6 << "\n"; + return ss.as_cslice().str(); +} + } // namespace validator } // namespace ton diff --git a/validator/db/celldb.hpp b/validator/db/celldb.hpp index 573d4b99..7dc1fa78 100644 --- a/validator/db/celldb.hpp +++ b/validator/db/celldb.hpp @@ -26,6 +26,7 @@ #include "interfaces/block-handle.h" #include "auto/tl/ton_api.h" #include "validator.h" +#include "db-utils.h" namespace rocksdb { class Statistics; @@ -42,9 +43,11 @@ class CellDbAsyncExecutor; class CellDbBase : public td::actor::Actor { public: - virtual void start_up(); + void start_up() override; + protected: std::shared_ptr async_executor; + private: void execute_sync(std::function f); friend CellDbAsyncExecutor; @@ -76,8 +79,7 @@ class CellDbIn : public CellDbBase { RootHash root_hash; DbEntry(tl_object_ptr entry); - DbEntry() { - } + DbEntry() = default; DbEntry(BlockIdExt block_id, KeyHash prev, KeyHash next, RootHash root_hash) : block_id(block_id), prev(prev), next(next), root_hash(root_hash) { } @@ -109,8 +111,6 @@ class CellDbIn : public CellDbBase { std::unique_ptr boc_; std::shared_ptr cell_db_; - std::shared_ptr statistics_; - td::Timestamp statistics_flush_at_ = td::Timestamp::never(); std::function on_load_callback_; std::set cells_to_migrate_; @@ -127,6 +127,21 @@ class CellDbIn : public CellDbBase { }; std::unique_ptr migration_stats_; + struct CellDbStatistics { + PercentileStats store_cell_time_; + PercentileStats gc_cell_time_; + td::Timestamp stats_start_time_ = td::Timestamp::now(); + + std::string to_string(); + void clear() { + *this = CellDbStatistics{}; + } + }; + + std::shared_ptr statistics_; + CellDbStatistics cell_db_statistics_; + td::Timestamp statistics_flush_at_ = td::Timestamp::never(); + public: class MigrationProxy : public td::actor::Actor { public: diff --git a/validator/db/db-utils.cpp b/validator/db/db-utils.cpp new file mode 100644 index 00000000..9375f97e --- /dev/null +++ b/validator/db/db-utils.cpp @@ -0,0 +1,54 @@ +/* + This file is part of TON Blockchain Library. + + TON Blockchain Library is free software: you can redistribute it and/or modify + it under the terms of the GNU Lesser General Public License as published by + the Free Software Foundation, either version 2 of the License, or + (at your option) any later version. + + TON Blockchain Library is distributed in the hope that it will be useful, + but WITHOUT ANY WARRANTY; without even the implied warranty of + MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE. See the + GNU Lesser General Public License for more details. + + You should have received a copy of the GNU Lesser General Public License + along with TON Blockchain Library. If not, see . +*/ +#include "db-utils.h" + +#include "td/utils/logging.h" + +#include + +namespace ton::validator { + +void PercentileStats::insert(double value) { + values_.insert(value); +} + +std::string PercentileStats::to_string() const { + double percentiles[4] = {0.0, 0.0, 0.0, 0.0}; + double sum = 0.0; + size_t size = values_.size(); + if (!values_.empty()) { + size_t indices[4] = {(size_t)std::ceil(0.5 * (double)size) - 1, (size_t)std::ceil(0.95 * (double)size) - 1, + (size_t)std::ceil(0.99 * (double)size) - 1, size - 1}; + size_t i = 0; + for (auto it = values_.begin(); it != values_.end(); ++it, ++i) { + for (size_t j = 0; j < 4; ++j) { + if (indices[j] == i) { + percentiles[j] = *it; + } + } + sum += *it; + } + } + return PSTRING() << "P50 : " << percentiles[0] << " P95 : " << percentiles[1] << " P99 : " << percentiles[2] + << " P100 : " << percentiles[3] << " COUNT : " << size << " SUM : " << sum; +} + +void PercentileStats::clear() { + values_.clear(); +} + +} // namespace ton::validator \ No newline at end of file diff --git a/validator/db/db-utils.h b/validator/db/db-utils.h new file mode 100644 index 00000000..8ffbf5c9 --- /dev/null +++ b/validator/db/db-utils.h @@ -0,0 +1,33 @@ +/* + This file is part of TON Blockchain Library. + + TON Blockchain Library is free software: you can redistribute it and/or modify + it under the terms of the GNU Lesser General Public License as published by + the Free Software Foundation, either version 2 of the License, or + (at your option) any later version. + + TON Blockchain Library is distributed in the hope that it will be useful, + but WITHOUT ANY WARRANTY; without even the implied warranty of + MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE. See the + GNU Lesser General Public License for more details. + + You should have received a copy of the GNU Lesser General Public License + along with TON Blockchain Library. If not, see . +*/ +#pragma once +#include +#include + +namespace ton::validator { + +class PercentileStats { + public: + void insert(double value); + std::string to_string() const; + void clear(); + + private: + std::multiset values_; +}; + +} // namespace ton::validator \ No newline at end of file From 9a543c6b28b4f7d952f4b0225b5f8ee433a3f392 Mon Sep 17 00:00:00 2001 From: EmelyanenkoK Date: Thu, 25 Apr 2024 18:47:15 +0300 Subject: [PATCH 2/2] Add more info to session stats (#973) * Improve validator session stats * Improve validator session stats Add got_submit_at, collation_cached, validation_cached. Fix stats cleanup. * Fix setting timestamp for cached blocks * Add serialize/deserialize time, serialized size to validator session stats, fix setting is_accepted --------- Co-authored-by: SpyCheese --- tl/generate/scheme/ton_api.tl | 9 +- tl/generate/scheme/ton_api.tlo | Bin 87952 -> 88712 bytes validator-session/candidate-serializer.cpp | 1 - validator-session/validator-session-types.h | 51 ++++- validator-session/validator-session.cpp | 223 ++++++++++++++++---- validator-session/validator-session.h | 14 +- validator-session/validator-session.hpp | 22 +- validator/manager.cpp | 8 +- validator/validator-group.cpp | 43 ++-- validator/validator-group.hpp | 6 +- 10 files changed, 309 insertions(+), 68 deletions(-) diff --git a/tl/generate/scheme/ton_api.tl b/tl/generate/scheme/ton_api.tl index c61bad85..af9df3fd 100644 --- a/tl/generate/scheme/ton_api.tl +++ b/tl/generate/scheme/ton_api.tl @@ -752,7 +752,14 @@ http.server.config dhs:(vector http.server.dnsEntry) local_hosts:(vector http.se ---types--- -validatorSession.statsProducer id:int256 candidate_id:int256 block_status:int block_timestamp:long comment:string = validatorSession.StatsProducer; +validatorSession.statsProducer id:int256 candidate_id:int256 block_status:int comment:string + block_timestamp:double is_accepted:Bool is_ours:Bool got_submit_at:double + collation_time:double collated_at:double collation_cached:Bool + validation_time:double validated_at:double validation_cached:Bool + gen_utime:double + approved_weight:long approved_33pct_at:double approved_66pct_at:double + signed_weight:long signed_33pct_at:double signed_66pct_at:double + serialize_time:double deserialize_time:double serialized_size:int = validatorSession.StatsProducer; validatorSession.statsRound timestamp:long producers:(vector validatorSession.statsProducer) = validatorSession.StatsRound; diff --git a/tl/generate/scheme/ton_api.tlo b/tl/generate/scheme/ton_api.tlo index b8f5d5a4936db19e0d67c2f4bf647954b93cccf4..c97fa2feefc0767775d31b5c072aaf671c979e35 100644 GIT binary patch delta 460 zcmbQRp0#5u>xLbMES~D@>YMi%^4tcqrk~+qRNw@O-8?4bBQd$KR(ZMvFJr*;3A~Il zlQ&FenV!MRC^7lOECEjL%;NaO Mn6=%7kI}~y0408<1poj5 delta 92 zcmeC!$~s{^>xLbMEGHyC=x*L)$a9+&#FCqSP=Ha4H=rm#r8GIUhyf%vxu8d5x&$v{ n!1NAYMv2KYN(858@-j+KZZPHm>z=+rfUyJ2+HNDr=;H|hYdj%F diff --git a/validator-session/candidate-serializer.cpp b/validator-session/candidate-serializer.cpp index c220b4a9..a85c4b72 100644 --- a/validator-session/candidate-serializer.cpp +++ b/validator-session/candidate-serializer.cpp @@ -14,7 +14,6 @@ You should have received a copy of the GNU Lesser General Public License along with TON Blockchain Library. If not, see . */ -#pragma once #include "candidate-serializer.h" #include "tl-utils/tl-utils.hpp" #include "vm/boc.h" diff --git a/validator-session/validator-session-types.h b/validator-session/validator-session-types.h index bcbaa8f7..db06bbd9 100644 --- a/validator-session/validator-session-types.h +++ b/validator-session/validator-session-types.h @@ -76,8 +76,57 @@ struct ValidatorSessionStats { PublicKeyHash id = PublicKeyHash::zero(); ValidatorSessionCandidateId candidate_id = ValidatorSessionCandidateId::zero(); int block_status = status_none; - td::uint64 block_timestamp = 0; + double block_timestamp = -1.0; std::string comment; + + bool is_accepted = false; + bool is_ours = false; + double got_submit_at = -1.0; + double collation_time = -1.0; + double validation_time = -1.0; + double collated_at = -1.0; + double validated_at = -1.0; + bool collation_cached = false; + bool validation_cached = false; + double gen_utime = -1.0; + + std::vector approvers, signers; + ValidatorWeight approved_weight = 0; + ValidatorWeight signed_weight = 0; + double approved_33pct_at = -1.0; + double approved_66pct_at = -1.0; + double signed_33pct_at = -1.0; + double signed_66pct_at = -1.0; + + double serialize_time = -1.0; + double deserialize_time = -1.0; + td::int32 serialized_size = -1; + + void set_approved_by(td::uint32 id, ValidatorWeight weight, ValidatorWeight total_weight) { + if (!approvers.at(id)) { + approvers.at(id) = true; + approved_weight += weight; + if (approved_33pct_at <= 0.0 && approved_weight >= total_weight / 3 + 1) { + approved_33pct_at = td::Clocks::system(); + } + if (approved_66pct_at <= 0.0 && approved_weight >= (total_weight * 2) / 3 + 1) { + approved_66pct_at = td::Clocks::system(); + } + } + } + + void set_signed_by(td::uint32 id, ValidatorWeight weight, ValidatorWeight total_weight) { + if (!signers.at(id)) { + signers.at(id) = true; + signed_weight += weight; + if (signed_33pct_at <= 0.0 && signed_weight >= total_weight / 3 + 1) { + signed_33pct_at = td::Clocks::system(); + } + if (signed_66pct_at <= 0.0 && signed_weight >= (total_weight * 2) / 3 + 1) { + signed_66pct_at = td::Clocks::system(); + } + } + } }; struct Round { td::uint64 timestamp = 0; diff --git a/validator-session/validator-session.cpp b/validator-session/validator-session.cpp index 6b328b2b..215b6b12 100644 --- a/validator-session/validator-session.cpp +++ b/validator-session/validator-session.cpp @@ -20,6 +20,7 @@ #include "td/utils/Random.h" #include "td/utils/crypto.h" #include "candidate-serializer.h" +#include "td/utils/overloaded.h" namespace ton { @@ -86,6 +87,7 @@ void ValidatorSessionImpl::process_blocks(std::vector for (auto &msg : msgs) { VLOG(VALIDATOR_SESSION_INFO) << this << ": applying action: " << msg.get(); + stats_process_action(local_idx(), *msg); real_state_ = ValidatorSessionState::action(description(), real_state_, local_idx(), att, msg.get()); } @@ -167,6 +169,7 @@ void ValidatorSessionImpl::preprocess_block(catchain::CatChainBlock *block) { for (auto &msg : B->actions_) { VLOG(VALIDATOR_SESSION_INFO) << this << "[node " << description().get_source_id(block->source()) << "][block " << block->hash() << "]: applying action " << msg.get(); + stats_process_action(block->source(), *msg); state = ValidatorSessionState::action(description(), state, block->source(), att, msg.get()); } state = ValidatorSessionState::make_all(description(), state, block->source(), att); @@ -222,9 +225,11 @@ void ValidatorSessionImpl::process_broadcast(PublicKeyHash src, td::BufferSlice // Note: src is not necessarily equal to the sender of this message: // If requested using get_broadcast_p2p, src is the creator of the block, sender possibly is some other node. auto src_idx = description().get_source_idx(src); + td::Timer deserialize_timer; auto R = deserialize_candidate(data, compress_block_candidates_, description().opts().max_block_size + description().opts().max_collated_data_size + 1024); + double deserialize_time = deserialize_timer.elapsed(); if (R.is_error()) { VLOG(VALIDATOR_SESSION_WARNING) << this << "[node " << src << "][broadcast " << sha256_bits256(data.as_slice()) << "]: failed to parse: " << R.move_as_error(); @@ -255,6 +260,18 @@ void ValidatorSessionImpl::process_broadcast(PublicKeyHash src, td::BufferSlice return; } + auto stat = stats_get_candidate_stat(block_round, src, block_id); + if (stat) { + if (stat->block_status == ValidatorSessionStats::status_none) { + stat->block_status = ValidatorSessionStats::status_received; + } + if (stat->block_timestamp <= 0.0) { + stat->block_timestamp = td::Clocks::system(); + } + stat->deserialize_time = deserialize_time; + stat->serialized_size = data.size(); + } + if ((td::int32)block_round < (td::int32)cur_round_ - MAX_PAST_ROUND_BLOCK || block_round >= cur_round_ + MAX_FUTURE_ROUND_BLOCK) { VLOG(VALIDATOR_SESSION_NOTICE) << this << "[node " << src << "][broadcast " << block_id @@ -291,7 +308,6 @@ void ValidatorSessionImpl::process_broadcast(PublicKeyHash src, td::BufferSlice CHECK(!pending_reject_.count(block_id)); CHECK(!rejected_.count(block_id)); - stats_set_candidate_status(cur_round_, src, block_id, ValidatorSessionStats::status_received); auto v = virtual_state_->choose_blocks_to_approve(description(), local_idx()); for (auto &b : v) { if (b && SentBlock::get_block_id(b) == block_id) { @@ -363,9 +379,16 @@ void ValidatorSessionImpl::process_query(PublicKeyHash src, td::BufferSlice data } void ValidatorSessionImpl::candidate_decision_fail(td::uint32 round, ValidatorSessionCandidateId hash, - std::string result, td::uint32 src, td::BufferSlice proof) { - stats_set_candidate_status(round, description().get_source_id(src), hash, ValidatorSessionStats::status_rejected, - result); + std::string result, td::uint32 src, td::BufferSlice proof, + double validation_time, bool validation_cached) { + auto stat = stats_get_candidate_stat(round, description().get_source_id(src), hash); + if (stat) { + stat->block_status = ValidatorSessionStats::status_rejected; + stat->comment = result; + stat->validation_time = validation_time; + stat->validated_at = td::Clocks::system(); + stat->validation_cached = validation_cached; + } if (round != cur_round_) { return; } @@ -379,9 +402,17 @@ void ValidatorSessionImpl::candidate_decision_fail(td::uint32 round, ValidatorSe } void ValidatorSessionImpl::candidate_decision_ok(td::uint32 round, ValidatorSessionCandidateId hash, RootHash root_hash, - FileHash file_hash, td::uint32 src, td::uint32 ok_from) { - stats_set_candidate_status(round, description().get_source_id(src), hash, ValidatorSessionStats::status_approved, - PSTRING() << "ts=" << ok_from); + FileHash file_hash, td::uint32 src, td::uint32 ok_from, + double validation_time, bool validation_cached) { + auto stat = stats_get_candidate_stat(round, description().get_source_id(src), hash); + if (stat) { + stat->block_status = ValidatorSessionStats::status_approved; + stat->comment = PSTRING() << "ts=" << ok_from; + stat->validation_time = validation_time; + stat->gen_utime = (double)ok_from; + stat->validated_at = td::Clocks::system(); + stat->validation_cached = validation_cached; + } if (round != cur_round_) { return; } @@ -418,10 +449,8 @@ void ValidatorSessionImpl::candidate_approved_signed(td::uint32 round, Validator } void ValidatorSessionImpl::generated_block(td::uint32 round, ValidatorSessionCandidateId root_hash, - td::BufferSlice data, td::BufferSlice collated_data) { - if (round != cur_round_) { - return; - } + td::BufferSlice data, td::BufferSlice collated_data, double collation_time, + bool collation_cached) { if (data.size() > description().opts().max_block_size || collated_data.size() > description().opts().max_collated_data_size) { LOG(ERROR) << this << ": generated candidate is too big. Dropping. size=" << data.size() << " " @@ -430,13 +459,27 @@ void ValidatorSessionImpl::generated_block(td::uint32 round, ValidatorSessionCan } auto file_hash = sha256_bits256(data.as_slice()); auto collated_data_file_hash = sha256_bits256(collated_data.as_slice()); + auto block_id = description().candidate_id(local_idx(), root_hash, file_hash, collated_data_file_hash); + auto stat = stats_get_candidate_stat(round, local_id(), block_id); + if (stat) { + stat->block_status = ValidatorSessionStats::status_received; + stat->collation_time = collation_time; + stat->collated_at = td::Clocks::system(); + stat->block_timestamp = td::Clocks::system(); + stat->collation_cached = collation_cached; + } + if (round != cur_round_) { + return; + } + td::Timer serialize_timer; auto b = create_tl_object(local_id().tl(), round, root_hash, std::move(data), std::move(collated_data)); - auto B = serialize_candidate(b, compress_block_candidates_).move_as_ok(); - - auto block_id = description().candidate_id(local_idx(), root_hash, file_hash, collated_data_file_hash); + if (stat) { + stat->serialize_time = serialize_timer.elapsed(); + stat->serialized_size = B.size(); + } td::actor::send_closure(catchain_, &catchain::CatChain::send_broadcast, std::move(B)); @@ -496,11 +539,11 @@ void ValidatorSessionImpl::check_generate_slot() { td::PerfWarningTimer timer{"too long block generation", 1.0}; auto P = td::PromiseCreator::lambda([SelfId = actor_id(this), print_id = print_id(), timer = std::move(timer), - round = cur_round_](td::Result R) { + round = cur_round_](td::Result R) { if (R.is_ok()) { - auto c = R.move_as_ok(); + auto c = std::move(R.ok_ref().candidate); td::actor::send_closure(SelfId, &ValidatorSessionImpl::generated_block, round, c.id.root_hash, - c.data.clone(), c.collated_data.clone()); + c.data.clone(), c.collated_data.clone(), timer.elapsed(), R.ok().is_cached); } else { LOG(WARNING) << print_id << ": failed to generate block candidate: " << R.move_as_error(); } @@ -550,6 +593,16 @@ void ValidatorSessionImpl::try_approve_block(const SentBlock *block) { it->second->round_ = std::max(it->second->round_, cur_round_); td::PerfWarningTimer timer{"too long block validation", 1.0}; auto &B = it->second; + auto stat = stats_get_candidate_stat(B->round_, PublicKeyHash{B->src_}); + if (stat) { + // Can happen if block is cached from previous round + if (stat->block_status == ValidatorSessionStats::status_none) { + stat->block_status = ValidatorSessionStats::status_received; + } + if (stat->block_timestamp <= 0.0) { + stat->block_timestamp = td::Clocks::system(); + } + } auto P = td::PromiseCreator::lambda([round = cur_round_, hash = block_id, root_hash = block->get_root_hash(), file_hash = block->get_file_hash(), timer = std::move(timer), @@ -563,10 +616,10 @@ void ValidatorSessionImpl::try_approve_block(const SentBlock *block) { auto R = res.move_as_ok(); if (R.is_ok()) { td::actor::send_closure(SelfId, &ValidatorSessionImpl::candidate_decision_ok, round, hash, root_hash, - file_hash, src, R.ok_from()); + file_hash, src, R.ok_from(), timer.elapsed(), R.is_cached()); } else { td::actor::send_closure(SelfId, &ValidatorSessionImpl::candidate_decision_fail, round, hash, R.reason(), - src, R.proof()); + src, R.proof(), timer.elapsed(), R.is_cached()); } }); pending_approve_.insert(block_id); @@ -824,22 +877,28 @@ void ValidatorSessionImpl::on_new_round(td::uint32 round) { cur_stats_.approve_signatures = (td::uint32)export_approve_sigs.size(); cur_stats_.approve_signatures_weight = approve_signatures_weight; cur_stats_.creator = description().get_source_id(block->get_src_idx()); + auto stat = stats_get_candidate_stat(cur_round_, cur_stats_.creator); + if (stat) { + stat->is_accepted = true; + } + auto stats = cur_stats_; + while (!stats.rounds.empty() && stats.rounds.size() + stats.first_round - 1 > cur_round_) { + stats.rounds.pop_back(); + } if (it == blocks_.end()) { callback_->on_block_committed(cur_round_, description().get_source_public_key(block->get_src_idx()), block->get_root_hash(), block->get_file_hash(), td::BufferSlice(), - std::move(export_sigs), std::move(export_approve_sigs), std::move(cur_stats_)); + std::move(export_sigs), std::move(export_approve_sigs), std::move(stats)); } else { callback_->on_block_committed(cur_round_, description().get_source_public_key(block->get_src_idx()), block->get_root_hash(), block->get_file_hash(), it->second->data_.clone(), - std::move(export_sigs), std::move(export_approve_sigs), std::move(cur_stats_)); + std::move(export_sigs), std::move(export_approve_sigs), std::move(stats)); } } cur_round_++; if (have_block) { stats_init(); - } else { - stats_add_round(); } auto it2 = blocks_.begin(); while (it2 != blocks_.end()) { @@ -997,13 +1056,35 @@ void ValidatorSessionImpl::start_up() { } void ValidatorSessionImpl::stats_init() { + auto old_rounds = std::move(cur_stats_.rounds); + if (stats_inited_ && cur_stats_.first_round + old_rounds.size() > cur_round_) { + old_rounds.erase(old_rounds.begin(), old_rounds.end() - (cur_stats_.first_round + old_rounds.size() - cur_round_)); + } else { + old_rounds.clear(); + } cur_stats_ = ValidatorSessionStats(); + cur_stats_.rounds = std::move(old_rounds); cur_stats_.first_round = cur_round_; cur_stats_.session_id = unique_hash_; cur_stats_.total_validators = description().get_total_nodes(); cur_stats_.total_weight = description().get_total_weight(); cur_stats_.self = description().get_source_id(local_idx()); - stats_add_round(); + + for (auto it = stats_pending_approve_.begin(); it != stats_pending_approve_.end(); ) { + if (it->first.first < cur_round_) { + it = stats_pending_approve_.erase(it); + } else { + ++it; + } + } + for (auto it = stats_pending_sign_.begin(); it != stats_pending_sign_.end(); ) { + if (it->first.first < cur_round_) { + it = stats_pending_sign_.erase(it); + } else { + ++it; + } + } + stats_inited_ = true; } void ValidatorSessionImpl::stats_add_round() { @@ -1016,6 +1097,9 @@ void ValidatorSessionImpl::stats_add_round() { if (priority >= 0) { CHECK((size_t)priority < round.producers.size()); round.producers[priority].id = description().get_source_id(i); + round.producers[priority].is_ours = (local_idx() == i); + round.producers[priority].approvers.resize(description().get_total_nodes(), false); + round.producers[priority].signers.resize(description().get_total_nodes(), false); } } while (!round.producers.empty() && round.producers.back().id.is_zero()) { @@ -1023,26 +1107,93 @@ void ValidatorSessionImpl::stats_add_round() { } } -void ValidatorSessionImpl::stats_set_candidate_status(td::uint32 round, PublicKeyHash src, - ValidatorSessionCandidateId candidate_id, int status, - std::string comment) { - if (round < cur_stats_.first_round || round - cur_stats_.first_round >= cur_stats_.rounds.size()) { - return; +ValidatorSessionStats::Producer *ValidatorSessionImpl::stats_get_candidate_stat( + td::uint32 round, PublicKeyHash src, ValidatorSessionCandidateId candidate_id) { + if (round < cur_stats_.first_round || round > cur_round_ + 5) { + return nullptr; + } + while (round - cur_stats_.first_round >= cur_stats_.rounds.size()) { + stats_add_round(); } auto &stats_round = cur_stats_.rounds[round - cur_stats_.first_round]; auto it = std::find_if(stats_round.producers.begin(), stats_round.producers.end(), [&](const ValidatorSessionStats::Producer &p) { return p.id == src; }); if (it == stats_round.producers.end()) { - return; + return nullptr; } - it->candidate_id = candidate_id; - if (it->block_status == ValidatorSessionStats::status_none) { - it->block_timestamp = (td::uint64)td::Clocks::system(); + if (!candidate_id.is_zero()) { + it->candidate_id = candidate_id; } - it->block_status = status; - if (!comment.empty()) { - it->comment = std::move(comment); + auto it2 = stats_pending_approve_.find({round, it->candidate_id}); + if (it2 != stats_pending_approve_.end()) { + for (td::uint32 node_id : it2->second) { + it->set_approved_by(node_id, description().get_node_weight(node_id), description().get_total_weight()); + } + stats_pending_approve_.erase(it2); } + it2 = stats_pending_sign_.find({round, it->candidate_id}); + if (it2 != stats_pending_sign_.end()) { + for (td::uint32 node_id : it2->second) { + it->set_signed_by(node_id, description().get_node_weight(node_id), description().get_total_weight()); + } + stats_pending_sign_.erase(it2); + } + return &*it; +} + +ValidatorSessionStats::Producer *ValidatorSessionImpl::stats_get_candidate_stat_by_id( + td::uint32 round, ValidatorSessionCandidateId candidate_id) { + if (round < cur_stats_.first_round || round > cur_round_ + 5) { + return nullptr; + } + while (round - cur_stats_.first_round >= cur_stats_.rounds.size()) { + stats_add_round(); + } + auto &stats_round = cur_stats_.rounds[round - cur_stats_.first_round]; + auto it = std::find_if(stats_round.producers.begin(), stats_round.producers.end(), + [&](const ValidatorSessionStats::Producer &p) { return p.candidate_id == candidate_id; }); + if (it == stats_round.producers.end()) { + return nullptr; + } + return &*it; +} + +void ValidatorSessionImpl::stats_process_action(td::uint32 node_id, ton_api::validatorSession_round_Message &action) { + ton_api::downcast_call(action, td::overloaded( + [&](const ton_api::validatorSession_message_submittedBlock &obj) { + auto candidate_id = description().candidate_id( + node_id, obj.root_hash_, obj.file_hash_, obj.collated_data_file_hash_); + auto stat = stats_get_candidate_stat( + obj.round_, description().get_source_id(node_id), candidate_id); + if (stat && stat->got_submit_at <= 0.0) { + stat->got_submit_at = td::Clocks::system(); + } + }, + [&](const ton_api::validatorSession_message_approvedBlock &obj) { + if (obj.candidate_ == skip_round_candidate_id()) { + return; + } + auto stat = stats_get_candidate_stat_by_id(obj.round_, obj.candidate_); + if (stat) { + stat->set_approved_by(node_id, description().get_node_weight(node_id), + description().get_total_weight()); + } else { + stats_pending_approve_[{obj.round_, obj.candidate_}].push_back(node_id); + } + }, + [&](const ton_api::validatorSession_message_commit &obj) { + if (obj.candidate_ == skip_round_candidate_id()) { + return; + } + auto stat = stats_get_candidate_stat_by_id(obj.round_, obj.candidate_); + if (stat) { + stat->set_signed_by(node_id, description().get_node_weight(node_id), + description().get_total_weight()); + } else { + stats_pending_sign_[{obj.round_, obj.candidate_}].push_back(node_id); + } + }, + [](const auto &) {})); } td::actor::ActorOwn ValidatorSession::create( diff --git a/validator-session/validator-session.h b/validator-session/validator-session.h index 6300eaa4..2dd6625c 100644 --- a/validator-session/validator-session.h +++ b/validator-session/validator-session.h @@ -56,6 +56,12 @@ class ValidatorSession : public td::actor::Actor { td::BufferSlice proof() const { return proof_.clone(); } + bool is_cached() const { + return is_cached_; + } + void set_is_cached(bool value = true) { + is_cached_ = value; + } CandidateDecision(td::uint32 ok_from) { ok_ = true; ok_from_ = ok_from; @@ -69,6 +75,12 @@ class ValidatorSession : public td::actor::Actor { td::uint32 ok_from_ = 0; std::string reason_; td::BufferSlice proof_; + bool is_cached_ = false; + }; + + struct GeneratedCandidate { + BlockCandidate candidate; + bool is_cached = false; }; class Callback { @@ -76,7 +88,7 @@ class ValidatorSession : public td::actor::Actor { virtual void on_candidate(td::uint32 round, PublicKey source, ValidatorSessionRootHash root_hash, td::BufferSlice data, td::BufferSlice collated_data, td::Promise promise) = 0; - virtual void on_generate_slot(td::uint32 round, td::Promise promise) = 0; + virtual void on_generate_slot(td::uint32 round, td::Promise promise) = 0; virtual void on_block_committed(td::uint32 round, PublicKey source, ValidatorSessionRootHash root_hash, ValidatorSessionFileHash file_hash, td::BufferSlice data, std::vector> signatures, diff --git a/validator-session/validator-session.hpp b/validator-session/validator-session.hpp index 619f7178..005292c0 100644 --- a/validator-session/validator-session.hpp +++ b/validator-session/validator-session.hpp @@ -159,10 +159,19 @@ class ValidatorSessionImpl : public ValidatorSession { bool compress_block_candidates_ = false; ValidatorSessionStats cur_stats_; + bool stats_inited_ = false; + std::map, std::vector> + stats_pending_approve_; // round, candidate_id -> approvers + std::map, std::vector> + stats_pending_sign_; // round, candidate_id -> signers void stats_init(); void stats_add_round(); - void stats_set_candidate_status(td::uint32 round, PublicKeyHash src, ValidatorSessionCandidateId candidate_id, - int status, std::string comment = ""); + ValidatorSessionStats::Producer *stats_get_candidate_stat( + td::uint32 round, PublicKeyHash src, + ValidatorSessionCandidateId candidate_id = ValidatorSessionCandidateId::zero()); + ValidatorSessionStats::Producer *stats_get_candidate_stat_by_id(td::uint32 round, + ValidatorSessionCandidateId candidate_id); + void stats_process_action(td::uint32 node_id, ton_api::validatorSession_round_Message &action); public: ValidatorSessionImpl(catchain::CatChainSessionId session_id, ValidatorSessionOptions opts, PublicKeyHash local_id, @@ -190,17 +199,16 @@ class ValidatorSessionImpl : public ValidatorSession { void process_query(PublicKeyHash src, td::BufferSlice data, td::Promise promise); void try_approve_block(const SentBlock *block); - void try_sign(); - void candidate_decision_fail(td::uint32 round, ValidatorSessionCandidateId hash, std::string result, - td::uint32 src, td::BufferSlice proof); + void candidate_decision_fail(td::uint32 round, ValidatorSessionCandidateId hash, std::string result, td::uint32 src, + td::BufferSlice proof, double validation_time, bool validation_cached); void candidate_decision_ok(td::uint32 round, ValidatorSessionCandidateId hash, RootHash root_hash, FileHash file_hash, - td::uint32 src, td::uint32 ok_from); + td::uint32 src, td::uint32 ok_from, double validation_time, bool validation_cached); void candidate_approved_signed(td::uint32 round, ValidatorSessionCandidateId hash, td::uint32 ok_from, td::BufferSlice signature); void generated_block(td::uint32 round, ValidatorSessionRootHash root_hash, td::BufferSlice data, - td::BufferSlice collated); + td::BufferSlice collated, double collation_time, bool collation_cached); void signed_block(td::uint32 round, ValidatorSessionCandidateId hash, td::BufferSlice signature); void end_request(td::uint32 round, ValidatorSessionCandidateId block_id) { diff --git a/validator/manager.cpp b/validator/manager.cpp index d88a5015..37281cc9 100644 --- a/validator/manager.cpp +++ b/validator/manager.cpp @@ -2714,8 +2714,12 @@ void ValidatorManagerImpl::log_validator_session_stats(BlockIdExt block_id, std::vector> producers; for (const auto &producer : round.producers) { producers.push_back(create_tl_object( - producer.id.bits256_value(), producer.candidate_id, producer.block_status, producer.block_timestamp, - producer.comment)); + producer.id.bits256_value(), producer.candidate_id, producer.block_status, producer.comment, + producer.block_timestamp, producer.is_accepted, producer.is_ours, producer.got_submit_at, + producer.collation_time, producer.collated_at, producer.collation_cached, producer.validation_time, + producer.validated_at, producer.validation_cached, producer.gen_utime, producer.approved_weight, + producer.approved_33pct_at, producer.approved_66pct_at, producer.signed_weight, producer.signed_33pct_at, + producer.signed_66pct_at, producer.serialize_time, producer.deserialize_time, producer.serialized_size)); } rounds.push_back(create_tl_object(round.timestamp, std::move(producers))); } diff --git a/validator/validator-group.cpp b/validator/validator-group.cpp index 05628ef5..5193e523 100644 --- a/validator/validator-group.cpp +++ b/validator/validator-group.cpp @@ -27,7 +27,8 @@ namespace ton { namespace validator { -void ValidatorGroup::generate_block_candidate(td::uint32 round_id, td::Promise promise) { +void ValidatorGroup::generate_block_candidate( + td::uint32 round_id, td::Promise promise) { if (round_id > last_known_round_id_) { last_known_round_id_ = round_id; } @@ -37,14 +38,18 @@ void ValidatorGroup::generate_block_candidate(td::uint32 round_id, td::Promiseresult) { - promise.set_result(cached_collated_block_->result.value().clone()); + promise.set_value({cached_collated_block_->result.value().clone(), true}); } else { - cached_collated_block_->promises.push_back(std::move(promise)); + cached_collated_block_->promises.push_back(promise.wrap([](BlockCandidate &&res) { + return validatorsession::ValidatorSession::GeneratedCandidate{std::move(res), true}; + })); } return; } cached_collated_block_ = std::make_shared(); - cached_collated_block_->promises.push_back(std::move(promise)); + cached_collated_block_->promises.push_back(promise.wrap([](BlockCandidate &&res) { + return validatorsession::ValidatorSession::GeneratedCandidate{std::move(res), false}; + })); run_collate_query( shard_, min_ts_, min_masterchain_block_id_, prev_block_ids_, Ed25519_PublicKey{local_id_full_.ed25519_value().raw()}, validator_set_, manager_, td::Timestamp::in(10.0), @@ -73,7 +78,7 @@ void ValidatorGroup::generated_block_candidate(std::shared_ptr promise) { + td::Promise> promise) { if (round_id > last_known_round_id_) { last_known_round_id_ = round_id; } @@ -88,7 +93,7 @@ void ValidatorGroup::validate_block_candidate(td::uint32 round_id, BlockCandidat CacheKey cache_key = block_to_cache_key(block); auto it = approved_candidates_cache_.find(cache_key); if (it != approved_candidates_cache_.end()) { - promise.set_result(it->second); + promise.set_value({it->second, true}); return; } @@ -113,7 +118,7 @@ void ValidatorGroup::validate_block_candidate(td::uint32 round_id, BlockCandidat ts); td::actor::send_closure(SelfId, &ValidatorGroup::add_available_block_candidate, block.pubkey.as_bits256(), block.id, block.collated_file_hash); - promise.set_result(ts); + promise.set_value({ts, false}); }, [&](CandidateReject reject) { promise.set_error( @@ -247,15 +252,18 @@ std::unique_ptr ValidatorGroup::ma void on_candidate(td::uint32 round, PublicKey source, validatorsession::ValidatorSessionRootHash root_hash, td::BufferSlice data, td::BufferSlice collated_data, td::Promise promise) override { - auto P = td::PromiseCreator::lambda([id = id_, promise = std::move(promise)](td::Result R) mutable { - if (R.is_ok()) { - promise.set_value(validatorsession::ValidatorSession::CandidateDecision{R.move_as_ok()}); - } else { - auto S = R.move_as_error(); - promise.set_value( - validatorsession::ValidatorSession::CandidateDecision{S.message().c_str(), td::BufferSlice()}); - } - }); + auto P = + td::PromiseCreator::lambda([promise = std::move(promise)](td::Result> R) mutable { + if (R.is_ok()) { + validatorsession::ValidatorSession::CandidateDecision decision(R.ok().first); + decision.set_is_cached(R.ok().second); + promise.set_value(std::move(decision)); + } else { + auto S = R.move_as_error(); + promise.set_value( + validatorsession::ValidatorSession::CandidateDecision{S.message().c_str(), td::BufferSlice()}); + } + }); BlockCandidate candidate{Ed25519_PublicKey{source.ed25519_value().raw()}, BlockIdExt{0, 0, 0, root_hash, sha256_bits256(data.as_slice())}, @@ -264,7 +272,8 @@ std::unique_ptr ValidatorGroup::ma td::actor::send_closure(id_, &ValidatorGroup::validate_block_candidate, round, std::move(candidate), std::move(P)); } - void on_generate_slot(td::uint32 round, td::Promise promise) override { + void on_generate_slot(td::uint32 round, + td::Promise promise) override { td::actor::send_closure(id_, &ValidatorGroup::generate_block_candidate, round, std::move(promise)); } void on_block_committed(td::uint32 round, PublicKey source, validatorsession::ValidatorSessionRootHash root_hash, diff --git a/validator/validator-group.hpp b/validator/validator-group.hpp index 2dbff8de..cb3f7a63 100644 --- a/validator/validator-group.hpp +++ b/validator/validator-group.hpp @@ -34,8 +34,10 @@ class ValidatorManager; class ValidatorGroup : public td::actor::Actor { public: - void generate_block_candidate(td::uint32 round_id, td::Promise promise); - void validate_block_candidate(td::uint32 round_id, BlockCandidate block, td::Promise promise); + void generate_block_candidate(td::uint32 round_id, + td::Promise promise); + void validate_block_candidate(td::uint32 round_id, BlockCandidate block, + td::Promise> promise); void accept_block_candidate(td::uint32 round_id, PublicKeyHash src, td::BufferSlice block, RootHash root_hash, FileHash file_hash, std::vector signatures, std::vector approve_signatures,