[PH] Added tps_performance_monitor

tests/trx_generator/CMakeLists.txt

@@ -5,7 +5,7 @@ target_include_directories(trx_generator PUBLIC ${CMAKE_CURRENT_BINARY_DIR} ${CM
 target_link_libraries( trx_generator
                        PRIVATE eosio_chain fc chain_plugin eosio_testing_contracts ${CMAKE_DL_LIBS} ${PLATFORM_SPECIFIC_LIBS} )
 
-add_executable(trx_generator_tests trx_generator_tests.cpp)
+add_executable(trx_generator_tests trx_generator_tests.cpp trx_provider.cpp)
 target_link_libraries( trx_generator_tests
         PRIVATE eosio_chain fc chain_plugin eosio_testing_contracts ${CMAKE_DL_LIBS} ${PLATFORM_SPECIFIC_LIBS} )
 target_include_directories(trx_generator_tests PUBLIC ${CMAKE_CURRENT_BINARY_DIR} ${CMAKE_CURRENT_SOURCE_DIR})

tests/trx_generator/trx_generator_tests.cpp

@@ -223,5 +223,102 @@ BOOST_AUTO_TEST_CASE(tps_med_run_med_tps_30us_delay)
            ("rt", runtime_us.count())("mx", maximum_runtime_us ) );
       BOOST_REQUIRE_LT(monitor->_calls.back().time_to_next_trx_us, 0);
    }
+
+}
+
+BOOST_AUTO_TEST_CASE(tps_performance_monitor_during_spin_up)
+{
+   tps_test_stats stats;
+   tps_performance_monitor monitor{std::chrono::microseconds(5s).count()};
+   stats.total_trxs = 1000;
+   stats.start_time = fc::time_point{fc::microseconds{0}};
+   stats.expected_sent = 100;
+   stats.trxs_sent = 90;
+
+   // behind, but still within spin up window
+   stats.last_run =  fc::time_point{fc::microseconds{100000}};
+   BOOST_REQUIRE(monitor.monitor_test(stats));
+
+   // violation, but still within spin up window
+   stats.last_run =  fc::time_point{fc::microseconds{1100000}};
+   BOOST_REQUIRE(monitor.monitor_test(stats));
+}
+
+BOOST_AUTO_TEST_CASE(tps_performance_monitor_outside_spin_up)
+{
+   tps_test_stats stats;
+   tps_performance_monitor monitor{std::chrono::microseconds(5s).count()};
+   stats.total_trxs = 1000;
+   stats.start_time = fc::time_point{fc::microseconds{0}};
+   stats.expected_sent = 100;
+   stats.trxs_sent = 90;
+
+   // behind, out of spin up window
+   stats.last_run =  fc::time_point{fc::microseconds{5500000}};
+   BOOST_REQUIRE(monitor.monitor_test(stats));
+
+   // violation, out of spin up window
+   stats.last_run =  fc::time_point{fc::microseconds{6600000}};
+   BOOST_REQUIRE(!monitor.monitor_test(stats));
+}
+
+BOOST_AUTO_TEST_CASE(tps_performance_monitor_outside_spin_up_within_limit)
+{
+   tps_test_stats stats;
+   tps_performance_monitor monitor{std::chrono::microseconds(5s).count()};
+   stats.total_trxs = 1000;
+   stats.start_time = fc::time_point{fc::microseconds{0}};
+   stats.expected_sent = 100;
+   stats.trxs_sent = 90;
+
+   // outside of limit,  out of spin up window
+   stats.last_run =  fc::time_point{fc::microseconds{5500000}};
+   BOOST_REQUIRE(monitor.monitor_test(stats));
+
+   // outside of limit, less than max violation duration
+   stats.last_run =  fc::time_point{fc::microseconds{6000000}};
+   BOOST_REQUIRE(monitor.monitor_test(stats));
+
+   stats.trxs_sent = 98;
+   // behind, but within limit, out of spin up window
+   stats.last_run =  fc::time_point{fc::microseconds{6600000}};
+   BOOST_REQUIRE(monitor.monitor_test(stats));
+
+   stats.expected_sent = 150;
+   // outside of limit again, out of spin up window
+   stats.last_run =  fc::time_point{fc::microseconds{7000000}};
+   BOOST_REQUIRE(monitor.monitor_test(stats));
+
+   // outside of limit for too long
+   stats.last_run =  fc::time_point{fc::microseconds{8100000}};
+   BOOST_REQUIRE(!monitor.monitor_test(stats));
+}
+
+BOOST_AUTO_TEST_CASE(tps_cant_keep_up_monitored)
+{
+   constexpr uint32_t test_duration_s = 5;
+   constexpr uint32_t test_tps = 100000;
+   constexpr uint32_t trx_delay_us = 10;
+   constexpr uint32_t expected_trxs = test_duration_s * test_tps;
+   constexpr uint64_t expected_runtime_us = test_duration_s * 1000000;
+   constexpr uint64_t allowable_runtime_deviation_per = 20;
+   constexpr uint64_t allowable_runtime_deviation_us = expected_runtime_us / allowable_runtime_deviation_per;
+   constexpr uint64_t minimum_runtime_us = expected_runtime_us - allowable_runtime_deviation_us;
+   constexpr uint64_t maximum_runtime_us = expected_runtime_us + allowable_runtime_deviation_us;
+
+   std::shared_ptr<mock_trx_generator> generator = std::make_shared<mock_trx_generator>(expected_trxs, trx_delay_us);
+   std::shared_ptr<tps_performance_monitor> monitor = std::make_shared<tps_performance_monitor>();
+
+
+   trx_tps_tester<mock_trx_generator, tps_performance_monitor> t1(generator, monitor, test_duration_s, test_tps);
+
+   fc::time_point start = fc::time_point::now();
+   t1.run();
+   fc::time_point end = fc::time_point::now();
+   fc::microseconds runtime_us = end.time_since_epoch() - start.time_since_epoch() ;
+
+   BOOST_REQUIRE_LT(runtime_us.count(), expected_runtime_us);
+   BOOST_REQUIRE_LT(generator->_calls.size(), expected_trxs);
+
 }
 BOOST_AUTO_TEST_SUITE_END()

tests/trx_generator/trx_provider.cpp

@@ -79,4 +79,33 @@ namespace eosio::testing {
       _peer_connection.disconnect();
   }
 
+  bool tps_performance_monitor::monitor_test(const tps_test_stats &stats) {
+      if ((!stats.expected_sent) || (stats.last_run - stats.start_time < _spin_up_time)) {
+         return true;
+      }
+
+      int32_t trxs_behind = stats.expected_sent - stats.trxs_sent;
+      if (trxs_behind < 1) {
+         return true;
+      }
+
+      uint32_t per_off = (100*trxs_behind) / stats.expected_sent;
+
+      if (per_off > _max_lag_per) {
+         if (_violation_start_time.has_value()) {
+           auto lag_duration_us = stats.last_run - _violation_start_time.value();
+           if (lag_duration_us > _max_lag_duration_us) {
+               elog("target tps lagging outside of defined limits. terminating test");
+               return false;
+           }
+         } else {
+            _violation_start_time.emplace(stats.last_run);
+         }
+      } else {
+         if (_violation_start_time.has_value()) {
+            _violation_start_time.reset();
+         }
+      }
+      return true;
+  }
 }

tests/trx_generator/trx_provider.hpp

@@ -43,23 +43,41 @@ namespace eosio::testing {
    using fc::time_point;
 
    struct tps_test_stats {
-      uint32_t total_trxs = 0;
-      uint32_t trxs_left = 0;
-      uint32_t trxs_sent = 0;
-      time_point start_time;
-      time_point expected_end_time;
-      time_point last_run;
-      time_point next_run;
-      int64_t time_to_next_trx_us = 0;
-
+      uint32_t          total_trxs = 0;
+      uint32_t          trxs_left = 0;
+      uint32_t          trxs_sent = 0;
+      time_point        start_time;
+      time_point        expected_end_time;
+      time_point        last_run;
+      time_point        next_run;
+      int64_t           time_to_next_trx_us = 0;
+      fc::microseconds  trx_interval;
+      uint32_t          expected_sent;
    };
 
-   constexpr int64_t min_sleep_us = 1;
+   constexpr int64_t min_sleep_us                  = 1;
+   constexpr int64_t default_spin_up_time_us       = std::chrono::microseconds(1s).count();
+   constexpr uint32_t default_max_lag_per          = 5;
+   constexpr int64_t default_max_lag_duration_us  = std::chrono::microseconds(1s).count();
 
    struct null_tps_monitor {
       bool monitor_test(const tps_test_stats& stats) {return true;}
    };
 
+   struct tps_performance_monitor {
+      fc::microseconds     _spin_up_time;
+      uint32_t             _max_lag_per;
+      fc::microseconds     _max_lag_duration_us;
+
+      std::optional<fc::time_point>       _violation_start_time;
+
+      tps_performance_monitor(int64_t spin_up_time=default_spin_up_time_us, uint32_t max_lag_per=default_max_lag_per,
+                              int64_t max_lag_duration_us=default_max_lag_duration_us) : _spin_up_time(spin_up_time),
+                              _max_lag_per(max_lag_per), _max_lag_duration_us(max_lag_duration_us) {}
+
+      bool monitor_test(const tps_test_stats& stats);
+   };
+
    template<typename G, typename M>
    struct trx_tps_tester {
       std::shared_ptr<G> _generator;
@@ -85,7 +103,7 @@ namespace eosio::testing {
          }
 
          tps_test_stats stats;
-         fc::microseconds trx_interval(std::chrono::microseconds(1s).count() / _target_tps);
+         stats.trx_interval = fc::microseconds(std::chrono::microseconds(1s).count() / _target_tps);
 
          stats.total_trxs = _gen_duration_seconds * _target_tps;
          stats.trxs_left = stats.total_trxs;
@@ -97,14 +115,15 @@ namespace eosio::testing {
 
          while (keep_running) {
             stats.last_run = fc::time_point::now();
-            stats.next_run = stats.start_time + fc::microseconds(trx_interval.count() * (stats.trxs_sent+1));
+            stats.next_run = stats.start_time + fc::microseconds(stats.trx_interval.count() * (stats.trxs_sent+1));
 
             if (_generator->generate_and_send()) {
                stats.trxs_sent++;
             } else {
                elog("generator unable to create/send a transaction");
             }
 
+            stats.expected_sent = ((stats.last_run - stats.start_time).count() / stats.trx_interval.count()) +1;
             stats.trxs_left--;
 
             keep_running = ((_monitor == nullptr || _monitor->monitor_test(stats)) && stats.trxs_left);