Adding shutdown tracing capabilities

use "--trace-shutdown" to enable the feature to start profiling when the user has pressed "shutdown" and specify "--trace-shutdown-file=<name>" to specify the file where you want to dump to. Additionally you can specify which modules to trace with e.g. "--trace-shutdown=base,net".

That said: NOTE that the dumping will cost time since it has to be done after the shutdown of Chrome is finished. As such it takes time and will make it impossible to get a correct reading of time from shutdown till a new startup is finished.

Note: This is similar to the trace-startup - with the exception that upon shutdown it is not possible to rely on threads for IO anymore.

BUG=281524
TEST=visual tests

Review URL: https://chromiumcodereview.appspot.com/23691025

git-svn-id: svn://svn.chromium.org/chrome/trunk/src@221631 0039d316-1c4b-4281-b951-d872f2087c98

ash/shell.cc

@@ -73,6 +73,7 @@
 #include "base/bind.h"
 #include "base/command_line.h"
 #include "base/debug/leak_annotations.h"
+#include "base/debug/trace_event.h"
 #include "ui/aura/client/aura_constants.h"
 #include "ui/aura/client/user_action_client.h"
 #include "ui/aura/env.h"
@@ -243,6 +244,8 @@ Shell::Shell(ShellDelegate* delegate)
 }
 
 Shell::~Shell() {
+  TRACE_EVENT0("shutdown", "ash::Shell::Destructor");
+
   views::FocusManagerFactory::Install(NULL);
 
   // Remove the focus from any window. This will prevent overhead and side

chrome/browser/browser_process_impl.cc

@@ -197,6 +197,7 @@ BrowserProcessImpl::~BrowserProcessImpl() {
 }
 
 void BrowserProcessImpl::StartTearDown() {
+    TRACE_EVENT0("shutdown", "BrowserProcessImpl::StartTearDown");
 #if defined(ENABLE_AUTOMATION)
   // Delete the AutomationProviderList before NotificationService,
   // since it may try to unregister notifications
@@ -235,7 +236,11 @@ void BrowserProcessImpl::StartTearDown() {
   notification_ui_manager_.reset();
 
   // Need to clear profiles (download managers) before the io_thread_.
-  profile_manager_.reset();
+  {
+    TRACE_EVENT0("shutdown",
+                 "BrowserProcessImpl::StartTearDown:ProfileManager");
+    profile_manager_.reset();
+  }
 
 #if !defined(OS_ANDROID)
   // Debugger must be cleaned up before IO thread and NotificationService.

chrome/browser/browser_shutdown.cc

@@ -90,6 +90,12 @@ void OnShutdownStarting(ShutdownType type) {
   if (shutdown_type_ != NOT_VALID)
     return;
 
+#if !defined(OS_CHROMEOS)
+  // Start the shutdown tracing. Note that On ChromeOS we have started this
+  // already.
+  chrome::StartShutdownTracing();
+#endif
+
   shutdown_type_ = type;
   // For now, we're only counting the number of renderer processes
   // since we can't safely count the number of plugin processes from this

chrome/browser/lifetime/application_lifetime.cc

@@ -7,6 +7,7 @@
 #include "ash/shell.h"
 #include "base/bind.h"
 #include "base/command_line.h"
+#include "base/debug/trace_event.h"
 #include "base/logging.h"
 #include "base/memory/scoped_ptr.h"
 #include "base/message_loop/message_loop.h"
@@ -125,6 +126,7 @@ void CloseAllBrowsers() {
 
 void AttemptUserExit() {
 #if defined(OS_CHROMEOS)
+  StartShutdownTracing();
   chromeos::BootTimesLoader::Get()->AddLogoutTimeMarker("LogoutStarted", false);
   // Write /tmp/uptime-logout-started as well.
   const char kLogoutStarted[] = "logout-started";
@@ -138,6 +140,7 @@ void AttemptUserExit() {
         state->GetString(prefs::kApplicationLocale) != owner_locale &&
         !state->IsManagedPreference(prefs::kApplicationLocale)) {
       state->SetString(prefs::kApplicationLocale, owner_locale);
+      TRACE_EVENT0("shutdown", "CommitPendingWrite");
       state->CommitPendingWrite();
     }
   }
@@ -154,6 +157,18 @@ void AttemptUserExit() {
 #endif
 }
 
+void StartShutdownTracing() {
+  const CommandLine& command_line = *CommandLine::ForCurrentProcess();
+  if (command_line.HasSwitch(switches::kTraceShutdown)) {
+    base::debug::CategoryFilter category_filter(
+        command_line.GetSwitchValueASCII(switches::kTraceShutdown));
+    base::debug::TraceLog::GetInstance()->SetEnabled(
+        category_filter,
+        base::debug::TraceLog::RECORD_UNTIL_FULL);
+  }
+  TRACE_EVENT0("shutdown", "StartShutdownTracing");
+}
+
 // The Android implementation is in application_lifetime_android.cc
 #if !defined(OS_ANDROID)
 void AttemptRestart() {

chrome/browser/lifetime/application_lifetime.h

@@ -16,6 +16,11 @@ namespace chrome {
 // SIGTERM to start actual exit process.
 void AttemptUserExit();
 
+// Starts to collect shutdown traces. On ChromeOS this will start immediately
+// on AttemptUserExit() and all other systems will start once all tabs are
+// closed.
+void StartShutdownTracing();
+
 // Starts a user initiated restart process. On platforms other than
 // chromeos, this sets a restart bit in the preference so that
 // chrome will be restarted at the end of shutdown process. On

chrome/browser/profiles/profile_destroyer.cc

@@ -5,6 +5,7 @@
 #include "chrome/browser/profiles/profile_destroyer.h"
 
 #include "base/bind.h"
+#include "base/debug/trace_event.h"
 #include "base/memory/scoped_ptr.h"
 #include "base/message_loop/message_loop.h"
 #include "chrome/browser/profiles/profile.h"
@@ -23,6 +24,8 @@ std::vector<ProfileDestroyer*>* ProfileDestroyer::pending_destroyers_ = NULL;
 
 // static
 void ProfileDestroyer::DestroyProfileWhenAppropriate(Profile* const profile) {
+  TRACE_EVENT0("shutdown", "ProfileDestroyer::DestroyProfileWhenAppropriate");
+
   DCHECK(profile);
   profile->MaybeSendDestroyedNotification();
 

content/browser/browser_main_loop.cc

@@ -698,6 +698,8 @@ void BrowserMainLoop::ShutdownThreadsAndCleanUp() {
     // Called early, nothing to do
     return;
   }
+  TRACE_EVENT0("shutdown", "BrowserMainLoop::ShutdownThreadsAndCleanUp")
+
   // Teardown may start in PostMainMessageLoopRun, and during teardown we
   // need to be able to perform IO.
   base::ThreadRestrictions::SetIOAllowed(true);
@@ -706,8 +708,11 @@ void BrowserMainLoop::ShutdownThreadsAndCleanUp() {
       base::Bind(base::IgnoreResult(&base::ThreadRestrictions::SetIOAllowed),
                  true));
 
-  if (parts_)
+  if (parts_) {
+    TRACE_EVENT0("shutdown",
+                 "BrowserMainLoop::Subsystem:PostMainMessageLoopRun");
     parts_->PostMainMessageLoopRun();
+  }
 
   trace_memory_controller_.reset();
 
@@ -716,14 +721,23 @@ void BrowserMainLoop::ShutdownThreadsAndCleanUp() {
   // delete related objects on the GPU thread. This must be done before
   // stopping the GPU thread. The GPU thread will close IPC channels to renderer
   // processes so this has to happen before stopping the IO thread.
-  GpuProcessHostUIShim::DestroyAll();
-
+  {
+    TRACE_EVENT0("shutdown", "BrowserMainLoop::Subsystem:GPUProcessHostShim");
+    GpuProcessHostUIShim::DestroyAll();
+  }
   // Cancel pending requests and prevent new requests.
-  if (resource_dispatcher_host_)
+  if (resource_dispatcher_host_) {
+    TRACE_EVENT0("shutdown",
+                 "BrowserMainLoop::Subsystem:ResourceDispatcherHost");
     resource_dispatcher_host_.get()->Shutdown();
+  }
 
 #if defined(USE_AURA)
-  ImageTransportFactory::Terminate();
+  {
+    TRACE_EVENT0("shutdown",
+                 "BrowserMainLoop::Subsystem:ImageTransportFactory");
+    ImageTransportFactory::Terminate();
+  }
 #endif
 
   // The device monitors are using |system_monitor_| as dependency, so delete
@@ -760,29 +774,42 @@ void BrowserMainLoop::ShutdownThreadsAndCleanUp() {
     //
     // - (Not sure why DB stops last.)
     switch (thread_id) {
-      case BrowserThread::DB:
-        db_thread_.reset();
+      case BrowserThread::DB: {
+          TRACE_EVENT0("shutdown", "BrowserMainLoop::Subsystem:DBThread");
+          db_thread_.reset();
+        }
         break;
-      case BrowserThread::FILE_USER_BLOCKING:
-        file_user_blocking_thread_.reset();
+      case BrowserThread::FILE_USER_BLOCKING: {
+          TRACE_EVENT0("shutdown",
+                       "BrowserMainLoop::Subsystem:FileUserBlockingThread");
+          file_user_blocking_thread_.reset();
+        }
         break;
-      case BrowserThread::FILE:
+      case BrowserThread::FILE: {
+          TRACE_EVENT0("shutdown", "BrowserMainLoop::Subsystem:FileThread");
 #if !defined(OS_IOS)
-        // Clean up state that lives on or uses the file_thread_ before
-        // it goes away.
-        if (resource_dispatcher_host_)
-          resource_dispatcher_host_.get()->save_file_manager()->Shutdown();
+          // Clean up state that lives on or uses the file_thread_ before
+          // it goes away.
+          if (resource_dispatcher_host_)
+            resource_dispatcher_host_.get()->save_file_manager()->Shutdown();
 #endif  // !defined(OS_IOS)
-        file_thread_.reset();
+          file_thread_.reset();
+        }
         break;
-      case BrowserThread::PROCESS_LAUNCHER:
-        process_launcher_thread_.reset();
+      case BrowserThread::PROCESS_LAUNCHER: {
+          TRACE_EVENT0("shutdown", "BrowserMainLoop::Subsystem:LauncherThread");
+          process_launcher_thread_.reset();
+        }
         break;
-      case BrowserThread::CACHE:
-        cache_thread_.reset();
+      case BrowserThread::CACHE: {
+          TRACE_EVENT0("shutdown", "BrowserMainLoop::Subsystem:CacheThread");
+          cache_thread_.reset();
+        }
         break;
-      case BrowserThread::IO:
-        io_thread_.reset();
+      case BrowserThread::IO: {
+          TRACE_EVENT0("shutdown", "BrowserMainLoop::Subsystem:IOThread");
+          io_thread_.reset();
+        }
         break;
       case BrowserThread::UI:
       case BrowserThread::ID_COUNT:
@@ -793,7 +820,10 @@ void BrowserMainLoop::ShutdownThreadsAndCleanUp() {
   }
 
 #if !defined(OS_IOS)
-  indexed_db_thread_.reset();
+  {
+    TRACE_EVENT0("shutdown", "BrowserMainLoop::Subsystem:IndexedDBThread");
+    indexed_db_thread_.reset();
+  }
 #endif
 
   // Close the blocking I/O pool after the other threads. Other threads such
@@ -802,23 +832,39 @@ void BrowserMainLoop::ShutdownThreadsAndCleanUp() {
   // may also be slow operations pending that will blcok shutdown, so closing
   // it here (which will block until required operations are complete) gives
   // more head start for those operations to finish.
-  BrowserThreadImpl::ShutdownThreadPool();
+  {
+    TRACE_EVENT0("shutdown", "BrowserMainLoop::Subsystem:ThreadPool");
+    BrowserThreadImpl::ShutdownThreadPool();
+  }
 
 #if !defined(OS_IOS)
   // Must happen after the IO thread is shutdown since this may be accessed from
   // it.
-  BrowserGpuChannelHostFactory::Terminate();
+  {
+    TRACE_EVENT0("shutdown", "BrowserMainLoop::Subsystem:GPUChannelFactory");
+    BrowserGpuChannelHostFactory::Terminate();
+  }
 
   // Must happen after the I/O thread is shutdown since this class lives on the
   // I/O thread and isn't threadsafe.
-  GamepadService::GetInstance()->Terminate();
-  DeviceInertialSensorService::GetInstance()->Shutdown();
-
-  URLDataManager::DeleteDataSources();
+  {
+    TRACE_EVENT0("shutdown", "BrowserMainLoop::Subsystem:GamepadService");
+    GamepadService::GetInstance()->Terminate();
+  }
+  {
+    TRACE_EVENT0("shutdown", "BrowserMainLoop::Subsystem:SensorService");
+    DeviceInertialSensorService::GetInstance()->Shutdown();
+  }
+  {
+    TRACE_EVENT0("shutdown", "BrowserMainLoop::Subsystem:DeleteDataSources");
+    URLDataManager::DeleteDataSources();
+  }
 #endif  // !defined(OS_IOS)
 
-  if (parts_)
+  if (parts_) {
+    TRACE_EVENT0("shutdown", "BrowserMainLoop::Subsystem:PostDestroyThreads");
     parts_->PostDestroyThreads();
+  }
 }
 
 void BrowserMainLoop::InitializeMainThread() {

content/browser/browser_main_runner.cc

@@ -12,6 +12,7 @@
 #include "base/metrics/histogram.h"
 #include "base/metrics/statistics_recorder.h"
 #include "content/browser/browser_main_loop.h"
+#include "content/browser/browser_shutdown_profile_dumper.h"
 #include "content/browser/notification_service_impl.h"
 #include "content/public/common/content_switches.h"
 #include "content/public/common/main_function_params.h"
@@ -124,20 +125,32 @@ class BrowserMainRunnerImpl : public BrowserMainRunner {
   virtual void Shutdown() OVERRIDE {
     DCHECK(initialization_started_);
     DCHECK(!is_shutdown_);
-    g_exited_main_message_loop = true;
+    // The shutdown tracing got enabled in AttemptUserExit earlier, but someone
+    // needs to write the result to disc. For that a dumper needs to get created
+    // which will dump the traces to disc when it gets destroyed.
+    const CommandLine& command_line = *CommandLine::ForCurrentProcess();
+    scoped_ptr<BrowserShutdownProfileDumper> profiler;
+    if (command_line.HasSwitch(switches::kTraceShutdown))
+      profiler.reset(new BrowserShutdownProfileDumper());
 
-    main_loop_->ShutdownThreadsAndCleanUp();
+    {
+      // The trace event has to stay between profiler creation and destruction.
+      TRACE_EVENT0("shutdown", "BrowserMainRunner");
+      g_exited_main_message_loop = true;
 
-    ui::ShutdownInputMethod();
-#if defined(OS_WIN)
-    ole_initializer_.reset(NULL);
-#endif
+      main_loop_->ShutdownThreadsAndCleanUp();
 
-    main_loop_.reset(NULL);
+      ui::ShutdownInputMethod();
+  #if defined(OS_WIN)
+      ole_initializer_.reset(NULL);
+  #endif
 
-    notification_service_.reset(NULL);
+      main_loop_.reset(NULL);
 
-    is_shutdown_ = true;
+      notification_service_.reset(NULL);
+
+      is_shutdown_ = true;
+    }
   }
 
  protected:

content/browser/browser_shutdown_profile_dumper.cc

@@ -0,0 +1,107 @@
+// Copyright 2013 The Chromium Authors. All rights reserved.
+// Use of this source code is governed by a BSD-style license that can be
+// found in the LICENSE file.
+
+#include "content/browser/browser_shutdown_profile_dumper.h"
+
+#include "base/base_switches.h"
+#include "base/command_line.h"
+#include "base/debug/trace_event.h"
+#include "base/debug/trace_event_impl.h"
+#include "base/file_util.h"
+#include "base/files/file_path.h"
+#include "base/logging.h"
+#include "content/public/common/content_switches.h"
+
+namespace content {
+
+BrowserShutdownProfileDumper::BrowserShutdownProfileDumper()
+    : blocks_(0),
+      dump_file_(NULL) {
+}
+
+BrowserShutdownProfileDumper::~BrowserShutdownProfileDumper() {
+  WriteTracesToDisc(GetFileName());
+}
+
+void BrowserShutdownProfileDumper::WriteTracesToDisc(
+    const base::FilePath& file_name) {
+  // Note: I have seen a usage of 0.000xx% when dumping - which fits easily.
+  // Since the tracer stops when the trace buffer is filled, we'd rather save
+  // what we have than nothing since we might see from the amount of events
+  // that caused the problem.
+  DVLOG(1) << "Flushing shutdown traces to disc. The buffer is %" <<
+      base::debug::TraceLog::GetInstance()->GetBufferPercentFull() <<
+      " full.";
+  DCHECK(!dump_file_);
+  dump_file_ = file_util::OpenFile(file_name, "w+");
+  if (!IsFileValid()) {
+    LOG(ERROR) << "Failed to open performance trace file: " <<
+        file_name.value();
+    return;
+  }
+  WriteString("{\"traceEvents\":");
+  WriteString("[");
+
+  base::debug::TraceLog::GetInstance()->Flush(
+      base::Bind(&BrowserShutdownProfileDumper::WriteTraceDataCollected,
+      base::Unretained(this)));
+
+  WriteString("]");
+  WriteString("}");
+  CloseFile();
+}
+
+base::FilePath BrowserShutdownProfileDumper::GetFileName() {
+  const CommandLine& command_line = *CommandLine::ForCurrentProcess();
+  base::FilePath trace_file =
+      command_line.GetSwitchValuePath(switches::kTraceShutdownFile);
+
+  if (!trace_file.empty())
+    return trace_file;
+
+  // Default to saving the startup trace into the current dir.
+  return base::FilePath().AppendASCII("chrometrace.log");
+}
+
+void BrowserShutdownProfileDumper::WriteTraceDataCollected(
+    const scoped_refptr<base::RefCountedString>& events_str) {
+  if (!IsFileValid())
+    return;
+  if (blocks_) {
+    // Blocks are not comma separated. Beginning with the second block we
+    // start therefore to add one in front of the previous block.
+    WriteString(",");
+  }
+  ++blocks_;
+  WriteString(events_str->data());
+}
+
+bool BrowserShutdownProfileDumper::IsFileValid() {
+  return dump_file_ && (ferror(dump_file_) == 0);
+}
+
+void BrowserShutdownProfileDumper::WriteString(const std::string& string) {
+  WriteChars(string.data(), string.size());
+}
+
+void BrowserShutdownProfileDumper::WriteChars(const char* chars, size_t size) {
+  if (!IsFileValid())
+    return;
+
+  size_t written = fwrite(chars, 1, size, dump_file_);
+  if (written != size) {
+    LOG(ERROR) << "Error " << ferror(dump_file_) <<
+        " in fwrite() to trace file";
+    CloseFile();
+  }
+}
+
+void BrowserShutdownProfileDumper::CloseFile() {
+  if (!dump_file_)
+    return;
+  file_util::CloseFile(dump_file_);
+  dump_file_ = NULL;
+}
+
+}  // namespace content

content/browser/browser_shutdown_profile_dumper.h

@@ -0,0 +1,69 @@
+// Copyright 2013 The Chromium Authors. All rights reserved.
+// Use of this source code is governed by a BSD-style license that can be
+// found in the LICENSE file.
+
+#ifndef CONTENT_BROWSER_BROWSER_SHUTDOWN_PROFILE_DUMPER_H_
+#define CONTENT_BROWSER_BROWSER_SHUTDOWN_PROFILE_DUMPER_H_
+
+#include <string>
+
+#include "base/basictypes.h"
+#include "base/memory/ref_counted.h"
+#include "base/memory/ref_counted_memory.h"
+#include "content/common/content_export.h"
+
+namespace base {
+class FilePath;
+}
+
+namespace content {
+
+// This class is intended to dump the tracing results of the shutdown process
+// to a file before the browser process exits.
+// It will save the file either into the command line passed
+// "--trace-shutdown-file=<name>" parameter - or - to "chrometrace.log" in the
+// current directory.
+// Use the class with a scoped_ptr to get files written in the destructor.
+// Note that we cannot use the asynchronous file writer since the
+// |SequencedWorkerPool| will get killed in the shutdown process.
+class BrowserShutdownProfileDumper {
+ public:
+  BrowserShutdownProfileDumper();
+
+  ~BrowserShutdownProfileDumper();
+
+ private:
+  // Writes all traces which happened to disk.
+  void WriteTracesToDisc(const base::FilePath& file_name);
+
+  // Returns the file name where we should save the trace dump to.
+  base::FilePath GetFileName();
+
+  // The callback for the |TraceLog::Flush| function. It saves all traces to
+  // disc.
+  void WriteTraceDataCollected(
+      const scoped_refptr<base::RefCountedString>& events_str);
+
+  // Returns true if the dump file is valid.
+  bool IsFileValid();
+
+  // Writes a string to the dump file.
+  void WriteString(const std::string& string);
+
+  // Write a buffer to the dump file.
+  void WriteChars(const char* chars, size_t size);
+
+  // Closes the dump file.
+  void CloseFile();
+
+  // The number of blocks we have already written.
+  int blocks_;
+  // For dumping the content to disc.
+  FILE* dump_file_;
+
+  DISALLOW_COPY_AND_ASSIGN(BrowserShutdownProfileDumper);
+};
+
+}  // namespace content
+
+#endif  // CONTENT_BROWSER_BROWSER_SHUTDOWN_PROFILE_DUMPER_H_

content/content_browser.gypi

@@ -333,6 +333,8 @@
     'browser/browser_plugin/browser_plugin_popup_menu_helper_mac.mm',
     'browser/browser_process_sub_thread.cc',
     'browser/browser_process_sub_thread.h',
+    'browser/browser_shutdown_profile_dumper.cc',
+    'browser/browser_shutdown_profile_dumper.h',
     'browser/browser_thread_impl.cc',
     'browser/browser_thread_impl.h',
     'browser/browser_url_handler_impl.cc',

content/public/common/content_switches.cc

@@ -793,6 +793,19 @@ const char kTestingFixedHttpsPort[]         = "testing-fixed-https-port";
 // Runs the security test for the renderer sandbox.
 const char kTestSandbox[]                   = "test-sandbox";
 
+// Causes TRACE_EVENT flags to be recorded beginning with shutdown. Optionally,
+// can specify the specific trace categories to include (e.g.
+// --trace-shutdown=base,net) otherwise, all events are recorded.
+// --trace-shutdown-file can be used to control where the trace log gets stored
+// to since there is otherwise no way to access the result.
+const char kTraceShutdown[]                 = "trace-shutdown";
+
+// If supplied, sets the file which shutdown tracing will be stored into, if
+// omitted the default will be used "chrometrace.log" in the current directory.
+// Has no effect unless --trace-shutdown is also supplied.
+// Example: --trace-shutdown --trace-shutdown-file=/tmp/trace_event.log
+const char kTraceShutdownFile[]             = "trace-shutdown-file";
+
 // Causes TRACE_EVENT flags to be recorded from startup. Optionally, can
 // specify the specific trace categories to include (e.g.
 // --trace-startup=base,net) otherwise, all events are recorded. Setting this

content/public/common/content_switches.h

@@ -227,6 +227,8 @@ extern const char kTapDownDeferralTimeMs[];
 CONTENT_EXPORT extern const char kTestingFixedHttpPort[];
 CONTENT_EXPORT extern const char kTestingFixedHttpsPort[];
 CONTENT_EXPORT extern const char kTestSandbox[];
+CONTENT_EXPORT extern const char kTraceShutdown[];
+extern const char kTraceShutdownFile[];
 extern const char kTraceStartup[];
 extern const char kTraceStartupDuration[];
 extern const char kTraceStartupFile[];

ui/aura/root_window.cc

@@ -170,6 +170,8 @@ RootWindow::RootWindow(const CreateParams& params)
 }
 
 RootWindow::~RootWindow() {
+  TRACE_EVENT0("shutdown", "RootWindow::Destructor");
+
   compositor_->RemoveObserver(this);
   // Make sure to destroy the compositor before terminating so that state is
   // cleared and we don't hit asserts.

ui/compositor/compositor.cc

@@ -9,6 +9,7 @@
 
 #include "base/bind.h"
 #include "base/command_line.h"
+#include "base/debug/trace_event.h"
 #include "base/memory/singleton.h"
 #include "base/message_loop/message_loop.h"
 #include "base/run_loop.h"
@@ -418,6 +419,8 @@ Compositor::Compositor(CompositorDelegate* delegate,
 }
 
 Compositor::~Compositor() {
+  TRACE_EVENT0("shutdown", "Compositor::destructor");
+
   DCHECK(g_compositor_initialized);
 
   CancelCompositorLock();