Instrument some of the exit paths likely to suffer hangs.

This is temporary instrumentation to try and narrow down the area
and mode where Chrome is (likely) hanging on logoff/restart.

TBR=mpearson@chromium.org,erikwright@chromium.org

BUG=412384

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

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

chrome/browser/background/background_mode_manager.cc

@@ -53,6 +53,10 @@
 #include "ui/base/l10n/l10n_util.h"
 #include "ui/base/resource/resource_bundle.h"
 
+#if defined(OS_WIN)
+#include "components/browser_watcher/exit_funnel_win.h"
+#endif
+
 using base::UserMetricsAction;
 using extensions::Extension;
 using extensions::UpdatedExtensionPermissionsInfo;
@@ -532,6 +536,10 @@ void BackgroundModeManager::ExecuteCommand(int command_id, int event_flags) {
       }
       break;
     case IDC_EXIT:
+#if defined(OS_WIN)
+      browser_watcher::ExitFunnel::RecordSingleEvent(
+            chrome::kBrowserExitCodesRegistryPath, L"TraybarExit");
+#endif
       content::RecordAction(UserMetricsAction("Exit"));
       chrome::CloseAllBrowsers();
       break;
@@ -638,6 +646,11 @@ void BackgroundModeManager::UpdateKeepAliveAndTrayIcon() {
     if (!keeping_alive_) {
       keeping_alive_ = true;
       chrome::IncrementKeepAliveCount();
+
+#if defined(OS_WIN)
+      browser_watcher::ExitFunnel::RecordSingleEvent(
+            chrome::kBrowserExitCodesRegistryPath, L"BackgroundOn");
+#endif
     }
     CreateStatusTrayIcon();
     return;
@@ -647,6 +660,11 @@ void BackgroundModeManager::UpdateKeepAliveAndTrayIcon() {
   if (keeping_alive_) {
     keeping_alive_ = false;
     chrome::DecrementKeepAliveCount();
+
+#if defined(OS_WIN)
+    browser_watcher::ExitFunnel::RecordSingleEvent(
+          chrome::kBrowserExitCodesRegistryPath, L"BackgroundOff");
+#endif
   }
 }
 

chrome/browser/lifetime/application_lifetime.cc

@@ -31,6 +31,7 @@
 #include "chrome/browser/ui/browser_window.h"
 #include "chrome/browser/ui/tabs/tab_strip_model.h"
 #include "chrome/browser/ui/user_manager.h"
+#include "chrome/common/chrome_constants.h"
 #include "chrome/common/chrome_switches.h"
 #include "chrome/common/pref_names.h"
 #include "content/public/browser/browser_shutdown.h"
@@ -48,6 +49,7 @@
 
 #if defined(OS_WIN)
 #include "base/win/win_util.h"
+#include "components/browser_watcher/exit_funnel_win.h"
 #endif
 
 namespace chrome {
@@ -251,6 +253,12 @@ void ExitCleanly() {
 #endif
 
 void SessionEnding() {
+#if defined(OS_WIN)
+  browser_watcher::ExitFunnel funnel;
+
+  funnel.Init(kBrowserExitCodesRegistryPath, base::GetCurrentProcessHandle());
+  funnel.RecordEvent(L"SessionEnding");
+#endif
   // This is a time-limited shutdown where we need to write as much to
   // disk as we can as soon as we can, and where we must kill the
   // process within a hang timeout to avoid user prompts.
@@ -276,6 +284,9 @@ void SessionEnding() {
       content::NotificationService::AllSources(),
       content::NotificationService::NoDetails());
 
+#if defined(OS_WIN)
+  funnel.RecordEvent(L"EndSession");
+#endif
   // Write important data first.
   g_browser_process->EndSession();
 
@@ -283,6 +294,12 @@ void SessionEnding() {
   base::win::SetShouldCrashOnProcessDetach(false);
 #endif
 
+#if defined(OS_WIN)
+  // KillProcess ought to terminate the process without further ado, so if
+  // execution gets to this point, presumably this is normal exit.
+  funnel.RecordEvent(L"KillProcess");
+#endif
+
   // On Windows 7 and later, the system will consider the process ripe for
   // termination as soon as it hides or destroys its windows. Since any
   // execution past that point will be non-deterministically cut short, we

chrome/browser/ui/browser.cc

@@ -201,6 +201,7 @@
 #include "chrome/browser/task_manager/task_manager.h"
 #include "chrome/browser/ui/view_ids.h"
 #include "components/autofill/core/browser/autofill_ie_toolbar_import_win.h"
+#include "components/browser_watcher/exit_funnel_win.h"
 #include "ui/base/touch/touch_device.h"
 #include "ui/base/win/shell.h"
 #endif  // OS_WIN
@@ -658,8 +659,13 @@ void Browser::OnWindowClosing() {
   bool should_quit_if_last_browser =
       browser_shutdown::IsTryingToQuit() || !chrome::WillKeepAlive();
 
-  if (should_quit_if_last_browser && chrome::ShouldStartShutdown(this))
+  if (should_quit_if_last_browser && chrome::ShouldStartShutdown(this)) {
+#if defined(OS_WIN)
+    browser_watcher::ExitFunnel::RecordSingleEvent(
+          chrome::kBrowserExitCodesRegistryPath, L"LastWindowClose");
+#endif
     browser_shutdown::OnShutdownStarting(browser_shutdown::WINDOW_CLOSE);
+  }
 
   // Don't use GetForProfileIfExisting here, we want to force creation of the
   // session service so that user can restore what was open.

chrome/browser/ui/views/frame/browser_desktop_window_tree_host_win.cc

@@ -6,6 +6,7 @@
 
 #include <dwmapi.h>
 
+#include "base/process/process_handle.h"
 #include "chrome/browser/lifetime/application_lifetime.h"
 #include "chrome/browser/themes/theme_service.h"
 #include "chrome/browser/themes/theme_service_factory.h"
@@ -16,6 +17,8 @@
 #include "chrome/browser/ui/views/frame/system_menu_insertion_delegate_win.h"
 #include "chrome/browser/ui/views/tabs/tab_strip.h"
 #include "chrome/browser/ui/views/theme_image_mapper.h"
+#include "chrome/common/chrome_constants.h"
+#include "components/browser_watcher/exit_funnel_win.h"
 #include "ui/base/theme_provider.h"
 #include "ui/gfx/win/dpi.h"
 #include "ui/views/controls/menu/native_menu_win.h"
@@ -70,6 +73,31 @@ class DesktopThemeProvider : public ui::ThemeProvider {
   DISALLOW_COPY_AND_ASSIGN(DesktopThemeProvider);
 };
 
+// See http://crbug.com/412384.
+void TraceSessionEnding(LPARAM lparam) {
+  browser_watcher::ExitFunnel funnel;
+  if (!funnel.Init(chrome::kBrowserExitCodesRegistryPath,
+                   base::GetCurrentProcessHandle())) {
+    return;
+  }
+
+  // This exit path is the prime suspect for most our unclean shutdowns.
+  // Trace all the possible options to WM_ENDSESSION. This may result in
+  // multiple events for a single shutdown, but that's fine.
+  funnel.RecordEvent(L"WM_ENDSESSION");
+
+  if (lparam & ENDSESSION_CLOSEAPP)
+    funnel.RecordEvent(L"ES_CloseApp");
+  if (lparam & ENDSESSION_CRITICAL)
+    funnel.RecordEvent(L"ES_Critical");
+  if (lparam & ENDSESSION_LOGOFF)
+    funnel.RecordEvent(L"ES_Logoff");
+  const LPARAM kKnownBits =
+      ENDSESSION_CLOSEAPP | ENDSESSION_CRITICAL | ENDSESSION_LOGOFF;
+  if (lparam & ~kKnownBits)
+    funnel.RecordEvent(L"ES_Other");
+}
+
 }  // namespace
 
 ////////////////////////////////////////////////////////////////////////////////
@@ -182,6 +210,7 @@ bool BrowserDesktopWindowTreeHostWin::PreHandleMSG(UINT message,
         minimize_button_metrics_.OnHWNDActivated();
       return false;
     case WM_ENDSESSION:
+      TraceSessionEnding(l_param);
       chrome::SessionEnding();
       return true;
     case WM_INITMENUPOPUP:

chrome/chrome_watcher/chrome_watcher_main.cc

@@ -7,8 +7,10 @@
 #include "base/at_exit.h"
 #include "base/command_line.h"
 #include "base/logging_win.h"
+#include "base/process/process_handle.h"
 #include "base/template_util.h"
 #include "components/browser_watcher/exit_code_watcher_win.h"
+#include "components/browser_watcher/exit_funnel_win.h"
 #include "components/browser_watcher/watcher_main_api_win.h"
 
 namespace {
@@ -42,8 +44,30 @@ extern "C" int WatcherMain(const base::char16* registry_path) {
   // Attempt to wait on our parent process, and record its exit status.
   if (exit_code_watcher.ParseArguments(
         *base::CommandLine::ForCurrentProcess())) {
+    base::ProcessHandle dupe = base::kNullProcessHandle;
+    // Duplicate the process handle for the exit funnel due to the wonky
+    // process handle lifetime management in base.
+    if (!::DuplicateHandle(base::GetCurrentProcessHandle(),
+                           exit_code_watcher.process(),
+                           base::GetCurrentProcessHandle(),
+                           &dupe,
+                           0,
+                           FALSE,
+                           DUPLICATE_SAME_ACCESS)) {
+      dupe = base::kNullProcessHandle;
+    }
+
     // Wait on the process.
     exit_code_watcher.WaitForExit();
+
+    if (dupe != base::kNullProcessHandle) {
+      browser_watcher::ExitFunnel funnel;
+      funnel.Init(registry_path, dupe);
+      funnel.RecordEvent(L"BrowserExit");
+
+      base::CloseProcessHandle(dupe);
+    }
+
     ret = 0;
   }
 

components/browser_watcher.gypi

@@ -14,6 +14,8 @@
             'sources': [
               'browser_watcher/exit_code_watcher_win.cc',
               'browser_watcher/exit_code_watcher_win.h',
+              'browser_watcher/exit_funnel_win.cc',
+              'browser_watcher/exit_funnel_win.h',
             ],
             'dependencies': [
               '../base/base.gyp:base',
@@ -24,8 +26,6 @@
             'target_name': 'browser_watcher_client',
             'type': 'static_library',
             'sources': [
-              'browser_watcher/exit_funnel_win.cc',
-              'browser_watcher/exit_funnel_win.h',
               'browser_watcher/watcher_client_win.cc',
               'browser_watcher/watcher_client_win.h',
               'browser_watcher/watcher_main_api_win.cc',

tools/metrics/histograms/histograms.xml

@@ -35484,6 +35484,71 @@ Therefore, the affected-histogram name has to have at least one dot in it.
   </summary>
 </histogram>
 
+<histogram name="Stability.ExitFunnel.BackgroundOff" units="milliseconds">
+  <owner>siggi@chromium.org</owner>
+  <summary>Temporary instrumentation. See http://crbug.com/412384.</summary>
+</histogram>
+
+<histogram name="Stability.ExitFunnel.BackgroundOn" units="milliseconds">
+  <owner>siggi@chromium.org</owner>
+  <summary>Temporary instrumentation. See http://crbug.com/412384.</summary>
+</histogram>
+
+<histogram name="Stability.ExitFunnel.BrowserExit" units="milliseconds">
+  <owner>siggi@chromium.org</owner>
+  <summary>Temporary instrumentation. See http://crbug.com/412384.</summary>
+</histogram>
+
+<histogram name="Stability.ExitFunnel.EndSession" units="milliseconds">
+  <owner>siggi@chromium.org</owner>
+  <summary>Temporary instrumentation. See http://crbug.com/412384.</summary>
+</histogram>
+
+<histogram name="Stability.ExitFunnel.ES_CloseApp" units="milliseconds">
+  <owner>siggi@chromium.org</owner>
+  <summary>Temporary instrumentation. See http://crbug.com/412384.</summary>
+</histogram>
+
+<histogram name="Stability.ExitFunnel.ES_Critical" units="milliseconds">
+  <owner>siggi@chromium.org</owner>
+  <summary>Temporary instrumentation. See http://crbug.com/412384.</summary>
+</histogram>
+
+<histogram name="Stability.ExitFunnel.ES_Logoff" units="milliseconds">
+  <owner>siggi@chromium.org</owner>
+  <summary>Temporary instrumentation. See http://crbug.com/412384.</summary>
+</histogram>
+
+<histogram name="Stability.ExitFunnel.ES_Other" units="milliseconds">
+  <owner>siggi@chromium.org</owner>
+  <summary>Temporary instrumentation. See http://crbug.com/412384.</summary>
+</histogram>
+
+<histogram name="Stability.ExitFunnel.KillProcess" units="milliseconds">
+  <owner>siggi@chromium.org</owner>
+  <summary>Temporary instrumentation. See http://crbug.com/412384.</summary>
+</histogram>
+
+<histogram name="Stability.ExitFunnel.LastWindowClose" units="milliseconds">
+  <owner>siggi@chromium.org</owner>
+  <summary>Temporary instrumentation. See http://crbug.com/412384.</summary>
+</histogram>
+
+<histogram name="Stability.ExitFunnel.SessionEnding" units="milliseconds">
+  <owner>siggi@chromium.org</owner>
+  <summary>Temporary instrumentation. See http://crbug.com/412384.</summary>
+</histogram>
+
+<histogram name="Stability.ExitFunnel.TraybarExit" units="milliseconds">
+  <owner>siggi@chromium.org</owner>
+  <summary>Temporary instrumentation. See http://crbug.com/412384.</summary>
+</histogram>
+
+<histogram name="Stability.ExitFunnel.WM_ENDSESSION" units="milliseconds">
+  <owner>siggi@chromium.org</owner>
+  <summary>Temporary instrumentation. See http://crbug.com/412384.</summary>
+</histogram>
+
 <histogram name="Stars.Goog_Related" units="percent">
   <owner>yefim@chromium.org</owner>
   <summary>