Merge "TimeCheck: Dump TimerThread tasks on timeout" into tm-dev
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);
}