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