Add UMA histograms to track very brief or frequent tabs and JS dialogs.

Review URL: https://codereview.chromium.org/1638013002

Cr-Commit-Position: refs/heads/master@{#374262}

7 files changed, 150 insertions, 10 deletions

diff --git a/chrome/browser/ui/tabs/tab_strip_model_stats_recorder.cc b/chrome/browser/ui/tabs/tab_strip_model_stats_recorder.cc
index 5db6a72..f96f18e 100644
--- a/chrome/browser/ui/tabs/tab_strip_model_stats_recorder.cc
+++ b/chrome/browser/ui/tabs/tab_strip_model_stats_recorder.cc
@@ -10,6 +10,7 @@
 #include "base/logging.h"
 #include "base/metrics/histogram_macros.h"
 #include "base/supports_user_data.h"
+#include "base/time/time.h"
 #include "chrome/browser/ui/browser.h"
 #include "chrome/browser/ui/browser_list.h"
 #include "chrome/browser/ui/tabs/tab_strip_model.h"
@@ -41,9 +42,12 @@ class TabStripModelStatsRecorder::TabInfo
     return info;
   }
 
+  base::TimeTicks creation_time() const { return creation_time_; }
+
  private:
   TabState current_state_ = TabState::INITIAL;
   base::TimeTicks last_state_modified_;
+  base::TimeTicks creation_time_ = base::TimeTicks::Now();
 
   static const char kKey[];
 };
@@ -101,6 +105,13 @@ void TabStripModelStatsRecorder::TabInfo::UpdateState(TabState new_state) {
       NOTREACHED();
       break;
   }
+
+  if (new_state == TabState::CLOSED) {
+    UMA_HISTOGRAM_MEDIUM_TIMES(
+        "Tabs.FineTiming.TimeBetweenTabCreatedAndSameTabClosed",
+        now - creation_time_);
+  }
+
   last_state_modified_ = now;
   current_state_ = new_state;
 }
@@ -109,6 +120,7 @@ void TabStripModelStatsRecorder::TabClosingAt(TabStripModel*,
                                               content::WebContents* contents,
                                               int index) {
   TabInfo::Get(contents)->UpdateState(TabState::CLOSED);
+  last_close_time_ = base::TimeTicks::Now();
 
   // Avoid having stale pointer in active_tab_history_
   std::replace(active_tab_history_.begin(), active_tab_history_.end(), contents,
@@ -131,6 +143,25 @@ void TabStripModelStatsRecorder::ActiveTabChanged(
   DCHECK(new_contents);
   TabInfo* tab_info = TabInfo::Get(new_contents);
 
+  if (tab_info->state() == TabState::INITIAL) {
+    // A new tab has been created: log the time since the last one was created.
+    if (!last_creation_time_.is_null()) {
+      UMA_HISTOGRAM_MEDIUM_TIMES(
+          "Tabs.FineTiming.TimeBetweenTabCreatedAndNextTabCreated",
+          tab_info->creation_time() - last_creation_time_);
+    }
+    last_creation_time_ = tab_info->creation_time();
+
+    // Also log the time since a tab was closed, but only if this is the first
+    // tab that was opened since the closing.
+    if (!last_close_time_.is_null()) {
+      UMA_HISTOGRAM_MEDIUM_TIMES(
+          "Tabs.FineTiming.TimeBetweenTabClosedAndNextTabCreated",
+          tab_info->creation_time() - last_close_time_);
+      last_close_time_ = base::TimeTicks();
+    }
+  }
+
   bool was_inactive = tab_info->state() == TabState::INACTIVE;
   tab_info->UpdateState(TabState::ACTIVE);
 
diff --git a/chrome/browser/ui/tabs/tab_strip_model_stats_recorder.h b/chrome/browser/ui/tabs/tab_strip_model_stats_recorder.h
index fbb980d..060433e 100644
--- a/chrome/browser/ui/tabs/tab_strip_model_stats_recorder.h
+++ b/chrome/browser/ui/tabs/tab_strip_model_stats_recorder.h
@@ -8,6 +8,7 @@
 #include <vector>
 
 #include "base/macros.h"
+#include "base/time/time.h"
 #include "chrome/browser/ui/browser_tab_strip_tracker.h"
 #include "chrome/browser/ui/tabs/tab_strip_model_observer.h"
 
@@ -67,6 +68,12 @@ class TabStripModelStatsRecorder : public TabStripModelObserver {
 
   BrowserTabStripTracker browser_tab_strip_tracker_;
 
+  // Record a single create and close timestamp to track the time between tab
+  // creation. (Tabs actually are not opened in a strict sequence so these
+  // timestamps are not accurate, but they'll suffice for an estimate.)
+  base::TimeTicks last_creation_time_;
+  base::TimeTicks last_close_time_;
+
   DISALLOW_COPY_AND_ASSIGN(TabStripModelStatsRecorder);
 };
 
diff --git a/components/app_modal/javascript_app_modal_dialog.cc b/components/app_modal/javascript_app_modal_dialog.cc
index d2cc903..efce144 100644
--- a/components/app_modal/javascript_app_modal_dialog.cc
+++ b/components/app_modal/javascript_app_modal_dialog.cc
@@ -4,6 +4,8 @@
 
 #include "components/app_modal/javascript_app_modal_dialog.h"
 
+#include "base/metrics/histogram_macros.h"
+#include "base/time/time.h"
 #include "build/build_config.h"
 #include "components/app_modal/javascript_dialog_manager.h"
 #include "components/app_modal/javascript_native_dialog_factory.h"
@@ -72,7 +74,8 @@ JavaScriptAppModalDialog::JavaScriptAppModalDialog(
       is_before_unload_dialog_(is_before_unload_dialog),
       is_reload_(is_reload),
       callback_(callback),
-      use_override_prompt_text_(false) {
+      use_override_prompt_text_(false),
+      creation_time_(base::TimeTicks::Now()) {
   EnforceMaxTextSize(message_text, &message_text_);
   EnforceMaxPromptSize(default_prompt_text, &default_prompt_text_);
 }
@@ -95,10 +98,7 @@ void JavaScriptAppModalDialog::Invalidate() {
     return;
 
   AppModalDialog::Invalidate();
-  if (!callback_.is_null()) {
-    callback_.Run(false, base::string16());
-    callback_.Reset();
-  }
+  CallDialogClosedCallback(false, base::string16());
   if (native_dialog())
     CloseModalDialog();
 }
@@ -142,12 +142,9 @@ void JavaScriptAppModalDialog::NotifyDelegate(bool success,
   if (!IsValid())
     return;
 
-  if (!callback_.is_null()) {
-    callback_.Run(success, user_input);
-    callback_.Reset();
-  }
+  CallDialogClosedCallback(success, user_input);
 
-  // The callback_ above may delete web_contents_, thus removing the extra
+  // The close callback above may delete web_contents_, thus removing the extra
   // data from the map owned by ::JavaScriptDialogManager. Make sure
   // to only use the data if still present. http://crbug.com/236476
   ExtraDataMap::iterator extra_data =
@@ -162,6 +159,20 @@ void JavaScriptAppModalDialog::NotifyDelegate(bool success,
   AppModalDialog::Invalidate();
 }
 
+void JavaScriptAppModalDialog::CallDialogClosedCallback(bool success,
+    const base::string16& user_input) {
+  // TODO(joenotcharles): Both the callers of this function also check IsValid
+  // and call AppModalDialog::Invalidate, but in different orders. If the
+  // difference is not significant, more common code could be moved here.
+  UMA_HISTOGRAM_MEDIUM_TIMES(
+      "JSDialogs.FineTiming.TimeBetweenDialogCreatedAndSameDialogClosed",
+      base::TimeTicks::Now() - creation_time_);
+  if (!callback_.is_null()) {
+    callback_.Run(success, user_input);
+    callback_.Reset();
+  }
+}
+
 // static
 std::string JavaScriptAppModalDialog::GetSerializedOriginForWebContents(
     content::WebContents* contents) {
diff --git a/components/app_modal/javascript_app_modal_dialog.h b/components/app_modal/javascript_app_modal_dialog.h
index 5c81ef7..111ba7d 100644
--- a/components/app_modal/javascript_app_modal_dialog.h
+++ b/components/app_modal/javascript_app_modal_dialog.h
@@ -10,6 +10,7 @@
 
 #include "base/compiler_specific.h"
 #include "base/macros.h"
+#include "base/time/time.h"
 #include "components/app_modal/app_modal_dialog.h"
 #include "content/public/browser/javascript_dialog_manager.h"
 
@@ -83,6 +84,9 @@ class JavaScriptAppModalDialog : public AppModalDialog {
   void NotifyDelegate(bool success, const base::string16& prompt_text,
                       bool suppress_js_messages);
 
+  void CallDialogClosedCallback(bool success,
+                                const base::string16& prompt_text);
+
   // A map of extra Chrome-only data associated with the delegate_. The keys
   // come from |GetSerializedOriginForWebContents|.
   ExtraDataMap* extra_data_map_;
@@ -102,6 +106,8 @@ class JavaScriptAppModalDialog : public AppModalDialog {
   base::string16 override_prompt_text_;
   bool use_override_prompt_text_;
 
+  base::TimeTicks creation_time_;
+
   DISALLOW_COPY_AND_ASSIGN(JavaScriptAppModalDialog);
 };
 
diff --git a/components/app_modal/javascript_dialog_manager.cc b/components/app_modal/javascript_dialog_manager.cc
index a0a08e6..f654f8bf3 100644
--- a/components/app_modal/javascript_dialog_manager.cc
+++ b/components/app_modal/javascript_dialog_manager.cc
@@ -9,6 +9,7 @@
 #include "base/bind.h"
 #include "base/i18n/rtl.h"
 #include "base/macros.h"
+#include "base/metrics/histogram_macros.h"
 #include "base/strings/utf_string_conversions.h"
 #include "components/app_modal/app_modal_dialog.h"
 #include "components/app_modal/app_modal_dialog_queue.h"
@@ -107,6 +108,25 @@ void JavaScriptDialogManager::RunJavaScriptDialog(
     return;
   }
 
+  base::TimeTicks now = base::TimeTicks::Now();
+  if (!last_creation_time_.is_null()) {
+    // A new dialog has been created: log the time since the last one was
+    // created.
+    UMA_HISTOGRAM_MEDIUM_TIMES(
+        "JSDialogs.FineTiming.TimeBetweenDialogCreatedAndNextDialogCreated",
+        now - last_creation_time_);
+  }
+  last_creation_time_ = now;
+
+  // Also log the time since a dialog was closed, but only if this is the first
+  // dialog that was opened since the closing.
+  if (!last_close_time_.is_null()) {
+    UMA_HISTOGRAM_MEDIUM_TIMES(
+        "JSDialogs.FineTiming.TimeBetweenDialogClosedAndNextDialogCreated",
+        now - last_close_time_);
+    last_close_time_ = base::TimeTicks();
+  }
+
   bool is_alert = message_type == content::JAVASCRIPT_MESSAGE_TYPE_ALERT;
   base::string16 dialog_title =
       GetTitle(web_contents, origin_url, accept_lang, is_alert);
@@ -261,6 +281,8 @@ void JavaScriptDialogManager::OnDialogClosed(
   // their WebContents is destroyed so |web_contents| is still valid here.)
   extensions_client_->OnDialogClosed(web_contents);
 
+  last_close_time_ = base::TimeTicks::Now();
+
   callback.Run(success, user_input);
 }
 
diff --git a/components/app_modal/javascript_dialog_manager.h b/components/app_modal/javascript_dialog_manager.h
index b204aaf8..9d70bd3 100644
--- a/components/app_modal/javascript_dialog_manager.h
+++ b/components/app_modal/javascript_dialog_manager.h
@@ -8,6 +8,7 @@
 #include "base/macros.h"
 #include "base/memory/scoped_ptr.h"
 #include "base/memory/singleton.h"
+#include "base/time/time.h"
 #include "components/app_modal/javascript_app_modal_dialog.h"
 #include "content/public/browser/javascript_dialog_manager.h"
 
@@ -80,6 +81,11 @@ class JavaScriptDialogManager : public content::JavaScriptDialogManager {
   scoped_ptr<JavaScriptNativeDialogFactory> native_dialog_factory_;
   scoped_ptr<JavaScriptDialogExtensionsClient> extensions_client_;
 
+  // Record a single create and close timestamp to track the time between
+  // dialogs. (Since Javascript dialogs are modal, this is even accurate!)
+  base::TimeTicks last_close_time_;
+  base::TimeTicks last_creation_time_;
+
   DISALLOW_COPY_AND_ASSIGN(JavaScriptDialogManager);
 };
 
diff --git a/tools/metrics/histograms/histograms.xml b/tools/metrics/histograms/histograms.xml
index c4e6fc5..7ed6c32 100644
--- a/tools/metrics/histograms/histograms.xml
+++ b/tools/metrics/histograms/histograms.xml
@@ -17683,6 +17683,36 @@ http://cs/file:chrome/histograms.xml - but prefer this file for new entries.
   </summary>
 </histogram>
 
+<histogram
+    name="JSDialogs.FineTiming.TimeBetweenDialogClosedAndNextDialogCreated"
+    units="ms">
+  <owner>joenotcharles@chromium.org</owner>
+  <summary>
+    Fine-grained (in msec) time between closing a Javascript dialog and opening
+    another, to track very frequent dialogs.
+  </summary>
+</histogram>
+
+<histogram
+    name="JSDialogs.FineTiming.TimeBetweenDialogCreatedAndNextDialogCreated"
+    units="ms">
+  <owner>joenotcharles@chromium.org</owner>
+  <summary>
+    Fine-grained (in msec) time between opening a Javascript dialog and opening
+    another, to track very frequent dialogs.
+  </summary>
+</histogram>
+
+<histogram
+    name="JSDialogs.FineTiming.TimeBetweenDialogCreatedAndSameDialogClosed"
+    units="ms">
+  <owner>joenotcharles@chromium.org</owner>
+  <summary>
+    Fine-grained (in msec) time between opening a Javascript dialog and closing
+    it, to track very short-lived dialogs.
+  </summary>
+</histogram>
+
 <histogram name="Keyboard.KeystrokeDeltas" units="ms">
   <owner>Please list the metric's owners. Add more owner tags as needed.</owner>
   <summary>
@@ -51016,6 +51046,33 @@ http://cs/file:chrome/histograms.xml - but prefer this file for new entries.
   </summary>
 </histogram>
 
+<histogram name="Tabs.FineTiming.TimeBetweenTabClosedAndNextTabCreated"
+    units="ms">
+  <owner>joenotcharles@chromium.org</owner>
+  <summary>
+    Fine-grained (in msec) time between closing a tab and opening another, to
+    track very frequent tabs.
+  </summary>
+</histogram>
+
+<histogram name="Tabs.FineTiming.TimeBetweenTabCreatedAndNextTabCreated"
+    units="ms">
+  <owner>joenotcharles@chromium.org</owner>
+  <summary>
+    Fine-grained (in msec) time between opening a tab and opening another, to
+    track very frequent tabs.
+  </summary>
+</histogram>
+
+<histogram name="Tabs.FineTiming.TimeBetweenTabCreatedAndSameTabClosed"
+    units="ms">
+  <owner>joenotcharles@chromium.org</owner>
+  <summary>
+    Fine-grained (in msec) time between opening a tab and closing it, to track
+    very short-lived tabs.
+  </summary>
+</histogram>
+
 <histogram name="Tabs.ForegroundTabAgeAtStartup" units="minutes">
   <owner>lliabraa@chromium.org</owner>
   <summary>