From d5165bafdabbfba23d33a5e0ceb9e0e680384183 Mon Sep 17 00:00:00 2001 From: Evan Martin Date: Thu, 5 Jan 2012 13:35:47 -0800 Subject: 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. --- configure.py | 1 + src/graph.cc | 3 ++ src/metrics.cc | 108 +++++++++++++++++++++++++++++++++++++++++++++++++++++++++ src/metrics.h | 64 ++++++++++++++++++++++++++++++++++ src/ninja.cc | 31 +++++++++++++++-- src/parsers.cc | 2 ++ 6 files changed, 206 insertions(+), 3 deletions(-) create mode 100644 src/metrics.cc create mode 100644 src/metrics.h 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 +#include +#include + +#ifndef WIN32 +#include +#else +#include +#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::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 +#include +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 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 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 #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 (;;) { -- cgit v0.12