Add metric to track delay between conversion and reporting

Bug: 1114213
Change-Id: I2465b566cfce6cb5eefab3c9c26dd0b2ee09a313
Reviewed-on: https://chromium-review.googlesource.com/c/chromium/src/+/2543129
Commit-Queue: Andrew Paseltiner <apaseltiner@chromium.org>
Reviewed-by: John Delaney <johnidel@chromium.org>
Reviewed-by: Charlie Harrison <csharrison@chromium.org>
Cr-Commit-Position: refs/heads/master@{#828531}

content/browser/conversions/conversion_internals_browsertest.cc

@@ -215,8 +215,8 @@ IN_PROC_BROWSER_TEST_F(ConversionInternalsWebUiBrowserTest,
   TestConversionManager manager;
   ConversionReport report(
       ImpressionBuilder(base::Time::Now()).SetData("100").Build(),
-      "7" /* conversion_data */, base::Time::Now() /* report_time */,
-      1 /* conversion_id */);
+      "7" /* conversion_data */, base::Time::Now() /* conversion_time */,
+      base::Time::Now() /* report_time */, 1 /* conversion_id */);
   manager.SetReportsForWebUI({report});
   OverrideWebUIConversionManager(&manager);
 
@@ -243,8 +243,8 @@ IN_PROC_BROWSER_TEST_F(ConversionInternalsWebUiBrowserTest,
   TestConversionManager manager;
   ConversionReport report(
       ImpressionBuilder(base::Time::Now()).SetData("100").Build(),
-      "7" /* conversion_data */, base::Time::Now() /* report_time */,
-      1 /* conversion_id */);
+      "7" /* conversion_data */, base::Time::Now() /* conversion_time */,
+      base::Time::Now() /* report_time */, 1 /* conversion_id */);
   manager.SetReportsForWebUI({report});
   OverrideWebUIConversionManager(&manager);
 
@@ -283,8 +283,8 @@ IN_PROC_BROWSER_TEST_F(ConversionInternalsWebUiBrowserTest,
   TestConversionManager manager;
   ConversionReport report(
       ImpressionBuilder(base::Time::Now()).SetData("100").Build(),
-      "7" /* conversion_data */, base::Time::Now() /* report_time */,
-      1 /* conversion_id */);
+      "7" /* conversion_data */, base::Time::Now() /* conversion_time */,
+      base::Time::Now() /* report_time */, 1 /* conversion_id */);
   manager.SetReportsForWebUI({report});
   OverrideWebUIConversionManager(&manager);
 

content/browser/conversions/conversion_manager_impl_unittest.cc

@@ -179,9 +179,11 @@ TEST_F(ConversionManagerImplTest, ImpressionConverted_ReportReturnedToWebUI) {
   auto conversion = DefaultConversion();
   conversion_manager_->HandleConversion(conversion);
 
-  ConversionReport expected_report(impression, conversion.conversion_data(),
-                                   clock().Now() + kFirstReportingWindow,
-                                   base::nullopt /* conversion_id */);
+  ConversionReport expected_report(
+      impression, conversion.conversion_data(),
+      /*conversion_time=*/clock().Now(),
+      /*report_time=*/clock().Now() + kFirstReportingWindow,
+      base::nullopt /* conversion_id */);
   expected_report.attribution_credit = 100;
 
   base::RunLoop run_loop;

content/browser/conversions/conversion_network_sender_impl.cc

@@ -10,6 +10,7 @@
 #include "base/bind.h"
 #include "base/check.h"
 #include "base/metrics/histogram_functions.h"
+#include "base/metrics/histogram_macros.h"
 #include "base/strings/strcat.h"
 #include "base/strings/string_number_conversions.h"
 #include "base/time/time.h"
@@ -56,13 +57,17 @@ void LogMetricsOnReportSend(ConversionReport* report) {
   // time since the report was originally scheduled, for reports at startup
   // whose |report_time| changes due to additional startup delay.
   base::Time now = base::Time::Now();
-  base::TimeDelta delay = (now - report->report_time) + report->extra_delay;
-  base::UmaHistogramCustomTimes("Conversions.ExtraReportDelay", delay,
+  base::TimeDelta time_since_original_report_time =
+      (now - report->report_time) + report->extra_delay;
+  base::UmaHistogramCustomTimes("Conversions.ExtraReportDelay",
+                                time_since_original_report_time,
                                 base::TimeDelta::FromSeconds(1),
                                 base::TimeDelta::FromDays(7), /*buckets=*/100);
 
-  // TODO(csharrison): We should thread the conversion time alongside the
-  // ConversionReport to log the effective time since conversion.
+  base::TimeDelta time_from_conversion_to_report_send =
+      report->report_time - report->conversion_time;
+  UMA_HISTOGRAM_COUNTS_1000("Conversions.TimeFromConversionToReportSend",
+                            time_from_conversion_to_report_send.InHours());
 }
 
 GURL GetReportUrl(const content::ConversionReport& report) {

content/browser/conversions/conversion_network_sender_impl_unittest.cc

@@ -46,6 +46,7 @@ ConversionReport GetReport(int64_t conversion_id) {
           .SetData(base::NumberToString(conversion_id))
           .Build(),
       /*conversion_data=*/base::NumberToString(conversion_id),
+      /*conversion_time=*/base::Time(),
       /*report_time=*/base::Time(),
       /*conversion_id=*/conversion_id);
 }
@@ -135,6 +136,7 @@ TEST_F(ConversionNetworkSenderTest, ReportSent_QueryParamsSetCorrectly) {
           .Build();
   ConversionReport report(impression,
                           /*conversion_data=*/"conversion",
+                          /*conversion_time=*/base::Time(),
                           /*report_time=*/base::Time(),
                           /*conversion_id=*/1);
   report.attribution_credit = 50;
@@ -157,6 +159,7 @@ TEST_F(ConversionNetworkSenderTest, ReportSent_RequestAttributesSet) {
           .Build();
   ConversionReport report(impression,
                           /*conversion_data=*/"1",
+                          /*conversion_time=*/base::Time(),
                           /*report_time=*/base::Time(),
                           /*conversion_id=*/1);
   network_sender_->SendReport(&report, base::DoNothing());
@@ -248,4 +251,15 @@ TEST_F(ConversionNetworkSenderTest, ErrorHistogram) {
   }
 }
 
+TEST_F(ConversionNetworkSenderTest, TimeFromConversionToReportSendHistogram) {
+  base::HistogramTester histograms;
+  auto report = GetReport(/*conversion_id=*/1);
+  report.report_time = base::Time() + base::TimeDelta::FromHours(5);
+  network_sender_->SendReport(&report, GetSentCallback());
+  EXPECT_TRUE(test_url_loader_factory_.SimulateResponseForPendingRequest(
+      GetReportUrl("1"), ""));
+  histograms.ExpectUniqueSample("Conversions.TimeFromConversionToReportSend", 5,
+                                1);
+}
+
 }  // namespace content

content/browser/conversions/conversion_report.cc

@@ -10,10 +10,12 @@ namespace content {
 
 ConversionReport::ConversionReport(const StorableImpression& impression,
                                    const std::string& conversion_data,
+                                   base::Time conversion_time,
                                    base::Time report_time,
                                    const base::Optional<int64_t>& conversion_id)
     : impression(impression),
       conversion_data(conversion_data),
+      conversion_time(conversion_time),
       report_time(report_time),
       conversion_id(conversion_id) {}
 
@@ -27,6 +29,7 @@ std::ostream& operator<<(std::ostream& out, const ConversionReport& report) {
       << ", conversion_origin: " << report.impression.conversion_origin()
       << ", reporting_origin: " << report.impression.reporting_origin()
       << ", conversion_data: " << report.conversion_data
+      << ", conversion_time: " << report.conversion_time
       << ", report_time: " << report.report_time
       << ", extra_delay: " << report.extra_delay
       << ", attribution_credit: " << report.attribution_credit;

content/browser/conversions/conversion_report.h

@@ -23,6 +23,7 @@ struct CONTENT_EXPORT ConversionReport {
   // The conversion_id may not be set for a conversion report.
   ConversionReport(const StorableImpression& impression,
                    const std::string& conversion_data,
+                   base::Time conversion_time,
                    base::Time report_time,
                    const base::Optional<int64_t>& conversion_id);
   ConversionReport(const ConversionReport& other);
@@ -35,6 +36,9 @@ struct CONTENT_EXPORT ConversionReport {
   // representing a valid hexadecimal number.
   const std::string conversion_data;
 
+  // The time the conversion occurred.
+  const base::Time conversion_time;
+
   // The time this conversion report should be sent.
   base::Time report_time;
 

content/browser/conversions/conversion_reporter_impl_unittest.cc

@@ -27,11 +27,13 @@ namespace {
 
 // Create a report which should be sent at |report_time|. Impression
 // data/conversion data/conversion id are all the same for simplicity.
-ConversionReport GetReport(base::Time report_time, int64_t conversion_id) {
+ConversionReport GetReport(base::Time conversion_time,
+                           base::Time report_time,
+                           int64_t conversion_id) {
   // Construct impressions with a null impression time as it is not used for
   // reporting.
   return ConversionReport(ImpressionBuilder(base::Time()).Build(),
-                          /*conversion_data=*/"", report_time,
+                          /*conversion_data=*/"", conversion_time, report_time,
                           /*conversion_id=*/conversion_id);
 }
 
@@ -84,10 +86,10 @@ class ConversionReporterImplTest : public testing::Test {
 
 TEST_F(ConversionReporterImplTest,
        ReportAddedWithImmediateReportTime_ReportSent) {
-  reporter_->AddReportsToQueue({GetReport(clock().Now(), /*conversion_id=*/1)},
-                               base::BindRepeating([](int64_t conversion_id) {
-                                 EXPECT_EQ(1L, conversion_id);
-                               }));
+  reporter_->AddReportsToQueue(
+      {GetReport(clock().Now(), clock().Now(), /*conversion_id=*/1)},
+      base::BindRepeating(
+          [](int64_t conversion_id) { EXPECT_EQ(1L, conversion_id); }));
 
   // Fast forward by 0, as we yield the thread when a report is scheduled to be
   // sent.
@@ -98,7 +100,7 @@ TEST_F(ConversionReporterImplTest,
 TEST_F(ConversionReporterImplTest,
        ReportWithReportTimeBeforeCurrentTime_ReportSent) {
   reporter_->AddReportsToQueue(
-      {GetReport(clock().Now() - base::TimeDelta::FromHours(10),
+      {GetReport(clock().Now(), clock().Now() - base::TimeDelta::FromHours(10),
                  /*conversion_id=*/1)},
       base::BindRepeating(
           [](int64_t conversion_id) { EXPECT_EQ(1L, conversion_id); }));
@@ -114,7 +116,7 @@ TEST_F(ConversionReporterImplTest,
   const base::TimeDelta delay = base::TimeDelta::FromMinutes(30);
 
   reporter_->AddReportsToQueue(
-      {GetReport(clock().Now() + delay, /*conversion_id=*/1)},
+      {GetReport(clock().Now(), clock().Now() + delay, /*conversion_id=*/1)},
       base::DoNothing());
   task_environment_.FastForwardBy(base::TimeDelta());
   EXPECT_EQ(0u, sender_->num_reports_sent());
@@ -128,13 +130,13 @@ TEST_F(ConversionReporterImplTest,
 
 TEST_F(ConversionReporterImplTest, DuplicateReportScheduled_Ignored) {
   reporter_->AddReportsToQueue(
-      {GetReport(clock().Now() + base::TimeDelta::FromMinutes(1),
+      {GetReport(clock().Now(), clock().Now() + base::TimeDelta::FromMinutes(1),
                  /*conversion_id=*/1)},
       base::DoNothing());
 
   // A duplicate report should not be scheduled.
   reporter_->AddReportsToQueue(
-      {GetReport(clock().Now() + base::TimeDelta::FromMinutes(1),
+      {GetReport(clock().Now(), clock().Now() + base::TimeDelta::FromMinutes(1),
                  /*conversion_id=*/1)},
       base::DoNothing());
   task_environment_.FastForwardBy(base::TimeDelta::FromMinutes(1));
@@ -143,15 +145,17 @@ TEST_F(ConversionReporterImplTest, DuplicateReportScheduled_Ignored) {
 
 TEST_F(ConversionReporterImplTest,
        NewReportWithPreviouslySeenConversionId_Scheduled) {
-  reporter_->AddReportsToQueue({GetReport(clock().Now(), /*conversion_id=*/1)},
-                               base::DoNothing());
+  reporter_->AddReportsToQueue(
+      {GetReport(clock().Now(), clock().Now(), /*conversion_id=*/1)},
+      base::DoNothing());
   task_environment_.FastForwardBy(base::TimeDelta());
   EXPECT_EQ(1u, sender_->num_reports_sent());
 
   // We should schedule the new report because the previous report has been
   // sent.
-  reporter_->AddReportsToQueue({GetReport(clock().Now(), /*conversion_id=*/1)},
-                               base::DoNothing());
+  reporter_->AddReportsToQueue(
+      {GetReport(clock().Now(), clock().Now(), /*conversion_id=*/1)},
+      base::DoNothing());
   task_environment_.FastForwardBy(base::TimeDelta());
   EXPECT_EQ(2u, sender_->num_reports_sent());
 }
@@ -160,7 +164,8 @@ TEST_F(ConversionReporterImplTest, ManyReportsAddedAtOnce_SentInOrder) {
   std::vector<ConversionReport> reports;
   int64_t last_report_id = 0UL;
   for (int i = 1; i < 10; i++) {
-    reports.push_back(GetReport(clock().Now() + base::TimeDelta::FromMinutes(i),
+    reports.push_back(GetReport(clock().Now(),
+                                clock().Now() + base::TimeDelta::FromMinutes(i),
                                 /*conversion_id=*/i));
   }
   reporter_->AddReportsToQueue(
@@ -185,7 +190,8 @@ TEST_F(ConversionReporterImplTest, ManyReportsAddedSeparately_SentInOrder) {
       [&](int64_t conversion_id) { last_report_id = conversion_id; });
   for (int i = 1; i < 10; i++) {
     reporter_->AddReportsToQueue(
-        {GetReport(clock().Now() + base::TimeDelta::FromMinutes(i),
+        {GetReport(clock().Now(),
+                   clock().Now() + base::TimeDelta::FromMinutes(i),
                    /*conversion_id=*/i)},
         report_sent_callback);
   }
@@ -205,10 +211,10 @@ TEST_F(ConversionReporterImplTest, EmbedderDisallowsConversions_ReportNotSent) {
   ConversionDisallowingContentBrowserClient disallowed_browser_client;
   ContentBrowserClient* old_browser_client =
       SetBrowserClientForTesting(&disallowed_browser_client);
-  reporter_->AddReportsToQueue({GetReport(clock().Now(), /*conversion_id=*/1)},
-                               base::BindRepeating([](int64_t conversion_id) {
-                                 EXPECT_EQ(1L, conversion_id);
-                               }));
+  reporter_->AddReportsToQueue(
+      {GetReport(clock().Now(), clock().Now(), /*conversion_id=*/1)},
+      base::BindRepeating(
+          [](int64_t conversion_id) { EXPECT_EQ(1L, conversion_id); }));
 
   // Fast forward by 0, as we yield the thread when a report is scheduled to be
   // sent.

content/browser/conversions/conversion_storage_delegate_impl_unittest.cc

@@ -21,9 +21,10 @@ constexpr base::TimeDelta kDefaultExpiry = base::TimeDelta::FromDays(30);
 ConversionReport GetReport(base::Time impression_time,
                            base::Time conversion_time,
                            base::TimeDelta expiry = kDefaultExpiry) {
+  base::Time report_time = conversion_time;
   return ConversionReport(
       ImpressionBuilder(impression_time).SetExpiry(expiry).Build(),
-      /*conversion_data=*/"123", conversion_time,
+      /*conversion_data=*/"123", conversion_time, report_time,
       /*conversion_id=*/base::nullopt);
 }
 

content/browser/conversions/conversion_storage_sql.cc

@@ -199,7 +199,9 @@ int ConversionStorageSql::MaybeCreateAndStoreConversionReports(
                                   impression_time, expiry_time, impression_id);
 
     ConversionReport report(std::move(impression), conversion.conversion_data(),
-                            current_time, /*conversion_id=*/base::nullopt);
+                            /*conversion_time=*/current_time,
+                            /*report_time=*/current_time,
+                            /*conversion_id=*/base::nullopt);
     new_reports.push_back(std::move(report));
   }
 
@@ -279,10 +281,10 @@ std::vector<ConversionReport> ConversionStorageSql::GetConversionsToReport(
   // Get all entries in the conversions table with a |report_time| less than
   // |expired_at| and their matching information from the impression table.
   const char kGetExpiredConversionsSql[] =
-      "SELECT C.conversion_data, C.attribution_credit, C.report_time, "
-      "C.conversion_id, I.impression_origin, I.conversion_origin, "
-      "I.reporting_origin, I.impression_data, I.impression_time, "
-      "I.expiry_time, I.impression_id "
+      "SELECT C.conversion_data, C.attribution_credit, C.conversion_time, "
+      "C.report_time, C.conversion_id, I.impression_origin, "
+      "I.conversion_origin, I.reporting_origin, I.impression_data, "
+      "I.impression_time, I.expiry_time, I.impression_id "
       "FROM conversions C JOIN impressions I ON "
       "C.impression_id = I.impression_id WHERE C.report_time <= ?";
   sql::Statement statement(
@@ -293,17 +295,18 @@ std::vector<ConversionReport> ConversionStorageSql::GetConversionsToReport(
   while (statement.Step()) {
     std::string conversion_data = statement.ColumnString(0);
     int attribution_credit = statement.ColumnInt(1);
-    base::Time report_time = DeserializeTime(statement.ColumnInt64(2));
-    int64_t conversion_id = statement.ColumnInt64(3);
+    base::Time conversion_time = DeserializeTime(statement.ColumnInt64(2));
+    base::Time report_time = DeserializeTime(statement.ColumnInt64(3));
+    int64_t conversion_id = statement.ColumnInt64(4);
     url::Origin impression_origin =
-        DeserializeOrigin(statement.ColumnString(4));
-    url::Origin conversion_origin =
         DeserializeOrigin(statement.ColumnString(5));
-    url::Origin reporting_origin = DeserializeOrigin(statement.ColumnString(6));
-    std::string impression_data = statement.ColumnString(7);
-    base::Time impression_time = DeserializeTime(statement.ColumnInt64(8));
-    base::Time expiry_time = DeserializeTime(statement.ColumnInt64(9));
-    int64_t impression_id = statement.ColumnInt64(10);
+    url::Origin conversion_origin =
+        DeserializeOrigin(statement.ColumnString(6));
+    url::Origin reporting_origin = DeserializeOrigin(statement.ColumnString(7));
+    std::string impression_data = statement.ColumnString(8);
+    base::Time impression_time = DeserializeTime(statement.ColumnInt64(9));
+    base::Time expiry_time = DeserializeTime(statement.ColumnInt64(10));
+    int64_t impression_id = statement.ColumnInt64(11);
 
     // Ensure origins are valid before continuing. This could happen if there is
     // database corruption.
@@ -320,8 +323,8 @@ std::vector<ConversionReport> ConversionStorageSql::GetConversionsToReport(
                                   conversion_origin, reporting_origin,
                                   impression_time, expiry_time, impression_id);
 
-    ConversionReport report(std::move(impression), conversion_data, report_time,
-                            conversion_id);
+    ConversionReport report(std::move(impression), conversion_data,
+                            conversion_time, report_time, conversion_id);
     report.attribution_credit = attribution_credit;
 
     conversions.push_back(std::move(report));

content/browser/conversions/conversion_storage_unittest.cc

@@ -64,10 +64,11 @@ class ConversionStorageTest : public testing::Test {
   ConversionReport GetExpectedReport(const StorableImpression& impression,
                                      const StorableConversion& conversion,
                                      int attribution_credit = 0) {
-    ConversionReport report(
-        impression, conversion.conversion_data(),
-        clock_.Now() + base::TimeDelta::FromMilliseconds(kReportTime),
-        base::nullopt /* conversion_id */);
+    ConversionReport report(impression, conversion.conversion_data(),
+                            /*conversion_time=*/clock_.Now(),
+                            /*report_time=*/clock_.Now() +
+                                base::TimeDelta::FromMilliseconds(kReportTime),
+                            base::nullopt /* conversion_id */);
     report.attribution_credit = attribution_credit;
     return report;
   }

tools/metrics/histograms/histograms_xml/others/histograms.xml

@@ -3051,6 +3051,16 @@ reviews. Googlers can read more about this at go/gwsq-gerrit.
   </summary>
 </histogram>
 
+<histogram name="Conversions.TimeFromConversionToReportSend" units="hours"
+    expires_after="M95">
+  <owner>johnidel@chromium.org</owner>
+  <owner>csharrison@chromium.org</owner>
+  <summary>
+    Records the time between a conversion and its reporting. This is emitted
+    whenever a conversion report is sent.
+  </summary>
+</histogram>
+
 <histogram name="CopylessPaste.CacheHit" enum="CopylessCacheHit"
     expires_after="2020-03-01">
   <owner>wychen@chromium.org</owner>