Adding shutdown tracing capabilities

content/browser/browser_main_runner.cc

 // Copyright (c) 2012 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/public/browser/browser_main_runner.h"
 
 #include "base/allocator/allocator_shim.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 "base/metrics/histogram.h"
 #include "base/metrics/statistics_recorder.h"
 #include "content/browser/browser_main_loop.h"
 #include "content/browser/notification_service_impl.h"
 #include "content/public/common/content_switches.h"
 #include "content/public/common/main_function_params.h"
 #include "ui/base/ime/input_method_initializer.h"
 
 #if defined(OS_WIN)
 #include "base/win/metro.h"
 #include "base/win/windows_version.h"
 #include "ui/base/win/scoped_ole_initializer.h"
 #endif
 
 bool g_exited_main_message_loop = false;
 
+namespace {
+
+// 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".
+// Use the class with a scoped_ptr to automatically write the dump when the
+// object gets destroyed.
+// Note that we cannot use the asynchronous file writer since the
+// |SequencedWorkerPool| will get killed in the shutdown process.
+class BrowserShutdownProfileDumper {
+ public:
+  BrowserShutdownProfileDumper() : blocks_(0), dump_file_(0) {
+  }
+
+  virtual ~BrowserShutdownProfileDumper() {
+    WriteTracesToDisc(GetFileName());
+  }
+
+ private:
+  // Writes all traces which happened to disc.
+  void WriteTracesToDisc(base::FilePath file_name) {

[DaveMoore, 2013/08/30 22:51:15]

What happens if the trace buffer fills up before this happens?

[Mr4D (OOO till 08-26), 2013/08/31 02:03:44]

As I understood it it will stop tracing when the buffer is full - but we cannot
do much about that state since there is no background writing... 
Since the fill levels I have seen were 0.00xx% I think that if it really gets
filled it is better to write out the content we have since it will show the
culprit.
Added a comment towards that.

+    LOG(ERROR) << "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();
+  }
+
+  // Returns the file name where we should save the trace dump to.
+  base::FilePath 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");
+  }
+
+  // The callback for the |TraceLog::Flush| function. It saves all traces to
+  // disc.
+  void 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());
+  }
+
+  // Returns true if the dump file is valid.
+  bool IsFileValid() {
+    return dump_file_ && (0 == ferror(dump_file_));
+  }
+
+  // Writes a string to the dump file.
+  void WriteString(const std::string& string) {
+    WriteChars(string.data(), string.size());
+
+  }
+
+  // Write a buffer to the dump file.
+  void 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();
+    }
+  }
+
+  // Closes the dump file.
+  void CloseFile() {
+    if (!IsFileValid())
+      return;
+    fclose(dump_file_);
+    dump_file_ = 0;
+  }
+
+  // The number of blocks we have already written.
+  int blocks_;
+  // For dumping the content to disc.
+  FILE* dump_file_;
+};
+
+}
+
 namespace content {
 
 class BrowserMainRunnerImpl : public BrowserMainRunner {
  public:
   BrowserMainRunnerImpl()
       : initialization_started_(false), is_shutdown_(false) {}
 
   virtual ~BrowserMainRunnerImpl() {
     if (initialization_started_ && !is_shutdown_)
       Shutdown();
@@ skipping 77 matching lines @@
   }
 
   virtual int Run() OVERRIDE {
     DCHECK(initialization_started_);
     DCHECK(!is_shutdown_);
     main_loop_->RunMainMessageLoopParts();
     return main_loop_->GetResultCode();
   }
 
   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");
+      DCHECK(initialization_started_);
+      DCHECK(!is_shutdown_);
+      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:
   // True if we have started to initialize the runner.
   bool initialization_started_;
 
   // True if the runner has been shut down.
   bool is_shutdown_;
 
   scoped_ptr<NotificationServiceImpl> notification_service_;
   scoped_ptr<BrowserMainLoop> main_loop_;
 #if defined(OS_WIN)
   scoped_ptr<ui::ScopedOleInitializer> ole_initializer_;
 #endif
 
   DISALLOW_COPY_AND_ASSIGN(BrowserMainRunnerImpl);
 };
 
 // static
 BrowserMainRunner* BrowserMainRunner::Create() {
   return new BrowserMainRunnerImpl();
 }
 
 }  // namespace content