Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

[1.0.3] Fix issue with block report log time including the time for maybe_switch_forks #881

Merged
merged 5 commits into from
Oct 3, 2024
Merged
Changes from 2 commits
Commits
File filter

Filter by extension

Filter by extension

Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
68 changes: 35 additions & 33 deletions plugins/producer_plugin/producer_plugin.cpp
Original file line number Diff line number Diff line change
Expand Up @@ -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 ) ) {
Expand Down Expand Up @@ -882,10 +881,13 @@ class producer_plugin_impl : public std::enable_shared_from_this<producer_plugin

if (block_info) {
auto[block_num, block_producer] = *block_info;
producer_plugin::speculative_block_metrics metrics;
_time_tracker.report(block_num, block_producer, metrics);
if (_update_speculative_block_metrics)
fc::time_point now = fc::time_point::now();
if (_update_speculative_block_metrics) {
producer_plugin::speculative_block_metrics metrics;
_time_tracker.populate_speculative_block_metrics(block_num, block_producer, now, metrics);
_update_speculative_block_metrics(metrics);
}
_time_tracker.report(block_num, block_producer, now);
}
_time_tracker.clear();
}
Expand Down Expand Up @@ -2020,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`
heifner marked this conversation as resolved.
Show resolved Hide resolved

if (chain.should_terminate()) {
app().quit();
Expand Down Expand Up @@ -2954,25 +2955,26 @@ 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);
heifner marked this conversation as resolved.
Show resolved Hide resolved

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<generated_transaction_multi_index, by_delay>().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<generated_transaction_multi_index, by_delay>().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();
}
Expand Down
Loading