TimeCheck: Use clock monotonic for elapsed time am: df1ed5c6ce (ced8a660) · Commits · e / os / android_frameworks_av

media/utils/TimeCheck.cpp

+71 −17

Original line number	Diff line number	Diff line
		@@ -139,22 +139,22 @@ std::string TimeCheck::toString() {
		return getTimeCheckThread().toString();
		}

		TimeCheck::TimeCheck(std::string_view tag, OnTimerFunc&& onTimer, uint32_t timeoutMs,
		TimeCheck::TimeCheck(std::string_view tag, OnTimerFunc&& onTimer, uint32_t requestedTimeoutMs,
		bool crashOnTimeout)
		: mTimeCheckHandler{ std::make_shared<TimeCheckHandler>(
		tag, std::move(onTimer), crashOnTimeout,
		tag, std::move(onTimer), crashOnTimeout, std::chrono::milliseconds(requestedTimeoutMs),
		std::chrono::system_clock::now(), gettid()) }
		, mTimerHandle(timeoutMs == 0
		, mTimerHandle(requestedTimeoutMs == 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();
		[ timeCheckHandler = mTimeCheckHandler ](TimerThread::Handle timerHandle) {
		timeCheckHandler->onTimeout(timerHandle);
		},
		std::chrono::milliseconds(timeoutMs))) {}
		std::chrono::milliseconds(requestedTimeoutMs))) {}

		TimeCheck::~TimeCheck() {
		if (mTimeCheckHandler) {
		@@ -162,23 +162,75 @@ TimeCheck::~TimeCheck() {
		}
		}

		/* static */
		std::string TimeCheck::analyzeTimeouts(
		float requestedTimeoutMs, float elapsedSteadyMs, float elapsedSystemMs) {
		// Track any OS clock issues with suspend.
		// It is possible that the elapsedSystemMs is much greater than elapsedSteadyMs if
		// a suspend occurs; however, we always expect the timeout ms should always be slightly
		// less than the elapsed steady ms regardless of whether a suspend occurs or not.

		std::string s("Timeout ms ");
		s.append(std::to_string(requestedTimeoutMs))
		.append(" elapsed steady ms ").append(std::to_string(elapsedSteadyMs))
		.append(" elapsed system ms ").append(std::to_string(elapsedSystemMs));

		// Is there something unusual?
		static constexpr float TOLERANCE_CONTEXT_SWITCH_MS = 200.f;

		if (requestedTimeoutMs > elapsedSteadyMs \|\| requestedTimeoutMs > elapsedSystemMs) {
		s.append("\nError: early expiration - "
		"requestedTimeoutMs should be less than elapsed time");
		}

		if (elapsedSteadyMs > elapsedSystemMs + TOLERANCE_CONTEXT_SWITCH_MS) {
		s.append("\nWarning: steady time should not advance faster than system time");
		}

		// This has been found in suspend stress testing.
		if (elapsedSteadyMs > requestedTimeoutMs + TOLERANCE_CONTEXT_SWITCH_MS) {
		s.append("\nWarning: steady time significantly exceeds timeout "
		"- possible thread stall or aborted suspend");
		}

		// This has been found in suspend stress testing.
		if (elapsedSystemMs > requestedTimeoutMs + TOLERANCE_CONTEXT_SWITCH_MS) {
		s.append("\nInformation: system time significantly exceeds timeout "
		"- possible suspend");
		}
		return s;
		}

		// To avoid any potential race conditions, the timer handle
		// (expiration = clock steady start + timeout) is passed into the callback.
		void TimeCheck::TimeCheckHandler::onCancel(TimerThread::Handle timerHandle) const
		{
		if (TimeCheck::getTimeCheckThread().cancelTask(timerHandle) && onTimer) {
		const std::chrono::system_clock::time_point endTime = std::chrono::system_clock::now();
		onTimer(false /* timeout */,
		std::chrono::duration_cast<std::chrono::duration<float, std::milli>>(
		endTime - startTime).count());
		const std::chrono::steady_clock::time_point endSteadyTime =
		std::chrono::steady_clock::now();
		const float elapsedSteadyMs = std::chrono::duration_cast<FloatMs>(
		endSteadyTime - timerHandle + timeoutDuration).count();
		// send the elapsed steady time for statistics.
		onTimer(false /* timeout */, elapsedSteadyMs);
		}
		}

		void TimeCheck::TimeCheckHandler::onTimeout() const
		// To avoid any potential race conditions, the timer handle
		// (expiration = clock steady start + timeout) is passed into the callback.
		void TimeCheck::TimeCheckHandler::onTimeout(TimerThread::Handle timerHandle) const
		{
		const std::chrono::system_clock::time_point endTime = std::chrono::system_clock::now();
		const std::chrono::steady_clock::time_point endSteadyTime = std::chrono::steady_clock::now();
		const std::chrono::system_clock::time_point endSystemTime = std::chrono::system_clock::now();
		// timerHandle incorporates the timeout
		const float elapsedSteadyMs = std::chrono::duration_cast<FloatMs>(
		endSteadyTime - (timerHandle - timeoutDuration)).count();
		const float elapsedSystemMs = std::chrono::duration_cast<FloatMs>(
		endSystemTime - startSystemTime).count();
		const float requestedTimeoutMs = std::chrono::duration_cast<FloatMs>(
		timeoutDuration).count();

		if (onTimer) {
		onTimer(true /* timeout */,
		std::chrono::duration_cast<std::chrono::duration<float, std::milli>>(
		endTime - startTime).count());
		onTimer(true /* timeout */, elapsedSteadyMs);
		}

		if (!crashOnTimeout) return;
		@@ -208,8 +260,10 @@ void TimeCheck::TimeCheckHandler::onTimeout() const
		// Create abort message string - caution: this can be very large.
		const std::string abortMessage = std::string("TimeCheck timeout for ")
		.append(tag)
		.append(" scheduled ").append(formatTime(startTime))
		.append(" scheduled ").append(formatTime(startSystemTime))
		.append(" on thread ").append(std::to_string(tid)).append("\n")
		.append(analyzeTimeouts(
		requestedTimeoutMs, elapsedSteadyMs, elapsedSystemMs)).append("\n")
		.append(halPids).append("\n")
		.append(summary);

		@@ -241,7 +295,7 @@ mediautils::TimeCheck makeTimeCheckStatsForClassMethod(
		} else {
		stats->event(safeMethodName.asStringView(), elapsedMs);
		}
		}, 0 /* timeoutMs */);
		}, 0 /* requestedTimeoutMs */);
		}

		} // namespace android::mediautils

media/utils/TimerThread-test.cpp

+28 −9

Original line number	Diff line number	Diff line
		@@ -36,7 +36,10 @@ inline size_t countChars(std::string_view s, char c) {
		TEST(TimerThread, Basic) {
		std::atomic<bool> taskRan = false;
		TimerThread thread;
		thread.scheduleTask("Basic", [&taskRan] { taskRan = true; }, 100ms);
		TimerThread::Handle handle =
		thread.scheduleTask("Basic", [&taskRan](TimerThread::Handle handle __unused) {
		taskRan = true; }, 100ms);
		ASSERT_TRUE(TimerThread::isTimeoutHandle(handle));
		std::this_thread::sleep_for(100ms - kJitter);
		ASSERT_FALSE(taskRan);
		std::this_thread::sleep_for(2 * kJitter);
		@@ -48,7 +51,9 @@ TEST(TimerThread, Cancel) {
		std::atomic<bool> taskRan = false;
		TimerThread thread;
		TimerThread::Handle handle =
		thread.scheduleTask("Cancel", [&taskRan] { taskRan = true; }, 100ms);
		thread.scheduleTask("Cancel", [&taskRan](TimerThread::Handle handle __unused) {
		taskRan = true; }, 100ms);
		ASSERT_TRUE(TimerThread::isTimeoutHandle(handle));
		std::this_thread::sleep_for(100ms - kJitter);
		ASSERT_FALSE(taskRan);
		ASSERT_TRUE(thread.cancelTask(handle));
		@@ -61,7 +66,10 @@ TEST(TimerThread, CancelAfterRun) {
		std::atomic<bool> taskRan = false;
		TimerThread thread;
		TimerThread::Handle handle =
		thread.scheduleTask("CancelAfterRun", [&taskRan] { taskRan = true; }, 100ms);
		thread.scheduleTask("CancelAfterRun",
		[&taskRan](TimerThread::Handle handle __unused) {
		taskRan = true; }, 100ms);
		ASSERT_TRUE(TimerThread::isTimeoutHandle(handle));
		std::this_thread::sleep_for(100ms + kJitter);
		ASSERT_TRUE(taskRan);
		ASSERT_FALSE(thread.cancelTask(handle));
		@@ -74,12 +82,18 @@ TEST(TimerThread, MultipleTasks) {

		auto startTime = std::chrono::steady_clock::now();

		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);
		thread.scheduleTask("0", [&taskRan](TimerThread::Handle handle __unused) {
		taskRan[0] = true; }, 300ms);
		thread.scheduleTask("1", [&taskRan](TimerThread::Handle handle __unused) {
		taskRan[1] = true; }, 100ms);
		thread.scheduleTask("2", [&taskRan](TimerThread::Handle handle __unused) {
		taskRan[2] = true; }, 200ms);
		thread.scheduleTask("3", [&taskRan](TimerThread::Handle handle __unused) {
		taskRan[3] = true; }, 400ms);
		auto handle4 = thread.scheduleTask("4", [&taskRan](TimerThread::Handle handle __unused) {
		taskRan[4] = true; }, 200ms);
		thread.scheduleTask("5", [&taskRan](TimerThread::Handle handle __unused) {
		taskRan[5] = true; }, 200ms);

		// 6 tasks pending
		ASSERT_EQ(6, countChars(thread.pendingToString(), REQUEST_START));
		@@ -178,6 +192,10 @@ TEST(TimerThread, TrackedTasks) {
		auto handle1 = thread.trackTask("1");
		auto handle2 = thread.trackTask("2");

		ASSERT_TRUE(TimerThread::isNoTimeoutHandle(handle0));
		ASSERT_TRUE(TimerThread::isNoTimeoutHandle(handle1));
		ASSERT_TRUE(TimerThread::isNoTimeoutHandle(handle2));

		// 3 tasks pending
		ASSERT_EQ(3, countChars(thread.pendingToString(), REQUEST_START));
		// 0 tasks retired
		@@ -201,6 +219,7 @@ TEST(TimerThread, TrackedTasks) {

		// Add another tracked task.
		auto handle3 = thread.trackTask("3");
		ASSERT_TRUE(TimerThread::isNoTimeoutHandle(handle3));

		// 2 tasks pending
		ASSERT_EQ(2, countChars(thread.pendingToString(), REQUEST_START));

media/utils/TimerThread.cpp

+20 −29

Original line number	Diff line number	Diff line
		@@ -25,16 +25,20 @@
		#include <mediautils/TimerThread.h>
		#include <utils/ThreadDefs.h>

		using namespace std::chrono_literals;

		namespace android::mediautils {

		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_view tag, std::function<void()>&& func, std::chrono::milliseconds timeout) {
		std::string_view tag, TimerCallback&& func, Duration timeoutDuration) {
		const auto now = std::chrono::system_clock::now();
		auto request = std::make_shared<const Request>(now, now + timeout, gettid(), tag);
		return mMonitorThread.add(std::move(request), std::move(func), timeout);
		auto request = std::make_shared<const Request>(now, now +
		std::chrono::duration_cast<std::chrono::system_clock::duration>(timeoutDuration),
		gettid(), tag);
		return mMonitorThread.add(std::move(request), std::move(func), timeoutDuration);
		}

		TimerThread::Handle TimerThread::trackTask(std::string_view tag) {
		@@ -44,7 +48,7 @@ TimerThread::Handle TimerThread::trackTask(std::string_view tag) {
		}

		bool TimerThread::cancelTask(Handle handle) {
		std::shared_ptr<const Request> request = mNoTimeoutMap.isValidHandle(handle) ?
		std::shared_ptr<const Request> request = isNoTimeoutHandle(handle) ?
		mNoTimeoutMap.remove(handle) : mMonitorThread.remove(handle);
		if (!request) return false;
		mRetiredQueue.add(std::move(request));
		@@ -125,12 +129,12 @@ struct TimerThread::Analysis TimerThread::analyzeTimeout(
		std::vector<std::shared_ptr<const Request>> pendingExact;
		std::vector<std::shared_ptr<const Request>> pendingPossible;

		// We look at pending requests that were scheduled no later than kDuration
		// We look at pending requests that were scheduled no later than kPendingDuration
		// after the timeout request. This prevents false matches with calls
		// that naturally block for a short period of time
		// such as HAL write() and read().
		//
		auto constexpr kDuration = std::chrono::milliseconds(1000);
		constexpr Duration kPendingDuration = 1000ms;
		for (const auto& pending : pendingRequests) {
		// If the pending tid is the same as timeout tid, problem identified.
		if (pending->tid == timeout->tid) {
		@@ -139,7 +143,7 @@ struct TimerThread::Analysis TimerThread::analyzeTimeout(
		}

		// if the pending tid is scheduled within time limit
		if (pending->scheduled - timeout->scheduled < kDuration) {
		if (pending->scheduled - timeout->scheduled < kPendingDuration) {
		pendingPossible.emplace_back(pending);
		}
		}
		@@ -239,15 +243,11 @@ void TimerThread::RequestQueue::copyRequests(
		}
		}

		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++);
		const Handle handle = getUniqueHandle_l();
		mMap[handle] = request;
		return handle;
		}
		@@ -269,16 +269,6 @@ void TimerThread::NoTimeoutMap::copyRequests(
		}
		}

		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(); }) {
		@@ -307,10 +297,12 @@ void TimerThread::MonitorThread::threadFunc() {
		_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.
		node.mapped().second(nextDeadline);
		// Caution: we don't hold lock when we call TimerCallback.
		// This is benign issue - we permit concurrent operations
		// while in the callback to the MonitorQueue.
		//
		// Anything left over is released here outside lock.
		}
		// reacquire the lock - if something was added, we loop immediately to check.
		_l.lock();
		@@ -324,8 +316,7 @@ void TimerThread::MonitorThread::threadFunc() {
		}

		TimerThread::Handle TimerThread::MonitorThread::add(
		std::shared_ptr<const Request> request, std::function<void()>&& func,
		std::chrono::milliseconds timeout) {
		std::shared_ptr<const Request> request, TimerCallback&& func, Duration timeout) {
		std::lock_guard _l(mMutex);
		const Handle handle = getUniqueHandle_l(timeout);
		mMonitorRequests.emplace(handle, std::make_pair(std::move(request), std::move(func)));
		@@ -340,7 +331,7 @@ std::shared_ptr<const TimerThread::Request> TimerThread::MonitorThread::remove(H
		return {};
		}
		std::shared_ptr<const TimerThread::Request> request = std::move(it->second.first);
		std::function<void()> func = std::move(it->second.second);
		TimerCallback func = std::move(it->second.second);
		mMonitorRequests.erase(it);
		ul.unlock(); // manually release lock here so func is released outside of lock.
		return request;

media/utils/include/mediautils/TimeCheck.h

+29 −11

Original line number	Diff line number	Diff line
		@@ -27,9 +27,23 @@ namespace android::mediautils {

		class TimeCheck {
		public:

		// Duration for TimeCheck is based on steady_clock, typically nanoseconds.
		using Duration = std::chrono::steady_clock::duration;

		// Duration for printing is in milliseconds, using float for additional precision.
		using FloatMs = std::chrono::duration<float, std::milli>;

		// OnTimerFunc is the callback function with 2 parameters.
		// bool timeout (which is true when the TimeCheck object
		// times out, false when the TimeCheck object is
		// destroyed or leaves scope before the timer expires.)
		// float elapsedMs (the elapsed time to this event).
		using OnTimerFunc = std::function<void(bool /* timeout /, float / elapsedMs */ )>;

		// The default timeout is chosen to be less than system server watchdog timeout
		// Note: kDefaultTimeOutMs should be no less than 2 seconds, otherwise spurious timeouts
		// may occur with system suspend.
		static constexpr uint32_t kDefaultTimeOutMs = 5000;

		/**
		@@ -44,24 +58,20 @@ class TimeCheck {
		* the deallocation.
		*
		* \param tag string associated with the TimeCheck object.
		* \param onTimer callback function with 2 parameters
		* bool timeout (which is true when the TimeCheck object
		* times out, false when the TimeCheck object is
		* destroyed or leaves scope before the timer expires.)
		* float elapsedMs (the elapsed time to this event).
		* \param onTimer callback function with 2 parameters (described above in OnTimerFunc).
		* The callback when timeout is true will be called on a different thread.
		* 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.
		* \param requestedTimeoutMs 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_view tag, OnTimerFunc&& onTimer = {},
		uint32_t timeoutMs = kDefaultTimeOutMs, bool crashOnTimeout = true);
		uint32_t requestedTimeoutMs = kDefaultTimeOutMs, bool crashOnTimeout = true);

		TimeCheck() = default;
		// Remove copy constructors as there should only be one call to the destructor.
		@@ -81,24 +91,32 @@ class TimeCheck {
		public:
		template <typename S, typename F>
		TimeCheckHandler(S&& _tag, F&& _onTimer, bool _crashOnTimeout,
		const std::chrono::system_clock::time_point& _startTime,
		Duration _timeoutDuration,
		std::chrono::system_clock::time_point _startSystemTime,
		pid_t _tid)
		: tag(std::forward<S>(_tag))
		, onTimer(std::forward<F>(_onTimer))
		, crashOnTimeout(_crashOnTimeout)
		, startTime(_startTime)
		, timeoutDuration(_timeoutDuration)
		, startSystemTime(_startSystemTime)
		, tid(_tid)
		{}
		const FixedString62 tag;
		const OnTimerFunc onTimer;
		const bool crashOnTimeout;
		const std::chrono::system_clock::time_point startTime;
		const Duration timeoutDuration;
		const std::chrono::system_clock::time_point startSystemTime;
		const pid_t tid;

		void onCancel(TimerThread::Handle handle) const;
		void onTimeout() const;
		void onTimeout(TimerThread::Handle handle) const;
		};

		// Returns a string that represents the timeout vs elapsed time,
		// and diagnostics if there are any potential issues.
		static std::string analyzeTimeouts(
		float timeoutMs, float elapsedSteadyMs, float elapsedSystemMs);

		static TimerThread& getTimeCheckThread();
		static void accessAudioHalPids(std::vector<pid_t>* pids, bool update);

media/utils/include/mediautils/TimerThread.h

+94 −24

File changed.

Preview size limit exceeded, changes collapsed.