Skip to content

Commit

Permalink
Merge pull request #52 from eosnetworkfoundation/sub-fail-log-2.0
Browse files Browse the repository at this point in the history
Add additional subjective cpu logging
  • Loading branch information
heifner authored Mar 12, 2022
2 parents 64c7f61 + fd9bb05 commit e024e34
Show file tree
Hide file tree
Showing 3 changed files with 27 additions and 27 deletions.
Original file line number Diff line number Diff line change
Expand Up @@ -171,10 +171,12 @@ class subjective_billing {
_block_subjective_bill_cache.clear();
}

void on_block( const block_state_ptr& bsp, const fc::time_point& now ) {
if( bsp == nullptr ) return;
void on_block( fc::logger& log, const block_state_ptr& bsp, const fc::time_point& now ) {
if( bsp == nullptr || _disabled ) return;
const auto time_ordinal = time_ordinal_for(now);
const auto orig_count = _account_subjective_bill_cache.size();
remove_subjective_billing( bsp, time_ordinal );
fc_dlog( log, "Subjective billed accounts ${n} removed ${r}", ("n", orig_count)("r", orig_count - _account_subjective_bill_cache.size()) );
}

bool remove_expired( fc::logger& log, const fc::time_point& pending_block_time, const fc::time_point& now, const fc::time_point& deadline ) {
Expand Down
38 changes: 18 additions & 20 deletions plugins/producer_plugin/producer_plugin.cpp
Original file line number Diff line number Diff line change
Expand Up @@ -282,7 +282,7 @@ class producer_plugin_impl : public std::enable_shared_from_this<producer_plugin

void on_block( const block_state_ptr& bsp ) {
_unapplied_transactions.clear_applied( bsp );
_subjective_billing.on_block( bsp, fc::time_point::now() );
_subjective_billing.on_block( _log, bsp, fc::time_point::now() );
}

void on_block_header( const block_state_ptr& bsp ) {
Expand Down Expand Up @@ -1824,28 +1824,26 @@ class account_failures {
return false;
}

void report() const {
void report(const subjective_billing& sub_bill) const {
if( _log.is_enabled( fc::log_level::debug ) ) {
auto now = fc::time_point::now();
for( const auto& e : failed_accounts ) {
std::string reason;
if( e.second.num_failures > max_failures_per_account ) {
reason.clear();
if( e.second.is_deadline() ) reason += "deadline";
if( e.second.is_tx_cpu_usage() ) {
if( !reason.empty() ) reason += ", ";
reason += "tx_cpu_usage";
}
if( e.second.is_eosio_assert() ) {
if( !reason.empty() ) reason += ", ";
reason += "assert";
}
if( e.second.is_other() ) {
if( !reason.empty() ) reason += ", ";
reason += "other";
}
fc_dlog( _log, "Dropped ${n} trxs, account: ${a}, reason: ${r} exceeded",
("n", e.second.num_failures - max_failures_per_account)("a", e.first)("r", reason) );
if( e.second.is_deadline() ) reason += "deadline";
if( e.second.is_tx_cpu_usage() ) {
if( !reason.empty() ) reason += ", ";
reason += "tx_cpu_usage";
}
if( e.second.is_eosio_assert() ) {
if( !reason.empty() ) reason += ", ";
reason += "assert";
}
if( e.second.is_other() ) {
if( !reason.empty() ) reason += ", ";
reason += "other";
}
fc_dlog( _log, "Failed ${n} trxs, account: ${a}, sub bill: ${b}us, reason: ${r}",
("n", e.second.num_failures)("b", sub_bill.get_subjective_bill(e.first, now))("a", e.first)("r", reason) );
}
}
}
Expand Down Expand Up @@ -1974,7 +1972,7 @@ bool producer_plugin_impl::process_unapplied_trxs( const fc::time_point& deadlin

fc_dlog( _log, "Processed ${m} of ${n} previously applied transactions, Applied ${applied}, Failed/Dropped ${failed}",
("m", num_processed)( "n", unapplied_trxs_size )("applied", num_applied)("failed", num_failed) );
account_fails.report();
account_fails.report(_subjective_billing);
}
return !exhausted;
}
Expand Down
10 changes: 5 additions & 5 deletions plugins/producer_plugin/test/test_subjective_billing.cpp
Original file line number Diff line number Diff line change
Expand Up @@ -41,7 +41,7 @@ BOOST_AUTO_TEST_CASE( subjective_bill_test ) {
BOOST_CHECK_EQUAL( 13+11, sub_bill.get_subjective_bill(a, now) );
BOOST_CHECK_EQUAL( 9, sub_bill.get_subjective_bill(b, now) );

sub_bill.on_block({}, now);
sub_bill.on_block(log, {}, now);
sub_bill.abort_block(); // they all failed so nothing in aborted block

BOOST_CHECK_EQUAL( 13+11, sub_bill.get_subjective_bill(a, now) );
Expand Down Expand Up @@ -69,13 +69,13 @@ BOOST_AUTO_TEST_CASE( subjective_bill_test ) {
BOOST_CHECK_EQUAL( 23+19, sub_bill.get_subjective_bill(a, now) );
BOOST_CHECK_EQUAL( 7, sub_bill.get_subjective_bill(b, now) );

sub_bill.on_block({}, now); // have not seen any of the transactions come back yet
sub_bill.on_block(log, {}, now); // have not seen any of the transactions come back yet
sub_bill.abort_block();

BOOST_CHECK_EQUAL( 23+19, sub_bill.get_subjective_bill(a, now) );
BOOST_CHECK_EQUAL( 7, sub_bill.get_subjective_bill(b, now) );

sub_bill.on_block({}, now);
sub_bill.on_block(log, {}, now);
sub_bill.remove_subjective_billing( id1, 0 ); // simulate seeing id1 come back in block (this is what on_block would do)
sub_bill.abort_block();

Expand All @@ -96,13 +96,13 @@ BOOST_AUTO_TEST_CASE( subjective_bill_test ) {
BOOST_CHECK_EQUAL( 0, sub_bill.get_subjective_bill(b, now) ); // should not include what is in the pending block
BOOST_CHECK_EQUAL( 0, sub_bill.get_subjective_bill(c, now) );

sub_bill.on_block({}, now); // have not seen any of the transactions come back yet
sub_bill.on_block(log, {}, now); // have not seen any of the transactions come back yet
sub_bill.abort_block(); // aborts the pending block, so subjective billing needs to include the reverted trxs

BOOST_CHECK_EQUAL( 23+19+55+11, sub_bill.get_subjective_bill(a, now) );
BOOST_CHECK_EQUAL( 3+7, sub_bill.get_subjective_bill(b, now) );

sub_bill.on_block({}, now);
sub_bill.on_block(log, {}, now);
sub_bill.remove_subjective_billing( id3, 0 ); // simulate seeing id3 come back in block (this is what on_block would do)
sub_bill.remove_subjective_billing( id4, 0 ); // simulate seeing id4 come back in block (this is what on_block would do)
sub_bill.abort_block();
Expand Down

0 comments on commit e024e34

Please sign in to comment.