From 21e9f196a861601712f0b1029d9398d2311a6c3f Mon Sep 17 00:00:00 2001
From: Christopher Tate <ctate@google.com>
Date: Tue, 8 Aug 2017 13:49:11 -0700
Subject: [PATCH] Light alarm activity tracing

Looking for a better grip on losing track of in-flight alarms.

Bug 64358454
Test: manual

Change-Id: I49c65dbdd9c89893ba584b192ec9917e0ff1dede
---
 .../com/android/server/AlarmManagerService.java    | 24 ++++++++++++++++++++--
 1 file changed, 22 insertions(+), 2 deletions(-)

diff --git a/services/core/java/com/android/server/AlarmManagerService.java b/services/core/java/com/android/server/AlarmManagerService.java
index e860dd6f39dd..be4d1064ec9c 100644
--- a/services/core/java/com/android/server/AlarmManagerService.java
+++ b/services/core/java/com/android/server/AlarmManagerService.java
@@ -32,7 +32,6 @@ import android.content.Context;
 import android.content.Intent;
 import android.content.IntentFilter;
 import android.content.pm.ApplicationInfo;
-import android.content.pm.PackageInfo;
 import android.content.pm.PackageManager;
 import android.content.pm.PackageManager.NameNotFoundException;
 import android.content.pm.PermissionInfo;
@@ -85,6 +84,7 @@ import static android.app.AlarmManager.RTC;
 import static android.app.AlarmManager.ELAPSED_REALTIME_WAKEUP;
 import static android.app.AlarmManager.ELAPSED_REALTIME;
 
+import com.android.internal.annotations.GuardedBy;
 import com.android.internal.util.DumpUtils;
 import com.android.internal.util.LocalLog;
 
@@ -1567,6 +1567,8 @@ class AlarmManagerService extends SystemService {
 
             pw.println();
             pw.print("  Broadcast ref count: "); pw.println(mBroadcastRefCount);
+            pw.print("  PendingIntent send/finish count: "); pw.println(mSendCount);
+            pw.print("  Listener send/complete count: "); pw.println(mListenerCount);
             pw.println();
 
             if (mInFlight.size() > 0) {
@@ -2939,7 +2941,18 @@ class AlarmManagerService extends SystemService {
         return bs;
     }
 
+    /**
+     * Canonical count of (operation.send() - onSendFinished()) and
+     * listener send/complete/timeout invocations.
+     * Guarded by the usual lock.
+     */
+    @GuardedBy("mLock")
+    private int mSendCount = 0;
+    @GuardedBy("mLock")
+    private int mListenerCount = 0;
+
     class DeliveryTracker extends IAlarmCompleteListener.Stub implements PendingIntent.OnFinished {
+
         private InFlight removeLocked(PendingIntent pi, Intent intent) {
             for (int i = 0; i < mInFlight.size(); i++) {
                 if (mInFlight.get(i).mPendingIntent == pi) {
@@ -3026,7 +3039,7 @@ class AlarmManagerService extends SystemService {
         @Override
         public void alarmComplete(IBinder who) {
             if (who == null) {
-                Slog.w(TAG, "Invalid alarmComplete: uid=" + Binder.getCallingUid()
+                mLog.w("Invalid alarmComplete: uid=" + Binder.getCallingUid()
                         + " pid=" + Binder.getCallingPid());
                 return;
             }
@@ -3041,6 +3054,7 @@ class AlarmManagerService extends SystemService {
                             Slog.i(TAG, "alarmComplete() from " + who);
                         }
                         updateTrackingLocked(inflight);
+                        mListenerCount--;
                     } else {
                         // Delivery timed out, and the timeout handling already took care of
                         // updating our tracking here, so we needn't do anything further.
@@ -3061,6 +3075,7 @@ class AlarmManagerService extends SystemService {
         public void onSendFinished(PendingIntent pi, Intent intent, int resultCode,
                 String resultData, Bundle resultExtras) {
             synchronized (mLock) {
+                mSendCount--;
                 updateTrackingLocked(removeLocked(pi, intent));
             }
         }
@@ -3077,10 +3092,12 @@ class AlarmManagerService extends SystemService {
                         Slog.i(TAG, "Alarm listener " + who + " timed out in delivery");
                     }
                     updateTrackingLocked(inflight);
+                    mListenerCount--;
                 } else {
                     if (DEBUG_LISTENER_CALLBACK) {
                         Slog.i(TAG, "Spurious timeout of listener " + who);
                     }
+                    mLog.w("Spurious timeout of listener " + who);
                 }
             }
         }
@@ -3091,6 +3108,7 @@ class AlarmManagerService extends SystemService {
         public void deliverLocked(Alarm alarm, long nowELAPSED, boolean allowWhileIdle) {
             if (alarm.operation != null) {
                 // PendingIntent alarm
+                mSendCount++;
                 try {
                     alarm.operation.send(getContext(), 0,
                             mBackgroundIntent.putExtra(
@@ -3107,10 +3125,12 @@ class AlarmManagerService extends SystemService {
                     // 'finished' callback won't be invoked.  We also don't need
                     // to do any wakelock or stats tracking, so we have nothing
                     // left to do here but go on to the next thing.
+                    mSendCount--;
                     return;
                 }
             } else {
                 // Direct listener callback alarm
+                mListenerCount++;
                 try {
                     if (DEBUG_LISTENER_CALLBACK) {
                         Slog.v(TAG, "Alarm to uid=" + alarm.uid
-- 
2.11.0