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/TimeCheck.cpp b/media/utils/TimeCheck.cpp
index 5f269af..0237977 100644
--- a/media/utils/TimeCheck.cpp
+++ b/media/utils/TimeCheck.cpp
@@ -17,8 +17,8 @@
#define LOG_TAG "TimeCheck"
#include <optional>
-#include <sstream>
+#include <audio_utils/clock.h>
#include <mediautils/EventLog.h>
#include <mediautils/TimeCheck.h>
#include <utils/Log.h>
@@ -26,14 +26,68 @@
namespace android::mediautils {
-namespace {
-
+/**
+ * Returns the std::string "HH:MM:SS.MSc" from a system_clock time_point.
+ */
std::string formatTime(std::chrono::system_clock::time_point t) {
- auto msSinceEpoch = std::chrono::round<std::chrono::milliseconds>(t.time_since_epoch());
- return (std::ostringstream() << msSinceEpoch.count()).str();
+ auto time_string = audio_utils_time_string_from_ns(
+ std::chrono::nanoseconds(t.time_since_epoch()).count());
+
+ // The time string is 19 characters (including null termination).
+ // Example: "03-27 16:47:06.187"
+ // MM DD HH MM SS MS
+ // We offset by 6 to get HH:MM:SS.MSc
+ //
+ return time_string.time + 6; // offset to remove month/day.
}
-} // namespace
+/**
+ * Finds the end of the common time prefix.
+ *
+ * This is as an option to remove the common time prefix to avoid
+ * unnecessary duplicated strings.
+ *
+ * \param time1 a time string
+ * \param time2 a time string
+ * \return the position where the common time prefix ends. For abbreviated
+ * printing of time2, offset the character pointer by this position.
+ */
+static size_t commonTimePrefixPosition(std::string_view time1, std::string_view time2) {
+ const size_t endPos = std::min(time1.size(), time2.size());
+ size_t i;
+
+ // Find location of the first mismatch between strings
+ for (i = 0; ; ++i) {
+ if (i == endPos) {
+ return i; // strings match completely to the length of one of the strings.
+ }
+ if (time1[i] != time2[i]) {
+ break;
+ }
+ if (time1[i] == '\0') {
+ return i; // "printed" strings match completely. No need to check further.
+ }
+ }
+
+ // Go backwards until we find a delimeter or space.
+ for (; i > 0
+ && isdigit(time1[i]) // still a number
+ && time1[i - 1] != ' '
+ ; --i) {
+ }
+ return i;
+}
+
+/**
+ * Returns the unique suffix of time2 that isn't present in time1.
+ *
+ * If time2 is identical to time1, then an empty string_view is returned.
+ * This method is used to elide the common prefix when printing times.
+ */
+std::string_view timeSuffix(std::string_view time1, std::string_view time2) {
+ const size_t pos = commonTimePrefixPosition(time1, time2);
+ return time2.substr(pos);
+}
// Audio HAL server pids vector used to generate audio HAL processes tombstone
// when audioserver watchdog triggers.
@@ -75,23 +129,34 @@
return sTimeCheckThread;
}
+/* static */
+std::string TimeCheck::toString() {
+ // note pending and retired are individually locked for maximum concurrency,
+ // snapshot is not instantaneous at a single time.
+ return getTimeCheckThread().toString();
+}
+
TimeCheck::TimeCheck(std::string tag, OnTimerFunc&& onTimer, uint32_t timeoutMs,
bool crashOnTimeout)
: mTimeCheckHandler(new TimeCheckHandler{
std::move(tag), std::move(onTimer), crashOnTimeout,
std::chrono::system_clock::now(), gettid()})
- , mTimerHandle(getTimeCheckThread().scheduleTask(
- // Pass in all the arguments by value to this task for safety.
- // The thread could call the callback before the constructor is finished.
- // The destructor will be blocked on the callback, but that is implementation
- // dependent.
- [ timeCheckHandler = mTimeCheckHandler ] {
- timeCheckHandler->onTimeout();
- },
- std::chrono::milliseconds(timeoutMs))) {}
+ , mTimerHandle(timeoutMs == 0
+ ? getTimeCheckThread().trackTask(mTimeCheckHandler->tag)
+ : getTimeCheckThread().scheduleTask(
+ mTimeCheckHandler->tag,
+ // Pass in all the arguments by value to this task for safety.
+ // The thread could call the callback before the constructor is finished.
+ // The destructor is not blocked on callback.
+ [ timeCheckHandler = mTimeCheckHandler ] {
+ timeCheckHandler->onTimeout();
+ },
+ std::chrono::milliseconds(timeoutMs))) {}
TimeCheck::~TimeCheck() {
- mTimeCheckHandler->onCancel(mTimerHandle);
+ if (mTimeCheckHandler) {
+ mTimeCheckHandler->onCancel(mTimerHandle);
+ }
}
void TimeCheck::TimeCheckHandler::onCancel(TimerThread::Handle timerHandle) const
@@ -115,6 +180,10 @@
if (!crashOnTimeout) return;
+ // Generate the TimerThread summary string early before sending signals to the
+ // HAL processes which can affect thread behavior.
+ const std::string summary = getTimeCheckThread().toString(4 /* retiredCount */);
+
// Generate audio HAL processes tombstones and allow time to complete
// before forcing restart
std::vector<pid_t> pids = TimeCheck::getAudioHalPids();
@@ -128,8 +197,8 @@
ALOGI("No HAL process pid available, skipping tombstones");
}
LOG_EVENT_STRING(LOGTAG_AUDIO_BINDER_TIMEOUT, tag.c_str());
- LOG_ALWAYS_FATAL("TimeCheck timeout for %s on thread %d (start=%s, end=%s)",
- tag.c_str(), tid, formatTime(startTime).c_str(), formatTime(endTime).c_str());
+ LOG_ALWAYS_FATAL("TimeCheck timeout for %s scheduled %s on thread %d\n%s",
+ tag.c_str(), formatTime(startTime).c_str(), tid, summary.c_str());
}
} // namespace android::mediautils
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
diff --git a/media/utils/TimerThread.cpp b/media/utils/TimerThread.cpp
index dfc84e1..3bc4549 100644
--- a/media/utils/TimerThread.cpp
+++ b/media/utils/TimerThread.cpp
@@ -17,18 +17,167 @@
#define LOG_TAG "TimerThread"
#include <optional>
+#include <sstream>
+#include <unistd.h>
+#include <vector>
#include <mediautils/TimerThread.h>
#include <utils/ThreadDefs.h>
-namespace android {
+namespace android::mediautils {
-TimerThread::TimerThread() : mThread([this] { threadFunc(); }) {
- pthread_setname_np(mThread.native_handle(), "TimeCheckThread");
- pthread_setschedprio(mThread.native_handle(), PRIORITY_URGENT_AUDIO);
+extern std::string formatTime(std::chrono::system_clock::time_point t);
+extern std::string_view timeSuffix(std::string_view time1, std::string_view time2);
+
+TimerThread::Handle TimerThread::scheduleTask(
+ std::string tag, std::function<void()>&& func, std::chrono::milliseconds timeout) {
+ const auto now = std::chrono::system_clock::now();
+ std::shared_ptr<const Request> request{
+ new Request{ now, now + timeout, gettid(), std::move(tag) }};
+ return mMonitorThread.add(std::move(request), std::move(func), timeout);
}
-TimerThread::~TimerThread() {
+TimerThread::Handle TimerThread::trackTask(std::string tag) {
+ const auto now = std::chrono::system_clock::now();
+ std::shared_ptr<const Request> request{
+ new Request{ now, now, gettid(), std::move(tag) }};
+ return mNoTimeoutMap.add(std::move(request));
+}
+
+bool TimerThread::cancelTask(Handle handle) {
+ std::shared_ptr<const Request> request = mNoTimeoutMap.isValidHandle(handle) ?
+ mNoTimeoutMap.remove(handle) : mMonitorThread.remove(handle);
+ if (!request) return false;
+ mRetiredQueue.add(std::move(request));
+ return true;
+}
+
+std::string TimerThread::toString(size_t retiredCount) const {
+ return std::string("now ")
+ .append(formatTime(std::chrono::system_clock::now()))
+ .append("\npending [ ")
+ .append(pendingToString())
+ .append(" ]\ntimeout [ ")
+ .append(timeoutToString())
+ .append(" ]\nretired [ ")
+ .append(retiredToString(retiredCount))
+ .append(" ]");
+}
+
+std::vector<std::shared_ptr<const TimerThread::Request>> TimerThread::getPendingRequests() const {
+ constexpr size_t kEstimatedPendingRequests = 8; // approx 128 byte alloc.
+ std::vector<std::shared_ptr<const Request>> pendingRequests;
+ pendingRequests.reserve(kEstimatedPendingRequests); // preallocate vector out of lock.
+
+ // following are internally locked calls, which add to our local pendingRequests.
+ mMonitorThread.copyRequests(pendingRequests);
+ mNoTimeoutMap.copyRequests(pendingRequests);
+
+ // Sort in order of scheduled time.
+ std::sort(pendingRequests.begin(), pendingRequests.end(),
+ [](const std::shared_ptr<const Request>& r1,
+ const std::shared_ptr<const Request>& r2) {
+ return r1->scheduled < r2->scheduled;
+ });
+ return pendingRequests;
+}
+
+std::string TimerThread::pendingToString() const {
+ return requestsToString(getPendingRequests());
+}
+
+std::string TimerThread::retiredToString(size_t n) const {
+ std::vector<std::shared_ptr<const Request>> retiredRequests;
+ mRetiredQueue.copyRequests(retiredRequests, n);
+
+ // Dump to string
+ return requestsToString(retiredRequests);
+}
+
+std::string TimerThread::timeoutToString(size_t n) const {
+ std::vector<std::shared_ptr<const Request>> timeoutRequests;
+ mTimeoutQueue.copyRequests(timeoutRequests, n);
+
+ // Dump to string
+ return requestsToString(timeoutRequests);
+}
+
+std::string TimerThread::Request::toString() const {
+ const auto scheduledString = formatTime(scheduled);
+ const auto deadlineString = formatTime(deadline);
+ return std::string(tag)
+ .append(" scheduled ").append(scheduledString)
+ .append(" deadline ").append(timeSuffix(scheduledString, deadlineString))
+ .append(" tid ").append(std::to_string(tid));
+}
+
+void TimerThread::RequestQueue::add(std::shared_ptr<const Request> request) {
+ std::lock_guard lg(mRQMutex);
+ mRequestQueue.emplace_back(std::chrono::system_clock::now(), std::move(request));
+ if (mRequestQueue.size() > mRequestQueueMax) {
+ mRequestQueue.pop_front();
+ }
+}
+
+void TimerThread::RequestQueue::copyRequests(
+ std::vector<std::shared_ptr<const Request>>& requests, size_t n) const {
+ std::lock_guard lg(mRQMutex);
+ const size_t size = mRequestQueue.size();
+ size_t i = n >= size ? 0 : size - n;
+ for (; i < size; ++i) {
+ const auto &[time, request] = mRequestQueue[i];
+ requests.emplace_back(request);
+ }
+}
+
+bool TimerThread::NoTimeoutMap::isValidHandle(Handle handle) const {
+ return handle > getIndexedHandle(mNoTimeoutRequests);
+}
+
+TimerThread::Handle TimerThread::NoTimeoutMap::add(std::shared_ptr<const Request> request) {
+ std::lock_guard lg(mNTMutex);
+ // A unique handle is obtained by mNoTimeoutRequests.fetch_add(1),
+ // This need not be under a lock, but we do so anyhow.
+ const Handle handle = getIndexedHandle(mNoTimeoutRequests++);
+ mMap[handle] = request;
+ return handle;
+}
+
+std::shared_ptr<const TimerThread::Request> TimerThread::NoTimeoutMap::remove(Handle handle) {
+ std::lock_guard lg(mNTMutex);
+ auto it = mMap.find(handle);
+ if (it == mMap.end()) return {};
+ auto request = it->second;
+ mMap.erase(it);
+ return request;
+}
+
+void TimerThread::NoTimeoutMap::copyRequests(
+ std::vector<std::shared_ptr<const Request>>& requests) const {
+ std::lock_guard lg(mNTMutex);
+ for (const auto &[handle, request] : mMap) {
+ requests.emplace_back(request);
+ }
+}
+
+TimerThread::Handle TimerThread::MonitorThread::getUniqueHandle_l(
+ std::chrono::milliseconds timeout) {
+ // To avoid key collisions, advance by 1 tick until the key is unique.
+ auto deadline = std::chrono::steady_clock::now() + timeout;
+ for (; mMonitorRequests.find(deadline) != mMonitorRequests.end();
+ deadline += std::chrono::steady_clock::duration(1))
+ ;
+ return deadline;
+}
+
+TimerThread::MonitorThread::MonitorThread(RequestQueue& timeoutQueue)
+ : mTimeoutQueue(timeoutQueue)
+ , mThread([this] { threadFunc(); }) {
+ pthread_setname_np(mThread.native_handle(), "TimerThread");
+ pthread_setschedprio(mThread.native_handle(), PRIORITY_URGENT_AUDIO);
+}
+
+TimerThread::MonitorThread::~MonitorThread() {
{
std::lock_guard _l(mMutex);
mShouldExit = true;
@@ -37,37 +186,26 @@
mThread.join();
}
-TimerThread::Handle TimerThread::scheduleTaskAtDeadline(std::function<void()>&& func,
- TimePoint deadline) {
- std::lock_guard _l(mMutex);
-
- // To avoid key collisions, advance by 1 tick until the key is unique.
- for (; mMonitorRequests.find(deadline) != mMonitorRequests.end();
- deadline += TimePoint::duration(1))
- ;
- mMonitorRequests.emplace(deadline, std::move(func));
- mCond.notify_all();
- return deadline;
-}
-
-// Returns true if cancelled, false if handle doesn't exist.
-// Beware of lock inversion with cancelTask() as the callback
-// is called while holding mMutex.
-bool TimerThread::cancelTask(Handle handle) {
- std::lock_guard _l(mMutex);
- return mMonitorRequests.erase(handle) != 0;
-}
-
-void TimerThread::threadFunc() {
+void TimerThread::MonitorThread::threadFunc() {
std::unique_lock _l(mMutex);
-
while (!mShouldExit) {
if (!mMonitorRequests.empty()) {
- TimePoint nextDeadline = mMonitorRequests.begin()->first;
+ Handle nextDeadline = mMonitorRequests.begin()->first;
if (nextDeadline < std::chrono::steady_clock::now()) {
- // Deadline expired.
- mMonitorRequests.begin()->second();
- mMonitorRequests.erase(mMonitorRequests.begin());
+ // Deadline has expired, handle the request.
+ {
+ auto node = mMonitorRequests.extract(mMonitorRequests.begin());
+ _l.unlock();
+ // We add Request to retired queue early so that it can be dumped out.
+ mTimeoutQueue.add(std::move(node.mapped().first));
+ node.mapped().second(); // Caution: we don't hold lock here - but do we care?
+ // this is the timeout case! We will crash soon,
+ // maybe before returning.
+ // anything left over is released here outside lock.
+ }
+ // reacquire the lock - if something was added, we loop immediately to check.
+ _l.lock();
+ continue;
}
mCond.wait_until(_l, nextDeadline);
} else {
@@ -76,4 +214,35 @@
}
}
-} // namespace android
+TimerThread::Handle TimerThread::MonitorThread::add(
+ std::shared_ptr<const Request> request, std::function<void()>&& func,
+ std::chrono::milliseconds timeout) {
+ std::lock_guard _l(mMutex);
+ const Handle handle = getUniqueHandle_l(timeout);
+ mMonitorRequests.emplace(handle, std::make_pair(std::move(request), std::move(func)));
+ mCond.notify_all();
+ return handle;
+}
+
+std::shared_ptr<const TimerThread::Request> TimerThread::MonitorThread::remove(Handle handle) {
+ std::unique_lock ul(mMutex);
+ const auto it = mMonitorRequests.find(handle);
+ if (it == mMonitorRequests.end()) {
+ return {};
+ }
+ std::shared_ptr<const TimerThread::Request> request = std::move(it->second.first);
+ std::function<void()> func = std::move(it->second.second);
+ mMonitorRequests.erase(it);
+ ul.unlock(); // manually release lock here so func is released outside of lock.
+ return request;
+}
+
+void TimerThread::MonitorThread::copyRequests(
+ std::vector<std::shared_ptr<const Request>>& requests) const {
+ std::lock_guard lg(mMutex);
+ for (const auto &[deadline, monitorpair] : mMonitorRequests) {
+ requests.emplace_back(monitorpair.first);
+ }
+}
+
+} // namespace android::mediautils
diff --git a/media/utils/include/mediautils/TimeCheck.h b/media/utils/include/mediautils/TimeCheck.h
index 991a921..d5130b0 100644
--- a/media/utils/include/mediautils/TimeCheck.h
+++ b/media/utils/include/mediautils/TimeCheck.h
@@ -50,27 +50,31 @@
* destroyed or leaves scope before the timer expires.)
* float elapsedMs (the elapsed time to this event).
* The callback when timeout is true will be called on a different thread.
- * Currently this is guaranteed to block the destructor
- * (potential lock inversion warning here) nevertheless
- * it would be safer not to depend on stack contents.
+ * This will cancel the callback on the destructor but is not guaranteed
+ * to block for callback completion if it is already in progress
+ * (for maximum concurrency and reduced deadlock potential), so use proper
+ * lifetime analysis (e.g. shared or weak pointers).
* \param timeoutMs timeout in milliseconds.
+ * A zero timeout means no timeout is set -
+ * the callback is called only when
+ * the TimeCheck object is destroyed or leaves scope.
* \param crashOnTimeout true if the object issues an abort on timeout.
*/
explicit TimeCheck(std::string tag, OnTimerFunc&& onTimer = {},
uint32_t timeoutMs = kDefaultTimeOutMs, bool crashOnTimeout = true);
+
+ TimeCheck() = default;
// Remove copy constructors as there should only be one call to the destructor.
// Move is kept implicitly disabled, but would be logically consistent if enabled.
TimeCheck(const TimeCheck& other) = delete;
TimeCheck& operator=(const TimeCheck&) = delete;
~TimeCheck();
+ static std::string toString();
static void setAudioHalPids(const std::vector<pid_t>& pids);
static std::vector<pid_t> getAudioHalPids();
private:
- static TimerThread& getTimeCheckThread();
- static void accessAudioHalPids(std::vector<pid_t>* pids, bool update);
-
// Helper class for handling events.
// The usage here is const safe.
class TimeCheckHandler {
@@ -85,11 +89,14 @@
void onTimeout() const;
};
+ static TimerThread& getTimeCheckThread();
+ static void accessAudioHalPids(std::vector<pid_t>* pids, bool update);
+
// mTimeCheckHandler is immutable, prefer to be first initialized, last destroyed.
// Technically speaking, we do not need a shared_ptr here because TimerThread::cancelTask()
// is mutually exclusive of the callback, but the price paid for lifetime safety is minimal.
const std::shared_ptr<const TimeCheckHandler> mTimeCheckHandler;
- const TimerThread::Handle mTimerHandle;
+ const TimerThread::Handle mTimerHandle = TimerThread::INVALID_HANDLE;
};
} // namespace android::mediautils
diff --git a/media/utils/include/mediautils/TimerThread.h b/media/utils/include/mediautils/TimerThread.h
index acf0b16..2dfe499 100644
--- a/media/utils/include/mediautils/TimerThread.h
+++ b/media/utils/include/mediautils/TimerThread.h
@@ -16,53 +16,225 @@
#pragma once
+#include <atomic>
#include <condition_variable>
+#include <deque>
#include <functional>
#include <map>
#include <mutex>
+#include <string>
#include <thread>
#include <android-base/thread_annotations.h>
-namespace android {
+namespace android::mediautils {
/**
* A thread for deferred execution of tasks, with cancellation.
*/
class TimerThread {
public:
+ // A Handle is a time_point that serves as a unique key. It is ordered.
using Handle = std::chrono::steady_clock::time_point;
- TimerThread();
- ~TimerThread();
+ static inline constexpr Handle INVALID_HANDLE =
+ std::chrono::steady_clock::time_point::min();
/**
- * Schedule a task to be executed in the future (`timeout` duration from now).
- * Returns a handle that can be used for cancellation.
+ * Schedules a task to be executed in the future (`timeout` duration from now).
+ *
+ * \param tag string associated with the task. This need not be unique,
+ * as the Handle returned is used for cancelling.
+ * \param func callback function that is invoked at the timeout.
+ * \param timeout timeout duration which is converted to milliseconds with at
+ * least 45 integer bits.
+ * A timeout of 0 (or negative) means the timer never expires
+ * so func() is never called. These tasks are stored internally
+ * and reported in the toString() until manually cancelled.
+ * \returns a handle that can be used for cancellation.
*/
- template <typename R, typename P>
- Handle scheduleTask(std::function<void()>&& func, std::chrono::duration<R, P> timeout) {
- auto deadline = std::chrono::steady_clock::now() + std::chrono::milliseconds(timeout);
- return scheduleTaskAtDeadline(std::move(func), deadline);
- }
+ Handle scheduleTask(
+ std::string tag, std::function<void()>&& func, std::chrono::milliseconds timeout);
/**
- * Cancel a task, previously scheduled with scheduleTask().
- * If the task has already executed, this is a no-op and returns false.
+ * Tracks a task that shows up on toString() until cancelled.
+ *
+ * \param tag string associated with the task.
+ * \returns a handle that can be used for cancellation.
+ */
+ Handle trackTask(std::string tag);
+
+ /**
+ * Cancels a task previously scheduled with scheduleTask()
+ * or trackTask().
+ *
+ * \returns true if cancelled. If the task has already executed
+ * or if the handle doesn't exist, this is a no-op
+ * and returns false.
*/
bool cancelTask(Handle handle);
+ std::string toString(size_t retiredCount = SIZE_MAX) const;
+
+ /**
+ * Returns a string representation of the TimerThread queue.
+ *
+ * The queue is dumped in order of scheduling (not deadline).
+ */
+ std::string pendingToString() const;
+
+ /**
+ * Returns a string representation of the last retired tasks.
+ *
+ * These tasks from trackTask() or scheduleTask() are
+ * cancelled.
+ *
+ * These are ordered when the task was retired.
+ *
+ * \param n is maximum number of tasks to dump.
+ */
+ std::string retiredToString(size_t n = SIZE_MAX) const;
+
+
+ /**
+ * Returns a string representation of the last timeout tasks.
+ *
+ * These tasks from scheduleTask() which have timed-out.
+ *
+ * These are ordered when the task had timed-out.
+ *
+ * \param n is maximum number of tasks to dump.
+ */
+ std::string timeoutToString(size_t n = SIZE_MAX) const;
+
+ /**
+ * Dumps a container with SmartPointer<Request> to a string.
+ *
+ * "{ Request1 } { Request2} ...{ RequestN }"
+ */
+ template <typename T>
+ static std::string requestsToString(const T& containerRequests) {
+ std::string s;
+ // append seems to be faster than stringstream.
+ // https://stackoverflow.com/questions/18892281/most-optimized-way-of-concatenation-in-strings
+ for (const auto& request : containerRequests) {
+ s.append("{ ").append(request->toString()).append(" } ");
+ }
+ // If not empty, there's an extra space at the end, so we trim it off.
+ if (!s.empty()) s.pop_back();
+ return s;
+ }
+
private:
- using TimePoint = std::chrono::steady_clock::time_point;
+ // To minimize movement of data, we pass around shared_ptrs to Requests.
+ // These are allocated and deallocated outside of the lock.
+ struct Request {
+ const std::chrono::system_clock::time_point scheduled;
+ const std::chrono::system_clock::time_point deadline; // deadline := scheduled + timeout
+ // if deadline == scheduled, no
+ // timeout, task not executed.
+ const pid_t tid;
+ const std::string tag;
- std::condition_variable mCond;
- std::mutex mMutex;
- std::thread mThread;
- std::map<TimePoint, std::function<void()>> mMonitorRequests GUARDED_BY(mMutex);
- bool mShouldExit GUARDED_BY(mMutex) = false;
+ std::string toString() const;
+ };
- void threadFunc();
- Handle scheduleTaskAtDeadline(std::function<void()>&& func, TimePoint deadline);
+ // Deque of requests, in order of add().
+ // This class is thread-safe.
+ class RequestQueue {
+ public:
+ explicit RequestQueue(size_t maxSize)
+ : mRequestQueueMax(maxSize) {}
+
+ void add(std::shared_ptr<const Request>);
+
+ // return up to the last "n" requests retired.
+ void copyRequests(std::vector<std::shared_ptr<const Request>>& requests,
+ size_t n = SIZE_MAX) const;
+
+ private:
+ const size_t mRequestQueueMax;
+ mutable std::mutex mRQMutex;
+ std::deque<std::pair<std::chrono::system_clock::time_point,
+ std::shared_ptr<const Request>>>
+ mRequestQueue GUARDED_BY(mRQMutex);
+ };
+
+ // A storage map of tasks without timeouts. There is no std::function<void()>
+ // required, it just tracks the tasks with the tag, scheduled time and the tid.
+ // These tasks show up on a pendingToString() until manually cancelled.
+ class NoTimeoutMap {
+ // This a counter of the requests that have no timeout (timeout == 0).
+ std::atomic<size_t> mNoTimeoutRequests{};
+
+ mutable std::mutex mNTMutex;
+ std::map<Handle, std::shared_ptr<const Request>> mMap GUARDED_BY(mNTMutex);
+
+ public:
+ bool isValidHandle(Handle handle) const; // lock free
+ Handle add(std::shared_ptr<const Request> request);
+ std::shared_ptr<const Request> remove(Handle handle);
+ void copyRequests(std::vector<std::shared_ptr<const Request>>& requests) const;
+ };
+
+ // Monitor thread.
+ // This thread manages shared pointers to Requests and a function to
+ // call on timeout.
+ // This class is thread-safe.
+ class MonitorThread {
+ mutable std::mutex mMutex;
+ mutable std::condition_variable mCond;
+
+ // Ordered map of requests based on time of deadline.
+ //
+ std::map<Handle, std::pair<std::shared_ptr<const Request>, std::function<void()>>>
+ mMonitorRequests GUARDED_BY(mMutex);
+
+ RequestQueue& mTimeoutQueue; // locked internally, added to when request times out.
+
+ // Worker thread variables
+ bool mShouldExit GUARDED_BY(mMutex) = false;
+
+ // To avoid race with initialization,
+ // mThread should be initialized last as the thread is launched immediately.
+ std::thread mThread;
+
+ void threadFunc();
+ Handle getUniqueHandle_l(std::chrono::milliseconds timeout) REQUIRES(mMutex);
+
+ public:
+ MonitorThread(RequestQueue &timeoutQueue);
+ ~MonitorThread();
+
+ Handle add(std::shared_ptr<const Request> request, std::function<void()>&& func,
+ std::chrono::milliseconds timeout);
+ std::shared_ptr<const Request> remove(Handle handle);
+ void copyRequests(std::vector<std::shared_ptr<const Request>>& requests) const;
+ };
+
+ std::vector<std::shared_ptr<const Request>> getPendingRequests() const;
+
+ // A no-timeout request is represented by a handles at the end of steady_clock time,
+ // counting down by the number of no timeout requests previously requested.
+ // We manage them on the NoTimeoutMap, but conceptually they could be scheduled
+ // on the MonitorThread because those time handles won't expire in
+ // the lifetime of the device.
+ static inline Handle getIndexedHandle(size_t index) {
+ return std::chrono::time_point<std::chrono::steady_clock>::max() -
+ std::chrono::time_point<std::chrono::steady_clock>::duration(index);
+ }
+
+ static constexpr size_t kRetiredQueueMax = 16;
+ RequestQueue mRetiredQueue{kRetiredQueueMax}; // locked internally
+
+ static constexpr size_t kTimeoutQueueMax = 16;
+ RequestQueue mTimeoutQueue{kTimeoutQueueMax}; // locked internally
+
+ NoTimeoutMap mNoTimeoutMap; // locked internally
+
+ MonitorThread mMonitorThread{mTimeoutQueue}; // This should be initialized last because
+ // the thread is launched immediately.
+ // Locked internally.
};
-} // namespace android
+} // namespace android::mediautils
diff --git a/media/utils/tests/timecheck_tests.cpp b/media/utils/tests/timecheck_tests.cpp
index 9833dc9..6ebf44d 100644
--- a/media/utils/tests/timecheck_tests.cpp
+++ b/media/utils/tests/timecheck_tests.cpp
@@ -23,6 +23,9 @@
#include <utils/Log.h>
using namespace android::mediautils;
+using namespace std::chrono_literals;
+
+namespace {
TEST(timecheck_tests, success) {
bool timeoutRegistered = false;
@@ -56,7 +59,7 @@
elapsedMsRegistered = elapsedMs;
event = true; // store-release, must be last.
}, 1 /* msec */, false /* crash */);
- usleep(100 * 1000 /* usec */); // extra time as callback called by different thread.
+ std::this_thread::sleep_for(100ms);
}
ASSERT_TRUE(event); // load-acquire, must be first.
ASSERT_TRUE(timeoutRegistered); // only called once on failure, not on dealloc.
@@ -65,3 +68,5 @@
// Note: We do not test TimeCheck crash because TimeCheck is multithreaded and the
// EXPECT_EXIT() signal catching is imperfect due to the gtest fork.
+
+} // namespace
\ No newline at end of file
diff --git a/services/audioflinger/Effects.cpp b/services/audioflinger/Effects.cpp
index efd2dbd..e6d7cf7 100644
--- a/services/audioflinger/Effects.cpp
+++ b/services/audioflinger/Effects.cpp
@@ -41,6 +41,7 @@
#include <media/audiohal/EffectsFactoryHalInterface.h>
#include <mediautils/MethodStatistics.h>
#include <mediautils/ServiceUtilities.h>
+#include <mediautils/TimeCheck.h>
#include "AudioFlinger.h"
@@ -1780,13 +1781,16 @@
status_t AudioFlinger::EffectHandle::onTransact(
uint32_t code, const Parcel& data, Parcel* reply, uint32_t flags) {
- std::chrono::system_clock::time_point startTime = std::chrono::system_clock::now();
- mediametrics::Defer defer([startTime, code] {
- std::chrono::system_clock::time_point endTime = std::chrono::system_clock::now();
- getIEffectStatistics().event(code,
- std::chrono::duration_cast<std::chrono::duration<float, std::milli>>(
- endTime - startTime).count());
- });
+ const std::string methodName = getIEffectStatistics().getMethodForCode(code);
+ mediautils::TimeCheck check(
+ std::string("IEffect::").append(methodName),
+ [code](bool timeout, float elapsedMs) {
+ if (timeout) {
+ ; // we don't timeout right now on the effect interface.
+ } else {
+ getIEffectStatistics().event(code, elapsedMs);
+ }
+ }, 0 /* timeoutMs */);
return BnEffect::onTransact(code, data, reply, flags);
}