From dddea62efcd2368852a00252b55ce7147e6c8950 Mon Sep 17 00:00:00 2001 From: Jeff Sharkey Date: Mon, 3 Apr 2023 10:36:47 -0600 Subject: [PATCH] Layer "locked" methods for better locking logs. When reporting either deadlocks or lock contention, the OS logs the line at which the lock was acquired, and our LocalHandler makes this tricky to track across builds as line numbers change. This change pivots to adding a call stack frame to give ourselves clearer information about what operation is working with the lock. Also restore missing code coverage for health checks that was accidentally deleted. Bug: 274681945 Test: atest FrameworksMockingServicesTests:BroadcastQueueTest Test: atest FrameworksMockingServicesTests:BroadcastQueueModernImplTest Test: atest FrameworksMockingServicesTests:BroadcastRecordTest Change-Id: Ic6de76f9a7e1ae7b9d1bd6358f556072eaf3ac7c --- .../server/am/BroadcastProcessQueue.java | 10 +- .../server/am/BroadcastQueueModernImpl.java | 132 ++++++++++-------- .../am/BroadcastQueueModernImplTest.java | 9 +- .../android/server/am/BroadcastQueueTest.java | 17 ++- 4 files changed, 103 insertions(+), 65 deletions(-) diff --git a/services/core/java/com/android/server/am/BroadcastProcessQueue.java b/services/core/java/com/android/server/am/BroadcastProcessQueue.java index d5b8bb44e853b..dbb351b23c85f 100644 --- a/services/core/java/com/android/server/am/BroadcastProcessQueue.java +++ b/services/core/java/com/android/server/am/BroadcastProcessQueue.java @@ -1050,13 +1050,13 @@ class BroadcastProcessQueue { * Check overall health, confirming things are in a reasonable state and * that we're not wedged. */ - public void checkHealthLocked() { - checkHealthLocked(mPending); - checkHealthLocked(mPendingUrgent); - checkHealthLocked(mPendingOffload); + public void assertHealthLocked() { + assertHealthLocked(mPending); + assertHealthLocked(mPendingUrgent); + assertHealthLocked(mPendingOffload); } - private void checkHealthLocked(@NonNull ArrayDeque queue) { + private void assertHealthLocked(@NonNull ArrayDeque queue) { if (queue.isEmpty()) return; final Iterator it = queue.descendingIterator(); diff --git a/services/core/java/com/android/server/am/BroadcastQueueModernImpl.java b/services/core/java/com/android/server/am/BroadcastQueueModernImpl.java index b18997a8d21fc..a4bdf61e628ff 100644 --- a/services/core/java/com/android/server/am/BroadcastQueueModernImpl.java +++ b/services/core/java/com/android/server/am/BroadcastQueueModernImpl.java @@ -246,21 +246,15 @@ class BroadcastQueueModernImpl extends BroadcastQueue { private final Handler.Callback mLocalCallback = (msg) -> { switch (msg.what) { case MSG_UPDATE_RUNNING_LIST: { - synchronized (mService) { - updateRunningListLocked(); - } + updateRunningList(); return true; } case MSG_DELIVERY_TIMEOUT_SOFT: { - synchronized (mService) { - deliveryTimeoutSoftLocked((BroadcastProcessQueue) msg.obj, msg.arg1); - } + deliveryTimeoutSoft((BroadcastProcessQueue) msg.obj, msg.arg1); return true; } case MSG_DELIVERY_TIMEOUT_HARD: { - synchronized (mService) { - deliveryTimeoutHardLocked((BroadcastProcessQueue) msg.obj); - } + deliveryTimeoutHard((BroadcastProcessQueue) msg.obj); return true; } case MSG_BG_ACTIVITY_START_TIMEOUT: { @@ -274,9 +268,7 @@ class BroadcastQueueModernImpl extends BroadcastQueue { return true; } case MSG_CHECK_HEALTH: { - synchronized (mService) { - checkHealthLocked(); - } + checkHealth(); return true; } } @@ -365,6 +357,12 @@ class BroadcastQueueModernImpl extends BroadcastQueue { } } + private void updateRunningList() { + synchronized (mService) { + updateRunningListLocked(); + } + } + /** * Consider updating the list of "running" queues. *

@@ -965,6 +963,13 @@ class BroadcastQueueModernImpl extends BroadcastQueue { r.resultTo = null; } + private void deliveryTimeoutSoft(@NonNull BroadcastProcessQueue queue, + int softTimeoutMillis) { + synchronized (mService) { + deliveryTimeoutSoftLocked(queue, softTimeoutMillis); + } + } + private void deliveryTimeoutSoftLocked(@NonNull BroadcastProcessQueue queue, int softTimeoutMillis) { if (queue.app != null) { @@ -981,6 +986,12 @@ class BroadcastQueueModernImpl extends BroadcastQueue { } } + private void deliveryTimeoutHard(@NonNull BroadcastProcessQueue queue) { + synchronized (mService) { + deliveryTimeoutHardLocked(queue); + } + } + private void deliveryTimeoutHardLocked(@NonNull BroadcastProcessQueue queue) { finishReceiverActiveLocked(queue, BroadcastRecord.DELIVERY_TIMEOUT, "deliveryTimeoutHardLocked"); @@ -1458,52 +1469,19 @@ class BroadcastQueueModernImpl extends BroadcastQueue { // TODO: implement } - /** - * Check overall health, confirming things are in a reasonable state and - * that we're not wedged. If we determine we're in an unhealthy state, dump - * current state once and stop future health checks to avoid spamming. - */ - @VisibleForTesting - void checkHealthLocked() { + private void checkHealth() { + synchronized (mService) { + checkHealthLocked(); + } + } + + private void checkHealthLocked() { try { - // 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); - } - } - - // Verify that pending cold start hasn't been orphaned - if (mRunningColdStart != null) { - checkState(getRunningIndexOf(mRunningColdStart) >= 0, - "isOrphaned " + mRunningColdStart); - } - - // Verify health of all known process queues - for (int i = 0; i < mProcessQueues.size(); i++) { - BroadcastProcessQueue leaf = mProcessQueues.valueAt(i); - while (leaf != null) { - leaf.checkHealthLocked(); - leaf = leaf.processNameNext; - } - } + assertHealthLocked(); // If no health issues found above, check again in the future - mLocalHandler.sendEmptyMessageDelayed(MSG_CHECK_HEALTH, DateUtils.MINUTE_IN_MILLIS); + mLocalHandler.sendEmptyMessageDelayed(MSG_CHECK_HEALTH, + DateUtils.MINUTE_IN_MILLIS); } catch (Exception e) { // Throw up a message to indicate that something went wrong, and @@ -1513,6 +1491,50 @@ class BroadcastQueueModernImpl extends BroadcastQueue { } } + /** + * Check overall health, confirming things are in a reasonable state and + * that we're not wedged. If we determine we're in an unhealthy state, dump + * current state once and stop future health checks to avoid spamming. + */ + @VisibleForTesting + void assertHealthLocked() { + // 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); + } + } + + // Verify that pending cold start hasn't been orphaned + if (mRunningColdStart != null) { + checkState(getRunningIndexOf(mRunningColdStart) >= 0, + "isOrphaned " + mRunningColdStart); + } + + // Verify health of all known process queues + for (int i = 0; i < mProcessQueues.size(); i++) { + BroadcastProcessQueue leaf = mProcessQueues.valueAt(i); + while (leaf != null) { + leaf.assertHealthLocked(); + leaf = leaf.processNameNext; + } + } + } + private void updateWarmProcess(@NonNull BroadcastProcessQueue queue) { if (!queue.isProcessWarm()) { setQueueProcess(queue, mService.getProcessRecordLocked(queue.processName, queue.uid)); diff --git a/services/tests/mockingservicestests/src/com/android/server/am/BroadcastQueueModernImplTest.java b/services/tests/mockingservicestests/src/com/android/server/am/BroadcastQueueModernImplTest.java index 0c512d2a0bd31..318067ee8681b 100644 --- a/services/tests/mockingservicestests/src/com/android/server/am/BroadcastQueueModernImplTest.java +++ b/services/tests/mockingservicestests/src/com/android/server/am/BroadcastQueueModernImplTest.java @@ -91,8 +91,8 @@ import org.junit.Rule; import org.junit.Test; import org.mockito.Mock; -import java.io.ByteArrayOutputStream; import java.io.PrintWriter; +import java.io.Writer; import java.lang.reflect.Array; import java.util.ArrayList; import java.util.List; @@ -596,7 +596,7 @@ public final class BroadcastQueueModernImplTest { // about the actual output, just that we don't crash queue.getActive().setDeliveryState(0, BroadcastRecord.DELIVERY_SCHEDULED, "Test-driven"); queue.dumpLocked(SystemClock.uptimeMillis(), - new IndentingPrintWriter(new PrintWriter(new ByteArrayOutputStream()))); + new IndentingPrintWriter(new PrintWriter(Writer.nullWriter()))); queue.makeActiveNextPending(); assertEquals(Intent.ACTION_LOCALE_CHANGED, queue.getActive().intent.getAction()); @@ -1166,6 +1166,11 @@ public final class BroadcastQueueModernImplTest { List intents) { for (int i = 0; i < intents.size(); i++) { queue.makeActiveNextPending(); + + // While we're here, give our health check some test coverage + queue.assertHealthLocked(); + queue.dumpLocked(0L, new IndentingPrintWriter(Writer.nullWriter())); + final Intent actualIntent = queue.getActive().intent; final Intent expectedIntent = intents.get(i); final String errMsg = "actual=" + actualIntent + ", expected=" + expectedIntent diff --git a/services/tests/mockingservicestests/src/com/android/server/am/BroadcastQueueTest.java b/services/tests/mockingservicestests/src/com/android/server/am/BroadcastQueueTest.java index cbc259797c123..b6bc02a41c21c 100644 --- a/services/tests/mockingservicestests/src/com/android/server/am/BroadcastQueueTest.java +++ b/services/tests/mockingservicestests/src/com/android/server/am/BroadcastQueueTest.java @@ -39,6 +39,7 @@ import static org.mockito.Mockito.atLeastOnce; import static org.mockito.Mockito.doAnswer; import static org.mockito.Mockito.doNothing; import static org.mockito.Mockito.doReturn; +import static org.mockito.Mockito.doThrow; import static org.mockito.Mockito.inOrder; import static org.mockito.Mockito.mock; import static org.mockito.Mockito.never; @@ -106,10 +107,10 @@ import org.mockito.Mock; import org.mockito.MockitoAnnotations; import org.mockito.verification.VerificationMode; -import java.io.ByteArrayOutputStream; import java.io.File; import java.io.FileDescriptor; import java.io.PrintWriter; +import java.io.Writer; import java.util.ArrayList; import java.util.Arrays; import java.util.Collection; @@ -231,6 +232,7 @@ public class BroadcastQueueTest { doAnswer((invocation) -> { Log.v(TAG, "Intercepting startProcessLocked() for " + Arrays.toString(invocation.getArguments())); + assertHealth(); final ProcessStartBehavior behavior = mNextProcessStartBehavior .getAndSet(ProcessStartBehavior.SUCCESS); if (behavior == ProcessStartBehavior.FAIL_NULL) { @@ -462,6 +464,7 @@ public class BroadcastQueueTest { doAnswer((invocation) -> { Log.v(TAG, "Intercepting scheduleReceiver() for " + Arrays.toString(invocation.getArguments())); + assertHealth(); final Intent intent = invocation.getArgument(0); final Bundle extras = invocation.getArgument(5); mScheduledBroadcasts.add(makeScheduledBroadcast(r, intent)); @@ -483,6 +486,7 @@ public class BroadcastQueueTest { doAnswer((invocation) -> { Log.v(TAG, "Intercepting scheduleRegisteredReceiver() for " + Arrays.toString(invocation.getArguments())); + assertHealth(); final Intent intent = invocation.getArgument(1); final Bundle extras = invocation.getArgument(4); final boolean ordered = invocation.getArgument(5); @@ -600,6 +604,13 @@ public class BroadcastQueueTest { BackgroundStartPrivileges.NONE, false, null); } + private void assertHealth() { + if (mImpl == Impl.MODERN) { + // If this fails, it'll throw a clear reason message + ((BroadcastQueueModernImpl) mQueue).assertHealthLocked(); + } + } + private static Map asMap(Bundle bundle) { final Map map = new HashMap<>(); if (bundle != null) { @@ -769,7 +780,7 @@ public class BroadcastQueueTest { // about the actual output, just that we don't crash mQueue.dumpDebug(new ProtoOutputStream(), ActivityManagerServiceDumpBroadcastsProto.BROADCAST_QUEUE); - mQueue.dumpLocked(FileDescriptor.err, new PrintWriter(new ByteArrayOutputStream()), + mQueue.dumpLocked(FileDescriptor.err, new PrintWriter(Writer.nullWriter()), null, 0, true, true, true, null, false); mQueue.dumpToDropBoxLocked(TAG); @@ -1166,7 +1177,7 @@ public class BroadcastQueueTest { // about the actual output, just that we don't crash mQueue.dumpDebug(new ProtoOutputStream(), ActivityManagerServiceDumpBroadcastsProto.BROADCAST_QUEUE); - mQueue.dumpLocked(FileDescriptor.err, new PrintWriter(new ByteArrayOutputStream()), + mQueue.dumpLocked(FileDescriptor.err, new PrintWriter(Writer.nullWriter()), null, 0, true, true, true, null, false); }