Adding shutdown tracing capabilities

content/browser/browser_main_runner.cc

Index: content/browser/browser_main_runner.cc
diff --git a/content/browser/browser_main_runner.cc b/content/browser/browser_main_runner.cc
index f97318a690657892c4676b1b1d454f9dd75f8a1b..5a0b0a1f5db76d1bb9bac20eaa48409b0788e725 100644
--- a/content/browser/browser_main_runner.cc
+++ b/content/browser/browser_main_runner.cc
@@ -8,6 +8,9 @@
 #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"
@@ -25,6 +28,124 @@
 
 bool g_exited_main_message_loop = false;
 
+namespace {
+
+// This class is intended to initiate tracing of the shutdown procedure as well
+// as dumping the resulting traces 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 BrowserShutdownProfilerAndDumper {

[James Cook, 2013/08/30 22:54:02]

I think this class is big enough to go in a separate file, even though it's only
used here.

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

Done.

+ public:
+  BrowserShutdownProfilerAndDumper() : blocks_(0), dump_file_(0) {
+    const CommandLine& command_line = *CommandLine::ForCurrentProcess();
+    base::debug::CategoryFilter category_filter(
+        command_line.GetSwitchValueASCII(switches::kTraceShutdown));
+    base::debug::TraceLog::GetInstance()->SetEnabled(
+        category_filter,
+        base::debug::TraceLog::RECORD_UNTIL_FULL);
+  }
+
+  virtual ~BrowserShutdownProfilerAndDumper() {
+    WriteTracesToDisc(GetFileName());
+  }
+
+ private:
+  // Writes all traces which happened to disc.
+  void WriteTracesToDisc(base::FilePath file_name) {
+    LOG(ERROR) << "Flushing shutdown traces to disc. The buffer is %" <<

[James Cook, 2013/08/30 22:54:02]

Could this be a VLOG?  Or is this slow enough that logging is needed on normal
devices?

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

I did never run VLOG yet, but since you asked for it I use that now (it is not
an error after all ;) ).
 Done.

+        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(&BrowserShutdownProfilerAndDumper::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");

[James Cook, 2013/08/30 22:54:02]

FYI - We usually use the suffix ".json" for trace files.

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

I used the same default name as for the startup case.

+  }
+
+  // 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_));

[James Cook, 2013/08/30 22:54:02]

ferror(dump_file_) == 0

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

Done.

+  }
+
+  // Writes a string to the dump file.
+  void WriteString(const std::string& string) {
+    WriteChars(string.data(), string.size());
+

[James Cook, 2013/08/30 22:54:02]

no blank line

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

Done.

+  }
+
+  // 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_);

[James Cook, 2013/08/30 22:54:02]

Use file_util::CloseFile()

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

Done.

+    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 {
@@ -122,22 +243,32 @@ class BrowserMainRunnerImpl : public BrowserMainRunner {
   }
 
   virtual void Shutdown() OVERRIDE {
-    DCHECK(initialization_started_);
-    DCHECK(!is_shutdown_);
-    g_exited_main_message_loop = true;
-
-    main_loop_->ShutdownThreadsAndCleanUp();
-
-    ui::ShutdownInputMethod();
-#if defined(OS_WIN)
-    ole_initializer_.reset(NULL);
-#endif
-
-    main_loop_.reset(NULL);
-
-    notification_service_.reset(NULL);
-
-    is_shutdown_ = true;
+    // Enable shutdown tracing automatically upon shutdown if requested.
+    const CommandLine& command_line = *CommandLine::ForCurrentProcess();
+    // When the object gets destroyed the traces will get written to disc.
+    scoped_ptr<BrowserShutdownProfilerAndDumper> profiler;
+    if (command_line.HasSwitch(switches::kTraceShutdown))
+      profiler.reset(new BrowserShutdownProfilerAndDumper());
+    {

[James Cook, 2013/08/30 22:54:02]

Put a blank line above this, or move the comment from 253 above it.  At first I
thought this scope was part of the if() statement.

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

Did that already in the following patch. Done.

+      // 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;
+
+      main_loop_->ShutdownThreadsAndCleanUp();
+
+      ui::ShutdownInputMethod();
+  #if defined(OS_WIN)
+      ole_initializer_.reset(NULL);
+  #endif
+
+      main_loop_.reset(NULL);
+
+      notification_service_.reset(NULL);
+
+      is_shutdown_ = true;
+    }
   }
 
  protected: