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

Commit cb899108 authored by Andy Hung's avatar Andy Hung
Browse files

TimeCheck: Allow property to change the timecheck timeouts. 

Example:
$ adb shell setprop audio.timecheck.timeout_duration_ms 4500
$ adb shell setprop audio.timecheck.second_chance_duration_ms 3500
$ adb shell pkill audioserver

Test: instrumented check with delay injection CL
Test: atest timerthread_tests
Test: atest timecheck_tests
Flag: EXEMPT bugfix
Bug: 353825734
Merged-In: Ibbf8f7868f9496317183457e964cd0c7db4fe657
Change-Id: Ibbf8f7868f9496317183457e964cd0c7db4fe657
parent ee898b7d

media/utils/TimeCheck.cpp

+53 −10
Original line number Diff line number Diff line
@@ -23,6 +23,7 @@ 
#include <android-base/logging.h>

#include <android-base/strings.h>

#include <audio_utils/clock.h>

#include <cutils/properties.h>

#include <mediautils/EventLog.h>

#include <mediautils/FixedString.h>

#include <mediautils/MethodStatistics.h>
@@ -36,6 +37,46 @@ 




namespace android::mediautils {



// Note: The sum of kDefaultTimeOutDurationMs and kDefaultSecondChanceDurationMs

// should be no less than 2 seconds, otherwise spurious timeouts

// may occur with system suspend.

static constexpr int kDefaultTimeoutDurationMs = 3000;



// Due to suspend abort not incrementing the monotonic clock,

// we allow another second chance timeout after the first timeout expires.

//

// The total timeout is therefore kDefaultTimeoutDuration + kDefaultSecondChanceDuration,

// and the result is more stable when the monotonic clock increments during suspend.

//

static constexpr int kDefaultSecondChanceDurationMs = 2000;



/* static */

TimeCheck::Duration TimeCheck::getDefaultTimeoutDuration() {

    static constinit std::atomic<int> defaultTimeoutDurationMs{};

    auto defaultMs = defaultTimeoutDurationMs.load(std::memory_order_relaxed);

    if (defaultMs == 0) {

        defaultMs = property_get_int32(

                "audio.timecheck.timeout_duration_ms", kDefaultTimeoutDurationMs);

        if (defaultMs < 1) defaultMs = kDefaultTimeoutDurationMs;

        defaultTimeoutDurationMs.store(defaultMs, std::memory_order_relaxed);

    }

    return std::chrono::milliseconds(defaultMs);

}



/* static */

TimeCheck::Duration TimeCheck::getDefaultSecondChanceDuration() {

    static constinit std::atomic<int> defaultSecondChanceDurationMs{};

    auto defaultMs = defaultSecondChanceDurationMs.load(std::memory_order_relaxed);

    if (defaultMs == 0) {

        defaultMs = property_get_int32(

                "audio.timecheck.second_chance_duration_ms", kDefaultSecondChanceDurationMs);

        if (defaultMs < 1) defaultMs = kDefaultSecondChanceDurationMs;

        defaultSecondChanceDurationMs.store(defaultMs, std::memory_order_relaxed);

    }

    return std::chrono::milliseconds(defaultMs);

}



// This function appropriately signals a pid to dump a backtrace if we are

// running on device (and the HAL exists). If we are not running on an Android

// device, there is no HAL to signal (so we do nothing).
@@ -182,23 +223,25 @@ TimeCheck::~TimeCheck() { 


/* static */

std::string TimeCheck::analyzeTimeouts(

        float requestedTimeoutMs, float elapsedSteadyMs, float elapsedSystemMs) {

        float requestedTimeoutMs, float secondChanceMs,

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

    const float totalTimeoutMs = requestedTimeoutMs + secondChanceMs;

    std::string s = std::format(

            "Timeout ms {:.2f} ({:.2f} + {:.2f})"

            " elapsed steady ms {:.4f} elapsed system ms {:.4f}",

            totalTimeoutMs, requestedTimeoutMs, secondChanceMs, elapsedSteadyMs, elapsedSystemMs);



    // Is there something unusual?

    static constexpr float TOLERANCE_CONTEXT_SWITCH_MS = 200.f;



    if (requestedTimeoutMs > elapsedSteadyMs || requestedTimeoutMs > elapsedSystemMs) {

    if (totalTimeoutMs > elapsedSteadyMs || totalTimeoutMs > elapsedSystemMs) {

        s.append("\nError: early expiration - "

                "requestedTimeoutMs should be less than elapsed time");

                "totalTimeoutMs should be less than elapsed time");

    }



    if (elapsedSteadyMs > elapsedSystemMs + TOLERANCE_CONTEXT_SWITCH_MS) {
@@ -206,13 +249,13 @@ std::string TimeCheck::analyzeTimeouts( 
    }



    // This has been found in suspend stress testing.

    if (elapsedSteadyMs > requestedTimeoutMs + TOLERANCE_CONTEXT_SWITCH_MS) {

    if (elapsedSteadyMs > totalTimeoutMs + 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) {

    if (elapsedSystemMs > totalTimeoutMs + TOLERANCE_CONTEXT_SWITCH_MS) {

        s.append("\nInformation: system time significantly exceeds timeout "

                "- possible suspend");

    }
@@ -282,7 +325,7 @@ void TimeCheck::TimeCheckHandler::onTimeout(TimerThread::Handle timerHandle) con 
            .append(tag)

            .append(" scheduled ").append(formatTime(startSystemTime))

            .append(" on thread ").append(std::to_string(tid)).append("\n")

            .append(analyzeTimeouts(requestedTimeoutMs + secondChanceMs,

            .append(analyzeTimeouts(requestedTimeoutMs, secondChanceMs,

                    elapsedSteadyMs, elapsedSystemMs)).append("\n")

            .append(halPids).append("\n")

            .append(snapshotAnalysis.toString());

media/utils/include/mediautils/TimeCheck.h

+25 −14
Original line number Diff line number Diff line
@@ -42,19 +42,29 @@ class TimeCheck { 
    //  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 TimeCheck::Duration kDefaultTimeoutDuration = std::chrono::milliseconds(3000);



    // Due to suspend abort not incrementing the monotonic clock,

    // we allow another second chance timeout after the first timeout expires.

    //

    // The total timeout is therefore kDefaultTimeoutDuration + kDefaultSecondChanceDuration,

    // and the result is more stable when the monotonic clock increments during suspend.

    //

    static constexpr TimeCheck::Duration kDefaultSecondChanceDuration =

            std::chrono::milliseconds(2000);

    /**

     * Returns the default timeout to use for TimeCheck.

     *

     * The default timeout of 3000ms (kDefaultTimeoutDurationMs) is chosen to be less than

     * the system server watchdog timeout, and can be changed by the sysprop

     * audio.timecheck.timeout_duration_ms.

     * A second chance wait may be set to extend the check.

     */

    static TimeCheck::Duration getDefaultTimeoutDuration();



    /**

     * Returns the second chance timeout to use for TimeCheck.

     *

     * Due to suspend abort not incrementing the monotonic clock,

     * we allow another second chance timeout after the first timeout expires.

     * The second chance timeout default of 2000ms (kDefaultSecondChanceDurationMs)

     * may be changed by the sysprop audio.timecheck.second_chance_duration_ms.

     *

     * The total timeout is therefore

     * getDefaultTimeoutDuration() + getDefaultSecondChanceDuration(),

     * and the result is more stable when the monotonic clock increments during suspend.

     */

    static TimeCheck::Duration getDefaultSecondChanceDuration();



    /**

     * TimeCheck is a RAII object which will notify a callback
@@ -130,7 +140,8 @@ class TimeCheck { 
    // 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);

            float timeoutMs, float secondChanceMs,

            float elapsedSteadyMs, float elapsedSystemMs);



    static TimerThread& getTimeCheckThread();

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

services/audioflinger/AudioFlinger.cpp

+2 −2
Original line number Diff line number Diff line
@@ -5104,8 +5104,8 @@ status_t AudioFlinger::onTransactWrapper(TransactionCode code, 
        } else {

            getIAudioFlingerStatistics().event(code, elapsedMs);

        }

    }, mediautils::TimeCheck::kDefaultTimeoutDuration,

    mediautils::TimeCheck::kDefaultSecondChanceDuration,

    }, mediautils::TimeCheck::getDefaultTimeoutDuration(),

    mediautils::TimeCheck::getDefaultSecondChanceDuration(),

    true /* crashOnTimeout */);



    return delegate();

services/audiopolicy/service/AudioPolicyService.cpp

+2 −2
Original line number Diff line number Diff line
@@ -1380,8 +1380,8 @@ status_t AudioPolicyService::onTransact( 
        } else {

            getIAudioPolicyServiceStatistics().event(code, elapsedMs);

        }

    }, mediautils::TimeCheck::kDefaultTimeoutDuration,

    mediautils::TimeCheck::kDefaultSecondChanceDuration,

    }, mediautils::TimeCheck::getDefaultTimeoutDuration(),

    mediautils::TimeCheck::getDefaultSecondChanceDuration(),

    true /* crashOnTimeout */);



    switch (code) {