metrics: Specify time when recording user action

When observing user actions in Java code, native libraries may not be
immediately available to record these actions. This change allows for
deferred recording of user actions.

Bug: 1048429
Change-Id: I66a151c163597622fdf08f9a7312f8c800da0e13
Reviewed-on: https://chromium-review.googlesource.com/c/chromium/src/+/2040053
Commit-Queue: bttk <bttk@chromium.org>
Reviewed-by: John Abd-El-Malek <jam@chromium.org>
Reviewed-by: Sylvain Defresne <sdefresne@chromium.org>
Reviewed-by: Alexei Svitkine <asvitkine@chromium.org>
Reviewed-by: Sky Malice <skym@chromium.org>
Reviewed-by: Ender <ender@google.com>
Cr-Commit-Position: refs/heads/master@{#744165}

base/android/record_user_action.cc

@@ -9,11 +9,9 @@
 #include "base/metrics/user_metrics.h"
 
 namespace {
-
 struct ActionCallbackWrapper {
   base::ActionCallback action_callback;
 };
-
 }  // namespace
 
 namespace base {
@@ -26,7 +24,8 @@ static void JNI_RecordUserAction_RecordUserAction(
 }
 
 static void OnActionRecorded(const JavaRef<jobject>& callback,
-                             const std::string& action) {
+                             const std::string& action,
+                             TimeTicks action_time) {
   JNIEnv* env = AttachCurrentThread();
   Java_UserActionCallback_onActionRecorded(
       env, callback, ConvertUTF8ToJavaString(env, action));

base/metrics/user_metrics.cc

@@ -13,6 +13,7 @@
 #include "base/location.h"
 #include "base/macros.h"
 #include "base/threading/thread_checker.h"
+#include "base/time/time.h"
 #include "base/trace_event/trace_event.h"
 
 namespace base {
@@ -30,20 +31,25 @@ void RecordAction(const UserMetricsAction& action) {
 }
 
 void RecordComputedAction(const std::string& action) {
-  TRACE_EVENT_INSTANT1("ui", "UserEvent", TRACE_EVENT_SCOPE_GLOBAL, "action", action);
+  RecordComputedActionAt(action, TimeTicks::Now());
+}
+
+void RecordComputedActionAt(const std::string& action, TimeTicks action_time) {
+  TRACE_EVENT_INSTANT1("ui", "UserEvent", TRACE_EVENT_SCOPE_GLOBAL, "action",
+                       action);
   if (!g_task_runner.Get()) {
     DCHECK(g_callbacks.Get().empty());
     return;
   }
 
   if (!g_task_runner.Get()->BelongsToCurrentThread()) {
-    g_task_runner.Get()->PostTask(FROM_HERE,
-                                  BindOnce(&RecordComputedAction, action));
+    g_task_runner.Get()->PostTask(
+        FROM_HERE, BindOnce(&RecordComputedActionAt, action, action_time));
     return;
   }
 
   for (const ActionCallback& callback : g_callbacks.Get()) {
-    callback.Run(action);
+    callback.Run(action, action_time);
   }
 }
 

base/metrics/user_metrics.h

@@ -14,6 +14,8 @@
 
 namespace base {
 
+class TimeTicks;
+
 // This module provides some helper functions for logging actions tracked by
 // the user metrics system.
 
@@ -55,8 +57,13 @@ BASE_EXPORT void RecordAction(const UserMetricsAction& action);
 // SetRecordActionTaskRunner().
 BASE_EXPORT void RecordComputedAction(const std::string& action);
 
+// Similar to RecordComputedAction, but also takes the time at which the action
+// was observed.
+BASE_EXPORT void RecordComputedActionAt(const std::string& action,
+                                        TimeTicks action_time);
+
 // Called with the action string.
-using ActionCallback = RepeatingCallback<void(const std::string&)>;
+using ActionCallback = RepeatingCallback<void(const std::string&, TimeTicks)>;
 
 // Add/remove action callbacks (see above).
 // These functions must be called after the task runner has been set with

base/test/metrics/user_action_tester.cc

@@ -31,7 +31,8 @@ void UserActionTester::ResetCounts() {
   count_map_.clear();
 }
 
-void UserActionTester::OnUserAction(const std::string& user_action) {
+void UserActionTester::OnUserAction(const std::string& user_action,
+                                    TimeTicks action_time) {
   ++(count_map_[user_action]);
 }
 

base/test/metrics/user_action_tester.h

@@ -13,6 +13,8 @@
 
 namespace base {
 
+class TimeTicks;
+
 // This class observes and collects user action notifications that are sent
 // by the tests, so that they can be examined afterwards for correctness.
 // Note: This class is NOT thread-safe.
@@ -31,7 +33,7 @@ class UserActionTester {
   typedef std::map<std::string, int> UserActionCountMap;
 
   // The callback that is notified when a user actions occurs.
-  void OnUserAction(const std::string& user_action);
+  void OnUserAction(const std::string& user_action, TimeTicks action_time);
 
   // A map that tracks the number of times a user action has occurred.
   UserActionCountMap count_map_;

chrome/browser/profiles/profile_activity_metrics_recorder.cc

@@ -129,6 +129,7 @@ ProfileActivityMetricsRecorder::~ProfileActivityMetricsRecorder() {
   base::RemoveActionCallback(action_callback_);
 }
 
-void ProfileActivityMetricsRecorder::OnUserAction(const std::string& action) {
+void ProfileActivityMetricsRecorder::OnUserAction(const std::string& action,
+                                                  base::TimeTicks action_time) {
   RecordUserAction(last_active_profile_);
 }

chrome/browser/profiles/profile_activity_metrics_recorder.h

@@ -38,7 +38,7 @@ class ProfileActivityMetricsRecorder
   ProfileActivityMetricsRecorder();
   ~ProfileActivityMetricsRecorder() override;
 
-  void OnUserAction(const std::string& action);
+  void OnUserAction(const std::string& action, base::TimeTicks action_time);
 
   Profile* last_active_profile_ = nullptr;
   base::TimeTicks profile_session_start_;

chrome/browser/ui/webui/chromeos/login/discover/modules/discover_module_launch_help_app_test.cc

@@ -17,8 +17,8 @@ IN_PROC_BROWSER_TEST_F(DiscoverModuleLaunchHelpAppTest, ShowHelpTab) {
 
   base::RunLoop run_loop;
 
-  base::ActionCallback on_user_action =
-      base::BindLambdaForTesting([&](const std::string& action) {
+  base::ActionCallback on_user_action = base::BindLambdaForTesting(
+      [&](const std::string& action, base::TimeTicks action_time) {
         if (action == "ShowHelpTab")
           run_loop.Quit();
       });

chrome/browser/ui/webui/user_actions/user_actions_ui_handler.cc

@@ -21,9 +21,9 @@ UserActionsUIHandler::~UserActionsUIHandler() {
 
 void UserActionsUIHandler::RegisterMessages() {}
 
-void UserActionsUIHandler::OnUserAction(const std::string& action) {
+void UserActionsUIHandler::OnUserAction(const std::string& action,
+                                        base::TimeTicks action_time) {
   base::Value user_action_name(action);
   web_ui()->CallJavascriptFunctionUnsafe("userActions.observeUserAction",
                                          user_action_name);
 }
-

chrome/browser/ui/webui/user_actions/user_actions_ui_handler.h

@@ -9,6 +9,10 @@
 #include "base/metrics/user_metrics.h"
 #include "content/public/browser/web_ui_message_handler.h"
 
+namespace base {
+class TimeTicks;
+}  // namespace base
+
 // UI Handler for chrome://user-actions/
 // It listens to user action notifications and passes those notifications
 // into the Javascript to update the page.
@@ -22,7 +26,7 @@ class UserActionsUIHandler : public content::WebUIMessageHandler {
   void RegisterMessages() override;
 
  private:
-  void OnUserAction(const std::string& action);
+  void OnUserAction(const std::string& action, base::TimeTicks action_time);
 
   base::ActionCallback action_callback_;
 

components/metrics/metrics_log.cc

@@ -68,6 +68,10 @@ class IndependentFlattener : public base::HistogramFlattener {
   DISALLOW_COPY_AND_ASSIGN(IndependentFlattener);
 };
 
+// Convenience function to return the given time at a resolution in seconds.
+static int64_t ToMonotonicSeconds(base::TimeTicks time_ticks) {
+  return (time_ticks - base::TimeTicks()).InSeconds();
+}
 
 }  // namespace
 
@@ -144,15 +148,16 @@ int64_t MetricsLog::GetBuildTime() {
 
 // static
 int64_t MetricsLog::GetCurrentTime() {
-  return (base::TimeTicks::Now() - base::TimeTicks()).InSeconds();
+  return ToMonotonicSeconds(base::TimeTicks::Now());
 }
 
-void MetricsLog::RecordUserAction(const std::string& key) {
+void MetricsLog::RecordUserAction(const std::string& key,
+                                  base::TimeTicks action_time) {
   DCHECK(!closed_);
 
   UserActionEventProto* user_action = uma_proto_.add_user_action_event();
   user_action->set_name_hash(Hash(key));
-  user_action->set_time_sec(GetCurrentTime());
+  user_action->set_time_sec(ToMonotonicSeconds(action_time));
 }
 
 // static

components/metrics/metrics_log.h

@@ -25,7 +25,7 @@ namespace base {
 class HistogramFlattener;
 class HistogramSamples;
 class HistogramSnapshotManager;
-}
+}  // namespace base
 
 namespace metrics {
 
@@ -118,7 +118,7 @@ class MetricsLog {
       SystemProfileProto* system_profile);
 
   // Records a user-initiated action.
-  void RecordUserAction(const std::string& key);
+  void RecordUserAction(const std::string& key, base::TimeTicks action_time);
 
   // Record any changes in a given histogram for transmission.
   void RecordHistogramDelta(const std::string& histogram_name,

components/metrics/metrics_log_unittest.cc

@@ -373,7 +373,7 @@ TEST_F(MetricsLogTest, TruncateEvents) {
   TestMetricsLog log(kClientId, kSessionId, MetricsLog::ONGOING_LOG, &client);
 
   for (int i = 0; i < internal::kUserActionEventLimit * 2; ++i) {
-    log.RecordUserAction("BasicAction");
+    log.RecordUserAction("BasicAction", base::TimeTicks::Now());
     EXPECT_EQ(i + 1, log.uma_proto().user_action_event_size());
   }
   for (int i = 0; i < internal::kOmniboxEventLimit * 2; ++i) {

components/metrics/metrics_service.cc

@@ -553,8 +553,9 @@ void MetricsService::InitializeMetricsState() {
   IncrementLongPrefsValue(prefs::kUninstallLaunchCount);
 }
 
-void MetricsService::OnUserAction(const std::string& action) {
-  log_manager_.current_log()->RecordUserAction(action);
+void MetricsService::OnUserAction(const std::string& action,
+                                  base::TimeTicks action_time) {
+  log_manager_.current_log()->RecordUserAction(action, action_time);
   HandleIdleSinceLastTransmission(false);
 }
 

components/metrics/metrics_service.h

@@ -236,7 +236,7 @@ class MetricsService : public base::HistogramFlattener {
   // state should be INIT_TASK_SCHEDULED.
   void FinishedInitTask();
 
-  void OnUserAction(const std::string& action);
+  void OnUserAction(const std::string& action, base::TimeTicks action_time);
 
   // Get the amount of uptime since this process started and since the last
   // call to this function.  Also updates the cumulative uptime metric (stored

ios/chrome/browser/crash_report/breadcrumbs/application_breadcrumbs_logger.h

@@ -10,6 +10,10 @@
 #include "base/memory/memory_pressure_listener.h"
 #include "base/metrics/user_metrics.h"
 
+namespace base {
+class TimeTicks;
+}  // namespace base
+
 class BreadcrumbManager;
 
 // Listens for and logs application wide breadcrumb events to the
@@ -24,7 +28,7 @@ class ApplicationBreadcrumbsLogger {
 
   // Callback which processes and logs the user action |action| to
   // |breadcrumb_manager_|.
-  void OnUserAction(const std::string& action);
+  void OnUserAction(const std::string& action, base::TimeTicks action_time);
 
   // Callback which processes and logs memory pressure warnings to
   // |breadcrumb_manager_|.

ios/chrome/browser/crash_report/breadcrumbs/application_breadcrumbs_logger.mm

@@ -32,7 +32,8 @@ ApplicationBreadcrumbsLogger::~ApplicationBreadcrumbsLogger() {
   breakpad::StopMonitoringBreadcrumbManager(breadcrumb_manager_);
 }
 
-void ApplicationBreadcrumbsLogger::OnUserAction(const std::string& action) {
+void ApplicationBreadcrumbsLogger::OnUserAction(const std::string& action,
+                                                base::TimeTicks action_time) {
   // Filter out unwanted actions.
   if (action.find("InProductHelp.") == 0) {
     // InProductHelp actions are very noisy.

ios/chrome/browser/metrics/first_user_action_recorder.cc

@@ -123,8 +123,9 @@ void FirstUserActionRecorder::RecordStartOnNTP() {
   RecordAction(START_ON_NTP, log_message);
 }
 
-void FirstUserActionRecorder::OnUserAction(const std::string& action_name) {
-  if (ShouldProcessAction(action_name)) {
+void FirstUserActionRecorder::OnUserAction(const std::string& action_name,
+                                           base::TimeTicks action_time) {
+  if (ShouldProcessAction(action_name, action_time)) {
     if (ArrayContainsString(kNewTaskActions, base::size(kNewTaskActions),
                             action_name.c_str())) {
       std::string log_message = base::StringPrintf(
@@ -181,7 +182,8 @@ void FirstUserActionRecorder::RecordAction(
 }
 
 bool FirstUserActionRecorder::ShouldProcessAction(
-    const std::string& action_name) {
+    const std::string& action_name,
+    base::TimeTicks action_time) {
   if (recorded_action_)
     return false;
 
@@ -190,7 +192,7 @@ bool FirstUserActionRecorder::ShouldProcessAction(
                           action_name.c_str())) {
     rethrow_callback_.Reset(
         base::BindOnce(&FirstUserActionRecorder::OnUserAction,
-                       base::Unretained(this), action_name));
+                       base::Unretained(this), action_name, action_time));
     base::ThreadTaskRunnerHandle::Get()->PostTask(FROM_HERE,
                                                   rethrow_callback_.callback());
     action_pending_ = true;

ios/chrome/browser/metrics/first_user_action_recorder.h

@@ -57,7 +57,8 @@ class FirstUserActionRecorder {
  private:
   // Records metrics if |action_name| indicates the start of a new task or the
   // continuation of an existing task.
-  void OnUserAction(const std::string& action_name);
+  void OnUserAction(const std::string& action_name,
+                    base::TimeTicks action_time);
 
   // Records the appropriate metrics for the given action type.
   void RecordAction(const FirstUserActionType& action_type,
@@ -65,7 +66,8 @@ class FirstUserActionRecorder {
 
   // Returns true if the specified action should be processed, or false if the
   // action should be ignored.
-  bool ShouldProcessAction(const std::string& action_name);
+  bool ShouldProcessAction(const std::string& action_name,
+                           base::TimeTicks action_time);
 
   // Returns true if the given array contains the given string.
   bool ArrayContainsString(const char* to_search[],

ios/chrome/browser/ui/ntp/notification_promo_whats_new_unittest.mm

@@ -106,7 +106,8 @@ class NotificationPromoWhatsNewTest : public PlatformTest {
       EXPECT_EQ(icon, promo_.icon());
   }
 
-  void OnUserAction(const std::string& user_action) {
+  void OnUserAction(const std::string& user_action,
+                    base::TimeTicks action_time) {
     user_action_count_map_[user_action]++;
   }
 

ios/chrome/browser/ui/webui/user_actions_handler.h

@@ -9,6 +9,10 @@
 #include "base/metrics/user_metrics.h"
 #include "ios/web/public/webui/web_ui_ios_message_handler.h"
 
+namespace base {
+class TimeTicks;
+}  // namespace base
+
 // UI Handler for chrome://user-actions/
 // It listens to user action notifications and passes those notifications
 // into the Javascript to update the page.
@@ -22,7 +26,7 @@ class UserActionsHandler : public web::WebUIIOSMessageHandler {
 
  private:
   // Called whenever a user action is registered.
-  void OnUserAction(const std::string& action);
+  void OnUserAction(const std::string& action, base::TimeTicks action_time);
 
   // The callback to invoke whenever a user action is registered.
   base::ActionCallback action_callback_;

ios/chrome/browser/ui/webui/user_actions_handler.mm

@@ -25,7 +25,8 @@ UserActionsHandler::~UserActionsHandler() {
 
 void UserActionsHandler::RegisterMessages() {}
 
-void UserActionsHandler::OnUserAction(const std::string& action) {
+void UserActionsHandler::OnUserAction(const std::string& action,
+                                      base::TimeTicks action_time) {
   base::Value user_action_name(action);
   std::vector<const base::Value*> args{&user_action_name};
   web_ui()->CallJavascriptFunction("userActions.observeUserAction", args);

services/tracing/public/cpp/perfetto/trace_event_data_source.cc

@@ -992,7 +992,8 @@ void TraceEventDataSource::OnMetricsSampleCallback(
 }
 
 void TraceEventDataSource::OnUserActionSampleCallback(
-    const std::string& action) {
+    const std::string& action,
+    base::TimeTicks action_time) {
   TRACE_EVENT_INSTANT(
       TRACE_DISABLED_BY_DEFAULT("user_action_samples"), "UserAction",
       TRACE_EVENT_SCOPE_GLOBAL, [&](perfetto::EventContext ctx) {

services/tracing/public/cpp/perfetto/trace_event_data_source.h

@@ -215,7 +215,8 @@ class COMPONENT_EXPORT(TRACING_CPP) TraceEventDataSource
 
   // Registered as a callback to receive every action recorded using
   // base::RecordAction(), when tracing is enabled with a histogram category.
-  static void OnUserActionSampleCallback(const std::string& action);
+  static void OnUserActionSampleCallback(const std::string& action,
+                                         base::TimeTicks action_time);
 
  private:
   friend class base::NoDestructor<TraceEventDataSource>;