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
Change-Id: Ibbf8f7868f9496317183457e964cd0c7db4fe657
diff --git a/media/utils/TimeCheck.cpp b/media/utils/TimeCheck.cpp
index ec68de7..658191e 100644
--- a/media/utils/TimeCheck.cpp
+++ b/media/utils/TimeCheck.cpp
@@ -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 @@
/* 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 @@
}
// 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 @@
.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());
diff --git a/media/utils/include/mediautils/TimeCheck.h b/media/utils/include/mediautils/TimeCheck.h
index f1d572f..3e8d35d 100644
--- a/media/utils/include/mediautils/TimeCheck.h
+++ b/media/utils/include/mediautils/TimeCheck.h
@@ -42,19 +42,29 @@
// 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);
+ /**
+ * 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();
- // 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 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 @@
// 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);
diff --git a/services/audioflinger/AudioFlinger.cpp b/services/audioflinger/AudioFlinger.cpp
index 20cd40c..c94c042 100644
--- a/services/audioflinger/AudioFlinger.cpp
+++ b/services/audioflinger/AudioFlinger.cpp
@@ -5204,8 +5204,8 @@
} else {
getIAudioFlingerStatistics().event(code, elapsedMs);
}
- }, mediautils::TimeCheck::kDefaultTimeoutDuration,
- mediautils::TimeCheck::kDefaultSecondChanceDuration,
+ }, mediautils::TimeCheck::getDefaultTimeoutDuration(),
+ mediautils::TimeCheck::getDefaultSecondChanceDuration(),
true /* crashOnTimeout */);
return delegate();
diff --git a/services/audiopolicy/service/AudioPolicyService.cpp b/services/audiopolicy/service/AudioPolicyService.cpp
index cc67481..6144f8c 100644
--- a/services/audiopolicy/service/AudioPolicyService.cpp
+++ b/services/audiopolicy/service/AudioPolicyService.cpp
@@ -1415,8 +1415,8 @@
} else {
getIAudioPolicyServiceStatistics().event(code, elapsedMs);
}
- }, mediautils::TimeCheck::kDefaultTimeoutDuration,
- mediautils::TimeCheck::kDefaultSecondChanceDuration,
+ }, mediautils::TimeCheck::getDefaultTimeoutDuration(),
+ mediautils::TimeCheck::getDefaultSecondChanceDuration(),
true /* crashOnTimeout */);
switch (code) {