Debugging for issue #2250075: Desk dock clock app sometimes doesn't
This adds a history of the last 100 broadcasts that is printed in the
debug log, to be able to see what recently happened at the time the
bug report was taken. Also does some optimization of the printing of
the broadcast records to make it feasible to print this number of
entries. (We kind-of need to do this because there are some broadcasts
like SIG_STR and SYNC_STATE_CHANGED that are being broadcast a LOT.)
Change-Id: I775e1ec0f63369c8bca8c83cee27b95ddc5ec450
diff --git a/services/java/com/android/server/am/ActivityManagerService.java b/services/java/com/android/server/am/ActivityManagerService.java
index c3aeca4..cb9984a 100644
--- a/services/java/com/android/server/am/ActivityManagerService.java
+++ b/services/java/com/android/server/am/ActivityManagerService.java
@@ -410,6 +410,13 @@
= new ArrayList<BroadcastRecord>();
/**
+ * Historical data of past broadcasts, for debugging.
+ */
+ static final int MAX_BROADCAST_HISTORY = 100;
+ final BroadcastRecord[] mBroadcastHistory
+ = new BroadcastRecord[MAX_BROADCAST_HISTORY];
+
+ /**
* Set when we current have a BROADCAST_INTENT_MSG in flight.
*/
boolean mBroadcastsScheduled = false;
@@ -9392,6 +9399,17 @@
}
pw.println(" ");
+ pw.println(" Historical broadcasts:");
+ for (int i=0; i<MAX_BROADCAST_HISTORY; i++) {
+ BroadcastRecord r = mBroadcastHistory[i];
+ if (r == null) {
+ break;
+ }
+ pw.println(" Historical Broadcast #" + i + ":");
+ r.dump(pw, " ");
+ }
+
+ pw.println(" ");
pw.println(" mBroadcastsScheduled=" + mBroadcastsScheduled);
if (mStickyBroadcasts != null) {
pw.println(" ");
@@ -11610,7 +11628,7 @@
Intent intent = (Intent)allSticky.get(i);
BroadcastRecord r = new BroadcastRecord(intent, null,
null, -1, -1, null, receivers, null, 0, null, null,
- false, true);
+ false, true, true);
if (mParallelBroadcasts.size() == 0) {
scheduleBroadcastsLocked();
}
@@ -11835,7 +11853,7 @@
BroadcastRecord r = new BroadcastRecord(intent, callerApp,
callerPackage, callingPid, callingUid, requiredPermission,
registeredReceivers, resultTo, resultCode, resultData, map,
- ordered, false);
+ ordered, sticky, false);
if (DEBUG_BROADCAST) Log.v(
TAG, "Enqueueing parallel broadcast " + r
+ ": prev had " + mParallelBroadcasts.size());
@@ -11914,7 +11932,8 @@
|| resultTo != null) {
BroadcastRecord r = new BroadcastRecord(intent, callerApp,
callerPackage, callingPid, callingUid, requiredPermission,
- receivers, resultTo, resultCode, resultData, map, ordered, false);
+ receivers, resultTo, resultCode, resultData, map, ordered,
+ sticky, false);
if (DEBUG_BROADCAST) Log.v(
TAG, "Enqueueing ordered broadcast " + r
+ ": prev had " + mOrderedBroadcasts.size());
@@ -12132,17 +12151,17 @@
}
long now = SystemClock.uptimeMillis();
BroadcastRecord r = mOrderedBroadcasts.get(0);
- if ((r.startTime+BROADCAST_TIMEOUT) > now) {
+ if ((r.receiverTime+BROADCAST_TIMEOUT) > now) {
if (DEBUG_BROADCAST) Log.v(TAG,
"Premature timeout @ " + now + ": resetting BROADCAST_TIMEOUT_MSG for "
- + (r.startTime + BROADCAST_TIMEOUT));
+ + (r.receiverTime + BROADCAST_TIMEOUT));
Message msg = mHandler.obtainMessage(BROADCAST_TIMEOUT_MSG);
- mHandler.sendMessageAtTime(msg, r.startTime+BROADCAST_TIMEOUT);
+ mHandler.sendMessageAtTime(msg, r.receiverTime+BROADCAST_TIMEOUT);
return;
}
Log.w(TAG, "Timeout of broadcast " + r + " - receiver=" + r.receiver);
- r.startTime = now;
+ r.receiverTime = now;
r.anrCount++;
// Current receiver has passed its expiration date.
@@ -12290,7 +12309,7 @@
}
performReceive(filter.receiverList.app, filter.receiverList.receiver,
new Intent(r.intent), r.resultCode,
- r.resultData, r.resultExtras, r.ordered, r.sticky);
+ r.resultData, r.resultExtras, r.ordered, r.initialSticky);
if (ordered) {
r.state = BroadcastRecord.CALL_DONE_RECEIVE;
}
@@ -12308,6 +12327,17 @@
}
}
+ private final void addBroadcastToHistoryLocked(BroadcastRecord r) {
+ if (r.callingUid < 0) {
+ // This was from a registerReceiver() call; ignore it.
+ return;
+ }
+ System.arraycopy(mBroadcastHistory, 0, mBroadcastHistory, 1,
+ MAX_BROADCAST_HISTORY-1);
+ r.finishTime = SystemClock.uptimeMillis();
+ mBroadcastHistory[0] = r;
+ }
+
private final void processNextBroadcast(boolean fromMsg) {
synchronized(this) {
BroadcastRecord r;
@@ -12325,6 +12355,7 @@
// First, deliver any non-serialized broadcasts right away.
while (mParallelBroadcasts.size() > 0) {
r = mParallelBroadcasts.remove(0);
+ r.dispatchTime = SystemClock.uptimeMillis();
final int N = r.receivers.size();
if (DEBUG_BROADCAST_LIGHT) Log.v(TAG, "Processing parallel broadcast "
+ r);
@@ -12335,6 +12366,7 @@
+ target + ": " + r);
deliverToRegisteredReceiver(r, (BroadcastFilter)target, false);
}
+ addBroadcastToHistoryLocked(r);
if (DEBUG_BROADCAST_LIGHT) Log.v(TAG, "Done with parallel broadcast "
+ r);
}
@@ -12392,7 +12424,7 @@
Log.w(TAG, "Hung broadcast discarded after timeout failure:"
+ " now=" + now
+ " dispatchTime=" + r.dispatchTime
- + " startTime=" + r.startTime
+ + " startTime=" + r.receiverTime
+ " intent=" + r.intent
+ " numReceivers=" + numReceivers
+ " nextReceiver=" + r.nextReceiver
@@ -12436,6 +12468,7 @@
+ r);
// ... and on to the next...
+ addBroadcastToHistoryLocked(r);
mOrderedBroadcasts.remove(0);
r = null;
looped = true;
@@ -12448,17 +12481,17 @@
// Keep track of when this receiver started, and make sure there
// is a timeout message pending to kill it if need be.
- r.startTime = SystemClock.uptimeMillis();
+ r.receiverTime = SystemClock.uptimeMillis();
if (recIdx == 0) {
- r.dispatchTime = r.startTime;
+ r.dispatchTime = r.receiverTime;
if (DEBUG_BROADCAST_LIGHT) Log.v(TAG, "Processing ordered broadcast "
+ r);
if (DEBUG_BROADCAST) Log.v(TAG,
"Submitting BROADCAST_TIMEOUT_MSG for "
- + (r.startTime + BROADCAST_TIMEOUT));
+ + (r.receiverTime + BROADCAST_TIMEOUT));
Message msg = mHandler.obtainMessage(BROADCAST_TIMEOUT_MSG);
- mHandler.sendMessageAtTime(msg, r.startTime+BROADCAST_TIMEOUT);
+ mHandler.sendMessageAtTime(msg, r.receiverTime+BROADCAST_TIMEOUT);
}
Object nextReceiver = r.receivers.get(recIdx);
diff --git a/services/java/com/android/server/am/BroadcastFilter.java b/services/java/com/android/server/am/BroadcastFilter.java
index 0eeb393..2e784d3 100644
--- a/services/java/com/android/server/am/BroadcastFilter.java
+++ b/services/java/com/android/server/am/BroadcastFilter.java
@@ -39,8 +39,16 @@
receiverList.dumpLocal(pw, prefix);
}
+ public void dumpBrief(PrintWriter pw, String prefix) {
+ dumpBroadcastFilterState(pw, prefix);
+ }
+
public void dumpInReceiverList(PrintWriter pw, Printer pr, String prefix) {
super.dump(pr, prefix);
+ dumpBroadcastFilterState(pw, prefix);
+ }
+
+ void dumpBroadcastFilterState(PrintWriter pw, String prefix) {
if (requiredPermission != null) {
pw.print(prefix); pw.print("requiredPermission="); pw.println(requiredPermission);
}
diff --git a/services/java/com/android/server/am/BroadcastRecord.java b/services/java/com/android/server/am/BroadcastRecord.java
index db0a6cb..75c9600 100644
--- a/services/java/com/android/server/am/BroadcastRecord.java
+++ b/services/java/com/android/server/am/BroadcastRecord.java
@@ -41,11 +41,13 @@
final int callingUid; // the uid of who sent this
final boolean ordered; // serialize the send to receivers?
final boolean sticky; // originated from existing sticky data?
+ final boolean initialSticky; // initial broadcast from register to sticky?
final String requiredPermission; // a permission the caller has required
final List receivers; // contains BroadcastFilter and ResolveInfo
final IIntentReceiver resultTo; // who receives final result if non-null
long dispatchTime; // when dispatch started on this set of receivers
- long startTime; // when current receiver started for timeouts.
+ long receiverTime; // when current receiver started for timeouts.
+ long finishTime; // when we finished the broadcast.
int resultCode; // current result code value.
String resultData; // current result data value.
Bundle resultExtras; // current result extra data values.
@@ -73,28 +75,55 @@
void dump(PrintWriter pw, String prefix) {
pw.println(prefix + this);
pw.println(prefix + intent);
+ if (sticky) {
+ Bundle bundle = intent.getExtras();
+ if (bundle != null) {
+ pw.println(prefix + "extras: " + bundle.toString());
+ }
+ }
pw.println(prefix + "proc=" + callerApp);
pw.println(prefix + "caller=" + callerPackage
+ " callingPid=" + callingPid
+ " callingUid=" + callingUid);
- pw.println(prefix + "requiredPermission=" + requiredPermission);
+ if (requiredPermission != null) {
+ pw.println(prefix + "requiredPermission=" + requiredPermission);
+ }
pw.println(prefix + "dispatchTime=" + dispatchTime + " ("
- + (SystemClock.uptimeMillis()-dispatchTime) + " since now)");
- pw.println(prefix + "startTime=" + startTime + " ("
- + (SystemClock.uptimeMillis()-startTime) + " since now)");
- pw.println(prefix + "anrCount=" + anrCount);
- pw.println(prefix + "resultTo=" + resultTo
- + " resultCode=" + resultCode + " resultData=" + resultData);
- pw.println(prefix + "resultExtras=" + resultExtras);
- pw.println(prefix + "resultAbort=" + resultAbort
- + " ordered=" + ordered + " sticky=" + sticky);
- pw.println(prefix + "nextReceiver=" + nextReceiver
- + " receiver=" + receiver);
- pw.println(prefix + "curFilter=" + curFilter);
- pw.println(prefix + "curReceiver="
- + ((curReceiver != null) ? curReceiver : "(null)"));
- pw.println(prefix + "curApp=" + curApp);
+ + (SystemClock.uptimeMillis()-dispatchTime) + "ms since now)");
+ if (finishTime != 0) {
+ pw.println(prefix + "finishTime=" + finishTime + " ("
+ + (SystemClock.uptimeMillis()-finishTime) + "ms since now)");
+ } else {
+ pw.println(prefix + "receiverTime=" + receiverTime + " ("
+ + (SystemClock.uptimeMillis()-receiverTime) + "ms since now)");
+ }
+ if (anrCount != 0) {
+ pw.println(prefix + "anrCount=" + anrCount);
+ }
+ if (resultTo != null || resultCode != -1 || resultData != null) {
+ pw.println(prefix + "resultTo=" + resultTo
+ + " resultCode=" + resultCode + " resultData=" + resultData);
+ }
+ if (resultExtras != null) {
+ pw.println(prefix + "resultExtras=" + resultExtras);
+ }
+ if (resultAbort || ordered || sticky || initialSticky) {
+ pw.println(prefix + "resultAbort=" + resultAbort
+ + " ordered=" + ordered + " sticky=" + sticky
+ + " initialSticky=" + initialSticky);
+ }
+ if (nextReceiver != 0 || receiver != null) {
+ pw.println(prefix + "nextReceiver=" + nextReceiver
+ + " receiver=" + receiver);
+ }
+ if (curFilter != null) {
+ pw.println(prefix + "curFilter=" + curFilter);
+ }
+ if (curReceiver != null) {
+ pw.println(prefix + "curReceiver=" + curReceiver);
+ }
if (curApp != null) {
+ pw.println(prefix + "curApp=" + curApp);
pw.println(prefix + "curComponent="
+ (curComponent != null ? curComponent.toShortString() : "--"));
pw.println(prefix + "curSourceDir=" + curReceiver.applicationInfo.sourceDir);
@@ -114,7 +143,7 @@
Object o = receivers.get(i);
pw.println(prefix + "Receiver #" + i + ": " + o);
if (o instanceof BroadcastFilter)
- ((BroadcastFilter)o).dump(pw, p2);
+ ((BroadcastFilter)o).dumpBrief(pw, p2);
else if (o instanceof ResolveInfo)
((ResolveInfo)o).dump(printer, p2);
}
@@ -124,7 +153,7 @@
int _callingPid, int _callingUid, String _requiredPermission,
List _receivers, IIntentReceiver _resultTo, int _resultCode,
String _resultData, Bundle _resultExtras, boolean _serialized,
- boolean _sticky) {
+ boolean _sticky, boolean _initialSticky) {
intent = _intent;
callerApp = _callerApp;
callerPackage = _callerPackage;
@@ -138,6 +167,7 @@
resultExtras = _resultExtras;
ordered = _serialized;
sticky = _sticky;
+ initialSticky = _initialSticky;
nextReceiver = 0;
state = IDLE;
}