Support dumpsys timeouts in milliseconds

- add new dumpsys argument to specify timeouts in milliseconds
- use milliseconds to define timeouts in dumpstate
- minor dumpsys output format changes:
    "SERVICE '<service_name>' DUMP TIMEOUT (1s) EXPIRED" ->
    "SERVICE '<service_name>' DUMP TIMEOUT (1000ms) EXPIRED"

Bug: 27429130
Test: mmm -j32 frameworks/native/cmds/dumpsys && \
      mmm -j32 frameworks/native/cmds/dumpstate && \
      adb sync data && adb shell /data/nativetest/dumpsys_test/dumpsys_test && \
      adb shell /data/nativetest64/dumpsys_test/dumpsys_test && \
      adb shell /data/nativetest/dumpstate_test/dumpstate_test && \
      adb shell /data/nativetest64/dumpstate_test/dumpstate_test && \
      printf "\n\n#### ALL TESTS PASSED ####\n"

    Change-Id: Ibc96ad030bb2c6d880b8201c9b6241fce20b284f

Change-Id: I6ef2ff19787f2b6d940d56e453a1a7462a8c854a

8 files changed, 119 insertions, 59 deletions

diff --git a/cmds/dumpstate/DumpstateUtil.cpp b/cmds/dumpstate/DumpstateUtil.cpp
index ede4254a9b..85eb464104 100644
--- a/cmds/dumpstate/DumpstateUtil.cpp
+++ b/cmds/dumpstate/DumpstateUtil.cpp
@@ -43,7 +43,7 @@ namespace {
 
 static constexpr const char* kSuPath = "/system/xbin/su";
 
-static bool waitpid_with_timeout(pid_t pid, int timeout_seconds, int* status) {
+static bool waitpid_with_timeout(pid_t pid, int timeout_ms, int* status) {
     sigset_t child_mask, old_mask;
     sigemptyset(&child_mask);
     sigaddset(&child_mask, SIGCHLD);
@@ -54,10 +54,11 @@ static bool waitpid_with_timeout(pid_t pid, int timeout_seconds, int* status) {
     }
 
     timespec ts;
-    ts.tv_sec = timeout_seconds;
-    ts.tv_nsec = 0;
+    ts.tv_sec = MSEC_TO_SEC(timeout_ms);
+    ts.tv_nsec = (timeout_ms % 1000) * 1000000;
     int ret = TEMP_FAILURE_RETRY(sigtimedwait(&child_mask, NULL, &ts));
     int saved_errno = errno;
+
     // Set the signals back the way they were.
     if (sigprocmask(SIG_SETMASK, &old_mask, NULL) == -1) {
         printf("*** sigprocmask failed: %s\n", strerror(errno));
@@ -91,7 +92,7 @@ static bool waitpid_with_timeout(pid_t pid, int timeout_seconds, int* status) {
 CommandOptions CommandOptions::DEFAULT = CommandOptions::WithTimeout(10).Build();
 CommandOptions CommandOptions::AS_ROOT = CommandOptions::WithTimeout(10).AsRoot().Build();
 
-CommandOptions::CommandOptionsBuilder::CommandOptionsBuilder(int64_t timeout) : values(timeout) {
+CommandOptions::CommandOptionsBuilder::CommandOptionsBuilder(int64_t timeout_ms) : values(timeout_ms) {
 }
 
 CommandOptions::CommandOptionsBuilder& CommandOptions::CommandOptionsBuilder::Always() {
@@ -130,8 +131,8 @@ CommandOptions CommandOptions::CommandOptionsBuilder::Build() {
     return CommandOptions(values);
 }
 
-CommandOptions::CommandOptionsValues::CommandOptionsValues(int64_t timeout)
-    : timeout_(timeout),
+CommandOptions::CommandOptionsValues::CommandOptionsValues(int64_t timeout_ms)
+    : timeout_ms_(timeout_ms),
       always_(false),
       account_mode_(DONT_DROP_ROOT),
       output_mode_(NORMAL_OUTPUT),
@@ -142,7 +143,11 @@ CommandOptions::CommandOptions(const CommandOptionsValues& values) : values(valu
 }
 
 int64_t CommandOptions::Timeout() const {
-    return values.timeout_;
+    return MSEC_TO_SEC(values.timeout_ms_);
+}
+
+int64_t CommandOptions::TimeoutInMs() const {
+    return values.timeout_ms_;
 }
 
 bool CommandOptions::Always() const {
@@ -161,8 +166,12 @@ std::string CommandOptions::LoggingMessage() const {
     return values.logging_message_;
 }
 
-CommandOptions::CommandOptionsBuilder CommandOptions::WithTimeout(int64_t timeout) {
-    return CommandOptions::CommandOptionsBuilder(timeout);
+CommandOptions::CommandOptionsBuilder CommandOptions::WithTimeout(int64_t timeout_sec) {
+    return CommandOptions::CommandOptionsBuilder(SEC_TO_MSEC(timeout_sec));
+}
+
+CommandOptions::CommandOptionsBuilder CommandOptions::WithTimeoutInMs(int64_t timeout_ms) {
+    return CommandOptions::CommandOptionsBuilder(timeout_ms);
 }
 
 std::string PropertiesHelper::build_type_ = "";
@@ -314,7 +323,7 @@ int RunCommandToFd(int fd, const std::string& title, const std::vector<std::stri
 
     /* handle parent case */
     int status;
-    bool ret = waitpid_with_timeout(pid, options.Timeout(), &status);
+    bool ret = waitpid_with_timeout(pid, options.TimeoutInMs(), &status);
     fsync(fd);
 
     uint64_t elapsed = Nanotime() - start;
@@ -333,9 +342,9 @@ int RunCommandToFd(int fd, const std::string& title, const std::vector<std::stri
                    static_cast<float>(elapsed) / NANOS_PER_SEC, pid);
         }
         kill(pid, SIGTERM);
-        if (!waitpid_with_timeout(pid, 5, nullptr)) {
+        if (!waitpid_with_timeout(pid, 5000, nullptr)) {
             kill(pid, SIGKILL);
-            if (!waitpid_with_timeout(pid, 5, nullptr)) {
+            if (!waitpid_with_timeout(pid, 5000, nullptr)) {
                 if (!silent)
                     dprintf(fd, "could not kill command '%s' (pid %d) even with SIGKILL.\n",
                             command, pid);
diff --git a/cmds/dumpstate/DumpstateUtil.h b/cmds/dumpstate/DumpstateUtil.h
index 698ceffcc4..8342099821 100644
--- a/cmds/dumpstate/DumpstateUtil.h
+++ b/cmds/dumpstate/DumpstateUtil.h
@@ -19,6 +19,16 @@
 #include <cstdint>
 #include <string>
 
+/*
+ * Converts seconds to milliseconds.
+ */
+#define SEC_TO_MSEC(second) (second * 1000)
+
+/*
+ * Converts milliseconds to seconds.
+ */
+#define MSEC_TO_SEC(millisecond) (millisecond / 1000)
+
 namespace android {
 namespace os {
 namespace dumpstate {
@@ -66,9 +76,9 @@ class CommandOptions {
   private:
     class CommandOptionsValues {
       private:
-        CommandOptionsValues(int64_t timeout);
+        CommandOptionsValues(int64_t timeout_ms);
 
-        int64_t timeout_;
+        int64_t timeout_ms_;
         bool always_;
         PrivilegeMode account_mode_;
         OutputMode output_mode_;
@@ -102,13 +112,15 @@ class CommandOptions {
         CommandOptions Build();
 
       private:
-        CommandOptionsBuilder(int64_t timeout);
+        CommandOptionsBuilder(int64_t timeout_ms);
         CommandOptionsValues values;
         friend class CommandOptions;
     };
 
-    /** Gets the command timeout, in seconds. */
+    /** Gets the command timeout in seconds. */
     int64_t Timeout() const;
+    /** Gets the command timeout in milliseconds. */
+    int64_t TimeoutInMs() const;
     /* Checks whether the command should always be run, even on dry-run mode. */
     bool Always() const;
     /** Gets the PrivilegeMode of the command. */
@@ -118,8 +130,11 @@ class CommandOptions {
     /** Gets the logging message header, it any. */
     std::string LoggingMessage() const;
 
-    /** Creates a builder with the requied timeout. */
-    static CommandOptionsBuilder WithTimeout(int64_t timeout);
+    /** Creates a builder with the requied timeout in seconds. */
+    static CommandOptionsBuilder WithTimeout(int64_t timeout_sec);
+
+    /** Creates a builder with the requied timeout in milliseconds. */
+    static CommandOptionsBuilder WithTimeoutInMs(int64_t timeout_ms);
 
     // Common options.
     static CommandOptions DEFAULT;
diff --git a/cmds/dumpstate/dumpstate.cpp b/cmds/dumpstate/dumpstate.cpp
index 364ead0d18..aba08d9de9 100644
--- a/cmds/dumpstate/dumpstate.cpp
+++ b/cmds/dumpstate/dumpstate.cpp
@@ -113,8 +113,8 @@ static int RunCommand(const std::string& title, const std::vector<std::string>&
 }
 static void RunDumpsys(const std::string& title, const std::vector<std::string>& dumpsysArgs,
                        const CommandOptions& options = Dumpstate::DEFAULT_DUMPSYS,
-                       long dumpsysTimeout = 0) {
-    return ds.RunDumpsys(title, dumpsysArgs, options, dumpsysTimeout);
+                       long dumpsysTimeoutMs = 0) {
+    return ds.RunDumpsys(title, dumpsysArgs, options, dumpsysTimeoutMs);
 }
 static int DumpFile(const std::string& title, const std::string& path) {
     return ds.DumpFile(title, path);
@@ -830,33 +830,32 @@ static void DoKmsg() {
 }
 
 static void DoLogcat() {
-    unsigned long timeout;
+    unsigned long timeout_ms;
     // DumpFile("EVENT LOG TAGS", "/etc/event-log-tags");
     // calculate timeout
-    timeout = logcat_timeout("main") + logcat_timeout("system") + logcat_timeout("crash");
-    if (timeout < 20000) {
-        timeout = 20000;
+    timeout_ms = logcat_timeout("main") + logcat_timeout("system") + logcat_timeout("crash");
+    if (timeout_ms < 20000) {
+        timeout_ms = 20000;
     }
     RunCommand("SYSTEM LOG",
-               {"logcat", "-v", "threadtime", "-v", "printable", "-v", "uid",
-                        "-d", "*:v"},
-               CommandOptions::WithTimeout(timeout / 1000).Build());
-    timeout = logcat_timeout("events");
-    if (timeout < 20000) {
-        timeout = 20000;
+               {"logcat", "-v", "threadtime", "-v", "printable", "-v", "uid", "-d", "*:v"},
+               CommandOptions::WithTimeoutInMs(timeout_ms).Build());
+    timeout_ms = logcat_timeout("events");
+    if (timeout_ms < 20000) {
+        timeout_ms = 20000;
     }
     RunCommand("EVENT LOG",
                {"logcat", "-b", "events", "-v", "threadtime", "-v", "printable", "-v", "uid",
                         "-d", "*:v"},
-               CommandOptions::WithTimeout(timeout / 1000).Build());
-    timeout = logcat_timeout("radio");
-    if (timeout < 20000) {
-        timeout = 20000;
+               CommandOptions::WithTimeoutInMs(timeout_ms).Build());
+    timeout_ms = logcat_timeout("radio");
+    if (timeout_ms < 20000) {
+        timeout_ms = 20000;
     }
     RunCommand("RADIO LOG",
                {"logcat", "-b", "radio", "-v", "threadtime", "-v", "printable", "-v", "uid",
                         "-d", "*:v"},
-               CommandOptions::WithTimeout(timeout / 1000).Build());
+               CommandOptions::WithTimeoutInMs(timeout_ms).Build());
 
     RunCommand("LOG STATISTICS", {"logcat", "-b", "all", "-S"});
 
diff --git a/cmds/dumpstate/dumpstate.h b/cmds/dumpstate/dumpstate.h
index 1bfafbaffe..8db23a94f4 100644
--- a/cmds/dumpstate/dumpstate.h
+++ b/cmds/dumpstate/dumpstate.h
@@ -196,19 +196,19 @@ class Dumpstate {
 
     /*
      * Runs `dumpsys` with the given arguments, automatically setting its timeout
-     * (`-t` argument)
+     * (`-T` argument)
      * according to the command options.
      *
      * |title| description of the command printed on `stdout` (or empty to skip
      * description).
      * |dumpsys_args| `dumpsys` arguments (except `-t`).
      * |options| optional argument defining the command's behavior.
-     * |dumpsys_timeout| when > 0, defines the value passed to `dumpsys -t` (otherwise it uses the
+     * |dumpsys_timeout| when > 0, defines the value passed to `dumpsys -T` (otherwise it uses the
      * timeout from `options`)
      */
     void RunDumpsys(const std::string& title, const std::vector<std::string>& dumpsys_args,
                     const android::os::dumpstate::CommandOptions& options = DEFAULT_DUMPSYS,
-                    long dumpsys_timeout = 0);
+                    long dumpsys_timeout_ms = 0);
 
     /*
      * Prints the contents of a file.
diff --git a/cmds/dumpstate/tests/dumpstate_test.cpp b/cmds/dumpstate/tests/dumpstate_test.cpp
index 92b0c0d8bc..a2e94538c2 100644
--- a/cmds/dumpstate/tests/dumpstate_test.cpp
+++ b/cmds/dumpstate/tests/dumpstate_test.cpp
@@ -1001,7 +1001,7 @@ TEST_F(DumpstateUtilTest, RunCommandCrashes) {
         err, StartsWith("stderr\n*** command '" + kSimpleCommand + " --crash' failed: exit code"));
 }
 
-TEST_F(DumpstateUtilTest, RunCommandTimesout) {
+TEST_F(DumpstateUtilTest, RunCommandTimesoutWithSec) {
     CreateFd("RunCommandTimesout.txt");
     EXPECT_EQ(-1, RunCommand("", {kSimpleCommand, "--sleep", "2"},
                              CommandOptions::WithTimeout(1).Build()));
@@ -1011,6 +1011,17 @@ TEST_F(DumpstateUtilTest, RunCommandTimesout) {
                                 " --sleep 2' timed out after 1"));
 }
 
+TEST_F(DumpstateUtilTest, RunCommandTimesoutWithMsec) {
+    CreateFd("RunCommandTimesout.txt");
+    EXPECT_EQ(-1, RunCommand("", {kSimpleCommand, "--sleep", "2"},
+                             CommandOptions::WithTimeoutInMs(1000).Build()));
+    EXPECT_THAT(out, StartsWith("stdout line1\n*** command '" + kSimpleCommand +
+                                " --sleep 2' timed out after 1"));
+    EXPECT_THAT(err, StartsWith("sleeping for 2s\n*** command '" + kSimpleCommand +
+                                " --sleep 2' timed out after 1"));
+}
+
+
 TEST_F(DumpstateUtilTest, RunCommandIsKilled) {
     CreateFd("RunCommandIsKilled.txt");
     CaptureStderr();
diff --git a/cmds/dumpstate/utils.cpp b/cmds/dumpstate/utils.cpp
index 6ff0dae01c..ac48041f6d 100644
--- a/cmds/dumpstate/utils.cpp
+++ b/cmds/dumpstate/utils.cpp
@@ -215,10 +215,10 @@ int32_t Progress::Get() const {
     return progress_;
 }
 
-bool Progress::Inc(int32_t delta) {
+bool Progress::Inc(int32_t delta_sec) {
     bool changed = false;
-    if (delta >= 0) {
-        progress_ += delta;
+    if (delta_sec >= 0) {
+        progress_ += delta_sec;
         if (progress_ > max_) {
             int32_t old_max = max_;
             max_ = floor((float)progress_ * growth_factor_);
@@ -723,9 +723,9 @@ int Dumpstate::RunCommand(const std::string& title, const std::vector<std::strin
 }
 
 void Dumpstate::RunDumpsys(const std::string& title, const std::vector<std::string>& dumpsys_args,
-                           const CommandOptions& options, long dumpsysTimeout) {
-    long timeout = dumpsysTimeout > 0 ? dumpsysTimeout : options.Timeout();
-    std::vector<std::string> dumpsys = {"/system/bin/dumpsys", "-t", std::to_string(timeout)};
+                           const CommandOptions& options, long dumpsysTimeoutMs) {
+    long timeout_ms = dumpsysTimeoutMs > 0 ? dumpsysTimeoutMs : options.TimeoutInMs();
+    std::vector<std::string> dumpsys = {"/system/bin/dumpsys", "-T", std::to_string(timeout_ms)};
     dumpsys.insert(dumpsys.end(), dumpsys_args.begin(), dumpsys_args.end());
     RunCommand(title, dumpsys, options);
 }
@@ -1165,14 +1165,14 @@ void dump_route_tables() {
 }
 
 // TODO: make this function thread safe if sections are generated in parallel.
-void Dumpstate::UpdateProgress(int32_t delta) {
+void Dumpstate::UpdateProgress(int32_t delta_sec) {
     if (progress_ == nullptr) {
         MYLOGE("UpdateProgress: progress_ not set\n");
         return;
     }
 
     // Always update progess so stats can be tuned...
-    bool max_changed = progress_->Inc(delta);
+    bool max_changed = progress_->Inc(delta_sec);
 
     // ...but only notifiy listeners when necessary.
     if (!update_progress_) return;
diff --git a/cmds/dumpsys/dumpsys.cpp b/cmds/dumpsys/dumpsys.cpp
index c36ab0872a..0862a40734 100644
--- a/cmds/dumpsys/dumpsys.cpp
+++ b/cmds/dumpsys/dumpsys.cpp
@@ -61,7 +61,8 @@ static void usage() {
             "SERVICE [ARGS]]\n"
             "         --help: shows this help\n"
             "         -l: only list services, do not dump them\n"
-            "         -t TIMEOUT: TIMEOUT to use in seconds instead of default 10 seconds\n"
+            "         -t TIMEOUT_SEC: TIMEOUT to use in seconds instead of default 10 seconds\n"
+            "         -T TIMEOUT_MS: TIMEOUT to use in milliseconds instead of default 10 seconds\n"
             "         --proto: filter services that support dumping data in proto format. Dumps"
             "               will be in proto format.\n"
             "         --priority LEVEL: filter services based on specified priority\n"
@@ -104,7 +105,7 @@ int Dumpsys::main(int argc, char* const argv[]) {
     bool showListOnly = false;
     bool skipServices = false;
     bool filterByProto = false;
-    int timeoutArg = 10;
+    int timeoutArgMs = 10000;
     int dumpPriorityFlags = IServiceManager::DUMP_FLAG_PRIORITY_ALL;
     static struct option longOptions[] = {{"priority", required_argument, 0, 0},
                                           {"proto", no_argument, 0, 0},
@@ -119,7 +120,7 @@ int Dumpsys::main(int argc, char* const argv[]) {
         int c;
         int optionIndex = 0;
 
-        c = getopt_long(argc, argv, "+t:l", longOptions, &optionIndex);
+        c = getopt_long(argc, argv, "+t:T:l", longOptions, &optionIndex);
 
         if (c == -1) {
             break;
@@ -146,10 +147,22 @@ int Dumpsys::main(int argc, char* const argv[]) {
 
         case 't':
             {
-                char *endptr;
-                timeoutArg = strtol(optarg, &endptr, 10);
-                if (*endptr != '\0' || timeoutArg <= 0) {
-                    fprintf(stderr, "Error: invalid timeout number: '%s'\n", optarg);
+                char* endptr;
+                timeoutArgMs = strtol(optarg, &endptr, 10);
+                timeoutArgMs = timeoutArgMs * 1000;
+                if (*endptr != '\0' || timeoutArgMs <= 0) {
+                    fprintf(stderr, "Error: invalid timeout(seconds) number: '%s'\n", optarg);
+                    return -1;
+                }
+            }
+            break;
+
+        case 'T':
+            {
+                char* endptr;
+                timeoutArgMs = strtol(optarg, &endptr, 10);
+                if (*endptr != '\0' || timeoutArgMs <= 0) {
+                    fprintf(stderr, "Error: invalid timeout(milliseconds) number: '%s'\n", optarg);
                     return -1;
                 }
             }
@@ -269,7 +282,7 @@ int Dumpsys::main(int argc, char* const argv[]) {
                 }
             });
 
-            auto timeout = std::chrono::seconds(timeoutArg);
+            auto timeout = std::chrono::milliseconds(timeoutArgMs);
             auto start = std::chrono::steady_clock::now();
             auto end = start + timeout;
 
@@ -321,8 +334,8 @@ int Dumpsys::main(int argc, char* const argv[]) {
 
             if (timed_out) {
                 aout << endl
-                     << "*** SERVICE '" << service_name << "' DUMP TIMEOUT (" << timeoutArg
-                     << "s) EXPIRED ***" << endl
+                     << "*** SERVICE '" << service_name << "' DUMP TIMEOUT (" << timeoutArgMs
+                     << "ms) EXPIRED ***" << endl
                      << endl;
             }
 
diff --git a/cmds/dumpsys/tests/dumpsys_test.cpp b/cmds/dumpsys/tests/dumpsys_test.cpp
index 18a4da9739..bdb0a9ad8f 100644
--- a/cmds/dumpsys/tests/dumpsys_test.cpp
+++ b/cmds/dumpsys/tests/dumpsys_test.cpp
@@ -299,12 +299,25 @@ TEST_F(DumpsysTest, DumpRunningService) {
 }
 
 // Tests 'dumpsys -t 1 service_name' on a service that times out after 2s
-TEST_F(DumpsysTest, DumpRunningServiceTimeout) {
+TEST_F(DumpsysTest, DumpRunningServiceTimeoutInSec) {
     sp<BinderMock> binder_mock = ExpectDumpAndHang("Valet", 2, "Here's your car");
 
     CallMain({"-t", "1", "Valet"});
 
-    AssertOutputContains("SERVICE 'Valet' DUMP TIMEOUT (1s) EXPIRED");
+    AssertOutputContains("SERVICE 'Valet' DUMP TIMEOUT (1000ms) EXPIRED");
+    AssertNotDumped("Here's your car");
+
+    // TODO(b/65056227): BinderMock is not destructed because thread is detached on dumpsys.cpp
+    Mock::AllowLeak(binder_mock.get());
+}
+
+// Tests 'dumpsys -T 500 service_name' on a service that times out after 2s
+TEST_F(DumpsysTest, DumpRunningServiceTimeoutInMs) {
+    sp<BinderMock> binder_mock = ExpectDumpAndHang("Valet", 2, "Here's your car");
+
+    CallMain({"-T", "500", "Valet"});
+
+    AssertOutputContains("SERVICE 'Valet' DUMP TIMEOUT (500ms) EXPIRED");
     AssertNotDumped("Here's your car");
 
     // TODO(b/65056227): BinderMock is not destructed because thread is detached on dumpsys.cpp