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.

Sign up for GitHub

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

[3.2] Additional transaction/block time logging #537

Merged
merged 4 commits into from
Jun 29, 2022
Merged

[3.2] Additional transaction/block time logging #537

Show file tree
Hide file tree
Changes from 3 commits
Commits
Show all changes
4 commits
Select commit Hold shift + click to select a range
a0e8d6d
GH-293 Add similar logging for failed and successful scheduled transa…
heifner Jun 23, 2022
a7cc626
GH-292 Add additional logging to Produced and Received block log mess…
heifner Jun 25, 2022
5f40d51
GH-294 Add wall clock time to some existing transaction logging. Adde…
heifner Jun 25, 2022
9c17974
Merge remote-tracking branch 'origin/main' into additional-logging
heifner Jun 29, 2022
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
44 changes: 30 additions & 14 deletions libraries/chain/controller.cpp
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -417,7 +417,8 @@ struct controller_impl {

for( auto bitr = branch.rbegin(); bitr != branch.rend(); ++bitr ) {
if( read_mode == db_read_mode::IRREVERSIBLE ) {
apply_block( *bitr, controller::block_status::complete, trx_meta_cache_lookup{} );
controller::block_report br;
apply_block( br, *bitr, controller::block_status::complete, trx_meta_cache_lookup{} );
head = (*bitr);
fork_db.mark_valid( head );
}
Expand Down Expand Up @@ -718,7 +719,8 @@ struct controller_impl {
pending_head = fork_db.pending_head()
) {
wlog( "applying branch from fork database ending with block: ${id}", ("id", pending_head->id) );
maybe_switch_forks( pending_head, controller::block_status::complete, forked_branch_callback{}, trx_meta_cache_lookup{} );
controller::block_report br;
maybe_switch_forks( br, pending_head, controller::block_status::complete, forked_branch_callback{}, trx_meta_cache_lookup{} );
}
}
}
Expand Down Expand Up @@ -1943,9 +1945,11 @@ struct controller_impl {
}


void apply_block( const block_state_ptr& bsp, controller::block_status s, const trx_meta_cache_lookup& trx_lookup )
void apply_block( controller::block_report& br, const block_state_ptr& bsp, controller::block_status s,
const trx_meta_cache_lookup& trx_lookup )
{ try {
try {
auto start = fc::time_point::now();
const signed_block_ptr& b = bsp->block;
const auto& new_protocol_feature_activations = bsp->get_new_protocol_feature_activations();

Expand Down Expand Up @@ -2021,6 +2025,12 @@ struct controller_impl {
EOS_ASSERT( r == static_cast<const transaction_receipt_header&>(receipt),
block_validate_exception, "receipt does not match, ${lhs} != ${rhs}",
("lhs", r)("rhs", static_cast<const transaction_receipt_header&>(receipt)) );

if( trace ) {
br.total_net_usage += trace->net_usage;
if( trace->receipt ) br.total_cpu_usage_us += trace->receipt->cpu_usage_us;
br.total_elapsed_time += trace->elapsed;
}
}

// validated in create_block_state_future()
Expand All @@ -2045,6 +2055,7 @@ struct controller_impl {
pending->_block_stage = completed_block{ bsp };

commit_block(false);
br.total_time = fc::time_point::now() - start;
return;
} catch ( const std::bad_alloc& ) {
throw;
Expand Down Expand Up @@ -2096,7 +2107,8 @@ struct controller_impl {
} );
}

void push_block( std::future<block_state_ptr>& block_state_future,
void push_block( controller::block_report& br,
std::future<block_state_ptr>& block_state_future,
const forked_branch_callback& forked_branch_cb, const trx_meta_cache_lookup& trx_lookup )
{
controller::block_status s = controller::block_status::complete;
Expand Down Expand Up @@ -2126,7 +2138,7 @@ struct controller_impl {
emit( self.accepted_block_header, bsp );

if( read_mode != db_read_mode::IRREVERSIBLE ) {
maybe_switch_forks( fork_db.pending_head(), s, forked_branch_cb, trx_lookup );
maybe_switch_forks( br, fork_db.pending_head(), s, forked_branch_cb, trx_lookup );
} else {
log_irreversible();
}
Expand Down Expand Up @@ -2170,8 +2182,9 @@ struct controller_impl {

emit( self.accepted_block_header, bsp );

controller::block_report br;
if( s == controller::block_status::irreversible ) {
apply_block( bsp, s, trx_meta_cache_lookup{} );
apply_block( br, bsp, s, trx_meta_cache_lookup{} );
head = bsp;

// On replay, log_irreversible is not called and so no irreversible_block signal is emitted.
Expand All @@ -2185,19 +2198,19 @@ struct controller_impl {
} else {
EOS_ASSERT( read_mode != db_read_mode::IRREVERSIBLE, block_validate_exception,
"invariant failure: cannot replay reversible blocks while in irreversible mode" );
maybe_switch_forks( bsp, s, forked_branch_callback{}, trx_meta_cache_lookup{} );
maybe_switch_forks( br, bsp, s, forked_branch_callback{}, trx_meta_cache_lookup{} );
}

} FC_LOG_AND_RETHROW( )
}

void maybe_switch_forks( const block_state_ptr& new_head, controller::block_status s,
void maybe_switch_forks( controller::block_report& br, const block_state_ptr& new_head, controller::block_status s,
const forked_branch_callback& forked_branch_cb, const trx_meta_cache_lookup& trx_lookup )
{
bool head_changed = true;
if( new_head->header.previous == head->id ) {
try {
apply_block( new_head, s, trx_lookup );
apply_block( br, new_head, s, trx_lookup );
fork_db.mark_valid( new_head );
head = new_head;
} catch ( const std::exception& e ) {
Expand Down Expand Up @@ -2228,8 +2241,9 @@ struct controller_impl {
for( auto ritr = branches.first.rbegin(); ritr != branches.first.rend(); ++ritr ) {
auto except = std::exception_ptr{};
try {
apply_block( *ritr, (*ritr)->is_valid() ? controller::block_status::validated
: controller::block_status::complete, trx_lookup );
br = controller::block_report{};
apply_block( br, *ritr, (*ritr)->is_valid() ? controller::block_status::validated
: controller::block_status::complete, trx_lookup );
fork_db.mark_valid( *ritr );
head = *ritr;
} catch ( const std::bad_alloc& ) {
Expand Down Expand Up @@ -2260,7 +2274,8 @@ struct controller_impl {

// re-apply good blocks
for( auto ritr = branches.second.rbegin(); ritr != branches.second.rend(); ++ritr ) {
apply_block( *ritr, controller::block_status::validated /* we previously validated these blocks*/, trx_lookup );
br = controller::block_report{};
apply_block( br, *ritr, controller::block_status::validated /* we previously validated these blocks*/, trx_lookup );
head = *ritr;
}
std::rethrow_exception(except);
Expand Down Expand Up @@ -2820,11 +2835,12 @@ std::future<block_state_ptr> controller::create_block_state_future( const block_
return my->create_block_state_future( id, b );
}

void controller::push_block( std::future<block_state_ptr>& block_state_future,
void controller::push_block( controller::block_report& br,
std::future<block_state_ptr>& block_state_future,
const forked_branch_callback& forked_branch_cb, const trx_meta_cache_lookup& trx_lookup )
{
validate_db_available_size();
my->push_block( block_state_future, forked_branch_cb, trx_lookup );
my->push_block( br, block_state_future, forked_branch_cb, trx_lookup );
}

transaction_trace_ptr controller::push_transaction( const transaction_metadata_ptr& trx,
Expand Down
10 changes: 9 additions & 1 deletion libraries/chain/include/eosio/chain/controller.hpp
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -170,12 +170,20 @@ namespace eosio { namespace chain {

std::future<block_state_ptr> create_block_state_future( const block_id_type& id, const signed_block_ptr& b );

struct block_report {
size_t total_net_usage = 0;
size_t total_cpu_usage_us = 0;
fc::microseconds total_elapsed_time{};
fc::microseconds total_time{};
};
/**
* @param br returns statistics for block
* @param block_state_future provide from call to create_block_state_future
* @param cb calls cb with forked applied transactions for each forked block
* @param trx_lookup user provided lookup function for externally cached transaction_metadata
*/
void push_block( std::future<block_state_ptr>& block_state_future,
void push_block( block_report& br,
std::future<block_state_ptr>& block_state_future,
const forked_branch_callback& cb,
const trx_meta_cache_lookup& trx_lookup );

Expand Down
9 changes: 6 additions & 3 deletions libraries/testing/include/eosio/testing/tester.hpp
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -597,7 +597,8 @@ namespace eosio { namespace testing {
signed_block_ptr produce_block( fc::microseconds skip_time = fc::milliseconds(config::block_interval_ms) )override {
auto sb = _produce_block(skip_time, false);
auto bsf = validating_node->create_block_state_future( sb->calculate_id(), sb );
validating_node->push_block( bsf, forked_branch_callback{}, trx_meta_cache_lookup{} );
controller::block_report br;
validating_node->push_block( br, bsf, forked_branch_callback{}, trx_meta_cache_lookup{} );

return sb;
}
Expand All @@ -608,14 +609,16 @@ namespace eosio { namespace testing {

void validate_push_block(const signed_block_ptr& sb) {
auto bs = validating_node->create_block_state_future( sb->calculate_id(), sb );
validating_node->push_block( bs, forked_branch_callback{}, trx_meta_cache_lookup{} );
controller::block_report br;
validating_node->push_block( br, bs, forked_branch_callback{}, trx_meta_cache_lookup{} );
}

signed_block_ptr produce_empty_block( fc::microseconds skip_time = fc::milliseconds(config::block_interval_ms) )override {
unapplied_transactions.add_aborted( control->abort_block() );
auto sb = _produce_block(skip_time, true);
auto bsf = validating_node->create_block_state_future( sb->calculate_id(), sb );
validating_node->push_block( bsf, forked_branch_callback{}, trx_meta_cache_lookup{} );
controller::block_report br;
validating_node->push_block( br, bsf, forked_branch_callback{}, trx_meta_cache_lookup{} );

return sb;
}
Expand Down
6 changes: 4 additions & 2 deletions libraries/testing/tester.cpp
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -322,7 +322,8 @@ namespace eosio { namespace testing {
void base_tester::push_block(signed_block_ptr b) {
auto bsf = control->create_block_state_future(b->calculate_id(), b);
unapplied_transactions.add_aborted( control->abort_block() );
control->push_block( bsf, [this]( const branch_type& forked_branch ) {
controller::block_report br;
control->push_block( br, bsf, [this]( const branch_type& forked_branch ) {
unapplied_transactions.add_forked( forked_branch );
}, [this]( const transaction_id_type& id ) {
return unapplied_transactions.get_trx( id );
Expand Down Expand Up @@ -1050,7 +1051,8 @@ namespace eosio { namespace testing {
if( block ) { //&& !b.control->is_known_block(block->id()) ) {
auto bsf = b.control->create_block_state_future( block->calculate_id(), block );
b.control->abort_block();
b.control->push_block(bsf, forked_branch_callback{}, trx_meta_cache_lookup{}); //, eosio::chain::validation_steps::created_block);
controller::block_report br;
b.control->push_block(br, bsf, forked_branch_callback{}, trx_meta_cache_lookup{}); //, eosio::chain::validation_steps::created_block);
}
}
};
Expand Down
Loading