[FCM] UMA histogram for how long it take to read persisted GCM messages

When a message arrives for a lazy GCM subscription and Chrome isn't in
the foreground, it is persisted on disk until next time Chrome is in the
foreground.

This CL adds two histograms
1- Record the time spent to check if a subscription lazy upon receiving
a GCM message while Chrome is in the background.
2- Record the time spent in reading and replaying persisted
messages when Chrome goes to the foreground.

Bug: 882887
Change-Id: I2ea8e5a5c5242b573e842b56f08d7f1070d48856
Reviewed-on: https://chromium-review.googlesource.com/c/1333656Reviewed-by: Robert Kaplow <rkaplow@chromium.org>
Reviewed-by: Peter Conn <peconn@chromium.org>
Reviewed-by: Peter Beverloo <peter@chromium.org>
Commit-Queue: Mohamed Amir Yosef <mamir@chromium.org>
Cr-Commit-Position: refs/heads/master@{#608925}

chrome/android/java/src/org/chromium/chrome/browser/services/gcm/ChromeGcmListenerService.java

@@ -7,6 +7,7 @@ package org.chromium.chrome.browser.services.gcm;
 import android.content.Context;
 import android.os.Build;
 import android.os.Bundle;
+import android.os.SystemClock;
 import android.text.TextUtils;
 
 import com.google.android.gms.gcm.GcmListenerService;
@@ -17,6 +18,7 @@ import org.chromium.base.ContextUtils;
 import org.chromium.base.Log;
 import org.chromium.base.ThreadUtils;
 import org.chromium.base.library_loader.ProcessInitException;
+import org.chromium.base.metrics.CachedMetrics;
 import org.chromium.chrome.browser.init.ChromeBrowserInitializer;
 import org.chromium.chrome.browser.init.ProcessInitializationHandler;
 import org.chromium.components.background_task_scheduler.BackgroundTaskSchedulerFactory;
@@ -26,6 +28,8 @@ import org.chromium.components.gcm_driver.GCMDriver;
 import org.chromium.components.gcm_driver.GCMMessage;
 import org.chromium.components.gcm_driver.LazySubscriptionsManager;
 
+import java.util.concurrent.TimeUnit;
+
 /**
  * Receives Downstream messages and status of upstream messages from GCM.
  */
@@ -101,13 +105,25 @@ public class ChromeGcmListenerService extends GcmListenerService {
         ThreadUtils.assertOnUiThread();
         final String subscriptionId = LazySubscriptionsManager.buildSubscriptionUniqueId(
                 message.getAppId(), message.getSenderId());
-        if (!ApplicationStatus.hasVisibleActivities()
-                && LazySubscriptionsManager.isSubscriptionLazy(subscriptionId)) {
-            // TODO(https://crbug.com/882887): record a UMA metric for how long
-            // does it take to check if the subscription is lazy.
+        if (!ApplicationStatus.hasVisibleActivities()) {
+            boolean isSubscriptionLazy = false;
+            long time = SystemClock.elapsedRealtime();
+            if (LazySubscriptionsManager.isSubscriptionLazy(subscriptionId)) {
+                isSubscriptionLazy = true;
                 LazySubscriptionsManager.persistMessage(subscriptionId, message);
+            }
+
+            // Use {@link CachedMetrics} so this gets reported when native is
+            // loaded instead of calling native right away.
+            new CachedMetrics
+                    .TimesHistogramSample(
+                            "PushMessaging.TimeToCheckIfSubscriptionLazy", TimeUnit.MILLISECONDS)
+                    .record(SystemClock.elapsedRealtime() - time);
+
+            if (isSubscriptionLazy) {
                 return;
             }
+        }
 
         if (Build.VERSION.SDK_INT >= Build.VERSION_CODES.N) {
             Bundle extras = message.toBundle();

components/gcm_driver/android/java/src/org/chromium/components/gcm_driver/GCMDriver.java

@@ -4,15 +4,19 @@
 
 package org.chromium.components.gcm_driver;
 
+import android.os.SystemClock;
+
 import org.chromium.base.Log;
 import org.chromium.base.ThreadUtils;
 import org.chromium.base.VisibleForTesting;
 import org.chromium.base.annotations.CalledByNative;
 import org.chromium.base.annotations.JNINamespace;
+import org.chromium.base.metrics.RecordHistogram;
 import org.chromium.base.task.AsyncTask;
 
 import java.io.IOException;
 import java.util.Set;
+import java.util.concurrent.TimeUnit;
 
 /**
  * This class is the Java counterpart to the C++ GCMDriverAndroid class.
@@ -53,8 +57,7 @@ public class GCMDriver {
         // LazySubscriptionsManager.hasPersistedMessages() should be a cheap way
         // to avoid unnecessary disk reads.
         if (LazySubscriptionsManager.hasPersistedMessages()) {
-            // TODO(https://crbug.com/882887): record a UMA metric for how long
-            // does it take to read all persisted messaged.
+            long time = SystemClock.elapsedRealtime();
             Set<String> lazySubscriptionIds = LazySubscriptionsManager.getLazySubscriptionIds();
             for (String id : lazySubscriptionIds) {
                 GCMMessage[] messages = LazySubscriptionsManager.readMessages(id);
@@ -64,6 +67,14 @@ public class GCMDriver {
                 LazySubscriptionsManager.deletePersistedMessagesForSubscriptionId(id);
             }
             LazySubscriptionsManager.storeHasPersistedMessages(/*hasPersistedMessages=*/false);
+
+            long duration = SystemClock.elapsedRealtime() - time;
+            // Call RecordHistogram.recordTimesHistogram() on a background thread to avoid expensive
+            // JNI calls in the critical path.
+            AsyncTask.THREAD_POOL_EXECUTOR.execute(() -> {
+                RecordHistogram.recordTimesHistogram("PushMessaging.TimeToReadPersistedMessages",
+                        duration, TimeUnit.MILLISECONDS);
+            });
         }
         return sInstance;
     }

tools/metrics/histograms/histograms.xml

@@ -86583,6 +86583,29 @@ uploading your change for review.
   </summary>
 </histogram>
 
+<histogram name="PushMessaging.TimeToCheckIfSubscriptionLazy" units="ms"
+    expires_after="2019-11-01">
+  <owner>mamir@chromium.org</owner>
+  <summary>
+    When a message arrives to a subscription while Chrome is in the background,
+    the subscription is checked first for being lazy, and accordingly the
+    message is forwarded or persisted on disk. Since this check may require disk
+    access, this histogram measures the time spent in checking if the
+    subscription is lazy.
+  </summary>
+</histogram>
+
+<histogram name="PushMessaging.TimeToReadPersistedMessages" units="ms"
+    expires_after="2019-11-01">
+  <owner>mamir@chromium.org</owner>
+  <summary>
+    When a message arrives for a lazy subscription and Chrome isn't in the
+    foreground, it is persisted on disk until next time Chrome is in the
+    foreground. This histogram measures the time spent in reading and replaying
+    persisted messages when Chrome goes to the foreground.
+  </summary>
+</histogram>
+
 <histogram name="PushMessaging.UnregistrationGCMResult" enum="GCMClientResult">
   <owner>johnme@google.com</owner>
   <summary>