Make spend_cpu_time more reliable by tracking time.

First, make the function that wastes user time keep track of how much
processor time has been used so far, and make the function that wastes
system time track overall wall time. This is to minimize the number
of "overhead" system calls, which can tamper with our measurements.

Second, make the loop of the function that wastes user time more costly
so that modern processors don't run it too fast. Otherwise, the overhead
to track used time becomes significant in system time and makes our
tests fail.

This should fix the flakiness observed in our process-wrapper tests
when run on the modern CPUs that the iMac Pros carry.

Tested: I haven't been able to reproduce the flakiness. Running the
spend_cpu_time binary by hand reports very accurate timings for both
system and user time, even when pausing the program while it runs.

RELNOTES: None.
PiperOrigin-RevId: 204264910

4 files changed, 84 insertions, 34 deletions

diff --git a/.bazelci/presubmit.yml b/.bazelci/presubmit.yml
index 631593930b..52aab52039 100644
--- a/.bazelci/presubmit.yml
+++ b/.bazelci/presubmit.yml
@@ -74,9 +74,6 @@ platforms:
     - "//tools/android/..."
     # Re-enable once fixed: https://github.com/bazelbuild/bazel/issues/4663
     - "-//src/test/shell/bazel/android:android_ndk_integration_test"
-    # Re-enable once fixed: b/110456205
-    - "-//src/test/java/com/google/devtools/build/lib/shell:ShellTests"
-    - "-//src/test/shell/integration:process_wrapper_test"
     # The below tests have been disabled because they are too slow on macOS.
     # Re-enable once fixed: https://github.com/bazelbuild/bazel/issues/4684
     - "-//src/test/shell/bazel:bazel_determinism_test"
diff --git a/src/test/shell/integration/linux-sandbox_test.sh b/src/test/shell/integration/linux-sandbox_test.sh
index 84a618bbea..28d0897108 100755
--- a/src/test/shell/integration/linux-sandbox_test.sh
+++ b/src/test/shell/integration/linux-sandbox_test.sh
@@ -250,6 +250,8 @@ function assert_linux_sandbox_exec_time() {
       -- \
       "${cpu_time_spender_sandbox_path}" "${user_time_low}" "${sys_time_low}" \
       &> "${TEST_log}" || code="$?"
+  sed -e 's,^subprocess stdout: ,,' "${stdout_path}" >>"${TEST_log}"
+  sed -e 's,^subprocess stderr: ,,' "${stderr_path}" >>"${TEST_log}"
   assert_equals 0 "${code}"
 
   assert_execution_time_in_range \
diff --git a/src/test/shell/integration/process-wrapper_test.sh b/src/test/shell/integration/process-wrapper_test.sh
index b5e9d245a8..fac45f9f72 100755
--- a/src/test/shell/integration/process-wrapper_test.sh
+++ b/src/test/shell/integration/process-wrapper_test.sh
@@ -139,6 +139,8 @@ function assert_process_wrapper_exec_time() {
       --stats="${stats_out_path}" \
       "${CPU_TIME_SPENDER}" "${user_time_low}" "${sys_time_low}" \
       &> "${TEST_log}" || code="$?"
+  sed -e 's,^subprocess stdout: ,,' "${stdout_path}" >>"${TEST_log}"
+  sed -e 's,^subprocess stderr: ,,' "${stderr_path}" >>"${TEST_log}"
   assert_equals 0 "${code}"
 
   assert_execution_time_in_range \
diff --git a/src/test/shell/integration/spend_cpu_time.cc b/src/test/shell/integration/spend_cpu_time.cc
index cc0acfaaf5..55b8fe9294 100644
--- a/src/test/shell/integration/spend_cpu_time.cc
+++ b/src/test/shell/integration/spend_cpu_time.cc
@@ -13,9 +13,12 @@
 // limitations under the License.
 
 #include <sys/param.h>
+#include <sys/time.h>
 #include <sys/types.h>
 #include <sys/resource.h>
 #include <err.h>
+#include <inttypes.h>
+#include <time.h>
 #include <unistd.h>
 
 #include <cerrno>
@@ -24,35 +27,62 @@
 #include <cstdlib>
 #include <cstring>
 
-// Marked as volatile to force the C compiler to calculate it.
-volatile uint64_t volatile_counter;
+// Computes the time that passed, in millis, since the previous timestamp.
+static uint64_t ElapsedCpuMillisSince(const clock_t before) {
+  const clock_t now = clock();
+  return 1000 * (now - before) / CLOCKS_PER_SEC;
+}
+
+// Computes the time that passed, in millis, since the previous timestamp.
+static uint64_t ElapsedWallTimeMillisSince(const struct timeval* before) {
+  struct timeval now;
+  gettimeofday(&now, NULL);
+  return (now.tv_sec * 1000 + now.tv_usec / 1000) -
+      (before->tv_sec * 1000 + before->tv_usec / 1000);
+}
 
-static void WasteUserTime() {
-  volatile_counter = 0;
-  while (true) {
-    volatile_counter++;
-    if (volatile_counter == 1000) {
-      break;
+// Spends CPU time for about the requested number of milliseconds.
+//
+// This function should not invoke any system calls, but as this is very hard to
+// do in a portable way, the number of such invocations should be kept to a
+// minimum so that their cost is not noticeable.
+//
+// This function does not guarantee that the used CPU time is above the given
+// millis. The caller needs to check this and, if not yet achieved, call this
+// function again with the remainder.
+static void WasteUserTime(const uint64_t millis) {
+  const clock_t before = clock();
+  while (ElapsedCpuMillisSince(before) < millis) {
+    // The body of this loop is supposed to consume enough CPU time to make the
+    // actual calls to clock() insignificant. This means that if this loop gets
+    // optimized, or if the CPU becomes fast enough to run this "too fast", this
+    // function may consume more system time than user time and cause tests to
+    // fail.
+    volatile uint64_t counter = 0;
+    while (counter < 1000000) {
+      counter++;
     }
   }
 }
 
-static void WasteSystemTime() {
+// Spends system time for about the requested number of milliseconds.
+//
+// This function does not guarantee that the used system time is above the given
+// millis. The caller needs to check this and, if not yet achieved, call this
+// function again with the remainder.
+static void WasteSystemTime(const uint64_t millis) {
   char current_dir_path[MAXPATHLEN];
   if (getcwd(current_dir_path, sizeof(current_dir_path)) == NULL) {
     err(EXIT_FAILURE, "getcwd() failed");
   }
 
-  volatile_counter = 0;
-  while (true) {
+  struct timeval before;
+  gettimeofday(&before, NULL);
+  while (ElapsedWallTimeMillisSince(&before) < millis) {
     // Arbitrary syscall to waste system time.
     if (chdir(current_dir_path) != 0) {
       err(EXIT_FAILURE, "chdir() failed");
     }
-    volatile_counter++;
-    if (volatile_counter == 1000) {
-      break;
-    }
   }
 }
 
@@ -62,16 +92,27 @@ static void GetResourceUsage(struct rusage *rusage) {
   }
 }
 
-static int GetUsedUserTimeSeconds() {
+static uint64_t GetUsedUserTimeMillis() {
   struct rusage my_rusage;
   GetResourceUsage(&my_rusage);
-  return my_rusage.ru_utime.tv_sec;
+  return my_rusage.ru_utime.tv_sec * 1000 + my_rusage.ru_utime.tv_usec / 1000;
 }
 
-static int GetUsedSystemTimeSeconds() {
+static uint64_t GetUsedSystemTimeMillis() {
   struct rusage my_rusage;
   GetResourceUsage(&my_rusage);
-  return my_rusage.ru_stime.tv_sec;
+  return my_rusage.ru_stime.tv_sec * 1000 + my_rusage.ru_stime.tv_usec / 1000;
+}
+
+// Substracts subtrahend from minuend, or returns zero if the subtrahend is
+// larger than the minuend.
+static uint64_t SubtractOrZero(const uint64_t minuend,
+                               const uint64_t subtrahend) {
+  if (subtrahend > minuend) {
+    return 0;
+  } else {
+    return minuend - subtrahend;
+  }
 }
 
 // This program just wastes (at least) the desired amount of CPU time, by
@@ -92,26 +133,34 @@ int main(int argc, char **argv) {
 
   // Waste system time first, because this also wastes some user time.
   if (requested_system_time_seconds > 0) {
-    int spent_system_time_seconds = 0;
-    while (spent_system_time_seconds < requested_system_time_seconds) {
-      WasteSystemTime();
-      spent_system_time_seconds = GetUsedSystemTimeSeconds();
+    const uint64_t requested_millis = requested_system_time_seconds * 1000;
+    for (;;) {
+      const uint64_t remaining_millis =
+          SubtractOrZero(requested_millis, GetUsedSystemTimeMillis());
+      if (remaining_millis == 0) {
+        break;
+      }
+      WasteSystemTime(remaining_millis);
     }
   }
 
   // Waste user time if we haven't already wasted enough.
   if (requested_user_time_seconds > 0) {
-    int spent_user_time_seconds = 0;
-    while (spent_user_time_seconds < requested_user_time_seconds) {
-      WasteUserTime();
-      spent_user_time_seconds = GetUsedUserTimeSeconds();
+    const uint64_t requested_millis = requested_user_time_seconds * 1000;
+    for (;;) {
+      const uint64_t remaining_millis =
+          SubtractOrZero(requested_millis, GetUsedUserTimeMillis());
+      if (remaining_millis == 0) {
+        break;
+      }
+      WasteUserTime(remaining_millis);
     }
   }
 
-  int spent_user_time_seconds = GetUsedUserTimeSeconds();
-  int spent_system_time_seconds = GetUsedSystemTimeSeconds();
-  printf("Total user time wasted: %d seconds\n", spent_user_time_seconds);
-  printf("Total system time wasted: %d seconds\n", spent_system_time_seconds);
+  printf("Total user time wasted: %" PRIu64 " ms\n",
+         GetUsedUserTimeMillis());
+  printf("Total system time wasted: %" PRIu64 " ms\n",
+         GetUsedSystemTimeMillis());
 
   exit(EXIT_SUCCESS);
 }