OSDN Git Service

Fix issue #29006049: Add logging for implicit broadcasts
authorDianne Hackborn <hackbod@google.com>
Fri, 3 Jun 2016 00:15:08 +0000 (17:15 -0700)
committerDianne Hackborn <hackbod@google.com>
Sun, 5 Jun 2016 06:40:12 +0000 (23:40 -0700)
We now have stats on broadcasts.  We collect them over a day and
then reset, retaining the last days stats.  When a checkin happens,
we return either the last day or the current stats and then clear
them.  Not bothing to persist anything to storage, this data is
not that critical.

Change-Id: I1c3b331bcd03f79fa5e10575d9bc2ad7d9104f6f

services/core/java/com/android/server/am/ActivityManagerService.java
services/core/java/com/android/server/am/ActivityManagerShellCommand.java
services/core/java/com/android/server/am/BroadcastQueue.java
services/core/java/com/android/server/am/BroadcastRecord.java
services/core/java/com/android/server/am/BroadcastStats.java [new file with mode: 0644]
services/core/java/com/android/server/am/PendingIntentRecord.java

index 9229b28..32aeea8 100644 (file)
@@ -41,7 +41,6 @@ import com.android.internal.util.FastPrintWriter;
 import com.android.internal.util.FastXmlSerializer;
 import com.android.internal.util.MemInfoReader;
 import com.android.internal.util.Preconditions;
-import com.android.internal.util.ProgressReporter;
 import com.android.server.AppOpsService;
 import com.android.server.AttributeCache;
 import com.android.server.DeviceIdleController;
@@ -98,7 +97,6 @@ import android.app.IUiAutomationConnection;
 import android.app.IUidObserver;
 import android.app.IUserSwitchObserver;
 import android.app.Instrumentation;
-import android.app.KeyguardManager;
 import android.app.Notification;
 import android.app.NotificationManager;
 import android.app.PendingIntent;
@@ -259,12 +257,10 @@ import static android.Manifest.permission.START_TASKS_FROM_RECENTS;
 import static android.app.ActivityManager.DOCKED_STACK_CREATE_MODE_TOP_OR_LEFT;
 import static android.app.ActivityManager.RESIZE_MODE_PRESERVE_WINDOW;
 import static android.app.ActivityManager.StackId.DOCKED_STACK_ID;
-import static android.app.ActivityManager.StackId.FIRST_STATIC_STACK_ID;
 import static android.app.ActivityManager.StackId.FREEFORM_WORKSPACE_STACK_ID;
 import static android.app.ActivityManager.StackId.FULLSCREEN_WORKSPACE_STACK_ID;
 import static android.app.ActivityManager.StackId.HOME_STACK_ID;
 import static android.app.ActivityManager.StackId.INVALID_STACK_ID;
-import static android.app.ActivityManager.StackId.LAST_STATIC_STACK_ID;
 import static android.app.ActivityManager.StackId.PINNED_STACK_ID;
 import static android.content.pm.PackageManager.FEATURE_FREEFORM_WINDOW_MANAGEMENT;
 import static android.content.pm.PackageManager.FEATURE_LEANBACK_ONLY;
@@ -570,6 +566,9 @@ public final class ActivityManagerService extends ActivityManagerNative
     // so that dispatch of foreground broadcasts gets precedence.
     final BroadcastQueue[] mBroadcastQueues = new BroadcastQueue[2];
 
+    BroadcastStats mLastBroadcastStats;
+    BroadcastStats mCurBroadcastStats;
+
     BroadcastQueue broadcastQueueForIntent(Intent intent) {
         final boolean isFg = (intent.getFlags() & Intent.FLAG_RECEIVER_FOREGROUND) != 0;
         if (DEBUG_BROADCAST_BACKGROUND) Slog.i(TAG_BROADCAST,
@@ -13771,6 +13770,8 @@ public final class ActivityManagerService extends ActivityManagerNative
 
         boolean dumpAll = false;
         boolean dumpClient = false;
+        boolean dumpCheckin = false;
+        boolean dumpCheckinFormat = false;
         String dumpPackage = null;
 
         int opti = 0;
@@ -13793,6 +13794,10 @@ public final class ActivityManagerService extends ActivityManagerNative
                     return;
                 }
                 dumpClient = true;
+            } else if ("--checkin".equals(opt)) {
+                dumpCheckin = dumpCheckinFormat = true;
+            } else if ("-C".equals(opt)) {
+                dumpCheckinFormat = true;
             } else if ("-h".equals(opt)) {
                 ActivityManagerShellCommand.dumpHelp(pw, true);
                 return;
@@ -13831,6 +13836,22 @@ public final class ActivityManagerService extends ActivityManagerNative
                 synchronized (this) {
                     dumpBroadcastsLocked(fd, pw, args, opti, true, dumpPackage);
                 }
+            } else if ("broadcast-stats".equals(cmd)) {
+                String[] newArgs;
+                String name;
+                if (opti >= args.length) {
+                    name = null;
+                    newArgs = EMPTY_STRING_ARRAY;
+                } else {
+                    dumpPackage = args[opti];
+                    opti++;
+                    newArgs = new String[args.length - opti];
+                    if (args.length > 2) System.arraycopy(args, opti, newArgs, 0,
+                            args.length - opti);
+                }
+                synchronized (this) {
+                    dumpBroadcastStatsLocked(fd, pw, args, opti, true, dumpPackage);
+                }
             } else if ("intents".equals(cmd) || "i".equals(cmd)) {
                 String[] newArgs;
                 String name;
@@ -13961,7 +13982,9 @@ public final class ActivityManagerService extends ActivityManagerNative
         }
 
         // No piece of data specified, dump everything.
-        if (dumpClient) {
+        if (dumpCheckinFormat) {
+            dumpBroadcastStatsCheckinLocked(fd, pw, args, opti, dumpCheckin, dumpPackage);
+        } else if (dumpClient) {
             ActiveServices.ServiceDumper sdumper;
             synchronized (this) {
                 dumpPendingIntentsLocked(fd, pw, args, opti, dumpAll, dumpPackage);
@@ -13974,6 +13997,13 @@ public final class ActivityManagerService extends ActivityManagerNative
                 if (dumpAll) {
                     pw.println("-------------------------------------------------------------------------------");
                 }
+                if (dumpAll || dumpPackage != null) {
+                    dumpBroadcastStatsLocked(fd, pw, args, opti, dumpAll, dumpPackage);
+                    pw.println();
+                    if (dumpAll) {
+                        pw.println("-------------------------------------------------------------------------------");
+                    }
+                }
                 dumpProvidersLocked(fd, pw, args, opti, dumpAll, dumpPackage);
                 pw.println();
                 if (dumpAll) {
@@ -14025,6 +14055,13 @@ public final class ActivityManagerService extends ActivityManagerNative
                 if (dumpAll) {
                     pw.println("-------------------------------------------------------------------------------");
                 }
+                if (dumpAll || dumpPackage != null) {
+                    dumpBroadcastStatsLocked(fd, pw, args, opti, dumpAll, dumpPackage);
+                    pw.println();
+                    if (dumpAll) {
+                        pw.println("-------------------------------------------------------------------------------");
+                    }
+                }
                 dumpProvidersLocked(fd, pw, args, opti, dumpAll, dumpPackage);
                 pw.println();
                 if (dumpAll) {
@@ -14975,6 +15012,58 @@ public final class ActivityManagerService extends ActivityManagerNative
         }
     }
 
+    void dumpBroadcastStatsLocked(FileDescriptor fd, PrintWriter pw, String[] args,
+            int opti, boolean dumpAll, String dumpPackage) {
+        if (mCurBroadcastStats == null) {
+            return;
+        }
+
+        pw.println("ACTIVITY MANAGER BROADCAST STATS STATE (dumpsys activity broadcast-stats)");
+        final long now = SystemClock.elapsedRealtime();
+        if (mLastBroadcastStats != null) {
+            pw.print("  Last stats (from ");
+            TimeUtils.formatDuration(mLastBroadcastStats.mStartRealtime, now, pw);
+            pw.print(" to ");
+            TimeUtils.formatDuration(mLastBroadcastStats.mEndRealtime, now, pw);
+            pw.print(", ");
+            TimeUtils.formatDuration(mLastBroadcastStats.mEndUptime
+                    - mLastBroadcastStats.mStartUptime, pw);
+            pw.println(" uptime):");
+            if (!mLastBroadcastStats.dumpStats(pw, "    ", dumpPackage)) {
+                pw.println("    (nothing)");
+            }
+            pw.println();
+        }
+        pw.print("  Current stats (from ");
+        TimeUtils.formatDuration(mCurBroadcastStats.mStartRealtime, now, pw);
+        pw.print(" to now, ");
+        TimeUtils.formatDuration(SystemClock.uptimeMillis()
+                - mCurBroadcastStats.mStartUptime, pw);
+        pw.println(" uptime):");
+        if (!mCurBroadcastStats.dumpStats(pw, "    ", dumpPackage)) {
+            pw.println("    (nothing)");
+        }
+    }
+
+    void dumpBroadcastStatsCheckinLocked(FileDescriptor fd, PrintWriter pw, String[] args,
+            int opti, boolean fullCheckin, String dumpPackage) {
+        if (mCurBroadcastStats == null) {
+            return;
+        }
+
+        if (mLastBroadcastStats != null) {
+            mLastBroadcastStats.dumpCheckinStats(pw, dumpPackage);
+            if (fullCheckin) {
+                mLastBroadcastStats = null;
+                return;
+            }
+        }
+        mCurBroadcastStats.dumpCheckinStats(pw, dumpPackage);
+        if (fullCheckin) {
+            mCurBroadcastStats = null;
+        }
+    }
+
     void dumpProvidersLocked(FileDescriptor fd, PrintWriter pw, String[] args,
             int opti, boolean dumpAll, String dumpPackage) {
         boolean needSep;
@@ -17943,11 +18032,34 @@ public final class ActivityManagerService extends ActivityManagerNative
                 queue.enqueueOrderedBroadcastLocked(r);
                 queue.scheduleBroadcastsLocked();
             }
+        } else {
+            // There was nobody interested in the broadcast, but we still want to record
+            // that it happened.
+            if (intent.getComponent() == null && intent.getPackage() == null
+                    && (intent.getFlags()&Intent.FLAG_RECEIVER_REGISTERED_ONLY) == 0) {
+                // This was an implicit broadcast... let's record it for posterity.
+                addBroadcastStatLocked(intent.getAction(), callerPackage, 0, 0, 0);
+            }
         }
 
         return ActivityManager.BROADCAST_SUCCESS;
     }
 
+    final void addBroadcastStatLocked(String action, String srcPackage, int receiveCount,
+            int skipCount, long dispatchTime) {
+        final long now = SystemClock.elapsedRealtime();
+        if (mCurBroadcastStats == null ||
+                (mCurBroadcastStats.mStartRealtime +(24*60*60*1000) < now)) {
+            mLastBroadcastStats = mCurBroadcastStats;
+            if (mLastBroadcastStats != null) {
+                mLastBroadcastStats.mEndRealtime = SystemClock.elapsedRealtime();
+                mLastBroadcastStats.mEndUptime = SystemClock.uptimeMillis();
+            }
+            mCurBroadcastStats = new BroadcastStats();
+        }
+        mCurBroadcastStats.addBroadcast(action, srcPackage, receiveCount, skipCount, dispatchTime);
+    }
+
     final Intent verifyBroadcastLocked(Intent intent) {
         // Refuse possible leaked file descriptors
         if (intent != null && intent.hasFileDescriptors() == true) {
index 9be6b43..adf6d36 100644 (file)
@@ -197,6 +197,7 @@ class ActivityManagerShellCommand extends ShellCommand {
             pw.println("    a[ctivities]: activity stack state");
             pw.println("    r[recents]: recent activities state");
             pw.println("    b[roadcasts] [PACKAGE_NAME] [history [-s]]: broadcast state");
+            pw.println("    broadcast-stats [PACKAGE_NAME]: aggregated broadcast statistics");
             pw.println("    i[ntents] [PACKAGE_NAME]: pending intent state");
             pw.println("    p[rocesses] [PACKAGE_NAME]: process state");
             pw.println("    o[om]: out of memory management");
@@ -216,12 +217,14 @@ class ActivityManagerShellCommand extends ShellCommand {
             pw.println("  -a: include all available server state.");
             pw.println("  -c: include client state.");
             pw.println("  -p: limit output to given package.");
+            pw.println("  --checkin: output checkin format, resetting data.");
+            pw.println("  --C: output checkin format, not resetting data.");
         } else {
             pw.println("Activity manager (activity) commands:");
             pw.println("  help");
             pw.println("    Print this help text.");
             pw.println("  force-stop [--user <USER_ID> | all | current] <PACKAGE>");
-            pw.println("    Complete stop the given application package.");
+            pw.println("    Completely stop the given application package.");
             pw.println("  kill [--user <USER_ID> | all | current] <PACKAGE>");
             pw.println("    Kill all processes associated with the given application.");
             pw.println("  kill-all");
index 8ffc6f3..88645c1 100644 (file)
@@ -898,6 +898,12 @@ public final class BroadcastQueue {
 
                     // ... and on to the next...
                     addBroadcastToHistoryLocked(r);
+                    if (r.intent.getComponent() == null && r.intent.getPackage() == null
+                            && (r.intent.getFlags()&Intent.FLAG_RECEIVER_REGISTERED_ONLY) == 0) {
+                        // This was an implicit broadcast... let's record it for posterity.
+                        mService.addBroadcastStatLocked(r.intent.getAction(), r.callerPackage,
+                                r.manifestCount, r.manifestSkipCount, r.finishTime-r.dispatchTime);
+                    }
                     mOrderedBroadcasts.remove(0);
                     r = null;
                     looped = true;
@@ -1083,6 +1089,11 @@ public final class BroadcastQueue {
                     skip = true;
                 }
             }
+            if (!skip) {
+                r.manifestCount++;
+            } else {
+                r.manifestSkipCount++;
+            }
             if (r.curApp != null && r.curApp.crashing) {
                 // If the target process is crashing, just skip it.
                 Slog.w(TAG, "Skipping deliver ordered [" + mQueueName + "] " + r
index e99cbf9..3437ae6 100644 (file)
@@ -72,6 +72,8 @@ final class BroadcastRecord extends Binder {
     IBinder receiver;       // who is currently running, null if none.
     int state;
     int anrCount;           // has this broadcast record hit any ANRs?
+    int manifestCount;      // number of manifest receivers dispatched.
+    int manifestSkipCount;  // number of manifest receivers skipped.
     BroadcastQueue queue;   // the outbound queue handling this broadcast
 
     static final int IDLE = 0;
diff --git a/services/core/java/com/android/server/am/BroadcastStats.java b/services/core/java/com/android/server/am/BroadcastStats.java
new file mode 100644 (file)
index 0000000..fdbaada
--- /dev/null
@@ -0,0 +1,163 @@
+/*
+ * Copyright (C) 2016 The Android Open Source Project
+ *
+ * Licensed under the Apache License, Version 2.0 (the "License");
+ * you may not use this file except in compliance with the License.
+ * You may obtain a copy of the License at
+ *
+ *      http://www.apache.org/licenses/LICENSE-2.0
+ *
+ * Unless required by applicable law or agreed to in writing, software
+ * distributed under the License is distributed on an "AS IS" BASIS,
+ * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
+ * See the License for the specific language governing permissions and
+ * limitations under the License.
+ */
+
+package com.android.server.am;
+
+import android.os.SystemClock;
+import android.util.ArrayMap;
+import android.util.TimeUtils;
+
+import java.io.PrintWriter;
+import java.util.ArrayList;
+import java.util.Collections;
+import java.util.Comparator;
+
+public final class BroadcastStats {
+    final long mStartRealtime;
+    final long mStartUptime;
+    long mEndRealtime;
+    long mEndUptime;
+    final ArrayMap<String, ActionEntry> mActions = new ArrayMap<>();
+
+    static final Comparator<ActionEntry> ACTIONS_COMPARATOR = new Comparator<ActionEntry>() {
+        @Override public int compare(ActionEntry o1, ActionEntry o2) {
+            if (o1.mTotalDispatchTime < o2.mTotalDispatchTime) {
+                return -1;
+            }
+            if (o1.mTotalDispatchTime > o2.mTotalDispatchTime) {
+                return 1;
+            }
+            return 0;
+        }
+    };
+
+    static final class ActionEntry {
+        final String mAction;
+        final ArrayMap<String, PackageEntry> mPackages = new ArrayMap<>();
+        int mReceiveCount;
+        int mSkipCount;
+        long mTotalDispatchTime;
+        long mMaxDispatchTime;
+
+        ActionEntry(String action) {
+            mAction = action;
+        }
+    }
+
+    static final class PackageEntry {
+        int mSendCount;
+    }
+
+    public BroadcastStats() {
+        mStartRealtime = SystemClock.elapsedRealtime();
+        mStartUptime = SystemClock.uptimeMillis();
+    }
+
+    public void addBroadcast(String action, String srcPackage, int receiveCount,
+            int skipCount, long dispatchTime) {
+        ActionEntry ae = mActions.get(action);
+        if (ae == null) {
+            ae = new ActionEntry(action);
+            mActions.put(action, ae);
+        }
+        ae.mReceiveCount += receiveCount;
+        ae.mSkipCount += skipCount;
+        ae.mTotalDispatchTime += dispatchTime;
+        if (ae.mMaxDispatchTime < dispatchTime) {
+            ae.mMaxDispatchTime = dispatchTime;
+        }
+        PackageEntry pe = ae.mPackages.get(srcPackage);
+        if (pe == null) {
+            pe = new PackageEntry();
+            ae.mPackages.put(srcPackage, pe);
+        }
+        pe.mSendCount++;
+    }
+
+    public boolean dumpStats(PrintWriter pw, String prefix, String dumpPackage) {
+        boolean printedSomething = false;
+        ArrayList<ActionEntry> actions = new ArrayList<>(mActions.size());
+        for (int i=mActions.size()-1; i>=0; i--) {
+            actions.add(mActions.valueAt(i));
+        }
+        Collections.sort(actions, ACTIONS_COMPARATOR);
+        for (int i=actions.size()-1; i>=0; i--) {
+            ActionEntry ae = actions.get(i);
+            if (dumpPackage != null && !ae.mPackages.containsKey(dumpPackage)) {
+                continue;
+            }
+            printedSomething = true;
+            pw.print(prefix);
+            pw.print(ae.mAction);
+            pw.println(":");
+            pw.print(prefix);
+            pw.print("  Number received: ");
+            pw.print(ae.mReceiveCount);
+            pw.print(", skipped: ");
+            pw.println(ae.mSkipCount);
+            pw.print(prefix);
+            pw.print("  Total dispatch time: ");
+            TimeUtils.formatDuration(ae.mTotalDispatchTime, pw);
+            pw.print(", max: ");
+            TimeUtils.formatDuration(ae.mMaxDispatchTime, pw);
+            pw.println();
+            for (int j=ae.mPackages.size()-1; j>=0; j--) {
+                pw.print(prefix);
+                pw.print("  Package ");
+                pw.print(ae.mPackages.keyAt(j));
+                pw.print(": ");
+                PackageEntry pe = ae.mPackages.valueAt(j);
+                pw.print(pe.mSendCount);
+                pw.println(" times");
+            }
+        }
+        return printedSomething;
+    }
+
+    public void dumpCheckinStats(PrintWriter pw, String dumpPackage) {
+        pw.print("broadcast-stats,1,");
+        pw.print(mStartRealtime);
+        pw.print(",");
+        pw.print(mEndRealtime == 0 ? SystemClock.elapsedRealtime() : mEndRealtime);
+        pw.print(",");
+        pw.println((mEndUptime == 0 ? SystemClock.uptimeMillis() : mEndUptime) - mStartUptime);
+        for (int i=mActions.size()-1; i>=0; i--) {
+            ActionEntry ae = mActions.valueAt(i);
+            if (dumpPackage != null && !ae.mPackages.containsKey(dumpPackage)) {
+                continue;
+            }
+            pw.print("a,");
+            pw.print(mActions.keyAt(i));
+            pw.print(",");
+            pw.print(ae.mReceiveCount);
+            pw.print(",");
+            pw.print(ae.mSkipCount);
+            pw.print(",");
+            pw.print(ae.mTotalDispatchTime);
+            pw.print(",");
+            pw.print(ae.mMaxDispatchTime);
+            pw.println();
+            for (int j=ae.mPackages.size()-1; j>=0; j--) {
+                pw.print("p,");
+                pw.print(ae.mPackages.keyAt(j));
+                PackageEntry pe = ae.mPackages.valueAt(j);
+                pw.print(",");
+                pw.print(pe.mSendCount);
+                pw.println();
+            }
+        }
+    }
+}
index c1ff4dd..2467a90 100644 (file)
@@ -32,6 +32,7 @@ import android.os.RemoteException;
 import android.os.TransactionTooLargeException;
 import android.os.UserHandle;
 import android.util.Slog;
+import android.util.TimeUtils;
 
 import com.android.server.am.ActivityStackSupervisor.ActivityContainer;
 
@@ -397,7 +398,12 @@ final class PendingIntentRecord extends IIntentSender.Stub {
             pw.print(prefix); pw.print("sent="); pw.print(sent);
                     pw.print(" canceled="); pw.println(canceled);
         }
-        pw.print(prefix); pw.println("whitelistDuration="); pw.println(whitelistDuration);
+        if (whitelistDuration != 0) {
+            pw.print(prefix);
+            pw.print("whitelistDuration=");
+            TimeUtils.formatDuration(whitelistDuration, pw);
+            pw.println();
+        }
     }
 
     public String toString() {
@@ -412,7 +418,9 @@ final class PendingIntentRecord extends IIntentSender.Stub {
         sb.append(' ');
         sb.append(key.typeName());
         if (whitelistDuration > 0) {
-            sb.append( " (whitelistDuration: ").append(whitelistDuration).append("ms)");
+            sb.append( " (whitelist: ");
+            TimeUtils.formatDuration(whitelistDuration, sb);
+            sb.append(")");
         }
         sb.append('}');
         return stringName = sb.toString();