Skip to content

Commit

Permalink
Merge pull request #837 from AntelopeIO/totaltime_fix
Browse files Browse the repository at this point in the history 
[1.0.2] Fix incorrect reported total time of applying a received block or produced block
  • Loading branch information
@linh2931
linh2931 authored Sep 30, 2024
2 parents b64bd34 + 130d69c commit 1440dc1
Show file tree
Hide file tree
Showing 3 changed files with 17 additions and 24 deletions.
34 changes: 14 additions & 20 deletions libraries/chain/controller.cpp
View file
Original file line number Diff line number Diff line change
Expand Up @@ -833,7 +833,7 @@ struct pending_state {
block_stage_type _block_stage;
controller::block_status _block_status = controller::block_status::ephemeral;
std::optional<block_id_type> _producer_block_id;
controller::block_report _block_report{};
controller::block_report _block_report;

// Legacy
pending_state(maybe_session&& s,
Expand Down Expand Up @@ -2761,7 +2761,6 @@ struct controller_impl {
trace->elapsed = fc::time_point::now() - start;
pending->_block_report.total_cpu_usage_us += billed_cpu_time_us;
pending->_block_report.total_elapsed_time += trace->elapsed;
pending->_block_report.total_time += trace->elapsed;
dmlog_applied_transaction(trace);
emit( applied_transaction, std::tie(trace, trx->packed_trx()), __FILE__, __LINE__ );
undo_session.squash();
Expand Down Expand Up @@ -2838,7 +2837,6 @@ struct controller_impl {
pending->_block_report.total_net_usage += trace->net_usage;
pending->_block_report.total_cpu_usage_us += trace->receipt->cpu_usage_us;
pending->_block_report.total_elapsed_time += trace->elapsed;
pending->_block_report.total_time += fc::time_point::now() - start;

return trace;
} catch( const disallowed_transaction_extensions_bad_block_exception& ) {
Expand Down Expand Up @@ -2877,7 +2875,6 @@ struct controller_impl {
pending->_block_report.total_net_usage += trace->net_usage;
if( trace->receipt ) pending->_block_report.total_cpu_usage_us += trace->receipt->cpu_usage_us;
pending->_block_report.total_elapsed_time += trace->elapsed;
pending->_block_report.total_time += trace->elapsed;
return trace;
}
trace->elapsed = fc::time_point::now() - start;
Expand Down Expand Up @@ -2927,7 +2924,6 @@ struct controller_impl {
pending->_block_report.total_net_usage += trace->net_usage;
if( trace->receipt ) pending->_block_report.total_cpu_usage_us += trace->receipt->cpu_usage_us;
pending->_block_report.total_elapsed_time += trace->elapsed;
pending->_block_report.total_time += fc::time_point::now() - start;

return trace;
} FC_CAPTURE_AND_RETHROW() } /// push_scheduled_transaction
Expand Down Expand Up @@ -3083,7 +3079,6 @@ struct controller_impl {
pending->_block_report.total_net_usage += trace->net_usage;
pending->_block_report.total_cpu_usage_us += trace->receipt->cpu_usage_us;
pending->_block_report.total_elapsed_time += trace->elapsed;
pending->_block_report.total_time += fc::time_point::now() - start;
}

return trace;
Expand Down Expand Up @@ -3111,7 +3106,6 @@ struct controller_impl {
pending->_block_report.total_net_usage += trace->net_usage;
if( trace->receipt ) pending->_block_report.total_cpu_usage_us += trace->receipt->cpu_usage_us;
pending->_block_report.total_elapsed_time += trace->elapsed;
pending->_block_report.total_time += fc::time_point::now() - start;
}

return trace;
Expand Down Expand Up @@ -3372,8 +3366,6 @@ struct controller_impl {
* @post regardless of the success of commit block there is no active pending block
*/
void commit_block( controller::block_report& br, controller::block_status s ) {
fc::time_point start = fc::time_point::now();

auto reset_pending_on_exit = fc::make_scoped_exit([this]{
pending.reset();
});
Expand Down Expand Up @@ -3464,13 +3456,13 @@ struct controller_impl {
if (s == controller::block_status::incomplete) {
const auto& id = chain_head.id();
const auto& new_b = chain_head.block();
br.total_time += fc::time_point::now() - start;
fc::time_point now = fc::time_point::now();

ilog("Produced block ${id}... #${n} @ ${t} signed by ${p} "
"[trxs: ${count}, lib: ${lib}${confs}, net: ${net}, cpu: ${cpu}, elapsed: ${et}, time: ${tt}]",
"[trxs: ${count}, lib: ${lib}${confs}, net: ${net}, cpu: ${cpu}, elapsed: ${et} us, time: ${tt} us]",
("p", new_b->producer)("id", id.str().substr(8, 16))("n", new_b->block_num())("t", new_b->timestamp)
("count", new_b->transactions.size())("lib", chain_head.irreversible_blocknum())("net", br.total_net_usage)
("cpu", br.total_cpu_usage_us)("et", br.total_elapsed_time)("tt", br.total_time)
("cpu", br.total_cpu_usage_us)("et", br.total_elapsed_time)("tt", now - br.start_time)
("confs", new_b->is_proper_svnn_block() ? "" : ", confirmed: " + std::to_string(new_b->confirmed)));
}

Expand Down Expand Up @@ -3631,19 +3623,19 @@ struct controller_impl {
fc::time_point now = fc::time_point::now();
if (now - bsp->timestamp() < fc::minutes(5) || (bsp->block_num() % 1000 == 0)) {
ilog("Received block ${id}... #${n} @ ${t} signed by ${p} " // "Received" instead of "Applied" so it matches existing log output
"[trxs: ${count}, lib: ${lib}, net: ${net}, cpu: ${cpu}, elapsed: ${elapsed}, time: ${time}, latency: ${latency} ms]",
"[trxs: ${count}, lib: ${lib}, net: ${net}, cpu: ${cpu}, elapsed: ${elapsed} us, time: ${time} us, latency: ${latency} ms]",
("p", bsp->producer())("id", bsp->id().str().substr(8, 16))("n", bsp->block_num())("t", bsp->timestamp())
("count", bsp->block->transactions.size())("lib", bsp->irreversible_blocknum())
("net", br.total_net_usage)("cpu", br.total_cpu_usage_us)
("elapsed", br.total_elapsed_time)("time", br.total_time)("latency", (now - bsp->timestamp()).count() / 1000));
("elapsed", br.total_elapsed_time)("time", now - br.start_time)("latency", (now - bsp->timestamp()).count() / 1000));
const auto& hb_id = chain_head.id();
const auto& hb = chain_head.block();
if (read_mode != db_read_mode::IRREVERSIBLE && hb && hb_id != bsp->id() && hb != nullptr) { // not applied to head
ilog("Block not applied to head ${id}... #${n} @ ${t} signed by ${p} "
"[trxs: ${count}, lib: ${lib}, net: ${net}, cpu: ${cpu}, elapsed: ${elapsed}, time: ${time}, latency: ${latency} ms]",
"[trxs: ${count}, lib: ${lib}, net: ${net}, cpu: ${cpu}, elapsed: ${elapsed} us, time: ${time} us, latency: ${latency} ms]",
("p", hb->producer)("id", hb_id.str().substr(8, 16))("n", hb->block_num())("t", hb->timestamp)
("count", hb->transactions.size())("lib", chain_head.irreversible_blocknum())
("net", br.total_net_usage)("cpu", br.total_cpu_usage_us)("elapsed", br.total_elapsed_time)("time", br.total_time)
("net", br.total_net_usage)("cpu", br.total_cpu_usage_us)("elapsed", br.total_elapsed_time)("time", now - br.start_time)
("latency", (now - hb->timestamp).count() / 1000));
}
}
Expand All @@ -3659,7 +3651,7 @@ struct controller_impl {
return false;
}

auto start = fc::time_point::now();
auto start = fc::time_point::now(); // want to report total time of applying a block

const bool already_valid = bsp->is_valid();
// Only need to consider voting if not already validated, if already validated then we have already voted.
Expand All @@ -3672,6 +3664,9 @@ struct controller_impl {

start_block( b->timestamp, b->confirmed, new_protocol_feature_activations, s, producer_block_id, fc::time_point::maximum() );

assert(pending); // created by start_block
pending->_block_report.start_time = start;

// validated in create_block_handle()
std::get<building_block>(pending->_block_stage).trx_mroot_or_receipt_digests() = b->transaction_mroot;

Expand Down Expand Up @@ -3795,7 +3790,6 @@ struct controller_impl {
pending->_block_stage = completed_block{ block_handle{bsp} };

br = pending->_block_report; // copy before commit block destroys pending
br.total_time += fc::time_point::now() - start;
commit_block(br, s);

if (!already_valid)
Expand Down Expand Up @@ -4459,7 +4453,7 @@ struct controller_impl {
try {
const auto& bsp = *ritr;

br = controller::block_report{};
br = controller::block_report();
bool applied = apply_block( br, bsp, bsp->is_valid() ? controller::block_status::validated
: controller::block_status::complete, trx_lookup );
if (!switch_fork && (!applied || check_shutdown())) {
Expand Down Expand Up @@ -4494,7 +4488,7 @@ struct controller_impl {

// re-apply good blocks
for( auto ritr = branches.second.rbegin(); ritr != branches.second.rend(); ++ritr ) {
br = controller::block_report{};
br = controller::block_report();
apply_block( br, *ritr, controller::block_status::validated /* we previously validated these blocks*/, trx_lookup );
}
std::rethrow_exception(except);
Expand Down
2 changes: 1 addition & 1 deletion libraries/chain/include/eosio/chain/controller.hpp
View file
Original file line number Diff line number Diff line change
Expand Up @@ -186,7 +186,7 @@ namespace eosio::chain {
size_t total_net_usage = 0;
size_t total_cpu_usage_us = 0;
fc::microseconds total_elapsed_time{};
fc::microseconds total_time{};
fc::time_point start_time;
};

void assemble_and_complete_block( block_report& br, const signer_callback_type& signer_callback );
Expand Down
5 changes: 2 additions & 3 deletions plugins/producer_plugin/producer_plugin.cpp
View file
Original file line number Diff line number Diff line change
Expand Up @@ -972,7 +972,7 @@ class producer_plugin_impl : public std::enable_shared_from_this<producer_plugin
_update_incoming_block_metrics({.trxs_incoming_total = block->transactions.size(),
.cpu_usage_us = br.total_cpu_usage_us,
.total_elapsed_time_us = br.total_elapsed_time.count(),
.total_time_us = br.total_time.count(),
.total_time_us = (now - br.start_time).count(),
.net_usage_us = br.total_net_usage,
.block_latency_us = (now - block->timestamp).count(),
.last_irreversible = chain.last_irreversible_block_num(),
Expand Down Expand Up @@ -2951,7 +2951,6 @@ void producer_plugin_impl::produce_block() {
return sigs;
});

br.total_time += fc::time_point::now() - start;
chain.commit_block(br);

const signed_block_ptr new_b = chain.head().block();
Expand All @@ -2963,7 +2962,7 @@ void producer_plugin_impl::produce_block() {
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 = br.total_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();
Expand Down

0 comments on commit 1440dc1

Please sign in to comment.