chromeos: Add UMA metrics for keyboard shortcut viewer startup time

This will measure the time from Ctrl-Shift-/ keystroke to dialog show.
This CL works with the non-mojo-app shortcut viewer we're using today.
When we switch to the app version we'll need to pass the keystroke
time over mojo to the app, perhaps via a Toggle() method. Adding the
mojo Toggle() interface is tracked in crbug.com/847615

Metric is Keyboard.ShortcutViewer.StartupTime

Bug: 847615, 847613
Test: added to ash_unittests, manually checked chrome://histograms
Change-Id: I425f44d0b71543f225d73857365d050be0e1b446
Reviewed-on: https://chromium-review.googlesource.com/1087779
Commit-Queue: James Cook <jamescook@chromium.org>
Reviewed-by: Ilya Sherman <isherman@chromium.org>
Reviewed-by: Tao Wu <wutao@chromium.org>
Cr-Commit-Position: refs/heads/master@{#564952}

ash/components/shortcut_viewer/BUILD.gn

@@ -63,6 +63,7 @@ source_set("unit_tests") {
   deps = [
     ":lib",
     "//ash:test_support_without_content",
+    "//base/test:test_support",
     "//services/ui/public/cpp/input_devices:test_support",
     "//testing/gtest",
     "//ui/events:test_support",

ash/components/shortcut_viewer/shortcut_viewer_application.cc

@@ -6,6 +6,7 @@
 
 #include "ash/components/shortcut_viewer/last_window_closed_observer.h"
 #include "ash/components/shortcut_viewer/views/keyboard_shortcut_view.h"
+#include "base/time/time.h"
 #include "base/trace_event/trace_event.h"
 #include "services/service_manager/public/cpp/connector.h"
 #include "services/service_manager/public/cpp/service_context.h"
@@ -23,6 +24,11 @@ void ShortcutViewerApplication::RegisterForTraceEvents() {
 }
 
 void ShortcutViewerApplication::OnStart() {
+  // TODO(jamescook): Pass the time of the accelerator keypress via a mojo
+  // Show() method so this time can be used to measure end-to-end startup time.
+  // https://crbug.com/847615
+  user_gesture_time_ = base::TimeTicks::Now();
+
   aura_init_ = views::AuraInit::Create(
       context()->connector(), context()->identity(), "views_mus_resources.pak",
       std::string(), nullptr, views::AuraInit::Mode::AURA_MUS2,
@@ -40,7 +46,7 @@ void ShortcutViewerApplication::OnStart() {
   // InputDeviceClient. If the device list is incomplete, wait for it to load.
   DCHECK(ui::InputDeviceManager::HasInstance());
   if (ui::InputDeviceManager::GetInstance()->AreDeviceListsComplete()) {
-    KeyboardShortcutView::Toggle();
+    KeyboardShortcutView::Toggle(user_gesture_time_);
   } else {
     ui::InputDeviceManager::GetInstance()->AddObserver(this);
   }
@@ -48,7 +54,7 @@ void ShortcutViewerApplication::OnStart() {
 
 void ShortcutViewerApplication::OnDeviceListsComplete() {
   ui::InputDeviceManager::GetInstance()->RemoveObserver(this);
-  KeyboardShortcutView::Toggle();
+  KeyboardShortcutView::Toggle(user_gesture_time_);
 }
 
 }  // namespace keyboard_shortcut_viewer

ash/components/shortcut_viewer/shortcut_viewer_application.h

@@ -8,6 +8,7 @@
 #include <memory>
 
 #include "base/macros.h"
+#include "base/time/time.h"
 #include "services/service_manager/public/cpp/service.h"
 #include "ui/events/devices/input_device_event_observer.h"
 
@@ -38,6 +39,10 @@ class ShortcutViewerApplication : public service_manager::Service,
   // ui::InputDeviceEventObserver:
   void OnDeviceListsComplete() override;
 
+  // Timestamp of the user gesture (e.g. Ctrl-Shift-/ keystroke) that triggered
+  // showing the window. Used for metrics.
+  base::TimeTicks user_gesture_time_;
+
   std::unique_ptr<views::AuraInit> aura_init_;
   std::unique_ptr<LastWindowClosedObserver> last_window_closed_observer_;
 

ash/components/shortcut_viewer/views/keyboard_shortcut_view.cc

@@ -18,9 +18,11 @@
 #include "ash/public/cpp/window_properties.h"
 #include "base/bind.h"
 #include "base/i18n/string_search.h"
+#include "base/metrics/histogram_macros.h"
 #include "base/metrics/user_metrics.h"
 #include "base/metrics/user_metrics_action.h"
 #include "base/strings/string_number_conversions.h"
+#include "base/time/time.h"
 #include "base/trace_event/trace_event.h"
 #include "ui/aura/client/aura_constants.h"
 #include "ui/aura/window.h"
@@ -96,7 +98,7 @@ KeyboardShortcutView::~KeyboardShortcutView() {
 }
 
 // static
-views::Widget* KeyboardShortcutView::Toggle() {
+views::Widget* KeyboardShortcutView::Toggle(base::TimeTicks start_time) {
   if (g_ksv_view) {
     if (g_ksv_view->GetWidget()->IsActive())
       g_ksv_view->GetWidget()->Close();
@@ -144,6 +146,9 @@ views::Widget* KeyboardShortcutView::Toggle() {
 
     g_ksv_view->GetWidget()->Show();
     g_ksv_view->search_box_view_->search_box()->RequestFocus();
+
+    UMA_HISTOGRAM_TIMES("Keyboard.ShortcutViewer.StartupTime",
+                        base::TimeTicks::Now() - start_time);
   }
   return g_ksv_view->GetWidget();
 }

ash/components/shortcut_viewer/views/keyboard_shortcut_view.h

@@ -14,6 +14,10 @@
 #include "ui/chromeos/search_box/search_box_view_delegate.h"
 #include "ui/views/widget/widget_delegate.h"
 
+namespace base {
+class TimeTicks;
+}
+
 namespace views {
 class TabbedPane;
 class Widget;
@@ -35,7 +39,9 @@ class KeyboardShortcutView : public views::WidgetDelegateView,
   // 1. Show the window if it is not open.
   // 2. Activate the window if it is open but not active.
   // 3. Close the window if it is open and active.
-  static views::Widget* Toggle();
+  // |start_time| is the time of the user gesture that caused the window to
+  // show. Used for metrics.
+  static views::Widget* Toggle(base::TimeTicks start_time);
 
   // views::View:
   bool AcceleratorPressed(const ui::Accelerator& accelerator) override;

ash/components/shortcut_viewer/views/keyboard_shortcut_view_unittest.cc

@@ -10,6 +10,7 @@
 #include "ash/components/shortcut_viewer/views/keyboard_shortcut_item_view.h"
 #include "ash/components/shortcut_viewer/views/ksv_search_box_view.h"
 #include "ash/test/ash_test_base.h"
+#include "base/test/metrics/histogram_tester.h"
 #include "services/ui/public/cpp/input_devices/input_device_client_test_api.h"
 #include "testing/gtest/include/gtest/gtest.h"
 #include "ui/aura/window.h"
@@ -64,6 +65,8 @@ class KeyboardShortcutViewTest : public ash::AshTestBase {
     }
   }
 
+  base::HistogramTester histograms_;
+
  private:
   KeyboardShortcutView* GetView() const {
     return KeyboardShortcutView::GetInstanceForTesting();
@@ -75,17 +78,23 @@ class KeyboardShortcutViewTest : public ash::AshTestBase {
 // Shows and closes the widget for KeyboardShortcutViewer.
 TEST_F(KeyboardShortcutViewTest, ShowAndClose) {
   // Show the widget.
-  views::Widget* widget = KeyboardShortcutView::Toggle();
+  views::Widget* widget = KeyboardShortcutView::Toggle(base::TimeTicks());
   EXPECT_TRUE(widget);
 
   // Cleaning up.
   widget->CloseNow();
 }
 
+TEST_F(KeyboardShortcutViewTest, StartupTimeHistogram) {
+  views::Widget* widget = KeyboardShortcutView::Toggle(base::TimeTicks());
+  histograms_.ExpectTotalCount("Keyboard.ShortcutViewer.StartupTime", 1);
+  widget->CloseNow();
+}
+
 // KeyboardShortcutViewer window should be centered in screen.
 TEST_F(KeyboardShortcutViewTest, CenterWindowInScreen) {
   // Show the widget.
-  views::Widget* widget = KeyboardShortcutView::Toggle();
+  views::Widget* widget = KeyboardShortcutView::Toggle(base::TimeTicks());
   EXPECT_TRUE(widget);
 
   gfx::Rect root_window_bounds =
@@ -106,7 +115,7 @@ TEST_F(KeyboardShortcutViewTest, CenterWindowInScreen) {
 // Test that the number of side tabs equals to the number of categories.
 TEST_F(KeyboardShortcutViewTest, SideTabsCount) {
   // Show the widget.
-  views::Widget* widget = KeyboardShortcutView::Toggle();
+  views::Widget* widget = KeyboardShortcutView::Toggle(base::TimeTicks());
 
   int category_number = 0;
   ShortcutCategory current_category = ShortcutCategory::kUnknown;
@@ -127,7 +136,7 @@ TEST_F(KeyboardShortcutViewTest, SideTabsCount) {
 // Test that the top line in two views should be center aligned.
 TEST_F(KeyboardShortcutViewTest, TopLineCenterAlignedInItemView) {
   // Show the widget.
-  views::Widget* widget = KeyboardShortcutView::Toggle();
+  views::Widget* widget = KeyboardShortcutView::Toggle(base::TimeTicks());
 
   for (const auto& item_view : GetShortcutViews()) {
     DCHECK(item_view->child_count() == 2);
@@ -152,7 +161,7 @@ TEST_F(KeyboardShortcutViewTest, TopLineCenterAlignedInItemView) {
 // Test that the focus is on search box when window inits and exits search mode.
 TEST_F(KeyboardShortcutViewTest, FocusOnSearchBox) {
   // Show the widget.
-  views::Widget* widget = KeyboardShortcutView::Toggle();
+  views::Widget* widget = KeyboardShortcutView::Toggle(base::TimeTicks());
 
   // Case 1: when window creates. The focus should be on search box.
   EXPECT_TRUE(GetSearchBoxView()->search_box()->HasFocus());
@@ -189,7 +198,7 @@ TEST_F(KeyboardShortcutViewTest, FocusOnSearchBox) {
 // Test that the window can be closed by accelerator.
 TEST_F(KeyboardShortcutViewTest, CloseWindowByAccelerator) {
   // Show the widget.
-  views::Widget* widget = KeyboardShortcutView::Toggle();
+  views::Widget* widget = KeyboardShortcutView::Toggle(base::TimeTicks());
   EXPECT_FALSE(widget->IsClosed());
 
   ui::test::EventGenerator& event_generator = GetEventGenerator();
@@ -200,18 +209,18 @@ TEST_F(KeyboardShortcutViewTest, CloseWindowByAccelerator) {
 // Test that the window can be activated or closed by toggling.
 TEST_F(KeyboardShortcutViewTest, ToggleWindow) {
   // Show the widget.
-  views::Widget* widget = KeyboardShortcutView::Toggle();
+  views::Widget* widget = KeyboardShortcutView::Toggle(base::TimeTicks());
   EXPECT_FALSE(widget->IsClosed());
 
   // Call |Toggle()| to activate the inactive widget.
   EXPECT_TRUE(widget->IsActive());
   widget->Deactivate();
   EXPECT_FALSE(widget->IsActive());
-  KeyboardShortcutView::Toggle();
+  KeyboardShortcutView::Toggle(base::TimeTicks());
   EXPECT_TRUE(widget->IsActive());
 
   // Call |Toggle()| to close the active widget.
-  KeyboardShortcutView::Toggle();
+  KeyboardShortcutView::Toggle(base::TimeTicks());
   EXPECT_TRUE(widget->IsClosed());
 }
 

chrome/browser/ui/ash/ksv/keyboard_shortcut_viewer_util.cc

@@ -8,19 +8,22 @@
 #include "ash/components/shortcut_viewer/views/keyboard_shortcut_view.h"
 #include "ash/public/cpp/ash_switches.h"
 #include "base/command_line.h"
+#include "base/time/time.h"
 #include "content/public/common/service_manager_connection.h"
 #include "services/service_manager/public/cpp/connector.h"
 
 namespace keyboard_shortcut_viewer_util {
 
 void ShowKeyboardShortcutViewer() {
+  base::TimeTicks user_gesture_time = base::TimeTicks::Now();
   if (base::CommandLine::ForCurrentProcess()->HasSwitch(
           ash::switches::kKeyboardShortcutViewerApp)) {
     service_manager::Connector* connector =
         content::ServiceManagerConnection::GetForProcess()->GetConnector();
+    // TODO(jamescook): Pass |user_gesture_time| via a mojo Show() method.
     connector->StartService(shortcut_viewer::mojom::kServiceName);
   } else {
-    keyboard_shortcut_viewer::KeyboardShortcutView::Toggle();
+    keyboard_shortcut_viewer::KeyboardShortcutView::Toggle(user_gesture_time);
   }
 }
 

tools/metrics/histograms/histograms.xml

@@ -35782,6 +35782,17 @@ uploading your change for review.
   </summary>
 </histogram>
 
+<histogram name="Keyboard.ShortcutViewer.StartupTime" units="ms">
+  <owner>jamescook@chromium.org</owner>
+  <owner>msw@chromium.org</owner>
+  <owner>wutao@chromium.org</owner>
+  <summary>
+    Time delay between the user gesture that triggered the keyboard shortcut
+    viewer dialog (e.g. pressing Ctrl-Alt-/) and the dialog widget being shown,
+    including layout time for the views::Views.
+  </summary>
+</histogram>
+
 <histogram name="Kiosk.Launch.CryptohomeFailure" enum="LoginFailureReason">
   <owner>xiyuan@chromium.org</owner>
   <summary>Tracks cryptohome failure during kiosk launch.</summary>