From fe6e1f4d8f0061357d91e93718a6b524d65c5949 Mon Sep 17 00:00:00 2001 From: greg7mdp Date: Wed, 2 Oct 2024 17:30:16 -0400 Subject: [PATCH 1/4] Small cleanup for metrics updating. --- plugins/producer_plugin/producer_plugin.cpp | 65 +++++++++++---------- 1 file changed, 34 insertions(+), 31 deletions(-) diff --git a/plugins/producer_plugin/producer_plugin.cpp b/plugins/producer_plugin/producer_plugin.cpp index bffd585d5c..141c964ee7 100644 --- a/plugins/producer_plugin/producer_plugin.cpp +++ b/plugins/producer_plugin/producer_plugin.cpp @@ -280,23 +280,22 @@ struct block_time_tracker { last_time_point = now; } - void report(uint32_t block_num, account_name producer, producer_plugin::speculative_block_metrics& metrics) { - auto now = fc::time_point::now(); - report(block_num, producer, now); - metrics.block_producer = producer; - metrics.block_num = block_num; - metrics.block_total_time_us = (now - clear_time_point).count(); - metrics.block_idle_us = block_idle_time.count(); - metrics.num_success_trx = trx_success_num; - metrics.success_trx_time_us = trx_success_time.count(); - metrics.num_fail_trx = trx_fail_num; - metrics.fail_trx_time_us = trx_fail_time.count(); - metrics.num_transient_trx = transient_trx_num; + void populate_speculative_block_metrics(uint32_t block_num, account_name producer, const fc::time_point& now, + producer_plugin::speculative_block_metrics& metrics) { + metrics.block_producer = producer; + metrics.block_num = block_num; + metrics.block_total_time_us = (now - clear_time_point).count(); + metrics.block_idle_us = block_idle_time.count(); + metrics.num_success_trx = trx_success_num; + metrics.success_trx_time_us = trx_success_time.count(); + metrics.num_fail_trx = trx_fail_num; + metrics.fail_trx_time_us = trx_fail_time.count(); + metrics.num_transient_trx = transient_trx_num; metrics.transient_trx_time_us = transient_trx_time.count(); - metrics.block_other_time_us = other_time.count(); + metrics.block_other_time_us = other_time.count(); } - void report(uint32_t block_num, account_name producer, const fc::time_point& now = fc::time_point::now()) { + void report(uint32_t block_num, account_name producer, const fc::time_point& now) { using namespace std::string_literals; assert(!paused); if( _log.is_enabled( fc::log_level::debug ) ) { @@ -882,10 +881,13 @@ class producer_plugin_impl : public std::enable_shared_from_thisblock_num(), new_b->producer, now); + if (_update_produced_block_metrics) { producer_plugin::produced_block_metrics metrics; - metrics.unapplied_transactions_total = _unapplied_transactions.size(); + metrics.unapplied_transactions_total = _unapplied_transactions.size(); metrics.subjective_bill_account_size_total = chain.get_subjective_billing().get_account_cache_size(); - metrics.scheduled_trxs_total = chain.db().get_index().size(); - metrics.trxs_produced_total = new_b->transactions.size(); - metrics.cpu_usage_us = br.total_cpu_usage_us; + metrics.scheduled_trxs_total = chain.db().get_index().size(); + metrics.trxs_produced_total = new_b->transactions.size(); + metrics.cpu_usage_us = br.total_cpu_usage_us; metrics.total_elapsed_time_us = br.total_elapsed_time.count(); - metrics.total_time_us = (fc::time_point::now() - br.start_time).count(); - metrics.net_usage_us = br.total_net_usage; - metrics.last_irreversible = chain.last_irreversible_block_num(); - metrics.head_block_num = chain.head().block_num(); - _update_produced_block_metrics(metrics); + metrics.total_time_us = (fc::time_point::now() - br.start_time).count(); + metrics.net_usage_us = br.total_net_usage; + metrics.last_irreversible = chain.last_irreversible_block_num(); + metrics.head_block_num = chain.head().block_num(); - _time_tracker.add_other_time(); - _time_tracker.report(new_b->block_num(), new_b->producer, metrics); - } else { - _time_tracker.add_other_time(); - _time_tracker.report(new_b->block_num(), new_b->producer); + _time_tracker.populate_speculative_block_metrics(new_b->block_num(), new_b->producer, now, metrics); + _update_produced_block_metrics(metrics); } _time_tracker.clear(); } From fbad7538d014531b915bce4885c7870c366ebe40 Mon Sep 17 00:00:00 2001 From: greg7mdp Date: Wed, 2 Oct 2024 18:11:21 -0400 Subject: [PATCH 2/4] Don't include the time for `maybe_switch_forks` in the block report as `other`. --- plugins/producer_plugin/producer_plugin.cpp | 3 +-- 1 file changed, 1 insertion(+), 2 deletions(-) diff --git a/plugins/producer_plugin/producer_plugin.cpp b/plugins/producer_plugin/producer_plugin.cpp index 141c964ee7..db02f59c53 100644 --- a/plugins/producer_plugin/producer_plugin.cpp +++ b/plugins/producer_plugin/producer_plugin.cpp @@ -2022,11 +2022,10 @@ producer_plugin_impl::start_block_result producer_plugin_impl::start_block() { if (!chain_plug->accept_transactions()) return start_block_result::waiting_for_block; - abort_block(); - chain.maybe_switch_forks([this](const transaction_metadata_ptr& trx) { _unapplied_transactions.add_forked(trx); }, [this](const transaction_id_type& id) { return _unapplied_transactions.get_trx(id); }); + abort_block(); // does reset `_time_tracker`, so should be after `maybe_switch_forks` if (chain.should_terminate()) { app().quit(); From b776b9d4462b24e681ef5a93938bd06c1ac1a3cb Mon Sep 17 00:00:00 2001 From: greg7mdp Date: Wed, 2 Oct 2024 20:05:34 -0400 Subject: [PATCH 3/4] keep `abort_block()` before `maybe_switch_forks` as the latter asserts that there is not a pending block. --- plugins/producer_plugin/producer_plugin.cpp | 6 ++++-- 1 file changed, 4 insertions(+), 2 deletions(-) diff --git a/plugins/producer_plugin/producer_plugin.cpp b/plugins/producer_plugin/producer_plugin.cpp index db02f59c53..9f96a3d509 100644 --- a/plugins/producer_plugin/producer_plugin.cpp +++ b/plugins/producer_plugin/producer_plugin.cpp @@ -2022,16 +2022,18 @@ producer_plugin_impl::start_block_result producer_plugin_impl::start_block() { if (!chain_plug->accept_transactions()) return start_block_result::waiting_for_block; + abort_block(); + chain.maybe_switch_forks([this](const transaction_metadata_ptr& trx) { _unapplied_transactions.add_forked(trx); }, [this](const transaction_id_type& id) { return _unapplied_transactions.get_trx(id); }); - abort_block(); // does reset `_time_tracker`, so should be after `maybe_switch_forks` - if (chain.should_terminate()) { app().quit(); return start_block_result::failed; } + _time_tracker.clear(); // make sure we start tracking block time after `maybe_switch_forks()` + block_handle head = chain.head(); block_num_type head_block_num = head.block_num(); const fc::time_point now = fc::time_point::now(); From a0c811772ad6b1896840c83921f51b9c5dfc8ba8 Mon Sep 17 00:00:00 2001 From: greg7mdp Date: Wed, 2 Oct 2024 20:14:38 -0400 Subject: [PATCH 4/4] Include the time for updating prometheus in `other` --- plugins/producer_plugin/producer_plugin.cpp | 12 +++++++----- 1 file changed, 7 insertions(+), 5 deletions(-) diff --git a/plugins/producer_plugin/producer_plugin.cpp b/plugins/producer_plugin/producer_plugin.cpp index 9f96a3d509..18e3350310 100644 --- a/plugins/producer_plugin/producer_plugin.cpp +++ b/plugins/producer_plugin/producer_plugin.cpp @@ -2957,20 +2957,18 @@ void producer_plugin_impl::produce_block() { chain.commit_block(br); const signed_block_ptr new_b = chain.head().block(); - fc::time_point now = fc::time_point::now(); - - _time_tracker.add_other_time(); - _time_tracker.report(new_b->block_num(), new_b->producer, now); if (_update_produced_block_metrics) { producer_plugin::produced_block_metrics metrics; + fc::time_point now = fc::time_point::now(); + metrics.unapplied_transactions_total = _unapplied_transactions.size(); metrics.subjective_bill_account_size_total = chain.get_subjective_billing().get_account_cache_size(); metrics.scheduled_trxs_total = chain.db().get_index().size(); metrics.trxs_produced_total = new_b->transactions.size(); metrics.cpu_usage_us = br.total_cpu_usage_us; metrics.total_elapsed_time_us = br.total_elapsed_time.count(); - metrics.total_time_us = (fc::time_point::now() - br.start_time).count(); + metrics.total_time_us = (now - br.start_time).count(); metrics.net_usage_us = br.total_net_usage; metrics.last_irreversible = chain.last_irreversible_block_num(); metrics.head_block_num = chain.head().block_num(); @@ -2978,6 +2976,10 @@ void producer_plugin_impl::produce_block() { _time_tracker.populate_speculative_block_metrics(new_b->block_num(), new_b->producer, now, metrics); _update_produced_block_metrics(metrics); } + + fc::time_point now = fc::time_point::now(); + _time_tracker.add_other_time(now); + _time_tracker.report(new_b->block_num(), new_b->producer, now); _time_tracker.clear(); }