Support --trace-startup and task tracing

passing --trace-startup puts the tracing system into record mode immediately saving the result to chrometrace.log or a file specified by --trace-startup-file


BUG=None
TEST=start chrome with --trace-startup, wait 5 secs, see chrometrace.log in current dir. open it in chrome://tracing/


Review URL: http://codereview.chromium.org/7887013

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

10 files changed, 166 insertions, 51 deletions

diff --git a/content/app/content_main.cc b/content/app/content_main.cc
index ace58ff..7e670c0 100644
--- a/content/app/content_main.cc
+++ b/content/app/content_main.cc
@@ -7,6 +7,7 @@
 #include "base/at_exit.h"
 #include "base/command_line.h"
 #include "base/debug/debugger.h"
+#include "base/debug/trace_event.h"
 #include "base/i18n/icu_util.h"
 #include "base/logging.h"
 #include "base/memory/scoped_ptr.h"
@@ -345,6 +346,12 @@ int ContentMain(int argc,
   std::string process_type =
         command_line.GetSwitchValueASCII(switches::kProcessType);
 
+  // Enable startup tracing asap to avoid early TRACE_EVENT calls being ignored.
+  if (command_line.HasSwitch(switches::kTraceStartup)) {
+    base::debug::TraceLog::GetInstance()->SetEnabled(
+        command_line.GetSwitchValueASCII(switches::kTraceStartup));
+  }
+
 #if defined(OS_MACOSX)
   // We need to allocate the IO Ports before the Sandbox is initialized or
   // the first instance of SystemMonitor is created.
diff --git a/content/browser/browser_main_loop.cc b/content/browser/browser_main_loop.cc
index 9045416..97da69e 100644
--- a/content/browser/browser_main_loop.cc
+++ b/content/browser/browser_main_loop.cc
@@ -13,6 +13,7 @@
 #include "base/threading/thread_restrictions.h"
 #include "base/tracked_objects.h"
 #include "content/browser/browser_thread_impl.h"
+#include "content/browser/trace_controller.h"
 #include "content/common/hi_res_timer_manager.h"
 #include "content/common/sandbox_policy.h"
 #include "content/public/browser/browser_main_parts.h"
@@ -246,6 +247,10 @@ void BrowserMainLoop::MainMessageLoopStart() {
 
   InitializeMainThread();
 
+  // Start tracing to a file if needed.
+  if (base::debug::TraceLog::GetInstance()->IsEnabled())
+    TraceController::GetInstance()->InitStartupTracing(parsed_command_line_);
+
   system_monitor_.reset(new base::SystemMonitor);
   hi_res_timer_manager_.reset(new HighResolutionTimerManager);
 
diff --git a/content/browser/gpu/gpu_process_host.cc b/content/browser/gpu/gpu_process_host.cc
index 305bbb9..0612fca 100644
--- a/content/browser/gpu/gpu_process_host.cc
+++ b/content/browser/gpu/gpu_process_host.cc
@@ -560,7 +560,8 @@ bool GpuProcessHost::LaunchGpuProcess() {
     switches::kGpuNoContextLost,
     switches::kGpuStartupDialog,
     switches::kLoggingLevel,
-    switches::kNoSandbox
+    switches::kNoSandbox,
+    switches::kTraceStartup,
   };
   cmd_line->CopySwitchesFrom(browser_command_line, kSwitchNames,
                              arraysize(kSwitchNames));
diff --git a/content/browser/plugin_process_host.cc b/content/browser/plugin_process_host.cc
index 475a4ef..1930bab 100644
--- a/content/browser/plugin_process_host.cc
+++ b/content/browser/plugin_process_host.cc
@@ -214,6 +214,7 @@ bool PluginProcessHost::Init(const webkit::WebPluginInfo& info,
     switches::kNoSandbox,
     switches::kPluginStartupDialog,
     switches::kTestSandbox,
+    switches::kTraceStartup,
     switches::kUseGL,
     switches::kUserAgent,
     switches::kV,
diff --git a/content/browser/renderer_host/browser_render_process_host.cc b/content/browser/renderer_host/browser_render_process_host.cc
index 659cc410..75e3473 100644
--- a/content/browser/renderer_host/browser_render_process_host.cc
+++ b/content/browser/renderer_host/browser_render_process_host.cc
@@ -616,6 +616,7 @@ void BrowserRenderProcessHost::PropagateBrowserCommandLineToRenderer(
     switches::kShowPaintRects,
     switches::kSimpleDataSource,
     switches::kTestSandbox,
+    switches::kTraceStartup,
     // This flag needs to be propagated to the renderer process for
     // --in-process-webgl.
     switches::kUseGL,
diff --git a/content/browser/trace_controller.cc b/content/browser/trace_controller.cc
index 9b380c0..137c4f7 100644
--- a/content/browser/trace_controller.cc
+++ b/content/browser/trace_controller.cc
@@ -5,14 +5,48 @@
 #include "content/browser/trace_controller.h"
 
 #include "base/bind.h"
+#include "base/command_line.h"
 #include "base/debug/trace_event.h"
-#include "base/string_tokenizer.h"
+#include "base/string_number_conversions.h"
 #include "content/browser/browser_message_filter.h"
 #include "content/browser/trace_message_filter.h"
+#include "content/browser/trace_subscriber_stdio.h"
 #include "content/common/child_process_messages.h"
+#include "content/public/common/content_switches.h"
 
+using base::debug::TraceLog;
 using content::BrowserThread;
 
+namespace {
+
+class AutoStopTraceSubscriberStdio : public TraceSubscriberStdio {
+ public:
+  AutoStopTraceSubscriberStdio(const FilePath& file_path)
+      : TraceSubscriberStdio(file_path) {}
+
+  static void EndStartupTrace(TraceSubscriberStdio* subscriber) {
+    if (!TraceController::GetInstance()->EndTracingAsync(subscriber))
+      delete subscriber;
+    // else, the tracing will end asynchronously in OnEndTracingComplete().
+  }
+
+  virtual void OnEndTracingComplete() {
+    TraceSubscriberStdio::OnEndTracingComplete();
+    delete this;
+    // TODO(joth): this would be the time to automatically open up
+    // chrome://tracing/ and load up the trace data collected.
+  }
+};
+
+}  // namespace
+
+void TraceSubscriber::OnKnownCategoriesCollected(
+      const std::set<std::string>& known_categories) {}
+
+void TraceSubscriber::OnTraceBufferPercentFullReply(float percent_full) {}
+
+TraceSubscriber::~TraceSubscriber() {}
+
 TraceController::TraceController() :
     subscriber_(NULL),
     pending_end_ack_count_(0),
@@ -20,21 +54,58 @@ TraceController::TraceController() :
     maximum_bpf_(0.0f),
     is_tracing_(false),
     is_get_categories_(false) {
-  base::debug::TraceLog::GetInstance()->SetOutputCallback(
+  TraceLog::GetInstance()->SetOutputCallback(
       base::Bind(&TraceController::OnTraceDataCollected,
                  base::Unretained(this)));
 }
 
 TraceController::~TraceController() {
-  if (base::debug::TraceLog* trace_log = base::debug::TraceLog::GetInstance())
-    trace_log->SetOutputCallback(base::debug::TraceLog::OutputCallback());
+  if (TraceLog* trace_log = TraceLog::GetInstance())
+    trace_log->SetOutputCallback(TraceLog::OutputCallback());
 }
 
-//static
 TraceController* TraceController::GetInstance() {
   return Singleton<TraceController>::get();
 }
 
+void TraceController::InitStartupTracing(const CommandLine& command_line) {
+  DCHECK(BrowserThread::CurrentlyOn(BrowserThread::UI));
+  FilePath trace_file = command_line.GetSwitchValuePath(
+      switches::kTraceStartupFile);
+  // trace_file = "none" means that startup events will show up for the next
+  // begin/end tracing (via about:tracing or AutomationProxy::BeginTracing/
+  // EndTracing, for example).
+  if (trace_file == FilePath().AppendASCII("none"))
+    return;
+
+  if (trace_file.empty()) {
+    // Default to saving the startup trace into the current dir.
+    trace_file = FilePath().AppendASCII("chrometrace.log");
+  }
+  scoped_ptr<AutoStopTraceSubscriberStdio> subscriber(
+      new AutoStopTraceSubscriberStdio(trace_file));
+  DCHECK(can_begin_tracing(subscriber.get()));
+  if (!subscriber->IsValid()) {
+    TraceLog::GetInstance()->SetDisabled();
+    return;
+  }
+
+  std::string delay_str = command_line.GetSwitchValueASCII(
+      switches::kTraceStartupDuration);
+  int delay_secs = 5;
+  if (!delay_str.empty() && !base::StringToInt(delay_str, &delay_secs)) {
+    DLOG(WARNING) << "Could not parse --" << switches::kTraceStartupDuration
+        << "=" << delay_str << " defaulting to 5 (secs)";
+    delay_secs = 5;
+  }
+
+  OnTracingBegan(subscriber.get());
+  BrowserThread::PostDelayedTask(BrowserThread::UI, FROM_HERE,
+      base::Bind(&AutoStopTraceSubscriberStdio::EndStartupTrace,
+                 base::Unretained(subscriber.release())),
+                 delay_secs * 1000);
+}
+
 bool TraceController::GetKnownCategoriesAsync(TraceSubscriber* subscriber) {
   DCHECK(BrowserThread::CurrentlyOn(BrowserThread::UI));
 
@@ -60,48 +131,29 @@ bool TraceController::BeginTracing(
     const std::vector<std::string>& excluded_categories) {
   DCHECK(BrowserThread::CurrentlyOn(BrowserThread::UI));
 
-  if (!can_begin_tracing() ||
-      (subscriber_ != NULL && subscriber != subscriber_))
+  if (!can_begin_tracing(subscriber))
     return false;
 
-  subscriber_ = subscriber;
-  included_categories_ = included_categories;
-  excluded_categories_ = excluded_categories;
-
   // Enable tracing
-  is_tracing_ = true;
-  base::debug::TraceLog::GetInstance()->SetEnabled(included_categories,
-                                                   excluded_categories);
-
-  // Notify all child processes.
-  for (FilterMap::iterator it = filters_.begin(); it != filters_.end(); ++it) {
-    it->get()->SendBeginTracing(included_categories, excluded_categories);
-  }
+  TraceLog::GetInstance()->SetEnabled(included_categories, excluded_categories);
+  OnTracingBegan(subscriber);
 
   return true;
 }
 
 bool TraceController::BeginTracing(TraceSubscriber* subscriber,
                                    const std::string& categories) {
-  std::vector<std::string> included, excluded;
-  // Tokenize list of categories, delimited by ','.
-  StringTokenizer tokens(categories, ",");
-  while (tokens.GetNext()) {
-    bool is_included = true;
-    std::string category = tokens.token();
-    // Excluded categories start with '-'.
-    if (category.at(0) == '-') {
-      // Remove '-' from category string.
-      category = category.substr(1);
-      is_included = false;
-    }
-    if (is_included)
-      included.push_back(category);
-    else
-      excluded.push_back(category);
-  }
+  DCHECK(BrowserThread::CurrentlyOn(BrowserThread::UI));
+
+  if (!can_begin_tracing(subscriber))
+    return false;
+
+  // Enable tracing
+  TraceLog::GetInstance()->SetEnabled(categories);
 
-  return BeginTracing(subscriber, included, excluded);
+  OnTracingBegan(subscriber);
+
+  return true;
 }
 
 bool TraceController::EndTracingAsync(TraceSubscriber* subscriber) {
@@ -121,7 +173,7 @@ bool TraceController::EndTracingAsync(TraceSubscriber* subscriber) {
   if (pending_end_ack_count_ == 1) {
     // Ack asynchronously now, because we don't have any children to wait for.
     std::vector<std::string> categories;
-    base::debug::TraceLog::GetInstance()->GetKnownCategories(&categories);
+    TraceLog::GetInstance()->GetKnownCategories(&categories);
     BrowserThread::PostTask(BrowserThread::UI, FROM_HERE,
         base::Bind(&TraceController::OnEndTracingAck, base::Unretained(this),
                    categories));
@@ -148,7 +200,7 @@ bool TraceController::GetTraceBufferPercentFullAsync(
   // Handle special case of zero child processes.
   if (pending_bpf_ack_count_ == 1) {
     // Ack asynchronously now, because we don't have any children to wait for.
-    float bpf = base::debug::TraceLog::GetInstance()->GetBufferPercentFull();
+    float bpf = TraceLog::GetInstance()->GetBufferPercentFull();
     BrowserThread::PostTask(BrowserThread::UI, FROM_HERE,
         base::Bind(&TraceController::OnTraceBufferPercentFullReply,
                    base::Unretained(this), bpf));
@@ -198,6 +250,19 @@ void TraceController::RemoveFilter(TraceMessageFilter* filter) {
   filters_.erase(filter);
 }
 
+void TraceController::OnTracingBegan(TraceSubscriber* subscriber) {
+  is_tracing_ = true;
+
+  subscriber_ = subscriber;
+
+  TraceLog::GetInstance()->GetEnabledTraceCategories(&included_categories_,
+                                                     &excluded_categories_);
+  // Notify all child processes.
+  for (FilterMap::iterator it = filters_.begin(); it != filters_.end(); ++it) {
+    it->get()->SendBeginTracing(included_categories_, excluded_categories_);
+  }
+}
+
 void TraceController::OnEndTracingAck(
     const std::vector<std::string>& known_categories) {
   if (!BrowserThread::CurrentlyOn(BrowserThread::UI)) {
@@ -221,7 +286,7 @@ void TraceController::OnEndTracingAck(
     // called with the last of the local trace data. Since we are on the UI
     // thread, the call to OnTraceDataCollected will be synchronous, so we can
     // immediately call OnEndTracingComplete below.
-    base::debug::TraceLog::GetInstance()->SetEnabled(false);
+    TraceLog::GetInstance()->SetEnabled(false);
 
     // Trigger callback if one is set.
     if (subscriber_) {
@@ -240,7 +305,7 @@ void TraceController::OnEndTracingAck(
     // The last ack represents local trace, so we need to ack it now. Note that
     // this code only executes if there were child processes.
     std::vector<std::string> categories;
-    base::debug::TraceLog::GetInstance()->GetKnownCategories(&categories);
+    TraceLog::GetInstance()->GetKnownCategories(&categories);
     BrowserThread::PostTask(BrowserThread::UI, FROM_HERE,
         base::Bind(&TraceController::OnEndTracingAck, base::Unretained(this),
                    categories));
@@ -248,8 +313,7 @@ void TraceController::OnEndTracingAck(
 }
 
 void TraceController::OnTraceDataCollected(
-    const scoped_refptr<base::debug::TraceLog::RefCountedString>&
-        events_str_ptr) {
+    const scoped_refptr<TraceLog::RefCountedString>& events_str_ptr) {
   // OnTraceDataCollected may be called from any browser thread, either by the
   // local event trace system or from child processes via TraceMessageFilter.
   if (!BrowserThread::CurrentlyOn(BrowserThread::UI)) {
@@ -301,7 +365,7 @@ void TraceController::OnTraceBufferPercentFullReply(float percent_full) {
   if (pending_bpf_ack_count_ == 1) {
     // The last ack represents local trace, so we need to ack it now. Note that
     // this code only executes if there were child processes.
-    float bpf = base::debug::TraceLog::GetInstance()->GetBufferPercentFull();
+    float bpf = TraceLog::GetInstance()->GetBufferPercentFull();
     BrowserThread::PostTask(BrowserThread::UI, FROM_HERE,
         base::Bind(&TraceController::OnTraceBufferPercentFullReply,
                    base::Unretained(this), bpf));
diff --git a/content/browser/trace_controller.h b/content/browser/trace_controller.h
index b14ec6a..1677056 100644
--- a/content/browser/trace_controller.h
+++ b/content/browser/trace_controller.h
@@ -13,6 +13,7 @@
 #include "base/memory/singleton.h"
 #include "content/common/content_export.h"
 
+class CommandLine;
 class TraceMessageFilter;
 
 // Objects interested in receiving trace data derive from TraceSubscriber.
@@ -28,8 +29,11 @@ class CONTENT_EXPORT TraceSubscriber {
   virtual void OnTraceDataCollected(const std::string& trace_fragment) = 0;
   // Called once after TraceController::GetKnownCategoriesAsync.
   virtual void OnKnownCategoriesCollected(
-      const std::set<std::string>& known_categories) {}
-  virtual void OnTraceBufferPercentFullReply(float percent_full) {}
+      const std::set<std::string>& known_categories);
+  virtual void OnTraceBufferPercentFullReply(float percent_full);
+
+ protected:
+  virtual ~TraceSubscriber();
 };
 
 // TraceController is used on the browser processes to enable/disable
@@ -40,6 +44,10 @@ class CONTENT_EXPORT TraceController {
  public:
   static TraceController* GetInstance();
 
+  // Called on the main thread of the browser process to initialize
+  // startup tracing.
+  void InitStartupTracing(const CommandLine& command_line);
+
   // Get set of known categories. This can change as new code paths are reached.
   // If true is returned, subscriber->OnKnownCategoriesCollected will be called
   // when once the categories are retrieved from child processes.
@@ -134,14 +142,16 @@ class CONTENT_EXPORT TraceController {
         pending_bpf_ack_count_ == 0;
   }
 
-  bool can_begin_tracing() const { return !is_tracing_; }
+  bool can_begin_tracing(TraceSubscriber* subscriber) const {
+    return !is_tracing_ &&
+        (subscriber_ == NULL || subscriber == subscriber_);
+  }
 
   // Methods for use by TraceMessageFilter.
 
-  // Passing as scoped_refptr so that the method can be run asynchronously as
-  // a task safely (otherwise the TraceMessageFilter could be destructed).
   void AddFilter(TraceMessageFilter* filter);
   void RemoveFilter(TraceMessageFilter* filter);
+  void OnTracingBegan(TraceSubscriber* subscriber);
   void OnEndTracingAck(const std::vector<std::string>& known_categories);
   void OnTraceDataCollected(
       const scoped_refptr<base::debug::TraceLog::RefCountedString>&
diff --git a/content/browser/trace_subscriber_stdio.cc b/content/browser/trace_subscriber_stdio.cc
index 901aea0..0ecd51e 100644
--- a/content/browser/trace_subscriber_stdio.cc
+++ b/content/browser/trace_subscriber_stdio.cc
@@ -56,7 +56,7 @@ void TraceSubscriberStdio::OnTraceDataCollected(
 
 void TraceSubscriberStdio::Write(const std::string& output_str) {
   if (IsValid()) {
-    size_t written = fwrite(output_str.c_str(), 1, output_str.size(), file_);
+    size_t written = fwrite(output_str.data(), 1, output_str.size(), file_);
     if (written != output_str.size()) {
       LOG(ERROR) << "Error " << ferror(file_) << " when writing to trace file";
       CloseFile();
diff --git a/content/public/common/content_switches.cc b/content/public/common/content_switches.cc
index f76c637..8d9cf93 100644
--- a/content/public/common/content_switches.cc
+++ b/content/public/common/content_switches.cc
@@ -465,6 +465,29 @@ const char kSkipGpuDataLoading[]            = "skip-gpu-data-loading";
 // Runs the security test for the renderer sandbox.
 const char kTestSandbox[]                   = "test-sandbox";
 
+// 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
+// flag results in the first call to BeginTracing() to receive all trace events
+// since startup. In Chrome, you may find --trace-startup-file and
+// --trace-startup-duration to control the auto-saving of the trace (not
+// supported in the base-only TraceLog component).
+const char kTraceStartup[]                  = "trace-startup";
+
+// If supplied, sets the file which startup tracing will be stored into, if
+// omitted the default will be used "chrometrace.log" in the current directory.
+// Has no effect unless --trace-startup is also supplied.
+// Example: --trace-startup --trace-startup-file=/tmp/trace_event.log
+// As a special case, can be set to 'none' - this disables automatically saving
+// the result to a file and the first manually recorded trace will then receive
+// all events since startup.
+const char kTraceStartupFile[]              = "trace-startup-file";
+
+// Sets the time in seconds until startup tracing ends. If omitted a default of
+// 5 seconds is used. Has no effect without --trace-startup, or if
+// --startup-trace-file=none was supplied.
+const char kTraceStartupDuration[]          = "trace-startup-duration";
+
 // A string used to override the default user agent with a custom one.
 const char kUserAgent[]                     = "user-agent";
 
diff --git a/content/public/common/content_switches.h b/content/public/common/content_switches.h
index f1409e5..e8a05c9 100644
--- a/content/public/common/content_switches.h
+++ b/content/public/common/content_switches.h
@@ -148,6 +148,9 @@ extern const char kSimpleDataSource[];
 CONTENT_EXPORT extern const char kSingleProcess[];
 CONTENT_EXPORT extern const char kSkipGpuDataLoading[];
 CONTENT_EXPORT extern const char kTestSandbox[];
+extern const char kTraceStartup[];
+extern const char kTraceStartupFile[];
+extern const char kTraceStartupDuration[];
 extern const char kUnlimitedQuotaForFiles[];
 CONTENT_EXPORT extern const char kUserAgent[];
 extern const char kUtilityCmdPrefix[];