android: Fix Startup.FirstCommitNavigationTime histogram

This CL makes following changes to the
Startup.FirstCommitNavigationTime3 histogram:
* Do not record the histogram multiple times per session
* Start recording from the application start time instead of the
  foreground time
* Record the histogram only for ChromeTabbedActivity
* Ignore foreground state, there will be separate histogram for this
  purpose
* Discard error, same document and non http(s) pages

The CL also renames the histogram to
Startup.Android.Experimental.Cold.TimeToFirstNavigationCommit

The rationale behind the recording the histogram from the application
start time instead of the foreground time:

The current metric doesn't cover the important part of the startup
latency because the ForegroundStartTime is measured after the native
library is loaded. That's a lot of important data missed. We're
exploring various ways to speed up the startup including the time
of native library initialization. We want to have a metric that will
show us these improvements.
Initially, this metric was measuring cold startups from the application
start but then it was changed. We would like to return to the initial
meaning. pasko@ described an evolution of the metric in
https://goo.gl/NyvX39

Bug: 778302
Change-Id: I01d7a6a73fbc504e31c1e877b1253fcf69a54ad8
Reviewed-on: https://chromium-review.googlesource.com/788875Reviewed-by: Yaron Friedman <yfriedman@chromium.org>
Reviewed-by: David Trainor <dtrainor@chromium.org>
Reviewed-by: Alexei Svitkine <asvitkine@chromium.org>
Reviewed-by: Egor Pasko <pasko@chromium.org>
Commit-Queue: Alexandr Ilin <alexilin@chromium.org>
Cr-Commit-Position: refs/heads/master@{#521771}

chrome/android/java/src/org/chromium/chrome/browser/metrics/UmaUtils.java

@@ -8,6 +8,9 @@ import android.os.SystemClock;
 
 import org.chromium.base.annotations.CalledByNative;
 import org.chromium.base.annotations.JNINamespace;
+import org.chromium.base.metrics.RecordHistogram;
+
+import java.util.concurrent.TimeUnit;
 
 /**
  * Utilities to support startup metrics - Android version.
@@ -17,8 +20,10 @@ public class UmaUtils {
     private static long sApplicationStartWallClockMs;
 
     private static boolean sRunningApplicationStart;
+    private static long sApplicationStartTimeMs;
     private static long sForegroundStartTimeMs;
     private static long sBackgroundTimeMs;
+    private static long sFirstCommitTimeMs;
 
     /**
      * Record the time at which the activity started. This should be called asap after
@@ -30,6 +35,7 @@ public class UmaUtils {
         // then need the start time in the C++ side before we return to Java. As such we
         // save it in a static that the C++ can fetch once it has initialized the JNI.
         sApplicationStartWallClockMs = System.currentTimeMillis();
+        sApplicationStartTimeMs = SystemClock.uptimeMillis();
     }
 
     /**
@@ -51,6 +57,22 @@ public class UmaUtils {
         sBackgroundTimeMs = SystemClock.uptimeMillis();
     }
 
+    /**
+     * Record the time after a navigation is finished.
+     */
+    public static void recordFinishNavigation(boolean isTrackedPage) {
+        boolean shouldRecordHistogram =
+                isTrackedPage && sRunningApplicationStart && sFirstCommitTimeMs == 0;
+        if (shouldRecordHistogram) {
+            sFirstCommitTimeMs = SystemClock.uptimeMillis() - sApplicationStartTimeMs;
+            // Uses the same buckets as UMA_HISTOGRAM_LONG_TIMES_100
+            RecordHistogram.recordCustomTimesHistogram(
+                    "Startup.Android.Experimental.Cold.TimeToFirstNavigationCommit",
+                    sFirstCommitTimeMs, 1, TimeUnit.HOURS.toMillis(1), TimeUnit.MILLISECONDS, 100);
+        }
+        sRunningApplicationStart = false;
+    }
+
     /**
      * Determines if Chrome was brought to foreground.
      */
@@ -88,6 +110,10 @@ public class UmaUtils {
         return sApplicationStartWallClockMs;
     }
 
+    public static long getApplicationStartTimeMs() {
+        return sApplicationStartTimeMs;
+    }
+
     public static long getForegroundStartTime() {
         assert sForegroundStartTimeMs != 0;
         return sForegroundStartTimeMs;

chrome/android/java/src/org/chromium/chrome/browser/tab/TabWebContentsObserver.java

@@ -4,7 +4,6 @@
 
 package org.chromium.chrome.browser.tab;
 
-import android.os.SystemClock;
 import android.support.annotation.IntDef;
 import android.view.View;
 
@@ -20,11 +19,10 @@ import org.chromium.chrome.browser.media.MediaCaptureNotificationService;
 import org.chromium.chrome.browser.metrics.UmaUtils;
 import org.chromium.chrome.browser.policy.PolicyAuditor;
 import org.chromium.chrome.browser.policy.PolicyAuditor.AuditEvent;
+import org.chromium.chrome.browser.util.UrlUtilities;
 import org.chromium.content_public.browser.WebContents;
 import org.chromium.content_public.browser.WebContentsObserver;
 
-import java.util.concurrent.TimeUnit;
-
 /**
  * WebContentsObserver used by Tab.
  */
@@ -206,22 +204,10 @@ public class TabWebContentsObserver extends WebContentsObserver {
             recordErrorInPolicyAuditor(url, errorDescription, errorCode);
         }
 
+        boolean isTrackedPage = hasCommitted && isInMainFrame && !isErrorPage && !isSameDocument
+                && !isFragmentNavigation && UrlUtilities.isHttpOrHttps(url);
+        UmaUtils.recordFinishNavigation(isTrackedPage);
         if (!hasCommitted) return;
-        if (isInMainFrame && UmaUtils.hasComeToForeground()) {
-            // Current median is 550ms, and long tail is very long. ZoomedIn gives good view of the
-            // median and ZoomedOut gives a good overview.
-            RecordHistogram.recordCustomTimesHistogram(
-                    "Startup.FirstCommitNavigationTime3.ZoomedIn",
-                    SystemClock.uptimeMillis() - UmaUtils.getForegroundStartTime(), 200, 1000,
-                    TimeUnit.MILLISECONDS, 100);
-            // For ZoomedOut very rarely is it under 50ms and this range matches
-            // CustomTabs.IntentToFirstCommitNavigationTime2.ZoomedOut.
-            RecordHistogram.recordCustomTimesHistogram(
-                    "Startup.FirstCommitNavigationTime3.ZoomedOut",
-                    SystemClock.uptimeMillis() - UmaUtils.getForegroundStartTime(), 50,
-                    TimeUnit.MINUTES.toMillis(10), TimeUnit.MILLISECONDS, 50);
-            UmaUtils.setRunningApplicationStart(false);
-        }
 
         if (isInMainFrame) {
             mTab.setIsTabStateDirty(true);

chrome/android/java_sources.gni

@@ -1590,6 +1590,7 @@ chrome_test_java_sources = [
   "javatests/src/org/chromium/chrome/browser/media/ui/PictureInPictureControllerTest.java",
   "javatests/src/org/chromium/chrome/browser/metrics/MainIntentBehaviorMetricsIntegrationTest.java",
   "javatests/src/org/chromium/chrome/browser/metrics/PageLoadMetricsTest.java",
+  "javatests/src/org/chromium/chrome/browser/metrics/StartupLoadingMetricsTest.java",
   "javatests/src/org/chromium/chrome/browser/metrics/UkmIncognitoTest.java",
   "javatests/src/org/chromium/chrome/browser/multiwindow/MultiWindowIntegrationTest.java",
   "javatests/src/org/chromium/chrome/browser/multiwindow/MultiWindowTestHelper.java",

chrome/android/javatests/src/org/chromium/chrome/browser/metrics/StartupLoadingMetricsTest.java

+// Copyright 2017 The Chromium Authors. All rights reserved.
+// Use of this source code is governed by a BSD-style license that can be
+// found in the LICENSE file.
+
+package org.chromium.chrome.browser.metrics;
+
+import android.content.Context;
+import android.support.test.InstrumentationRegistry;
+import android.support.test.filters.LargeTest;
+
+import org.junit.Assert;
+import org.junit.Before;
+import org.junit.Rule;
+import org.junit.Test;
+import org.junit.runner.RunWith;
+
+import org.chromium.base.metrics.RecordHistogram;
+import org.chromium.base.test.util.CommandLineFlags;
+import org.chromium.base.test.util.RetryOnFailure;
+import org.chromium.chrome.browser.ChromeSwitches;
+import org.chromium.chrome.browser.ChromeTabbedActivity;
+import org.chromium.chrome.test.ChromeActivityTestRule;
+import org.chromium.chrome.test.ChromeJUnit4ClassRunner;
+import org.chromium.net.test.EmbeddedTestServer;
+
+/**
+ * Tests for startup timing histograms.
+ */
+@RunWith(ChromeJUnit4ClassRunner.class)
+@CommandLineFlags.Add(ChromeSwitches.DISABLE_FIRST_RUN_EXPERIENCE)
+public class StartupLoadingMetricsTest {
+    @Rule
+    public ChromeActivityTestRule<ChromeTabbedActivity> mActivityTestRule =
+            new ChromeActivityTestRule<>(ChromeTabbedActivity.class);
+
+    private static final String TEST_PAGE = "/chrome/test/data/android/google.html";
+    private static final String TEST_PAGE_2 = "/chrome/test/data/android/test.html";
+    private static final String FIRST_COMMIT_HISTOGRAM =
+            "Startup.Android.Experimental.Cold.TimeToFirstNavigationCommit";
+
+    private String mTestPage;
+    private String mTestPage2;
+    private EmbeddedTestServer mTestServer;
+
+    @Before
+    public void setUp() throws Exception {
+        Context appContext = InstrumentationRegistry.getInstrumentation()
+                                     .getTargetContext()
+                                     .getApplicationContext();
+        mTestServer = EmbeddedTestServer.createAndStartServer(appContext);
+        mTestPage = mTestServer.getURL(TEST_PAGE);
+        mTestPage2 = mTestServer.getURL(TEST_PAGE_2);
+    }
+
+    /**
+     * Tests that the startup time to first navigation commit histograms are recorded only once on
+     * startup.
+     */
+    @Test
+    @LargeTest
+    @RetryOnFailure
+    public void testNavigationCommitUmaRecorded() throws InterruptedException {
+        mActivityTestRule.startMainActivityWithURL(mTestPage);
+        Assert.assertEquals(
+                1, RecordHistogram.getHistogramTotalCountForTesting(FIRST_COMMIT_HISTOGRAM));
+        mActivityTestRule.loadUrl(mTestPage2);
+        Assert.assertEquals(
+                1, RecordHistogram.getHistogramTotalCountForTesting(FIRST_COMMIT_HISTOGRAM));
+    }
+
+    /**
+     * Tests that the startup time to first navigation commit histograms are recorded in case of
+     * intent coming from an external app.
+     */
+    @Test
+    @LargeTest
+    @RetryOnFailure
+    public void testNavigationCommitUmaFromExternalAppRecorded() throws InterruptedException {
+        mActivityTestRule.startMainActivityFromExternalApp(mTestPage, null);
+        Assert.assertEquals(
+                1, RecordHistogram.getHistogramTotalCountForTesting(FIRST_COMMIT_HISTOGRAM));
+        mActivityTestRule.loadUrl(mTestPage2);
+        Assert.assertEquals(
+                1, RecordHistogram.getHistogramTotalCountForTesting(FIRST_COMMIT_HISTOGRAM));
+    }
+
+    /**
+     * Tests that the startup time to first navigation commit histograms are not recorded in case of
+     * navigation to the NTP.
+     */
+    @Test
+    @LargeTest
+    @RetryOnFailure
+    public void testNavigationCommitUmaNTPNotRecorded() throws InterruptedException {
+        mActivityTestRule.startMainActivityFromLauncher();
+        Assert.assertEquals(
+                0, RecordHistogram.getHistogramTotalCountForTesting(FIRST_COMMIT_HISTOGRAM));
+        mActivityTestRule.loadUrl(mTestPage2);
+        Assert.assertEquals(
+                0, RecordHistogram.getHistogramTotalCountForTesting(FIRST_COMMIT_HISTOGRAM));
+    }
+
+    /**
+     * Tests that the startup time to first navigation commit histograms are not recorded in case of
+     * navigation to the blank page.
+     */
+    @Test
+    @LargeTest
+    @RetryOnFailure
+    public void testNavigationCommitUmaBlankPageNotRecorded() throws InterruptedException {
+        mActivityTestRule.startMainActivityOnBlankPage();
+        Assert.assertEquals(
+                0, RecordHistogram.getHistogramTotalCountForTesting(FIRST_COMMIT_HISTOGRAM));
+        mActivityTestRule.loadUrl(mTestPage2);
+        Assert.assertEquals(
+                0, RecordHistogram.getHistogramTotalCountForTesting(FIRST_COMMIT_HISTOGRAM));
+    }
+}
\ No newline at end of file

tools/metrics/histograms/histograms.xml

@@ -82895,6 +82895,18 @@ http://cs/file:chrome/histograms.xml - but prefer this file for new entries.
   </summary>
 </histogram>
 
+<histogram name="Startup.Android.Experimental.Cold.TimeToFirstNavigationCommit"
+    units="ms">
+  <owner>pasko@chromium.org</owner>
+  <owner>alexilin@chromium.org</owner>
+  <summary>
+    Android: The time from the earliest entry point in the browser process to
+    the moment the first navigation is committed, i.e. when renderer gets the
+    first byte of the document. It excludes all navigations to non http(s) pages
+    like chrome error pages, a new tab page, a blank page.
+  </summary>
+</histogram>
+
 <histogram name="Startup.AppListFirstPaintColdStart" units="ms">
   <owner>tapted@chromium.org</owner>
   <summary>
@@ -83234,6 +83246,10 @@ http://cs/file:chrome/histograms.xml - but prefer this file for new entries.
 </histogram>
 
 <histogram name="Startup.FirstCommitNavigationTime3" units="ms">
+  <obsolete>
+    Replaced with Startup.Android.Experimental.Cold.TimeToFirstNavigationCommit
+    on 11/2017
+  </obsolete>
   <owner>pasko@chromium.org</owner>
   <owner>wnwen@chromium.org</owner>
   <summary>