Skip to content

Commit

Permalink
GH-2102 Move produced/received block logging into controller so it lo…
Browse files Browse the repository at this point in the history 
…gs all processed blocks
  • Loading branch information
@heifner
heifner committed Apr 6, 2024
1 parent ba5006e commit 9de11ff
Show file tree
Hide file tree
Showing 4 changed files with 78 additions and 66 deletions.
66 changes: 49 additions & 17 deletions libraries/chain/controller.cpp
View file
Original file line number Diff line number Diff line change
Expand Up @@ -3339,16 +3339,45 @@ struct controller_impl {
return {};
}


template<typename BSP>
void log_applied(controller::block_report& br, const BSP& bsp) const {
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]",
("p", bsp->producer())("id", bsp->id().str().substr(8, 16))("n", bsp->block_num())("t", bsp->timestamp())
("count", bsp->block->transactions.size())("lib", fork_db_root_block_num())
("net", br.total_net_usage)("cpu", br.total_cpu_usage_us)
("elapsed", br.total_elapsed_time)("time", br.total_time)("latency", (fc::time_point::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]",
("p", hb->producer)("id", hb_id.str().substr(8, 16))("n", hb->block_num())("t", hb->timestamp)
("count", hb->transactions.size())("lib", fork_db_root_block_num())
("net", br.total_net_usage)("cpu", br.total_cpu_usage_us)("elapsed", br.total_elapsed_time)("time", br.total_time)
("latency", (now - hb->timestamp).count() / 1000));
}
}
}

template<class BSP>
void apply_block( controller::block_report& br, const BSP& bsp, controller::block_status s,
const trx_meta_cache_lookup& trx_lookup ) {
try {
try {
auto start = fc::time_point::now();

const bool already_valid = bsp->is_valid();
if (!already_valid) // has not been validated (applied) before, only in forkdb, integrate and possibly vote now
integrate_qc(bsp);

const signed_block_ptr& b = bsp->block;
const auto& new_protocol_feature_activations = bsp->get_new_protocol_feature_activations();
const auto& producer_block_id = bsp->id();

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

// validated in create_block_handle()
Expand Down Expand Up @@ -3476,6 +3505,9 @@ struct controller_impl {
commit_block(s);
br.total_time = fc::time_point::now() - start;

if (!already_valid)
log_applied(br, bsp);

} catch ( const std::bad_alloc& ) {
throw;
} catch ( const boost::interprocess::bad_alloc& ) {
Expand Down Expand Up @@ -4012,23 +4044,11 @@ struct controller_impl {
auto except = std::exception_ptr{};
try {
const auto& bsp = *ritr;
bool valid = bsp->is_valid();
if (!valid) // has not been validated (applied) before, only in forkdb, integrate and possibly vote now
integrate_qc(bsp);

br = controller::block_report{};
apply_block( br, bsp, valid ? controller::block_status::validated
: controller::block_status::complete, trx_lookup );
if (!valid) { // was just applied for first time so log it
if (fc::time_point::now() - bsp->timestamp() < fc::minutes(5) || (bsp->block_num() % 1000 == 0)) {
ilog("Applied block ${id}... #${n} @ ${t} signed by ${p} "
"[trxs: ${count}, lib: ${lib}, net: ${net}, cpu: ${cpu}, elapsed: ${elapsed}, time: ${time}, 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", fork_db_root_block_num())
("net", br.total_net_usage)("cpu", br.total_cpu_usage_us)
("elapsed", br.total_elapsed_time)("time", br.total_time)("latency", (fc::time_point::now() - bsp->timestamp()).count() / 1000));
}
}
apply_block( br, bsp, bsp->is_valid() ? controller::block_status::validated
: controller::block_status::complete, trx_lookup );

if( conf.terminate_at_block > 0 && conf.terminate_at_block <= chain_head.block_num()) {
ilog("Reached configured maximum block ${num}; terminating", ("num", conf.terminate_at_block) );
shutdown();
Expand Down Expand Up @@ -4750,9 +4770,21 @@ void controller::assemble_and_complete_block( block_report& br, const signer_cal
br = my->pending->_block_report;
}

void controller::commit_block() {
void controller::commit_block(block_report& br) {
fc::time_point start = fc::time_point::now();

validate_db_available_size();
my->commit_block(block_status::incomplete);

const auto& id = head_block_id();
const auto& new_b = head_block();
br.total_time += fc::time_point::now() - start;

ilog("Produced block ${id}... #${n} @ ${t} signed by ${p} "
"[trxs: ${count}, lib: ${lib}, confirmed: ${confs}, net: ${net}, cpu: ${cpu}, elapsed: ${et}, time: ${tt}]",
("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", last_irreversible_block_num())("net", br.total_net_usage)
("cpu", br.total_cpu_usage_us)("et", br.total_elapsed_time)("tt", br.total_time)("confs", new_b->confirmed));
}

void controller::maybe_switch_forks(const forked_callback_t& cb, const trx_meta_cache_lookup& trx_lookup) {
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 @@ -177,7 +177,7 @@ namespace eosio::chain {

void assemble_and_complete_block( block_report& br, const signer_callback_type& signer_callback );
void sign_block( const signer_callback_type& signer_callback );
void commit_block();
void commit_block(block_report& br);
void maybe_switch_forks(const forked_callback_t& cb, const trx_meta_cache_lookup& trx_lookup);

// thread-safe
Expand Down
2 changes: 1 addition & 1 deletion libraries/testing/tester.cpp
View file
Original file line number Diff line number Diff line change
Expand Up @@ -482,7 +482,7 @@ namespace eosio { namespace testing {
return result;
} );

control->commit_block();
control->commit_block(br);
last_produced_block[producer_name] = control->head_block_id();

_wait_for_vote_if_needed(*control);
Expand Down
74 changes: 27 additions & 47 deletions plugins/producer_plugin/producer_plugin.cpp
View file
Original file line number Diff line number Diff line change
Expand Up @@ -283,19 +283,8 @@ struct block_time_tracker {
}

void report(uint32_t block_num, account_name producer, producer_plugin::speculative_block_metrics& metrics) {
using namespace std::string_literals;
assert(!paused);
auto now = fc::time_point::now();
if( _log.is_enabled( fc::log_level::debug ) ) {
auto diff = now - clear_time_point - block_idle_time - trx_success_time - trx_fail_time - transient_trx_time - other_time;
fc_dlog( _log, "Block #${n} ${p} trx idle: ${i}us out of ${t}us, success: ${sn}, ${s}us, fail: ${fn}, ${f}us, "
"transient: ${ttn}, ${tt}us, other: ${o}us${rest}",
("n", block_num)("p", producer)
("i", block_idle_time)("t", now - clear_time_point)("sn", trx_success_num)("s", trx_success_time)
("fn", trx_fail_num)("f", trx_fail_time)
("ttn", transient_trx_num)("tt", transient_trx_time)
("o", other_time)("rest", diff.count() > 5 ? ", diff: "s + std::to_string(diff.count()) + "us"s : ""s ) );
}
report(block_num, producer, now);
metrics.block_producer = producer;
metrics.block_num = block_num;
metrics.block_total_time_us = (now - clear_time_point).count();
Expand All @@ -309,6 +298,21 @@ struct block_time_tracker {
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()) {
using namespace std::string_literals;
assert(!paused);
if( _log.is_enabled( fc::log_level::debug ) ) {
auto diff = now - clear_time_point - block_idle_time - trx_success_time - trx_fail_time - transient_trx_time - other_time;
fc_dlog( _log, "Block #${n} ${p} trx idle: ${i}us out of ${t}us, success: ${sn}, ${s}us, fail: ${fn}, ${f}us, "
"transient: ${ttn}, ${tt}us, other: ${o}us${rest}",
("n", block_num)("p", producer)
("i", block_idle_time)("t", now - clear_time_point)("sn", trx_success_num)("s", trx_success_time)
("fn", trx_fail_num)("f", trx_fail_time)
("ttn", transient_trx_num)("tt", transient_trx_time)
("o", other_time)("rest", diff.count() > 5 ? ", diff: "s + std::to_string(diff.count()) + "us"s : ""s ) );
}
}

void clear() {
assert(!paused);
block_idle_time = trx_fail_time = trx_success_time = transient_trx_time = other_time = fc::microseconds{};
Expand Down Expand Up @@ -744,25 +748,7 @@ class producer_plugin_impl : public std::enable_shared_from_this<producer_plugin
_production_enabled = true;
}

if (now - block->timestamp < fc::minutes(5) || (blk_num % 1000 == 0)) {
ilog("Received block ${id}... #${n} @ ${t} signed by ${p} "
"[trxs: ${count}, lib: ${lib}, net: ${net}, cpu: ${cpu}, elapsed: ${elapsed}, time: ${time}, latency: ${latency} ms]",
("p", block->producer)("id", id.str().substr(8, 16))("n", blk_num)("t", block->timestamp)
("count", block->transactions.size())("lib", chain.last_irreversible_block_num())
("net", br.total_net_usage)("cpu", br.total_cpu_usage_us)
("elapsed", br.total_elapsed_time)("time", br.total_time)("latency", (now - block->timestamp).count() / 1000));
const auto& hb_id = chain.head_block_id();
const auto& hb = chain.head_block();
if (chain.get_read_mode() != db_read_mode::IRREVERSIBLE && hb && hb_id != 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]",
("p", hb->producer)("id", hb_id.str().substr(8, 16))("n", hb->block_num())("t", hb->timestamp)
("count", hb->transactions.size())("lib", chain.last_irreversible_block_num())
("net", br.total_net_usage)("cpu", br.total_cpu_usage_us)("elapsed", br.total_elapsed_time)("time", br.total_time)
("latency", (now - hb->timestamp).count() / 1000));
}
}
if (_update_incoming_block_metrics) {
if (_update_incoming_block_metrics) { // only includes those blocks pushed, not those that are accepted and processed internally
_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(),
Expand Down Expand Up @@ -2672,25 +2658,12 @@ void producer_plugin_impl::produce_block() {
return sigs;
});

chain.commit_block();

const auto& id = chain.head_block_id();
const auto& new_b = chain.head_block();
producer_plugin::produced_block_metrics metrics;

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

ilog("Produced block ${id}... #${n} @ ${t} signed by ${p} "
"[trxs: ${count}, lib: ${lib}, confirmed: ${confs}, net: ${net}, cpu: ${cpu}, elapsed: ${et}, time: ${tt}]",
("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.last_irreversible_block_num())("net", br.total_net_usage)
("cpu", br.total_cpu_usage_us)("et", br.total_elapsed_time)("tt", br.total_time)("confs", new_b->confirmed));

_time_tracker.add_other_time();
_time_tracker.report(new_b->block_num(), new_b->producer, metrics);
_time_tracker.clear();

const auto& new_b = chain.head_block();
if (_update_produced_block_metrics) {
producer_plugin::produced_block_metrics metrics;
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();
Expand All @@ -2702,7 +2675,14 @@ void producer_plugin_impl::produce_block() {
metrics.last_irreversible = chain.last_irreversible_block_num();
metrics.head_block_num = chain.head_block_num();
_update_produced_block_metrics(metrics);

_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.clear();
}

void producer_plugin::received_block(uint32_t block_num) {
Expand Down

0 comments on commit 9de11ff

Please sign in to comment.