Add a function in ExecUtils to return wall time and CPU time.
Bug: 245380798
Test: m test-art-host-gtest-art_runtime_tests
Ignore-AOSP-First: Will cherry-pick later.
Change-Id: I25d0d4c3dfaf24490c96ca650f076b2214597d2a
diff --git a/libartbase/base/utils.cc b/libartbase/base/utils.cc
index e0c37d8..bff9f45 100644
--- a/libartbase/base/utils.cc
+++ b/libartbase/base/utils.cc
@@ -251,6 +251,9 @@
template void Split(const std::string_view& s,
char separator,
std::vector<std::string_view>* out_result);
+template void Split(const std::string_view& s,
+ char separator,
+ std::vector<std::string>* out_result);
template <typename Str>
void Split(const Str& s, char separator, size_t len, Str* out_result) {
diff --git a/runtime/exec_utils.cc b/runtime/exec_utils.cc
index 722f70a..cc4667c 100644
--- a/runtime/exec_utils.cc
+++ b/runtime/exec_utils.cc
@@ -21,6 +21,9 @@
#include <sys/wait.h>
#include <unistd.h>
+#include <ctime>
+#include <string_view>
+
#ifdef __BIONIC__
#include <sys/pidfd.h>
#endif
@@ -34,17 +37,22 @@
#include <thread>
#include <vector>
+#include "android-base/file.h"
+#include "android-base/parseint.h"
#include "android-base/scopeguard.h"
#include "android-base/stringprintf.h"
#include "android-base/strings.h"
#include "android-base/unique_fd.h"
#include "base/macros.h"
+#include "base/utils.h"
#include "runtime.h"
namespace art {
namespace {
+using ::android::base::ParseInt;
+using ::android::base::ReadFileToString;
using ::android::base::StringPrintf;
using ::android::base::unique_fd;
@@ -102,14 +110,14 @@
// WNOWAIT leaves the child in a waitable state. The call is still blocking.
int options = WEXITED | (no_wait ? WNOWAIT : 0);
if (TEMP_FAILURE_RETRY(waitid(P_PID, pid, &info, options)) != 0) {
- *error_msg = StringPrintf("Failed to execute (%s) because waitid failed for pid %d: %s",
+ *error_msg = StringPrintf("waitid failed for (%s) pid %d: %s",
ToCommandLine(arg_vector).c_str(),
pid,
strerror(errno));
return -1;
}
if (info.si_pid != pid) {
- *error_msg = StringPrintf("Failed to execute (%s) because waitid failed: wanted %d, got %d: %s",
+ *error_msg = StringPrintf("waitid failed for (%s): wanted pid %d, got %d: %s",
ToCommandLine(arg_vector).c_str(),
pid,
info.si_pid,
@@ -126,10 +134,6 @@
return info.si_status;
}
-int WaitChild(pid_t pid, const std::vector<std::string>& arg_vector, std::string* error_msg) {
- return WaitChild(pid, arg_vector, /*no_wait=*/false, error_msg);
-}
-
// A fallback implementation of `WaitChildWithTimeout` that creates a thread to wait instead of
// relying on `pidfd_open`.
int WaitChildWithTimeoutFallback(pid_t pid,
@@ -145,16 +149,11 @@
std::unique_lock<std::mutex> lock(m);
if (!cv.wait_for(lock, std::chrono::milliseconds(timeout_ms), [&] { return child_exited; })) {
*timed_out = true;
- *error_msg =
- StringPrintf("Child process %d timed out after %dms. Killing it", pid, timeout_ms);
kill(pid, SIGKILL);
}
});
- // Leave the child in a waitable state just in case `wait_thread` sends a `SIGKILL` after the
- // child exits.
- std::string ignored_error_msg;
- WaitChild(pid, arg_vector, /*no_wait=*/true, &ignored_error_msg);
+ int status = WaitChild(pid, arg_vector, /*no_wait=*/true, error_msg);
{
std::unique_lock<std::mutex> lock(m);
@@ -163,13 +162,19 @@
cv.notify_all();
wait_thread.join();
+ // The timeout error should have a higher priority than any other error.
if (*timed_out) {
- WaitChild(pid, arg_vector, &ignored_error_msg);
+ *error_msg =
+ StringPrintf("Failed to execute (%s) because the child process timed out after %dms",
+ ToCommandLine(arg_vector).c_str(),
+ timeout_ms);
return -1;
}
- return WaitChild(pid, arg_vector, error_msg);
+
+ return status;
}
+// Waits for the child process to finish and leaves the child in a waitable state.
int WaitChildWithTimeout(pid_t pid,
unique_fd pidfd,
const std::vector<std::string>& arg_vector,
@@ -179,7 +184,7 @@
auto cleanup = android::base::make_scope_guard([&]() {
kill(pid, SIGKILL);
std::string ignored_error_msg;
- WaitChild(pid, arg_vector, &ignored_error_msg);
+ WaitChild(pid, arg_vector, /*no_wait=*/true, &ignored_error_msg);
});
struct pollfd pfd;
@@ -195,12 +200,42 @@
}
if (poll_ret == 0) {
*timed_out = true;
- *error_msg = StringPrintf("Child process %d timed out after %dms. Killing it", pid, timeout_ms);
+ *error_msg =
+ StringPrintf("Failed to execute (%s) because the child process timed out after %dms",
+ ToCommandLine(arg_vector).c_str(),
+ timeout_ms);
return -1;
}
cleanup.Disable();
- return WaitChild(pid, arg_vector, error_msg);
+ return WaitChild(pid, arg_vector, /*no_wait=*/true, error_msg);
+}
+
+bool ParseProcStat(const std::string& stat_content,
+ int64_t uptime_ms,
+ int64_t ticks_per_sec,
+ /*out*/ ProcessStat* stat) {
+ size_t pos = stat_content.rfind(") ");
+ if (pos == std::string::npos) {
+ return false;
+ }
+ std::vector<std::string> stat_fields;
+ // Skip the first two fields. The second field is the parenthesized process filename, which can
+ // contain anything, including spaces.
+ Split(std::string_view(stat_content).substr(pos + 2), ' ', &stat_fields);
+ constexpr int kSkippedFields = 2;
+ int64_t utime, stime, cutime, cstime, starttime;
+ if (stat_fields.size() < 22 - kSkippedFields ||
+ !ParseInt(stat_fields[13 - kSkippedFields], &utime) ||
+ !ParseInt(stat_fields[14 - kSkippedFields], &stime) ||
+ !ParseInt(stat_fields[15 - kSkippedFields], &cutime) ||
+ !ParseInt(stat_fields[16 - kSkippedFields], &cstime) ||
+ !ParseInt(stat_fields[21 - kSkippedFields], &starttime)) {
+ return false;
+ }
+ stat->cpu_time_ms = (utime + stime + cutime + cstime) * 1000 / ticks_per_sec;
+ stat->wall_time_ms = uptime_ms - starttime * 1000 / ticks_per_sec;
+ return true;
}
} // namespace
@@ -215,6 +250,14 @@
int timeout_sec,
bool* timed_out,
std::string* error_msg) const {
+ return ExecAndReturnCode(arg_vector, timeout_sec, timed_out, /*stat=*/nullptr, error_msg);
+}
+
+int ExecUtils::ExecAndReturnCode(const std::vector<std::string>& arg_vector,
+ int timeout_sec,
+ /*out*/ bool* timed_out,
+ /*out*/ ProcessStat* stat,
+ /*out*/ std::string* error_msg) const {
*timed_out = false;
if (timeout_sec > INT_MAX / 1000) {
@@ -229,20 +272,37 @@
}
// Wait for subprocess to finish.
+ int status;
if (timeout_sec >= 0) {
unique_fd pidfd = PidfdOpen(pid);
if (pidfd.get() >= 0) {
- return WaitChildWithTimeout(
+ status = WaitChildWithTimeout(
pid, std::move(pidfd), arg_vector, timeout_sec * 1000, timed_out, error_msg);
} else {
LOG(DEBUG) << StringPrintf(
"pidfd_open failed for pid %d: %s, falling back", pid, strerror(errno));
- return WaitChildWithTimeoutFallback(
- pid, arg_vector, timeout_sec * 1000, timed_out, error_msg);
+ status =
+ WaitChildWithTimeoutFallback(pid, arg_vector, timeout_sec * 1000, timed_out, error_msg);
}
} else {
- return WaitChild(pid, arg_vector, error_msg);
+ status = WaitChild(pid, arg_vector, /*no_wait=*/true, error_msg);
}
+
+ if (stat != nullptr) {
+ std::string local_error_msg;
+ if (!GetStat(pid, stat, &local_error_msg)) {
+ LOG(ERROR) << "Failed to get process stat: " << local_error_msg;
+ }
+ }
+
+ std::string local_error_msg;
+ // TODO(jiakaiz): Use better logic to detect waitid failure.
+ if (WaitChild(pid, arg_vector, /*no_wait=*/false, &local_error_msg) < 0 &&
+ local_error_msg.find("waitid failed") == 0) {
+ LOG(ERROR) << "Failed to clean up child process '" << arg_vector[0] << "': " << local_error_msg;
+ }
+
+ return status;
}
bool ExecUtils::Exec(const std::vector<std::string>& arg_vector, std::string* error_msg) const {
@@ -272,4 +332,37 @@
#endif
}
+std::string ExecUtils::GetProcStat(pid_t pid) const {
+ std::string stat_content;
+ if (!ReadFileToString(StringPrintf("/proc/%d/stat", pid), &stat_content)) {
+ stat_content = "";
+ }
+ return stat_content;
+}
+
+int64_t ExecUtils::GetUptimeMs() const {
+ timespec t;
+ clock_gettime(CLOCK_MONOTONIC, &t);
+ return t.tv_sec * 1000 + t.tv_nsec / 1000000;
+}
+
+int64_t ExecUtils::GetTicksPerSec() const { return sysconf(_SC_CLK_TCK); }
+
+bool ExecUtils::GetStat(pid_t pid,
+ /*out*/ ProcessStat* stat,
+ /*out*/ std::string* error_msg) const {
+ int64_t uptime_ms = GetUptimeMs();
+ std::string stat_content = GetProcStat(pid);
+ if (stat_content.empty()) {
+ *error_msg = StringPrintf("Failed to read /proc/%d/stat: %s", pid, strerror(errno));
+ return false;
+ }
+ int64_t ticks_per_sec = GetTicksPerSec();
+ if (!ParseProcStat(stat_content, uptime_ms, ticks_per_sec, stat)) {
+ *error_msg = StringPrintf("Failed to parse /proc/%d/stat '%s'", pid, stat_content.c_str());
+ return false;
+ }
+ return true;
+}
+
} // namespace art
diff --git a/runtime/exec_utils.h b/runtime/exec_utils.h
index 79a12d7..751c64d 100644
--- a/runtime/exec_utils.h
+++ b/runtime/exec_utils.h
@@ -26,6 +26,14 @@
namespace art {
+struct ProcessStat {
+ // The total wall time, in milliseconds, that the process spent, or 0 if failed to get the value.
+ int wall_time_ms = 0;
+ // The total CPU time, in milliseconds, that the process and any waited-for children spent, or 0
+ // if failed to get the value.
+ int cpu_time_ms = 0;
+};
+
// Wrapper on fork/execv to run a command in a subprocess.
// These spawn child processes using the environment as it was set when the single instance
// of the runtime (Runtime::Current()) was started. If no instance of the runtime was started, it
@@ -49,8 +57,26 @@
/*out*/ bool* timed_out,
/*out*/ std::string* error_msg) const;
+ // Same as above, but also collects stat of the process. The stat is collected no matter the child
+ // process succeeds or not.
+ virtual int ExecAndReturnCode(const std::vector<std::string>& arg_vector,
+ int timeout_sec,
+ /*out*/ bool* timed_out,
+ /*out*/ ProcessStat* stat,
+ /*out*/ std::string* error_msg) const;
+
protected:
virtual android::base::unique_fd PidfdOpen(pid_t pid) const;
+
+ // Returns the content of `/proc/<pid>/stat`, or an empty string if failed.
+ virtual std::string GetProcStat(pid_t pid) const;
+
+ virtual int64_t GetUptimeMs() const;
+
+ virtual int64_t GetTicksPerSec() const;
+
+ private:
+ bool GetStat(pid_t pid, /*out*/ ProcessStat* stat, /*out*/ std::string* error_msg) const;
};
inline bool Exec(const std::vector<std::string>& arg_vector, /*out*/ std::string* error_msg) {
diff --git a/runtime/exec_utils_test.cc b/runtime/exec_utils_test.cc
index c10b84e..c09bf40 100644
--- a/runtime/exec_utils_test.cc
+++ b/runtime/exec_utils_test.cc
@@ -28,10 +28,15 @@
#include "base/file_utils.h"
#include "base/memory_tool.h"
#include "common_runtime_test.h"
+#include "gmock/gmock.h"
#include "gtest/gtest.h"
namespace art {
+using ::testing::_;
+using ::testing::HasSubstr;
+using ::testing::Return;
+
std::string PrettyArguments(const char* signature);
std::string PrettyReturnType(const char* signature);
@@ -54,12 +59,19 @@
return version;
}
-class AlwaysFallbackExecUtils : public ExecUtils {
+class TestingExecUtils : public ExecUtils {
+ public:
+ MOCK_METHOD(std::string, GetProcStat, (pid_t pid), (const, override));
+ MOCK_METHOD(int64_t, GetUptimeMs, (), (const, override));
+ MOCK_METHOD(int64_t, GetTicksPerSec, (), (const, override));
+};
+
+class AlwaysFallbackExecUtils : public TestingExecUtils {
protected:
android::base::unique_fd PidfdOpen(pid_t) const override { return android::base::unique_fd(-1); }
};
-class NeverFallbackExecUtils : public ExecUtils {
+class NeverFallbackExecUtils : public TestingExecUtils {
protected:
android::base::unique_fd PidfdOpen(pid_t pid) const override {
android::base::unique_fd pidfd = ExecUtils::PidfdOpen(pid);
@@ -84,7 +96,7 @@
}
}
- std::unique_ptr<ExecUtils> exec_utils_;
+ std::unique_ptr<TestingExecUtils> exec_utils_;
};
TEST_P(ExecUtilsTest, ExecSuccess) {
@@ -159,6 +171,7 @@
bool timed_out;
ASSERT_EQ(exec_utils_->ExecAndReturnCode(command, kWaitSeconds, &timed_out, &error_msg), -1);
EXPECT_TRUE(timed_out) << error_msg;
+ EXPECT_THAT(error_msg, HasSubstr("timed out"));
}
TEST_P(ExecUtilsTest, ExecNoTimeout) {
@@ -172,6 +185,51 @@
EXPECT_FALSE(timed_out);
}
+TEST_P(ExecUtilsTest, ExecStat) {
+ std::vector<std::string> command;
+ command.push_back(GetBin("id"));
+
+ std::string error_msg;
+ bool timed_out;
+ ProcessStat stat;
+
+ // The process filename is "a) b".
+ EXPECT_CALL(*exec_utils_, GetProcStat(_))
+ .WillOnce(Return(
+ "14963 (a) b) Z 6067 14963 1 0 -1 4228108 105 0 0 0 94 5 0 0 39 19 1 0 162034388 0 0 "
+ "18446744073709551615 0 0 0 0 0 0 20999 0 0 1 0 0 17 71 0 0 0 0 0 0 0 0 0 0 0 0 9"));
+ EXPECT_CALL(*exec_utils_, GetUptimeMs()).WillOnce(Return(1620344887ll));
+ EXPECT_CALL(*exec_utils_, GetTicksPerSec()).WillOnce(Return(100));
+
+ ASSERT_EQ(
+ exec_utils_->ExecAndReturnCode(command, /*timeout_sec=*/-1, &timed_out, &stat, &error_msg), 0)
+ << error_msg;
+
+ EXPECT_EQ(stat.cpu_time_ms, 990);
+ EXPECT_EQ(stat.wall_time_ms, 1007);
+}
+
+TEST_P(ExecUtilsTest, ExecStatFailed) {
+ std::vector<std::string> command = SleepCommand(5);
+
+ std::string error_msg;
+ bool timed_out;
+ ProcessStat stat;
+
+ EXPECT_CALL(*exec_utils_, GetProcStat(_))
+ .WillOnce(Return(
+ "14963 (a) b) Z 6067 14963 1 0 -1 4228108 105 0 0 0 94 5 0 0 39 19 1 0 162034388 0 0 "
+ "18446744073709551615 0 0 0 0 0 0 20999 0 0 1 0 0 17 71 0 0 0 0 0 0 0 0 0 0 0 0 9"));
+ EXPECT_CALL(*exec_utils_, GetUptimeMs()).WillOnce(Return(1620344887ll));
+ EXPECT_CALL(*exec_utils_, GetTicksPerSec()).WillOnce(Return(100));
+
+ // This will always time out.
+ exec_utils_->ExecAndReturnCode(command, /*timeout_sec=*/1, &timed_out, &stat, &error_msg);
+
+ EXPECT_EQ(stat.cpu_time_ms, 990);
+ EXPECT_EQ(stat.wall_time_ms, 1007);
+}
+
INSTANTIATE_TEST_SUITE_P(AlwaysOrNeverFallback, ExecUtilsTest, testing::Values(true, false));
} // namespace art