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

Commit 4568a30b authored by Jeff Sharkey's avatar Jeff Sharkey
Browse files

BroadcastQueue: misc debugging, fix runnable bug.

Add new per-reciever fields to BroadcastRecord dump information, where
we have both "scheduled" and "terminal" timestamps.  Update legacy
stack to also record these timestamps for consistent dumps.  Update
modern stack to record overall dispatch and finish times.

Add "reason" behind per-process queue runnable calculation, aiding
debugging of why a process might be delayed or paused.  Simplify dump
of per-process queue to omit redundant details.

Fix subtle bug when skipping broadcasts, where we might need to update
sorted runnable list position if we modified the queue.  Consistency
check logic to help identify bugs.

Bug: 249389115
Test: atest FrameworksMockingServicesTests:BroadcastQueueTest
Test: atest FrameworksMockingServicesTests:BroadcastQueueModernImplTest
Change-Id: I73c442f749fba9c461a67debfa871ffcd0dda086
parent a4c77ee3
Loading
Loading
Loading
Loading
+109 −22
Original line number Diff line number Diff line
@@ -16,18 +16,23 @@

package com.android.server.am;

import static com.android.server.am.BroadcastQueue.checkState;
import static com.android.server.am.BroadcastRecord.deliveryStateToString;

import android.annotation.IntDef;
import android.annotation.NonNull;
import android.annotation.Nullable;
import android.annotation.UptimeMillisLong;
import android.content.pm.ResolveInfo;
import android.os.Trace;
import android.os.UserHandle;
import android.util.IndentingPrintWriter;
import android.util.TimeUtils;

import com.android.internal.annotations.VisibleForTesting;
import com.android.internal.os.SomeArgs;

import java.lang.annotation.Retention;
import java.lang.annotation.RetentionPolicy;
import java.util.ArrayDeque;
import java.util.Iterator;
import java.util.Objects;
@@ -115,6 +120,7 @@ class BroadcastProcessQueue {
    private int mCountAlarm;

    private @UptimeMillisLong long mRunnableAt = Long.MAX_VALUE;
    private @Reason int mRunnableAtReason = REASON_EMPTY;
    private boolean mRunnableAtInvalidated;

    private boolean mProcessCached;
@@ -256,7 +262,6 @@ class BroadcastProcessQueue {
     */
    public void makeActiveNextPending() {
        // TODO: what if the next broadcast isn't runnable yet?
        checkState(isRunnable(), "isRunnable");
        final SomeArgs next = mPending.removeFirst();
        mActive = (BroadcastRecord) next.arg1;
        mActiveIndex = next.argi1;
@@ -316,8 +321,7 @@ class BroadcastProcessQueue {
     * Return the broadcast being actively dispatched in this process.
     */
    public @NonNull BroadcastRecord getActive() {
        checkState(isActive(), "isActive");
        return mActive;
        return Objects.requireNonNull(mActive);
    }

    /**
@@ -325,7 +329,7 @@ class BroadcastProcessQueue {
     * being actively dispatched in this process.
     */
    public int getActiveIndex() {
        checkState(isActive(), "isActive");
        Objects.requireNonNull(mActive);
        return mActiveIndex;
    }

@@ -356,10 +360,55 @@ class BroadcastProcessQueue {
        return mRunnableAt;
    }

    /**
     * Return the "reason" behind the current {@link #getRunnableAt()} value,
     * such as indicating why the queue is being delayed or paused.
     */
    public @Reason int getRunnableAtReason() {
        if (mRunnableAtInvalidated) updateRunnableAt();
        return mRunnableAtReason;
    }

    public void invalidateRunnableAt() {
        mRunnableAtInvalidated = true;
    }

    private static final int REASON_EMPTY = 0;
    private static final int REASON_CONTAINS_FOREGROUND = 1;
    private static final int REASON_CONTAINS_ORDERED = 2;
    private static final int REASON_CONTAINS_ALARM = 3;
    private static final int REASON_CACHED = 4;
    private static final int REASON_NORMAL = 5;
    private static final int REASON_MAX_PENDING = 6;
    private static final int REASON_BLOCKED_ORDERED = 7;

    @IntDef(flag = false, prefix = { "REASON_" }, value = {
            REASON_EMPTY,
            REASON_CONTAINS_FOREGROUND,
            REASON_CONTAINS_ORDERED,
            REASON_CONTAINS_ALARM,
            REASON_CACHED,
            REASON_NORMAL,
            REASON_MAX_PENDING,
            REASON_BLOCKED_ORDERED,
    })
    @Retention(RetentionPolicy.SOURCE)
    public @interface Reason {}

    static @NonNull String reasonToString(@Reason int reason) {
        switch (reason) {
            case REASON_EMPTY: return "EMPTY";
            case REASON_CONTAINS_FOREGROUND: return "CONTAINS_FOREGROUND";
            case REASON_CONTAINS_ORDERED: return "CONTAINS_ORDERED";
            case REASON_CONTAINS_ALARM: return "CONTAINS_ALARM";
            case REASON_CACHED: return "CACHED";
            case REASON_NORMAL: return "NORMAL";
            case REASON_MAX_PENDING: return "MAX_PENDING";
            case REASON_BLOCKED_ORDERED: return "BLOCKED_ORDERED";
            default: return Integer.toString(reason);
        }
    }

    /**
     * Update {@link #getRunnableAt()} if it's currently invalidated.
     */
@@ -368,34 +417,43 @@ class BroadcastProcessQueue {
        if (next != null) {
            final BroadcastRecord r = (BroadcastRecord) next.arg1;
            final int index = next.argi1;
            final long runnableAt = r.enqueueTime;

            // If our next broadcast is ordered, and we're not the next receiver
            // in line, then we're not runnable at all
            if (r.ordered && r.finishedCount != index) {
                mRunnableAt = Long.MAX_VALUE;
                mRunnableAtReason = REASON_BLOCKED_ORDERED;
                return;
            }

            // If we have too many broadcasts pending, bypass any delays that
            // might have been applied above to aid draining
            if (mPending.size() >= constants.MAX_PENDING_BROADCASTS) {
                mRunnableAt = runnableAt;
                mRunnableAtReason = REASON_MAX_PENDING;
                return;
            }

            final long runnableAt = r.enqueueTime;
            if (mCountForeground > 0) {
                mRunnableAt = runnableAt;
                mRunnableAtReason = REASON_CONTAINS_FOREGROUND;
            } else if (mCountOrdered > 0) {
                mRunnableAt = runnableAt;
                mRunnableAtReason = REASON_CONTAINS_ORDERED;
            } else if (mCountAlarm > 0) {
                mRunnableAt = runnableAt;
                mRunnableAtReason = REASON_CONTAINS_ALARM;
            } else if (mProcessCached) {
                mRunnableAt = runnableAt + constants.DELAY_CACHED_MILLIS;
                mRunnableAtReason = REASON_CACHED;
            } else {
                mRunnableAt = runnableAt + constants.DELAY_NORMAL_MILLIS;
            }

            // If we have too many broadcasts pending, bypass any delays that
            // might have been applied above to aid draining
            if (mPending.size() >= constants.MAX_PENDING_BROADCASTS) {
                mRunnableAt = runnableAt;
                mRunnableAtReason = REASON_NORMAL;
            }
        } else {
            mRunnableAt = Long.MAX_VALUE;
            mRunnableAtReason = REASON_EMPTY;
        }
    }

@@ -476,24 +534,53 @@ class BroadcastProcessQueue {
        return mCachedToShortString;
    }

    public void dumpLocked(@NonNull IndentingPrintWriter pw) {
    public void dumpLocked(@UptimeMillisLong long now, @NonNull IndentingPrintWriter pw) {
        if ((mActive == null) && mPending.isEmpty()) return;

        pw.println(toShortString());
        pw.print(toShortString());
        if (isRunnable()) {
            pw.print(" runnable at ");
            TimeUtils.formatDuration(getRunnableAt(), now, pw);
        } else {
            pw.print(" not runnable");
        }
        pw.print(" because ");
        pw.print(reasonToString(mRunnableAtReason));
        pw.println();
        pw.increaseIndent();
        if (mActive != null) {
            pw.print("🏃 ");
            pw.print(mActive.toShortString());
            pw.print(' ');
            pw.println(mActive.receivers.get(mActiveIndex));
            dumpRecord(now, pw, mActive, mActiveIndex);
        }
        for (SomeArgs args : mPending) {
            final BroadcastRecord r = (BroadcastRecord) args.arg1;
            pw.print("\u3000 ");
            pw.print(r.toShortString());
            pw.print(' ');
            pw.println(r.receivers.get(args.argi1));
            dumpRecord(now, pw, r, args.argi1);
        }
        pw.decreaseIndent();
        pw.println();
    }

    private void dumpRecord(@UptimeMillisLong long now, @NonNull IndentingPrintWriter pw,
            @NonNull BroadcastRecord record, int recordIndex) {
        TimeUtils.formatDuration(record.enqueueTime, now, pw);
        pw.print(' ');
        pw.println(record.toShortString());
        pw.print("    ");
        final int deliveryState = record.delivery[recordIndex];
        pw.print(deliveryStateToString(deliveryState));
        if (deliveryState == BroadcastRecord.DELIVERY_SCHEDULED) {
            pw.print(" at ");
            TimeUtils.formatDuration(record.scheduledTime[recordIndex], now, pw);
        }
        final Object receiver = record.receivers.get(recordIndex);
        if (receiver instanceof BroadcastFilter) {
            final BroadcastFilter filter = (BroadcastFilter) receiver;
            pw.print(" for registered ");
            pw.print(Integer.toHexString(System.identityHashCode(filter)));
        } else /* if (receiver instanceof ResolveInfo) */ {
            final ResolveInfo info = (ResolveInfo) receiver;
            pw.print(" for manifest ");
            pw.print(info.activityInfo.name);
        }
        pw.println();
    }
}
+4 −0
Original line number Diff line number Diff line
@@ -60,6 +60,10 @@ public abstract class BroadcastQueue {
        }
    }

    static void logw(String msg) {
        Slog.w(TAG, msg);
    }

    static void logv(String msg) {
        Slog.v(TAG, msg);
    }
+3 −1
Original line number Diff line number Diff line
@@ -601,7 +601,7 @@ public class BroadcastQueueImpl extends BroadcastQueue {
        // If we're abandoning this broadcast before any receivers were actually spun up,
        // nextReceiver is zero; in which case time-to-process bookkeeping doesn't apply.
        if (r.nextReceiver > 0) {
            r.duration[r.nextReceiver - 1] = elapsed;
            r.terminalTime[r.nextReceiver - 1] = finishTime;
        }

        // if this receiver was slow, impose deferral policy on the app.  This will kick in
@@ -827,6 +827,7 @@ public class BroadcastQueueImpl extends BroadcastQueue {
                }
            } else {
                r.receiverTime = SystemClock.uptimeMillis();
                r.scheduledTime[index] = r.receiverTime;
                maybeAddAllowBackgroundActivityStartsToken(filter.receiverList.app, r);
                maybeScheduleTempAllowlistLocked(filter.owningUid, r, r.options);
                maybeReportBroadcastDispatchedEventLocked(r, filter.owningUid);
@@ -1235,6 +1236,7 @@ public class BroadcastQueueImpl extends BroadcastQueue {
        // Keep track of when this receiver started, and make sure there
        // is a timeout message pending to kill it if need be.
        r.receiverTime = SystemClock.uptimeMillis();
        r.scheduledTime[recIdx] = r.receiverTime;
        if (recIdx == 0) {
            r.dispatchTime = r.receiverTime;
            r.dispatchRealTime = SystemClock.elapsedRealtime();
+72 −19
Original line number Diff line number Diff line
@@ -27,6 +27,7 @@ import static com.android.internal.util.FrameworkStatsLog.BROADCAST_DELIVERY_EVE
import static com.android.internal.util.FrameworkStatsLog.BROADCAST_DELIVERY_EVENT_REPORTED__RECEIVER_TYPE__RUNTIME;
import static com.android.server.am.ActivityManagerDebugConfig.DEBUG_BROADCAST;
import static com.android.server.am.BroadcastProcessQueue.insertIntoRunnableList;
import static com.android.server.am.BroadcastProcessQueue.reasonToString;
import static com.android.server.am.BroadcastProcessQueue.removeFromRunnableList;
import static com.android.server.am.BroadcastRecord.deliveryStateToString;
import static com.android.server.am.BroadcastRecord.getReceiverPackageName;
@@ -60,7 +61,6 @@ import android.os.SystemClock;
import android.os.Trace;
import android.os.UserHandle;
import android.util.IndentingPrintWriter;
import android.util.Slog;
import android.util.SparseArray;
import android.util.TimeUtils;
import android.util.proto.ProtoOutputStream;
@@ -139,6 +139,13 @@ class BroadcastQueueModernImpl extends BroadcastQueue {
    // TODO: pause queues when background services are running
    // TODO: pause queues when processes are frozen

    /**
     * When enabled, invoke {@link #checkConsistencyLocked()} periodically to
     * verify that our internal state is consistent. Checking consistency is
     * relatively expensive, so this should be typically disabled.
     */
    private static final boolean CHECK_CONSISTENCY = true;

    /**
     * Map from UID to per-process broadcast queues. If a UID hosts more than
     * one process, each additional process is stored as a linked list using
@@ -293,6 +300,8 @@ class BroadcastQueueModernImpl extends BroadcastQueue {
        if (queue.isEmpty() && !queue.isActive() && !queue.isProcessWarm()) {
            removeProcessQueue(queue.processName, queue.uid);
        }

        if (CHECK_CONSISTENCY) checkConsistencyLocked();
    }

    /**
@@ -396,6 +405,8 @@ class BroadcastQueueModernImpl extends BroadcastQueue {
            mWaitingForIdle.clear();
        }

        if (CHECK_CONSISTENCY) checkConsistencyLocked();

        traceEnd(TAG, cookie);
    }

@@ -451,13 +462,12 @@ class BroadcastQueueModernImpl extends BroadcastQueue {

            // Skip any pending registered receivers, since the old process
            // would never be around to receive them
            queue.removeMatchingBroadcasts((r, i) -> {
            boolean didSomething = queue.removeMatchingBroadcasts((r, i) -> {
                return (r.receivers.get(i) instanceof BroadcastFilter);
            }, mBroadcastConsumerSkip);

            // If queue has nothing else pending, consider cleaning it
            if (queue.isEmpty()) {
            if (didSomething || queue.isEmpty()) {
                updateRunnableList(queue);
                enqueueUpdateRunningList();
            }
        }
    }
@@ -565,6 +575,12 @@ class BroadcastQueueModernImpl extends BroadcastQueue {
        final int index = queue.getActiveIndex();
        final Object receiver = r.receivers.get(index);

        if (r.finishedCount == 0) {
            r.dispatchTime = SystemClock.uptimeMillis();
            r.dispatchRealTime = SystemClock.elapsedRealtime();
            r.dispatchClockTime = System.currentTimeMillis();
        }

        // If someone already finished this broadcast, finish immediately
        final int oldDeliveryState = getDeliveryState(r, index);
        if (isDeliveryStateTerminal(oldDeliveryState)) {
@@ -646,7 +662,7 @@ class BroadcastQueueModernImpl extends BroadcastQueue {
            } catch (RemoteException e) {
                final String msg = "Failed to schedule " + r + " to " + receiver
                        + " via " + app + ": " + e;
                Slog.w(TAG, msg);
                logw(msg);
                app.scheduleCrashLocked(msg, CannotDeliverBroadcastException.TYPE_ID, null);
                app.setKilled(true);
                finishReceiverLocked(queue, BroadcastRecord.DELIVERY_FAILURE);
@@ -673,7 +689,7 @@ class BroadcastQueueModernImpl extends BroadcastQueue {
                        r.userId, app.mState.getReportedProcState());
            } catch (RemoteException e) {
                final String msg = "Failed to schedule result of " + r + " via " + app + ": " + e;
                Slog.w(TAG, msg);
                logw(msg);
                app.scheduleCrashLocked(msg, CannotDeliverBroadcastException.TYPE_ID, null);
            }
        }
@@ -761,13 +777,6 @@ class BroadcastQueueModernImpl extends BroadcastQueue {
            @NonNull Object receiver, @DeliveryState int newDeliveryState) {
        final int oldDeliveryState = getDeliveryState(r, index);

        if (newDeliveryState != BroadcastRecord.DELIVERY_DELIVERED) {
            Slog.w(TAG, "Delivery state of " + r + " to " + receiver
                    + " via " + app + " changed from "
                    + deliveryStateToString(oldDeliveryState) + " to "
                    + deliveryStateToString(newDeliveryState));
        }

        // Only apply state when we haven't already reached a terminal state;
        // this is how we ignore racing timeout messages
        if (!isDeliveryStateTerminal(oldDeliveryState)) {
@@ -789,6 +798,13 @@ class BroadcastQueueModernImpl extends BroadcastQueue {
        // bookkeeping to update for ordered broadcasts
        if (!isDeliveryStateTerminal(oldDeliveryState)
                && isDeliveryStateTerminal(newDeliveryState)) {
            if (newDeliveryState != BroadcastRecord.DELIVERY_DELIVERED) {
                logw("Delivery state of " + r + " to " + receiver
                        + " via " + app + " changed from "
                        + deliveryStateToString(oldDeliveryState) + " to "
                        + deliveryStateToString(newDeliveryState));
            }

            r.finishedCount++;
            notifyFinishReceiver(queue, r, index, receiver);

@@ -801,6 +817,7 @@ class BroadcastQueueModernImpl extends BroadcastQueue {
                            getReceiverProcessName(nextReceiver), getReceiverUid(nextReceiver));
                    nextQueue.invalidateRunnableAt();
                    updateRunnableList(nextQueue);
                    enqueueUpdateRunningList();
                } else {
                    // Everything finished, so deliver final result
                    scheduleResultTo(r);
@@ -880,12 +897,18 @@ class BroadcastQueueModernImpl extends BroadcastQueue {
            BroadcastProcessQueue leaf = mProcessQueues.valueAt(i);
            while (leaf != null) {
                if (queuePredicate.test(leaf)) {
                    didSomething |= leaf.removeMatchingBroadcasts(broadcastPredicate,
                            mBroadcastConsumerSkip);
                    if (leaf.removeMatchingBroadcasts(broadcastPredicate,
                            mBroadcastConsumerSkip)) {
                        updateRunnableList(leaf);
                        didSomething = true;
                    }
                }
                leaf = leaf.processNameNext;
            }
        }
        if (didSomething) {
            enqueueUpdateRunningList();
        }
        return didSomething;
    }

@@ -951,6 +974,32 @@ class BroadcastQueueModernImpl extends BroadcastQueue {
        // TODO: implement
    }

    /**
     * Heavy verification of internal consistency.
     */
    private void checkConsistencyLocked() {
        // Verify all runnable queues are sorted
        BroadcastProcessQueue prev = null;
        BroadcastProcessQueue next = mRunnableHead;
        while (next != null) {
            checkState(next.runnableAtPrev == prev, "runnableAtPrev");
            checkState(next.isRunnable(), "isRunnable " + next);
            if (prev != null) {
                checkState(next.getRunnableAt() >= prev.getRunnableAt(),
                        "getRunnableAt " + next + " vs " + prev);
            }
            prev = next;
            next = next.runnableAtNext;
        }

        // Verify all running queues are active
        for (BroadcastProcessQueue queue : mRunning) {
            if (queue != null) {
                checkState(queue.isActive(), "isActive " + queue);
            }
        }
    }

    private int traceBegin(String trackName, String methodName) {
        final int cookie = methodName.hashCode();
        Trace.asyncTraceForTrackBegin(Trace.TRACE_TAG_ACTIVITY_MANAGER,
@@ -1086,7 +1135,7 @@ class BroadcastQueueModernImpl extends BroadcastQueue {
        // "dispatched" and "scheduled", so we report no "receive delay"
        final long dispatchDelay = r.scheduledTime[index] - r.enqueueTime;
        final long receiveDelay = 0;
        final long finishDelay = r.duration[index];
        final long finishDelay = r.terminalTime[index] - r.scheduledTime[index];
        FrameworkStatsLog.write(BROADCAST_DELIVERY_EVENT_REPORTED, uid, senderUid, actionName,
                receiverType, type, dispatchDelay, receiveDelay, finishDelay);

@@ -1094,6 +1143,7 @@ class BroadcastQueueModernImpl extends BroadcastQueue {
        if (recordFinished) {
            mHistory.addBroadcastToHistoryLocked(r);

            r.finishTime = SystemClock.uptimeMillis();
            r.nextReceiver = r.receivers.size();
            BroadcastQueueImpl.logBootCompletedBroadcastCompletionLatencyIfPossible(r);

@@ -1214,7 +1264,7 @@ class BroadcastQueueModernImpl extends BroadcastQueue {
        for (int i = 0; i < mProcessQueues.size(); i++) {
            BroadcastProcessQueue leaf = mProcessQueues.valueAt(i);
            while (leaf != null) {
                leaf.dumpLocked(ipw);
                leaf.dumpLocked(now, ipw);
                leaf = leaf.processNameNext;
            }
        }
@@ -1230,7 +1280,10 @@ class BroadcastQueueModernImpl extends BroadcastQueue {
            while (queue != null) {
                TimeUtils.formatDuration(queue.getRunnableAt(), now, ipw);
                ipw.print(' ');
                ipw.println(queue.toShortString());
                ipw.print(reasonToString(queue.getRunnableAtReason()));
                ipw.print(' ');
                ipw.print(queue.toShortString());
                ipw.println();
                queue = queue.runnableAtNext;
            }
        }
+37 −23
Original line number Diff line number Diff line
@@ -23,12 +23,13 @@ import static com.android.server.am.BroadcastConstants.DEFER_BOOT_COMPLETED_BROA
import static com.android.server.am.BroadcastConstants.DEFER_BOOT_COMPLETED_BROADCAST_CHANGE_ID;
import static com.android.server.am.BroadcastConstants.DEFER_BOOT_COMPLETED_BROADCAST_NONE;
import static com.android.server.am.BroadcastConstants.DEFER_BOOT_COMPLETED_BROADCAST_TARGET_T_ONLY;
import static com.android.server.am.BroadcastQueue.checkState;

import android.annotation.DurationMillisLong;
import android.annotation.CurrentTimeMillisLong;
import android.annotation.ElapsedRealtimeLong;
import android.annotation.IntDef;
import android.annotation.NonNull;
import android.annotation.Nullable;
import android.annotation.UptimeMillisLong;
import android.app.ActivityManagerInternal;
import android.app.AppOpsManager;
import android.app.BroadcastOptions;
@@ -89,20 +90,20 @@ final class BroadcastRecord extends Binder {
    final BroadcastOptions options; // BroadcastOptions supplied by caller
    final List receivers;   // contains BroadcastFilter and ResolveInfo
    final @DeliveryState int[] delivery;   // delivery state of each receiver
    final long[] scheduledTime; // uptimeMillis when each receiver was scheduled
    final long[] duration;   // duration a receiver took to process broadcast
    IIntentReceiver resultTo; // who receives final result if non-null
    boolean deferred;
    int splitCount;         // refcount for result callback, when split
    int splitToken;         // identifier for cross-BroadcastRecord refcount
    long enqueueTime;       // uptimeMillis when the broadcast was enqueued
    long enqueueRealTime;   // elapsedRealtime when the broadcast was enqueued
    long enqueueClockTime;  // the clock time the broadcast was enqueued
    long dispatchTime;      // when dispatch started on this set of receivers
    long dispatchRealTime;  // elapsedRealtime when the broadcast was dispatched
    long dispatchClockTime; // the clock time the dispatch started
    long receiverTime;      // when current receiver started for timeouts.
    long finishTime;        // when we finished the current receiver.
    @UptimeMillisLong       long enqueueTime;        // when broadcast enqueued
    @ElapsedRealtimeLong    long enqueueRealTime;    // when broadcast enqueued
    @CurrentTimeMillisLong  long enqueueClockTime;   // when broadcast enqueued
    @UptimeMillisLong       long dispatchTime;       // when broadcast dispatch started
    @ElapsedRealtimeLong    long dispatchRealTime;   // when broadcast dispatch started
    @CurrentTimeMillisLong  long dispatchClockTime;  // when broadcast dispatch started
    @UptimeMillisLong       long receiverTime;       // when receiver started for timeouts
    @UptimeMillisLong       long finishTime;         // when broadcast finished
    final @UptimeMillisLong long[] scheduledTime;    // when each receiver was scheduled
    final @UptimeMillisLong long[] terminalTime;     // when each receiver was terminal
    boolean timeoutExempt;  // true if this broadcast is not subject to receiver timeouts
    int resultCode;         // current result code value.
    String resultData;      // current result data value.
@@ -163,12 +164,12 @@ final class BroadcastRecord extends Binder {

    static @NonNull String deliveryStateToString(@DeliveryState int deliveryState) {
        switch (deliveryState) {
            case DELIVERY_PENDING: return "Pending";
            case DELIVERY_DELIVERED: return "Delivered";
            case DELIVERY_SKIPPED: return "Skipped";
            case DELIVERY_TIMEOUT: return "Timeout";
            case DELIVERY_SCHEDULED: return "Scheduled";
            case DELIVERY_FAILURE: return "Failure";
            case DELIVERY_PENDING: return "PENDING";
            case DELIVERY_DELIVERED: return "DELIVERED";
            case DELIVERY_SKIPPED: return "SKIPPED";
            case DELIVERY_TIMEOUT: return "TIMEOUT";
            case DELIVERY_SCHEDULED: return "SCHEDULED";
            case DELIVERY_FAILURE: return "FAILURE";
            default: return Integer.toString(deliveryState);
        }
    }
@@ -306,7 +307,17 @@ final class BroadcastRecord extends Binder {
            Object o = receivers.get(i);
            pw.print(prefix);
            pw.print(deliveryStateToString(delivery[i]));
            pw.print(" "); TimeUtils.formatDuration(duration[i], pw);
            pw.print(' ');
            if (scheduledTime[i] != 0) {
                pw.print("scheduled ");
                TimeUtils.formatDuration(scheduledTime[i] - enqueueTime, pw);
                pw.print(' ');
            }
            if (terminalTime[i] != 0) {
                pw.print("terminal ");
                TimeUtils.formatDuration(terminalTime[i] - scheduledTime[i], pw);
                pw.print(' ');
            }
            pw.print("#"); pw.print(i); pw.print(": ");
            if (o instanceof BroadcastFilter) {
                pw.println(o);
@@ -352,7 +363,7 @@ final class BroadcastRecord extends Binder {
        receivers = _receivers;
        delivery = new int[_receivers != null ? _receivers.size() : 0];
        scheduledTime = new long[delivery.length];
        duration = new long[delivery.length];
        terminalTime = new long[delivery.length];
        resultTo = _resultTo;
        resultCode = _resultCode;
        resultData = _resultData;
@@ -399,7 +410,7 @@ final class BroadcastRecord extends Binder {
        receivers = from.receivers;
        delivery = from.delivery;
        scheduledTime = from.scheduledTime;
        duration = from.duration;
        terminalTime = from.terminalTime;
        resultTo = from.resultTo;
        enqueueTime = from.enqueueTime;
        enqueueRealTime = from.enqueueRealTime;
@@ -559,7 +570,10 @@ final class BroadcastRecord extends Binder {

        switch (deliveryState) {
            case DELIVERY_DELIVERED:
                duration[index] = SystemClock.uptimeMillis() - scheduledTime[index];
            case DELIVERY_SKIPPED:
            case DELIVERY_TIMEOUT:
            case DELIVERY_FAILURE:
                terminalTime[index] = SystemClock.uptimeMillis();
                break;
            case DELIVERY_SCHEDULED:
                scheduledTime[index] = SystemClock.uptimeMillis();