From 4209a52a73435f34715359d211b2c2fdd22f321e Mon Sep 17 00:00:00 2001 From: Steven Moreland Date: Wed, 11 Jan 2023 02:10:04 +0000 Subject: binderUtilsHostTest: more debuggable Changes to make a flake that happens here more visible. - if final sleep is not logged, wait much longer - log times of various commands Bug: 264505396 Test: binderUtilsHostTest Change-Id: I0cb676556ce18fbbbb6d7955cfa43fef77fecc3d --- libs/binder/tests/binderUtilsHostTest.cpp | 38 +++++++++++++++++-------------- 1 file changed, 21 insertions(+), 17 deletions(-) diff --git a/libs/binder/tests/binderUtilsHostTest.cpp b/libs/binder/tests/binderUtilsHostTest.cpp index 4330e3e615..25e286ce0c 100644 --- a/libs/binder/tests/binderUtilsHostTest.cpp +++ b/libs/binder/tests/binderUtilsHostTest.cpp @@ -37,17 +37,24 @@ TEST(UtilsHost, ExecuteImmediately) { EXPECT_EQ(result->stdoutStr, "foo\n"); } +template +auto millisSince(std::chrono::time_point now) { + auto elapsed = std::chrono::system_clock::now() - now; + return std::chrono::duration_cast(elapsed).count(); +} + TEST(UtilsHost, ExecuteLongRunning) { - auto now = std::chrono::system_clock::now(); + auto start = std::chrono::system_clock::now(); { - std::vector args{"sh", "-c", - "sleep 0.5 && echo -n f && sleep 0.5 && echo oo && sleep 1"}; - auto result = execute(std::move(args), [](const CommandResult& commandResult) { + std::vector + args{"sh", "-c", "sleep 0.5 && echo -n f && sleep 0.5 && echo oo && sleep 100"}; + auto result = execute(std::move(args), [&](const CommandResult& commandResult) { + std::cout << millisSince(start) + << "ms: GOT PARTIAL COMMAND RESULT:" << commandResult.stdoutStr << std::endl; return android::base::EndsWith(commandResult.stdoutStr, "\n"); }); - auto elapsed = std::chrono::system_clock::now() - now; - auto elapsedMs = std::chrono::duration_cast(elapsed).count(); + auto elapsedMs = millisSince(start); EXPECT_GE(elapsedMs, 1000); EXPECT_LT(elapsedMs, 2000); @@ -58,22 +65,21 @@ TEST(UtilsHost, ExecuteLongRunning) { // ~CommandResult() called, child process is killed. // Assert that the second sleep does not finish. - auto elapsed = std::chrono::system_clock::now() - now; - auto elapsedMs = std::chrono::duration_cast(elapsed).count(); - EXPECT_LT(elapsedMs, 2000); + EXPECT_LT(millisSince(start), 2000); } TEST(UtilsHost, ExecuteLongRunning2) { - auto now = std::chrono::system_clock::now(); + auto start = std::chrono::system_clock::now(); { std::vector args{"sh", "-c", - "sleep 2 && echo -n f && sleep 2 && echo oo && sleep 2"}; - auto result = execute(std::move(args), [](const CommandResult& commandResult) { + "sleep 2 && echo -n f && sleep 2 && echo oo && sleep 100"}; + auto result = execute(std::move(args), [&](const CommandResult& commandResult) { + std::cout << millisSince(start) + << "ms: GOT PARTIAL COMMAND RESULT:" << commandResult.stdoutStr << std::endl; return android::base::EndsWith(commandResult.stdoutStr, "\n"); }); - auto elapsed = std::chrono::system_clock::now() - now; - auto elapsedMs = std::chrono::duration_cast(elapsed).count(); + auto elapsedMs = millisSince(start); EXPECT_GE(elapsedMs, 4000); EXPECT_LT(elapsedMs, 6000); @@ -84,9 +90,7 @@ TEST(UtilsHost, ExecuteLongRunning2) { // ~CommandResult() called, child process is killed. // Assert that the second sleep does not finish. - auto elapsed = std::chrono::system_clock::now() - now; - auto elapsedMs = std::chrono::duration_cast(elapsed).count(); - EXPECT_LT(elapsedMs, 6000); + EXPECT_LT(millisSince(start), 6000); } TEST(UtilsHost, KillWithSigKill) { -- cgit v1.2.3-59-g8ed1b