From bc02a3901dea52d236dd855722191155156cb856 Mon Sep 17 00:00:00 2001 From: Dianne Hackborn Date: Thu, 2 Jun 2016 17:15:08 -0700 Subject: [PATCH] Fix issue #29006049: Add logging for implicit broadcasts 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 --- .../android/server/am/ActivityManagerService.java | 122 ++++++++++++++- .../server/am/ActivityManagerShellCommand.java | 5 +- .../java/com/android/server/am/BroadcastQueue.java | 11 ++ .../com/android/server/am/BroadcastRecord.java | 2 + .../java/com/android/server/am/BroadcastStats.java | 163 +++++++++++++++++++++ .../com/android/server/am/PendingIntentRecord.java | 12 +- 6 files changed, 307 insertions(+), 8 deletions(-) create mode 100644 services/core/java/com/android/server/am/BroadcastStats.java diff --git a/services/core/java/com/android/server/am/ActivityManagerService.java b/services/core/java/com/android/server/am/ActivityManagerService.java index 9229b28e6cb7..32aeea809b87 100644 --- a/services/core/java/com/android/server/am/ActivityManagerService.java +++ b/services/core/java/com/android/server/am/ActivityManagerService.java @@ -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) { diff --git a/services/core/java/com/android/server/am/ActivityManagerShellCommand.java b/services/core/java/com/android/server/am/ActivityManagerShellCommand.java index 9be6b43f21c6..adf6d3670af3 100644 --- a/services/core/java/com/android/server/am/ActivityManagerShellCommand.java +++ b/services/core/java/com/android/server/am/ActivityManagerShellCommand.java @@ -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 | all | current] "); - pw.println(" Complete stop the given application package."); + pw.println(" Completely stop the given application package."); pw.println(" kill [--user | all | current] "); pw.println(" Kill all processes associated with the given application."); pw.println(" kill-all"); diff --git a/services/core/java/com/android/server/am/BroadcastQueue.java b/services/core/java/com/android/server/am/BroadcastQueue.java index 8ffc6f321c3e..88645c1e8afd 100644 --- a/services/core/java/com/android/server/am/BroadcastQueue.java +++ b/services/core/java/com/android/server/am/BroadcastQueue.java @@ -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 diff --git a/services/core/java/com/android/server/am/BroadcastRecord.java b/services/core/java/com/android/server/am/BroadcastRecord.java index e99cbf9e563f..3437ae6195f6 100644 --- a/services/core/java/com/android/server/am/BroadcastRecord.java +++ b/services/core/java/com/android/server/am/BroadcastRecord.java @@ -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 index 000000000000..fdbaada49091 --- /dev/null +++ b/services/core/java/com/android/server/am/BroadcastStats.java @@ -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 mActions = new ArrayMap<>(); + + static final Comparator ACTIONS_COMPARATOR = new Comparator() { + @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 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 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(); + } + } + } +} diff --git a/services/core/java/com/android/server/am/PendingIntentRecord.java b/services/core/java/com/android/server/am/PendingIntentRecord.java index c1ff4dd0e4a3..2467a9094072 100644 --- a/services/core/java/com/android/server/am/PendingIntentRecord.java +++ b/services/core/java/com/android/server/am/PendingIntentRecord.java @@ -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(); -- 2.11.0