From a0e8d6dc64910a4255cb74d883b8ae90cc6913e8 Mon Sep 17 00:00:00 2001
From: Kevin Heifner <heifnerk@objectcomputing.com>
Date: Wed, 22 Jun 2022 21:30:34 -0500
Subject: [PATCH 1/3] GH-293 Add similar logging for failed and successful
 scheduled transactions as input transactions.

---
 plugins/producer_plugin/producer_plugin.cpp | 21 ++++++++++++++++++++-
 1 file changed, 20 insertions(+), 1 deletion(-)

diff --git a/plugins/producer_plugin/producer_plugin.cpp b/plugins/producer_plugin/producer_plugin.cpp
index 8e4a7919cb..a4f4ddd85c 100644
--- a/plugins/producer_plugin/producer_plugin.cpp
+++ b/plugins/producer_plugin/producer_plugin.cpp
@@ -581,7 +581,6 @@ class producer_plugin_impl : public std::enable_shared_from_this<producer_plugin
                } else {
                   return chain_plug->get_log_trx_trace( std::get<transaction_trace_ptr>(response) );
                }
-
             };
 
             fc::exception_ptr except_ptr; // rejected
@@ -2157,6 +2156,14 @@ void producer_plugin_impl::process_scheduled_and_incoming_trxs( const fc::time_p
          break;
       }
 
+      auto get_first_authorizer = [&](const transaction_trace_ptr& trace) {
+         for( const auto& a : trace->action_traces ) {
+            for( const auto& u : a.act.authorization )
+               return u.actor;
+         }
+         return account_name();
+      };
+
       try {
          fc::microseconds max_trx_time = fc::milliseconds( _max_transaction_time_ms.load() );
          if( max_trx_time.count() < 0 ) max_trx_time = fc::microseconds::maximum();
@@ -2169,11 +2176,23 @@ void producer_plugin_impl::process_scheduled_and_incoming_trxs( const fc::time_p
                   break;
                }
             } else {
+               fc_dlog(_trx_failed_trace_log, "[TRX_TRACE] Block ${block_num} for producer ${prod} is REJECTING scheduled tx: ${txid}, auth: ${a} : ${why} ",
+                       ("block_num", chain.head_block_num() + 1)("prod", get_pending_block_producer())
+                       ("txid", trx_id)("a", get_first_authorizer(trace))("why", trace->except->what()));
+               fc_dlog(_trx_trace_failure_log, "[TRX_TRACE] Block ${block_num} for producer ${prod} is REJECTING scheduled tx: ${entire_trace}",
+                       ("block_num", chain.head_block_num() + 1)("prod", get_pending_block_producer())
+                       ("entire_trace", chain_plug->get_log_trx_trace(trace)));
                // this failed our configured maximum transaction time, we don't want to replay it add it to a blacklist
                _blacklisted_transactions.insert(transaction_id_with_expiry{trx_id, sch_expiration});
                num_failed++;
             }
          } else {
+            fc_dlog(_trx_successful_trace_log, "[TRX_TRACE] Block ${block_num} for producer ${prod} is ACCEPTING scheduled tx: ${txid}, auth: ${a}, cpu: ${cpu}",
+                    ("block_num", chain.head_block_num() + 1)("prod", get_pending_block_producer())
+                    ("txid", trx_id)("a", get_first_authorizer(trace))("cpu", trace->receipt ? trace->receipt->cpu_usage_us : 0));
+            fc_dlog(_trx_trace_success_log, "[TRX_TRACE] Block ${block_num} for producer ${prod} is ACCEPTING scheduled tx: ${entire_trace}",
+                    ("block_num", chain.head_block_num() + 1)("prod", get_pending_block_producer())
+                    ("entire_trace", chain_plug->get_log_trx_trace(trace)));
             num_applied++;
          }
       } LOG_AND_DROP();

From a7cc6266dd634f03905aa8cd53ec3e3589bdf5fd Mon Sep 17 00:00:00 2001
From: Kevin Heifner <heifnerk@objectcomputing.com>
Date: Sat, 25 Jun 2022 10:18:02 -0500
Subject: [PATCH 2/3] GH-292 Add additional logging to Produced and Received
 block log messages.

---
 libraries/chain/controller.cpp                | 44 +++++++++++++------
 .../chain/include/eosio/chain/controller.hpp  | 10 ++++-
 .../testing/include/eosio/testing/tester.hpp  |  9 ++--
 libraries/testing/tester.cpp                  |  6 ++-
 plugins/producer_plugin/producer_plugin.cpp   | 30 +++++++++----
 unittests/block_tests.cpp                     |  6 ++-
 unittests/forked_tests.cpp                    |  3 +-
 7 files changed, 77 insertions(+), 31 deletions(-)

diff --git a/libraries/chain/controller.cpp b/libraries/chain/controller.cpp
index 384247db91..0dc854dfa1 100644
--- a/libraries/chain/controller.cpp
+++ b/libraries/chain/controller.cpp
@@ -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 );
             }
@@ -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{} );
          }
       }
    }
@@ -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();
 
@@ -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()
@@ -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;
@@ -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;
@@ -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();
          }
@@ -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.
@@ -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 ) {
@@ -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& ) {
@@ -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);
@@ -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,
diff --git a/libraries/chain/include/eosio/chain/controller.hpp b/libraries/chain/include/eosio/chain/controller.hpp
index b95b9e33ea..67996ccd21 100644
--- a/libraries/chain/include/eosio/chain/controller.hpp
+++ b/libraries/chain/include/eosio/chain/controller.hpp
@@ -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 );
 
diff --git a/libraries/testing/include/eosio/testing/tester.hpp b/libraries/testing/include/eosio/testing/tester.hpp
index 67ede1bc49..975220063f 100644
--- a/libraries/testing/include/eosio/testing/tester.hpp
+++ b/libraries/testing/include/eosio/testing/tester.hpp
@@ -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;
       }
@@ -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;
       }
diff --git a/libraries/testing/tester.cpp b/libraries/testing/tester.cpp
index 27042d491a..b65102652f 100644
--- a/libraries/testing/tester.cpp
+++ b/libraries/testing/tester.cpp
@@ -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 );
@@ -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);
             }
          }
       };
diff --git a/plugins/producer_plugin/producer_plugin.cpp b/plugins/producer_plugin/producer_plugin.cpp
index a4f4ddd85c..5f6a374ebb 100644
--- a/plugins/producer_plugin/producer_plugin.cpp
+++ b/plugins/producer_plugin/producer_plugin.cpp
@@ -470,8 +470,9 @@ class producer_plugin_impl : public std::enable_shared_from_this<producer_plugin
             throw;
          };
 
+         controller::block_report br;
          try {
-            chain.push_block( bsf, [this]( const branch_type& forked_branch ) {
+            chain.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 );
@@ -498,15 +499,21 @@ class producer_plugin_impl : public std::enable_shared_from_this<producer_plugin
          }
 
          if( fc::time_point::now() - block->timestamp < fc::minutes(5) || (blk_num % 1000 == 0) ) {
-            ilog("Received block ${id}... #${n} @ ${t} signed by ${p} [trxs: ${count}, lib: ${lib}, conf: ${confs}, latency: ${latency} ms]",
+            ilog("Received block ${id}... #${n} @ ${t} signed by ${p} "
+                 "[trxs: ${count}, lib: ${lib}, conf: ${confs}, 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())
-                 ("confs", block->confirmed)("latency", (fc::time_point::now() - block->timestamp).count()/1000 ) );
+                 ("confs", block->confirmed)("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() - block->timestamp).count()/1000 ) );
             if( chain.get_read_mode() != db_read_mode::IRREVERSIBLE && hbs->id != id && hbs->block != nullptr ) { // not applied to head
-               ilog("Block not applied to head ${id}... #${n} @ ${t} signed by ${p} [trxs: ${count}, dpos: ${dpos}, conf: ${confs}, latency: ${latency} ms]",
+               ilog("Block not applied to head ${id}... #${n} @ ${t} signed by ${p} "
+                    "[trxs: ${count}, dpos: ${dpos}, conf: ${confs}, net: ${net}, cpu: ${cpu}, elapsed: ${elapsed}, time: ${time}, latency: ${latency} ms]",
                     ("p",hbs->block->producer)("id",hbs->id.str().substr(8,16))("n",hbs->block_num)("t",hbs->block->timestamp)
                     ("count",hbs->block->transactions.size())("dpos", hbs->dpos_irreversible_blocknum)
-                    ("confs", hbs->block->confirmed)("latency", (fc::time_point::now() - hbs->block->timestamp).count()/1000 ) );
+                    ("confs", hbs->block->confirmed)("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() - hbs->block->timestamp).count()/1000 ) );
             }
          }
 
@@ -2450,11 +2457,18 @@ void producer_plugin_impl::produce_block() {
    _account_fails.report();
    _account_fails.clear();
 
-   ilog("Produced block ${id}... #${n} @ ${t} signed by ${p} [trxs: ${count}, lib: ${lib}, confirmed: ${confs}]",
+   controller::block_report br;
+   for( const auto& r : new_bs->block->transactions ) {
+      br.total_cpu_usage_us += r.cpu_usage_us;
+      br.total_net_usage += r.net_usage_words * 8;
+   }
+   ilog("Produced block ${id}... #${n} @ ${t} signed by ${p} "
+        "[trxs: ${count}, lib: ${lib}, confirmed: ${confs}, net: ${net}, cpu: ${cpu}]",
         ("p",new_bs->header.producer)("id",new_bs->id.str().substr(8,16))
         ("n",new_bs->block_num)("t",new_bs->header.timestamp)
-        ("count",new_bs->block->transactions.size())("lib",chain.last_irreversible_block_num())("confs", new_bs->header.confirmed));
-
+        ("count",new_bs->block->transactions.size())("lib",chain.last_irreversible_block_num())
+        ("net", br.total_net_usage)("cpu", br.total_cpu_usage_us)
+        ("confs", new_bs->header.confirmed));
 }
 
 void producer_plugin::log_failed_transaction(const transaction_id_type& trx_id, const packed_transaction_ptr& packed_trx_ptr, const char* reason) const {
diff --git a/unittests/block_tests.cpp b/unittests/block_tests.cpp
index d837a13dd2..d3072f133f 100644
--- a/unittests/block_tests.cpp
+++ b/unittests/block_tests.cpp
@@ -46,7 +46,8 @@ BOOST_AUTO_TEST_CASE(block_with_invalid_tx_test)
    tester validator;
    auto bs = validator.control->create_block_state_future( copy_b->calculate_id(), copy_b );
    validator.control->abort_block();
-   BOOST_REQUIRE_EXCEPTION(validator.control->push_block( bs, forked_branch_callback{}, trx_meta_cache_lookup{} ), fc::exception ,
+   controller::block_report br;
+   BOOST_REQUIRE_EXCEPTION(validator.control->push_block( br, bs, forked_branch_callback{}, trx_meta_cache_lookup{} ), fc::exception ,
    [] (const fc::exception &e)->bool {
       return e.code() == account_name_exists_exception::code_value ;
    }) ;
@@ -84,7 +85,8 @@ BOOST_AUTO_TEST_CASE(block_with_invalid_tx_mroot_test)
    tester validator;
    auto bs = validator.control->create_block_state_future( copy_b->calculate_id(), copy_b );
    validator.control->abort_block();
-   BOOST_REQUIRE_EXCEPTION(validator.control->push_block( bs, forked_branch_callback{}, trx_meta_cache_lookup{} ), fc::exception ,
+   controller::block_report br;
+   BOOST_REQUIRE_EXCEPTION(validator.control->push_block( br, bs, forked_branch_callback{}, trx_meta_cache_lookup{} ), fc::exception ,
                            [] (const fc::exception &e)->bool {
                               return e.code() == block_validate_exception::code_value &&
                                      e.to_detail_string().find("invalid block transaction merkle root") != std::string::npos;
diff --git a/unittests/forked_tests.cpp b/unittests/forked_tests.cpp
index 6c178d0894..ebb321fc71 100644
--- a/unittests/forked_tests.cpp
+++ b/unittests/forked_tests.cpp
@@ -269,7 +269,8 @@ BOOST_AUTO_TEST_CASE( forking ) try {
    auto bad_id = bad_block.calculate_id();
    auto bad_block_bs = c.control->create_block_state_future( bad_id, std::make_shared<signed_block>(std::move(bad_block)) );
    c.control->abort_block();
-   BOOST_REQUIRE_EXCEPTION(c.control->push_block( bad_block_bs, forked_branch_callback{}, trx_meta_cache_lookup{} ), fc::exception,
+   controller::block_report br;
+   BOOST_REQUIRE_EXCEPTION(c.control->push_block( br, bad_block_bs, forked_branch_callback{}, trx_meta_cache_lookup{} ), fc::exception,
       [] (const fc::exception &ex)->bool {
          return ex.to_detail_string().find("block signed by unexpected key") != std::string::npos;
       });

From 5f40d51a8c55bc0900d0facfdb5ac97ab81f82d3 Mon Sep 17 00:00:00 2001
From: Kevin Heifner <heifnerk@objectcomputing.com>
Date: Sat, 25 Jun 2022 11:52:13 -0500
Subject: [PATCH 3/3] GH-294 Add wall clock time to some existing transaction
 logging. Added log of time between transactions to give some information on
 time the chain is idle.

---
 plugins/producer_plugin/producer_plugin.cpp | 35 +++++++++++++++------
 1 file changed, 25 insertions(+), 10 deletions(-)

diff --git a/plugins/producer_plugin/producer_plugin.cpp b/plugins/producer_plugin/producer_plugin.cpp
index 5f6a374ebb..028a448dc0 100644
--- a/plugins/producer_plugin/producer_plugin.cpp
+++ b/plugins/producer_plugin/producer_plugin.cpp
@@ -333,6 +333,7 @@ class producer_plugin_impl : public std::enable_shared_from_this<producer_plugin
       bool                                                      _disable_subjective_api_billing = true;
       fc::time_point                                            _irreversible_block_time;
       fc::microseconds                                          _keosd_provider_timeout_us;
+      fc::time_point                                            _idle_trx_time;
 
       std::vector<chain::digest_type>                           _protocol_features_to_activate;
       bool                                                      _protocol_features_signaled = false; // to mark whether it has been signaled in start_block
@@ -685,6 +686,7 @@ class producer_plugin_impl : public std::enable_shared_from_this<producer_plugin
             }
 
             auto start = fc::time_point::now();
+            fc_dlog( _trx_successful_trace_log, "Time since last trx: ${t}us", ("t", start - _idle_trx_time) );
             fc::microseconds max_trx_time = fc::milliseconds( _max_transaction_time_ms.load() );
             if( max_trx_time.count() < 0 ) max_trx_time = fc::microseconds::maximum();
             const auto block_deadline = calculate_block_deadline( chain.pending_block_time() );
@@ -700,7 +702,6 @@ class producer_plugin_impl : public std::enable_shared_from_this<producer_plugin
 
             auto prev_billed_cpu_time_us = trx->billed_cpu_time_us;
             auto trace = chain.push_transaction( trx, block_deadline, max_trx_time, prev_billed_cpu_time_us, false, sub_bill );
-            fc_dlog( _trx_failed_trace_log, "Subjective bill for ${a}: ${b} elapsed ${t}us", ("a",first_auth)("b",sub_bill)("t",trace->elapsed));
             if( trace->except ) {
                if( exception_is_exhausted( *trace->except ) ) {
                   _unapplied_transactions.add_incoming( trx, persist_until_expired, return_failure_traces, next );
@@ -715,8 +716,10 @@ class producer_plugin_impl : public std::enable_shared_from_this<producer_plugin
                   }
                   exhausted = block_is_exhausted();
                } else {
-                   if (!disable_subjective_billing)
-                      _subjective_billing.subjective_bill_failure( first_auth, trace->elapsed, fc::time_point::now() );
+                  fc_dlog( _trx_failed_trace_log, "Subjective bill for failed ${a}: ${b} elapsed ${t}us, time ${r}us",
+                           ("a",first_auth)("b",sub_bill)("t",trace->elapsed)("r", fc::time_point::now() - start));
+                  if (!disable_subjective_billing)
+                     _subjective_billing.subjective_bill_failure( first_auth, trace->elapsed, fc::time_point::now() );
 
                   if( _pending_block_mode == pending_block_mode::producing ) {
                      auto failure_code = trace->except->code();
@@ -736,6 +739,8 @@ class producer_plugin_impl : public std::enable_shared_from_this<producer_plugin
                   }
                }
             } else {
+               fc_dlog( _trx_successful_trace_log, "Subjective bill for success ${a}: ${b} elapsed ${t}us, time ${r}us",
+                        ("a",first_auth)("b",sub_bill)("t",trace->elapsed)("r", fc::time_point::now() - start));
                if( persist_until_expired && !_disable_persist_until_expired ) {
                   // if this trx didnt fail/soft-fail and the persist flag is set, store its ID so that we can
                   // ensure its applied to all future speculative blocks as well.
@@ -758,6 +763,7 @@ class producer_plugin_impl : public std::enable_shared_from_this<producer_plugin
             chain_plugin::handle_bad_alloc();
          } CATCH_AND_CALL(send_response);
 
+         _idle_trx_time = fc::time_point::now();
          return !exhausted;
       }
 
@@ -1693,6 +1699,7 @@ producer_plugin_impl::start_block_result producer_plugin_impl::start_block() {
    const fc::time_point now = fc::time_point::now();
    const fc::time_point block_time = calculate_pending_block_time();
    const fc::time_point preprocess_deadline = calculate_block_deadline(block_time);
+   _idle_trx_time = now;
 
    const pending_block_mode previous_pending_mode = _pending_block_mode;
    _pending_block_mode = pending_block_mode::producing;
@@ -2045,7 +2052,6 @@ bool producer_plugin_impl::process_unapplied_trxs( const fc::time_point& deadlin
                || trx->read_only;
 
             auto trace = chain.push_transaction( trx, deadline, max_trx_time, prev_billed_cpu_time_us, false, sub_bill );
-            fc_dlog( _trx_failed_trace_log, "Subjective unapplied bill for ${a}: ${b} prev ${t}us", ("a",first_auth)("b",prev_billed_cpu_time_us)("t",trace->elapsed));
             if( trace->except ) {
                if( exception_is_exhausted( *trace->except ) ) {
                   if( block_is_exhausted() ) {
@@ -2054,7 +2060,8 @@ bool producer_plugin_impl::process_unapplied_trxs( const fc::time_point& deadlin
                      break;
                   }
                } else {
-                  fc_dlog( _trx_failed_trace_log, "Subjective unapplied bill for failed ${a}: ${b} prev ${t}us", ("a",first_auth)("b",prev_billed_cpu_time_us)("t",trace->elapsed));
+                  fc_dlog( _trx_failed_trace_log, "Subjective bill for failed ${a}: ${b} prev ${t}us, time ${r}us",
+                           ("a",first_auth)("b",prev_billed_cpu_time_us)("t",trace->elapsed)("r", fc::time_point::now() - start));
                   auto failure_code = trace->except->code();
                   if( failure_code != tx_duplicate::code_value ) {
                      // this failed our configured maximum transaction time, we don't want to replay it
@@ -2073,7 +2080,8 @@ bool producer_plugin_impl::process_unapplied_trxs( const fc::time_point& deadlin
                   continue;
                }
             } else {
-               fc_dlog( _trx_successful_trace_log, "Subjective unapplied bill for success ${a}: ${b} prev ${t}us", ("a",first_auth)("b",prev_billed_cpu_time_us)("t",trace->elapsed));
+               fc_dlog( _trx_successful_trace_log, "Subjective bill for success ${a}: ${b} prev ${t}us, time ${r}us",
+                        ("a",first_auth)("b",prev_billed_cpu_time_us)("t",trace->elapsed)("r", fc::time_point::now() - start));
                // if db_read_mode SPECULATIVE then trx is in the pending block and not immediately reverted
                if (!disable_subjective_billing)
                   _subjective_billing.subjective_bill( trx->id(), trx->packed_trx()->expiration(), first_auth, trace->elapsed,
@@ -2137,6 +2145,7 @@ void producer_plugin_impl::process_scheduled_and_incoming_trxs( const fc::time_p
 
       num_processed++;
 
+      _idle_trx_time = fc::time_point::now();
       // configurable ratio of incoming txns vs deferred txns
       while (incoming_trx_weight >= 1.0 && pending_incoming_process_limit && itr != end ) {
          if (deadline <= fc::time_point::now()) {
@@ -2172,6 +2181,7 @@ void producer_plugin_impl::process_scheduled_and_incoming_trxs( const fc::time_p
       };
 
       try {
+         auto start = fc::time_point::now();
          fc::microseconds max_trx_time = fc::milliseconds( _max_transaction_time_ms.load() );
          if( max_trx_time.count() < 0 ) max_trx_time = fc::microseconds::maximum();
 
@@ -2183,9 +2193,11 @@ void producer_plugin_impl::process_scheduled_and_incoming_trxs( const fc::time_p
                   break;
                }
             } else {
-               fc_dlog(_trx_failed_trace_log, "[TRX_TRACE] Block ${block_num} for producer ${prod} is REJECTING scheduled tx: ${txid}, auth: ${a} : ${why} ",
+               fc_dlog(_trx_failed_trace_log,
+                       "[TRX_TRACE] Block ${block_num} for producer ${prod} is REJECTING scheduled tx: ${txid}, time: ${r}, auth: ${a} : ${why} ",
                        ("block_num", chain.head_block_num() + 1)("prod", get_pending_block_producer())
-                       ("txid", trx_id)("a", get_first_authorizer(trace))("why", trace->except->what()));
+                       ("txid", trx_id)("r", fc::time_point::now() - start)("a", get_first_authorizer(trace))
+                       ("why", trace->except->what()));
                fc_dlog(_trx_trace_failure_log, "[TRX_TRACE] Block ${block_num} for producer ${prod} is REJECTING scheduled tx: ${entire_trace}",
                        ("block_num", chain.head_block_num() + 1)("prod", get_pending_block_producer())
                        ("entire_trace", chain_plug->get_log_trx_trace(trace)));
@@ -2194,9 +2206,11 @@ void producer_plugin_impl::process_scheduled_and_incoming_trxs( const fc::time_p
                num_failed++;
             }
          } else {
-            fc_dlog(_trx_successful_trace_log, "[TRX_TRACE] Block ${block_num} for producer ${prod} is ACCEPTING scheduled tx: ${txid}, auth: ${a}, cpu: ${cpu}",
+            fc_dlog(_trx_successful_trace_log,
+                    "[TRX_TRACE] Block ${block_num} for producer ${prod} is ACCEPTING scheduled tx: ${txid}, time: ${r}, auth: ${a}, cpu: ${cpu}",
                     ("block_num", chain.head_block_num() + 1)("prod", get_pending_block_producer())
-                    ("txid", trx_id)("a", get_first_authorizer(trace))("cpu", trace->receipt ? trace->receipt->cpu_usage_us : 0));
+                    ("txid", trx_id)("r", fc::time_point::now() - start)("a", get_first_authorizer(trace))
+                    ("cpu", trace->receipt ? trace->receipt->cpu_usage_us : 0));
             fc_dlog(_trx_trace_success_log, "[TRX_TRACE] Block ${block_num} for producer ${prod} is ACCEPTING scheduled tx: ${entire_trace}",
                     ("block_num", chain.head_block_num() + 1)("prod", get_pending_block_producer())
                     ("entire_trace", chain_plug->get_log_trx_trace(trace)));
@@ -2222,6 +2236,7 @@ bool producer_plugin_impl::process_incoming_trxs( const fc::time_point& deadline
 {
    bool exhausted = false;
    if( pending_incoming_process_limit ) {
+      _idle_trx_time = fc::time_point::now();
       size_t processed = 0;
       fc_dlog( _log, "Processing ${n} pending transactions", ("n", pending_incoming_process_limit) );
       auto itr = _unapplied_transactions.incoming_begin();