Logging a wtf if alarm delivery gets stuck
If alarm delivery is stuck, detect and log a wtf. This will help us
catch relevant information sooner and also indicate how frequently this
happens. Otherwise this is something that can easily go unnoticed and is
usually hard to debug once the alarms are running as expected again.
Test: Builds, boots, existing alarm tests pass.
adb shell dumpsys alarm
Bug: 78560047
Change-Id: Ife881f2c9649b8dfd87ba05a425483375361da64
diff --git a/services/core/java/com/android/server/AlarmManagerService.java b/services/core/java/com/android/server/AlarmManagerService.java
index 6ca81c2..3261209 100644
--- a/services/core/java/com/android/server/AlarmManagerService.java
+++ b/services/core/java/com/android/server/AlarmManagerService.java
@@ -172,7 +172,8 @@
long mNativeData;
private long mNextWakeup;
private long mNextNonWakeup;
- private long mLastWakeupSet;
+ private long mNextWakeUpSetAt;
+ private long mNextNonWakeUpSetAt;
private long mLastWakeup;
private long mLastTrigger;
private long mLastTickSet;
@@ -1939,7 +1940,7 @@
TimeUtils.formatDuration(nowELAPSED - mLastAlarmDeliveryTime, pw);
pw.println();
pw.print(" Next non-wakeup delivery time: ");
- TimeUtils.formatDuration(nowELAPSED - mNextNonWakeupDeliveryTime, pw);
+ TimeUtils.formatDuration(mNextNonWakeupDeliveryTime, nowELAPSED, pw);
pw.println();
long nextWakeupRTC = mNextWakeup + (nowRTC - nowELAPSED);
@@ -1948,10 +1949,12 @@
TimeUtils.formatDuration(mNextNonWakeup, nowELAPSED, pw);
pw.print(" = "); pw.print(mNextNonWakeup);
pw.print(" = "); pw.println(sdf.format(new Date(nextNonWakeupRTC)));
+ pw.print(" set at "); TimeUtils.formatDuration(mNextNonWakeUpSetAt, nowELAPSED, pw);
+ pw.println();
pw.print(" Next wakeup alarm: "); TimeUtils.formatDuration(mNextWakeup, nowELAPSED, pw);
pw.print(" = "); pw.print(mNextWakeup);
pw.print(" = "); pw.println(sdf.format(new Date(nextWakeupRTC)));
- pw.print(" set at "); TimeUtils.formatDuration(mLastWakeupSet, nowELAPSED, pw);
+ pw.print(" set at "); TimeUtils.formatDuration(mNextWakeUpSetAt, nowELAPSED, pw);
pw.println();
pw.print(" Next kernel non-wakeup alarm: ");
@@ -2290,7 +2293,7 @@
proto.write(AlarmManagerServiceDumpProto.TIME_SINCE_LAST_WAKEUP_MS,
nowElapsed - mLastWakeup);
proto.write(AlarmManagerServiceDumpProto.TIME_SINCE_LAST_WAKEUP_SET_MS,
- nowElapsed - mLastWakeupSet);
+ nowElapsed - mNextWakeUpSetAt);
proto.write(AlarmManagerServiceDumpProto.TIME_CHANGE_EVENT_COUNT, mNumTimeChanged);
final TreeSet<Integer> users = new TreeSet<>();
@@ -2675,16 +2678,49 @@
DateFormat.format(pattern, info.getTriggerTime()).toString();
}
+ /**
+ * If the last time AlarmThread woke up precedes any due wakeup or non-wakeup alarm that we set
+ * by more than half a minute, log a wtf.
+ */
+ private void validateLastAlarmExpiredLocked(long nowElapsed) {
+ final StringBuilder errorMsg = new StringBuilder();
+ boolean stuck = false;
+ if (mNextNonWakeup < nowElapsed && mLastWakeup < (mNextNonWakeup - 30_000)) {
+ stuck = true;
+ errorMsg.append("[mNextNonWakeup=");
+ TimeUtils.formatDuration(mNextNonWakeup - nowElapsed, errorMsg);
+ errorMsg.append(", mLastWakeup=");
+ TimeUtils.formatDuration(mLastWakeup - nowElapsed, errorMsg);
+ errorMsg.append(", timerfd_gettime=" + getNextAlarm(mNativeData, ELAPSED_REALTIME));
+ errorMsg.append("];");
+ }
+ if (mNextWakeup < nowElapsed && mLastWakeup < (mNextWakeup - 30_000)) {
+ stuck = true;
+ errorMsg.append("[mNextWakeup=");
+ TimeUtils.formatDuration(mNextWakeup - nowElapsed, errorMsg);
+ errorMsg.append(", mLastWakeup=");
+ TimeUtils.formatDuration(mLastWakeup - nowElapsed, errorMsg);
+ errorMsg.append(", timerfd_gettime="
+ + getNextAlarm(mNativeData, ELAPSED_REALTIME_WAKEUP));
+ errorMsg.append("];");
+ }
+ if (stuck) {
+ Slog.wtf(TAG, "Alarm delivery stuck: " + errorMsg.toString());
+ }
+ }
+
void rescheduleKernelAlarmsLocked() {
// Schedule the next upcoming wakeup alarm. If there is a deliverable batch
// prior to that which contains no wakeups, we schedule that as well.
+ final long nowElapsed = SystemClock.elapsedRealtime();
+ validateLastAlarmExpiredLocked(nowElapsed);
long nextNonWakeup = 0;
if (mAlarmBatches.size() > 0) {
final Batch firstWakeup = findFirstWakeupBatchLocked();
final Batch firstBatch = mAlarmBatches.get(0);
if (firstWakeup != null) {
mNextWakeup = firstWakeup.start;
- mLastWakeupSet = SystemClock.elapsedRealtime();
+ mNextWakeUpSetAt = nowElapsed;
setLocked(ELAPSED_REALTIME_WAKEUP, firstWakeup.start);
}
if (firstBatch != firstWakeup) {
@@ -2698,6 +2734,7 @@
}
if (nextNonWakeup != 0) {
mNextNonWakeup = nextNonWakeup;
+ mNextNonWakeUpSetAt = nowElapsed;
setLocked(ELAPSED_REALTIME, nextNonWakeup);
}
}