From f4165425008ebf05036748e280444d8b8f71762b Mon Sep 17 00:00:00 2001 From: Kevin Heifner Date: Mon, 7 Mar 2022 16:56:15 -0600 Subject: [PATCH] Add additional subjective cpu logging --- .../producer_plugin/subjective_billing.hpp | 6 ++- plugins/producer_plugin/producer_plugin.cpp | 38 +++++++++---------- .../test/test_subjective_billing.cpp | 10 ++--- 3 files changed, 27 insertions(+), 27 deletions(-) diff --git a/plugins/producer_plugin/include/eosio/producer_plugin/subjective_billing.hpp b/plugins/producer_plugin/include/eosio/producer_plugin/subjective_billing.hpp index 3361575ce07..8b3a4781e76 100644 --- a/plugins/producer_plugin/include/eosio/producer_plugin/subjective_billing.hpp +++ b/plugins/producer_plugin/include/eosio/producer_plugin/subjective_billing.hpp @@ -174,10 +174,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 ) { diff --git a/plugins/producer_plugin/producer_plugin.cpp b/plugins/producer_plugin/producer_plugin.cpp index 62626e466ab..c99caf09806 100644 --- a/plugins/producer_plugin/producer_plugin.cpp +++ b/plugins/producer_plugin/producer_plugin.cpp @@ -249,7 +249,7 @@ class producer_plugin_impl : public std::enable_shared_from_this 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) ); } } } @@ -1932,7 +1930,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; } diff --git a/plugins/producer_plugin/test/test_subjective_billing.cpp b/plugins/producer_plugin/test/test_subjective_billing.cpp index 40ea4d21c5d..e7e2106130b 100644 --- a/plugins/producer_plugin/test/test_subjective_billing.cpp +++ b/plugins/producer_plugin/test/test_subjective_billing.cpp @@ -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) ); @@ -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(); @@ -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();