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);