blob: b82816f66fdae4aeb4fd24dd0d151f7a7a5c36ba [file] [log] [blame]
/*
* Copyright (C) 2021 The Android Open Source Project
*
* Licensed under the Apache License, Version 2.0 (the "License");
* you may not use this file except in compliance with the License.
* You may obtain a copy of the License at
*
* http://www.apache.org/licenses/LICENSE-2.0
*
* Unless required by applicable law or agreed to in writing, software
* distributed under the License is distributed on an "AS IS" BASIS,
* WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
* See the License for the specific language governing permissions and
* limitations under the License.
*/
#define LOG_TAG "TimerThread"
#include <optional>
#include <sstream>
#include <unistd.h>
#include <vector>
#include <mediautils/TimerThread.h>
#include <utils/ThreadDefs.h>
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 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::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 {
// Note: These request queues are snapshot very close together but
// not at "identical" times as we don't use a class-wide lock.
std::vector<std::shared_ptr<const Request>> timeoutRequests;
std::vector<std::shared_ptr<const Request>> retiredRequests;
mTimeoutQueue.copyRequests(timeoutRequests);
mRetiredQueue.copyRequests(retiredRequests, retiredCount);
std::vector<std::shared_ptr<const Request>> pendingRequests =
getPendingRequests();
struct Analysis analysis = analyzeTimeout(timeoutRequests, pendingRequests);
std::string analysisSummary;
if (!analysis.summary.empty()) {
analysisSummary = std::string("\nanalysis [ ").append(analysis.summary).append(" ]");
}
return std::string("now ")
.append(formatTime(std::chrono::system_clock::now()))
.append(analysisSummary)
.append("\ntimeout [ ")
.append(requestsToString(timeoutRequests))
.append(" ]\npending [ ")
.append(requestsToString(pendingRequests))
.append(" ]\nretired [ ")
.append(requestsToString(retiredRequests))
.append(" ]");
}
// A HAL method is where the substring "Hidl" is in the class name.
// The tag should look like: ... Hidl ... :: ...
// When the audio HAL is updated to AIDL perhaps we will use instead
// a global directory of HAL classes.
//
// See MethodStatistics.cpp:
// mediautils::getStatisticsClassesForModule(METHOD_STATISTICS_MODULE_NAME_AUDIO_HIDL)
//
/* static */
bool TimerThread::isRequestFromHal(const std::shared_ptr<const Request>& request) {
const size_t hidlPos = request->tag.find("Hidl");
if (hidlPos == std::string::npos) return false;
// should be a separator afterwards Hidl which indicates the string was in the class.
const size_t separatorPos = request->tag.find("::", hidlPos);
return separatorPos != std::string::npos;
}
/* static */
struct TimerThread::Analysis TimerThread::analyzeTimeout(
const std::vector<std::shared_ptr<const Request>>& timeoutRequests,
const std::vector<std::shared_ptr<const Request>>& pendingRequests) {
if (timeoutRequests.empty() || pendingRequests.empty()) return {}; // nothing to say.
// for now look at last timeout (in our case, the only timeout)
const std::shared_ptr<const Request> timeout = timeoutRequests.back();
// pending Requests that are problematic.
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
// 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);
for (const auto& pending : pendingRequests) {
// If the pending tid is the same as timeout tid, problem identified.
if (pending->tid == timeout->tid) {
pendingExact.emplace_back(pending);
continue;
}
// if the pending tid is scheduled within time limit
if (pending->scheduled - timeout->scheduled < kDuration) {
pendingPossible.emplace_back(pending);
}
}
struct Analysis analysis{};
analysis.timeoutTid = timeout->tid;
std::string& summary = analysis.summary;
if (!pendingExact.empty()) {
const auto& request = pendingExact.front();
const bool hal = isRequestFromHal(request);
if (hal) {
summary = std::string("Blocked directly due to HAL call: ")
.append(request->toString());
}
}
if (summary.empty() && !pendingPossible.empty()) {
for (const auto& request : pendingPossible) {
const bool hal = isRequestFromHal(request);
if (hal) {
// The first blocked call is the most likely one.
// Recent calls might be temporarily blocked
// calls such as write() or read() depending on kDuration.
summary = std::string("Blocked possibly due to HAL call: ")
.append(request->toString());
analysis.HALBlockedTid = request->tid;
}
}
}
return analysis;
}
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;
mCond.notify_all();
}
mThread.join();
}
void TimerThread::MonitorThread::threadFunc() {
std::unique_lock _l(mMutex);
while (!mShouldExit) {
if (!mMonitorRequests.empty()) {
Handle nextDeadline = mMonitorRequests.begin()->first;
if (nextDeadline < std::chrono::steady_clock::now()) {
// 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 {
mCond.wait(_l);
}
}
}
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