Donate to e Foundation | Murena handsets with /e/OS | Own a part of Murena! Learn more

Commit 4db88d0a authored by Matías Hernández's avatar Matías Hernández
Browse files

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
parent 4918bf7b

services/core/java/com/android/server/notification/NotificationManagerService.java

+23 −17
Original line number Diff line number Diff line
@@ -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<Runnable> 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;















        }















    }















}

























services/core/java/com/android/server/notification/NotificationRecordLogger.java



+2
−0




























Original line number
Diff line number
Diff line








@@ -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,

































services/tests/uiservicestests/src/com/android/server/notification/NotificationManagerServiceTest.java



+24
−24




























Original line number
Diff line number
Diff line








@@ -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());















    }

































services/tests/uiservicestests/src/com/android/server/notification/NotificationRecordLoggerFake.java



+4
−0




























Original line number
Diff line number
Diff line








@@ -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