Make process-wrapper output execution statistics for executed commands.

For example, it now outputs resource usage statistics like the amount of user time and system time used.

RELNOTES: None
PiperOrigin-RevId: 177263221

3 files changed, 210 insertions, 4 deletions

diff --git a/src/test/shell/integration/BUILD b/src/test/shell/integration/BUILD
index a04bb2c6b3..1d9b55d76c 100644
--- a/src/test/shell/integration/BUILD
+++ b/src/test/shell/integration/BUILD
@@ -288,9 +288,23 @@ sh_test(
     name = "process_wrapper_test",
     size = "medium",
     srcs = ["process-wrapper_test.sh"],
-    data = [":test-deps"],
+    data = [
+        ":spend_cpu_time",
+        ":test-deps",
+        "//src/main/protobuf:execution_statistics.proto",
+    ],
 )
 
+cc_binary(
+    name = "spend_cpu_time",
+    testonly = 1,
+    srcs = ["spend_cpu_time.cc"],
+    malloc = "//base:system_malloc",
+)
+
+########################################################################
+# Test suites.
+
 test_suite(
     name = "all_tests",
     visibility = ["//visibility:public"],
diff --git a/src/test/shell/integration/process-wrapper_test.sh b/src/test/shell/integration/process-wrapper_test.sh
index bff6099e5d..e6aeda064e 100755
--- a/src/test/shell/integration/process-wrapper_test.sh
+++ b/src/test/shell/integration/process-wrapper_test.sh
@@ -24,10 +24,19 @@ CURRENT_DIR="$(cd "$(dirname "${BASH_SOURCE[0]}")" && pwd)"
 source "${CURRENT_DIR}/../integration_test_setup.sh" \
   || { echo "integration_test_setup.sh not found!" >&2; exit 1; }
 
+enable_errexit
+
+readonly STATS_PROTO_PATH="${CURRENT_DIR}/../../../main/protobuf/execution_statistics.proto"
+readonly STATS_PROTO_DIR="$(cd "$(dirname "${STATS_PROTO_PATH}")" && pwd)"
+
+readonly CPU_TIME_SPENDER="${CURRENT_DIR}/../../../test/shell/integration/spend_cpu_time"
+
 readonly OUT_DIR="${TEST_TMPDIR}/out"
 readonly OUT="${OUT_DIR}/outfile"
 readonly ERR="${OUT_DIR}/errfile"
 
+readonly EXIT_STATUS_SIGALRM=$((128 + 14))
+
 function set_up() {
   rm -rf $OUT_DIR
   mkdir -p $OUT_DIR
@@ -68,7 +77,7 @@ function test_signal_catcher() {
   local code=0
   $process_wrapper --timeout=1 --kill_delay=10 --stdout=$OUT --stderr=$ERR /bin/sh -c \
     'trap "echo later; exit 0" INT TERM ALRM; sleep 10' &> $TEST_log || code=$?
-  assert_equals 142 "$code" # SIGNAL_BASE + SIGALRM = 128 + 14
+  assert_equals "${EXIT_STATUS_SIGALRM}" "$code"
   assert_stdout "later"
 }
 
@@ -87,7 +96,7 @@ function test_timeout_grace() {
   $process_wrapper --timeout=1 --kill_delay=10 --stdout=$OUT --stderr=$ERR /bin/sh -c \
     'trap "echo before; sleep 1; echo after; exit 0" INT TERM ALRM; sleep 10' \
     &> $TEST_log || code=$?
-  assert_equals 142 "$code" # SIGNAL_BASE + SIGALRM = 128 + 14
+  assert_equals "${EXIT_STATUS_SIGALRM}" "$code"
   assert_stdout 'before
 after'
 }
@@ -101,7 +110,7 @@ function test_timeout_kill() {
   $process_wrapper --timeout=1 --kill_delay=2 --stdout=$OUT --stderr=$ERR /bin/sh -c \
     'trap "echo before; sleep 10; echo after; exit 0" INT TERM ALRM; sleep 10' \
     &> $TEST_log || code=$?
-  assert_equals 142 "$code" # SIGNAL_BASE + SIGALRM = 128 + 14
+  assert_equals "${EXIT_STATUS_SIGALRM}" "$code"
   assert_stdout "before"
 }
 
@@ -112,4 +121,70 @@ function test_execvp_error_message() {
   assert_contains "\"execvp(/bin/notexisting, ...)\": No such file or directory" "$ERR"
 }
 
+function check_execution_time_for_command() {
+  local user_time_low="$1"; shift 1
+  local user_time_high="$1"; shift 1
+  local sys_time_low="$1"; shift 1
+  local sys_time_high="$1"; shift 1
+
+  local stats_out_path="${OUT_DIR}/statsfile"
+  local stats_out_decoded_path="${OUT_DIR}/statsfile.decoded"
+
+  # Wrapped process will be terminated after 100 seconds if not self terminated.
+  local code=0
+  "${process_wrapper}" --timeout=100 --kill_delay=2 --stdout="${OUT}" \
+      --stderr="${ERR}" --stats="${stats_out_path}" \
+      "$@" &> "${TEST_log}" || code="$?"
+  assert_equals 0 "${code}"
+
+  if [ ! -e "${stats_out_path}" ]; then
+    fail "Stats file not found: '${stats_out_path}'"
+  fi
+
+  "${protoc_compiler}" --proto_path="${STATS_PROTO_DIR}" \
+      --decode tools.protos.ExecutionStatistics execution_statistics.proto \
+      < "${stats_out_path}" > "${stats_out_decoded_path}"
+
+  if [ ! -e "${stats_out_decoded_path}" ]; then
+    fail "Decoded stats file not found: '${stats_out_decoded_path}'"
+  fi
+
+  local utime=0
+  if grep -q utime_sec "${stats_out_decoded_path}"; then
+    utime="$(grep utime_sec ${stats_out_decoded_path} | cut -f2 -d':' | \
+      tr -dc '0-9')"
+  fi
+
+  local stime=0
+  if grep -q stime_sec "${stats_out_decoded_path}"; then
+    stime="$(grep stime_sec ${stats_out_decoded_path} | cut -f2 -d':' | \
+      tr -dc '0-9')"
+  fi
+
+  if ! [ ${utime} -ge ${user_time_low} -a ${utime} -le ${user_time_high} ]; then
+    fail "reported utime of '${utime}' is out of expected range"
+  fi
+  if ! [ ${stime} -ge ${sys_time_low} -a ${stime} -le ${sys_time_high} ]; then
+    fail "reported stime of '${stime}' is out of expected range"
+  fi
+}
+
+function test_stats_high_user_time() {
+  # Tested with blaze test --runs_per_test 1000 on November 28, 2017.
+  check_execution_time_for_command 10 11 0 1 \
+      "${CPU_TIME_SPENDER}" 10 0
+}
+
+function test_stats_high_system_time() {
+  # Tested with blaze test --runs_per_test 1000 on November 28, 2017.
+  check_execution_time_for_command 0 1 10 11 \
+      "${CPU_TIME_SPENDER}" 0 10
+}
+
+function test_stats_high_user_time_and_high_system_time() {
+  # Tested with blaze test --runs_per_test 1000 on November 28, 2017.
+  check_execution_time_for_command 10 11 10 11 \
+      "${CPU_TIME_SPENDER}" 10 10
+}
+
 run_suite "process-wrapper"
diff --git a/src/test/shell/integration/spend_cpu_time.cc b/src/test/shell/integration/spend_cpu_time.cc
new file mode 100644
index 0000000000..636a2a1692
--- /dev/null
+++ b/src/test/shell/integration/spend_cpu_time.cc
@@ -0,0 +1,117 @@
+// Copyright 2017 The Bazel Authors. All rights reserved.
+//
+// Licensed under the Apache License, Version 2.0 (the "License");
+// you may not use this file except in compliance with the License.
+// You may obtain a copy of the License at
+//
+//    http://www.apache.org/licenses/LICENSE-2.0
+//
+// Unless required by applicable law or agreed to in writing, software
+// distributed under the License is distributed on an "AS IS" BASIS,
+// WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
+// See the License for the specific language governing permissions and
+// limitations under the License.
+
+#include <sys/param.h>
+#include <sys/types.h>
+#include <sys/resource.h>
+#include <err.h>
+#include <unistd.h>
+
+#include <cerrno>
+#include <cstdint>
+#include <cstdio>
+#include <cstdlib>
+#include <cstring>
+
+// Marked as volatile to force the C compiler to calculate it.
+volatile uint64_t volatile_counter;
+
+static void WasteUserTime() {
+  volatile_counter = 0;
+  while (true) {
+    volatile_counter++;
+    if (volatile_counter == 10000000) {
+      break;
+    }
+  }
+}
+
+static void WasteSystemTime() {
+  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) {
+    // Arbitrary syscall to waste system time.
+    if (chdir(current_dir_path) != 0) {
+      err(EXIT_FAILURE, "chdir() failed");
+    }
+    volatile_counter++;
+    if (volatile_counter == 100000) {
+      break;
+    }
+  }
+}
+
+static void GetResourceUsage(struct rusage *rusage) {
+  if (getrusage(RUSAGE_SELF, rusage) != 0) {
+    err(EXIT_FAILURE, "getrusage() failed");
+  }
+}
+
+static int GetUsedUserTimeSeconds() {
+  struct rusage my_rusage;
+  GetResourceUsage(&my_rusage);
+  return my_rusage.ru_utime.tv_sec;
+}
+
+static int GetUsedSystemTimeSeconds() {
+  struct rusage my_rusage;
+  GetResourceUsage(&my_rusage);
+  return my_rusage.ru_stime.tv_sec;
+}
+
+// This program just wastes (at least) the desired amount of CPU time, by
+// checking its own resource usage (rusage) while running.
+int main(int argc, char **argv) {
+  // Parse command-line arguments.
+  const char *progname = argv[0] ? argv[0] : "spend_cpu_time";
+  if (argc != 3) {
+    fprintf(stderr, "Usage: %s <user_time_seconds> <system_time_seconds>\n",
+            progname);
+    exit(EXIT_FAILURE);
+  }
+
+  int requested_user_time_seconds \
+      = atoi(argv[1]);  // NOLINT(runtime/deprecated_fn)
+  int requested_system_time_seconds \
+      = atoi(argv[2]);  // NOLINT(runtime/deprecated_fn)
+
+  // 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();
+    }
+  }
+
+  // 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();
+    }
+  }
+
+  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);
+
+  exit(EXIT_SUCCESS);
+}