Donate to e Foundation | Murena handsets with /e/OS | Own a part of Murena! Learn more

Commit 41c5691a authored by Christopher Tate's avatar Christopher Tate
Browse files

Fix broadcast deferral completion refcounting

Also noticed that we haven't properly tracked time spent in some
registered receivers, and that we've been overly aggressive in applying
deferral policy (deferring per individual receiver slot rather than per
broadcast).  Finally, augmented the debug logging in useful ways.

Bug: 125421639
Bug: 123904494
Test: atest MixedManagedProfileOwnerTest#testSupportMessage
Test: tests/ActivityTests
Test: manual (observe trace logging w/ debug on)
Change-Id: I8afdedef6530c296cedc3a4d284853a9dfbb0eb7
parent ecb35be7
Loading
Loading
Loading
Loading
+3 −1
Original line number Original line Diff line number Diff line
@@ -81,7 +81,9 @@ final class BroadcastFilter extends IntentFilter {
        StringBuilder sb = new StringBuilder();
        StringBuilder sb = new StringBuilder();
        sb.append("BroadcastFilter{");
        sb.append("BroadcastFilter{");
        sb.append(Integer.toHexString(System.identityHashCode(this)));
        sb.append(Integer.toHexString(System.identityHashCode(this)));
        sb.append(" u");
        sb.append(' ');
        sb.append(owningUid);
        sb.append("/u");
        sb.append(owningUserId);
        sb.append(owningUserId);
        sb.append(' ');
        sb.append(' ');
        sb.append(receiverList);
        sb.append(receiverList);
+25 −13
Original line number Original line Diff line number Diff line
@@ -445,7 +445,7 @@ public final class BroadcastQueue {
        final long elapsed = finishTime - r.receiverTime;
        final long elapsed = finishTime - r.receiverTime;
        r.state = BroadcastRecord.IDLE;
        r.state = BroadcastRecord.IDLE;
        if (state == BroadcastRecord.IDLE) {
        if (state == BroadcastRecord.IDLE) {
            Slog.w(TAG, "finishReceiver [" + mQueueName + "] called but state is IDLE");
            Slog.w(TAG_BROADCAST, "finishReceiver [" + mQueueName + "] called but state is IDLE");
        }
        }
        if (r.allowBackgroundActivityStarts && r.curApp != null) {
        if (r.allowBackgroundActivityStarts && r.curApp != null) {
            if (elapsed > mConstants.ALLOW_BG_ACTIVITY_START_TIMEOUT) {
            if (elapsed > mConstants.ALLOW_BG_ACTIVITY_START_TIMEOUT) {
@@ -478,12 +478,13 @@ public final class BroadcastQueue {
        if (!r.timeoutExempt) {
        if (!r.timeoutExempt) {
            if (mConstants.SLOW_TIME > 0 && elapsed > mConstants.SLOW_TIME) {
            if (mConstants.SLOW_TIME > 0 && elapsed > mConstants.SLOW_TIME) {
                if (DEBUG_BROADCAST_DEFERRAL) {
                if (DEBUG_BROADCAST_DEFERRAL) {
                    Slog.i(TAG, "Broadcast receiver was slow: " + receiver + " br=" + r);
                    Slog.i(TAG_BROADCAST, "Broadcast receiver " + (r.nextReceiver - 1)
                            + " was slow: " + receiver + " br=" + r);
                }
                }
                if (r.curApp != null) {
                if (r.curApp != null) {
                    mDispatcher.startDeferring(r.curApp.uid);
                    mDispatcher.startDeferring(r.curApp.uid);
                } else {
                } else {
                    Slog.d(TAG, "finish receiver curApp is null? " + r);
                    Slog.d(TAG_BROADCAST, "finish receiver curApp is null? " + r);
                }
                }
            }
            }
        } else {
        } else {
@@ -796,9 +797,7 @@ public final class BroadcastQueue {
                    skipReceiverLocked(r);
                    skipReceiverLocked(r);
                }
                }
            } else {
            } else {
                if (r.receiverTime == 0) {
                r.receiverTime = SystemClock.uptimeMillis();
                r.receiverTime = SystemClock.uptimeMillis();
                }
                maybeAddAllowBackgroundActivityStartsToken(filter.receiverList.app, r);
                maybeAddAllowBackgroundActivityStartsToken(filter.receiverList.app, r);
                performReceiveLocked(filter.receiverList.app, filter.receiverList.receiver,
                performReceiveLocked(filter.receiverList.app, filter.receiverList.receiver,
                        new Intent(r.intent), r.resultCode, r.resultData,
                        new Intent(r.intent), r.resultCode, r.resultData,
@@ -1083,16 +1082,19 @@ public final class BroadcastQueue {
                        if (newCount == 0) {
                        if (newCount == 0) {
                            // done!  clear out this record's bookkeeping and deliver
                            // done!  clear out this record's bookkeeping and deliver
                            if (DEBUG_BROADCAST_DEFERRAL) {
                            if (DEBUG_BROADCAST_DEFERRAL) {
                                Slog.i(TAG, "Sending broadcast completion for split token "
                                Slog.i(TAG_BROADCAST,
                                        + r.splitToken);
                                        "Sending broadcast completion for split token "
                                        + r.splitToken + " : " + r.intent.getAction());
                            }
                            }
                            mSplitRefcounts.delete(r.splitToken);
                            mSplitRefcounts.delete(r.splitToken);
                        } else {
                        } else {
                            // still have some split broadcast records in flight; update refcount
                            // still have some split broadcast records in flight; update refcount
                            // and hold off on the callback
                            // and hold off on the callback
                            if (DEBUG_BROADCAST_DEFERRAL) {
                            if (DEBUG_BROADCAST_DEFERRAL) {
                                Slog.i(TAG, "Result refcount " + newCount + " for split token "
                                Slog.i(TAG_BROADCAST,
                                        + r.splitToken + " - not sending completion yet");
                                        "Result refcount now " + newCount + " for split token "
                                        + r.splitToken + " : " + r.intent.getAction()
                                        + " - not sending completion yet");
                            }
                            }
                            sendResult = false;
                            sendResult = false;
                            mSplitRefcounts.put(r.splitToken, newCount);
                            mSplitRefcounts.put(r.splitToken, newCount);
@@ -1155,7 +1157,7 @@ public final class BroadcastQueue {
                    BroadcastRecord defer;
                    BroadcastRecord defer;
                    if (r.nextReceiver + 1 == numReceivers) {
                    if (r.nextReceiver + 1 == numReceivers) {
                        if (DEBUG_BROADCAST_DEFERRAL) {
                        if (DEBUG_BROADCAST_DEFERRAL) {
                            Slog.i(TAG, "Sole receiver of " + r
                            Slog.i(TAG_BROADCAST, "Sole receiver of " + r
                                    + " is under deferral; setting aside and proceeding");
                                    + " is under deferral; setting aside and proceeding");
                        }
                        }
                        defer = r;
                        defer = r;
@@ -1185,15 +1187,25 @@ public final class BroadcastQueue {
                                // first split of this record; refcount for 'r' and 'deferred'
                                // first split of this record; refcount for 'r' and 'deferred'
                                r.splitToken = defer.splitToken = nextSplitTokenLocked();
                                r.splitToken = defer.splitToken = nextSplitTokenLocked();
                                mSplitRefcounts.put(r.splitToken, 2);
                                mSplitRefcounts.put(r.splitToken, 2);
                                if (DEBUG_BROADCAST_DEFERRAL) {
                                    Slog.i(TAG_BROADCAST,
                                            "Broadcast needs split refcount; using new token "
                                            + r.splitToken);
                                }
                            } else {
                            } else {
                                // new split from an already-refcounted situation; increment count
                                // new split from an already-refcounted situation; increment count
                                final int curCount = mSplitRefcounts.get(token);
                                final int curCount = mSplitRefcounts.get(token);
                                if (DEBUG_BROADCAST_DEFERRAL) {
                                if (DEBUG_BROADCAST_DEFERRAL) {
                                    if (curCount == 0) {
                                    if (curCount == 0) {
                                        Slog.wtf(TAG, "Split refcount is zero with token for " + r);
                                        Slog.wtf(TAG_BROADCAST,
                                                "Split refcount is zero with token for " + r);
                                    }
                                    }
                                }
                                }
                                mSplitRefcounts.put(token, curCount + 1);
                                mSplitRefcounts.put(token, curCount + 1);
                                if (DEBUG_BROADCAST_DEFERRAL) {
                                    Slog.i(TAG_BROADCAST, "New split count for token " + token
                                            + " is " + (curCount + 1));
                                }
                            }
                            }
                        }
                        }
                    }
                    }
@@ -1529,7 +1541,7 @@ public final class BroadcastQueue {
        if (skip) {
        if (skip) {
            if (DEBUG_BROADCAST)  Slog.v(TAG_BROADCAST,
            if (DEBUG_BROADCAST)  Slog.v(TAG_BROADCAST,
                    "Skipping delivery of ordered [" + mQueueName + "] "
                    "Skipping delivery of ordered [" + mQueueName + "] "
                    + r + " for whatever reason");
                    + r + " for reason described above");
            r.delivery[recIdx] = BroadcastRecord.DELIVERY_SKIPPED;
            r.delivery[recIdx] = BroadcastRecord.DELIVERY_SKIPPED;
            r.receiver = null;
            r.receiver = null;
            r.curFilter = null;
            r.curFilter = null;
+1 −1
Original line number Original line Diff line number Diff line
@@ -332,7 +332,6 @@ final class BroadcastRecord extends Binder {
                }
                }
                splitReceivers.add(o);
                splitReceivers.add(o);
                receivers.remove(i);
                receivers.remove(i);
                break;
            } else {
            } else {
                i++;
                i++;
            }
            }
@@ -350,6 +349,7 @@ final class BroadcastRecord extends Binder {
                resultData, resultExtras, ordered, sticky, initialSticky, userId,
                resultData, resultExtras, ordered, sticky, initialSticky, userId,
                allowBackgroundActivityStarts, timeoutExempt);
                allowBackgroundActivityStarts, timeoutExempt);


        split.splitToken = this.splitToken;
        return split;
        return split;
    }
    }