Make linux-sandbox 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: 178948958

7 files changed, 186 insertions, 61 deletions

diff --git a/src/main/tools/linux-sandbox-options.cc b/src/main/tools/linux-sandbox-options.cc
index 88e1fa2d73..b399b02c63 100644
--- a/src/main/tools/linux-sandbox-options.cc
+++ b/src/main/tools/linux-sandbox-options.cc
@@ -65,6 +65,7 @@ static void Usage(char *program_name, const char *fmt, ...) {
           "mounted readonly.\n"
           "    The -M option specifies which directory to mount, the -m option "
           "specifies where to\n"
+          "  -S <file>  if set, write stats in protobuf format to a file\n"
           "  -H  if set, make hostname in the sandbox equal to 'localhost'\n"
           "  -N  if set, a new network namespace will be created\n"
           "  -R  if set, make the uid/gid be root\n"
@@ -90,8 +91,8 @@ static void ParseCommandLine(unique_ptr<vector<char *>> args) {
   int c;
   bool source_specified = false;
 
-  while ((c = getopt(args->size(), args->data(), ":W:T:t:l:L:w:e:M:m:HNRUD")) !=
-         -1) {
+  while ((c = getopt(args->size(), args->data(),
+                     ":W:T:t:l:L:w:e:M:m:S:HNRUD")) != -1) {
     if (c != 'M' && c != 'm') source_specified = false;
     switch (c) {
       case 'W':
@@ -156,6 +157,14 @@ static void ParseCommandLine(unique_ptr<vector<char *>> args) {
         opt.bind_mount_targets.emplace_back(optarg);
         source_specified = false;
         break;
+      case 'S':
+        if (opt.stats_path.empty()) {
+          opt.stats_path.assign(optarg);
+        } else {
+          Usage(args->front(),
+                "Cannot write stats to more than one destination.");
+        }
+        break;
       case 'H':
         opt.fake_hostname = true;
         break;
diff --git a/src/main/tools/linux-sandbox-options.h b/src/main/tools/linux-sandbox-options.h
index c190372d5c..c0b6027e97 100644
--- a/src/main/tools/linux-sandbox-options.h
+++ b/src/main/tools/linux-sandbox-options.h
@@ -40,6 +40,8 @@ struct Options {
   std::vector<std::string> bind_mount_sources;
   // Target of files or directories to explicitly bind mount in the sandbox (-m)
   std::vector<std::string> bind_mount_targets;
+  // Where to write stats, in protobuf format (-S)
+  std::string stats_path;
   // Set the hostname inside the sandbox to 'localhost' (-H)
   bool fake_hostname;
   // Create a new network namespace (-N)
diff --git a/src/main/tools/linux-sandbox.cc b/src/main/tools/linux-sandbox.cc
index 4e7762f50e..98a54bccb4 100644
--- a/src/main/tools/linux-sandbox.cc
+++ b/src/main/tools/linux-sandbox.cc
@@ -51,6 +51,7 @@
 #include <stdlib.h>
 #include <string.h>
 #include <sys/prctl.h>
+#include <sys/resource.h>
 #include <sys/stat.h>
 #include <sys/time.h>
 #include <sys/types.h>
@@ -170,12 +171,22 @@ static void SpawnPid1() {
 
 static int WaitForPid1() {
   int err, status;
-  do {
-    err = waitpid(global_child_pid, &status, 0);
-  } while (err < 0 && errno == EINTR);
-
-  if (err < 0) {
-    DIE("waitpid");
+  if (!opt.stats_path.empty()) {
+    struct rusage child_rusage;
+    do {
+      err = wait4(global_child_pid, &status, 0, &child_rusage);
+    } while (err < 0 && errno == EINTR);
+    if (err < 0) {
+      DIE("wait4");
+    }
+    WriteStatsToFile(&child_rusage, opt.stats_path);
+  } else {
+    do {
+      err = waitpid(global_child_pid, &status, 0);
+    } while (err < 0 && errno == EINTR);
+    if (err < 0) {
+      DIE("waitpid");
+    }
   }
 
   if (global_signal > 0) {
diff --git a/src/test/shell/integration/BUILD b/src/test/shell/integration/BUILD
index 35522fd5fb..2f75eb550f 100644
--- a/src/test/shell/integration/BUILD
+++ b/src/test/shell/integration/BUILD
@@ -296,6 +296,7 @@ sh_test(
     size = "medium",
     srcs = ["process-wrapper_test.sh"],
     data = [
+        ":execution_statistics_utils.sh",
         ":spend_cpu_time",
         ":test-deps",
         "//src/main/protobuf:execution_statistics.proto",
@@ -308,8 +309,12 @@ sh_test(
     size = "large",
     srcs = ["linux-sandbox_test.sh"],
     data = [
+        ":execution_statistics_utils.sh",
+        ":spend_cpu_time",
         ":test-deps",
+        "//src/main/protobuf:execution_statistics.proto",
         "//src/test/shell:sandboxing_test_utils.sh",
+        "//third_party/protobuf:protoc",
     ],
 )
 
diff --git a/src/test/shell/integration/execution_statistics_utils.sh b/src/test/shell/integration/execution_statistics_utils.sh
new file mode 100644
index 0000000000..d958c32ec5
--- /dev/null
+++ b/src/test/shell/integration/execution_statistics_utils.sh
@@ -0,0 +1,68 @@
+#!/bin/bash
+#
+# 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.
+
+set -euo pipefail
+
+# Assumes integration_test_setup.sh was loaded elsewhere (can't load it twice)
+enable_errexit
+
+readonly CURRENT_DIR="$(cd "$(dirname "${BASH_SOURCE[0]}")" && pwd)"
+readonly STATS_PROTO_PATH="${CURRENT_DIR}/../../../main/protobuf/execution_statistics.proto"
+readonly STATS_PROTO_DIR="$(cd "$(dirname "${STATS_PROTO_PATH}")" && pwd)"
+
+# Checks that user CPU time and system CPU time, as read from an execution
+# statistics proto file, are within expected bounds.
+#
+# This relies on ${protoc_compiler} being set (currently set in testenv.sh)
+#
+function assert_execution_time_in_range() {
+  local utime_low="$1"; shift
+  local utime_high="$1"; shift
+  local stime_low="$1"; shift
+  local stime_high="$1"; shift
+  local stats_out_path="$1"; shift
+
+  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 ${utime_low} && ${utime} -le ${utime_high} ]]; then
+    fail "reported utime of '${utime}' is out of expected range"
+  fi
+  if ! [[ ${stime} -ge ${stime_low} && ${stime} -le ${stime_high} ]]; then
+    fail "reported stime of '${stime}' is out of expected range"
+  fi
+}
diff --git a/src/test/shell/integration/linux-sandbox_test.sh b/src/test/shell/integration/linux-sandbox_test.sh
index 945f74e0c5..959e982f2f 100755
--- a/src/test/shell/integration/linux-sandbox_test.sh
+++ b/src/test/shell/integration/linux-sandbox_test.sh
@@ -25,6 +25,8 @@ source "${CURRENT_DIR}/../integration_test_setup.sh" \
   || { echo "integration_test_setup.sh not found!" >&2; exit 1; }
 source "${CURRENT_DIR}/../sandboxing_test_utils.sh" \
   || { echo "sandboxing_test_utils.sh not found!" >&2; exit 1; }
+source "${CURRENT_DIR}/execution_statistics_utils.sh" \
+  || { echo "execution_statistics_utils.sh not found!" >&2; exit 1; }
 
 enable_errexit
 
@@ -34,6 +36,8 @@ readonly ERR="${OUT_DIR}/errfile"
 readonly SANDBOX_DIR="${OUT_DIR}/sandbox"
 readonly MOUNT_TARGET_ROOT="${TEST_TMPDIR}/targets"
 
+readonly CPU_TIME_SPENDER="${CURRENT_DIR}/../../../test/shell/integration/spend_cpu_time"
+
 SANDBOX_DEFAULT_OPTS="-W $SANDBOX_DIR"
 
 function set_up {
@@ -53,7 +57,7 @@ function test_execvp_error_message_contains_path() {
 
 function test_default_user_is_current_user() {
   $linux_sandbox $SANDBOX_DEFAULT_OPTS -- /usr/bin/id &> $TEST_log || fail
-  local current_uid_number=$(id -u)
+  local current_uid_number="$(id -u)"
   # Expecting something like: uid=485038(ruperts) ...
   expect_log "uid=${current_uid_number}("
 }
@@ -219,6 +223,55 @@ function test_dev_shm_is_writable() {
     &> $TEST_log || fail
 }
 
+function assert_linux_sandbox_exec_time() {
+  local user_time_low="$1"; shift
+  local user_time_high="$1"; shift
+  local sys_time_low="$1"; shift
+  local sys_time_high="$1"; shift
+
+  local local_tmp="$(mktemp -d "${OUT_DIR}/assert_linux_sandbox_exec_timeXXXX")"
+  local stdout_path="${local_tmp}/stdout"
+  local stderr_path="${local_tmp}/stderr"
+  local stats_out_path="${local_tmp}/statsfile"
+  local stats_out_decoded_path="${local_tmp}/statsfile.decoded"
+
+  cp "${CPU_TIME_SPENDER}" "${SANDBOX_DIR}"
+  local cpu_time_spender_sandbox_path="${SANDBOX_DIR}/spend_cpu_time"
+
+  # Sandboxed process will be terminated after 100 seconds if not already dead.
+  local code=0
+  "${linux_sandbox}" \
+      -W "${SANDBOX_DIR}" \
+      -T 100 \
+      -t 2 \
+      -l "${stdout_path}" \
+      -L "${stderr_path}" \
+      -S "${stats_out_path}" \
+      -- \
+      "${cpu_time_spender_sandbox_path}" "${user_time_low}" "${sys_time_low}" \
+      &> "${TEST_log}" || code="$?"
+  assert_equals 0 "${code}"
+
+  assert_execution_time_in_range \
+      "${user_time_low}" \
+      "${user_time_high}" \
+      "${sys_time_low}" \
+      "${sys_time_high}" \
+      "${stats_out_path}"
+}
+
+function test_stats_high_user_time() {
+  assert_linux_sandbox_exec_time 10 11 0 1
+}
+
+function test_stats_high_system_time() {
+  assert_linux_sandbox_exec_time 0 1 10 11
+}
+
+function test_stats_high_user_time_and_high_system_time() {
+  assert_linux_sandbox_exec_time 10 11 10 11
+}
+
 # The test shouldn't fail if the environment doesn't support running it.
 check_supported_platform || exit 0
 check_sandbox_allowed || exit 0
diff --git a/src/test/shell/integration/process-wrapper_test.sh b/src/test/shell/integration/process-wrapper_test.sh
index 8ef7e55392..70b5c524c8 100755
--- a/src/test/shell/integration/process-wrapper_test.sh
+++ b/src/test/shell/integration/process-wrapper_test.sh
@@ -20,12 +20,11 @@ set -euo pipefail
 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; }
+source "${CURRENT_DIR}/execution_statistics_utils.sh" \
+  || { echo "execution_statistics_utils.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"
@@ -118,70 +117,48 @@ 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
+function assert_process_wrapper_exec_time() {
+  local user_time_low="$1"; shift
+  local user_time_high="$1"; shift
+  local sys_time_low="$1"; shift
+  local sys_time_high="$1"; shift
 
-  local stats_out_path="${OUT_DIR}/statsfile"
-  local stats_out_decoded_path="${OUT_DIR}/statsfile.decoded"
+  local local_tmp="$(mktemp -d "${OUT_DIR}/assert_process_wrapper_timeXXXXXX")"
+  local stdout_path="${local_tmp}/stdout"
+  local stderr_path="${local_tmp}/stderr"
+  local stats_out_path="${local_tmp}/statsfile"
+  local stats_out_decoded_path="${local_tmp}/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="$?"
+  "${process_wrapper}" \
+      --timeout=100 \
+      --kill_delay=2 \
+      --stdout="${stdout_path}" \
+      --stderr="${stderr_path}" \
+      --stats="${stats_out_path}" \
+      "${CPU_TIME_SPENDER}" "${user_time_low}" "${sys_time_low}" \
+      &> "${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
+  assert_execution_time_in_range \
+      "${user_time_low}" \
+      "${user_time_high}" \
+      "${sys_time_low}" \
+      "${sys_time_high}" \
+      "${stats_out_path}"
 }
 
 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
+  assert_process_wrapper_exec_time 10 11 0 1
 }
 
 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
+  assert_process_wrapper_exec_time 0 1 10 11
 }
 
 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
+  assert_process_wrapper_exec_time 10 11 10 11
 }
 
 run_suite "process-wrapper"