TimeCheck: Dump TimerThread tasks on timeout
On timeout, shows pending and retired tasks.
Fix race condition on TimerThread construction.
Split mutexes for better concurrency.
Track tasks that don't have timeout.
Enable dumping of pending requests.
Enable dumping of recent retired requests.
Format time in HH:MM:SS.MSc system_clock easier debugging.
Add default TimeCheck constructor that does nothing.
Test: atest libmediautils_test
Test: atest methodstatistics_tests
Test: atest timecheck_tests
Test: adb shell dumpsys media.audio_flinger
Test: adb shell dumpsys media.audio_policy
Test: adb shell dumpsys media.metrics
Bug: 219958414
Change-Id: I25742006578448813e557cdd20e304b9be286964
diff --git a/media/utils/TimerThread-test.cpp b/media/utils/TimerThread-test.cpp
index ee8a811..93cd64c 100644
--- a/media/utils/TimerThread-test.cpp
+++ b/media/utils/TimerThread-test.cpp
@@ -20,54 +20,71 @@
#include <mediautils/TimerThread.h>
using namespace std::chrono_literals;
+using namespace android::mediautils;
-namespace android {
namespace {
constexpr auto kJitter = 10ms;
+// Each task written by *ToString() will start with a left brace.
+constexpr char REQUEST_START = '{';
+
+inline size_t countChars(std::string_view s, char c) {
+ return std::count(s.begin(), s.end(), c);
+}
+
TEST(TimerThread, Basic) {
std::atomic<bool> taskRan = false;
TimerThread thread;
- thread.scheduleTask([&taskRan] { taskRan = true; }, 100ms);
+ thread.scheduleTask("Basic", [&taskRan] { taskRan = true; }, 100ms);
std::this_thread::sleep_for(100ms - kJitter);
ASSERT_FALSE(taskRan);
std::this_thread::sleep_for(2 * kJitter);
ASSERT_TRUE(taskRan);
+ ASSERT_EQ(1, countChars(thread.retiredToString(), REQUEST_START));
}
TEST(TimerThread, Cancel) {
std::atomic<bool> taskRan = false;
TimerThread thread;
- TimerThread::Handle handle = thread.scheduleTask([&taskRan] { taskRan = true; }, 100ms);
+ TimerThread::Handle handle =
+ thread.scheduleTask("Cancel", [&taskRan] { taskRan = true; }, 100ms);
std::this_thread::sleep_for(100ms - kJitter);
ASSERT_FALSE(taskRan);
- thread.cancelTask(handle);
+ ASSERT_TRUE(thread.cancelTask(handle));
std::this_thread::sleep_for(2 * kJitter);
ASSERT_FALSE(taskRan);
+ ASSERT_EQ(1, countChars(thread.retiredToString(), REQUEST_START));
}
TEST(TimerThread, CancelAfterRun) {
std::atomic<bool> taskRan = false;
TimerThread thread;
- TimerThread::Handle handle = thread.scheduleTask([&taskRan] { taskRan = true; }, 100ms);
+ TimerThread::Handle handle =
+ thread.scheduleTask("CancelAfterRun", [&taskRan] { taskRan = true; }, 100ms);
std::this_thread::sleep_for(100ms + kJitter);
ASSERT_TRUE(taskRan);
- thread.cancelTask(handle);
+ ASSERT_FALSE(thread.cancelTask(handle));
+ ASSERT_EQ(1, countChars(thread.retiredToString(), REQUEST_START));
}
TEST(TimerThread, MultipleTasks) {
- std::array<std::atomic<bool>, 6> taskRan;
+ std::array<std::atomic<bool>, 6> taskRan{};
TimerThread thread;
auto startTime = std::chrono::steady_clock::now();
- thread.scheduleTask([&taskRan] { taskRan[0] = true; }, 300ms);
- thread.scheduleTask([&taskRan] { taskRan[1] = true; }, 100ms);
- thread.scheduleTask([&taskRan] { taskRan[2] = true; }, 200ms);
- thread.scheduleTask([&taskRan] { taskRan[3] = true; }, 400ms);
- auto handle4 = thread.scheduleTask([&taskRan] { taskRan[4] = true; }, 200ms);
- thread.scheduleTask([&taskRan] { taskRan[5] = true; }, 200ms);
+ thread.scheduleTask("0", [&taskRan] { taskRan[0] = true; }, 300ms);
+ thread.scheduleTask("1", [&taskRan] { taskRan[1] = true; }, 100ms);
+ thread.scheduleTask("2", [&taskRan] { taskRan[2] = true; }, 200ms);
+ thread.scheduleTask("3", [&taskRan] { taskRan[3] = true; }, 400ms);
+ auto handle4 = thread.scheduleTask("4", [&taskRan] { taskRan[4] = true; }, 200ms);
+ thread.scheduleTask("5", [&taskRan] { taskRan[5] = true; }, 200ms);
+
+ // 6 tasks pending
+ ASSERT_EQ(6, countChars(thread.pendingToString(), REQUEST_START));
+ // 0 tasks completed
+ ASSERT_EQ(0, countChars(thread.retiredToString(), REQUEST_START));
// Task 1 should trigger around 100ms.
std::this_thread::sleep_until(startTime + 100ms - kJitter);
@@ -123,6 +140,11 @@
ASSERT_FALSE(taskRan[4]);
ASSERT_TRUE(taskRan[5]);
+ // 1 task pending
+ ASSERT_EQ(1, countChars(thread.pendingToString(), REQUEST_START));
+ // 4 tasks ran and 1 cancelled
+ ASSERT_EQ(4 + 1, countChars(thread.retiredToString(), REQUEST_START));
+
// Task 3 should trigger around 400ms.
std::this_thread::sleep_until(startTime + 400ms - kJitter);
ASSERT_TRUE(taskRan[0]);
@@ -132,6 +154,9 @@
ASSERT_FALSE(taskRan[4]);
ASSERT_TRUE(taskRan[5]);
+ // 4 tasks ran and 1 cancelled
+ ASSERT_EQ(4 + 1, countChars(thread.retiredToString(), REQUEST_START));
+
std::this_thread::sleep_until(startTime + 400ms + kJitter);
ASSERT_TRUE(taskRan[0]);
ASSERT_TRUE(taskRan[1]);
@@ -139,8 +164,62 @@
ASSERT_TRUE(taskRan[3]);
ASSERT_FALSE(taskRan[4]);
ASSERT_TRUE(taskRan[5]);
+
+ // 0 tasks pending
+ ASSERT_EQ(0, countChars(thread.pendingToString(), REQUEST_START));
+ // 5 tasks ran and 1 cancelled
+ ASSERT_EQ(5 + 1, countChars(thread.retiredToString(), REQUEST_START));
}
+TEST(TimerThread, TrackedTasks) {
+ TimerThread thread;
+
+ auto handle0 = thread.trackTask("0");
+ auto handle1 = thread.trackTask("1");
+ auto handle2 = thread.trackTask("2");
+
+ // 3 tasks pending
+ ASSERT_EQ(3, countChars(thread.pendingToString(), REQUEST_START));
+ // 0 tasks retired
+ ASSERT_EQ(0, countChars(thread.retiredToString(), REQUEST_START));
+
+ ASSERT_TRUE(thread.cancelTask(handle0));
+ ASSERT_TRUE(thread.cancelTask(handle1));
+
+ // 1 task pending
+ ASSERT_EQ(1, countChars(thread.pendingToString(), REQUEST_START));
+ // 2 tasks retired
+ ASSERT_EQ(2, countChars(thread.retiredToString(), REQUEST_START));
+
+ // handle1 is stale, cancel returns false.
+ ASSERT_FALSE(thread.cancelTask(handle1));
+
+ // 1 task pending
+ ASSERT_EQ(1, countChars(thread.pendingToString(), REQUEST_START));
+ // 2 tasks retired
+ ASSERT_EQ(2, countChars(thread.retiredToString(), REQUEST_START));
+
+ // Add another tracked task.
+ auto handle3 = thread.trackTask("3");
+
+ // 2 tasks pending
+ ASSERT_EQ(2, countChars(thread.pendingToString(), REQUEST_START));
+ // 2 tasks retired
+ ASSERT_EQ(2, countChars(thread.retiredToString(), REQUEST_START));
+
+ ASSERT_TRUE(thread.cancelTask(handle2));
+
+ // 1 tasks pending
+ ASSERT_EQ(1, countChars(thread.pendingToString(), REQUEST_START));
+ // 3 tasks retired
+ ASSERT_EQ(3, countChars(thread.retiredToString(), REQUEST_START));
+
+ ASSERT_TRUE(thread.cancelTask(handle3));
+
+ // 0 tasks pending
+ ASSERT_EQ(0, countChars(thread.pendingToString(), REQUEST_START));
+ // 4 tasks retired
+ ASSERT_EQ(4, countChars(thread.retiredToString(), REQUEST_START));
+}
} // namespace
-} // namespace android