From e119ee828dbc371dd40c5acba24e8cd3fe5d12db Mon Sep 17 00:00:00 2001 From: Fiona Campbell <flc@google.com> Date: Wed, 11 Oct 2023 17:14:27 +0000 Subject: [PATCH] Add DisplayManager Logging - Add logging to registering & unregistering listeners in display manager. - Add logging to follow path of listener notifications Bug: 284687313 Test: adb shell setprop persist.debug.vri_package <package-name> (cherry picked from https://googleplex-android-review.googlesource.com/q/commit:9edaca21093acaa3a53af23a1afb736225f3b141) Merged-In: I5093162cbfa632bafe6870c84177952becc82c50 Change-Id: I5093162cbfa632bafe6870c84177952becc82c50 --- .../hardware/display/DisplayManager.java | 4 +- .../display/DisplayManagerGlobal.java | 95 +++++++++++++++++-- core/java/android/view/Display.java | 4 +- core/java/android/view/ViewRootImpl.java | 10 +- .../jank/DisplayResolutionTracker.java | 4 +- .../display/DisplayManagerGlobalTest.java | 21 ++-- .../server/display/DisplayManagerService.java | 56 ++++++++++- 7 files changed, 166 insertions(+), 28 deletions(-) diff --git a/core/java/android/hardware/display/DisplayManager.java b/core/java/android/hardware/display/DisplayManager.java index 4323bf8af5fa..f53d5fe50cf1 100644 --- a/core/java/android/hardware/display/DisplayManager.java +++ b/core/java/android/hardware/display/DisplayManager.java @@ -30,6 +30,7 @@ import android.annotation.RequiresPermission; import android.annotation.SystemApi; import android.annotation.SystemService; import android.annotation.TestApi; +import android.app.ActivityThread; import android.app.KeyguardManager; import android.compat.annotation.UnsupportedAppUsage; import android.content.Context; @@ -757,7 +758,8 @@ public final class DisplayManager { */ public void registerDisplayListener(@NonNull DisplayListener listener, @Nullable Handler handler, @EventsMask long eventsMask) { - mGlobal.registerDisplayListener(listener, handler, eventsMask); + mGlobal.registerDisplayListener(listener, handler, eventsMask, + ActivityThread.currentPackageName()); } /** diff --git a/core/java/android/hardware/display/DisplayManagerGlobal.java b/core/java/android/hardware/display/DisplayManagerGlobal.java index 3be82bc2b4f9..256ac3fb4a4b 100644 --- a/core/java/android/hardware/display/DisplayManagerGlobal.java +++ b/core/java/android/hardware/display/DisplayManagerGlobal.java @@ -25,6 +25,7 @@ import android.annotation.IntDef; import android.annotation.NonNull; import android.annotation.Nullable; import android.annotation.RequiresPermission; +import android.app.ActivityThread; import android.app.PropertyInvalidatedCache; import android.compat.annotation.UnsupportedAppUsage; import android.content.Context; @@ -45,8 +46,11 @@ import android.os.Message; import android.os.RemoteException; import android.os.ServiceManager; import android.os.Trace; +import android.sysprop.DisplayProperties; +import android.text.TextUtils; import android.util.Log; import android.util.Pair; +import android.util.Slog; import android.util.SparseArray; import android.view.Display; import android.view.DisplayAdjustments; @@ -72,7 +76,13 @@ import java.util.concurrent.atomic.AtomicLong; */ public final class DisplayManagerGlobal { private static final String TAG = "DisplayManager"; - private static final boolean DEBUG = false; + + private static final String EXTRA_LOGGING_PACKAGE_NAME = + DisplayProperties.debug_vri_package().orElse(null); + private static String sCurrentPackageName = ActivityThread.currentPackageName(); + private static boolean sExtraDisplayListenerLogging = initExtraLogging(); + + private static final boolean DEBUG = false || sExtraDisplayListenerLogging; // True if display info and display ids should be cached. // @@ -126,6 +136,8 @@ public final class DisplayManagerGlobal { @VisibleForTesting public DisplayManagerGlobal(IDisplayManager dm) { mDm = dm; + initExtraLogging(); + try { mWideColorSpace = ColorSpace.get( @@ -317,12 +329,14 @@ public final class DisplayManagerGlobal { * If null, listener will use the handler for the current thread, and if still null, * the handler for the main thread. * If that is still null, a runtime exception will be thrown. + * @param packageName of the calling package. */ public void registerDisplayListener(@NonNull DisplayListener listener, - @Nullable Handler handler, @EventsMask long eventsMask) { + @Nullable Handler handler, @EventsMask long eventsMask, String packageName) { Looper looper = getLooperForHandler(handler); Handler springBoard = new Handler(looper); - registerDisplayListener(listener, new HandlerExecutor(springBoard), eventsMask); + registerDisplayListener(listener, new HandlerExecutor(springBoard), eventsMask, + packageName); } /** @@ -330,9 +344,11 @@ public final class DisplayManagerGlobal { * * @param listener The listener that will be called when display changes occur. * @param executor Executor for the thread that will be receiving the callbacks. Cannot be null. + * @param eventsMask Mask of events to be listened to. + * @param packageName of the calling package. */ public void registerDisplayListener(@NonNull DisplayListener listener, - @NonNull Executor executor, @EventsMask long eventsMask) { + @NonNull Executor executor, @EventsMask long eventsMask, String packageName) { if (listener == null) { throw new IllegalArgumentException("listener must not be null"); } @@ -341,15 +357,22 @@ public final class DisplayManagerGlobal { throw new IllegalArgumentException("The set of events to listen to must not be empty."); } + if (extraLogging()) { + Slog.i(TAG, "Registering Display Listener: " + + Long.toBinaryString(eventsMask) + ", packageName: " + packageName); + } + synchronized (mLock) { int index = findDisplayListenerLocked(listener); if (index < 0) { - mDisplayListeners.add(new DisplayListenerDelegate(listener, executor, eventsMask)); + mDisplayListeners.add(new DisplayListenerDelegate(listener, executor, eventsMask, + packageName)); registerCallbackIfNeededLocked(); } else { mDisplayListeners.get(index).setEventsMask(eventsMask); } updateCallbackIfNeededLocked(); + maybeLogAllDisplayListeners(); } } @@ -358,6 +381,10 @@ public final class DisplayManagerGlobal { throw new IllegalArgumentException("listener must not be null"); } + if (extraLogging()) { + Slog.i(TAG, "Unregistering Display Listener: " + listener); + } + synchronized (mLock) { int index = findDisplayListenerLocked(listener); if (index >= 0) { @@ -367,6 +394,18 @@ public final class DisplayManagerGlobal { updateCallbackIfNeededLocked(); } } + maybeLogAllDisplayListeners(); + } + + private void maybeLogAllDisplayListeners() { + if (!extraLogging()) { + return; + } + + Slog.i(TAG, "Currently Registered Display Listeners:"); + for (int i = 0; i < mDisplayListeners.size(); i++) { + Slog.i(TAG, i + ": " + mDisplayListeners.get(i)); + } } private static Looper getLooperForHandler(@Nullable Handler handler) { @@ -1114,15 +1153,20 @@ public final class DisplayManagerGlobal { private final DisplayInfo mDisplayInfo = new DisplayInfo(); private final Executor mExecutor; private AtomicLong mGenerationId = new AtomicLong(1); + private final String mPackageName; DisplayListenerDelegate(DisplayListener listener, @NonNull Executor executor, - @EventsMask long eventsMask) { + @EventsMask long eventsMask, String packageName) { mExecutor = executor; mListener = listener; mEventsMask = eventsMask; + mPackageName = packageName; } public void sendDisplayEvent(int displayId, @DisplayEvent int event, DisplayInfo info) { + if (extraLogging()) { + Slog.i(TAG, "Sending Display Event: " + eventToString(event)); + } long generationId = mGenerationId.get(); Message msg = Message.obtain(null, event, displayId, 0, info); mExecutor.execute(() -> { @@ -1143,11 +1187,19 @@ public final class DisplayManagerGlobal { } private void handleMessage(Message msg) { + if (extraLogging()) { + Slog.i(TAG, "DLD(" + eventToString(msg.what) + + ", display=" + msg.arg1 + + ", mEventsMask=" + Long.toBinaryString(mEventsMask) + + ", mPackageName=" + mPackageName + + ", msg.obj=" + msg.obj + + ", listener=" + mListener.getClass() + ")"); + } if (DEBUG) { - Trace.beginSection( - "DisplayListenerDelegate(" + eventToString(msg.what) + Trace.beginSection(TextUtils.trimToSize( + "DLD(" + eventToString(msg.what) + ", display=" + msg.arg1 - + ", listener=" + mListener.getClass() + ")"); + + ", listener=" + mListener.getClass() + ")", 127)); } switch (msg.what) { case EVENT_DISPLAY_ADDED: @@ -1159,6 +1211,10 @@ public final class DisplayManagerGlobal { if ((mEventsMask & DisplayManager.EVENT_FLAG_DISPLAY_CHANGED) != 0) { DisplayInfo newInfo = (DisplayInfo) msg.obj; if (newInfo != null && !newInfo.equals(mDisplayInfo)) { + if (extraLogging()) { + Slog.i(TAG, "Sending onDisplayChanged: Display Changed. Info: " + + newInfo); + } mDisplayInfo.copyFrom(newInfo); mListener.onDisplayChanged(msg.arg1); } @@ -1184,6 +1240,11 @@ public final class DisplayManagerGlobal { Trace.endSection(); } } + + @Override + public String toString() { + return "mask: {" + mEventsMask + "}, for " + mListener.getClass(); + } } /** @@ -1305,4 +1366,20 @@ public final class DisplayManagerGlobal { } return "UNKNOWN"; } + + + private static boolean initExtraLogging() { + if (sCurrentPackageName == null) { + sCurrentPackageName = ActivityThread.currentPackageName(); + sExtraDisplayListenerLogging = !TextUtils.isEmpty(EXTRA_LOGGING_PACKAGE_NAME) + && EXTRA_LOGGING_PACKAGE_NAME.equals(sCurrentPackageName); + } + // TODO: b/306170135 - return sExtraDisplayListenerLogging instead + return true; + } + + private static boolean extraLogging() { + // TODO: b/306170135 - return sExtraDisplayListenerLogging & package name check instead + return true; + } } diff --git a/core/java/android/view/Display.java b/core/java/android/view/Display.java index 0b2b6ce33666..506945501609 100644 --- a/core/java/android/view/Display.java +++ b/core/java/android/view/Display.java @@ -26,6 +26,7 @@ import android.annotation.Nullable; import android.annotation.RequiresPermission; import android.annotation.SuppressLint; import android.annotation.TestApi; +import android.app.ActivityThread; import android.app.KeyguardManager; import android.app.WindowConfiguration; import android.compat.annotation.UnsupportedAppUsage; @@ -1366,7 +1367,8 @@ public final class Display { // form of the larger DISPLAY_CHANGED event mGlobal.registerDisplayListener(toRegister, executor, DisplayManager.EVENT_FLAG_HDR_SDR_RATIO_CHANGED - | DisplayManagerGlobal.EVENT_DISPLAY_CHANGED); + | DisplayManagerGlobal.EVENT_DISPLAY_CHANGED, + ActivityThread.currentPackageName()); } } diff --git a/core/java/android/view/ViewRootImpl.java b/core/java/android/view/ViewRootImpl.java index cd2d36c60ade..a5f5818b14d3 100644 --- a/core/java/android/view/ViewRootImpl.java +++ b/core/java/android/view/ViewRootImpl.java @@ -1140,7 +1140,8 @@ public final class ViewRootImpl implements ViewParent, mDisplay = display; mBasePackageName = context.getBasePackageName(); final String name = DisplayProperties.debug_vri_package().orElse(null); - mExtraDisplayListenerLogging = !TextUtils.isEmpty(name) && name.equals(mBasePackageName); + // TODO: b/306170135 - return to using textutils check on package name. + mExtraDisplayListenerLogging = true; mThread = Thread.currentThread(); mLocation = new WindowLeaked(null); mLocation.fillInStackTrace(); @@ -1684,7 +1685,8 @@ public final class ViewRootImpl implements ViewParent, mHandler, DisplayManager.EVENT_FLAG_DISPLAY_ADDED | DisplayManager.EVENT_FLAG_DISPLAY_CHANGED - | DisplayManager.EVENT_FLAG_DISPLAY_REMOVED); + | DisplayManager.EVENT_FLAG_DISPLAY_REMOVED, + mBasePackageName); } /** @@ -2118,6 +2120,10 @@ public final class ViewRootImpl implements ViewParent, Slog.i(mTag, "DisplayState - old: " + oldDisplayState + ", new: " + newDisplayState); } + if (Trace.isTagEnabled(Trace.TRACE_TAG_WINDOW_MANAGER)) { + Trace.traceCounter(Trace.TRACE_TAG_WINDOW_MANAGER, + "vri#screenState[" + mTag + "] state=", newDisplayState); + } if (oldDisplayState != newDisplayState) { mAttachInfo.mDisplayState = newDisplayState; pokeDrawLockIfNeeded(); diff --git a/core/java/com/android/internal/jank/DisplayResolutionTracker.java b/core/java/com/android/internal/jank/DisplayResolutionTracker.java index 72a1bac28c9f..ca6c54dc0285 100644 --- a/core/java/com/android/internal/jank/DisplayResolutionTracker.java +++ b/core/java/com/android/internal/jank/DisplayResolutionTracker.java @@ -24,6 +24,7 @@ import static com.android.internal.util.FrameworkStatsLog.UIINTERACTION_FRAME_IN import android.annotation.IntDef; import android.annotation.Nullable; +import android.app.ActivityThread; import android.hardware.display.DisplayManager; import android.hardware.display.DisplayManagerGlobal; import android.os.Handler; @@ -147,7 +148,8 @@ public class DisplayResolutionTracker { public void registerDisplayListener(DisplayManager.DisplayListener listener) { manager.registerDisplayListener(listener, handler, DisplayManager.EVENT_FLAG_DISPLAY_ADDED - | DisplayManager.EVENT_FLAG_DISPLAY_CHANGED); + | DisplayManager.EVENT_FLAG_DISPLAY_CHANGED, + ActivityThread.currentPackageName()); } @Override diff --git a/core/tests/coretests/src/android/hardware/display/DisplayManagerGlobalTest.java b/core/tests/coretests/src/android/hardware/display/DisplayManagerGlobalTest.java index 149f58f0a69b..c2e6b60cd680 100644 --- a/core/tests/coretests/src/android/hardware/display/DisplayManagerGlobalTest.java +++ b/core/tests/coretests/src/android/hardware/display/DisplayManagerGlobalTest.java @@ -42,8 +42,8 @@ import org.mockito.MockitoAnnotations; public class DisplayManagerGlobalTest { private static final long ALL_DISPLAY_EVENTS = DisplayManager.EVENT_FLAG_DISPLAY_ADDED - | DisplayManager.EVENT_FLAG_DISPLAY_CHANGED - | DisplayManager.EVENT_FLAG_DISPLAY_REMOVED; + | DisplayManager.EVENT_FLAG_DISPLAY_CHANGED + | DisplayManager.EVENT_FLAG_DISPLAY_REMOVED; @Mock private IDisplayManager mDisplayManager; @@ -69,7 +69,8 @@ public class DisplayManagerGlobalTest { @Test public void testDisplayListenerIsCalled_WhenDisplayEventOccurs() throws RemoteException { - mDisplayManagerGlobal.registerDisplayListener(mListener, mHandler, ALL_DISPLAY_EVENTS); + mDisplayManagerGlobal.registerDisplayListener(mListener, mHandler, ALL_DISPLAY_EVENTS, + null); Mockito.verify(mDisplayManager) .registerCallbackWithEventMask(mCallbackCaptor.capture(), anyLong()); IDisplayManagerCallback callback = mCallbackCaptor.getValue(); @@ -97,26 +98,27 @@ public class DisplayManagerGlobalTest { public void testDisplayListenerIsNotCalled_WhenClientIsNotSubscribed() throws RemoteException { // First we subscribe to all events in order to test that the subsequent calls to // registerDisplayListener will update the event mask. - mDisplayManagerGlobal.registerDisplayListener(mListener, mHandler, ALL_DISPLAY_EVENTS); + mDisplayManagerGlobal.registerDisplayListener(mListener, mHandler, ALL_DISPLAY_EVENTS, + null); Mockito.verify(mDisplayManager) .registerCallbackWithEventMask(mCallbackCaptor.capture(), anyLong()); IDisplayManagerCallback callback = mCallbackCaptor.getValue(); int displayId = 1; mDisplayManagerGlobal.registerDisplayListener(mListener, mHandler, - ALL_DISPLAY_EVENTS & ~DisplayManager.EVENT_FLAG_DISPLAY_ADDED); + ALL_DISPLAY_EVENTS & ~DisplayManager.EVENT_FLAG_DISPLAY_ADDED, null); callback.onDisplayEvent(displayId, DisplayManagerGlobal.EVENT_DISPLAY_ADDED); waitForHandler(); Mockito.verifyZeroInteractions(mListener); mDisplayManagerGlobal.registerDisplayListener(mListener, mHandler, - ALL_DISPLAY_EVENTS & ~DisplayManager.EVENT_FLAG_DISPLAY_CHANGED); + ALL_DISPLAY_EVENTS & ~DisplayManager.EVENT_FLAG_DISPLAY_CHANGED, null); callback.onDisplayEvent(displayId, DisplayManagerGlobal.EVENT_DISPLAY_CHANGED); waitForHandler(); Mockito.verifyZeroInteractions(mListener); mDisplayManagerGlobal.registerDisplayListener(mListener, mHandler, - ALL_DISPLAY_EVENTS & ~DisplayManager.EVENT_FLAG_DISPLAY_REMOVED); + ALL_DISPLAY_EVENTS & ~DisplayManager.EVENT_FLAG_DISPLAY_REMOVED, null); callback.onDisplayEvent(displayId, DisplayManagerGlobal.EVENT_DISPLAY_REMOVED); waitForHandler(); Mockito.verifyZeroInteractions(mListener); @@ -139,7 +141,7 @@ public class DisplayManagerGlobalTest { public void testDisplayManagerGlobalRegistersWithDisplayManager_WhenThereAreListeners() throws RemoteException { mDisplayManagerGlobal.registerDisplayListener(mListener, mHandler, - DisplayManager.EVENT_FLAG_DISPLAY_BRIGHTNESS); + DisplayManager.EVENT_FLAG_DISPLAY_BRIGHTNESS, null); InOrder inOrder = Mockito.inOrder(mDisplayManager); inOrder.verify(mDisplayManager) @@ -163,6 +165,7 @@ public class DisplayManagerGlobalTest { } private void waitForHandler() { - mHandler.runWithScissors(() -> { }, 0); + mHandler.runWithScissors(() -> { + }, 0); } } diff --git a/services/core/java/com/android/server/display/DisplayManagerService.java b/services/core/java/com/android/server/display/DisplayManagerService.java index 6466b440b3a0..f9fa18a12fde 100644 --- a/services/core/java/com/android/server/display/DisplayManagerService.java +++ b/services/core/java/com/android/server/display/DisplayManagerService.java @@ -487,7 +487,8 @@ public final class DisplayManagerService extends SystemService { private boolean mBootCompleted = false; // If we would like to keep a particular eye on a package, we can set the package name. - private boolean mExtraDisplayEventLogging; + private final boolean mExtraDisplayEventLogging; + private final String mExtraDisplayLoggingPackageName; private final BroadcastReceiver mIdleModeReceiver = new BroadcastReceiver() { @Override @@ -569,8 +570,9 @@ public final class DisplayManagerService extends SystemService { mOverlayProperties = SurfaceControl.getOverlaySupport(); mSystemReady = false; mConfigParameterProvider = new DeviceConfigParameterProvider(DeviceConfigInterface.REAL); - final String name = DisplayProperties.debug_vri_package().orElse(null); - mExtraDisplayEventLogging = !TextUtils.isEmpty(name); + mExtraDisplayLoggingPackageName = DisplayProperties.debug_vri_package().orElse(null); + // TODO: b/306170135 - return TextUtils package name check instead + mExtraDisplayEventLogging = true; } public void setupSchedulerPolicies() { @@ -2836,11 +2838,24 @@ public final class DisplayManagerService extends SystemService { } private void sendDisplayEventLocked(@NonNull LogicalDisplay display, @DisplayEvent int event) { + + final boolean displayIsEnabled = display.isEnabledLocked(); + if (Trace.isTagEnabled(Trace.TRACE_TAG_POWER)) { + Trace.instant(Trace.TRACE_TAG_POWER, + "sendDisplayEventLocked#event=" + event + ",displayEnabled=" + + displayIsEnabled); + } + // Only send updates outside of DisplayManagerService for enabled displays - if (display.isEnabledLocked()) { + if (displayIsEnabled) { + if (mExtraDisplayEventLogging) { + Slog.i(TAG, "Deliver Display Event on Handler: " + event); + } int displayId = display.getDisplayIdLocked(); Message msg = mHandler.obtainMessage(MSG_DELIVER_DISPLAY_EVENT, displayId, event); mHandler.sendMessage(msg); + } else if (mExtraDisplayEventLogging) { + Slog.i(TAG, "Not Sending Display Event; display is not enabled: " + display); } } @@ -2885,6 +2900,11 @@ public final class DisplayManagerService extends SystemService { + displayId + ", event=" + event + (uids != null ? ", uids=" + uids : "")); } + if (Trace.isTagEnabled(Trace.TRACE_TAG_POWER)) { + Trace.instant(Trace.TRACE_TAG_POWER, + "deliverDisplayEvent#event=" + event + ",displayId=" + + displayId + (uids != null ? ", uids=" + uids : "")); + } // Grab the lock and copy the callbacks. final int count; @@ -2906,6 +2926,10 @@ public final class DisplayManagerService extends SystemService { // For cached apps, save the pending event until it becomes non-cached synchronized (mPendingCallbackSelfLocked) { PendingCallback pendingCallback = mPendingCallbackSelfLocked.get(uid); + if (extraLogging(callbackRecord.mPackageName)) { + Slog.i(TAG, + "Uid is cached: " + uid + ", pendingCallback: " + pendingCallback); + } if (pendingCallback == null) { mPendingCallbackSelfLocked.put(uid, new PendingCallback(callbackRecord, displayId, event)); @@ -2920,6 +2944,11 @@ public final class DisplayManagerService extends SystemService { mTempCallbacks.clear(); } + private boolean extraLogging(String packageName) { + // TODO: b/306170135 - return sExtraDisplayListenerLogging & package name check instead + return true; + } + // Runs on Handler thread. // Delivers display group event notifications to callbacks. private void deliverDisplayGroupEvent(int groupId, int event) { @@ -3339,6 +3368,7 @@ public final class DisplayManagerService extends SystemService { public final int mUid; private final IDisplayManagerCallback mCallback; private @EventsMask AtomicLong mEventsMask; + private final String mPackageName; public boolean mWifiDisplayScanRequested; @@ -3348,6 +3378,9 @@ public final class DisplayManagerService extends SystemService { mUid = uid; mCallback = callback; mEventsMask = new AtomicLong(eventsMask); + + String[] packageNames = mContext.getPackageManager().getPackagesForUid(uid); + mPackageName = packageNames == null ? null : packageNames[0]; } public void updateEventsMask(@EventsMask long eventsMask) { @@ -3356,9 +3389,13 @@ public final class DisplayManagerService extends SystemService { @Override public void binderDied() { - if (DEBUG) { + if (DEBUG || extraLogging(mPackageName)) { Slog.d(TAG, "Display listener for pid " + mPid + " died."); } + if (Trace.isTagEnabled(Trace.TRACE_TAG_POWER)) { + Trace.instant(Trace.TRACE_TAG_POWER, + "displayManagerBinderDied#mPid=" + mPid); + } onCallbackDied(this); } @@ -3367,6 +3404,15 @@ public final class DisplayManagerService extends SystemService { */ public boolean notifyDisplayEventAsync(int displayId, @DisplayEvent int event) { if (!shouldSendEvent(event)) { + if (extraLogging(mPackageName)) { + Slog.i(TAG, + "Not sending displayEvent: " + event + " due to mask:" + mEventsMask); + } + if (Trace.isTagEnabled(Trace.TRACE_TAG_POWER)) { + Trace.instant(Trace.TRACE_TAG_POWER, + "notifyDisplayEventAsync#notSendingEvent=" + event + ",mEventsMask=" + + mEventsMask); + } return true; } -- GitLab