add a '-d stats' flag for detailed timings

1) Add a system for recording detailed timing info of functions.
2) Add a -d flag for requesting debug info at runtime, with the
   above as the first user.

6 files changed, 206 insertions, 3 deletions

diff --git a/configure.py b/configure.py
index 8f4ec24..b8ff1f5 100755
--- a/configure.py
+++ b/configure.py
@@ -212,6 +212,7 @@ for name in ['build',
              'graph',
              'graphviz',
              'lexer',
+             'metrics',
              'parsers',
              'state',
              'util']:
diff --git a/src/graph.cc b/src/graph.cc
index eb107f2..5c7507a 100644
--- a/src/graph.cc
+++ b/src/graph.cc
@@ -20,11 +20,13 @@
 #include "build_log.h"
 #include "depfile_parser.h"
 #include "disk_interface.h"
+#include "metrics.h"
 #include "parsers.h"
 #include "state.h"
 #include "util.h"
 
 bool Node::Stat(DiskInterface* disk_interface) {
+  METRIC_RECORD("node stat");
   mtime_ = disk_interface->Stat(path_);
   return mtime_ > 0;
 }
@@ -219,6 +221,7 @@ string Edge::GetDescription() {
 
 bool Edge::LoadDepFile(State* state, DiskInterface* disk_interface,
                        string* err) {
+  METRIC_RECORD("depfile load");
   string path = EvaluateDepFile();
   string content = disk_interface->ReadFile(path, err);
   if (!err->empty())
diff --git a/src/metrics.cc b/src/metrics.cc
new file mode 100644
index 0000000..07caade
--- /dev/null
+++ b/src/metrics.cc
@@ -0,0 +1,108 @@
+// Copyright 2011 Google Inc. All Rights Reserved.
+//
+// Licensed under the Apache License, Version 2.0 (the "License");
+// you may not use this file except in compliance with the License.
+// You may obtain a copy of the License at
+//
+//     http://www.apache.org/licenses/LICENSE-2.0
+//
+// Unless required by applicable law or agreed to in writing, software
+// distributed under the License is distributed on an "AS IS" BASIS,
+// WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
+// See the License for the specific language governing permissions and
+// limitations under the License.
+
+#include "metrics.h"
+
+#include <errno.h>
+#include <stdio.h>
+#include <string.h>
+
+#ifndef WIN32
+#include <sys/time.h>
+#else
+#include <windows.h>
+#endif
+
+#include "util.h"
+
+Metrics* g_metrics = NULL;
+
+namespace {
+
+#ifndef WIN32
+/// Compute a platform-specific high-res timer value that fits into an int64.
+int64_t HighResTimer() {
+  timeval tv;
+  if (gettimeofday(&tv, NULL) < 0)
+    Fatal("gettimeofday: %s", strerror(errno));
+  return (int64_t)tv.tv_sec * 1000*1000 + tv.tv_usec;
+}
+
+/// Convert a delta of HighResTimer() values to microseconds.
+int64_t TimerToMicros(int64_t dt) {
+  // No conversion necessary.
+  return dt;
+}
+#else
+int64_t LargeIntegerToInt64(const LARGE_INTEGER& i) {
+  return ((int64_t)i.HighPart) << 32 | i.LowPart;
+}
+
+int64_t HighResTimer() {
+  LARGE_INTEGER counter;
+  if (!QueryPerformanceCounter(&counter))
+    Fatal("QueryPerformanceCounter: %s", GetLastErrorString().c_str());
+  return LargeIntegerToInt64(counter);
+}
+
+int64_t TimerToMicros(int64_t dt) {
+  static int64_t ticks_per_sec = 0;
+  if (!ticks_per_sec) {
+    LARGE_INTEGER freq;
+    if (!QueryPerformanceFrequency(&freq))
+      Fatal("QueryPerformanceFrequency: %s", GetLastErrorString().c_str());
+    ticks_per_sec = LargeIntegerToInt64(freq);
+  }
+
+  // dt is in ticks.  We want microseconds.
+  return (dt * 1000000) / ticks_per_sec;
+}
+#endif
+
+}  // anonymous namespace
+
+ScopedMetric::ScopedMetric(Metric* metric) {
+  metric_ = metric;
+  if (!metric_)
+    return;
+  start_ = HighResTimer();
+}
+ScopedMetric::~ScopedMetric() {
+  if (!metric_)
+    return;
+  metric_->count++;
+  int64_t dt = TimerToMicros(HighResTimer() - start_);
+  metric_->sum += dt;
+}
+
+Metric* Metrics::NewMetric(const string& name) {
+  Metric* metric = new Metric;
+  metric->name = name;
+  metric->count = 0;
+  metric->sum = 0;
+  metrics_.push_back(metric);
+  return metric;
+}
+
+void Metrics::Report() {
+  printf("%-10s\t%-6s\t%9s\t%s\n",
+         "metric", "count", "total (ms)" , "avg (us)");
+  for (vector<Metric*>::iterator i = metrics_.begin(); i != metrics_.end(); ++i) {
+    Metric* metric = *i;
+    double total = metric->sum / (double)1000;
+    double avg = metric->sum / (double)metric->count;
+    printf("%-10s\t%-6d\t%-8.1f\t%.1f\n", metric->name.c_str(),
+           metric->count, total, avg);
+  }
+}
diff --git a/src/metrics.h b/src/metrics.h
new file mode 100644
index 0000000..74f5f8f
--- /dev/null
+++ b/src/metrics.h
@@ -0,0 +1,64 @@
+// Copyright 2011 Google Inc. All Rights Reserved.
+//
+// Licensed under the Apache License, Version 2.0 (the "License");
+// you may not use this file except in compliance with the License.
+// You may obtain a copy of the License at
+//
+//     http://www.apache.org/licenses/LICENSE-2.0
+//
+// Unless required by applicable law or agreed to in writing, software
+// distributed under the License is distributed on an "AS IS" BASIS,
+// WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
+// See the License for the specific language governing permissions and
+// limitations under the License.
+
+#include <string>
+#include <vector>
+using namespace std;
+
+#include "util.h"  // For int64_t.
+
+/// The Metrics module is used for the debug mode that dumps timing stats of
+/// various actions.  To use, see METRIC_RECORD below.
+
+/// A single metrics we're tracking, like "depfile load time".
+struct Metric {
+  string name;
+  /// Number of times we've hit the code path.
+  int count;
+  /// Total time (in micros) we've spent on the code path.
+  int64_t sum;
+};
+
+/// A scoped object for recording a metric across the body of a function.
+/// Used by the METRIC_RECORD macro.
+struct ScopedMetric {
+  explicit ScopedMetric(Metric* metric);
+  ~ScopedMetric();
+
+private:
+  Metric* metric_;
+  /// Timestamp when the measurement started.
+  /// Value is platform-dependent.
+  int64_t start_;
+};
+
+/// The singleton that stores metrics and prints the report.
+struct Metrics {
+  Metric* NewMetric(const string& name);
+
+  /// Print a summary report to stdout.
+  void Report();
+
+private:
+  vector<Metric*> metrics_;
+};
+
+/// The primary interface to metrics.  Use METRIC_RECORD("foobar") at the top
+/// of a function to get timing stats recorded for each call of the function.
+#define METRIC_RECORD(name)                                             \
+  static Metric* metrics_h_metric =                                     \
+      g_metrics ? g_metrics->NewMetric(name) : NULL;                    \
+  ScopedMetric metrics_h_scoped(metrics_h_metric);
+
+extern Metrics* g_metrics;
diff --git a/src/ninja.cc b/src/ninja.cc
index a55bfc4..3f76e9c 100644
--- a/src/ninja.cc
+++ b/src/ninja.cc
@@ -39,6 +39,7 @@
 #include "edit_distance.h"
 #include "graph.h"
 #include "graphviz.h"
+#include "metrics.h"
 #include "parsers.h"
 #include "state.h"
 #include "util.h"
@@ -85,6 +86,7 @@ void Usage(const BuildConfig& config) {
 "  -n       dry run (don't run commands but pretend they succeeded)\n"
 "  -v       show all command lines while building\n"
 "\n"
+"  -d MODE  enable debugging (use -d list to list modes)\n"
 "  -t TOOL  run a subtool\n"
 "    use '-t list' to list subtools.\n"
 "    terminates toplevel options; further flags are passed to the tool.\n",
@@ -517,6 +519,23 @@ int RunTool(const string& tool, Globals* globals, int argc, char** argv) {
   return 1;
 }
 
+/// Enable a debugging mode.  Returns false if Ninja should exit instead
+/// of continuing.
+bool DebugEnable(const string& name, Globals* globals) {
+  if (name == "list") {
+    printf("debugging modes:\n"
+"  stats  print operation counts/timing info\n");
+//"multiple modes can be enabled via -d FOO -d BAR\n");
+    return false;
+  } else if (name == "stats") {
+    g_metrics = new Metrics;
+    return true;
+  } else {
+    printf("ninja: unknown debug setting '%s'\n", name.c_str());
+    return false;
+  }
+}
+
 int RunBuild(Globals* globals, int argc, char** argv) {
   string err;
   vector<Node*> targets;
@@ -551,7 +570,6 @@ int RunBuild(Globals* globals, int argc, char** argv) {
   return 0;
 }
 
-
 }  // anonymous namespace
 
 int main(int argc, char** argv) {
@@ -572,9 +590,13 @@ int main(int argc, char** argv) {
 
   int opt;
   while (tool.empty() &&
-         (opt = getopt_long(argc, argv, "f:hj:k:nt:vC:", kLongOptions,
+         (opt = getopt_long(argc, argv, "d:f:hj:k:nt:vC:", kLongOptions,
                             NULL)) != -1) {
     switch (opt) {
+      case 'd':
+        if (!DebugEnable(optarg, &globals))
+          return 1;
+        break;
       case 'f':
         input_file = optarg;
         break;
@@ -680,5 +702,8 @@ reload:
     }
   }
 
-  return RunBuild(&globals, argc, argv);
+  int result = RunBuild(&globals, argc, argv);
+  if (g_metrics)
+    g_metrics->Report();
+  return result;
 }
diff --git a/src/parsers.cc b/src/parsers.cc
index e310c90..c1badd8 100644
--- a/src/parsers.cc
+++ b/src/parsers.cc
@@ -20,6 +20,7 @@
 #include <string.h>
 
 #include "graph.h"
+#include "metrics.h"
 #include "state.h"
 #include "util.h"
 
@@ -40,6 +41,7 @@ bool ManifestParser::Load(const string& filename, string* err) {
 
 bool ManifestParser::Parse(const string& filename, const string& input,
                            string* err) {
+  METRIC_RECORD(".ninja parse");
   lexer_.Start(filename, input);
 
   for (;;) {