[sms] Add UMA tracking for SMS retrieval time & timeout values

This change adds UMA tracking for SMSReceiver API to give us data on
the how long an SMS takes to be delievered and how long a developer expects
the sms to be delievered. Specifically it will track the following:

1. Duration from when the API is called to when an SMS is
   successfully received.

2. Timeout value specified when the API is called.

Bug: 976332
Change-Id: I05fea36e67c1b256bcb60dc0d0edca4207fd0149
Reviewed-on: https://chromium-review.googlesource.com/c/chromium/src/+/1717429Reviewed-by: Steven Holte <holte@chromium.org>
Reviewed-by: Reilly Grant <reillyg@chromium.org>
Reviewed-by: Jun Cai <juncai@chromium.org>
Commit-Queue: Ayu Ishii <ayui@chromium.org>
Cr-Commit-Position: refs/heads/master@{#684368}

content/browser/sms/sms_metrics.cc

@@ -8,6 +8,10 @@
 
 namespace content {
 
+void RecordSmsReceiveTime(base::TimeDelta duration) {
+  UMA_HISTOGRAM_MEDIUM_TIMES("Blink.Sms.Receive.TimeSmsReceive", duration);
+}
+
 void RecordCancelOnSuccessTime(base::TimeDelta duration) {
   UMA_HISTOGRAM_MEDIUM_TIMES("Blink.Sms.Receive.TimeCancelOnSuccess", duration);
 }

content/browser/sms/sms_metrics.h

@@ -11,6 +11,10 @@ class TimeDelta;
 
 namespace content {
 
+// Records the time from when a call to the API was made to when an SMS has been
+// successfully received.
+void RecordSmsReceiveTime(base::TimeDelta duration);
+
 // Records the time from when a successful SMS was retrieved to when the user
 // presses the Cancel button.
 void RecordCancelOnSuccessTime(base::TimeDelta duration);

content/browser/sms/sms_service.cc

@@ -63,6 +63,8 @@ void SmsService::Receive(base::TimeDelta timeout, ReceiveCallback callback) {
   DCHECK(!prompt_);
   DCHECK(!sms_);
 
+  start_time_ = base::TimeTicks::Now();
+
   sms_provider_->AddObserver(this);
 
   callback_ = std::move(callback);
@@ -84,6 +86,9 @@ bool SmsService::OnReceive(const url::Origin& origin, const std::string& sms) {
   DCHECK(prompt_);
   DCHECK(!sms_);
   DCHECK(timer_.IsRunning());
+  DCHECK(!start_time_.is_null());
+
+  RecordSmsReceiveTime(base::TimeTicks::Now() - start_time_);
 
   timer_.Stop();
   sms_provider_->RemoveObserver(this);
@@ -159,6 +164,7 @@ void SmsService::Dismiss() {
   timer_.Stop();
   callback_.Reset();
   sms_.reset();
+  start_time_ = base::TimeTicks();
   receive_time_ = base::TimeTicks();
   sms_provider_->RemoveObserver(this);
 }

content/browser/sms/sms_service.h

@@ -78,6 +78,7 @@ class CONTENT_EXPORT SmsService
   base::OneShotTimer timer_;
   ReceiveCallback callback_;
   base::Optional<std::string> sms_;
+  base::TimeTicks start_time_;
   base::TimeTicks receive_time_;
 
   SEQUENCE_CHECKER(sequence_checker_);

content/browser/sms/sms_service_unittest.cc

@@ -588,7 +588,7 @@ TEST_F(SmsServiceTest, SecondRequestTimesOutEarlierThanFirstRequest) {
   sms_loop1.Run();
 }
 
-TEST_F(SmsServiceTest, RecordContinueOnSuccessTimeMetric) {
+TEST_F(SmsServiceTest, RecordTimeMetricsForContinueOnSuccess) {
   NavigateAndCommit(GURL(kTestUrl));
 
   Service service(web_contents());
@@ -610,13 +610,17 @@ TEST_F(SmsServiceTest, RecordContinueOnSuccessTimeMetric) {
 
   loop.Run();
 
-  std::unique_ptr<base::HistogramSamples> samples(
+  std::unique_ptr<base::HistogramSamples> continue_samples(
       GetHistogramSamplesSinceTestStart(
           "Blink.Sms.Receive.TimeContinueOnSuccess"));
-  EXPECT_EQ(1, samples->TotalCount());
+  EXPECT_EQ(1, continue_samples->TotalCount());
+
+  std::unique_ptr<base::HistogramSamples> receive_samples(
+      GetHistogramSamplesSinceTestStart("Blink.Sms.Receive.TimeSmsReceive"));
+  EXPECT_EQ(1, receive_samples->TotalCount());
 }
 
-TEST_F(SmsServiceTest, RecordCancelOnSuccessTimeMetric) {
+TEST_F(SmsServiceTest, RecordMetricsForCancelOnSuccess) {
   NavigateAndCommit(GURL(kTestUrl));
 
   Service service(web_contents());
@@ -652,6 +656,10 @@ TEST_F(SmsServiceTest, RecordCancelOnSuccessTimeMetric) {
         GetHistogramSamplesSinceTestStart(
             "Blink.Sms.Receive.TimeCancelOnSuccess"));
     EXPECT_EQ(0, samples->TotalCount());
+
+    std::unique_ptr<base::HistogramSamples> receive_samples(
+        GetHistogramSamplesSinceTestStart("Blink.Sms.Receive.TimeSmsReceive"));
+    EXPECT_EQ(0, receive_samples->TotalCount());
   }
 
   {
@@ -693,6 +701,10 @@ TEST_F(SmsServiceTest, RecordCancelOnSuccessTimeMetric) {
         GetHistogramSamplesSinceTestStart(
             "Blink.Sms.Receive.TimeCancelOnSuccess"));
     EXPECT_EQ(1, samples->TotalCount());
+
+    std::unique_ptr<base::HistogramSamples> receive_samples(
+        GetHistogramSamplesSinceTestStart("Blink.Sms.Receive.TimeSmsReceive"));
+    EXPECT_EQ(1, receive_samples->TotalCount());
   }
 }
 

third_party/blink/renderer/modules/sms/sms_metrics.cc

@@ -16,6 +16,11 @@ void RecordSMSSuccessTime(base::TimeDelta duration) {
   UMA_HISTOGRAM_MEDIUM_TIMES("Blink.Sms.Receive.TimeSuccess", duration);
 }
 
+void RecordSMSRequestedTimeout(uint32_t timeout_seconds) {
+  UMA_HISTOGRAM_COUNTS_10000("Blink.Sms.Receive.RequestedTimeout",
+                             timeout_seconds);
+}
+
 void RecordSMSTimeoutExceededTime(base::TimeDelta duration) {
   UMA_HISTOGRAM_MEDIUM_TIMES("Blink.Sms.Receive.TimeTimeoutExceeded", duration);
 }

third_party/blink/renderer/modules/sms/sms_metrics.h

@@ -5,6 +5,8 @@
 #ifndef THIRD_PARTY_BLINK_RENDERER_MODULES_SMS_SMS_METRICS_H_
 #define THIRD_PARTY_BLINK_RENDERER_MODULES_SMS_SMS_METRICS_H_
 
+#include <stdint.h>
+
 namespace base {
 class TimeDelta;
 }
@@ -21,12 +23,22 @@ enum class SMSReceiverOutcome {
   kMaxValue = kCancelled
 };
 
+// Records the result of a call to the SMSReceiver API.
 void RecordSMSOutcome(SMSReceiverOutcome outcome);
 
+// Records the time from when the API is called to when the user successfully
+// receives the SMS and presses continue to move on with the verification flow.
 void RecordSMSSuccessTime(base::TimeDelta duration);
 
+// Records the timeout value specified with the API is called. The value of 0
+// indicates that no value was specified.
+void RecordSMSRequestedTimeout(uint32_t timeout_seconds);
+
+// Records the time from when the API is called to when the user gets timed out.
 void RecordSMSTimeoutExceededTime(base::TimeDelta duration);
 
+// Records the time from when the API is called to when the user presses the
+// cancel button to abort SMS retrieval.
 void RecordSMSCancelTime(base::TimeDelta duration);
 
 }  // namespace blink

third_party/blink/renderer/modules/sms/sms_receiver.cc

@@ -53,6 +53,8 @@ ScriptPromise SMSReceiver::receive(ScriptState* script_state,
                                            "Invalid timeout."));
   }
 
+  RecordSMSRequestedTimeout(options->hasTimeout() ? options->timeout() : 0);
+
   auto* resolver = MakeGarbageCollected<ScriptPromiseResolver>(script_state);
   requests_.insert(resolver);
 

tools/metrics/histograms/histograms.xml

@@ -14689,6 +14689,17 @@ uploading your change for review.
   <summary>Records the result of a call to the SmsReceiver API.</summary>
 </histogram>
 
+<histogram name="Blink.Sms.Receive.RequestedTimeout" units="ms">
+  <owner>goto@chromium.org</owner>
+  <owner>reillyg@chromium.org</owner>
+  <owner>ayui@chromium.org</owner>
+  <summary>
+    Records the timeout value specified when the API is called regardless of
+    whether or not the call actually timed out. The value of 0 indicates that no
+    value was specified.
+  </summary>
+</histogram>
+
 <histogram name="Blink.Sms.Receive.TimeCancel" units="ms">
   <owner>goto@chromium.org</owner>
   <owner>reillyg@chromium.org</owner>
@@ -14719,6 +14730,16 @@ uploading your change for review.
   </summary>
 </histogram>
 
+<histogram name="Blink.Sms.Receive.TimeSmsReceive" units="ms">
+  <owner>goto@chromium.org</owner>
+  <owner>reillyg@chromium.org</owner>
+  <owner>ayui@chromium.org</owner>
+  <summary>
+    Records the duration from when the API is called to when an SMS has been
+    successfully received.
+  </summary>
+</histogram>
+
 <histogram name="Blink.Sms.Receive.TimeSuccess" units="ms">
   <owner>goto@chromium.org</owner>
   <owner>reillyg@chromium.org</owner>