UKM that threads together multiple form interaction events.

components/autofill/core/browser/autofill_metrics.cc

Index: components/autofill/core/browser/autofill_metrics.cc
diff --git a/components/autofill/core/browser/autofill_metrics.cc b/components/autofill/core/browser/autofill_metrics.cc
index e813b1836f15f987cf2b02cadc879399f5e49b74..42cbe8648dfc6cc04c6a1c8b32000b50c2b292b6 100644
--- a/components/autofill/core/browser/autofill_metrics.cc
+++ b/components/autofill/core/browser/autofill_metrics.cc
@@ -5,6 +5,8 @@
 #include "components/autofill/core/browser/autofill_metrics.h"
 
 #include <algorithm>
+#include <utility>
+#include <vector>
 
 #include "base/logging.h"
 #include "base/metrics/histogram_macros.h"
@@ -22,6 +24,13 @@ const char kUKMCardUploadDecisionEntryName[] = "Autofill.CardUploadDecision";
 const char kUKMCardUploadDecisionMetricName[] = "UploadDecision";
 const char kUKMDeveloperEngagementEntryName[] = "Autofill.DeveloperEngagement";
 const char kUKMDeveloperEngagementMetricName[] = "DeveloperEngagement";
+const char kUKMAutofillFormSubmittedStateName[] = "AutofillFormSubmittedState";
+const char kUKMUserHappinessMetricName[] = "UserHappinessMetric";
+const char kUKMAddressFormEventName[] = "FormEvent.Address";
+const char kUKMCreditCardFormEventName[] = "FormEvent.CreditCard";
+const char kUKMUnmaskPromptEventName[] = "UnmaskPromptEvent";
+const char kUKMMillisecondsSinceFormLoadedMetricName[] =
+    "MillisecondsSinceFormLoaded";
 }  // namespace internal
 
 namespace autofill {
@@ -616,7 +625,8 @@ void AutofillMetrics::LogProfileActionOnFormSubmitted(
 
 // static
 void AutofillMetrics::LogAutofillFormSubmittedState(
-    AutofillFormSubmittedState state) {
+    AutofillFormSubmittedState state,
+    AutofillMetrics::FormInteractionsUkmLogger* form_interactions_ukm_logger) {
   UMA_HISTOGRAM_ENUMERATION("Autofill.FormSubmittedState", state,
                             AUTOFILL_FORM_SUBMITTED_STATE_ENUM_SIZE);
 
@@ -650,6 +660,7 @@ void AutofillMetrics::LogAutofillFormSubmittedState(
       NOTREACHED();
       break;
   }
+  form_interactions_ukm_logger->LogAutofillFormSubmittedState(state);
 }
 
 // static
@@ -706,7 +717,7 @@ void AutofillMetrics::LogCardUploadDecisionUkm(
   if (upload_decision >= AutofillMetrics::NUM_CARD_UPLOAD_DECISION_METRICS)
     return;
 
-  const std::map<std::string, int> metrics = {
+  const std::vector<std::pair<const char*, int>> metrics = {
       {internal::kUKMCardUploadDecisionMetricName,
        static_cast<int>(upload_decision)}};
   LogUkm(ukm_service, url, internal::kUKMCardUploadDecisionEntryName, metrics);
@@ -716,18 +727,22 @@ void AutofillMetrics::LogCardUploadDecisionUkm(
 void AutofillMetrics::LogDeveloperEngagementUkm(
     ukm::UkmService* ukm_service,
     const GURL& url,
-    AutofillMetrics::DeveloperEngagementMetric metric) {
-  const std::map<std::string, int> form_structure_metrics = {
-      {internal::kUKMDeveloperEngagementMetricName, static_cast<int>(metric)}};
+    std::vector<AutofillMetrics::DeveloperEngagementMetric> metrics) {
+  std::vector<std::pair<const char*, int>> form_structure_metrics;
+  for (const auto it : metrics)
+    form_structure_metrics.push_back(
+        {internal::kUKMDeveloperEngagementMetricName, static_cast<int>(it)});
+
   LogUkm(ukm_service, url, internal::kUKMDeveloperEngagementEntryName,
          form_structure_metrics);
 }
 
 // static
-bool AutofillMetrics::LogUkm(ukm::UkmService* ukm_service,
-                             const GURL& url,
-                             const std::string& ukm_entry_name,
-                             const std::map<std::string, int>& metrics) {
+bool AutofillMetrics::LogUkm(
+    ukm::UkmService* ukm_service,
+    const GURL& url,
+    const std::string& ukm_entry_name,
+    const std::vector<std::pair<const char*, int>>& metrics) {
   if (!IsUkmLoggingEnabled() || !ukm_service || !url.is_valid() ||
       metrics.empty()) {
     return false;
@@ -739,13 +754,15 @@ bool AutofillMetrics::LogUkm(ukm::UkmService* ukm_service,
       ukm_service->GetEntryBuilder(source_id, ukm_entry_name.c_str());
 
   for (auto it = metrics.begin(); it != metrics.end(); ++it) {
-    builder->AddMetric(it->first.c_str(), it->second);
+    builder->AddMetric(it->first, it->second);
   }
 
   return true;
 }
 
-AutofillMetrics::FormEventLogger::FormEventLogger(bool is_for_credit_card)
+AutofillMetrics::FormEventLogger::FormEventLogger(
+    bool is_for_credit_card,
+    AutofillMetrics::FormInteractionsUkmLogger* form_interactions_ukm_logger)
     : is_for_credit_card_(is_for_credit_card),
       is_server_data_available_(false),
       is_local_data_available_(false),
@@ -757,12 +774,13 @@ AutofillMetrics::FormEventLogger::FormEventLogger(bool is_for_credit_card)
       has_logged_will_submit_(false),
       has_logged_submitted_(false),
       logged_suggestion_filled_was_server_data_(false),
-      logged_suggestion_filled_was_masked_server_card_(false) {}
+      logged_suggestion_filled_was_masked_server_card_(false),
+      form_interactions_ukm_logger_(form_interactions_ukm_logger) {}
 
 void AutofillMetrics::FormEventLogger::OnDidInteractWithAutofillableForm() {
   if (!has_logged_interacted_) {
     has_logged_interacted_ = true;
-    Log(AutofillMetrics::FORM_EVENT_INTERACTED_ONCE);
+    Log(AutofillMetrics::FORM_EVENT_INTERACTED_ONCE, false /* log_ukm */);
   }
 }
 
@@ -786,10 +804,11 @@ void AutofillMetrics::FormEventLogger::OnDidPollSuggestions(
 }
 
 void AutofillMetrics::FormEventLogger::OnDidShowSuggestions() {
-  Log(AutofillMetrics::FORM_EVENT_SUGGESTIONS_SHOWN);
+  Log(AutofillMetrics::FORM_EVENT_SUGGESTIONS_SHOWN, true /* log_ukm */);
   if (!has_logged_suggestions_shown_) {
     has_logged_suggestions_shown_ = true;
-    Log(AutofillMetrics::FORM_EVENT_SUGGESTIONS_SHOWN_ONCE);
+    Log(AutofillMetrics::FORM_EVENT_SUGGESTIONS_SHOWN_ONCE,
+        false /* log_ukm */);
   }
 
   if (is_for_credit_card_) {
@@ -803,11 +822,13 @@ void AutofillMetrics::FormEventLogger::OnDidShowSuggestions() {
 
 void AutofillMetrics::FormEventLogger::OnDidSelectMaskedServerCardSuggestion() {
   DCHECK(is_for_credit_card_);
-  Log(AutofillMetrics::FORM_EVENT_MASKED_SERVER_CARD_SUGGESTION_SELECTED);
+  Log(AutofillMetrics::FORM_EVENT_MASKED_SERVER_CARD_SUGGESTION_SELECTED,
+      true /* log_ukm */);
   if (!has_logged_masked_server_card_suggestion_selected_) {
     has_logged_masked_server_card_suggestion_selected_ = true;
-    Log(AutofillMetrics
-            ::FORM_EVENT_MASKED_SERVER_CARD_SUGGESTION_SELECTED_ONCE);
+    Log(AutofillMetrics ::
+            FORM_EVENT_MASKED_SERVER_CARD_SUGGESTION_SELECTED_ONCE,
+        false /* log_ukm */);
   }
 }
 
@@ -815,11 +836,14 @@ void AutofillMetrics::FormEventLogger::OnDidFillSuggestion(
     const CreditCard& credit_card) {
   DCHECK(is_for_credit_card_);

[Steven Holte, 2017/04/12 02:26:30]

This seems like a much more natural place to log the event from, since most of
this seems to be to try to flatten / multiply things for UMA, which is probably
not helpful for UKM, since you can just add the information to the event.

e.g.

std::unique_ptr<ukm::UkmEntryBuilder> builder =
    ukm_service_->GetEntryBuilder(source_id, "FormEvent");
builder->AddMetric("EventType", FILL_SUGGESTION);
builder->AddMetric(internal::kUKMMillisecondsSinceFormLoadedMetricName,
                   GetTimeSinceFormLoaded());
builder->AddMetric("RecordType", credit_card.record_type());
// You could pack 
builder->AddMetric("IsContextSecure", is_context_secure_);
builder->AddMetric("FilledBefore", has_logged_suggestion_filled_);
has_logged_suggestion_filled_=true;

[csashi, 2017/04/12 05:53:58]

Done.

   if (credit_card.record_type() == CreditCard::MASKED_SERVER_CARD)
-    Log(AutofillMetrics::FORM_EVENT_MASKED_SERVER_CARD_SUGGESTION_FILLED);
+    Log(AutofillMetrics::FORM_EVENT_MASKED_SERVER_CARD_SUGGESTION_FILLED,
+        true /* log_ukm */);
   else if (credit_card.record_type() == CreditCard::FULL_SERVER_CARD)
-    Log(AutofillMetrics::FORM_EVENT_SERVER_SUGGESTION_FILLED);
+    Log(AutofillMetrics::FORM_EVENT_SERVER_SUGGESTION_FILLED,
+        true /* log_ukm */);
   else
-    Log(AutofillMetrics::FORM_EVENT_LOCAL_SUGGESTION_FILLED);
+    Log(AutofillMetrics::FORM_EVENT_LOCAL_SUGGESTION_FILLED,
+        true /* log_ukm */);
 
   if (!has_logged_suggestion_filled_) {
     has_logged_suggestion_filled_ = true;
@@ -829,12 +853,15 @@ void AutofillMetrics::FormEventLogger::OnDidFillSuggestion(
     logged_suggestion_filled_was_masked_server_card_ =
         credit_card.record_type() == CreditCard::MASKED_SERVER_CARD;
     if (credit_card.record_type() == CreditCard::MASKED_SERVER_CARD) {
-      Log(AutofillMetrics
-              ::FORM_EVENT_MASKED_SERVER_CARD_SUGGESTION_FILLED_ONCE);
+      Log(AutofillMetrics ::
+              FORM_EVENT_MASKED_SERVER_CARD_SUGGESTION_FILLED_ONCE,
+          false /* log_ukm */);
     } else if (credit_card.record_type() == CreditCard::FULL_SERVER_CARD) {
-      Log(AutofillMetrics::FORM_EVENT_SERVER_SUGGESTION_FILLED_ONCE);
+      Log(AutofillMetrics::FORM_EVENT_SERVER_SUGGESTION_FILLED_ONCE,
+          false /* log_ukm */);
     } else {
-      Log(AutofillMetrics::FORM_EVENT_LOCAL_SUGGESTION_FILLED_ONCE);
+      Log(AutofillMetrics::FORM_EVENT_LOCAL_SUGGESTION_FILLED_ONCE,
+          false /* log_ukm */);
     }
   }
 
@@ -846,17 +873,20 @@ void AutofillMetrics::FormEventLogger::OnDidFillSuggestion(
     const AutofillProfile& profile) {
   DCHECK(!is_for_credit_card_);
   if (profile.record_type() == AutofillProfile::SERVER_PROFILE)
-    Log(AutofillMetrics::FORM_EVENT_SERVER_SUGGESTION_FILLED);
+    Log(AutofillMetrics::FORM_EVENT_SERVER_SUGGESTION_FILLED,
+        true /* log_ukm */);
   else
-    Log(AutofillMetrics::FORM_EVENT_LOCAL_SUGGESTION_FILLED);
+    Log(AutofillMetrics::FORM_EVENT_LOCAL_SUGGESTION_FILLED,
+        true /* log_ukm */);
 
   if (!has_logged_suggestion_filled_) {
     has_logged_suggestion_filled_ = true;
     logged_suggestion_filled_was_server_data_ =
         profile.record_type() == AutofillProfile::SERVER_PROFILE;
     Log(profile.record_type() == AutofillProfile::SERVER_PROFILE
-        ? AutofillMetrics::FORM_EVENT_SERVER_SUGGESTION_FILLED_ONCE
-        : AutofillMetrics::FORM_EVENT_LOCAL_SUGGESTION_FILLED_ONCE);
+            ? AutofillMetrics::FORM_EVENT_SERVER_SUGGESTION_FILLED_ONCE
+            : AutofillMetrics::FORM_EVENT_LOCAL_SUGGESTION_FILLED_ONCE,
+        false /* log_ukm */);
   }
 
   base::RecordAction(
@@ -874,18 +904,23 @@ void AutofillMetrics::FormEventLogger::OnWillSubmitForm() {
   has_logged_will_submit_ = true;
 
   if (!has_logged_suggestion_filled_) {
-    Log(AutofillMetrics::FORM_EVENT_NO_SUGGESTION_WILL_SUBMIT_ONCE);
+    Log(AutofillMetrics::FORM_EVENT_NO_SUGGESTION_WILL_SUBMIT_ONCE,
+        false /* log_ukm */);
   } else if (logged_suggestion_filled_was_masked_server_card_) {
     Log(AutofillMetrics::
-            FORM_EVENT_MASKED_SERVER_CARD_SUGGESTION_WILL_SUBMIT_ONCE);
+            FORM_EVENT_MASKED_SERVER_CARD_SUGGESTION_WILL_SUBMIT_ONCE,
+        false /* log_ukm */);
   } else if (logged_suggestion_filled_was_server_data_) {
-    Log(AutofillMetrics::FORM_EVENT_SERVER_SUGGESTION_WILL_SUBMIT_ONCE);
+    Log(AutofillMetrics::FORM_EVENT_SERVER_SUGGESTION_WILL_SUBMIT_ONCE,
+        false /* log_ukm */);
   } else {
-    Log(AutofillMetrics::FORM_EVENT_LOCAL_SUGGESTION_WILL_SUBMIT_ONCE);
+    Log(AutofillMetrics::FORM_EVENT_LOCAL_SUGGESTION_WILL_SUBMIT_ONCE,
+        false /* log_ukm */);
   }
 
   if (has_logged_suggestions_shown_) {
-    Log(AutofillMetrics::FORM_EVENT_SUGGESTION_SHOWN_WILL_SUBMIT_ONCE);
+    Log(AutofillMetrics::FORM_EVENT_SUGGESTION_SHOWN_WILL_SUBMIT_ONCE,
+        false /* log_ukm */);
   }
 
   base::RecordAction(base::UserMetricsAction("Autofill_OnWillSubmitForm"));
@@ -902,22 +937,28 @@ void AutofillMetrics::FormEventLogger::OnFormSubmitted() {
   has_logged_submitted_ = true;
 
   if (!has_logged_suggestion_filled_) {
-    Log(AutofillMetrics::FORM_EVENT_NO_SUGGESTION_SUBMITTED_ONCE);
+    Log(AutofillMetrics::FORM_EVENT_NO_SUGGESTION_SUBMITTED_ONCE,
+        false /* log_ukm */);
   } else if (logged_suggestion_filled_was_masked_server_card_) {
-    Log(AutofillMetrics
-            ::FORM_EVENT_MASKED_SERVER_CARD_SUGGESTION_SUBMITTED_ONCE);
+    Log(AutofillMetrics ::
+            FORM_EVENT_MASKED_SERVER_CARD_SUGGESTION_SUBMITTED_ONCE,
+        false /* log_ukm */);
   } else if (logged_suggestion_filled_was_server_data_) {
-    Log(AutofillMetrics::FORM_EVENT_SERVER_SUGGESTION_SUBMITTED_ONCE);
+    Log(AutofillMetrics::FORM_EVENT_SERVER_SUGGESTION_SUBMITTED_ONCE,
+        false /* log_ukm */);
   } else {
-    Log(AutofillMetrics::FORM_EVENT_LOCAL_SUGGESTION_SUBMITTED_ONCE);
+    Log(AutofillMetrics::FORM_EVENT_LOCAL_SUGGESTION_SUBMITTED_ONCE,
+        false /* log_ukm */);
   }
 
   if (has_logged_suggestions_shown_) {
-    Log(AutofillMetrics::FORM_EVENT_SUGGESTION_SHOWN_SUBMITTED_ONCE);
+    Log(AutofillMetrics::FORM_EVENT_SUGGESTION_SHOWN_SUBMITTED_ONCE,
+        false /* log_ukm */);
   }
 }
 
-void AutofillMetrics::FormEventLogger::Log(FormEvent event) const {
+void AutofillMetrics::FormEventLogger::Log(FormEvent event,
+                                           bool log_ukm) const {
   DCHECK_LT(event, NUM_FORM_EVENTS);
   std::string name("Autofill.FormEvents.");
   if (is_for_credit_card_)
@@ -946,6 +987,80 @@ void AutofillMetrics::FormEventLogger::Log(FormEvent event) const {
   else
     name += ".WithBothServerAndLocalData";
   LogUMAHistogramEnumeration(name, event, NUM_FORM_EVENTS);
+
+  if (log_ukm) {
+    if (is_for_credit_card_)
+      form_interactions_ukm_logger_->LogCreditCardFormEvent(event);
+    else
+      form_interactions_ukm_logger_->LogAddressFormEvent(event);
+  }
+}
+
+AutofillMetrics::FormInteractionsUkmLogger::FormInteractionsUkmLogger(
+    ukm::UkmService* ukm_service)
+    : ukm_service_(ukm_service) {}
+
+AutofillMetrics::FormInteractionsUkmLogger::~FormInteractionsUkmLogger() {
+  // Submit pending events, if any. If the browser tab starts loading a new page
+  // when the user types a new URL prior to form submission,
+  // |LogAutofillFormSubmittedState| would not be invoked.
+  SubmitUkm();
+}
+
+void AutofillMetrics::FormInteractionsUkmLogger::LogAutofillFormSubmittedState(
+    AutofillFormSubmittedState state) {
+  AddEvent(internal::kUKMAutofillFormSubmittedStateName,
+           static_cast<int>(state));
+
+  // User submitted form, we can submit the events for this form.
+  SubmitUkm();
+}
+
+void AutofillMetrics::FormInteractionsUkmLogger::LogUserHappinessMetric(
+    UserHappinessMetric metric) {
+  AddEvent(internal::kUKMUserHappinessMetricName, static_cast<int>(metric));
+}
+
+void AutofillMetrics::FormInteractionsUkmLogger::LogAddressFormEvent(
+    FormEvent event) {
+  AddEvent(internal::kUKMAddressFormEventName, static_cast<int>(event));
+}
+
+void AutofillMetrics::FormInteractionsUkmLogger::LogCreditCardFormEvent(
+    FormEvent event) {
+  AddEvent(internal::kUKMCreditCardFormEventName, static_cast<int>(event));
+}
+
+void AutofillMetrics::FormInteractionsUkmLogger::LogUnmaskPromptEvent(
+    UnmaskPromptEvent event) {
+  AddEvent(internal::kUKMUnmaskPromptEventName, static_cast<int>(event));
+}
+
+void AutofillMetrics::FormInteractionsUkmLogger::SubmitUkm() {
+  if (!IsUkmLoggingEnabled() || !ukm_service_ || !url_.is_valid() ||
+      events_.empty())
+    return;
+
+  const int32_t source_id = ukm_service_->GetNewSourceID();

[Steven Holte, 2017/04/12 02:26:30]

Maybe call GetNewSourceID() in your constructor,
Call UpdateSourceURL when you set url_,
and GetEntryBuilder in AddEvent?

There doesn't seem to be a reason to wait for SubmitUkm()

[csashi, 2017/04/12 05:53:58]

Done.  I wasn't sure of when the logs will get "flushed"? Is it possible that
logs will be sent before we have updated with the correct URL?

[Steven Holte, 2017/04/12 19:42:15]

It is possible that the Entry and Source will be sent in different uploads, but
that's expected to be a typical case with UKM logs.  When analyzing the logs,
the first step should usually be to join by session_id + source_id across
multiple logs.  This is pretty quick and simple to do with the raw data that we
have currently, and we are currently building a sessionized logs source where
this step will be done already.

+  ukm_service_->UpdateSourceURL(source_id, url_);
+  for (const auto& it : events_) {
+    std::unique_ptr<ukm::UkmEntryBuilder> builder =
+        ukm_service_->GetEntryBuilder(source_id, it.name);
+    builder->AddMetric(it.name, it.value);
+    builder->AddMetric(internal::kUKMMillisecondsSinceFormLoadedMetricName,
+                       it.time_delta_millis);
+  }
+  events_.clear();
+  form_loaded_timestamp_ = base::TimeTicks();
+}
+
+void AutofillMetrics::FormInteractionsUkmLogger::AddEvent(
+    const char* const name,
+    int value) {
+  DCHECK(!form_loaded_timestamp_.is_null());
+  events_.push_back(Event(
+      name, value,
+      (base::TimeTicks::Now() - form_loaded_timestamp_).InMilliseconds()));
 }
 
 }  // namespace autofill