This CL adds histogram for experiment time measurement to TFLite Experiment Observer.

Bug: 1116210
Change-Id: I09a3ddbea5756cc569d38805b5c11e4f06ecee6a
Reviewed-on: https://chromium-review.googlesource.com/c/chromium/src/+/2357679
Commit-Queue: Mehrdad Hessar <mehrdadh@google.com>
Reviewed-by: Michael Crouse <mcrouse@chromium.org>
Reviewed-by: Ryan Sturm <ryansturm@chromium.org>
Cr-Commit-Position: refs/heads/master@{#799436}

chrome/browser/tflite_experiment/tflite_experiment_keyed_service_browsertest.cc

@@ -75,6 +75,8 @@ class TFLiteExperimentKeyedServiceDisabledBrowserTest
               0);
   }
 
+  const base::HistogramTester* histogram_tester() { return &histogram_tester_; }
+
  private:
   base::HistogramTester histogram_tester_;
 };
@@ -93,6 +95,8 @@ IN_PROC_BROWSER_TEST_F(
   GURL navigation_url(kNavigationURL);
   ui_test_utils::NavigateToURL(browser(), navigation_url);
   WaitForTFLiteObserverToCallNullTFLitePredictor();
+  histogram_tester()->ExpectUniqueSample(
+      "TFLiteExperiment.Observer.TFLitePredictor.Null", true, 1);
 }
 
 class TFLiteExperimentKeyedServiceBrowserTest : public InProcessBrowserTest {
@@ -138,6 +142,8 @@ class TFLiteExperimentKeyedServiceBrowserTest : public InProcessBrowserTest {
         0);
   }
 
+  const base::HistogramTester* histogram_tester() { return &histogram_tester_; }
+
  private:
   base::HistogramTester histogram_tester_;
 };
@@ -174,6 +180,20 @@ IN_PROC_BROWSER_TEST_F(TFLiteExperimentKeyedServiceBrowserTest,
   base::ReadFileToString(GetTFLiteExperimentLogPath(), &data);
   base::Optional<base::Value> root = base::JSONReader::Read(data);
   EXPECT_TRUE(root);
-  EXPECT_TRUE(*root->FindIntKey("input_set_time"));
-  EXPECT_TRUE(*root->FindIntKey("evaluation_time"));
+  EXPECT_TRUE(root->FindIntKey("input_set_time_ms"));
+  EXPECT_TRUE(root->FindIntKey("evaluation_time_ms"));
+}
+
+IN_PROC_BROWSER_TEST_F(TFLiteExperimentKeyedServiceBrowserTest,
+                       TFLiteExperimentHistogram) {
+  GURL navigation_url(kNavigationURL);
+  ui_test_utils::NavigateToURL(browser(), navigation_url);
+  WaitForObserverToFinish();
+
+  histogram_tester()->ExpectTotalCount(
+      "TFLiteExperiment.Observer.TFLitePredictor.InputSetTime", 1);
+  histogram_tester()->ExpectTotalCount(
+      "TFLiteExperiment.Observer.TFLitePredictor.EvaluationTime", 1);
+  histogram_tester()->ExpectUniqueSample("TFLiteExperiment.Observer.Finish",
+                                         true, 1);
 }

chrome/browser/tflite_experiment/tflite_experiment_observer.cc

@@ -18,7 +18,7 @@
 #include "content/public/browser/render_frame_host.h"
 #include "content/public/browser/web_contents.h"
 
-constexpr int32_t kTFLitePredictorEvaluationLoop = 10;
+constexpr int kHistogramBucketSize = 1001;
 
 namespace {
 
@@ -66,18 +66,32 @@ void TFLiteExperimentObserver::DidFinishNavigation(
   if (is_tflite_evaluated_)
     return;
 
-  base::TimeTicks t1 = base::TimeTicks::Now();
+  auto create_predictor_input_start_time(base::TimeTicks::Now());
   CreatePredictorInputForTesting();
-  base::TimeTicks t2 = base::TimeTicks::Now();
-  // Run evaluation for |kTFLitePredictorEvaluationLoop| times and report
-  // average time.
-  for (int i = 0; i < kTFLitePredictorEvaluationLoop; i++)
-    tflite_predictor_->Evaluate();
-  base::TimeTicks t3 = base::TimeTicks::Now();
-
-  log_dict_.SetIntKey("input_set_time", (t2 - t1).InMicroseconds());
-  log_dict_.SetIntKey("evaluation_time", (t3 - t2).InMilliseconds() /
-                                             kTFLitePredictorEvaluationLoop);
+  auto create_predictor_input_end_time(base::TimeTicks::Now());
+
+  LOCAL_HISTOGRAM_CUSTOM_TIMES(
+      "TFLiteExperiment.Observer.TFLitePredictor.InputSetTime",
+      create_predictor_input_end_time - create_predictor_input_start_time,
+      base::TimeDelta::FromMilliseconds(0), base::TimeDelta::FromSeconds(1),
+      kHistogramBucketSize);
+
+  // Run evaluation report histogram and log time.
+  auto predictor_eval_start_time(base::TimeTicks::Now());
+  tflite_predictor_->Evaluate();
+  auto predictor_eval_end_time(base::TimeTicks::Now());
+  const base::TimeDelta evaluation_time =
+      predictor_eval_end_time - predictor_eval_start_time;
+  LOCAL_HISTOGRAM_CUSTOM_TIMES(
+      "TFLiteExperiment.Observer.TFLitePredictor.EvaluationTime",
+      evaluation_time, base::TimeDelta::FromMilliseconds(0),
+      base::TimeDelta::FromSeconds(1), kHistogramBucketSize);
+
+  // Record timing in TFLite experiment log file in addition to histogram.
+  log_dict_.SetIntKey("input_set_time_ms", (create_predictor_input_end_time -
+                                            create_predictor_input_start_time)
+                                               .InMilliseconds());
+  log_dict_.SetIntKey("evaluation_time_ms", evaluation_time.InMilliseconds());
 
   is_tflite_evaluated_ = true;
   LOCAL_HISTOGRAM_BOOLEAN(