From 4db88d0a705ace86b893a1494bcfcf2ccf505509 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Mat=C3=ADas=20Hern=C3=A1ndez?= Date: Tue, 9 May 2023 19:27:59 +0200 Subject: [PATCH] Prepare to log post_duration_millis to statsd We now compute the milliseconds elapsed and supply the value to the NotificationRecordLogger. But note that nothing is actually logged until we update the proto file. This CL also removes the mReport field from PostNotificationTracker. After the last-minute code reshuffle in the previous change, it's no longer necessary and we can pass it directly to notifyListenersPostedAndLogLocked(). Bug: 275044361 Test: atest NotificationManagerServiceTest Change-Id: I23395aaf89d196ca87d1d7325568a46b81c036ea --- .../NotificationManagerService.java | 40 +++++++++------- .../NotificationRecordLogger.java | 2 + .../NotificationManagerServiceTest.java | 48 +++++++++---------- .../NotificationRecordLoggerFake.java | 4 ++ 4 files changed, 53 insertions(+), 41 deletions(-) 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 ff6c534b81ede..4c4bd08b61642 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