Donate to e Foundation | Murena handsets with /e/OS | Own a part of Murena! Learn more

Commit 34f26b1f authored by Ytai Ben-Tsvi's avatar Ytai Ben-Tsvi
Browse files

Add timestamps to TimeCheck logs 

Change the error message to include the start/end times of the
offending scope, in ms since system_clock epoch.

Bug: 208120087
Test: Injected a timeout into AudioFlinger and observed the logs.
Change-Id: I9dbe25c8b9b637c57eff4ff13c40ab78c7da7953
parent 96024460

media/utils/TimeCheck.cpp

+18 −4
Original line number Diff line number Diff line
@@ -17,6 +17,7 @@ 
#define LOG_TAG "TimeCheck"



#include <optional>

#include <sstream>



#include <mediautils/EventLog.h>

#include <mediautils/TimeCheck.h>
@@ -25,6 +26,15 @@ 


namespace android {



namespace {



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();

}



}  // namespace



// Audio HAL server pids vector used to generate audio HAL processes tombstone

// when audioserver watchdog triggers.

// We use a lockless storage to avoid potential deadlocks in the context of watchdog
@@ -66,7 +76,8 @@ TimerThread* TimeCheck::getTimeCheckThread() { 
}



TimeCheck::TimeCheck(const char* tag, uint32_t timeoutMs)

    : mTimerHandle(getTimeCheckThread()->scheduleTask([tag] { crash(tag); },

    : mTimerHandle(getTimeCheckThread()->scheduleTask(

              [tag, startTime = std::chrono::system_clock::now()] { crash(tag, startTime); },

              std::chrono::milliseconds(timeoutMs))) {}



TimeCheck::~TimeCheck() {
@@ -74,7 +85,9 @@ TimeCheck::~TimeCheck() { 
}



/* static */

void TimeCheck::crash(const char* tag) {

void TimeCheck::crash(const char* tag, std::chrono::system_clock::time_point startTime) {

    std::chrono::system_clock::time_point endTime = std::chrono::system_clock::now();



    // Generate audio HAL processes tombstones and allow time to complete

    // before forcing restart

    std::vector<pid_t> pids = getAudioHalPids();
@@ -88,7 +101,8 @@ void TimeCheck::crash(const char* tag) { 
        ALOGI("No HAL process pid available, skipping tombstones");

    }

    LOG_EVENT_STRING(LOGTAG_AUDIO_BINDER_TIMEOUT, tag);

    LOG_ALWAYS_FATAL("TimeCheck timeout for %s", tag);

    LOG_ALWAYS_FATAL("TimeCheck timeout for %s (start=%s, end=%s)", tag,

                     formatTime(startTime).c_str(), formatTime(endTime).c_str());

}



};  // namespace android

media/utils/include/mediautils/TimeCheck.h

+1 −1
Original line number Diff line number Diff line
@@ -38,7 +38,7 @@ class TimeCheck { 
  private:

    static TimerThread* getTimeCheckThread();

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

    static void crash(const char* tag);

    static void crash(const char* tag, std::chrono::system_clock::time_point startTime);



    const TimerThread::Handle mTimerHandle;

};