Switch to enableHRTimer -- improve request-release timing accuracy

source/client/process_impl.cc

@@ -100,6 +100,8 @@ ProcessImpl::ProcessImpl(const Options& options, Envoy::Event::TimeSystem& time_
       access_log_manager_(std::chrono::milliseconds(1000), *api_, *dispatcher_, access_log_lock_,
                           store_root_),
       init_watcher_("Nighthawk", []() {}), validation_context_(false, false) {
+  // Any dispatchers created after the following call will use hr timers.
+  setupForHRTimers();
   std::string lower = absl::AsciiStrToLower(
       nighthawk::client::Verbosity::VerbosityOptions_Name(options_.verbosity()));
   configureComponentLogLevels(spdlog::level::from_str(lower));
@@ -408,5 +410,14 @@ bool ProcessImpl::run(OutputCollector& collector) {
   return counters.find("sequencer.failed_terminations") == counters.end();
 }
 
+void ProcessImpl::setupForHRTimers() {
+  // We override the local environment to indicate to libevent that we favor precision over
+  // efficiency. Note that it is also possible to do this at setup time via libevent's api's.
+  // The upside of the approach below is that we are very loosely coupled and have a one-liner.
+  // Getting to libevent for the other approach is going to introduce more code as we would need to
+  // derive our own customized versions of certain Envoy concepts.
+  putenv(const_cast<char*>("EVENT_PRECISE_TIMER=1"));
+}
+
 } // namespace Client
 } // namespace Nighthawk

source/client/process_impl.h

@@ -66,6 +66,7 @@ class ProcessImpl : public Process, public Envoy::Logger::Loggable<Envoy::Logger
   std::vector<StatisticPtr>
   mergeWorkerStatistics(const StatisticFactory& statistic_factory,
                         const std::vector<ClientWorkerPtr>& workers) const;
+  void setupForHRTimers();
   Envoy::ProcessWide process_wide_;
   Envoy::PlatformImpl platform_impl_;
   Envoy::Event::TimeSystem& time_system_;

source/common/sequencer_impl.cc

@@ -42,7 +42,7 @@ void SequencerImpl::start() {
   run(false);
 }
 
-void SequencerImpl::scheduleRun() { periodic_timer_->enableTimer(EnvoyTimerMinResolution); }
+void SequencerImpl::scheduleRun() { periodic_timer_->enableHRTimer(NighthawkTimerResolution); }
 
 void SequencerImpl::stop(bool failed) {
   ASSERT(running_);
@@ -109,7 +109,7 @@ void SequencerImpl::run(bool from_periodic_timer) {
         if (this->running_) {
           // Immediately schedule us to check again, as chances are we can get on with the next
           // task.
-          spin_timer_->enableTimer(0ms);
+          spin_timer_->enableHRTimer(0ms);
         }
       });
 
@@ -141,11 +141,11 @@ void SequencerImpl::run(bool from_periodic_timer) {
       // TODO(oschaaf): Ideally we would have much finer grained timers instead.
       // TODO(oschaaf): Optionize performing this spin loop.
       platform_util_.yieldCurrentThread();
-      spin_timer_->enableTimer(0ms);
+      spin_timer_->enableHRTimer(0ms);
     } else if (idle_strategy_ == nighthawk::client::SequencerIdleStrategy::SLEEP) {
       // optionize sleep duration.
       platform_util_.sleep(50us);
-      spin_timer_->enableTimer(0ms);
+      spin_timer_->enableHRTimer(0ms);
     } // .. else we poll, the periodic timer will be active
   }
 }

source/common/sequencer_impl.h

@@ -19,7 +19,8 @@ namespace {
 
 using namespace std::chrono_literals;
 
-constexpr std::chrono::milliseconds EnvoyTimerMinResolution = 1ms;
+// We shoot for a 40kHz resolution.
+constexpr std::chrono::microseconds NighthawkTimerResolution = 25us;
 
 } // namespace
 

test/sequencer_test.cc

@@ -81,11 +81,11 @@ class SequencerTestWithTimerEmulation : public SequencerTest {
         }));
     EXPECT_CALL(*timer1_, disableTimer()).WillOnce(Invoke([&]() { timer1_set_ = false; }));
     EXPECT_CALL(*timer2_, disableTimer()).WillOnce(Invoke([&]() { timer2_set_ = false; }));
-    EXPECT_CALL(*timer1_, enableTimer(_, _))
-        .WillRepeatedly(Invoke([&](const std::chrono::milliseconds,
+    EXPECT_CALL(*timer1_, enableHRTimer(_, _))
+        .WillRepeatedly(Invoke([&](const std::chrono::microseconds,
                                    const Envoy::ScopeTrackedObject*) { timer1_set_ = true; }));
-    EXPECT_CALL(*timer2_, enableTimer(_, _))
-        .WillRepeatedly(Invoke([&](const std::chrono::milliseconds,
+    EXPECT_CALL(*timer2_, enableHRTimer(_, _))
+        .WillRepeatedly(Invoke([&](const std::chrono::microseconds,
                                    const Envoy::ScopeTrackedObject*) { timer2_set_ = true; }));
     EXPECT_CALL(*dispatcher_, exit()).WillOnce(Invoke([&]() { stopped_ = true; }));
     simulation_start_ = time_system_.monotonicTime();
@@ -108,7 +108,7 @@ class SequencerTestWithTimerEmulation : public SequencerTest {
   // Moves time forward 1ms, and runs the ballbacks of set timers.
   void simulateTimerLoop() {
     while (!stopped_) {
-      time_system_.setMonotonicTime(time_system_.monotonicTime() + EnvoyTimerMinResolution);
+      time_system_.setMonotonicTime(time_system_.monotonicTime() + NighthawkTimerResolution);
 
       // TODO(oschaaf): This can be implemented more accurately, by keeping track of timer
       // enablement preserving ordering of which timer should fire first. For now this seems to
@@ -291,7 +291,7 @@ TEST_F(SequencerIntegrationTest, CallbacksDoNotInfluenceTestDuration) {
 
   auto diff = time_system_.monotonicTime() - pre_timeout;
 
-  auto expected_duration = (test_number_of_intervals_ * interval_) + EnvoyTimerMinResolution;
+  auto expected_duration = (test_number_of_intervals_ * interval_) + NighthawkTimerResolution;
   EXPECT_EQ(expected_duration, diff);
 
   // the test itself should have seen all callbacks...