Fix big negative dex2oatWallTimeMillis.

We calculate dex2oatWallTimeMillis by (uptime - starttime). To get a
reasonable result, both times need to be from the same clock. However,
it's unclear which clock the kernel uses for the latter.

proc_pid_stat(5) does not have anything helpful on this matter:

    (22) starttime  %llu
        The time the process started after system boot.
        Before Linux 2.6, this value was expressed in
        jiffies.  Since Linux 2.6, the value is expressed
        in clock ticks (divide by sysconf(_SC_CLK_TCK)).

        The format for this field was %lu before Linux 2.6.

To make sure we use the same clock, we obtain the uptime on process
start as the start time.

Bug: 315061143
Test: Presubmit
Change-Id: I5f344e953a945656474b3f625368c1ccb5aa52d8

3 files changed, 26 insertions, 28 deletions

diff --git a/runtime/exec_utils.cc b/runtime/exec_utils.cc
index 05a7cc6bdc..927cc38df9 100644
--- a/runtime/exec_utils.cc
+++ b/runtime/exec_utils.cc
@@ -212,9 +212,8 @@ ExecResult WaitChildWithTimeout(pid_t pid,
 }
 
 bool ParseProcStat(const std::string& stat_content,
-                   int64_t uptime_ms,
                    int64_t ticks_per_sec,
-                   /*out*/ ProcessStat* stat) {
+                   /*out*/ int64_t* cpu_time_ms) {
   size_t pos = stat_content.rfind(") ");
   if (pos == std::string::npos) {
     return false;
@@ -224,22 +223,15 @@ bool ParseProcStat(const std::string& stat_content,
   // 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;
+  int64_t utime, stime, cutime, cstime;
   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)) {
+      !ParseInt(stat_fields[16 - kSkippedFields], &cstime)) {
     return false;
   }
-  if (starttime == 0) {
-    // The start time is the time the process started after system boot, so it's not supposed to be
-    // zero unless the process is `init`.
-    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;
+  *cpu_time_ms = (utime + stime + cutime + cstime) * 1000 / ticks_per_sec;
   return true;
 }
 
@@ -278,6 +270,8 @@ ExecResult ExecUtils::ExecAndReturnResult(const std::vector<std::string>& arg_ve
     return {.status = ExecResult::kStartFailed};
   }
 
+  std::string stat_error_msg;
+  std::optional<int64_t> start_time = GetUptimeMs(&stat_error_msg);
   callbacks.on_start(pid);
 
   // Wait for subprocess to finish.
@@ -297,9 +291,8 @@ ExecResult ExecUtils::ExecAndReturnResult(const std::vector<std::string>& arg_ve
   }
 
   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;
+    if (!start_time.has_value() || !GetStat(pid, start_time.value(), stat, &stat_error_msg)) {
+      LOG(ERROR) << "Failed to get process stat: " << stat_error_msg;
     }
   }
 
@@ -352,6 +345,7 @@ std::optional<int64_t> ExecUtils::GetUptimeMs(std::string* error_msg) const {
 int64_t ExecUtils::GetTicksPerSec() const { return sysconf(_SC_CLK_TCK); }
 
 bool ExecUtils::GetStat(pid_t pid,
+                        int64_t start_time,
                         /*out*/ ProcessStat* stat,
                         /*out*/ std::string* error_msg) const {
   std::optional<int64_t> uptime_ms = GetUptimeMs(error_msg);
@@ -364,10 +358,11 @@ bool ExecUtils::GetStat(pid_t pid,
     return false;
   }
   int64_t ticks_per_sec = GetTicksPerSec();
-  if (!ParseProcStat(stat_content, *uptime_ms, ticks_per_sec, stat)) {
+  if (!ParseProcStat(stat_content, ticks_per_sec, &stat->cpu_time_ms)) {
     *error_msg = StringPrintf("Failed to parse /proc/%d/stat '%s'", pid, stat_content.c_str());
     return false;
   }
+  stat->wall_time_ms = uptime_ms.value() - start_time;
   return true;
 }
 
diff --git a/runtime/exec_utils.h b/runtime/exec_utils.h
index ebcc2e4e66..61e9beae32 100644
--- a/runtime/exec_utils.h
+++ b/runtime/exec_utils.h
@@ -118,7 +118,10 @@ class EXPORT ExecUtils {
   virtual int64_t GetTicksPerSec() const;
 
  private:
-  bool GetStat(pid_t pid, /*out*/ ProcessStat* stat, /*out*/ std::string* error_msg) const;
+  bool GetStat(pid_t pid,
+               int64_t start_time,
+               /*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 e1fc6272d5..eb21652c19 100644
--- a/runtime/exec_utils_test.cc
+++ b/runtime/exec_utils_test.cc
@@ -218,9 +218,11 @@ TEST_P(ExecUtilsTest, ExecStat) {
   // 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 "
+          "14963 (a) b) Z 6067 14963 1 0 -1 4228108 105 0 0 0 94 5 0 0 39 19 1 0 0 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_, DoGetUptimeMs()).WillOnce(Return(1620344887ll));
+  EXPECT_CALL(*exec_utils_, DoGetUptimeMs())
+      .WillOnce(Return(1620343880ll))
+      .WillOnce(Return(1620344887ll));
   EXPECT_CALL(*exec_utils_, GetTicksPerSec()).WillOnce(Return(100));
 
   ASSERT_EQ(exec_utils_
@@ -245,13 +247,8 @@ TEST_P(ExecUtilsTest, ExecStatNoStartTime) {
   std::string error_msg;
   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 0 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_, DoGetUptimeMs()).WillOnce(Return(1620344887ll));
-  EXPECT_CALL(*exec_utils_, GetTicksPerSec()).WillOnce(Return(100));
+  EXPECT_CALL(*exec_utils_, DoGetUptimeMs())
+      .WillOnce(Return(Result<int64_t>(Errorf("Failed to get uptime"))));
 
   ASSERT_EQ(exec_utils_
                 ->ExecAndReturnResult(command,
@@ -276,6 +273,7 @@ TEST_P(ExecUtilsTest, ExecStatNoUptime) {
   ProcessStat stat;
 
   EXPECT_CALL(*exec_utils_, DoGetUptimeMs())
+      .WillOnce(Return(162034388ll))
       .WillOnce(Return(Result<int64_t>(Errorf("Failed to get uptime"))));
 
   ASSERT_EQ(exec_utils_
@@ -301,9 +299,11 @@ TEST_P(ExecUtilsTest, ExecStatFailed) {
 
   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 "
+          "14963 (a) b) Z 6067 14963 1 0 -1 4228108 105 0 0 0 94 5 0 0 39 19 1 0 0 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_, DoGetUptimeMs()).WillOnce(Return(1620344887ll));
+  EXPECT_CALL(*exec_utils_, DoGetUptimeMs())
+      .WillOnce(Return(1620343880ll))
+      .WillOnce(Return(1620344887ll));
   EXPECT_CALL(*exec_utils_, GetTicksPerSec()).WillOnce(Return(100));
 
   // This will always time out.