Instrument variations seed loading in WebView

Variations.SeedLoadBlockingTime tells us how long WebView startup is
delayed waiting for the seed. This is less than the total time to load
the seed, because we block after loading has already started.

Variations.SeedLoadResult tells us whether the load was successful. Its
VariationsSeedLoadResult enum is extended to include failure modes for
the FutureTask that WebView uses to load the seed. WebView is still
using dummy seed files without actual seed data, so the enum's various
seed corruption values aren't yet applicable.

BUG=828610

Change-Id: If9af5a82cedf990cf670f6b0dcf123ac10ea69bb
Reviewed-on: https://chromium-review.googlesource.com/994253
Reviewed-by: Bo <boliu@chromium.org>
Reviewed-by: Steven Holte <holte@chromium.org>
Commit-Queue: Paul Miller <paulmiller@chromium.org>
Cr-Original-Commit-Position: refs/heads/master@{#554240}(cherry picked from commit 58467fe)
Reviewed-on: https://chromium-review.googlesource.com/1048906
Reviewed-by: Paul Miller <paulmiller@chromium.org>
Cr-Commit-Position: refs/branch-heads/3396@{#525}
Cr-Branched-From: 9ef2aa8-refs/heads/master@{#550428}

android_webview/BUILD.gn

@@ -893,6 +893,7 @@ android_library("android_webview_java") {
     "//components/navigation_interception/android:navigation_interception_java",
     "//components/policy/android:policy_java",
     "//components/safe_browsing/android:safe_browsing_java",
+    "//components/variations:load_seed_result_enum_java",
     "//components/variations/android:variations_java",
     "//components/version_info/android:version_constants_java",
     "//components/web_contents_delegate_android:web_contents_delegate_android_java",

android_webview/java/src/org/chromium/android_webview/VariationsSeedLoader.java

@@ -12,13 +12,17 @@
 import android.os.IBinder;
 import android.os.ParcelFileDescriptor;
 import android.os.RemoteException;
+import android.os.SystemClock;
 
 import org.chromium.android_webview.services.IVariationsSeedServer;
 import org.chromium.android_webview.services.VariationsSeedServer;
 import org.chromium.base.CommandLine;
 import org.chromium.base.ContextUtils;
 import org.chromium.base.Log;
 import org.chromium.base.VisibleForTesting;
+import org.chromium.base.metrics.CachedMetrics.EnumeratedHistogramSample;
+import org.chromium.base.metrics.CachedMetrics.TimesHistogramSample;
+import org.chromium.components.variations.LoadSeedResult;
 import org.chromium.components.variations.firstrun.VariationsSeedFetcher.SeedInfo;
 
 import java.io.File;
@@ -72,9 +76,15 @@ public class VariationsSeedLoader {
     // is exceeded, proceed with variations disabled.
     private static final long SEED_LOAD_TIMEOUT_MILLIS = 20;
 
+    private static void recordLoadSeedResult(int result) {
+        EnumeratedHistogramSample histogram = new EnumeratedHistogramSample(
+                "Variations.SeedLoadResult", LoadSeedResult.ENUM_SIZE);
+        histogram.record(result);
+    }
+
     // AGSA will notify us to enable variations by touching this file.
     // TODO(paulmiller): Remove this after completing the experiment.
-    private static boolean isEnabledByExperiment() {
+    private static boolean checkEnabledByExperiment() {
         File filesDir = ContextUtils.getApplicationContext().getFilesDir();
         File experimentFile = new File(new File(filesDir, "webview"), "finch-exp");
         return experimentFile.exists();
@@ -97,12 +107,19 @@ private class SeedLoadAndUpdateRunnable implements Runnable {
         // - mNeedNewSeed: Should we request a new seed from the service?
         // - mCurrentSeedDate: The "date" field of our local seed, converted to milliseconds since
         //   epoch, or Long.MIN_VALUE if we have no seed.
+        // - mEnabledByExperiment: Whether variations enabled by the AGSA experiment. If so, and
+        //   variations is not already enabled by CommandLine, then it should be made enabled by
+        //   CommandLine. This is volatile because it's set inside mLoadTask on a background thread,
+        //   but read in isVariationsEnabled() on the main thread. TODO(paulmiller): Remove this
+        //   after completing the experiment.
         private boolean mFoundNewSeed;
         private boolean mNeedNewSeed;
         private long mCurrentSeedDate = Long.MIN_VALUE;
+        private volatile boolean mEnabledByExperiment;
 
         private FutureTask<SeedInfo> mLoadTask = new FutureTask<>(() -> {
-            if (!(mEnabledByCmd || isEnabledByExperiment())) return null;
+            mEnabledByExperiment = checkEnabledByExperiment();
+            if (!(mEnabledByCmd || mEnabledByExperiment)) return null;
 
             File newSeedFile = VariationsUtils.getNewSeedFile();
             File oldSeedFile = VariationsUtils.getSeedFile();
@@ -187,6 +204,12 @@ public SeedInfo get(long timeout, TimeUnit unit)
                 throws InterruptedException, ExecutionException, TimeoutException {
             return mLoadTask.get(timeout, unit);
         }
+
+        // mEnabledByExperiment is set in mLoadTask, so isVariationsEnabled() should only be called
+        // after run() returns.
+        public boolean isVariationsEnabled() {
+            return mEnabledByCmd || mEnabledByExperiment;
+        }
     }
 
     // Connects to VariationsSeedServer service. Sends a file descriptor for our local copy of the
@@ -229,6 +252,36 @@ public void onServiceDisconnected(ComponentName name) {}
 
     private SeedLoadAndUpdateRunnable mRunnable;
 
+    private SeedInfo getSeedBlockingAndLog() {
+        long start = SystemClock.elapsedRealtime();
+        try {
+            try {
+                return mRunnable.get(SEED_LOAD_TIMEOUT_MILLIS, TimeUnit.MILLISECONDS);
+            } finally {
+                if (mRunnable.isVariationsEnabled()) {
+                    long end = SystemClock.elapsedRealtime();
+                    TimesHistogramSample histogram = new TimesHistogramSample(
+                            "Variations.SeedLoadBlockingTime", TimeUnit.MILLISECONDS);
+                    histogram.record(end - start);
+                }
+            }
+        } catch (TimeoutException e) {
+            if (mRunnable.isVariationsEnabled()) {
+                recordLoadSeedResult(LoadSeedResult.LOAD_TIMED_OUT);
+            }
+        } catch (InterruptedException e) {
+            if (mRunnable.isVariationsEnabled()) {
+                recordLoadSeedResult(LoadSeedResult.LOAD_INTERRUPTED);
+            }
+        } catch (ExecutionException e) {
+            if (mRunnable.isVariationsEnabled()) {
+                recordLoadSeedResult(LoadSeedResult.LOAD_OTHER_FAILURE);
+            }
+        }
+        Log.e(TAG, "Failed loading variations seed. Variations disabled.");
+        return null;
+    }
+
     @VisibleForTesting // Overridden by tests to wait until all work is done.
     protected void onBackgroundWorkFinished() {}
 
@@ -276,24 +329,16 @@ public void startVariationsInit() {
     // Block on loading the seed with a timeout. Then if a seed was successfully loaded, initialize
     // variations.
     public void finishVariationsInit() {
-        try {
-            SeedInfo seed = mRunnable.get(SEED_LOAD_TIMEOUT_MILLIS, TimeUnit.MILLISECONDS);
-            if (seed != null) {
-                // If variations was not enabled by CommandLine, but we got a seed anyway, that
-                // means variations is enabled by the AGSA experiment. So enable it by CommandLine
-                // as well.
-                if (!isEnabledByCmd()) {
-                    CommandLine.getInstance().appendSwitch(AwSwitches.ENABLE_WEBVIEW_VARIATIONS);
-                }
+        SeedInfo seed = getSeedBlockingAndLog();
 
-                // TODO(paulmiller): Once we have actual seeds, this would be the place to do
-                // VariationsSeedBridge.setVariationsFirstRunSeed() with the loaded seed.
-            }
-        } catch (TimeoutException e) {
-            // TODO(paulmiller): Log seed load time and success rate in UMA.
-            Log.w(TAG, "Timeout out waiting for variations seed - variations disabled");
-        } catch (InterruptedException | ExecutionException e) {
-            Log.e(TAG, "Failed loading variations seed - variations disabled", e);
+        // If enabled by experiment but not cmd, then also enable by cmd.
+        // isVariationsEnabled() must not be called before getSeedBlockingAndLog() returns.
+        // TODO(paulmiller): Remove this after completing the experiment.
+        if (mRunnable.isVariationsEnabled() && !isEnabledByCmd()) {
+            CommandLine.getInstance().appendSwitch(AwSwitches.ENABLE_WEBVIEW_VARIATIONS);
         }
+
+        // TODO(paulmiller): Once we have actual seeds, this would be the place to do:
+        // if (seed != null) { VariationsSeedBridge.setVariationsFirstRunSeed(seed); }
     }
 }

android_webview/javatests/src/org/chromium/android_webview/test/VariationsSeedLoaderTest.java

@@ -21,6 +21,7 @@
 import org.chromium.android_webview.services.ServiceInit;
 import org.chromium.android_webview.test.services.MockVariationsSeedServer;
 import org.chromium.base.ContextUtils;
+import org.chromium.base.metrics.RecordHistogram;
 import org.chromium.base.test.BaseJUnit4ClassRunner;
 import org.chromium.base.test.util.CallbackHelper;
 import org.chromium.base.test.util.parameter.SkipCommandLineParameterization;
@@ -129,11 +130,13 @@ public void setUp() throws IOException {
                 InstrumentationRegistry.getInstrumentation()
                         .getTargetContext().getApplicationContext());
         ServiceInit.setPrivateDataDirectorySuffix();
+        RecordHistogram.setDisabledForTests(true);
         deleteSeeds();
     }
 
     @After
     public void tearDown() throws IOException {
+        RecordHistogram.setDisabledForTests(false);
         deleteSeeds();
     }
 

components/variations/BUILD.gn

@@ -100,6 +100,15 @@ if (is_android) {
     ]
     jni_package = "variations"
   }
+
+  android_library("load_seed_result_enum_java") {
+    deps = [ "//base:base_java" ]
+    srcjar_deps = [ ":load_seed_result_enum_srcjar" ]
+  }
+
+  java_cpp_enum("load_seed_result_enum_srcjar") {
+    sources = [ "metrics.h" ]
+  }
 }
 
 static_library("test_support") {

components/variations/metrics.h

@@ -24,6 +24,7 @@ enum class FirstRunSeedImportResult {
 
 // The result of attempting to load a variations seed on startup.
 // Note: UMA histogram enum - don't re-order or remove entries.
+// GENERATED_JAVA_ENUM_PACKAGE: org.chromium.components.variations
 enum class LoadSeedResult {
   SUCCESS,
   EMPTY,
@@ -32,6 +33,9 @@ enum class LoadSeedResult {
   CORRUPT_BASE64,
   CORRUPT_PROTOBUF,
   CORRUPT_GZIP,
+  LOAD_TIMED_OUT,
+  LOAD_INTERRUPTED,
+  LOAD_OTHER_FAILURE,
   ENUM_SIZE
 };
 

tools/metrics/histograms/enums.xml

@@ -45797,6 +45797,9 @@ Full version information for the fingerprint enum values:
   <int value="4" label="Seed Corrupt Base64 Data"/>
   <int value="5" label="Seed Corrupt Protobuf"/>
   <int value="6" label="Seed Corrupt Gzip Data"/>
+  <int value="7" label="Seed Load Timed Out"/>
+  <int value="8" label="Seed Load Interrupted"/>
+  <int value="9" label="Seed Load Other Failure"/>
 </enum>
 
 <enum name="VariationsSeedStoreResult">

tools/metrics/histograms/histograms.xml

@@ -100050,6 +100050,17 @@ http://cs/file:chrome/histograms.xml - but prefer this file for new entries.
   </summary>
 </histogram>
 
+<histogram name="Variations.SeedLoadBlockingTime" units="ms">
+  <owner>paulmiller@chromium.org</owner>
+  <summary>
+    Records the time spent blocking WebView startup to wait for the variatinos
+    seed. This is less than the entire time needed to load the seed, since
+    startup is only blocked if loading is not complete by the time the seed is
+    needed. This is logged once per WebView startup, whether or not the load was
+    successful.
+  </summary>
+</histogram>
+
 <histogram name="Variations.SeedLoadResult" enum="VariationsSeedLoadResult">
   <owner>asvitkine@chromium.org</owner>
   <summary>