log notification longevity and freshness

Split out monolithic visibility notifications into individual logs for
each visibility change with longevity and freshness.

Add exposure time to cancelation logs.

Bug: 20122735
Change-Id: I56c112cdb54fb65b41cfbef4c36ce8706729c5cb

diff --git a/services/core/java/com/android/server/EventLogTags.logtags b/services/core/java/com/android/server/EventLogTags.logtags
index ef9d0c3..4b65dec 100644 (file)
--- a/services/core/java/com/android/server/EventLogTags.logtags
+++ b/services/core/java/com/android/server/EventLogTags.logtags
@@ -72,7 +72,9 @@ option java_package com.android.server
 # when a notification action button has been clicked
 27521 notification_action_clicked (key|3),(action_index|1)
 # when a notification has been canceled
-27530 notification_canceled (key|3),(reason|1),(lifespan|1)
+27530 notification_canceled (key|3),(reason|1),(lifespan|1),(exposure|1)
+# replaces 27510 with a row per notification
+27531 notification_visibility (key|3),(visibile|1),(lifespan|1),(freshness|1)
 
 # ---------------------------
 # Watchdog.java

diff --git a/services/core/java/com/android/server/notification/NotificationManagerService.java b/services/core/java/com/android/server/notification/NotificationManagerService.java
index 311ca65..ef4da02 100644 (file)
--- a/services/core/java/com/android/server/notification/NotificationManagerService.java
+++ b/services/core/java/com/android/server/notification/NotificationManagerService.java
@@ -660,6 +660,7 @@ public class NotificationManagerService extends SystemService {
                 String[] newlyVisibleKeys, String[] noLongerVisibleKeys) {
             // Using ';' as separator since eventlogs uses ',' to separate
             // args.
+            // TODO remove this: b/21248682
             EventLogTags.writeNotificationVisibilityChanged(
                     TextUtils.join(";", newlyVisibleKeys),
                     TextUtils.join(";", noLongerVisibleKeys));
@@ -667,7 +668,7 @@ public class NotificationManagerService extends SystemService {
                 for (String key : newlyVisibleKeys) {
                     NotificationRecord r = mNotificationsByKey.get(key);
                     if (r == null) continue;
-                    r.stats.onVisibilityChanged(true);
+                    r.setVisibility(true);
                 }
                 // Note that we might receive this event after notifications
                 // have already left the system, e.g. after dismissing from the
@@ -676,7 +677,7 @@ public class NotificationManagerService extends SystemService {
                 for (String key : noLongerVisibleKeys) {
                     NotificationRecord r = mNotificationsByKey.get(key);
                     if (r == null) continue;
-                    r.stats.onVisibilityChanged(false);
+                    r.setVisibility(false);
                 }
             }
         }
@@ -2784,8 +2785,11 @@ public class NotificationManagerService extends SystemService {
         // Save it for users of getHistoricalNotifications()
         mArchive.record(r.sbn);
 
-        int lifespan = (int) (System.currentTimeMillis() - r.getCreationTimeMs());
-        EventLogTags.writeNotificationCanceled(canceledKey, reason, lifespan);
+        final long now = System.currentTimeMillis();
+        final int lifespan = (int) (now - r.getCreationTimeMs());
+        final long visibleSinceMs = r.getVisibleSinceMs();
+        final int exposure = visibleSinceMs == 0L ? 0 : (int) (now - visibleSinceMs);
+        EventLogTags.writeNotificationCanceled(canceledKey, reason, lifespan, exposure);
     }
 
     /**

diff --git a/services/core/java/com/android/server/notification/NotificationRecord.java b/services/core/java/com/android/server/notification/NotificationRecord.java
index 02cc840..b8478c1 100644 (file)
--- a/services/core/java/com/android/server/notification/NotificationRecord.java
+++ b/services/core/java/com/android/server/notification/NotificationRecord.java
@@ -26,6 +26,7 @@ import android.os.UserHandle;
 import android.service.notification.StatusBarNotification;
 
 import com.android.internal.annotations.VisibleForTesting;
+import com.android.server.EventLogTags;
 
 import java.io.PrintWriter;
 import java.lang.reflect.Array;
@@ -68,6 +69,12 @@ public final class NotificationRecord {
     // The first post time, stable across updates.
     private long mCreationTimeMs;
 
+    // The most recent visibility event.
+    private long mVisibleSinceMs;
+
+    // The most recent update time, or the creation time if no updates.
+    private long mUpdateTimeMs;
+
     // Is this record an update of an old record?
     public boolean isUpdate;
     private int mPackagePriority;
@@ -84,6 +91,7 @@ public final class NotificationRecord {
         mOriginalFlags = sbn.getNotification().flags;
         mRankingTimeMs = calculateRankingTimeMs(0L);
         mCreationTimeMs = sbn.getPostTime();
+        mUpdateTimeMs = mCreationTimeMs;
     }
 
     // copy any notes that the ranking system may have made before the update
@@ -95,6 +103,7 @@ public final class NotificationRecord {
         mIntercept = previous.mIntercept;
         mRankingTimeMs = calculateRankingTimeMs(previous.getRankingTimeMs());
         mCreationTimeMs = previous.mCreationTimeMs;
+        mVisibleSinceMs = previous.mVisibleSinceMs;
         // Don't copy mGlobalSortKey, recompute it.
     }
 
@@ -181,6 +190,8 @@ public final class NotificationRecord {
         pw.println(prefix + "  mGlobalSortKey=" + mGlobalSortKey);
         pw.println(prefix + "  mRankingTimeMs=" + mRankingTimeMs);
         pw.println(prefix + "  mCreationTimeMs=" + mCreationTimeMs);
+        pw.println(prefix + "  mVisibleSinceMs=" + mVisibleSinceMs);
+        pw.println(prefix + "  mUpdateTimeMs=" + mUpdateTimeMs);
     }
 
 
@@ -277,6 +288,13 @@ public final class NotificationRecord {
     }
 
     /**
+     * Returns the timestamp of the most recent updates, or the post time if none.
+     */
+    public long getUpdateTimeMs() {
+        return mUpdateTimeMs;
+    }
+
+    /**
      * Returns the timestamp of the first post, ignoring updates.
      */
     public long getCreationTimeMs() {
@@ -284,6 +302,25 @@ public final class NotificationRecord {
     }
 
     /**
+     * Returns the timestamp of the most recent visibility event, or 0L if hidden.
+     */
+    public long getVisibleSinceMs() {
+        return mVisibleSinceMs;
+    }
+
+    /**
+     * Set the visibility of the notification.
+     */
+    public void setVisibility(boolean visible) {
+        final long now = System.currentTimeMillis();
+        mVisibleSinceMs = visible ? now : 0L;
+        stats.onVisibilityChanged(visible);
+        EventLogTags.writeNotificationVisibility(getKey(), visible ? 1 : 0,
+                (int) (now - mCreationTimeMs),
+                (int) (now - mUpdateTimeMs));
+    }
+
+    /**
      * @param previousRankingTimeMs for updated notifications, {@link #getRankingTimeMs()}
      *     of the previous notification record, 0 otherwise
      */