Add tracing and timing info to GN

This allows outputting a performance summary of time blame, as well as writing a chrome trace log.

Moves the help printing functions from command_help to standard_out since I re-used the coloring routines for timing output.

BUG=
R=scottmg@chromium.org

Review URL: https://codereview.chromium.org/24331007

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

14 files changed, 506 insertions, 68 deletions

diff --git a/tools/gn/BUILD.gn b/tools/gn/BUILD.gn
index 2c38661..e3d5301 100644
--- a/tools/gn/BUILD.gn
+++ b/tools/gn/BUILD.gn
@@ -129,6 +129,8 @@ static_library("gn_lib") {
     "toolchain.h",
     "toolchain_manager.cc",
     "toolchain_manager.h",
+    "trace.cc",
+    "trace.h",
     "value.cc",
     "value.h",
     "value_extractors.cc",
diff --git a/tools/gn/command_help.cc b/tools/gn/command_help.cc
index f378e80..954db12 100644
--- a/tools/gn/command_help.cc
+++ b/tools/gn/command_help.cc
@@ -5,7 +5,6 @@
 #include <algorithm>
 #include <iostream>
 
-#include "base/strings/string_split.h"
 #include "tools/gn/args.h"
 #include "tools/gn/commands.h"
 #include "tools/gn/err.h"
@@ -21,73 +20,6 @@ namespace commands {
 
 namespace {
 
-// Prints a line for a command, assuming there is a colon. Everything before
-// the colon is the command (and is highlighted). After the colon if there is
-// a square bracket, the contents of the bracket is dimmed.
-void PrintShortHelp(const std::string& line) {
-  size_t colon_offset = line.find(':');
-  size_t first_normal = 0;
-  if (colon_offset != std::string::npos) {
-    OutputString("  " + line.substr(0, colon_offset), DECORATION_YELLOW);
-    first_normal = colon_offset;
-  }
-
-  // See if the colon is followed by a " [" and if so, dim the contents of [ ].
-  if (first_normal > 0 &&
-      line.size() > first_normal + 2 &&
-      line[first_normal + 1] == ' ' && line[first_normal + 2] == '[') {
-    size_t begin_bracket = first_normal + 2;
-    OutputString(": ");
-    first_normal = line.find(']', begin_bracket);
-    if (first_normal == std::string::npos)
-      first_normal = line.size();
-    else
-      first_normal++;
-    OutputString(line.substr(begin_bracket, first_normal - begin_bracket),
-                 DECORATION_DIM);
-  }
-
-  OutputString(line.substr(first_normal) + "\n");
-}
-
-// Rules:
-// - Lines beginning with non-whitespace are highlighted up to the first
-//   colon (or the whole line if not).
-// - Lines whose first non-whitespace character is a # are dimmed.
-void PrintLongHelp(const std::string& text) {
-  std::vector<std::string> lines;
-  base::SplitStringDontTrim(text, '\n', &lines);
-
-  for (size_t i = 0; i < lines.size(); i++) {
-    const std::string& line = lines[i];
-
-    // Check for a heading line.
-    if (!line.empty() && line[0] != ' ') {
-      // Highlight up to the colon (if any).
-      size_t chars_to_highlight = line.find(':');
-      if (chars_to_highlight == std::string::npos)
-        chars_to_highlight = line.size();
-      OutputString(line.substr(0, chars_to_highlight), DECORATION_YELLOW);
-      OutputString(line.substr(chars_to_highlight) + "\n");
-      continue;
-    }
-
-    // Check for a comment.
-    TextDecoration dec = DECORATION_NONE;
-    for (size_t char_i = 0; char_i < line.size(); char_i++) {
-      if (line[char_i] == '#') {
-        // Got a comment, draw dimmed.
-        dec = DECORATION_DIM;
-        break;
-      } else if (line[char_i] != ' ') {
-        break;
-      }
-    }
-
-    OutputString(line + "\n", dec);
-  }
-}
-
 void PrintToplevelHelp() {
   OutputString("Commands (type \"gn help <command>\" for more details):\n");
 
@@ -114,6 +46,10 @@ void PrintToplevelHelp() {
   PrintShortHelp(
       "--secondary: Specifies secondary source root (overrides .gn file).");
   PrintShortHelp(
+      "--time: Outputs a summary of how long everything took.");
+  PrintShortHelp(
+      "--tracelog: Writes a Chrome-compatible trace log to the given file.");
+  PrintShortHelp(
       "-v: Verbose mode, print lots of logging.");
 
   // Functions.
diff --git a/tools/gn/function_exec_script.cc b/tools/gn/function_exec_script.cc
index c00579a..4a76199 100644
--- a/tools/gn/function_exec_script.cc
+++ b/tools/gn/function_exec_script.cc
@@ -18,6 +18,7 @@
 #include "tools/gn/input_file.h"
 #include "tools/gn/parse_tree.h"
 #include "tools/gn/scheduler.h"
+#include "tools/gn/trace.h"
 #include "tools/gn/value.h"
 
 #if defined(OS_WIN)
@@ -302,6 +303,9 @@ Value RunExecScript(Scope* scope,
     script_path = build_settings->GetFullPathSecondary(script_source);
   }
 
+  ScopedTrace trace(TraceItem::TRACE_SCRIPT_EXECUTE, script_source.value());
+  trace.SetToolchain(settings->toolchain()->label());
+
   // Add all dependencies of this script, including the script itself, to the
   // build deps.
   g_scheduler->AddGenDependency(script_path);
@@ -334,6 +338,7 @@ Value RunExecScript(Scope* scope,
   }
 
   // Log command line for debugging help.
+  trace.SetCommandLine(cmdline);
   base::TimeTicks begin_exec;
   if (g_scheduler->verbose_logging()) {
 #if defined(OS_WIN)
diff --git a/tools/gn/gn.gyp b/tools/gn/gn.gyp
index 52c928e..fb5a53e 100644
--- a/tools/gn/gn.gyp
+++ b/tools/gn/gn.gyp
@@ -139,6 +139,8 @@
         'toolchain.h',
         'toolchain_manager.cc',
         'toolchain_manager.h',
+        'trace.cc',
+        'trace.h',
         'value.cc',
         'value.h',
         'value_extractors.cc',
diff --git a/tools/gn/input_file_manager.cc b/tools/gn/input_file_manager.cc
index 1b55ea4..5e42118 100644
--- a/tools/gn/input_file_manager.cc
+++ b/tools/gn/input_file_manager.cc
@@ -11,6 +11,7 @@
 #include "tools/gn/scheduler.h"
 #include "tools/gn/scope_per_file_provider.h"
 #include "tools/gn/tokenizer.h"
+#include "tools/gn/trace.h"
 
 namespace {
 
@@ -203,6 +204,7 @@ bool InputFileManager::LoadFile(const LocationRange& origin,
 
   // Read.
   base::FilePath primary_path = build_settings->GetFullPath(name);
+  ScopedTrace load_trace(TraceItem::TRACE_FILE_LOAD, name.value());
   if (!file->Load(primary_path)) {
     if (!build_settings->secondary_source_path().empty()) {
       // Fall back to secondary source tree.
@@ -221,6 +223,9 @@ bool InputFileManager::LoadFile(const LocationRange& origin,
       return false;
     }
   }
+  load_trace.Done();
+
+  ScopedTrace exec_trace(TraceItem::TRACE_FILE_PARSE, name.value());
 
   // Tokenize.
   std::vector<Token> tokens = Tokenizer::Tokenize(file, err);
@@ -233,6 +238,8 @@ bool InputFileManager::LoadFile(const LocationRange& origin,
     return false;
   ParseNode* unowned_root = root.get();
 
+  exec_trace.Done();
+
   std::vector<FileLoadCallback> callbacks;
   {
     base::AutoLock lock(lock_);
diff --git a/tools/gn/ninja_build_writer.cc b/tools/gn/ninja_build_writer.cc
index 4000d0cd..6aa3cf2 100644
--- a/tools/gn/ninja_build_writer.cc
+++ b/tools/gn/ninja_build_writer.cc
@@ -17,6 +17,7 @@
 #include "tools/gn/input_file_manager.h"
 #include "tools/gn/scheduler.h"
 #include "tools/gn/target.h"
+#include "tools/gn/trace.h"
 
 #if defined(OS_WIN)
 #include <windows.h>
@@ -87,6 +88,8 @@ bool NinjaBuildWriter::RunAndWriteFile(
     const BuildSettings* build_settings,
     const std::vector<const Settings*>& all_settings,
     const std::vector<const Target*>& default_toolchain_targets) {
+  ScopedTrace trace(TraceItem::TRACE_FILE_WRITE, "build.ninja");
+
   base::FilePath ninja_file(build_settings->GetFullPath(
       SourceFile(build_settings->build_dir().value() + "build.ninja")));
   file_util::CreateDirectory(ninja_file.DirName());
diff --git a/tools/gn/ninja_target_writer.cc b/tools/gn/ninja_target_writer.cc
index 79cdc30..e384cd4 100644
--- a/tools/gn/ninja_target_writer.cc
+++ b/tools/gn/ninja_target_writer.cc
@@ -17,6 +17,7 @@
 #include "tools/gn/scheduler.h"
 #include "tools/gn/string_utils.h"
 #include "tools/gn/target.h"
+#include "tools/gn/trace.h"
 
 NinjaTargetWriter::NinjaTargetWriter(const Target* target, std::ostream& out)
     : settings_(target->settings()),
@@ -42,6 +43,10 @@ void NinjaTargetWriter::RunAndWriteFile(const Target* target) {
   const Settings* settings = target->settings();
   NinjaHelper helper(settings->build_settings());
 
+  ScopedTrace trace(TraceItem::TRACE_FILE_WRITE,
+                    target->label().GetUserVisibleName(false));
+  trace.SetToolchain(settings->toolchain()->label());
+
   base::FilePath ninja_file(settings->build_settings()->GetFullPath(
       helper.GetNinjaFileForTarget(target).GetSourceFile(
           settings->build_settings())));
diff --git a/tools/gn/ninja_toolchain_writer.cc b/tools/gn/ninja_toolchain_writer.cc
index 0a45e17..4afa460 100644
--- a/tools/gn/ninja_toolchain_writer.cc
+++ b/tools/gn/ninja_toolchain_writer.cc
@@ -13,6 +13,7 @@
 #include "tools/gn/settings.h"
 #include "tools/gn/target.h"
 #include "tools/gn/toolchain.h"
+#include "tools/gn/trace.h"
 
 NinjaToolchainWriter::NinjaToolchainWriter(
     const Settings* settings,
@@ -45,6 +46,8 @@ bool NinjaToolchainWriter::RunAndWriteFile(
   base::FilePath ninja_file(settings->build_settings()->GetFullPath(
       helper.GetNinjaFileForToolchain(settings).GetSourceFile(
           settings->build_settings())));
+  ScopedTrace trace(TraceItem::TRACE_FILE_WRITE, FilePathToUTF8(ninja_file));
+
   file_util::CreateDirectory(ninja_file.DirName());
 
   std::ofstream file;
diff --git a/tools/gn/setup.cc b/tools/gn/setup.cc
index 28f8ec6..b183468 100644
--- a/tools/gn/setup.cc
+++ b/tools/gn/setup.cc
@@ -13,7 +13,9 @@
 #include "tools/gn/parser.h"
 #include "tools/gn/source_dir.h"
 #include "tools/gn/source_file.h"
+#include "tools/gn/standard_out.h"
 #include "tools/gn/tokenizer.h"
+#include "tools/gn/trace.h"
 #include "tools/gn/value.h"
 
 extern const char kDotfile_Help[] =
@@ -63,6 +65,11 @@ const char kSwitchArgs[] = "args";
 // Set root dir.
 const char kSwitchRoot[] = "root";
 
+// Enable timing.
+const char kTimeSwitch[] = "time";
+
+const char kTracelogSwitch[] = "tracelog";
+
 // Set build output directory.
 const char kSwitchBuildOutput[] = "output";
 
@@ -99,6 +106,9 @@ bool Setup::DoSetup() {
   CommandLine* cmdline = CommandLine::ForCurrentProcess();
 
   scheduler_.set_verbose_logging(cmdline->HasSwitch(kSwitchVerbose));
+  if (cmdline->HasSwitch(kTimeSwitch) ||
+      cmdline->HasSwitch(kTracelogSwitch))
+    EnableTracing();
 
   if (!FillArguments(*cmdline))
     return false;
@@ -153,6 +163,14 @@ bool Setup::Run() {
     err.PrintToStdout();
     return false;
   }
+
+  // Write out tracing and timing if requested.
+  const CommandLine* cmdline = CommandLine::ForCurrentProcess();
+  if (cmdline->HasSwitch(kTimeSwitch))
+    PrintLongHelp(SummarizeTraces());
+  if (cmdline->HasSwitch(kTracelogSwitch))
+    SaveTraces(cmdline->GetSwitchValuePath(kTracelogSwitch));
+
   return true;
 }
 
diff --git a/tools/gn/standard_out.cc b/tools/gn/standard_out.cc
index 3b3ed77..0dfa96d3 100644
--- a/tools/gn/standard_out.cc
+++ b/tools/gn/standard_out.cc
@@ -4,6 +4,9 @@
 
 #include "tools/gn/standard_out.h"
 
+#include <vector>
+
+#include "base/strings/string_split.h"
 #include "build/build_config.h"
 
 #if defined(OS_WIN)
@@ -110,3 +113,64 @@ void OutputString(const std::string& output, TextDecoration dec) {
 }
 
 #endif
+
+void PrintShortHelp(const std::string& line) {
+  size_t colon_offset = line.find(':');
+  size_t first_normal = 0;
+  if (colon_offset != std::string::npos) {
+    OutputString("  " + line.substr(0, colon_offset), DECORATION_YELLOW);
+    first_normal = colon_offset;
+  }
+
+  // See if the colon is followed by a " [" and if so, dim the contents of [ ].
+  if (first_normal > 0 &&
+      line.size() > first_normal + 2 &&
+      line[first_normal + 1] == ' ' && line[first_normal + 2] == '[') {
+    size_t begin_bracket = first_normal + 2;
+    OutputString(": ");
+    first_normal = line.find(']', begin_bracket);
+    if (first_normal == std::string::npos)
+      first_normal = line.size();
+    else
+      first_normal++;
+    OutputString(line.substr(begin_bracket, first_normal - begin_bracket),
+                 DECORATION_DIM);
+  }
+
+  OutputString(line.substr(first_normal) + "\n");
+}
+
+void PrintLongHelp(const std::string& text) {
+  std::vector<std::string> lines;
+  base::SplitStringDontTrim(text, '\n', &lines);
+
+  for (size_t i = 0; i < lines.size(); i++) {
+    const std::string& line = lines[i];
+
+    // Check for a heading line.
+    if (!line.empty() && line[0] != ' ') {
+      // Highlight up to the colon (if any).
+      size_t chars_to_highlight = line.find(':');
+      if (chars_to_highlight == std::string::npos)
+        chars_to_highlight = line.size();
+      OutputString(line.substr(0, chars_to_highlight), DECORATION_YELLOW);
+      OutputString(line.substr(chars_to_highlight) + "\n");
+      continue;
+    }
+
+    // Check for a comment.
+    TextDecoration dec = DECORATION_NONE;
+    for (size_t char_i = 0; char_i < line.size(); char_i++) {
+      if (line[char_i] == '#') {
+        // Got a comment, draw dimmed.
+        dec = DECORATION_DIM;
+        break;
+      } else if (line[char_i] != ' ') {
+        break;
+      }
+    }
+
+    OutputString(line + "\n", dec);
+  }
+}
+
diff --git a/tools/gn/standard_out.h b/tools/gn/standard_out.h
index d3d3b51..9ccbe52 100644
--- a/tools/gn/standard_out.h
+++ b/tools/gn/standard_out.h
@@ -19,4 +19,17 @@ enum TextDecoration {
 void OutputString(const std::string& output,
                   TextDecoration dec = DECORATION_NONE);
 
+// Prints a line for a command, assuming there is a colon. Everything before
+// the colon is the command (and is highlighted). After the colon if there is
+// a square bracket, the contents of the bracket is dimmed.
+//
+// The line is indented 2 spaces.
+void PrintShortHelp(const std::string& line);
+
+// Rules:
+// - Lines beginning with non-whitespace are highlighted up to the first
+//   colon (or the whole line if not).
+// - Lines whose first non-whitespace character is a # are dimmed.
+void PrintLongHelp(const std::string& text);
+
 #endif  // TOOLS_GN_STANDARD_OUT_H_
diff --git a/tools/gn/toolchain_manager.cc b/tools/gn/toolchain_manager.cc
index bd70baa..affdec9 100644
--- a/tools/gn/toolchain_manager.cc
+++ b/tools/gn/toolchain_manager.cc
@@ -16,6 +16,7 @@
 #include "tools/gn/scheduler.h"
 #include "tools/gn/scope.h"
 #include "tools/gn/scope_per_file_provider.h"
+#include "tools/gn/trace.h"
 
 // How toolchain loading works
 // ---------------------------
@@ -492,10 +493,16 @@ void ToolchainManager::BackgroundLoadBuildConfig(Info* info,
     if (is_default)
       base_config->SetProcessingDefaultBuildConfig();
 
+    ScopedTrace trace(TraceItem::TRACE_FILE_EXECUTE,
+        info->settings.build_settings()->build_config_file().value());
+    trace.SetToolchain(info->settings.toolchain()->label());
+
     const BlockNode* root_block = root->AsBlock();
     Err err;
     root_block->ExecuteBlockInScope(base_config, &err);
 
+    trace.Done();
+
     base_config->ClearProcessingBuildConfig();
     if (is_default)
       base_config->ClearProcessingDefaultBuildConfig();
@@ -540,11 +547,16 @@ void ToolchainManager::BackgroundInvoke(const Info* info,
     ScopePerFileProvider per_file_provider(&our_scope);
     our_scope.set_source_dir(file_name.GetDir());
 
+    ScopedTrace trace(TraceItem::TRACE_FILE_EXECUTE, file_name.value());
+    trace.SetToolchain(info->settings.toolchain()->label());
+
     Err err;
     root->Execute(&our_scope, &err);
     if (err.has_error())
       g_scheduler->FailWithError(err);
 
+    trace.Done();
+
     {
       // Check to see if any build config invocations depend on this file and
       // invoke them.
diff --git a/tools/gn/trace.cc b/tools/gn/trace.cc
new file mode 100644
index 0000000..34944fd
--- /dev/null
+++ b/tools/gn/trace.cc
@@ -0,0 +1,275 @@
+// Copyright (c) 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 "tools/gn/trace.h"
+
+#include <algorithm>
+#include <map>
+#include <sstream>
+#include <vector>
+
+#include "base/file_util.h"
+#include "base/json/string_escape.h"
+#include "base/logging.h"
+#include "base/strings/stringprintf.h"
+#include "base/synchronization/lock.h"
+#include "tools/gn/filesystem_utils.h"
+#include "tools/gn/label.h"
+
+namespace {
+
+class TraceLog {
+ public:
+  TraceLog() {
+    events_.reserve(16384);
+  }
+  ~TraceLog() {
+    // Trace items leanked intentionally.
+  }
+
+  void Add(TraceItem* item) {
+    base::AutoLock lock(lock_);
+    events_.push_back(item);
+  }
+
+  // Returns a copy for threadsafety.
+  std::vector<TraceItem*> events() const { return events_; }
+
+ private:
+  base::Lock lock_;
+
+  std::vector<TraceItem*> events_;
+
+  DISALLOW_COPY_AND_ASSIGN(TraceLog);
+};
+
+TraceLog* trace_log = NULL;
+
+struct Coalesced {
+  Coalesced() : name_ptr(NULL), total_duration(0.0), count(0) {}
+
+  const std::string* name_ptr;  // Pointer to a string with the name in it.
+  double total_duration;
+  int count;
+};
+
+bool DurationGreater(const TraceItem* a, const TraceItem* b) {
+  return a->delta() > b->delta();
+}
+
+bool CoalescedDurationGreater(const Coalesced& a, const Coalesced& b) {
+  return a.total_duration > b.total_duration;
+}
+
+void SummarizeParses(std::vector<const TraceItem*>& loads,
+                     std::ostream& out) {
+  out << "File parse times: (time in ms, name)\n";
+
+  std::sort(loads.begin(), loads.end(), &DurationGreater);
+
+  for (size_t i = 0; i < loads.size(); i++) {
+    out << base::StringPrintf(" %8.2f  ",
+                              loads[i]->delta().InMillisecondsF());
+    out << loads[i]->name() << std::endl;
+  }
+}
+
+void SummarizeCoalesced(std::vector<const TraceItem*>& items,
+                        std::ostream& out) {
+  // Group by file name.
+  std::map<std::string, Coalesced> coalesced;
+  for (size_t i = 0; i < items.size(); i++) {
+    Coalesced& c = coalesced[items[i]->name()];
+    c.name_ptr = &items[i]->name();
+    c.total_duration += items[i]->delta().InMillisecondsF();
+    c.count++;
+  }
+
+  // Sort by duration.
+  std::vector<Coalesced> sorted;
+  for (std::map<std::string, Coalesced>::iterator iter = coalesced.begin();
+       iter != coalesced.end(); ++iter)
+    sorted.push_back(iter->second);
+  std::sort(sorted.begin(), sorted.end(), &CoalescedDurationGreater);
+
+  for (size_t i = 0; i < sorted.size(); i++) {
+    out << base::StringPrintf(" %8.2f  %d  ",
+                              sorted[i].total_duration, sorted[i].count);
+    out << *sorted[i].name_ptr << std::endl;
+  }
+}
+
+void SummarizeFileExecs(std::vector<const TraceItem*>& execs,
+                        std::ostream& out) {
+  out << "File execute times: (total time in ms, # executions, name)\n";
+  SummarizeCoalesced(execs, out);
+}
+
+void SummarizeScriptExecs(std::vector<const TraceItem*>& execs,
+                          std::ostream& out) {
+  out << "Script execute times: (total time in ms, # executions, name)\n";
+  SummarizeCoalesced(execs, out);
+}
+
+}  // namespace
+
+TraceItem::TraceItem(Type type,
+                     const std::string& name,
+                     base::PlatformThreadId thread_id)
+    : type_(type),
+      name_(name),
+      thread_id_(thread_id) {
+}
+
+TraceItem::~TraceItem() {
+}
+
+ScopedTrace::ScopedTrace(TraceItem::Type t, const std::string& name)
+    : item_(NULL),
+      done_(false) {
+  if (trace_log) {
+    item_ = new TraceItem(t, name, base::PlatformThread::CurrentId());
+    item_->set_begin(base::TimeTicks::HighResNow());
+  }
+}
+
+ScopedTrace::~ScopedTrace() {
+  Done();
+}
+
+void ScopedTrace::SetToolchain(const Label& label) {
+  if (item_)
+    item_->set_toolchain(label.GetUserVisibleName(false));
+}
+
+void ScopedTrace::SetCommandLine(const CommandLine& cmdline) {
+  if (item_)
+    item_->set_cmdline(FilePathToUTF8(cmdline.GetArgumentsString()));
+}
+
+void ScopedTrace::Done() {
+  if (!done_) {
+    done_ = true;
+    if (trace_log) {
+      item_->set_end(base::TimeTicks::HighResNow());
+      AddTrace(item_);
+    }
+  }
+}
+
+void EnableTracing() {
+  CHECK(!trace_log);
+  trace_log = new TraceLog;
+}
+
+void AddTrace(TraceItem* item) {
+  trace_log->Add(item);
+}
+
+std::string SummarizeTraces() {
+  if (!trace_log)
+    return std::string();
+
+  std::vector<TraceItem*> events = trace_log->events();
+
+  // Classify all events.
+  std::vector<const TraceItem*> parses;
+  std::vector<const TraceItem*> file_execs;
+  std::vector<const TraceItem*> script_execs;
+  for (size_t i = 0; i < events.size(); i++) {
+    switch (events[i]->type()) {
+      case TraceItem::TRACE_FILE_PARSE:
+        parses.push_back(events[i]);
+        break;
+      case TraceItem::TRACE_FILE_EXECUTE:
+        file_execs.push_back(events[i]);
+        break;
+      case TraceItem::TRACE_SCRIPT_EXECUTE:
+        script_execs.push_back(events[i]);
+        break;
+      case TraceItem::TRACE_FILE_LOAD:
+      case TraceItem::TRACE_FILE_WRITE:
+        break;  // Ignore these for the summary.
+    }
+  }
+
+  std::ostringstream out;
+  SummarizeParses(parses, out);
+  out << std::endl;
+  SummarizeFileExecs(file_execs, out);
+  out << std::endl;
+  SummarizeScriptExecs(script_execs, out);
+  out << std::endl;
+
+  return out.str();
+}
+
+void SaveTraces(const base::FilePath& file_name) {
+  std::ostringstream out;
+
+  out << "{\"traceEvents\":[";
+
+  std::string quote_buffer;  // Allocate outside loop to prevent reallocationg.
+
+  std::vector<TraceItem*> events = trace_log->events();
+  for (size_t i = 0; i < events.size(); i++) {
+    const TraceItem& item = *events[i];
+
+    if (i != 0)
+      out << ",";
+    out << "{\"pid\":0,\"tid\":" << item.thread_id();
+    out << ",\"ts\":" << item.begin().ToInternalValue();
+    out << ",\"ph\":\"X\"";  // "X" = complete event with begin & duration.
+    out << ",\"dur\":" << item.delta().InMicroseconds();
+
+    quote_buffer.resize(0);
+    base::JsonDoubleQuote(item.name(), true, &quote_buffer);
+    out << ",\"name\":" << quote_buffer;
+
+    out << ",\"cat\":";
+    switch (item.type()) {
+      case TraceItem::TRACE_FILE_LOAD:
+        out << "\"load\"";
+        break;
+      case TraceItem::TRACE_FILE_PARSE:
+        out << "\"parse\"";
+        break;
+      case TraceItem::TRACE_FILE_EXECUTE:
+        out << "\"file_exec\"";
+        break;
+      case TraceItem::TRACE_FILE_WRITE:
+        out << "\"file_write\"";
+        break;
+      case TraceItem::TRACE_SCRIPT_EXECUTE:
+        out << "\"script_exec\"";
+        break;
+    }
+
+    if (!item.toolchain().empty() || !item.cmdline().empty()) {
+      out << ",\"args\":{";
+      bool needs_comma = false;
+      if (!item.toolchain().empty()) {
+        quote_buffer.resize(0);
+        base::JsonDoubleQuote(item.toolchain(), true, &quote_buffer);
+        out << "\"toolchain\":" << quote_buffer;
+        needs_comma = true;
+      }
+      if (!item.cmdline().empty()) {
+        quote_buffer.resize(0);
+        base::JsonDoubleQuote(item.cmdline(), true, &quote_buffer);
+        if (needs_comma)
+          out << ",";
+        out << "\"cmdline\":" << quote_buffer;
+        needs_comma = true;
+      }
+      out << "}";
+    }
+    out << "}";
+  }
+
+  out << "]}";
+
+  std::string out_str = out.str();
+  file_util::WriteFile(file_name, out_str.data(), out_str.size());
+}
diff --git a/tools/gn/trace.h b/tools/gn/trace.h
new file mode 100644
index 0000000..dcd8060
--- /dev/null
+++ b/tools/gn/trace.h
@@ -0,0 +1,93 @@
+// Copyright (c) 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 TOOLS_GN_TRACE_H_
+#define TOOLS_GN_TRACE_H_
+
+#include <string>
+
+#include "base/basictypes.h"
+#include "base/command_line.h"
+#include "base/files/file_path.h"
+#include "base/memory/scoped_ptr.h"
+#include "base/threading/platform_thread.h"
+#include "base/time/time.h"
+
+class Label;
+
+class TraceItem {
+ public:
+  enum Type {
+    TRACE_FILE_LOAD,
+    TRACE_FILE_PARSE,
+    TRACE_FILE_EXECUTE,
+    TRACE_FILE_WRITE,
+    TRACE_SCRIPT_EXECUTE
+  };
+
+  TraceItem(Type type,
+            const std::string& name,
+            base::PlatformThreadId thread_id);
+  ~TraceItem();
+
+  Type type() const { return type_; }
+  const std::string& name() const { return name_; }
+  base::PlatformThreadId thread_id() const { return thread_id_; }
+
+  base::TimeTicks begin() const { return begin_; }
+  void set_begin(base::TimeTicks b) { begin_ = b; }
+  base::TimeTicks end() const { return end_; }
+  void set_end(base::TimeTicks e) { end_ = e; }
+
+  base::TimeDelta delta() const { return end_ - begin_; }
+
+  // Optional toolchain label.
+  const std::string& toolchain() const { return toolchain_; }
+  void set_toolchain(const std::string& t) { toolchain_ = t; }
+
+  // Optional command line.
+  const std::string& cmdline() const { return cmdline_; }
+  void set_cmdline(const std::string& c) { cmdline_ = c; }
+
+ private:
+  Type type_;
+  std::string name_;
+  base::PlatformThreadId thread_id_;
+
+  base::TimeTicks begin_;
+  base::TimeTicks end_;
+
+  std::string toolchain_;
+  std::string cmdline_;
+};
+
+class ScopedTrace {
+ public:
+  ScopedTrace(TraceItem::Type t, const std::string& name);
+  ~ScopedTrace();
+
+  void SetToolchain(const Label& label);
+  void SetCommandLine(const CommandLine& cmdline);
+
+  void Done();
+
+ private:
+  TraceItem* item_;
+  bool done_;
+};
+
+// Call to turn tracing on. It's off by default.
+void EnableTracing();
+
+// Adds a trace event to the log. Takes ownership of the pointer.
+void AddTrace(TraceItem* item);
+
+// Returns a summary of the current traces, or the empty string if tracing is
+// not enabled.
+std::string SummarizeTraces();
+
+// Saves the current traces to the given filename in JSON format.
+void SaveTraces(const base::FilePath& file_name);
+
+#endif  // TOOLS_GN_TRACE_H_