diff options
| author | 2023-08-25 14:55:37 -0400 | |
|---|---|---|
| committer | 2023-08-30 18:28:56 -0400 | |
| commit | 4ff21545341dc98e9b32f619e4a665fe93b9099f (patch) | |
| tree | 4ded5641015cc4e1317f4e0a08249b1d3fe9c9a7 | |
| parent | 163a9defe3927567074e35277c50767c4ec85485 (diff) | |
Log lots more about notification inflation
We're debugging a bug in which an incoming call notification never
appeared, and seemed like it might've been stuck partway through the
inflation process.
We also don't have great logs at the lower levels of the inflation
process.
So, add a new log buffer (NotifInflationLog) and add logging in many
more places, making sure to cover potentially slow/hung operations well.
Bug: 290800796
Test: manual
Change-Id: I891a648748b612faae1fc732b08aa057a6cb2504
14 files changed, 503 insertions, 51 deletions
diff --git a/packages/SystemUI/src/com/android/systemui/log/dagger/LogModule.java b/packages/SystemUI/src/com/android/systemui/log/dagger/LogModule.java index 5127d142d783..6c2ce7fa5156 100644 --- a/packages/SystemUI/src/com/android/systemui/log/dagger/LogModule.java +++ b/packages/SystemUI/src/com/android/systemui/log/dagger/LogModule.java @@ -80,6 +80,14 @@ public class LogModule { return factory.create("NotifHeadsUpLog", 1000); } + /** Provides a logging buffer for logs related to inflation of notifications. */ + @Provides + @SysUISingleton + @NotifInflationLog + public static LogBuffer provideNotifInflationLogBuffer(LogBufferFactory factory) { + return factory.create("NotifInflationLog", 100); + } + /** Provides a logging buffer for notification interruption calculations. */ @Provides @SysUISingleton diff --git a/packages/SystemUI/src/com/android/systemui/log/dagger/NotifInflationLog.java b/packages/SystemUI/src/com/android/systemui/log/dagger/NotifInflationLog.java new file mode 100644 index 000000000000..9f201c377850 --- /dev/null +++ b/packages/SystemUI/src/com/android/systemui/log/dagger/NotifInflationLog.java @@ -0,0 +1,33 @@ +/* + * Copyright (C) 2023 The Android Open Source Project + * + * Licensed under the Apache License, Version 2.0 (the "License"); + * you may not use this file except in compliance with the License. + * You may obtain a copy of the License at + * + * http://www.apache.org/licenses/LICENSE-2.0 + * + * Unless required by applicable law or agreed to in writing, software + * distributed under the License is distributed on an "AS IS" BASIS, + * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. + * See the License for the specific language governing permissions and + * limitations under the License. + */ + +package com.android.systemui.log.dagger; + +import static java.lang.annotation.RetentionPolicy.RUNTIME; + +import com.android.systemui.log.LogBuffer; + +import java.lang.annotation.Documented; +import java.lang.annotation.Retention; + +import javax.inject.Qualifier; + +/** A {@link LogBuffer} for messages related to inflation of notifications. */ +@Qualifier +@Documented +@Retention(RUNTIME) +public @interface NotifInflationLog { +} diff --git a/packages/SystemUI/src/com/android/systemui/statusbar/notification/ConversationNotifications.kt b/packages/SystemUI/src/com/android/systemui/statusbar/notification/ConversationNotifications.kt index d24896148095..6e3b15da4423 100644 --- a/packages/SystemUI/src/com/android/systemui/statusbar/notification/ConversationNotifications.kt +++ b/packages/SystemUI/src/com/android/systemui/statusbar/notification/ConversationNotifications.kt @@ -34,6 +34,7 @@ import com.android.systemui.statusbar.notification.collection.inflation.BindEven import com.android.systemui.statusbar.notification.collection.notifcollection.CommonNotifCollection import com.android.systemui.statusbar.notification.collection.notifcollection.NotifCollectionListener import com.android.systemui.statusbar.notification.row.ExpandableNotificationRow +import com.android.systemui.statusbar.notification.row.NotificationContentInflaterLogger import com.android.systemui.statusbar.notification.row.NotificationContentView import com.android.systemui.statusbar.notification.stack.StackStateAnimator import com.android.systemui.statusbar.policy.HeadsUpManager @@ -47,7 +48,11 @@ class ConversationNotificationProcessor @Inject constructor( private val launcherApps: LauncherApps, private val conversationNotificationManager: ConversationNotificationManager ) { - fun processNotification(entry: NotificationEntry, recoveredBuilder: Notification.Builder) { + fun processNotification( + entry: NotificationEntry, + recoveredBuilder: Notification.Builder, + logger: NotificationContentInflaterLogger + ) { val messagingStyle = recoveredBuilder.style as? Notification.MessagingStyle ?: return messagingStyle.conversationType = if (entry.ranking.channel.isImportantConversation) @@ -55,6 +60,7 @@ class ConversationNotificationProcessor @Inject constructor( else Notification.MessagingStyle.CONVERSATION_TYPE_NORMAL entry.ranking.conversationShortcutInfo?.let { shortcutInfo -> + logger.logAsyncTaskProgress(entry, "getting shortcut icon") messagingStyle.shortcutIcon = launcherApps.getShortcutIcon(shortcutInfo) shortcutInfo.label?.let { label -> messagingStyle.conversationTitle = label diff --git a/packages/SystemUI/src/com/android/systemui/statusbar/notification/collection/NotifInflaterImpl.java b/packages/SystemUI/src/com/android/systemui/statusbar/notification/collection/NotifInflaterImpl.java index d1aa01bb2125..98109f940289 100644 --- a/packages/SystemUI/src/com/android/systemui/statusbar/notification/collection/NotifInflaterImpl.java +++ b/packages/SystemUI/src/com/android/systemui/statusbar/notification/collection/NotifInflaterImpl.java @@ -36,12 +36,14 @@ import javax.inject.Inject; public class NotifInflaterImpl implements NotifInflater { private final NotifInflationErrorManager mNotifErrorManager; + private final NotifInflaterLogger mLogger; private NotificationRowBinderImpl mNotificationRowBinder; @Inject - public NotifInflaterImpl(NotifInflationErrorManager errorManager) { + public NotifInflaterImpl(NotifInflationErrorManager errorManager, NotifInflaterLogger logger) { mNotifErrorManager = errorManager; + mLogger = logger; } /** @@ -51,12 +53,6 @@ public class NotifInflaterImpl implements NotifInflater { mNotificationRowBinder = rowBinder; } - @Override - public void rebindViews(@NonNull NotificationEntry entry, @NonNull Params params, - @NonNull InflationCallback callback) { - inflateViews(entry, params, callback); - } - /** * Called to inflate the views of an entry. Views are not considered inflated until all of its * views are bound. @@ -64,23 +60,43 @@ public class NotifInflaterImpl implements NotifInflater { @Override public void inflateViews(@NonNull NotificationEntry entry, @NonNull Params params, @NonNull InflationCallback callback) { + mLogger.logInflatingViews(entry, params); + inflateViewsImpl(entry, params, callback); + mLogger.logInflatedViews(entry); + } + @Override + public void rebindViews(@NonNull NotificationEntry entry, @NonNull Params params, + @NonNull InflationCallback callback) { + mLogger.logRebindingViews(entry, params); + inflateViewsImpl(entry, params, callback); + mLogger.logReboundViews(entry); + } + + private void inflateViewsImpl(@NonNull NotificationEntry entry, @NonNull Params params, + @NonNull InflationCallback callback) { try { requireBinder().inflateViews( entry, params, wrapInflationCallback(callback)); } catch (InflationException e) { + mLogger.logInflationException(entry, e); mNotifErrorManager.setInflationError(entry, e); } } @Override public boolean abortInflation(NotificationEntry entry) { - return entry.abortTask(); + final boolean abortedTask = entry.abortTask(); + if (abortedTask) { + mLogger.logAbortInflationAbortedTask(entry); + } + return abortedTask; } @Override public void releaseViews(@NonNull NotificationEntry entry) { + mLogger.logReleasingViews(entry); requireBinder().releaseViews(entry); } diff --git a/packages/SystemUI/src/com/android/systemui/statusbar/notification/collection/NotifInflaterLogger.kt b/packages/SystemUI/src/com/android/systemui/statusbar/notification/collection/NotifInflaterLogger.kt new file mode 100644 index 000000000000..366c7d329662 --- /dev/null +++ b/packages/SystemUI/src/com/android/systemui/statusbar/notification/collection/NotifInflaterLogger.kt @@ -0,0 +1,86 @@ +/* + * Copyright (C) 2023 The Android Open Source Project + * + * Licensed under the Apache License, Version 2.0 (the "License"); + * you may not use this file except in compliance with the License. + * You may obtain a copy of the License at + * + * http://www.apache.org/licenses/LICENSE-2.0 + * + * Unless required by applicable law or agreed to in writing, software + * distributed under the License is distributed on an "AS IS" BASIS, + * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. + * See the License for the specific language governing permissions and + * limitations under the License. + */ + +package com.android.systemui.statusbar.notification.collection + +import com.android.systemui.log.LogBuffer +import com.android.systemui.log.core.LogLevel +import com.android.systemui.log.dagger.NotifInflationLog +import com.android.systemui.statusbar.notification.InflationException +import com.android.systemui.statusbar.notification.collection.inflation.NotifInflater.Params +import com.android.systemui.statusbar.notification.logKey +import javax.inject.Inject + +class NotifInflaterLogger @Inject constructor(@NotifInflationLog private val buffer: LogBuffer) { + fun logInflatingViews(entry: NotificationEntry, params: Params) { + buffer.log( + TAG, + LogLevel.DEBUG, + { + str1 = entry.logKey + str2 = params.reason + }, + { "inflating views for $str1: $str2" } + ) + } + + fun logInflatedViews(entry: NotificationEntry) { + buffer.log(TAG, LogLevel.DEBUG, { str1 = entry.logKey }, { "inflated views for $str1" }) + } + + fun logRebindingViews(entry: NotificationEntry, params: Params) { + buffer.log( + TAG, + LogLevel.DEBUG, + { + str1 = entry.logKey + str2 = params.reason + }, + { "rebinding views for $str1: $str2" } + ) + } + + fun logReboundViews(entry: NotificationEntry) { + buffer.log(TAG, LogLevel.DEBUG, { str1 = entry.logKey }, { "rebound views for $str1" }) + } + + fun logInflationException(entry: NotificationEntry, exc: InflationException) { + buffer.log( + TAG, + LogLevel.WARNING, + { + str1 = entry.logKey + str2 = exc.stackTraceToString() + }, + { "exception inflating views for $str1: $str2" } + ) + } + + fun logAbortInflationAbortedTask(entry: NotificationEntry) { + buffer.log( + TAG, + LogLevel.DEBUG, + { str1 = entry.logKey }, + { "aborted task to abort inflation for $str1" } + ) + } + + fun logReleasingViews(entry: NotificationEntry) { + buffer.log(TAG, LogLevel.DEBUG, { str1 = entry.logKey }, { "aborting inflation for $str1" }) + } +} + +private const val TAG = "NotifInflater" diff --git a/packages/SystemUI/src/com/android/systemui/statusbar/notification/collection/inflation/NotificationRowBinderImpl.java b/packages/SystemUI/src/com/android/systemui/statusbar/notification/collection/inflation/NotificationRowBinderImpl.java index 9ecf50ee4f8c..e20614178885 100644 --- a/packages/SystemUI/src/com/android/systemui/statusbar/notification/collection/inflation/NotificationRowBinderImpl.java +++ b/packages/SystemUI/src/com/android/systemui/statusbar/notification/collection/inflation/NotificationRowBinderImpl.java @@ -67,6 +67,7 @@ public class NotificationRowBinderImpl implements NotificationRowBinder { private final ExpandableNotificationRowComponent.Builder mExpandableNotificationRowComponentBuilder; private final IconManager mIconManager; + private final NotificationRowBinderLogger mLogger; private NotificationPresenter mPresenter; private NotificationListContainer mListContainer; @@ -84,6 +85,7 @@ public class NotificationRowBinderImpl implements NotificationRowBinder { Provider<RowInflaterTask> rowInflaterTaskProvider, ExpandableNotificationRowComponent.Builder expandableNotificationRowComponentBuilder, IconManager iconManager, + NotificationRowBinderLogger logger, FeatureFlags featureFlags) { mContext = context; mNotifBindPipeline = notifBindPipeline; @@ -94,6 +96,7 @@ public class NotificationRowBinderImpl implements NotificationRowBinder { mRowInflaterTaskProvider = rowInflaterTaskProvider; mExpandableNotificationRowComponentBuilder = expandableNotificationRowComponentBuilder; mIconManager = iconManager; + mLogger = logger; mFeatureFlags = featureFlags; } @@ -124,15 +127,19 @@ public class NotificationRowBinderImpl implements NotificationRowBinder { ViewGroup parent = mListContainer.getViewParentForNotification(entry); if (entry.rowExists()) { + mLogger.logUpdatingRow(entry, params); mIconManager.updateIcons(entry); ExpandableNotificationRow row = entry.getRow(); row.reset(); updateRow(entry, row); inflateContentViews(entry, params, row, callback); } else { + mLogger.logCreatingRow(entry, params); mIconManager.createIcons(entry); + mLogger.logInflatingRow(entry); mRowInflaterTaskProvider.get().inflate(mContext, parent, entry, row -> { + mLogger.logInflatedRow(entry); // Setup the controller for the view. ExpandableNotificationRowComponent component = mExpandableNotificationRowComponentBuilder @@ -154,8 +161,10 @@ public class NotificationRowBinderImpl implements NotificationRowBinder { @Override public void releaseViews(NotificationEntry entry) { if (!entry.rowExists()) { + mLogger.logNotReleasingViewsRowDoesntExist(entry); return; } + mLogger.logReleasingViews(entry); final RowContentBindParams params = mRowContentBindStage.getStageParams(entry); params.markContentViewsFreeable(FLAG_CONTENT_VIEW_CONTRACTED); params.markContentViewsFreeable(FLAG_CONTENT_VIEW_EXPANDED); @@ -220,7 +229,9 @@ public class NotificationRowBinderImpl implements NotificationRowBinder { } params.rebindAllContentViews(); + mLogger.logRequestingRebind(entry, inflaterParams); mRowContentBindStage.requestRebind(entry, en -> { + mLogger.logRebindComplete(entry); row.setUsesIncreasedCollapsedHeight(useIncreasedCollapsedHeight); row.setIsLowPriority(isLowPriority); if (inflationCallback != null) { diff --git a/packages/SystemUI/src/com/android/systemui/statusbar/notification/collection/inflation/NotificationRowBinderLogger.kt b/packages/SystemUI/src/com/android/systemui/statusbar/notification/collection/inflation/NotificationRowBinderLogger.kt new file mode 100644 index 000000000000..7eafc59019d4 --- /dev/null +++ b/packages/SystemUI/src/com/android/systemui/statusbar/notification/collection/inflation/NotificationRowBinderLogger.kt @@ -0,0 +1,92 @@ +/* + * Copyright (C) 2023 The Android Open Source Project + * + * Licensed under the Apache License, Version 2.0 (the "License"); + * you may not use this file except in compliance with the License. + * You may obtain a copy of the License at + * + * http://www.apache.org/licenses/LICENSE-2.0 + * + * Unless required by applicable law or agreed to in writing, software + * distributed under the License is distributed on an "AS IS" BASIS, + * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. + * See the License for the specific language governing permissions and + * limitations under the License. + */ + +package com.android.systemui.statusbar.notification.collection.inflation + +import com.android.systemui.log.LogBuffer +import com.android.systemui.log.core.LogLevel +import com.android.systemui.log.dagger.NotifInflationLog +import com.android.systemui.statusbar.notification.collection.NotificationEntry +import com.android.systemui.statusbar.notification.collection.inflation.NotifInflater.Params +import com.android.systemui.statusbar.notification.logKey +import javax.inject.Inject + +class NotificationRowBinderLogger +@Inject +constructor(@NotifInflationLog private val buffer: LogBuffer) { + fun logCreatingRow(entry: NotificationEntry, params: Params) { + buffer.log( + TAG, + LogLevel.DEBUG, + { + str1 = entry.logKey + str2 = params.reason + }, + { "creating row for $str1: $str2" } + ) + } + + fun logInflatingRow(entry: NotificationEntry) { + buffer.log(TAG, LogLevel.DEBUG, { str1 = entry.logKey }, { "inflating row for $str1" }) + } + + fun logInflatedRow(entry: NotificationEntry) { + buffer.log(TAG, LogLevel.DEBUG, { str1 = entry.logKey }, { "inflated row for $str1" }) + } + + fun logUpdatingRow(entry: NotificationEntry, params: Params) { + buffer.log( + TAG, + LogLevel.DEBUG, + { + str1 = entry.logKey + str2 = params.reason + }, + { "updating row for $str1: $str2" } + ) + } + + fun logReleasingViews(entry: NotificationEntry) { + buffer.log(TAG, LogLevel.DEBUG, { str1 = entry.logKey }, { "releasing views for $str1" }) + } + + fun logNotReleasingViewsRowDoesntExist(entry: NotificationEntry) { + buffer.log( + TAG, + LogLevel.DEBUG, + { str1 = entry.logKey }, + { "not releasing views for $str1: row doesn't exist" } + ) + } + + fun logRequestingRebind(entry: NotificationEntry, params: Params) { + buffer.log( + TAG, + LogLevel.DEBUG, + { + str1 = entry.key + str2 = params.reason + }, + { "requesting rebind for $str1: $str2" } + ) + } + + fun logRebindComplete(entry: NotificationEntry) { + buffer.log(TAG, LogLevel.DEBUG, { str1 = entry.key }, { "rebind complete for $str1" }) + } +} + +private const val TAG = "NotificationRowBinder" diff --git a/packages/SystemUI/src/com/android/systemui/statusbar/notification/row/NotificationContentInflater.java b/packages/SystemUI/src/com/android/systemui/statusbar/notification/row/NotificationContentInflater.java index 86f545dc190e..f805183d52aa 100644 --- a/packages/SystemUI/src/com/android/systemui/statusbar/notification/row/NotificationContentInflater.java +++ b/packages/SystemUI/src/com/android/systemui/statusbar/notification/row/NotificationContentInflater.java @@ -80,6 +80,7 @@ public class NotificationContentInflater implements NotificationRowContentBinder private final Executor mBgExecutor; private final SmartReplyStateInflater mSmartReplyStateInflater; private final NotifLayoutInflaterFactory.Provider mNotifLayoutInflaterFactoryProvider; + private final NotificationContentInflaterLogger mLogger; @Inject NotificationContentInflater( @@ -89,7 +90,8 @@ public class NotificationContentInflater implements NotificationRowContentBinder MediaFeatureFlag mediaFeatureFlag, @Background Executor bgExecutor, SmartReplyStateInflater smartRepliesInflater, - NotifLayoutInflaterFactory.Provider notifLayoutInflaterFactoryProvider) { + NotifLayoutInflaterFactory.Provider notifLayoutInflaterFactoryProvider, + NotificationContentInflaterLogger logger) { mRemoteViewCache = remoteViewCache; mRemoteInputManager = remoteInputManager; mConversationProcessor = conversationProcessor; @@ -97,6 +99,7 @@ public class NotificationContentInflater implements NotificationRowContentBinder mBgExecutor = bgExecutor; mSmartReplyStateInflater = smartRepliesInflater; mNotifLayoutInflaterFactoryProvider = notifLayoutInflaterFactoryProvider; + mLogger = logger; } @Override @@ -111,9 +114,12 @@ public class NotificationContentInflater implements NotificationRowContentBinder // We don't want to reinflate anything for removed notifications. Otherwise views might // be readded to the stack, leading to leaks. This may happen with low-priority groups // where the removal of already removed children can lead to a reinflation. + mLogger.logNotBindingRowWasRemoved(entry); return; } + mLogger.logBinding(entry, contentToBind); + StatusBarNotification sbn = entry.getSbn(); // To check if the notification has inline image and preload inline image if necessary. @@ -141,7 +147,8 @@ public class NotificationContentInflater implements NotificationRowContentBinder mRemoteInputManager.getRemoteViewsOnClickHandler(), mIsMediaInQS, mSmartReplyStateInflater, - mNotifLayoutInflaterFactoryProvider); + mNotifLayoutInflaterFactoryProvider, + mLogger); if (mInflateSynchronously) { task.onPostExecute(task.doInBackground()); } else { @@ -166,12 +173,11 @@ public class NotificationContentInflater implements NotificationRowContentBinder bindParams.usesIncreasedHeadsUpHeight, packageContext, row, - mNotifLayoutInflaterFactoryProvider); + mNotifLayoutInflaterFactoryProvider, + mLogger); - result = inflateSmartReplyViews(result, reInflateFlags, entry, - row.getContext(), packageContext, - row.getExistingSmartReplyState(), - smartRepliesInflater); + result = inflateSmartReplyViews(result, reInflateFlags, entry, row.getContext(), + packageContext, row.getExistingSmartReplyState(), smartRepliesInflater, mLogger); apply( mBgExecutor, @@ -182,15 +188,20 @@ public class NotificationContentInflater implements NotificationRowContentBinder entry, row, mRemoteInputManager.getRemoteViewsOnClickHandler(), - null); + null /* callback */, + mLogger); return result; } @Override - public void cancelBind( + public boolean cancelBind( @NonNull NotificationEntry entry, @NonNull ExpandableNotificationRow row) { - entry.abortTask(); + final boolean abortedTask = entry.abortTask(); + if (abortedTask) { + mLogger.logCancelBindAbortedTask(entry); + } + return abortedTask; } @Override @@ -198,6 +209,7 @@ public class NotificationContentInflater implements NotificationRowContentBinder @NonNull NotificationEntry entry, @NonNull ExpandableNotificationRow row, @InflationFlag int contentToUnbind) { + mLogger.logUnbinding(entry, contentToUnbind); int curFlag = 1; while (contentToUnbind != 0) { if ((contentToUnbind & curFlag) != 0) { @@ -279,7 +291,8 @@ public class NotificationContentInflater implements NotificationRowContentBinder Context context, Context packageContext, InflatedSmartReplyState previousSmartReplyState, - SmartReplyStateInflater inflater) { + SmartReplyStateInflater inflater, + NotificationContentInflaterLogger logger) { boolean inflateContracted = (reInflateFlags & FLAG_CONTENT_VIEW_CONTRACTED) != 0 && result.newContentView != null; boolean inflateExpanded = (reInflateFlags & FLAG_CONTENT_VIEW_EXPANDED) != 0 @@ -287,14 +300,17 @@ public class NotificationContentInflater implements NotificationRowContentBinder boolean inflateHeadsUp = (reInflateFlags & FLAG_CONTENT_VIEW_HEADS_UP) != 0 && result.newHeadsUpView != null; if (inflateContracted || inflateExpanded || inflateHeadsUp) { + logger.logAsyncTaskProgress(entry, "inflating contracted smart reply state"); result.inflatedSmartReplyState = inflater.inflateSmartReplyState(entry); } if (inflateExpanded) { + logger.logAsyncTaskProgress(entry, "inflating expanded smart reply state"); result.expandedInflatedSmartReplies = inflater.inflateSmartReplyViewHolder( context, packageContext, entry, previousSmartReplyState, result.inflatedSmartReplyState); } if (inflateHeadsUp) { + logger.logAsyncTaskProgress(entry, "inflating heads up smart reply state"); result.headsUpInflatedSmartReplies = inflater.inflateSmartReplyViewHolder( context, packageContext, entry, previousSmartReplyState, result.inflatedSmartReplyState); @@ -306,22 +322,28 @@ public class NotificationContentInflater implements NotificationRowContentBinder Notification.Builder builder, boolean isLowPriority, boolean usesIncreasedHeight, boolean usesIncreasedHeadsUpHeight, Context packageContext, ExpandableNotificationRow row, - NotifLayoutInflaterFactory.Provider notifLayoutInflaterFactoryProvider) { + NotifLayoutInflaterFactory.Provider notifLayoutInflaterFactoryProvider, + NotificationContentInflaterLogger logger) { InflationProgress result = new InflationProgress(); + final NotificationEntry entryForLogging = row.getEntry(); if ((reInflateFlags & FLAG_CONTENT_VIEW_CONTRACTED) != 0) { + logger.logAsyncTaskProgress(entryForLogging, "creating contracted remote view"); result.newContentView = createContentView(builder, isLowPriority, usesIncreasedHeight); } if ((reInflateFlags & FLAG_CONTENT_VIEW_EXPANDED) != 0) { + logger.logAsyncTaskProgress(entryForLogging, "creating expanded remote view"); result.newExpandedView = createExpandedView(builder, isLowPriority); } if ((reInflateFlags & FLAG_CONTENT_VIEW_HEADS_UP) != 0) { + logger.logAsyncTaskProgress(entryForLogging, "creating heads up remote view"); result.newHeadsUpView = builder.createHeadsUpContentView(usesIncreasedHeadsUpHeight); } if ((reInflateFlags & FLAG_CONTENT_VIEW_PUBLIC) != 0) { + logger.logAsyncTaskProgress(entryForLogging, "creating public remote view"); result.newPublicView = builder.makePublicContentView(isLowPriority); } setNotifsViewsInflaterFactory(result, row, notifLayoutInflaterFactoryProvider); @@ -361,7 +383,8 @@ public class NotificationContentInflater implements NotificationRowContentBinder NotificationEntry entry, ExpandableNotificationRow row, RemoteViews.InteractionHandler remoteViewClickHandler, - @Nullable InflationCallback callback) { + @Nullable InflationCallback callback, + NotificationContentInflaterLogger logger) { NotificationContentView privateLayout = row.getPrivateLayout(); NotificationContentView publicLayout = row.getPublicLayout(); final HashMap<Integer, CancellationSignal> runningInflations = new HashMap<>(); @@ -374,6 +397,7 @@ public class NotificationContentInflater implements NotificationRowContentBinder ApplyCallback applyCallback = new ApplyCallback() { @Override public void setResultView(View v) { + logger.logAsyncTaskProgress(entry, "contracted view applied"); result.inflatedContentView = v; } @Override @@ -381,12 +405,13 @@ public class NotificationContentInflater implements NotificationRowContentBinder return result.newContentView; } }; + logger.logAsyncTaskProgress(entry, "applying contracted view"); applyRemoteView(bgExecutor, inflateSynchronously, result, reInflateFlags, flag, remoteViewCache, entry, row, isNewView, remoteViewClickHandler, callback, privateLayout, privateLayout.getContractedChild(), privateLayout.getVisibleWrapper( NotificationContentView.VISIBLE_TYPE_CONTRACTED), - runningInflations, applyCallback); + runningInflations, applyCallback, logger); } flag = FLAG_CONTENT_VIEW_EXPANDED; @@ -398,6 +423,7 @@ public class NotificationContentInflater implements NotificationRowContentBinder ApplyCallback applyCallback = new ApplyCallback() { @Override public void setResultView(View v) { + logger.logAsyncTaskProgress(entry, "expanded view applied"); result.inflatedExpandedView = v; } @@ -406,12 +432,13 @@ public class NotificationContentInflater implements NotificationRowContentBinder return result.newExpandedView; } }; + logger.logAsyncTaskProgress(entry, "applying expanded view"); applyRemoteView(bgExecutor, inflateSynchronously, result, reInflateFlags, flag, remoteViewCache, entry, row, isNewView, remoteViewClickHandler, callback, privateLayout, privateLayout.getExpandedChild(), privateLayout.getVisibleWrapper( NotificationContentView.VISIBLE_TYPE_EXPANDED), runningInflations, - applyCallback); + applyCallback, logger); } } @@ -424,6 +451,7 @@ public class NotificationContentInflater implements NotificationRowContentBinder ApplyCallback applyCallback = new ApplyCallback() { @Override public void setResultView(View v) { + logger.logAsyncTaskProgress(entry, "heads up view applied"); result.inflatedHeadsUpView = v; } @@ -432,12 +460,13 @@ public class NotificationContentInflater implements NotificationRowContentBinder return result.newHeadsUpView; } }; + logger.logAsyncTaskProgress(entry, "applying heads up view"); applyRemoteView(bgExecutor, inflateSynchronously, result, reInflateFlags, flag, remoteViewCache, entry, row, isNewView, remoteViewClickHandler, callback, privateLayout, privateLayout.getHeadsUpChild(), privateLayout.getVisibleWrapper( VISIBLE_TYPE_HEADSUP), runningInflations, - applyCallback); + applyCallback, logger); } } @@ -449,6 +478,7 @@ public class NotificationContentInflater implements NotificationRowContentBinder ApplyCallback applyCallback = new ApplyCallback() { @Override public void setResultView(View v) { + logger.logAsyncTaskProgress(entry, "public view applied"); result.inflatedPublicView = v; } @@ -457,19 +487,23 @@ public class NotificationContentInflater implements NotificationRowContentBinder return result.newPublicView; } }; + logger.logAsyncTaskProgress(entry, "applying public view"); applyRemoteView(bgExecutor, inflateSynchronously, result, reInflateFlags, flag, remoteViewCache, entry, row, isNewView, remoteViewClickHandler, callback, publicLayout, publicLayout.getContractedChild(), publicLayout.getVisibleWrapper(NotificationContentView.VISIBLE_TYPE_CONTRACTED), - runningInflations, applyCallback); + runningInflations, applyCallback, logger); } // Let's try to finish, maybe nobody is even inflating anything finishIfDone(result, reInflateFlags, remoteViewCache, runningInflations, callback, entry, - row); + row, logger); CancellationSignal cancellationSignal = new CancellationSignal(); cancellationSignal.setOnCancelListener( - () -> runningInflations.values().forEach(CancellationSignal::cancel)); + () -> { + logger.logAsyncTaskProgress(entry, "apply cancelled"); + runningInflations.values().forEach(CancellationSignal::cancel); + }); return cancellationSignal; } @@ -491,7 +525,8 @@ public class NotificationContentInflater implements NotificationRowContentBinder View existingView, NotificationViewWrapper existingWrapper, final HashMap<Integer, CancellationSignal> runningInflations, - ApplyCallback applyCallback) { + ApplyCallback applyCallback, + NotificationContentInflaterLogger logger) { RemoteViews newContentView = applyCallback.getRemoteView(); if (inflateSynchronously) { try { @@ -511,7 +546,8 @@ public class NotificationContentInflater implements NotificationRowContentBinder existingWrapper.onReinflated(); } } catch (Exception e) { - handleInflationError(runningInflations, e, row.getEntry(), callback); + handleInflationError(runningInflations, e, row.getEntry(), callback, logger, + "applying view synchronously"); // Add a running inflation to make sure we don't trigger callbacks. // Safe to do because only happens in tests. runningInflations.put(inflationId, new CancellationSignal()); @@ -532,7 +568,7 @@ public class NotificationContentInflater implements NotificationRowContentBinder String invalidReason = isValidView(v, entry, row.getResources()); if (invalidReason != null) { handleInflationError(runningInflations, new InflationException(invalidReason), - row.getEntry(), callback); + row.getEntry(), callback, logger, "applied invalid view"); runningInflations.remove(inflationId); return; } @@ -543,7 +579,7 @@ public class NotificationContentInflater implements NotificationRowContentBinder } runningInflations.remove(inflationId); finishIfDone(result, reInflateFlags, remoteViewCache, runningInflations, - callback, entry, row); + callback, entry, row, logger); } @Override @@ -569,7 +605,7 @@ public class NotificationContentInflater implements NotificationRowContentBinder } catch (Exception anotherException) { runningInflations.remove(inflationId); handleInflationError(runningInflations, e, row.getEntry(), - callback); + callback, logger, "applying view"); } } }; @@ -653,8 +689,10 @@ public class NotificationContentInflater implements NotificationRowContentBinder private static void handleInflationError( HashMap<Integer, CancellationSignal> runningInflations, Exception e, - NotificationEntry notification, @Nullable InflationCallback callback) { + NotificationEntry notification, @Nullable InflationCallback callback, + NotificationContentInflaterLogger logger, String logContext) { Assert.isMainThread(); + logger.logAsyncTaskException(notification, logContext, e); runningInflations.values().forEach(CancellationSignal::cancel); if (callback != null) { callback.handleInflationException(notification, e); @@ -670,11 +708,12 @@ public class NotificationContentInflater implements NotificationRowContentBinder @InflationFlag int reInflateFlags, NotifRemoteViewCache remoteViewCache, HashMap<Integer, CancellationSignal> runningInflations, @Nullable InflationCallback endListener, NotificationEntry entry, - ExpandableNotificationRow row) { + ExpandableNotificationRow row, NotificationContentInflaterLogger logger) { Assert.isMainThread(); NotificationContentView privateLayout = row.getPrivateLayout(); NotificationContentView publicLayout = row.getPublicLayout(); if (runningInflations.isEmpty()) { + logger.logAsyncTaskProgress(entry, "finishing"); boolean setRepliesAndActions = true; if ((reInflateFlags & FLAG_CONTENT_VIEW_CONTRACTED) != 0) { if (result.inflatedContentView != null) { @@ -828,6 +867,7 @@ public class NotificationContentInflater implements NotificationRowContentBinder private final boolean mIsMediaInQS; private final SmartReplyStateInflater mSmartRepliesInflater; private final NotifLayoutInflaterFactory.Provider mNotifLayoutInflaterFactoryProvider; + private final NotificationContentInflaterLogger mLogger; private AsyncInflationTask( Executor bgExecutor, @@ -844,7 +884,8 @@ public class NotificationContentInflater implements NotificationRowContentBinder RemoteViews.InteractionHandler remoteViewClickHandler, boolean isMediaFlagEnabled, SmartReplyStateInflater smartRepliesInflater, - NotifLayoutInflaterFactory.Provider notifLayoutInflaterFactoryProvider) { + NotifLayoutInflaterFactory.Provider notifLayoutInflaterFactoryProvider, + NotificationContentInflaterLogger logger) { mEntry = entry; mRow = row; mBgExecutor = bgExecutor; @@ -861,6 +902,7 @@ public class NotificationContentInflater implements NotificationRowContentBinder mConversationProcessor = conversationProcessor; mIsMediaInQS = isMediaFlagEnabled; mNotifLayoutInflaterFactoryProvider = notifLayoutInflaterFactoryProvider; + mLogger = logger; entry.setInflationTask(this); } @@ -900,13 +942,16 @@ public class NotificationContentInflater implements NotificationRowContentBinder packageContext = new RtlEnabledContext(packageContext); } if (mEntry.getRanking().isConversation()) { - mConversationProcessor.processNotification(mEntry, recoveredBuilder); + mConversationProcessor.processNotification(mEntry, recoveredBuilder, mLogger); } InflationProgress inflationProgress = createRemoteViews(mReInflateFlags, recoveredBuilder, mIsLowPriority, mUsesIncreasedHeight, mUsesIncreasedHeadsUpHeight, packageContext, mRow, - mNotifLayoutInflaterFactoryProvider); + mNotifLayoutInflaterFactoryProvider, mLogger); + mLogger.logAsyncTaskProgress(mEntry, + "getting existing smart reply state (on wrong thread!)"); InflatedSmartReplyState previousSmartReplyState = mRow.getExistingSmartReplyState(); + mLogger.logAsyncTaskProgress(mEntry, "inflating smart reply views"); InflationProgress result = inflateSmartReplyViews( inflationProgress, mReInflateFlags, @@ -914,14 +959,20 @@ public class NotificationContentInflater implements NotificationRowContentBinder mContext, packageContext, previousSmartReplyState, - mSmartRepliesInflater); + mSmartRepliesInflater, + mLogger); + mLogger.logAsyncTaskProgress(mEntry, + "getting row image resolver (on wrong thread!)"); + final NotificationInlineImageResolver imageResolver = mRow.getImageResolver(); // wait for image resolver to finish preloading - mRow.getImageResolver().waitForPreloadedImages(IMG_PRELOAD_TIMEOUT_MS); + mLogger.logAsyncTaskProgress(mEntry, "waiting for preloaded images"); + imageResolver.waitForPreloadedImages(IMG_PRELOAD_TIMEOUT_MS); return result; } catch (Exception e) { mError = e; + mLogger.logAsyncTaskException(mEntry, "inflating", e); return null; } } @@ -929,6 +980,7 @@ public class NotificationContentInflater implements NotificationRowContentBinder @Override protected void onPostExecute(InflationProgress result) { if (mError == null) { + // Logged in detail in apply. mCancellationSignal = apply( mBgExecutor, mInflateSynchronously, @@ -938,7 +990,8 @@ public class NotificationContentInflater implements NotificationRowContentBinder mEntry, mRow, mRemoteViewClickHandler, - this); + this /* callback */, + mLogger); } else { handleError(mError); } @@ -961,10 +1014,13 @@ public class NotificationContentInflater implements NotificationRowContentBinder @Override public void abort() { + mLogger.logAsyncTaskProgress(mEntry, "cancelling inflate"); cancel(true /* mayInterruptIfRunning */); if (mCancellationSignal != null) { + mLogger.logAsyncTaskProgress(mEntry, "cancelling apply"); mCancellationSignal.cancel(); } + mLogger.logAsyncTaskProgress(mEntry, "aborted"); } @Override diff --git a/packages/SystemUI/src/com/android/systemui/statusbar/notification/row/NotificationContentInflaterLogger.kt b/packages/SystemUI/src/com/android/systemui/statusbar/notification/row/NotificationContentInflaterLogger.kt new file mode 100644 index 000000000000..4f5455dc455f --- /dev/null +++ b/packages/SystemUI/src/com/android/systemui/statusbar/notification/row/NotificationContentInflaterLogger.kt @@ -0,0 +1,129 @@ +/* + * Copyright (C) 2023 The Android Open Source Project + * + * Licensed under the Apache License, Version 2.0 (the "License"); + * you may not use this file except in compliance with the License. + * You may obtain a copy of the License at + * + * http://www.apache.org/licenses/LICENSE-2.0 + * + * Unless required by applicable law or agreed to in writing, software + * distributed under the License is distributed on an "AS IS" BASIS, + * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. + * See the License for the specific language governing permissions and + * limitations under the License. + */ + +package com.android.systemui.statusbar.notification.row + +import com.android.systemui.log.LogBuffer +import com.android.systemui.log.core.LogLevel +import com.android.systemui.log.dagger.NotifInflationLog +import com.android.systemui.statusbar.notification.collection.NotificationEntry +import com.android.systemui.statusbar.notification.logKey +import com.android.systemui.statusbar.notification.row.NotificationRowContentBinder.FLAG_CONTENT_VIEW_ALL +import com.android.systemui.statusbar.notification.row.NotificationRowContentBinder.FLAG_CONTENT_VIEW_CONTRACTED +import com.android.systemui.statusbar.notification.row.NotificationRowContentBinder.FLAG_CONTENT_VIEW_EXPANDED +import com.android.systemui.statusbar.notification.row.NotificationRowContentBinder.FLAG_CONTENT_VIEW_HEADS_UP +import com.android.systemui.statusbar.notification.row.NotificationRowContentBinder.FLAG_CONTENT_VIEW_PUBLIC +import com.android.systemui.statusbar.notification.row.NotificationRowContentBinder.InflationFlag +import javax.inject.Inject + +class NotificationContentInflaterLogger +@Inject +constructor(@NotifInflationLog private val buffer: LogBuffer) { + fun logNotBindingRowWasRemoved(entry: NotificationEntry) { + buffer.log( + TAG, + LogLevel.INFO, + { str1 = entry.logKey }, + { "not inflating $str1: row was removed" } + ) + } + + fun logBinding(entry: NotificationEntry, @InflationFlag flag: Int) { + buffer.log( + TAG, + LogLevel.DEBUG, + { + str1 = entry.logKey + int1 = flag + }, + { "binding views ${flagToString(int1)} for $str1" } + ) + } + + fun logCancelBindAbortedTask(entry: NotificationEntry) { + buffer.log( + TAG, + LogLevel.INFO, + { str1 = entry.logKey }, + { "aborted task to cancel binding $str1" } + ) + } + + fun logUnbinding(entry: NotificationEntry, @InflationFlag flag: Int) { + buffer.log( + TAG, + LogLevel.DEBUG, + { + str1 = entry.logKey + int1 = flag + }, + { "unbinding views ${flagToString(int1)} for $str1" } + ) + } + + fun logAsyncTaskProgress(entry: NotificationEntry, progress: String) { + buffer.log( + TAG, + LogLevel.DEBUG, + { + str1 = entry.logKey + str2 = progress + }, + { "async task for $str1: $str2" } + ) + } + + fun logAsyncTaskException(entry: NotificationEntry, logContext: String, exception: Throwable) { + buffer.log( + TAG, + LogLevel.DEBUG, + { + str1 = entry.logKey + str2 = logContext + str3 = exception.stackTraceToString() + }, + { "async task for $str1 got exception $str2: $str3" } + ) + } + + companion object { + fun flagToString(@InflationFlag flag: Int): String { + if (flag == 0) { + return "NONE" + } + if (flag == FLAG_CONTENT_VIEW_ALL) { + return "ALL" + } + + var l = mutableListOf<String>() + if (flag and FLAG_CONTENT_VIEW_CONTRACTED != 0) { + l.add("CONTRACTED") + } + if (flag and FLAG_CONTENT_VIEW_EXPANDED != 0) { + l.add("EXPANDED") + } + if (flag and FLAG_CONTENT_VIEW_HEADS_UP != 0) { + l.add("HEADS_UP") + } + if (flag and FLAG_CONTENT_VIEW_PUBLIC != 0) { + l.add("PUBLIC") + } + return l.joinToString("|") + } + } +} + +private const val TAG = "NotificationContentInflater" diff --git a/packages/SystemUI/src/com/android/systemui/statusbar/notification/row/NotificationRowContentBinder.java b/packages/SystemUI/src/com/android/systemui/statusbar/notification/row/NotificationRowContentBinder.java index a9f83c8b9e6b..d7b7aa210257 100644 --- a/packages/SystemUI/src/com/android/systemui/statusbar/notification/row/NotificationRowContentBinder.java +++ b/packages/SystemUI/src/com/android/systemui/statusbar/notification/row/NotificationRowContentBinder.java @@ -54,8 +54,9 @@ public interface NotificationRowContentBinder { * * @param entry notification * @param row notification row to cancel bind on + * @return true if an on-going bind operation was cancelled */ - void cancelBind( + boolean cancelBind( @NonNull NotificationEntry entry, @NonNull ExpandableNotificationRow row); diff --git a/packages/SystemUI/src/com/android/systemui/statusbar/notification/row/RowContentBindStage.java b/packages/SystemUI/src/com/android/systemui/statusbar/notification/row/RowContentBindStage.java index 81cf14646465..b70da00ad517 100644 --- a/packages/SystemUI/src/com/android/systemui/statusbar/notification/row/RowContentBindStage.java +++ b/packages/SystemUI/src/com/android/systemui/statusbar/notification/row/RowContentBindStage.java @@ -57,7 +57,7 @@ public class RowContentBindStage extends BindStage<RowContentBindParams> { @NonNull StageCallback callback) { RowContentBindParams params = getStageParams(entry); - mLogger.logStageParams(entry, params); + mLogger.logExecutingStage(entry, params); // Resolve content to bind/unbind. @InflationFlag int inflationFlags = params.getContentViews(); @@ -96,7 +96,10 @@ public class RowContentBindStage extends BindStage<RowContentBindParams> { protected void abortStage( @NonNull NotificationEntry entry, @NonNull ExpandableNotificationRow row) { - mBinder.cancelBind(entry, row); + final boolean cancelledBind = mBinder.cancelBind(entry, row); + if (cancelledBind) { + mLogger.logAbortStageCancelledBind(entry); + } } @Override diff --git a/packages/SystemUI/src/com/android/systemui/statusbar/notification/row/RowContentBindStageLogger.kt b/packages/SystemUI/src/com/android/systemui/statusbar/notification/row/RowContentBindStageLogger.kt index 02627fd8f975..1b961cfbb34c 100644 --- a/packages/SystemUI/src/com/android/systemui/statusbar/notification/row/RowContentBindStageLogger.kt +++ b/packages/SystemUI/src/com/android/systemui/statusbar/notification/row/RowContentBindStageLogger.kt @@ -16,22 +16,30 @@ package com.android.systemui.statusbar.notification.row -import com.android.systemui.log.dagger.NotificationLog import com.android.systemui.log.LogBuffer import com.android.systemui.log.core.LogLevel.INFO +import com.android.systemui.log.dagger.NotifInflationLog import com.android.systemui.statusbar.notification.collection.NotificationEntry import com.android.systemui.statusbar.notification.logKey import javax.inject.Inject class RowContentBindStageLogger @Inject constructor( - @NotificationLog private val buffer: LogBuffer + @NotifInflationLog private val buffer: LogBuffer ) { - fun logStageParams(entry: NotificationEntry, stageParams: RowContentBindParams) { + fun logExecutingStage(entry: NotificationEntry, stageParams: RowContentBindParams) { buffer.log(TAG, INFO, { str1 = entry.logKey str2 = stageParams.toString() }, { - "Invalidated notif $str1 with params: $str2" + "executing bind stage for $str1 with params $str2" + }) + } + + fun logAbortStageCancelledBind(entry: NotificationEntry) { + buffer.log(TAG, INFO, { + str1 = entry.logKey + }, { + "cancelled bind to abort stage for $str1" }) } } diff --git a/packages/SystemUI/tests/src/com/android/systemui/statusbar/notification/row/NotificationContentInflaterTest.java b/packages/SystemUI/tests/src/com/android/systemui/statusbar/notification/row/NotificationContentInflaterTest.java index ea87c808debd..e52cb572f289 100644 --- a/packages/SystemUI/tests/src/com/android/systemui/statusbar/notification/row/NotificationContentInflaterTest.java +++ b/packages/SystemUI/tests/src/com/android/systemui/statusbar/notification/row/NotificationContentInflaterTest.java @@ -135,7 +135,8 @@ public class NotificationContentInflaterTest extends SysuiTestCase { mock(MediaFeatureFlag.class), mock(Executor.class), mSmartReplyStateInflater, - mNotifLayoutInflaterFactoryProvider); + mNotifLayoutInflaterFactoryProvider, + mock(NotificationContentInflaterLogger.class)); } @Test @@ -258,7 +259,8 @@ public class NotificationContentInflaterTest extends SysuiTestCase { return new AsyncFailRemoteView(mContext.getPackageName(), R.layout.custom_view_dark); } - }); + }, + mock(NotificationContentInflaterLogger.class)); assertTrue(countDownLatch.await(500, TimeUnit.MILLISECONDS)); } diff --git a/packages/SystemUI/tests/src/com/android/systemui/statusbar/notification/row/NotificationTestHelper.java b/packages/SystemUI/tests/src/com/android/systemui/statusbar/notification/row/NotificationTestHelper.java index 9dfcb3f75eb1..638694038a6a 100644 --- a/packages/SystemUI/tests/src/com/android/systemui/statusbar/notification/row/NotificationTestHelper.java +++ b/packages/SystemUI/tests/src/com/android/systemui/statusbar/notification/row/NotificationTestHelper.java @@ -174,7 +174,8 @@ public class NotificationTestHelper { mock(MediaFeatureFlag.class), mock(Executor.class), new MockSmartReplyInflater(), - mock(NotifLayoutInflaterFactory.Provider.class)); + mock(NotifLayoutInflaterFactory.Provider.class), + mock(NotificationContentInflaterLogger.class)); contentBinder.setInflateSynchronously(true); mBindStage = new RowContentBindStage(contentBinder, mock(NotifInflationErrorManager.class), |