New Pipeline: Log reentrant invalidations at wtf, not e.

I'd like more data on how often these are happening, and wtf will log
exceptions in Pitot without crashing user/userdebug builds, so switch to
that, and intercept wtfs in the tests so they don't crash.

Bug: 238243716
Bug: 236072637
Bug: 231388160
Bug: 243542723
Bug: 243542867
Test: atest ShadeListBuilderTest
Change-Id: Ia763e755f5320a476a0e4dfd89ea4e5b4b7bdccd
This commit is contained in:
Julia Tuttle
2022-09-30 15:32:27 -04:00
parent fa1f278976
commit 3f17b3972b
2 changed files with 113 additions and 32 deletions

View File

@@ -1398,7 +1398,7 @@ public class ShadeListBuilder implements Dumpable, PipelineDumpable {
throw exception;
}
Log.e(TAG, "Allowing " + mConsecutiveReentrantRebuilds
Log.wtf(TAG, "Allowing " + mConsecutiveReentrantRebuilds
+ " consecutive reentrant notification pipeline rebuild(s).", exception);
mChoreographer.schedule();
}

View File

@@ -17,6 +17,7 @@
package com.android.systemui.statusbar.notification.collection;
import static com.android.systemui.statusbar.notification.collection.ListDumper.dumpTree;
import static com.android.systemui.statusbar.notification.collection.ShadeListBuilder.MAX_CONSECUTIVE_REENTRANT_REBUILDS;
import static com.google.common.truth.Truth.assertThat;
@@ -45,6 +46,7 @@ import android.os.SystemClock;
import android.testing.AndroidTestingRunner;
import android.testing.TestableLooper;
import android.util.ArrayMap;
import android.util.Log;
import androidx.annotation.NonNull;
import androidx.annotation.Nullable;
@@ -125,6 +127,10 @@ public class ShadeListBuilderTest extends SysuiTestCase {
private Map<String, Integer> mNextIdMap = new ArrayMap<>();
private int mNextRank = 0;
private Log.TerribleFailureHandler mOldWtfHandler = null;
private Log.TerribleFailure mLastWtf = null;
private int mWtfCount = 0;
@Before
public void setUp() {
MockitoAnnotations.initMocks(this);
@@ -1748,14 +1754,17 @@ public class ShadeListBuilderTest extends SysuiTestCase {
mListBuilder.addPreGroupFilter(filter);
mListBuilder.addOnBeforeTransformGroupsListener(listener);
interceptWtfs();
// WHEN we try to run the pipeline and the filter is invalidated exactly
// MAX_CONSECUTIVE_REENTRANT_REBUILDS times,
addNotif(0, PACKAGE_2);
invalidator.setInvalidationCount(ShadeListBuilder.MAX_CONSECUTIVE_REENTRANT_REBUILDS);
invalidator.setInvalidationCount(MAX_CONSECUTIVE_REENTRANT_REBUILDS);
dispatchBuild();
runWhileScheduledUpTo(ShadeListBuilder.MAX_CONSECUTIVE_REENTRANT_REBUILDS + 2);
runWhileScheduledUpTo(MAX_CONSECUTIVE_REENTRANT_REBUILDS + 2);
// THEN an exception is NOT thrown.
// THEN an exception is NOT thrown directly, but a WTF IS logged.
expectWtfs(MAX_CONSECUTIVE_REENTRANT_REBUILDS);
}
@Test(expected = IllegalStateException.class)
@@ -1767,18 +1776,24 @@ public class ShadeListBuilderTest extends SysuiTestCase {
mListBuilder.addPreGroupFilter(filter);
mListBuilder.addOnBeforeTransformGroupsListener(listener);
interceptWtfs();
// WHEN we try to run the pipeline and the filter is invalidated more than
// MAX_CONSECUTIVE_REENTRANT_REBUILDS times,
addNotif(0, PACKAGE_2);
invalidator.setInvalidationCount(ShadeListBuilder.MAX_CONSECUTIVE_REENTRANT_REBUILDS + 1);
invalidator.setInvalidationCount(MAX_CONSECUTIVE_REENTRANT_REBUILDS + 1);
dispatchBuild();
runWhileScheduledUpTo(ShadeListBuilder.MAX_CONSECUTIVE_REENTRANT_REBUILDS + 2);
try {
runWhileScheduledUpTo(MAX_CONSECUTIVE_REENTRANT_REBUILDS + 2);
} finally {
expectWtfs(MAX_CONSECUTIVE_REENTRANT_REBUILDS);
}
// THEN an exception IS thrown.
}
@Test
public void testNonConsecutiveOutOfOrderInvalidationDontThrowAfterTooManyRuns() {
public void testNonConsecutiveOutOfOrderInvalidationsDontThrowAfterTooManyRuns() {
// GIVEN a PreGroupNotifFilter that gets invalidated during the grouping stage,
NotifFilter filter = new PackageFilter(PACKAGE_1);
CountingInvalidator invalidator = new CountingInvalidator(filter);
@@ -1786,17 +1801,22 @@ public class ShadeListBuilderTest extends SysuiTestCase {
mListBuilder.addPreGroupFilter(filter);
mListBuilder.addOnBeforeTransformGroupsListener(listener);
// WHEN we try to run the pipeline and the filter is invalidated at least
// MAX_CONSECUTIVE_REENTRANT_REBUILDS times,
addNotif(0, PACKAGE_2);
invalidator.setInvalidationCount(ShadeListBuilder.MAX_CONSECUTIVE_REENTRANT_REBUILDS);
dispatchBuild();
runWhileScheduledUpTo(ShadeListBuilder.MAX_CONSECUTIVE_REENTRANT_REBUILDS + 2);
invalidator.setInvalidationCount(ShadeListBuilder.MAX_CONSECUTIVE_REENTRANT_REBUILDS);
dispatchBuild();
runWhileScheduledUpTo(ShadeListBuilder.MAX_CONSECUTIVE_REENTRANT_REBUILDS + 2);
interceptWtfs();
// THEN an exception is NOT thrown.
// WHEN we try to run the pipeline and the filter is invalidated
// MAX_CONSECUTIVE_REENTRANT_REBUILDS times, the pipeline runs for a non-reentrant reason,
// and then the filter is invalidated MAX_CONSECUTIVE_REENTRANT_REBUILDS times again,
addNotif(0, PACKAGE_2);
invalidator.setInvalidationCount(MAX_CONSECUTIVE_REENTRANT_REBUILDS);
dispatchBuild();
runWhileScheduledUpTo(MAX_CONSECUTIVE_REENTRANT_REBUILDS + 2);
invalidator.setInvalidationCount(MAX_CONSECUTIVE_REENTRANT_REBUILDS);
// Note: dispatchBuild itself triggers a non-reentrant pipeline run.
dispatchBuild();
runWhileScheduledUpTo(MAX_CONSECUTIVE_REENTRANT_REBUILDS + 2);
// THEN an exception is NOT thrown, but WTFs ARE logged.
expectWtfs(MAX_CONSECUTIVE_REENTRANT_REBUILDS * 2);
}
@Test
@@ -1808,14 +1828,18 @@ public class ShadeListBuilderTest extends SysuiTestCase {
mListBuilder.addPromoter(promoter);
mListBuilder.addOnBeforeSortListener(listener);
interceptWtfs();
// WHEN we try to run the pipeline and the promoter is invalidated exactly
// MAX_CONSECUTIVE_REENTRANT_REBUILDS times,
addNotif(0, PACKAGE_1);
invalidator.setInvalidationCount(ShadeListBuilder.MAX_CONSECUTIVE_REENTRANT_REBUILDS);
invalidator.setInvalidationCount(MAX_CONSECUTIVE_REENTRANT_REBUILDS);
dispatchBuild();
runWhileScheduledUpTo(ShadeListBuilder.MAX_CONSECUTIVE_REENTRANT_REBUILDS + 2);
runWhileScheduledUpTo(MAX_CONSECUTIVE_REENTRANT_REBUILDS + 2);
// THEN an exception is NOT thrown directly, but a WTF IS logged.
expectWtfs(MAX_CONSECUTIVE_REENTRANT_REBUILDS);
// THEN an exception is NOT thrown.
}
@Test(expected = IllegalStateException.class)
@@ -1827,12 +1851,18 @@ public class ShadeListBuilderTest extends SysuiTestCase {
mListBuilder.addPromoter(promoter);
mListBuilder.addOnBeforeSortListener(listener);
interceptWtfs();
// WHEN we try to run the pipeline and the promoter is invalidated more than
// MAX_CONSECUTIVE_REENTRANT_REBUILDS times,
addNotif(0, PACKAGE_1);
invalidator.setInvalidationCount(ShadeListBuilder.MAX_CONSECUTIVE_REENTRANT_REBUILDS + 1);
invalidator.setInvalidationCount(MAX_CONSECUTIVE_REENTRANT_REBUILDS + 1);
dispatchBuild();
runWhileScheduledUpTo(ShadeListBuilder.MAX_CONSECUTIVE_REENTRANT_REBUILDS + 2);
try {
runWhileScheduledUpTo(MAX_CONSECUTIVE_REENTRANT_REBUILDS + 2);
} finally {
expectWtfs(MAX_CONSECUTIVE_REENTRANT_REBUILDS);
}
// THEN an exception IS thrown.
}
@@ -1846,14 +1876,17 @@ public class ShadeListBuilderTest extends SysuiTestCase {
mListBuilder.setComparators(singletonList(comparator));
mListBuilder.addOnBeforeRenderListListener(listener);
interceptWtfs();
// WHEN we try to run the pipeline and the comparator is invalidated exactly
// MAX_CONSECUTIVE_REENTRANT_REBUILDS times,
addNotif(0, PACKAGE_2);
invalidator.setInvalidationCount(ShadeListBuilder.MAX_CONSECUTIVE_REENTRANT_REBUILDS);
invalidator.setInvalidationCount(MAX_CONSECUTIVE_REENTRANT_REBUILDS);
dispatchBuild();
runWhileScheduledUpTo(ShadeListBuilder.MAX_CONSECUTIVE_REENTRANT_REBUILDS + 2);
runWhileScheduledUpTo(MAX_CONSECUTIVE_REENTRANT_REBUILDS + 2);
// THEN an exception is NOT thrown.
// THEN an exception is NOT thrown directly, but a WTF IS logged.
expectWtfs(MAX_CONSECUTIVE_REENTRANT_REBUILDS);
}
@Test(expected = IllegalStateException.class)
@@ -1865,12 +1898,14 @@ public class ShadeListBuilderTest extends SysuiTestCase {
mListBuilder.setComparators(singletonList(comparator));
mListBuilder.addOnBeforeRenderListListener(listener);
interceptWtfs();
// WHEN we try to run the pipeline and the comparator is invalidated more than
// MAX_CONSECUTIVE_REENTRANT_REBUILDS times,
addNotif(0, PACKAGE_2);
invalidator.setInvalidationCount(ShadeListBuilder.MAX_CONSECUTIVE_REENTRANT_REBUILDS + 1);
invalidator.setInvalidationCount(MAX_CONSECUTIVE_REENTRANT_REBUILDS + 1);
dispatchBuild();
runWhileScheduledUpTo(ShadeListBuilder.MAX_CONSECUTIVE_REENTRANT_REBUILDS + 2);
runWhileScheduledUpTo(MAX_CONSECUTIVE_REENTRANT_REBUILDS + 2);
// THEN an exception IS thrown.
}
@@ -1884,14 +1919,17 @@ public class ShadeListBuilderTest extends SysuiTestCase {
mListBuilder.addFinalizeFilter(filter);
mListBuilder.addOnBeforeRenderListListener(listener);
interceptWtfs();
// WHEN we try to run the pipeline and the PreRenderFilter is invalidated exactly
// MAX_CONSECUTIVE_REENTRANT_REBUILDS times,
addNotif(0, PACKAGE_2);
invalidator.setInvalidationCount(ShadeListBuilder.MAX_CONSECUTIVE_REENTRANT_REBUILDS);
invalidator.setInvalidationCount(MAX_CONSECUTIVE_REENTRANT_REBUILDS);
dispatchBuild();
runWhileScheduledUpTo(ShadeListBuilder.MAX_CONSECUTIVE_REENTRANT_REBUILDS + 2);
runWhileScheduledUpTo(MAX_CONSECUTIVE_REENTRANT_REBUILDS + 2);
// THEN an exception is NOT thrown.
// THEN an exception is NOT thrown directly, but a WTF IS logged.
expectWtfs(MAX_CONSECUTIVE_REENTRANT_REBUILDS);
}
@Test(expected = IllegalStateException.class)
@@ -1903,16 +1941,59 @@ public class ShadeListBuilderTest extends SysuiTestCase {
mListBuilder.addFinalizeFilter(filter);
mListBuilder.addOnBeforeRenderListListener(listener);
interceptWtfs();
// WHEN we try to run the pipeline and the PreRenderFilter is invalidated more than
// MAX_CONSECUTIVE_REENTRANT_REBUILDS times,
addNotif(0, PACKAGE_2);
invalidator.setInvalidationCount(ShadeListBuilder.MAX_CONSECUTIVE_REENTRANT_REBUILDS + 1);
invalidator.setInvalidationCount(MAX_CONSECUTIVE_REENTRANT_REBUILDS + 1);
dispatchBuild();
runWhileScheduledUpTo(ShadeListBuilder.MAX_CONSECUTIVE_REENTRANT_REBUILDS + 2);
try {
runWhileScheduledUpTo(MAX_CONSECUTIVE_REENTRANT_REBUILDS + 2);
} finally {
expectWtfs(MAX_CONSECUTIVE_REENTRANT_REBUILDS);
}
// THEN an exception IS thrown.
}
private void interceptWtfs() {
assertNull(mOldWtfHandler);
mLastWtf = null;
mWtfCount = 0;
mOldWtfHandler = Log.setWtfHandler((tag, e, system) -> {
Log.e("ShadeListBuilderTest", "Observed WTF: " + e);
mLastWtf = e;
mWtfCount++;
});
}
private void expectNoWtfs() {
assertNull(expectWtfs(0));
}
private Log.TerribleFailure expectWtf() {
return expectWtfs(1);
}
private Log.TerribleFailure expectWtfs(int expectedWtfCount) {
assertNotNull(mOldWtfHandler);
Log.setWtfHandler(mOldWtfHandler);
mOldWtfHandler = null;
Log.TerribleFailure wtf = mLastWtf;
int wtfCount = mWtfCount;
mLastWtf = null;
mWtfCount = 0;
assertEquals(expectedWtfCount, wtfCount);
return wtf;
}
@Test
public void testStableOrdering() {
mStabilityManager.setAllowEntryReordering(false);