Subtle improvements to notification logging.

* NotificationLog buffer is now 10x the size when dev-logging flag is enabled.
* NotifCollection now passes a reason to buildList, which gets logged.
* ShadeListBuilder (when dev-logging flag is enabled) now logs the rank of every notification in the list.

All of these changes are targeted at better understanding whether the incorrect order of children in some situations is due to unexpected changes in the ranking provided to the ShadeListBuilder, or due to incorrect logic in that class.

Bug: 237216329
Test: atest SystemUITests
Test: dumpsysui NotifLog ShadeListBuilder
Change-Id: I45be2cc3af4114fa4285491e8fd961c0fd548f3c
This commit is contained in:
Jeff DeCew
2022-06-27 12:06:27 +00:00
parent 6dfbb419d7
commit 3d952d3514
7 changed files with 58 additions and 30 deletions

View File

@@ -27,6 +27,8 @@ import com.android.systemui.log.LogBufferFactory;
import com.android.systemui.log.LogcatEchoTracker;
import com.android.systemui.log.LogcatEchoTrackerDebug;
import com.android.systemui.log.LogcatEchoTrackerProd;
import com.android.systemui.statusbar.notification.NotifPipelineFlags;
import com.android.systemui.util.Compile;
import dagger.Module;
import dagger.Provides;
@@ -48,8 +50,14 @@ public class LogModule {
@Provides
@SysUISingleton
@NotificationLog
public static LogBuffer provideNotificationsLogBuffer(LogBufferFactory factory) {
return factory.create("NotifLog", 1000 /* maxSize */, false /* systrace */);
public static LogBuffer provideNotificationsLogBuffer(
LogBufferFactory factory,
NotifPipelineFlags notifPipelineFlags) {
int maxSize = 1000;
if (Compile.IS_DEBUG && notifPipelineFlags.isDevLoggingEnabled()) {
maxSize *= 10;
}
return factory.create("NotifLog", maxSize, false /* systrace */);
}
/** Provides a logging buffer for logs related to heads up presentation of notifications. */

View File

@@ -310,7 +310,7 @@ public class NotifCollection implements Dumpable {
}
locallyDismissNotifications(entriesToLocallyDismiss);
dispatchEventsAndRebuildList();
dispatchEventsAndRebuildList("dismissNotifications");
}
/**
@@ -354,7 +354,7 @@ public class NotifCollection implements Dumpable {
}
locallyDismissNotifications(entries);
dispatchEventsAndRebuildList();
dispatchEventsAndRebuildList("dismissAllNotifications");
}
/**
@@ -401,7 +401,7 @@ public class NotifCollection implements Dumpable {
postNotification(sbn, requireRanking(rankingMap, sbn.getKey()));
applyRanking(rankingMap);
dispatchEventsAndRebuildList();
dispatchEventsAndRebuildList("onNotificationPosted");
}
private void onNotificationGroupPosted(List<CoalescedEvent> batch) {
@@ -412,7 +412,7 @@ public class NotifCollection implements Dumpable {
for (CoalescedEvent event : batch) {
postNotification(event.getSbn(), event.getRanking());
}
dispatchEventsAndRebuildList();
dispatchEventsAndRebuildList("onNotificationGroupPosted");
}
private void onNotificationRemoved(
@@ -433,14 +433,14 @@ public class NotifCollection implements Dumpable {
entry.mCancellationReason = reason;
tryRemoveNotification(entry);
applyRanking(rankingMap);
dispatchEventsAndRebuildList();
dispatchEventsAndRebuildList("onNotificationRemoved");
}
private void onNotificationRankingUpdate(RankingMap rankingMap) {
Assert.isMainThread();
mEventQueue.add(new RankingUpdatedEvent(rankingMap));
applyRanking(rankingMap);
dispatchEventsAndRebuildList();
dispatchEventsAndRebuildList("onNotificationRankingUpdate");
}
private void onNotificationChannelModified(
@@ -450,7 +450,7 @@ public class NotifCollection implements Dumpable {
int modificationType) {
Assert.isMainThread();
mEventQueue.add(new ChannelChangedEvent(pkgName, user, channel, modificationType));
dispatchEventsAndRebuildList();
dispatchEventsAndRebuildList("onNotificationChannelModified");
}
private void onNotificationsInitialized() {
@@ -610,7 +610,7 @@ public class NotifCollection implements Dumpable {
mEventQueue.add(new RankingAppliedEvent());
}
private void dispatchEventsAndRebuildList() {
private void dispatchEventsAndRebuildList(String reason) {
Trace.beginSection("NotifCollection.dispatchEventsAndRebuildList");
mAmDispatchingToOtherCode = true;
while (!mEventQueue.isEmpty()) {
@@ -619,7 +619,7 @@ public class NotifCollection implements Dumpable {
mAmDispatchingToOtherCode = false;
if (mBuildListener != null) {
mBuildListener.onBuildList(mReadOnlyNotificationSet);
mBuildListener.onBuildList(mReadOnlyNotificationSet, reason);
}
Trace.endSection();
}
@@ -654,7 +654,7 @@ public class NotifCollection implements Dumpable {
if (!isLifetimeExtended(entry)) {
if (tryRemoveNotification(entry)) {
dispatchEventsAndRebuildList();
dispatchEventsAndRebuildList("onEndLifetimeExtension");
}
}
}
@@ -955,7 +955,7 @@ public class NotifCollection implements Dumpable {
mEventQueue.add(new EntryUpdatedEvent(entry, false /* fromSystem */));
// Skip the applyRanking step and go straight to dispatching the events
dispatchEventsAndRebuildList();
dispatchEventsAndRebuildList("updateNotificationInternally");
}
/**

View File

@@ -304,11 +304,11 @@ public class ShadeListBuilder implements Dumpable {
private final CollectionReadyForBuildListener mReadyForBuildListener =
new CollectionReadyForBuildListener() {
@Override
public void onBuildList(Collection<NotificationEntry> entries) {
public void onBuildList(Collection<NotificationEntry> entries, String reason) {
Assert.isMainThread();
mPipelineState.requireIsBefore(STATE_BUILD_STARTED);
mLogger.logOnBuildList();
mLogger.logOnBuildList(reason);
mAllEntries = entries;
mChoreographer.schedule();
}
@@ -456,7 +456,8 @@ public class ShadeListBuilder implements Dumpable {
mLogger.logEndBuildList(
mIterationCount,
mReadOnlyNotifList.size(),
countChildren(mReadOnlyNotifList));
countChildren(mReadOnlyNotifList),
/* enforcedVisualStability */ !mNotifStabilityManager.isEveryChangeAllowed());
if (mAlwaysLogList || mIterationCount % 10 == 0) {
Trace.beginSection("ShadeListBuilder.logFinalList");
mLogger.logFinalList(mNotifList);

View File

@@ -21,31 +21,42 @@ import com.android.systemui.log.LogLevel.DEBUG
import com.android.systemui.log.LogLevel.INFO
import com.android.systemui.log.LogLevel.WARNING
import com.android.systemui.log.dagger.NotificationLog
import com.android.systemui.statusbar.notification.NotifPipelineFlags
import com.android.systemui.statusbar.notification.collection.GroupEntry
import com.android.systemui.statusbar.notification.collection.ListEntry
import com.android.systemui.statusbar.notification.collection.NotificationEntry
import com.android.systemui.statusbar.notification.collection.listbuilder.pluggable.NotifFilter
import com.android.systemui.statusbar.notification.collection.listbuilder.pluggable.NotifPromoter
import com.android.systemui.statusbar.notification.logKey
import com.android.systemui.util.Compile
import javax.inject.Inject
class ShadeListBuilderLogger @Inject constructor(
notifPipelineFlags: NotifPipelineFlags,
@NotificationLog private val buffer: LogBuffer
) {
fun logOnBuildList() {
fun logOnBuildList(reason: String?) {
buffer.log(TAG, INFO, {
str1 = reason
}, {
"Request received from NotifCollection"
"Request received from NotifCollection for $str1"
})
}
fun logEndBuildList(buildId: Int, topLevelEntries: Int, numChildren: Int) {
fun logEndBuildList(
buildId: Int,
topLevelEntries: Int,
numChildren: Int,
enforcedVisualStability: Boolean
) {
buffer.log(TAG, INFO, {
long1 = buildId.toLong()
int1 = topLevelEntries
int2 = numChildren
bool1 = enforcedVisualStability
}, {
"(Build $long1) Build complete ($int1 top-level entries, $int2 children)"
"(Build $long1) Build complete ($int1 top-level entries, $int2 children)" +
" enforcedVisualStability=$bool1"
})
}
@@ -280,6 +291,8 @@ class ShadeListBuilderLogger @Inject constructor(
})
}
val logRankInFinalList = Compile.IS_DEBUG && notifPipelineFlags.isDevLoggingEnabled()
fun logFinalList(entries: List<ListEntry>) {
if (entries.isEmpty()) {
buffer.log(TAG, DEBUG, {}, { "(empty list)" })
@@ -289,16 +302,20 @@ class ShadeListBuilderLogger @Inject constructor(
buffer.log(TAG, DEBUG, {
int1 = i
str1 = entry.logKey
bool1 = logRankInFinalList
int2 = entry.representativeEntry!!.ranking.rank
}, {
"[$int1] $str1"
"[$int1] $str1".let { if (bool1) "$it rank=$int2" else it }
})
if (entry is GroupEntry) {
entry.summary?.let {
buffer.log(TAG, DEBUG, {
str1 = it.logKey
bool1 = logRankInFinalList
int2 = it.ranking.rank
}, {
" [*] $str1 (summary)"
" [*] $str1 (summary)".let { if (bool1) "$it rank=$int2" else it }
})
}
for (j in entry.children.indices) {
@@ -306,8 +323,10 @@ class ShadeListBuilderLogger @Inject constructor(
buffer.log(TAG, DEBUG, {
int1 = j
str1 = child.logKey
bool1 = logRankInFinalList
int2 = child.ranking.rank
}, {
" [$int1] $str1"
" [$int1] $str1".let { if (bool1) "$it rank=$int2" else it }
})
}
}
@@ -318,4 +337,4 @@ class ShadeListBuilderLogger @Inject constructor(
buffer.log(TAG, INFO, {}) { "Suppressing pipeline run during animation." }
}
private const val TAG = "ShadeListBuilder"
private const val TAG = "ShadeListBuilder"

View File

@@ -29,5 +29,5 @@ public interface CollectionReadyForBuildListener {
* Called by the NotifCollection to indicate that something in the collection has changed and
* that the list builder should regenerate the list.
*/
void onBuildList(Collection<NotificationEntry> entries);
void onBuildList(Collection<NotificationEntry> entries, String reason);
}

View File

@@ -1684,9 +1684,9 @@ public class NotifCollectionTest extends SysuiTestCase {
return new CollectionEvent(rawEvent, requireNonNull(mEntryCaptor.getValue()));
}
private void verifyBuiltList(Collection<NotificationEntry> list) {
verify(mBuildListener).onBuildList(mBuildListCaptor.capture());
assertEquals(new ArraySet<>(list), new ArraySet<>(mBuildListCaptor.getValue()));
private void verifyBuiltList(Collection<NotificationEntry> expectedList) {
verify(mBuildListener).onBuildList(mBuildListCaptor.capture(), any());
assertThat(mBuildListCaptor.getValue()).containsExactly(expectedList.toArray());
}
private static class RecordingCollectionListener implements NotifCollectionListener {

View File

@@ -570,7 +570,7 @@ public class ShadeListBuilderTest extends SysuiTestCase {
assertTrue(entry.hasFinishedInitialization());
// WHEN the pipeline is kicked off
mReadyForBuildListener.onBuildList(singletonList(entry));
mReadyForBuildListener.onBuildList(singletonList(entry), "test");
mPipelineChoreographer.runIfScheduled();
// THEN the entry's initialization time is reset
@@ -2092,7 +2092,7 @@ public class ShadeListBuilderTest extends SysuiTestCase {
mPendingSet.clear();
}
mReadyForBuildListener.onBuildList(mEntrySet);
mReadyForBuildListener.onBuildList(mEntrySet, "test");
mPipelineChoreographer.runIfScheduled();
}