Browse Source

execute_process: Restore support for short timeouts

Since commit 5420639a8d (cmExecuteProcessCommand: Replace cmsysProcess
with cmUVProcessChain, 2023-06-01, v3.28.0-rc1~138^2~8) we've
occasionally observed immediate timeouts on processes that take longer
than the timeout to start, even though we only start the timer after the
child processes start.  The problem is that:

* `uv_loop_init` initializes `uv_loop_t`'s cached "now" time.
* Starting processes takes time but does not update the "now" time.
* `uv_timer_start` computes expiry relative the cached "now" time,
  so short timers may be expired as soon as they are started.
* `uv_run` invokes expired timer callbacks before polling for I/O
  or process completion, so we "timeout" immediately.

Fix this by updating the cached "now" time via `uv_update_time` just
before starting timers.  This is needed only for timers that start
before the `uv_run` event loop.  Update our `uv_timer_ptr` wrapper
to make all callers consider the choice when calling `start()`.
Brad King 3 weeks ago
parent
commit
6ec2c51f0c

+ 1 - 1
Source/CTest/cmCTestBuildHandler.cxx

@@ -840,7 +840,7 @@ bool cmCTestBuildHandler::RunMakeCommand(const std::string& command,
         auto* timedOutPtr = static_cast<bool*>(t->data);
         *timedOutPtr = true;
       },
-      timeout * 1000, 0);
+      timeout * 1000, 0, cm::uv_update_time::yes);
   }
 
   // For every chunk of data

+ 1 - 1
Source/CTest/cmCTestMultiProcessHandler.cxx

@@ -733,7 +733,7 @@ void cmCTestMultiProcessHandler::StartNextTestsOnTimer()
       auto* self = static_cast<cmCTestMultiProcessHandler*>(timer->data);
       self->StartNextTests();
     },
-    milliseconds, 0);
+    milliseconds, 0, cm::uv_update_time::no);
 }
 
 void cmCTestMultiProcessHandler::FinishTestProcess(

+ 2 - 1
Source/CTest/cmProcess.cxx

@@ -156,7 +156,8 @@ void cmProcess::StartTimer()
     auto msec =
       std::chrono::duration_cast<std::chrono::milliseconds>(*this->Timeout);
     this->Timer.start(&cmProcess::OnTimeoutCB,
-                      static_cast<uint64_t>(msec.count()), 0);
+                      static_cast<uint64_t>(msec.count()), 0,
+                      cm::uv_update_time::no);
   }
 }
 

+ 2 - 1
Source/cmCTest.cxx

@@ -3553,7 +3553,8 @@ bool cmCTest::RunCommand(std::vector<std::string> const& args,
         auto* timedOutPtr = static_cast<bool*>(t->data);
         *timedOutPtr = true;
       },
-      static_cast<uint64_t>(timeout.count() * 1000.0), 0);
+      static_cast<uint64_t>(timeout.count() * 1000.0), 0,
+      cm::uv_update_time::yes);
   }
 
   std::vector<char> tempOutput;

+ 1 - 1
Source/cmExecuteProcessCommand.cxx

@@ -306,7 +306,7 @@ bool cmExecuteProcessCommand(std::vector<std::string> const& args,
         auto* timeoutPtr = static_cast<bool*>(handle->data);
         *timeoutPtr = true;
       },
-      timeoutMillis, 0);
+      timeoutMillis, 0, cm::uv_update_time::yes);
   }
 
   // Read the process output.

+ 4 - 2
Source/cmSystemTools.cxx

@@ -610,7 +610,8 @@ bool cmSystemTools::RunSingleCommand(std::vector<std::string> const& command,
         auto* timedOutPtr = static_cast<bool*>(t->data);
         *timedOutPtr = true;
       },
-      static_cast<uint64_t>(timeout.count() * 1000.0), 0);
+      static_cast<uint64_t>(timeout.count() * 1000.0), 0,
+      cm::uv_update_time::yes);
   }
 
   std::vector<char> tempStdOut;
@@ -2343,7 +2344,8 @@ cmSystemTools::WaitForLineResult cmSystemTools::WaitForLine(
         auto* timedOutPtr = static_cast<bool*>(handle->data);
         *timedOutPtr = true;
       },
-      static_cast<uint64_t>(timeout.count() * 1000.0), 0);
+      static_cast<uint64_t>(timeout.count() * 1000.0), 0,
+      cm::uv_update_time::no);
 
     uv_run(loop, UV_RUN_ONCE);
     if (timedOut) {

+ 5 - 1
Source/cmUVHandlePtr.cxx

@@ -243,9 +243,13 @@ int uv_timer_ptr::init(uv_loop_t& loop, void* data)
   return uv_timer_init(&loop, *this);
 }
 
-int uv_timer_ptr::start(uv_timer_cb cb, uint64_t timeout, uint64_t repeat)
+int uv_timer_ptr::start(uv_timer_cb cb, uint64_t timeout, uint64_t repeat,
+                        uv_update_time update_time)
 {
   assert(this->handle);
+  if (update_time == uv_update_time::yes) {
+    ::uv_update_time(this->handle->loop);
+  }
   return uv_timer_start(*this, cb, timeout, repeat);
 }
 

+ 16 - 1
Source/cmUVHandlePtr.h

@@ -30,6 +30,20 @@
 
 namespace cm {
 
+/** Whether to call uv_update_time before starting a timer.
+ *
+ * uv_loop_t caches a "now" time that uv_loop_init initializes and
+ * uv_run updates on each event loop iteration.  uv_timer_start
+ * computes timer expiry relative to the loop's cached "now" time.
+ * For short timeouts started before the event loop, we may need to
+ * update the "now" time when starting the timer.
+ */
+enum class uv_update_time
+{
+  no,
+  yes,
+};
+
 /***
  * RAII class to simplify and ensure the safe usage of uv_loop_t. This includes
  * making sure resources are properly freed.
@@ -251,7 +265,8 @@ struct uv_timer_ptr : public uv_handle_ptr_<uv_timer_t>
 
   int init(uv_loop_t& loop, void* data = nullptr);
 
-  int start(uv_timer_cb cb, uint64_t timeout, uint64_t repeat);
+  int start(uv_timer_cb cb, uint64_t timeout, uint64_t repeat,
+            uv_update_time update_time);
 
   void stop();
 };

+ 1 - 1
Source/cmUVProcessChain.cxx

@@ -439,7 +439,7 @@ bool cmUVProcessChain::Wait(uint64_t milliseconds)
         auto* timeoutPtr = static_cast<bool*>(handle->data);
         *timeoutPtr = true;
       },
-      milliseconds, 0);
+      milliseconds, 0, cm::uv_update_time::yes);
   }
 
   while (!timeout &&

+ 2 - 2
Tests/CMakeLib/testUVHandlePtr.cxx

@@ -74,7 +74,7 @@ static bool testTimer()
 
   cm::uv_timer_ptr timer;
   timer.init(*loop, &timed);
-  timer.start(cb, 10, 0);
+  timer.start(cb, 10, 0, cm::uv_update_time::no);
   uv_run(loop, UV_RUN_DEFAULT);
 
   if (!timed) {
@@ -83,7 +83,7 @@ static bool testTimer()
   }
 
   timed = false;
-  timer.start(cb, 10, 0);
+  timer.start(cb, 10, 0, cm::uv_update_time::no);
   timer.stop();
   uv_run(loop, UV_RUN_DEFAULT);