diff --git a/services/core/java/com/android/server/notification/NotificationManagerService.java b/services/core/java/com/android/server/notification/NotificationManagerService.java index f0ab815db2c16..31074c1039e6c 100755 --- a/services/core/java/com/android/server/notification/NotificationManagerService.java +++ b/services/core/java/com/android/server/notification/NotificationManagerService.java @@ -136,6 +136,7 @@ import static com.android.server.utils.PriorityDump.PRIORITY_ARG_NORMAL; import android.Manifest; import android.Manifest.permission; +import android.annotation.DurationMillisLong; import android.annotation.ElapsedRealtimeLong; import android.annotation.MainThread; import android.annotation.NonNull; @@ -7872,11 +7873,11 @@ public class NotificationManagerService extends SystemService { } if (notification.getSmallIcon() != null) { - mTracker.setReport( + NotificationRecordLogger.NotificationReported maybeReport = mNotificationRecordLogger.prepareToLogNotificationPosted(r, old, position, buzzBeepBlinkLoggingCode, - getGroupInstanceId(r.getSbn().getGroupKey()))); - notifyListenersPostedAndLogLocked(r, old, mTracker); + getGroupInstanceId(r.getSbn().getGroupKey())); + notifyListenersPostedAndLogLocked(r, old, mTracker, maybeReport); posted = true; StatusBarNotification oldSbn = (old != null) ? old.getSbn() : null; @@ -10860,16 +10861,17 @@ public class NotificationManagerService extends SystemService { */ @GuardedBy("mNotificationLock") private void notifyListenersPostedAndLogLocked(NotificationRecord r, NotificationRecord old, - @NonNull PostNotificationTracker tracker) { + @NonNull PostNotificationTracker tracker, + @Nullable NotificationRecordLogger.NotificationReported report) { List listenerCalls = mListeners.prepareNotifyPostedLocked(r, old, true); mHandler.post(() -> { for (Runnable listenerCall : listenerCalls) { listenerCall.run(); } - tracker.finish(); - NotificationRecordLogger.NotificationReported report = tracker.getReport(); + long postDurationMillis = tracker.finish(); if (report != null) { + report.post_duration_millis = postDurationMillis; mNotificationRecordLogger.logNotificationPosted(report); } }); @@ -12161,14 +12163,6 @@ public class NotificationManagerService extends SystemService { } } - void setReport(@Nullable NotificationRecordLogger.NotificationReported report) { - mReport = report; - } - - NotificationRecordLogger.NotificationReported getReport() { - return mReport; - } - @ElapsedRealtimeLong long getStartTime() { return mStartTime; @@ -12179,6 +12173,11 @@ public class NotificationManagerService extends SystemService { return mOngoing; } + /** + * Cancels the tracker (TODO(b/275044361): releasing the acquired WakeLock). Either + * {@link #finish} or {@link #cancel} (exclusively) should be called on this object before + * it's discarded. + */ void cancel() { if (!isOngoing()) { Log.wtfStack(TAG, "cancel() called on already-finished tracker"); @@ -12195,20 +12194,27 @@ public class NotificationManagerService extends SystemService { } } - void finish() { + /** + * Finishes the tracker (TODO(b/275044361): releasing the acquired WakeLock) and returns the + * time elapsed since the operation started, in milliseconds. Either {@link #finish} or + * {@link #cancel} (exclusively) should be called on this object before it's discarded. + */ + @DurationMillisLong + long finish() { + long elapsedTime = SystemClock.elapsedRealtime() - mStartTime; if (!isOngoing()) { Log.wtfStack(TAG, "finish() called on already-finished tracker"); - return; + return elapsedTime; } mOngoing = false; // TODO(b/275044361): Release wakelock. - long elapsedTime = SystemClock.elapsedRealtime() - mStartTime; if (DBG) { Slog.d(TAG, TextUtils.formatSimple("PostNotification: Finished in %d ms", elapsedTime)); } + return elapsedTime; } } } diff --git a/services/core/java/com/android/server/notification/NotificationRecordLogger.java b/services/core/java/com/android/server/notification/NotificationRecordLogger.java index 71ebf7a39610a..0cc4fc4e05162 100644 --- a/services/core/java/com/android/server/notification/NotificationRecordLogger.java +++ b/services/core/java/com/android/server/notification/NotificationRecordLogger.java @@ -21,6 +21,7 @@ import static android.service.notification.NotificationListenerService.REASON_CA import static android.service.notification.NotificationListenerService.REASON_CLEAR_DATA; import static android.service.notification.NotificationListenerService.REASON_CLICK; +import android.annotation.DurationMillisLong; import android.annotation.NonNull; import android.annotation.Nullable; import android.app.Notification; @@ -499,6 +500,7 @@ interface NotificationRecordLogger { final boolean is_foreground_service; final long timeout_millis; final boolean is_non_dismissible; + @DurationMillisLong long post_duration_millis; // Not final; calculated at the end. NotificationReported(NotificationRecordPair p, NotificationReportedEvent eventType, int position, int buzzBeepBlink, diff --git a/services/tests/uiservicestests/src/com/android/server/notification/NotificationManagerServiceTest.java b/services/tests/uiservicestests/src/com/android/server/notification/NotificationManagerServiceTest.java index 7d028d21ce0a6..025315ec42e63 100755 --- a/services/tests/uiservicestests/src/com/android/server/notification/NotificationManagerServiceTest.java +++ b/services/tests/uiservicestests/src/com/android/server/notification/NotificationManagerServiceTest.java @@ -81,6 +81,9 @@ import static com.android.internal.config.sysui.SystemUiSystemPropertiesFlags.No import static com.android.internal.config.sysui.SystemUiSystemPropertiesFlags.NotificationFlags.FSI_FORCE_DEMOTE; import static com.android.internal.config.sysui.SystemUiSystemPropertiesFlags.NotificationFlags.SHOW_STICKY_HUN_FOR_DENIED_FSI; import static com.android.internal.widget.LockPatternUtils.StrongAuthTracker.STRONG_AUTH_REQUIRED_AFTER_USER_LOCKDOWN; +import static com.android.server.notification.NotificationRecordLogger.NotificationReportedEvent.NOTIFICATION_ADJUSTED; +import static com.android.server.notification.NotificationRecordLogger.NotificationReportedEvent.NOTIFICATION_POSTED; +import static com.android.server.notification.NotificationRecordLogger.NotificationReportedEvent.NOTIFICATION_UPDATED; import static com.google.common.truth.Truth.assertThat; import static com.google.common.truth.Truth.assertWithMessage; @@ -663,6 +666,11 @@ public class NotificationManagerServiceTest extends UiServiceTestCase { for (NotificationRecordLoggerFake.CallRecord call : mNotificationRecordLogger.getCalls()) { if (call.wasLogged) { assertNotNull(call.event); + if (call.event == NOTIFICATION_POSTED || call.event == NOTIFICATION_UPDATED) { + assertThat(call.postDurationMillisLogged).isGreaterThan(0); + } else { + assertThat(call.postDurationMillisLogged).isNull(); + } } } assertThat(mNotificationRecordLogger.getPendingLogs()).isEmpty(); @@ -1564,8 +1572,7 @@ public class NotificationManagerServiceTest extends UiServiceTestCase { NotificationRecordLoggerFake.CallRecord call = mNotificationRecordLogger.get(0); assertTrue(call.wasLogged); - assertEquals(NotificationRecordLogger.NotificationReportedEvent.NOTIFICATION_POSTED, - call.event); + assertEquals(NOTIFICATION_POSTED, call.event); assertNotNull(call.r); assertNull(call.old); assertEquals(0, call.position); @@ -1574,6 +1581,7 @@ public class NotificationManagerServiceTest extends UiServiceTestCase { assertEquals(0, call.r.getSbn().getId()); assertEquals(tag, call.r.getSbn().getTag()); assertEquals(1, call.getInstanceId()); // Fake instance IDs are assigned in order + assertThat(call.postDurationMillisLogged).isGreaterThan(0); } @Test @@ -1592,17 +1600,15 @@ public class NotificationManagerServiceTest extends UiServiceTestCase { assertEquals(2, mNotificationRecordLogger.numCalls()); assertTrue(mNotificationRecordLogger.get(0).wasLogged); - assertEquals( - NotificationRecordLogger.NotificationReportedEvent.NOTIFICATION_POSTED, - mNotificationRecordLogger.event(0)); + assertEquals(NOTIFICATION_POSTED, mNotificationRecordLogger.event(0)); assertEquals(1, mNotificationRecordLogger.get(0).getInstanceId()); + assertThat(mNotificationRecordLogger.get(0).postDurationMillisLogged).isGreaterThan(0); assertTrue(mNotificationRecordLogger.get(1).wasLogged); - assertEquals( - NotificationRecordLogger.NotificationReportedEvent.NOTIFICATION_UPDATED, - mNotificationRecordLogger.event(1)); + assertEquals(NOTIFICATION_UPDATED, mNotificationRecordLogger.event(1)); // Instance ID doesn't change on update of an active notification assertEquals(1, mNotificationRecordLogger.get(1).getInstanceId()); + assertThat(mNotificationRecordLogger.get(1).postDurationMillisLogged).isGreaterThan(0); } @Test @@ -1615,9 +1621,7 @@ public class NotificationManagerServiceTest extends UiServiceTestCase { waitForIdle(); assertEquals(2, mNotificationRecordLogger.numCalls()); assertTrue(mNotificationRecordLogger.get(0).wasLogged); - assertEquals( - NotificationRecordLogger.NotificationReportedEvent.NOTIFICATION_POSTED, - mNotificationRecordLogger.event(0)); + assertEquals(NOTIFICATION_POSTED, mNotificationRecordLogger.event(0)); assertFalse(mNotificationRecordLogger.get(1).wasLogged); assertNull(mNotificationRecordLogger.event(1)); } @@ -1633,9 +1637,7 @@ public class NotificationManagerServiceTest extends UiServiceTestCase { mBinderService.enqueueNotificationWithTag(PKG, PKG, tag, 0, notif, 0); waitForIdle(); assertEquals(2, mNotificationRecordLogger.numCalls()); - assertEquals( - NotificationRecordLogger.NotificationReportedEvent.NOTIFICATION_POSTED, - mNotificationRecordLogger.event(0)); + assertEquals(NOTIFICATION_POSTED, mNotificationRecordLogger.event(0)); assertNull(mNotificationRecordLogger.event(1)); } @@ -1653,23 +1655,23 @@ public class NotificationManagerServiceTest extends UiServiceTestCase { waitForIdle(); assertEquals(3, mNotificationRecordLogger.numCalls()); - assertEquals( - NotificationRecordLogger.NotificationReportedEvent.NOTIFICATION_POSTED, - mNotificationRecordLogger.event(0)); + assertEquals(NOTIFICATION_POSTED, mNotificationRecordLogger.event(0)); assertTrue(mNotificationRecordLogger.get(0).wasLogged); assertEquals(1, mNotificationRecordLogger.get(0).getInstanceId()); + assertThat(mNotificationRecordLogger.get(0).postDurationMillisLogged).isGreaterThan(0); assertEquals( NotificationRecordLogger.NotificationCancelledEvent.NOTIFICATION_CANCEL_APP_CANCEL, mNotificationRecordLogger.event(1)); assertEquals(1, mNotificationRecordLogger.get(1).getInstanceId()); + // Cancel is not post, so no logged post_duration_millis. + assertThat(mNotificationRecordLogger.get(1).postDurationMillisLogged).isNull(); - assertEquals( - NotificationRecordLogger.NotificationReportedEvent.NOTIFICATION_POSTED, - mNotificationRecordLogger.event(2)); + assertEquals(NOTIFICATION_POSTED, mNotificationRecordLogger.event(2)); assertTrue(mNotificationRecordLogger.get(2).wasLogged); // New instance ID because notification was canceled before re-post assertEquals(2, mNotificationRecordLogger.get(2).getInstanceId()); + assertThat(mNotificationRecordLogger.get(2).postDurationMillisLogged).isGreaterThan(0); } @Test @@ -5315,10 +5317,8 @@ public class NotificationManagerServiceTest extends UiServiceTestCase { assertEquals(IMPORTANCE_HIGH, r1.getImportance()); assertTrue(r2.rankingScoreMatches(-0.5f)); assertEquals(2, mNotificationRecordLogger.numCalls()); - assertEquals(NotificationRecordLogger.NotificationReportedEvent.NOTIFICATION_ADJUSTED, - mNotificationRecordLogger.event(0)); - assertEquals(NotificationRecordLogger.NotificationReportedEvent.NOTIFICATION_ADJUSTED, - mNotificationRecordLogger.event(1)); + assertEquals(NOTIFICATION_ADJUSTED, mNotificationRecordLogger.event(0)); + assertEquals(NOTIFICATION_ADJUSTED, mNotificationRecordLogger.event(1)); assertEquals(1, mNotificationRecordLogger.get(0).getInstanceId()); assertEquals(2, mNotificationRecordLogger.get(1).getInstanceId()); } diff --git a/services/tests/uiservicestests/src/com/android/server/notification/NotificationRecordLoggerFake.java b/services/tests/uiservicestests/src/com/android/server/notification/NotificationRecordLoggerFake.java index 1bb35021d76ca..25148936b2ada 100644 --- a/services/tests/uiservicestests/src/com/android/server/notification/NotificationRecordLoggerFake.java +++ b/services/tests/uiservicestests/src/com/android/server/notification/NotificationRecordLoggerFake.java @@ -16,6 +16,8 @@ package com.android.server.notification; +import android.annotation.DurationMillisLong; + import androidx.annotation.Nullable; import com.android.internal.logging.InstanceId; @@ -38,6 +40,7 @@ class NotificationRecordLoggerFake implements NotificationRecordLogger { public int position = INVALID, buzzBeepBlink = INVALID; public boolean wasLogged; public InstanceId groupInstanceId; + @Nullable @DurationMillisLong public Long postDurationMillisLogged; CallRecord(NotificationRecord r, NotificationRecord old, int position, int buzzBeepBlink, InstanceId groupId) { @@ -111,6 +114,7 @@ class NotificationRecordLoggerFake implements NotificationRecordLogger { } mPendingLogs.remove(nr); callRecord.wasLogged = true; + callRecord.postDurationMillisLogged = nr.post_duration_millis; } @Override