From 8d09101fcaaac51ce8dae33c0650028e3fabd612 Mon Sep 17 00:00:00 2001
From: Kevin Heifner <heifnerk@objectcomputing.com>
Date: Thu, 20 Jul 2023 17:00:50 -0500
Subject: [PATCH 1/6] GH-1417 Better track trx idle time and block time
 tracking. Also add producer to Block time report.

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

diff --git a/plugins/producer_plugin/producer_plugin.cpp b/plugins/producer_plugin/producer_plugin.cpp
index 71ca488274..4c56d481d9 100644
--- a/plugins/producer_plugin/producer_plugin.cpp
+++ b/plugins/producer_plugin/producer_plugin.cpp
@@ -278,12 +278,11 @@ struct block_time_tracker {
       }
    }
 
-   void report( const fc::time_point& idle_trx_time, uint32_t block_num ) {
+   void report(uint32_t block_num, account_name producer) {
       if( _log.is_enabled( fc::log_level::debug ) ) {
          auto now = fc::time_point::now();
-         add_idle_time( now - idle_trx_time );
-         fc_dlog( _log, "Block #${n} trx idle: ${i}us out of ${t}us, success: ${sn}, ${s}us, fail: ${fn}, ${f}us, transient: ${trans_trx_num}, ${trans_trx_time}us, other: ${o}us",
-                  ("n", block_num)
+         fc_dlog( _log, "Block #${n} ${p} trx idle: ${i}us out of ${t}us, success: ${sn}, ${s}us, fail: ${fn}, ${f}us, transient: ${trans_trx_num}, ${trans_trx_time}us, other: ${o}us",
+                  ("n", block_num)("p", producer)
                   ("i", block_idle_time)("t", now - clear_time)("sn", trx_success_num)("s", trx_success_time)
                   ("fn", trx_fail_num)("f", trx_fail_time)
                   ("trans_trx_num", transient_trx_num)("trans_trx_time", transient_trx_time)
@@ -558,11 +557,18 @@ class producer_plugin_impl : public std::enable_shared_from_this<producer_plugin
       void abort_block() {
          auto& chain = chain_plug->chain();
 
+         std::optional<std::tuple<uint32_t, account_name>> block_info;
          if( chain.is_building_block() ) {
-            _time_tracker.report( _idle_trx_time, chain.pending_block_num() );
+            block_info = std::make_tuple(chain.pending_block_num(), chain.pending_block_producer());
          }
          _unapplied_transactions.add_aborted( chain.abort_block() );
          _subjective_billing.abort_block();
+
+         if (block_info) {
+            auto[block_num, block_producer] = *block_info;
+            _time_tracker.report(block_num, block_producer);
+         }
+         _time_tracker.clear();
          _idle_trx_time = fc::time_point::now();
       }
 
@@ -586,6 +592,8 @@ class producer_plugin_impl : public std::enable_shared_from_this<producer_plugin
          if (now - block->timestamp < fc::minutes(5) || (blk_num % 1000 == 0)) // only log every 1000 during sync
             fc_dlog(_log, "received incoming block ${n} ${id}", ("n", blk_num)("id", id));
 
+         _time_tracker.add_idle_time(now - _idle_trx_time);
+
          EOS_ASSERT( block->timestamp < (now + fc::seconds( 7 )), block_from_the_future,
                      "received a block from the future, ignoring it: ${id}", ("id", id) );
 
@@ -2028,7 +2036,6 @@ producer_plugin_impl::start_block_result producer_plugin_impl::start_block() {
 
       try {
          _account_fails.report_and_clear(hbs->block_num);
-         _time_tracker.clear();
 
          if( !remove_expired_trxs( preprocess_deadline ) )
             return start_block_result::exhausted;
@@ -2624,8 +2631,6 @@ void producer_plugin_impl::schedule_production_loop() {
 
    auto result = start_block();
 
-   _idle_trx_time = fc::time_point::now();
-
    if (result == start_block_result::failed) {
       elog("Failed to start a pending block, will try again later");
       _timer.expires_from_now( boost::posix_time::microseconds( config::block_interval_us  / 10 ));
@@ -2661,6 +2666,8 @@ void producer_plugin_impl::schedule_production_loop() {
    } else {
       fc_dlog(_log, "Speculative Block Created");
    }
+
+   _idle_trx_time = fc::time_point::now();
 }
 
 void producer_plugin_impl::schedule_maybe_produce_block( bool exhausted ) {
@@ -2770,6 +2777,8 @@ static auto maybe_make_debug_time_logger() -> std::optional<decltype(make_debug_
 void producer_plugin_impl::produce_block() {
    //ilog("produce_block ${t}", ("t", fc::time_point::now())); // for testing _produce_time_offset_us
    auto start = fc::time_point::now();
+   _time_tracker.add_idle_time( start - _idle_trx_time );
+
    EOS_ASSERT(in_producing_mode(), producer_exception, "called produce_block while not actually producing");
    chain::controller& chain = chain_plug->chain();
    EOS_ASSERT(chain.is_building_block(), missing_pending_block_state, "pending_block_state does not exist but it should, another plugin may have corrupted it");
@@ -2811,8 +2820,6 @@ void producer_plugin_impl::produce_block() {
 
    block_state_ptr new_bs = chain.head_block_state();
 
-   _time_tracker.report(_idle_trx_time, new_bs->block_num);
-
    br.total_time += fc::time_point::now() - start;
 
    ++_metrics.blocks_produced.value;
@@ -2825,6 +2832,11 @@ void producer_plugin_impl::produce_block() {
         ("count",new_bs->block->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_bs->header.confirmed));
+
+   _time_tracker.report(new_bs->block_num, new_bs->block->producer);
+   _time_tracker.clear();
+
+   _idle_trx_time = fc::time_point::now();
 }
 
 void producer_plugin::received_block(uint32_t block_num) {

From 144f99f57be68bcf39a9d6459437974f681d7495 Mon Sep 17 00:00:00 2001
From: Kevin Heifner <heifnerk@objectcomputing.com>
Date: Mon, 24 Jul 2023 13:36:59 -0500
Subject: [PATCH 2/6] GH-1417 Refactor block_time_tracker to use RAII for
 simplify use.

---
 plugins/producer_plugin/producer_plugin.cpp | 165 ++++++++++++--------
 1 file changed, 100 insertions(+), 65 deletions(-)

diff --git a/plugins/producer_plugin/producer_plugin.cpp b/plugins/producer_plugin/producer_plugin.cpp
index 4c56d481d9..78e3b6a970 100644
--- a/plugins/producer_plugin/producer_plugin.cpp
+++ b/plugins/producer_plugin/producer_plugin.cpp
@@ -253,29 +253,58 @@ class account_failures {
 
 struct block_time_tracker {
 
-   void add_idle_time( const fc::microseconds& idle ) {
-      block_idle_time += idle;
-   }
+   struct trx_time_tracker {
+      enum class trx_status { success, fail, other };
 
-   void add_fail_time( const fc::microseconds& fail_time, bool is_transient ) {
-      if( is_transient ) {
-         // transient time includes both success and fail time
-         transient_trx_time += fail_time;
-         ++transient_trx_num;
-      } else {
-         trx_fail_time += fail_time;
-         ++trx_fail_num;
+      trx_time_tracker(block_time_tracker& btt, bool transient)
+          : _block_time_tracker(btt), _is_transient(transient) {}
+
+      trx_time_tracker(trx_time_tracker&&) = default;
+
+      trx_time_tracker() = delete;
+      trx_time_tracker(const trx_time_tracker&) = delete;
+      trx_time_tracker& operator=(const trx_time_tracker&) = delete;
+      trx_time_tracker& operator=(trx_time_tracker&&) = delete;
+
+      void trx_success() { _trx_status = trx_status::success; }
+
+      // Neither success for fail, will be reported as other
+      void cancel() { _trx_status = trx_status::other; }
+
+      // updates block_time_tracker
+      ~trx_time_tracker() {
+         switch (_trx_status) {
+         case trx_status::success:
+            _block_time_tracker.add_success_time(_is_transient);
+            break;
+         case trx_status::fail:
+            _block_time_tracker.add_fail_time(_is_transient);
+            break;
+         case trx_status::other:
+            break; // just reset timer which happens below
+         }
+         _block_time_tracker.start_idle_time();
       }
+
+    private:
+      block_time_tracker& _block_time_tracker;
+      trx_status _trx_status = trx_status::fail;
+      bool _is_transient;
+   };
+
+   trx_time_tracker start_trx(bool is_transient, fc::time_point now = fc::time_point::now()) {
+      last_trx_time_point = now;
+      return {*this, is_transient};
    }
 
-   void add_success_time( const fc::microseconds& time, bool is_transient ) {
-      if( is_transient ) {
-         transient_trx_time += time;
-         ++transient_trx_num;
-      } else {
-         trx_success_time += time;
-         ++trx_success_num;
-      }
+   void start_idle_time(fc::time_point now = fc::time_point::now()) {
+      last_trx_time_point = now;
+   }
+
+   fc::microseconds add_idle_time(fc::time_point now = fc::time_point::now()) {
+      auto dur = now - last_trx_time_point;
+      block_idle_time += dur;
+      return dur;
    }
 
    void report(uint32_t block_num, account_name producer) {
@@ -283,19 +312,44 @@ struct block_time_tracker {
          auto now = fc::time_point::now();
          fc_dlog( _log, "Block #${n} ${p} trx idle: ${i}us out of ${t}us, success: ${sn}, ${s}us, fail: ${fn}, ${f}us, transient: ${trans_trx_num}, ${trans_trx_time}us, other: ${o}us",
                   ("n", block_num)("p", producer)
-                  ("i", block_idle_time)("t", now - clear_time)("sn", trx_success_num)("s", trx_success_time)
+                  ("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)
                   ("trans_trx_num", transient_trx_num)("trans_trx_time", transient_trx_time)
-                  ("o", (now - clear_time) - block_idle_time - trx_success_time - trx_fail_time - transient_trx_time) );
+                  ("o", (now - clear_time_point) - block_idle_time - trx_success_time - trx_fail_time - transient_trx_time) );
       }
    }
 
    void clear() {
       block_idle_time = trx_fail_time = trx_success_time = transient_trx_time = fc::microseconds{};
       trx_fail_num = trx_success_num = transient_trx_num = 0;
-      clear_time = fc::time_point::now();
+      clear_time_point = last_trx_time_point = fc::time_point::now();
+   }
+
+ private:
+   void add_success_time(bool is_transient) {
+      auto now = fc::time_point::now();
+      if( is_transient ) {
+         transient_trx_time += now - last_trx_time_point;
+         ++transient_trx_num;
+      } else {
+         trx_success_time += now - last_trx_time_point;
+         ++trx_success_num;
+      }
    }
 
+   void add_fail_time(bool is_transient) {
+      auto now = fc::time_point::now();
+      if( is_transient ) {
+         // transient time includes both success and fail time
+         transient_trx_time += now - last_trx_time_point;
+         ++transient_trx_num;
+      } else {
+         trx_fail_time += now - last_trx_time_point;
+         ++trx_fail_num;
+      }
+   }
+
+ private:
    fc::microseconds block_idle_time;
    uint32_t trx_success_num = 0;
    uint32_t trx_fail_num = 0;
@@ -303,7 +357,8 @@ struct block_time_tracker {
    fc::microseconds trx_success_time;
    fc::microseconds trx_fail_time;
    fc::microseconds transient_trx_time;
-   fc::time_point clear_time{fc::time_point::now()};
+   fc::time_point last_trx_time_point{fc::time_point::now()};
+   fc::time_point clear_time_point{fc::time_point::now()};
 };
 
 } // anonymous namespace
@@ -379,7 +434,6 @@ class producer_plugin_impl : public std::enable_shared_from_this<producer_plugin
       bool                                                      _disable_subjective_p2p_billing = true;
       bool                                                      _disable_subjective_api_billing = true;
       fc::time_point                                            _irreversible_block_time;
-      fc::time_point                                            _idle_trx_time{fc::time_point::now()};
 
       std::vector<chain::digest_type>                           _protocol_features_to_activate;
       bool                                                      _protocol_features_signaled = false; // to mark whether it has been signaled in start_block
@@ -569,7 +623,6 @@ class producer_plugin_impl : public std::enable_shared_from_this<producer_plugin
             _time_tracker.report(block_num, block_producer);
          }
          _time_tracker.clear();
-         _idle_trx_time = fc::time_point::now();
       }
 
       bool on_incoming_block(const signed_block_ptr& block, const std::optional<block_id_type>& block_id, const block_state_ptr& bsp) {
@@ -585,14 +638,14 @@ class producer_plugin_impl : public std::enable_shared_from_this<producer_plugin
             schedule_production_loop();
          });
 
+         auto now = fc::time_point::now();
          const auto& id = block_id ? *block_id : block->calculate_id();
          auto blk_num = block->block_num();
 
-         auto now = fc::time_point::now();
          if (now - block->timestamp < fc::minutes(5) || (blk_num % 1000 == 0)) // only log every 1000 during sync
             fc_dlog(_log, "received incoming block ${n} ${id}", ("n", blk_num)("id", id));
 
-         _time_tracker.add_idle_time(now - _idle_trx_time);
+         _time_tracker.add_idle_time(now);
 
          EOS_ASSERT( block->timestamp < (now + fc::seconds( 7 )), block_from_the_future,
                      "received a block from the future, ignoring it: ${id}", ("id", id) );
@@ -725,28 +778,23 @@ class producer_plugin_impl : public std::enable_shared_from_this<producer_plugin
                future.wait();
                app().executor().post( priority::low, exec_queue::read_write, [self, future{std::move(future)}, api_trx, is_transient, next{std::move( next )}, trx{std::move(trx)}, return_failure_traces]() mutable {
                   auto start = fc::time_point::now();
-                  auto idle_time = start - self->_idle_trx_time;
-                  self->_time_tracker.add_idle_time( idle_time );
+                  auto idle_time = self->_time_tracker.add_idle_time(start);
+                  auto trx_tracker = self->_time_tracker.start_trx(is_transient, start);
                   fc_tlog( _log, "Time since last trx: ${t}us", ("t", idle_time) );
 
                   auto exception_handler = [self, is_transient, &next, trx{std::move(trx)}, &start](fc::exception_ptr ex) {
-                     self->_time_tracker.add_idle_time( start - self->_idle_trx_time );
                      self->log_trx_results( trx, nullptr, ex, 0, start, is_transient );
                      next( std::move(ex) );
-                     self->_idle_trx_time = fc::time_point::now();
-                     auto dur = self->_idle_trx_time - start;
-                     self->_time_tracker.add_fail_time(dur, is_transient);
                   };
                   try {
                      auto result = future.get();
-                     if( !self->process_incoming_transaction_async( result, api_trx, return_failure_traces, next) ) {
+                     if( !self->process_incoming_transaction_async( result, api_trx, return_failure_traces, trx_tracker, next) ) {
                         if( self->in_producing_mode() ) {
                            self->schedule_maybe_produce_block( true );
                         } else {
                            self->restart_speculative_block();
                         }
                      }
-                     self->_idle_trx_time = fc::time_point::now();
                   } CATCH_AND_CALL(exception_handler);
                } );
             }
@@ -756,6 +804,7 @@ class producer_plugin_impl : public std::enable_shared_from_this<producer_plugin
       bool process_incoming_transaction_async(const transaction_metadata_ptr& trx,
                                               bool api_trx,
                                               bool return_failure_trace,
+                                              block_time_tracker::trx_time_tracker& trx_tracker,
                                               const next_function<transaction_trace_ptr>& next) {
          bool exhausted = false;
          chain::controller& chain = chain_plug->chain();
@@ -783,12 +832,16 @@ class producer_plugin_impl : public std::enable_shared_from_this<producer_plugin
 
             if( !chain.is_building_block()) {
                _unapplied_transactions.add_incoming( trx, api_trx, return_failure_trace, next );
+               trx_tracker.cancel();
                return true;
             }
 
             const auto block_deadline = calculate_block_deadline( chain.pending_block_time() );
             push_result pr = push_transaction( block_deadline, trx, api_trx, return_failure_trace, next );
 
+            if (!pr.failed) {
+               trx_tracker.trx_success();
+            }
             if( pr.trx_exhausted ) {
                _unapplied_transactions.add_incoming( trx, api_trx, return_failure_trace, next );
             }
@@ -2290,7 +2343,6 @@ producer_plugin_impl::push_transaction( const fc::time_point& block_deadline,
          log_trx_results( trx, except_ptr );
          next( except_ptr );
       }
-      _time_tracker.add_fail_time(fc::time_point::now() - start, trx->is_transient());
       return push_result{.failed = true};
    }
 
@@ -2329,14 +2381,6 @@ producer_plugin_impl::handle_push_result( const transaction_metadata_ptr& trx,
    auto end = fc::time_point::now();
    push_result pr;
    if( trace->except ) {
-      // Transient trxs are dry-run or read-only.
-      // Dry-run trxs only run in write window. Read-only trxs can run in
-      // both write and read windows; time spent in read window is counted
-      // by read window summary.
-      if ( chain.is_write_window() ) {
-         auto dur = end - start;
-         _time_tracker.add_fail_time(dur, trx->is_transient());
-      }
       if( exception_is_exhausted( *trace->except ) ) {
          if( in_producing_mode() ) {
             fc_dlog(trx->is_transient() ? _transient_trx_failed_trace_log : _trx_failed_trace_log, "[TRX_TRACE] Block ${block_num} for producer ${prod} COULD NOT FIT, tx: ${txid} RETRYING ",
@@ -2376,14 +2420,6 @@ producer_plugin_impl::handle_push_result( const transaction_metadata_ptr& trx,
    } else {
       fc_tlog( _log, "Subjective bill for success ${a}: ${b} elapsed ${t}us, time ${r}us",
                ("a",first_auth)("b",sub_bill)("t",trace->elapsed)("r", end - start));
-      // Transient trxs are dry-run or read-only.
-      // Dry-run trxs only run in write window. Read-only trxs can run in
-      // both write and read windows; time spent in read window is counted
-      // by read window summary.
-      if ( chain.is_write_window() ) {
-         auto dur = end - start;
-         _time_tracker.add_success_time(dur, trx->is_transient());
-      }
       log_trx_results( trx, trace, start );
       // if producing then trx is in objective cpu account billing
       if (!disable_subjective_enforcement && _pending_block_mode != pending_block_mode::producing) {
@@ -2522,13 +2558,13 @@ void producer_plugin_impl::process_scheduled_and_incoming_trxs( const fc::time_p
 
       try {
          auto start = fc::time_point::now();
+         auto trx_tracker = _time_tracker.start_trx(false, start); // delayed transaction cannot be transient
          fc::microseconds max_trx_time = fc::milliseconds( _max_transaction_time_ms.load() );
          if( max_trx_time.count() < 0 ) max_trx_time = fc::microseconds::maximum();
 
          auto trace = chain.push_scheduled_transaction(trx_id, deadline, max_trx_time, 0, false);
          auto end = fc::time_point::now();
          if (trace->except) {
-            _time_tracker.add_fail_time(end - start, false); // delayed transaction cannot be transient
             if (exception_is_exhausted(*trace->except)) {
                if( block_is_exhausted() ) {
                   exhausted = true;
@@ -2548,7 +2584,7 @@ void producer_plugin_impl::process_scheduled_and_incoming_trxs( const fc::time_p
                num_failed++;
             }
          } else {
-            _time_tracker.add_success_time(end - start, false); // delayed transaction cannot be transient
+            trx_tracker.trx_success();
             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())
@@ -2667,7 +2703,7 @@ void producer_plugin_impl::schedule_production_loop() {
       fc_dlog(_log, "Speculative Block Created");
    }
 
-   _idle_trx_time = fc::time_point::now();
+   _time_tracker.start_idle_time();
 }
 
 void producer_plugin_impl::schedule_maybe_produce_block( bool exhausted ) {
@@ -2777,7 +2813,7 @@ static auto maybe_make_debug_time_logger() -> std::optional<decltype(make_debug_
 void producer_plugin_impl::produce_block() {
    //ilog("produce_block ${t}", ("t", fc::time_point::now())); // for testing _produce_time_offset_us
    auto start = fc::time_point::now();
-   _time_tracker.add_idle_time( start - _idle_trx_time );
+   _time_tracker.add_idle_time(start);
 
    EOS_ASSERT(in_producing_mode(), producer_exception, "called produce_block while not actually producing");
    chain::controller& chain = chain_plug->chain();
@@ -2835,8 +2871,6 @@ void producer_plugin_impl::produce_block() {
 
    _time_tracker.report(new_bs->block_num, new_bs->block->producer);
    _time_tracker.clear();
-
-   _idle_trx_time = fc::time_point::now();
 }
 
 void producer_plugin::received_block(uint32_t block_num) {
@@ -2883,9 +2917,10 @@ void producer_plugin_impl::start_write_window() {
    app().executor().set_to_write_window();
    chain.set_to_write_window();
    chain.unset_db_read_only_mode();
-   _idle_trx_time = _ro_window_deadline = fc::time_point::now();
+   auto now = fc::time_point::now();
+   _time_tracker.start_idle_time(now);
 
-   _ro_window_deadline += _ro_write_window_time_us; // not allowed on block producers, so no need to limit to block deadline
+   _ro_window_deadline = now + _ro_write_window_time_us; // not allowed on block producers, so no need to limit to block deadline
    auto expire_time = boost::posix_time::microseconds(_ro_write_window_time_us.count());
    _ro_timer.expires_from_now( expire_time );
    _ro_timer.async_wait( app().executor().wrap(  // stay on app thread
@@ -2905,7 +2940,7 @@ void producer_plugin_impl::switch_to_read_window() {
    EOS_ASSERT(chain.is_write_window(),  producer_exception, "expected to be in write window");
    EOS_ASSERT( _ro_num_active_exec_tasks.load() == 0 && _ro_exec_tasks_fut.empty(), producer_exception, "_ro_exec_tasks_fut expected to be empty" );
 
-   _time_tracker.add_idle_time( fc::time_point::now() - _idle_trx_time );
+   _time_tracker.add_idle_time();
 
    // we are in write window, so no read-only trx threads are processing transactions.
    if ( app().executor().read_only_queue().empty() ) { // no read-only tasks to process. stay in write window
@@ -3024,10 +3059,10 @@ bool producer_plugin_impl::push_read_only_transaction(transaction_metadata_ptr t
             chain.unset_db_read_only_mode();
       });
 
+      std::optional<block_time_tracker::trx_time_tracker> trx_tracker;
       if ( chain.is_write_window() ) {
          chain.set_db_read_only_mode();
-         auto idle_time = fc::time_point::now() - _idle_trx_time;
-         _time_tracker.add_idle_time( idle_time );
+         trx_tracker.emplace(_time_tracker.start_trx(true, start));
       }
 
       // use read-window/write-window deadline if there are read/write windows, otherwise use block_deadline if only the app thead
@@ -3044,8 +3079,8 @@ bool producer_plugin_impl::push_read_only_transaction(transaction_metadata_ptr t
          _ro_exhausted_trx_queue.push_front( {std::move(trx), std::move(next)} );
       }
 
-      if ( chain.is_write_window() ) {
-         _idle_trx_time = fc::time_point::now();
+      if ( chain.is_write_window() && !pr.failed ) {
+         trx_tracker->trx_success();
       }
    } catch ( const guard_exception& e ) {
       chain_plugin::handle_guard_exception(e);

From 56124be461dbfa9a63c046de2b09fc62dab220ee Mon Sep 17 00:00:00 2001
From: Kevin Heifner <heifnerk@objectcomputing.com>
Date: Mon, 24 Jul 2023 14:14:27 -0500
Subject: [PATCH 3/6] GH-1417 Guard against double accounting

---
 plugins/producer_plugin/producer_plugin.cpp | 7 +++++--
 1 file changed, 5 insertions(+), 2 deletions(-)

diff --git a/plugins/producer_plugin/producer_plugin.cpp b/plugins/producer_plugin/producer_plugin.cpp
index 78e3b6a970..5f51858ec3 100644
--- a/plugins/producer_plugin/producer_plugin.cpp
+++ b/plugins/producer_plugin/producer_plugin.cpp
@@ -281,9 +281,9 @@ struct block_time_tracker {
             _block_time_tracker.add_fail_time(_is_transient);
             break;
          case trx_status::other:
-            break; // just reset timer which happens below
+            _block_time_tracker.start_idle_time(); // just reset timer, will be in other category
+            break;
          }
-         _block_time_tracker.start_idle_time();
       }
 
     private:
@@ -304,6 +304,7 @@ struct block_time_tracker {
    fc::microseconds add_idle_time(fc::time_point now = fc::time_point::now()) {
       auto dur = now - last_trx_time_point;
       block_idle_time += dur;
+      last_trx_time_point = now; // guard against calling add_idle_time() twice in a row.
       return dur;
    }
 
@@ -335,6 +336,7 @@ struct block_time_tracker {
          trx_success_time += now - last_trx_time_point;
          ++trx_success_num;
       }
+      last_trx_time_point = now;
    }
 
    void add_fail_time(bool is_transient) {
@@ -347,6 +349,7 @@ struct block_time_tracker {
          trx_fail_time += now - last_trx_time_point;
          ++trx_fail_num;
       }
+      last_trx_time_point = now;
    }
 
  private:

From c9f0ff7cfa05aa49f809b27485ad7e44359a2761 Mon Sep 17 00:00:00 2001
From: Kevin Heifner <heifnerk@objectcomputing.com>
Date: Mon, 24 Jul 2023 15:15:29 -0500
Subject: [PATCH 4/6] GH-1417 Add back in counting of trx in start_block missed
 in the refactor

---
 plugins/producer_plugin/producer_plugin.cpp | 23 ++++++++++++++-------
 1 file changed, 15 insertions(+), 8 deletions(-)

diff --git a/plugins/producer_plugin/producer_plugin.cpp b/plugins/producer_plugin/producer_plugin.cpp
index 5f51858ec3..110fd90667 100644
--- a/plugins/producer_plugin/producer_plugin.cpp
+++ b/plugins/producer_plugin/producer_plugin.cpp
@@ -395,6 +395,7 @@ class producer_plugin_impl : public std::enable_shared_from_this<producer_plugin
       push_result push_transaction( const fc::time_point& block_deadline,
                                     const transaction_metadata_ptr& trx,
                                     bool api_trx, bool return_failure_trace,
+                                    block_time_tracker::trx_time_tracker& trx_tracker,
                                     const next_function<transaction_trace_ptr>& next );
       push_result handle_push_result( const transaction_metadata_ptr& trx,
                                       const next_function<transaction_trace_ptr>& next,
@@ -840,11 +841,8 @@ class producer_plugin_impl : public std::enable_shared_from_this<producer_plugin
             }
 
             const auto block_deadline = calculate_block_deadline( chain.pending_block_time() );
-            push_result pr = push_transaction( block_deadline, trx, api_trx, return_failure_trace, next );
+            push_result pr = push_transaction( block_deadline, trx, api_trx, return_failure_trace, trx_tracker, next );
 
-            if (!pr.failed) {
-               trx_tracker.trx_success();
-            }
             if( pr.trx_exhausted ) {
                _unapplied_transactions.add_incoming( trx, api_trx, return_failure_trace, next );
             }
@@ -2326,6 +2324,7 @@ producer_plugin_impl::push_transaction( const fc::time_point& block_deadline,
                                         const transaction_metadata_ptr& trx,
                                         bool api_trx,
                                         bool return_failure_trace,
+                                        block_time_tracker::trx_time_tracker& trx_tracker,
                                         const next_function<transaction_trace_ptr>& next )
 {
    auto start = fc::time_point::now();
@@ -2367,7 +2366,12 @@ producer_plugin_impl::push_transaction( const fc::time_point& block_deadline,
 
    auto trace = chain.push_transaction( trx, block_deadline, max_trx_time, prev_billed_cpu_time_us, false, sub_bill );
 
-   return handle_push_result(trx, next, start, chain, trace, return_failure_trace, disable_subjective_enforcement, first_auth, sub_bill, prev_billed_cpu_time_us);
+   auto pr = handle_push_result(trx, next, start, chain, trace, return_failure_trace, disable_subjective_enforcement, first_auth, sub_bill, prev_billed_cpu_time_us);
+
+   if (!pr.failed) {
+      trx_tracker.trx_success();
+   }
+   return pr;
 }
 
 producer_plugin_impl::push_result
@@ -2452,7 +2456,8 @@ bool producer_plugin_impl::process_unapplied_trxs( const fc::time_point& deadlin
 
          ++num_processed;
          try {
-            push_result pr = push_transaction( deadline, itr->trx_meta, false, itr->return_failure_trace, itr->next );
+            auto trx_tracker = _time_tracker.start_trx(itr->trx_meta->is_transient());
+            push_result pr = push_transaction( deadline, itr->trx_meta, false, itr->return_failure_trace, trx_tracker, itr->next );
 
             exhausted = pr.block_exhausted;
             if( exhausted ) {
@@ -2534,7 +2539,8 @@ void producer_plugin_impl::process_scheduled_and_incoming_trxs( const fc::time_p
          auto trx_meta = itr->trx_meta;
          bool api_trx = itr->trx_type == trx_enum_type::incoming_api;
 
-         push_result pr = push_transaction( deadline, trx_meta, api_trx, itr->return_failure_trace, itr->next );
+         auto trx_tracker = _time_tracker.start_trx(trx_meta->is_transient());
+         push_result pr = push_transaction( deadline, trx_meta, api_trx, itr->return_failure_trace, trx_tracker, itr->next );
 
          exhausted = pr.block_exhausted;
          if( pr.trx_exhausted ) {
@@ -2631,7 +2637,8 @@ bool producer_plugin_impl::process_incoming_trxs( const fc::time_point& deadline
          auto trx_meta = itr->trx_meta;
          bool api_trx = itr->trx_type == trx_enum_type::incoming_api;
 
-         push_result pr = push_transaction( deadline, trx_meta, api_trx, itr->return_failure_trace, itr->next );
+         auto trx_tracker = _time_tracker.start_trx(trx_meta->is_transient());
+         push_result pr = push_transaction( deadline, trx_meta, api_trx, itr->return_failure_trace, trx_tracker, itr->next );
 
          exhausted = pr.block_exhausted;
          if( pr.trx_exhausted ) {

From 1cc213bc9fc84622f676900fd16a8ad71432e8f6 Mon Sep 17 00:00:00 2001
From: Kevin Heifner <heifnerk@objectcomputing.com>
Date: Mon, 24 Jul 2023 17:45:49 -0500
Subject: [PATCH 5/6] GH-1417 Explicitly track other time. Add pause/unpause
 for when in read window.

---
 plugins/producer_plugin/producer_plugin.cpp | 90 ++++++++++++++-------
 1 file changed, 61 insertions(+), 29 deletions(-)

diff --git a/plugins/producer_plugin/producer_plugin.cpp b/plugins/producer_plugin/producer_plugin.cpp
index 110fd90667..18d9721dcb 100644
--- a/plugins/producer_plugin/producer_plugin.cpp
+++ b/plugins/producer_plugin/producer_plugin.cpp
@@ -254,7 +254,7 @@ class account_failures {
 struct block_time_tracker {
 
    struct trx_time_tracker {
-      enum class trx_status { success, fail, other };
+      enum class time_status { success, fail, other };
 
       trx_time_tracker(block_time_tracker& btt, bool transient)
           : _block_time_tracker(btt), _is_transient(transient) {}
@@ -266,90 +266,117 @@ struct block_time_tracker {
       trx_time_tracker& operator=(const trx_time_tracker&) = delete;
       trx_time_tracker& operator=(trx_time_tracker&&) = delete;
 
-      void trx_success() { _trx_status = trx_status::success; }
+      void trx_success() { _time_status = time_status::success; }
 
       // Neither success for fail, will be reported as other
-      void cancel() { _trx_status = trx_status::other; }
+      void cancel() { _time_status = time_status::other; }
 
       // updates block_time_tracker
       ~trx_time_tracker() {
-         switch (_trx_status) {
-         case trx_status::success:
+         switch (_time_status) {
+         case time_status::success:
             _block_time_tracker.add_success_time(_is_transient);
             break;
-         case trx_status::fail:
+         case time_status::fail:
             _block_time_tracker.add_fail_time(_is_transient);
             break;
-         case trx_status::other:
-            _block_time_tracker.start_idle_time(); // just reset timer, will be in other category
+         case time_status::other:
+            _block_time_tracker.add_other_time();
             break;
          }
       }
 
     private:
       block_time_tracker& _block_time_tracker;
-      trx_status _trx_status = trx_status::fail;
+      time_status _time_status = time_status::fail;
       bool _is_transient;
    };
 
    trx_time_tracker start_trx(bool is_transient, fc::time_point now = fc::time_point::now()) {
-      last_trx_time_point = now;
+      assert(!paused);
+      add_other_time(now);
+      last_time_point = now;
       return {*this, is_transient};
    }
 
-   void start_idle_time(fc::time_point now = fc::time_point::now()) {
-      last_trx_time_point = now;
+   void add_other_time(fc::time_point now = fc::time_point::now()) {
+      assert(!paused);
+      other_time += now - last_time_point;
+      last_time_point = now;
    }
 
    fc::microseconds add_idle_time(fc::time_point now = fc::time_point::now()) {
-      auto dur = now - last_trx_time_point;
+      assert(!paused);
+      auto dur = now - last_time_point;
       block_idle_time += dur;
-      last_trx_time_point = now; // guard against calling add_idle_time() twice in a row.
+      last_time_point = now; // guard against calling add_idle_time() twice in a row.
       return dur;
    }
 
+   // assumes idle time before pause
+   void pause(fc::time_point now = fc::time_point::now()) {
+      assert(!paused);
+      add_idle_time(now);
+      paused = true;
+   }
+
+   // assumes last call was to pause
+   void unpause(fc::time_point now = fc::time_point::now()) {
+      assert(paused);
+      paused = false;
+      auto pause_time = now - last_time_point;
+      clear_time_point += pause_time;
+      last_time_point = now;
+   }
+
    void report(uint32_t block_num, account_name producer) {
+      using namespace std::string_literals;
+      assert(!paused);
       if( _log.is_enabled( fc::log_level::debug ) ) {
          auto now = fc::time_point::now();
-         fc_dlog( _log, "Block #${n} ${p} trx idle: ${i}us out of ${t}us, success: ${sn}, ${s}us, fail: ${fn}, ${f}us, transient: ${trans_trx_num}, ${trans_trx_time}us, other: ${o}us",
+         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)
-                  ("trans_trx_num", transient_trx_num)("trans_trx_time", transient_trx_time)
-                  ("o", (now - clear_time_point) - block_idle_time - trx_success_time - trx_fail_time - transient_trx_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() {
-      block_idle_time = trx_fail_time = trx_success_time = transient_trx_time = fc::microseconds{};
+      assert(!paused);
+      block_idle_time = trx_fail_time = trx_success_time = transient_trx_time = other_time = fc::microseconds{};
       trx_fail_num = trx_success_num = transient_trx_num = 0;
-      clear_time_point = last_trx_time_point = fc::time_point::now();
+      clear_time_point = last_time_point = fc::time_point::now();
    }
 
  private:
    void add_success_time(bool is_transient) {
+      assert(!paused);
       auto now = fc::time_point::now();
       if( is_transient ) {
-         transient_trx_time += now - last_trx_time_point;
+         transient_trx_time += now - last_time_point;
          ++transient_trx_num;
       } else {
-         trx_success_time += now - last_trx_time_point;
+         trx_success_time += now - last_time_point;
          ++trx_success_num;
       }
-      last_trx_time_point = now;
+      last_time_point = now;
    }
 
    void add_fail_time(bool is_transient) {
+      assert(!paused);
       auto now = fc::time_point::now();
       if( is_transient ) {
          // transient time includes both success and fail time
-         transient_trx_time += now - last_trx_time_point;
+         transient_trx_time += now - last_time_point;
          ++transient_trx_num;
       } else {
-         trx_fail_time += now - last_trx_time_point;
+         trx_fail_time += now - last_time_point;
          ++trx_fail_num;
       }
-      last_trx_time_point = now;
+      last_time_point = now;
    }
 
  private:
@@ -360,8 +387,10 @@ struct block_time_tracker {
    fc::microseconds trx_success_time;
    fc::microseconds trx_fail_time;
    fc::microseconds transient_trx_time;
-   fc::time_point last_trx_time_point{fc::time_point::now()};
+   fc::microseconds other_time;
+   fc::time_point last_time_point{fc::time_point::now()};
    fc::time_point clear_time_point{fc::time_point::now()};
+   bool paused = false;
 };
 
 } // anonymous namespace
@@ -621,6 +650,7 @@ class producer_plugin_impl : public std::enable_shared_from_this<producer_plugin
          }
          _unapplied_transactions.add_aborted( chain.abort_block() );
          _subjective_billing.abort_block();
+         _time_tracker.add_other_time();
 
          if (block_info) {
             auto[block_num, block_producer] = *block_info;
@@ -1344,6 +1374,7 @@ void producer_plugin::plugin_startup()
             chain.init_thread_local_data();
          });
 
+      my->_time_tracker.pause(); // start_write_window assumes time_tracker is paused
       my->start_write_window();
    }
 
@@ -2713,7 +2744,7 @@ void producer_plugin_impl::schedule_production_loop() {
       fc_dlog(_log, "Speculative Block Created");
    }
 
-   _time_tracker.start_idle_time();
+   _time_tracker.add_other_time();
 }
 
 void producer_plugin_impl::schedule_maybe_produce_block( bool exhausted ) {
@@ -2879,6 +2910,7 @@ void producer_plugin_impl::produce_block() {
         ("net", br.total_net_usage)("cpu", br.total_cpu_usage_us)("et", br.total_elapsed_time)("tt", br.total_time)
         ("confs", new_bs->header.confirmed));
 
+   _time_tracker.add_other_time();
    _time_tracker.report(new_bs->block_num, new_bs->block->producer);
    _time_tracker.clear();
 }
@@ -2928,7 +2960,7 @@ void producer_plugin_impl::start_write_window() {
    chain.set_to_write_window();
    chain.unset_db_read_only_mode();
    auto now = fc::time_point::now();
-   _time_tracker.start_idle_time(now);
+   _time_tracker.unpause(now);
 
    _ro_window_deadline = now + _ro_write_window_time_us; // not allowed on block producers, so no need to limit to block deadline
    auto expire_time = boost::posix_time::microseconds(_ro_write_window_time_us.count());
@@ -2950,7 +2982,7 @@ void producer_plugin_impl::switch_to_read_window() {
    EOS_ASSERT(chain.is_write_window(),  producer_exception, "expected to be in write window");
    EOS_ASSERT( _ro_num_active_exec_tasks.load() == 0 && _ro_exec_tasks_fut.empty(), producer_exception, "_ro_exec_tasks_fut expected to be empty" );
 
-   _time_tracker.add_idle_time();
+   _time_tracker.pause();
 
    // we are in write window, so no read-only trx threads are processing transactions.
    if ( app().executor().read_only_queue().empty() ) { // no read-only tasks to process. stay in write window

From c669aea5d66b7eb43f966b02945ef687d919b6d5 Mon Sep 17 00:00:00 2001
From: Kevin Heifner <heifnerk@objectcomputing.com>
Date: Tue, 25 Jul 2023 09:11:08 -0500
Subject: [PATCH 6/6] GH-1417 Fix spelling in comment

---
 plugins/producer_plugin/producer_plugin.cpp | 2 +-
 1 file changed, 1 insertion(+), 1 deletion(-)

diff --git a/plugins/producer_plugin/producer_plugin.cpp b/plugins/producer_plugin/producer_plugin.cpp
index 18d9721dcb..1f0a12667c 100644
--- a/plugins/producer_plugin/producer_plugin.cpp
+++ b/plugins/producer_plugin/producer_plugin.cpp
@@ -268,7 +268,7 @@ struct block_time_tracker {
 
       void trx_success() { _time_status = time_status::success; }
 
-      // Neither success for fail, will be reported as other
+      // Neither success nor fail, will be reported as other
       void cancel() { _time_status = time_status::other; }
 
       // updates block_time_tracker