From 6b9516ced325e93880e9c8ef2793380866a1c579 Mon Sep 17 00:00:00 2001 From: Narayan Kamath Date: Fri, 27 Oct 2017 11:15:51 +0100 Subject: dumpstate: always include last ANR as a separate entry. For consistency, as well as to make tooling easier. Most of this change is an extended yak-shave to try and close DumpData FDs in a consistent manner. Several layers of abstraction were assuming that it was their job to close input FDs, leading to double closes in some cases. These double closes are benign prior to this change to dump a given DumpData twice, given that dumpstate is single threaded. Bug: 68188758 Test: adb bugreport Change-Id: I6302f4cb553139c0c26defb4859c4eca5b18ec93 --- cmds/dumpstate/DumpstateUtil.cpp | 7 ++++--- 1 file changed, 4 insertions(+), 3 deletions(-) (limited to 'cmds/dumpstate/DumpstateUtil.cpp') diff --git a/cmds/dumpstate/DumpstateUtil.cpp b/cmds/dumpstate/DumpstateUtil.cpp index ea7109bacd..ede4254a9b 100644 --- a/cmds/dumpstate/DumpstateUtil.cpp +++ b/cmds/dumpstate/DumpstateUtil.cpp @@ -30,6 +30,7 @@ #include #include #include +#include #include #include "DumpstateInternal.h" @@ -182,8 +183,8 @@ bool PropertiesHelper::IsDryRun() { } int DumpFileToFd(int out_fd, const std::string& title, const std::string& path) { - int fd = TEMP_FAILURE_RETRY(open(path.c_str(), O_RDONLY | O_NONBLOCK | O_CLOEXEC)); - if (fd < 0) { + android::base::unique_fd fd(TEMP_FAILURE_RETRY(open(path.c_str(), O_RDONLY | O_NONBLOCK | O_CLOEXEC))); + if (fd.get() < 0) { int err = errno; if (title.empty()) { dprintf(out_fd, "*** Error dumping %s: %s\n", path.c_str(), strerror(err)); @@ -194,7 +195,7 @@ int DumpFileToFd(int out_fd, const std::string& title, const std::string& path) fsync(out_fd); return -1; } - return DumpFileFromFdToFd(title, path, fd, out_fd, PropertiesHelper::IsDryRun()); + return DumpFileFromFdToFd(title, path, fd.get(), out_fd, PropertiesHelper::IsDryRun()); } int RunCommandToFd(int fd, const std::string& title, const std::vector& full_command, -- cgit v1.2.3-59-g8ed1b From 6921f80f26cb779d2982d2e37e14aeadbc8230b7 Mon Sep 17 00:00:00 2001 From: Vishnu Nair Date: Wed, 22 Nov 2017 09:17:23 -0800 Subject: 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 '' DUMP TIMEOUT (1s) EXPIRED" -> "SERVICE '' 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 --- cmds/dumpstate/DumpstateUtil.cpp | 33 +++++++++++++++++++++------------ cmds/dumpstate/DumpstateUtil.h | 27 +++++++++++++++++++++------ cmds/dumpstate/dumpstate.cpp | 33 ++++++++++++++++----------------- cmds/dumpstate/dumpstate.h | 6 +++--- cmds/dumpstate/tests/dumpstate_test.cpp | 13 ++++++++++++- cmds/dumpstate/utils.cpp | 16 ++++++++-------- cmds/dumpsys/dumpsys.cpp | 33 +++++++++++++++++++++++---------- cmds/dumpsys/tests/dumpsys_test.cpp | 17 +++++++++++++++-- 8 files changed, 119 insertions(+), 59 deletions(-) (limited to 'cmds/dumpstate/DumpstateUtil.cpp') 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(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 #include +/* + * 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& } static void RunDumpsys(const std::string& title, const std::vector& 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& 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& dumpsys_args, - const CommandOptions& options, long dumpsysTimeout) { - long timeout = dumpsysTimeout > 0 ? dumpsysTimeout : options.Timeout(); - std::vector dumpsys = {"/system/bin/dumpsys", "-t", std::to_string(timeout)}; + const CommandOptions& options, long dumpsysTimeoutMs) { + long timeout_ms = dumpsysTimeoutMs > 0 ? dumpsysTimeoutMs : options.TimeoutInMs(); + std::vector 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 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 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 -- cgit v1.2.3-59-g8ed1b