[M103][VCN] Add GetDetailsForEnrollment request latency logging

Broken down by enrollment source and the rpc result. (cherry picked from commit f77c3eb) Bug: 1330658 Change-Id: Id0adc7ec73aff7a24bea2de455f80d517984261a Reviewed-on: https://chromium-review.googlesource.com/c/chromium/src/+/3665679 Reviewed-by: Jared Saul <jsaul@google.com> Reviewed-by: Dominic Battré <battre@chromium.org> Commit-Queue: Siyu An <siyua@chromium.org> Cr-Original-Commit-Position: refs/heads/main@{#1007632} Reviewed-on: https://chromium-review.googlesource.com/c/chromium/src/+/3680388 Bot-Commit: Rubber Stamper <rubber-stamper@appspot.gserviceaccount.com> Auto-Submit: Siyu An <siyua@chromium.org> Owners-Override: Prudhvikumar Bommana <pbommana@google.com> Cr-Commit-Position: refs/branch-heads/5060@{#427} Cr-Branched-From: b83393d-refs/heads/main@{#1002911}
chromium · May 31, 2022 · ab33c2d · ab33c2d
1 parent 7891ca3
commit ab33c2d
Show file tree

Hide file tree

Showing 8 changed files with 90 additions and 24 deletions.
diff --git a/components/autofill/core/browser/metrics/autofill_metrics.cc b/components/autofill/core/browser/metrics/autofill_metrics.cc
@@ -1372,33 +1372,11 @@ void AutofillMetrics::LogCardUnmaskDurationAfterWebauthn(
     const base::TimeDelta& duration,
     AutofillClient::PaymentsRpcResult result,
     AutofillClient::PaymentsRpcCardType card_type) {
-  std::string result_suffix;
-
-  switch (result) {
-    case AutofillClient::PaymentsRpcResult::kSuccess:
-      result_suffix = "Success";
-      break;
-    case AutofillClient::PaymentsRpcResult::kTryAgainFailure:
-    case AutofillClient::PaymentsRpcResult::kPermanentFailure:
-      result_suffix = "Failure";
-      break;
-    case AutofillClient::PaymentsRpcResult::kNetworkError:
-      result_suffix = "NetworkError";
-      break;
-    case AutofillClient::PaymentsRpcResult::kVcnRetrievalTryAgainFailure:
-    case AutofillClient::PaymentsRpcResult::kVcnRetrievalPermanentFailure:
-      result_suffix = "VcnRetrievalFailure";
-      break;
-    case AutofillClient::PaymentsRpcResult::kNone:
-      NOTREACHED();
-      return;
-  }
-
   base::UmaHistogramLongTimes("Autofill.BetterAuth.CardUnmaskDuration.Fido",
                               duration);
   base::UmaHistogramLongTimes("Autofill.BetterAuth.CardUnmaskDuration.Fido" +
-                                  GetCreditCardTypeSuffix(card_type) + "." +
-                                  result_suffix,
+                                  GetCreditCardTypeSuffix(card_type) +
+                                  PaymentsRpcResultToMetricsSuffix(result),
                               duration);
 }
 
@@ -3546,4 +3524,30 @@ void AutofillMetrics::
       is_same);
 }
 
+const std::string PaymentsRpcResultToMetricsSuffix(
+    AutofillClient::PaymentsRpcResult result) {
+  std::string result_suffix;
+
+  switch (result) {
+    case AutofillClient::PaymentsRpcResult::kSuccess:
+      result_suffix = ".Success";
+      break;
+    case AutofillClient::PaymentsRpcResult::kTryAgainFailure:
+    case AutofillClient::PaymentsRpcResult::kPermanentFailure:
+      result_suffix = ".Failure";
+      break;
+    case AutofillClient::PaymentsRpcResult::kNetworkError:
+      result_suffix = ".NetworkError";
+      break;
+    case AutofillClient::PaymentsRpcResult::kVcnRetrievalTryAgainFailure:
+    case AutofillClient::PaymentsRpcResult::kVcnRetrievalPermanentFailure:
+      result_suffix = ".VcnRetrievalFailure";
+      break;
+    case AutofillClient::PaymentsRpcResult::kNone:
+      NOTREACHED();
+  }
+
+  return result_suffix;
+}
+
 }  // namespace autofill
diff --git a/components/autofill/core/browser/metrics/autofill_metrics.h b/components/autofill/core/browser/metrics/autofill_metrics.h
@@ -2110,5 +2110,8 @@ int GetFieldTypeUserEditStatusMetric(
     AutofillMetrics::AutofilledFieldUserEditingStatusMetric metric);
 #endif
 
+const std::string PaymentsRpcResultToMetricsSuffix(
+    AutofillClient::PaymentsRpcResult result);
+
 }  // namespace autofill
 #endif  // COMPONENTS_AUTOFILL_CORE_BROWSER_METRICS_AUTOFILL_METRICS_H_
diff --git a/components/autofill/core/browser/metrics/payments/virtual_card_enrollment_metrics.cc b/components/autofill/core/browser/metrics/payments/virtual_card_enrollment_metrics.cc
@@ -9,6 +9,7 @@
 #include "base/strings/strcat.h"
 #include "base/strings/string_util.h"
 #include "base/time/time.h"
+#include "components/autofill/core/browser/metrics/autofill_metrics.h"
 #include "components/autofill/core/browser/payments/virtual_card_enrollment_flow.h"
 
 namespace autofill {
@@ -73,6 +74,17 @@ void LogGetDetailsForEnrollmentRequestResult(VirtualCardEnrollmentSource source,
       succeeded);
 }
 
+void LogGetDetailsForEnrollmentRequestLatency(
+    VirtualCardEnrollmentSource source,
+    AutofillClient::PaymentsRpcResult result,
+    base::TimeDelta latency) {
+  base::UmaHistogramMediumTimes(
+      "Autofill.VirtualCard.GetDetailsForEnrollment.Latency." +
+          VirtualCardEnrollmentSourceToMetricSuffix(source) +
+          PaymentsRpcResultToMetricsSuffix(result),
+      latency);
+}
+
 void LogUpdateVirtualCardEnrollmentRequestAttempt(
     VirtualCardEnrollmentSource source,
     VirtualCardEnrollmentRequestType type) {

diff --git a/components/autofill/core/browser/metrics/payments/virtual_card_enrollment_metrics.h b/components/autofill/core/browser/metrics/payments/virtual_card_enrollment_metrics.h
@@ -7,6 +7,7 @@
 
 #include <string>
 
+#include "components/autofill/core/browser/autofill_client.h"
 #include "components/autofill/core/browser/payments/virtual_card_enrollment_flow.h"
 
 namespace base {
@@ -100,6 +101,10 @@ void LogGetDetailsForEnrollmentRequestAttempt(
     VirtualCardEnrollmentSource source);
 void LogGetDetailsForEnrollmentRequestResult(VirtualCardEnrollmentSource source,
                                              bool succeeded);
+void LogGetDetailsForEnrollmentRequestLatency(
+    VirtualCardEnrollmentSource source,
+    AutofillClient::PaymentsRpcResult result,
+    base::TimeDelta latency);
 
 // UpdateVirtualCardEnrollmentRequest related metrics. Attempts and results
 // should be 1:1 mapping.

diff --git a/components/autofill/core/browser/payments/virtual_card_enrollment_manager.cc b/components/autofill/core/browser/payments/virtual_card_enrollment_manager.cc
@@ -351,6 +351,9 @@ void VirtualCardEnrollmentManager::GetDetailsForEnroll() {
       state_.virtual_card_enrollment_fields.credit_card.instrument_id();
   request_details.source =
       state_.virtual_card_enrollment_fields.virtual_card_enrollment_source;
+
+  get_details_for_enrollment_request_sent_timestamp_ = AutofillClock::Now();
+
   payments_client_->GetVirtualCardEnrollmentDetails(
       request_details,
       base::BindOnce(
@@ -366,6 +369,15 @@ void VirtualCardEnrollmentManager::OnDidGetDetailsForEnrollResponse(
         response) {
   enroll_response_details_received_ = true;
 
+  if (get_details_for_enrollment_request_sent_timestamp_.has_value()) {
+    LogGetDetailsForEnrollmentRequestLatency(
+        state_.virtual_card_enrollment_fields.virtual_card_enrollment_source,
+        result,
+        AutofillClock::Now() -
+            get_details_for_enrollment_request_sent_timestamp_.value());
+    get_details_for_enrollment_request_sent_timestamp_.reset();
+  }
+
   LogGetDetailsForEnrollmentRequestResult(
       state_.virtual_card_enrollment_fields.virtual_card_enrollment_source,
       /*succeeded=*/result == AutofillClient::PaymentsRpcResult::kSuccess);

diff --git a/components/autofill/core/browser/payments/virtual_card_enrollment_manager.h b/components/autofill/core/browser/payments/virtual_card_enrollment_manager.h
@@ -323,6 +323,9 @@ class VirtualCardEnrollmentManager {
   // metric. |save_card_bubble_accepted_timestamp_| will then be reset.
   absl::optional<base::Time> save_card_bubble_accepted_timestamp_;
 
+  // The timestamp when a GetDetailsForEnrollment request is sent.
+  absl::optional<base::Time> get_details_for_enrollment_request_sent_timestamp_;
+
   base::WeakPtrFactory<VirtualCardEnrollmentManager> weak_ptr_factory_{this};
 };
 

diff --git a/components/autofill/core/browser/payments/virtual_card_enrollment_manager_unittest.cc b/components/autofill/core/browser/payments/virtual_card_enrollment_manager_unittest.cc
@@ -14,6 +14,7 @@
 #include "components/autofill/core/browser/autofill_test_utils.h"
 #include "components/autofill/core/browser/data_model/credit_card.h"
 #include "components/autofill/core/browser/data_model/credit_card_art_image.h"
+#include "components/autofill/core/browser/metrics/autofill_metrics.h"
 #include "components/autofill/core/browser/metrics/payments/virtual_card_enrollment_metrics.h"
 #include "components/autofill/core/browser/payments/payments_requests/update_virtual_card_enrollment_request.h"
 #include "components/autofill/core/browser/payments/payments_util.h"
@@ -253,6 +254,7 @@ TEST_F(VirtualCardEnrollmentManagerTest, OnRiskDataLoadedForVirtualCard) {
 
 TEST_F(VirtualCardEnrollmentManagerTest, OnDidGetDetailsForEnrollResponse) {
   base::HistogramTester histogram_tester;
+  TestAutofillClock test_autofill_clock(AutofillClock::Now());
   const TestLegalMessageLine google_legal_message =
       TestLegalMessageLine("google_test_legal_message");
   const TestLegalMessageLine issuer_legal_message =
@@ -269,6 +271,9 @@ TEST_F(VirtualCardEnrollmentManagerTest, OnDidGetDetailsForEnrollResponse) {
 #else
     for (bool make_image_present : {true, false}) {
 #endif  // BUILDFLAG(IS_IOS)
+      virtual_card_enrollment_manager_
+          ->get_details_for_enrollment_request_sent_timestamp_ =
+          AutofillClock::Now();
       payments::PaymentsClient::GetDetailsForEnrollmentResponseDetails
           response = std::move(SetUpOnDidGetDetailsForEnrollResponse(
               google_legal_message, issuer_legal_message, make_image_present));
@@ -285,6 +290,8 @@ TEST_F(VirtualCardEnrollmentManagerTest, OnDidGetDetailsForEnrollResponse) {
             network_image);
       }
 
+      test_autofill_clock.Advance(base::Milliseconds(5));
+
       virtual_card_enrollment_manager_->OnDidGetDetailsForEnrollResponse(
           AutofillClient::PaymentsRpcResult::kSuccess, response);
 
@@ -313,6 +320,12 @@ TEST_F(VirtualCardEnrollmentManagerTest, OnDidGetDetailsForEnrollResponse) {
           "Autofill.VirtualCard.GetDetailsForEnrollment.Result." +
               VirtualCardEnrollmentSourceToMetricSuffix(source),
           /*sample=*/true, make_image_present ? 1 : 2);
+      histogram_tester.ExpectBucketCount(
+          "Autofill.VirtualCard.GetDetailsForEnrollment.Latency." +
+              VirtualCardEnrollmentSourceToMetricSuffix(source) +
+              PaymentsRpcResultToMetricsSuffix(
+                  AutofillClient::PaymentsRpcResult::kSuccess),
+          /*sample=*/5, make_image_present ? 1 : 2);
     }
   }
 }

diff --git a/tools/metrics/histograms/metadata/autofill/histograms.xml b/tools/metrics/histograms/metadata/autofill/histograms.xml
@@ -3624,6 +3624,20 @@ chromium-metrics-reviews@google.com.
   <token key="Source" variants="Autofill.VirtualCard.RequestSource"/>
 </histogram>
 
+<histogram
+    name="Autofill.VirtualCard.GetDetailsForEnrollment.Latency.{Source}.{Result}"
+    units="ms" expires_after="2022-08-07">
+  <owner>siyua@chromium.org</owner>
+  <owner>payments-autofill-team@google.com</owner>
+  <summary>
+    Records the latency for the GetDetailsForEnrollment roundtrip call. The
+    timer starts when a GetDetailsForEnrollment request is sent. It is recorded
+    (the timer stops) when a GetDetailsForEnrollment response is received.
+  </summary>
+  <token key="Source" variants="Autofill.VirtualCard.RequestSource"/>
+  <token key="Result" variants="Autofill.PaymentsRpcResult"/>
+</histogram>
+
 <histogram name="Autofill.VirtualCard.GetDetailsForEnrollment.Result.{Source}"
     enum="BooleanSuccess" expires_after="2022-08-07">
   <owner>siyua@chromium.org</owner>