From c0c5ef9bffb0130e169aeddcb8487b670c6b56fe Mon Sep 17 00:00:00 2001 From: Peter Kuemmel Date: Fri, 29 Jun 2012 16:12:03 +0200 Subject: print edges per second prints the rate of finished edges per second to the console, for instance with NINJA_STATUS="[%s/%t %o(%c)/s] ": [132/1922 16.1(14)/s] 16.1 is the average for all processed files (here 132 since start) 14 is the average of the last n files while n is the number specifies by -j (or its default) --- doc/manual.asciidoc | 2 ++ src/build.cc | 28 +++++++++++++++++++++++++++- src/build.h | 35 +++++++++++++++++++++++++++++++++++ src/build_log_perftest.cc | 1 + src/canon_perftest.cc | 1 + src/metrics.cc | 10 ++++++++++ src/metrics.h | 25 +++++++++++++++++++++++++ src/parser_perftest.cc | 1 + src/util.cc | 10 ---------- src/util.h | 5 ----- 10 files changed, 102 insertions(+), 16 deletions(-) diff --git a/doc/manual.asciidoc b/doc/manual.asciidoc index e7983be..94744be 100644 --- a/doc/manual.asciidoc +++ b/doc/manual.asciidoc @@ -218,6 +218,8 @@ Several placeholders are available: * `%r`: The number of currently running edges. * `%u`: The number of remaining edges to start. * `%f`: The number of finished edges. +* `%o`: Overall rate of finished edges per second +* `%c`: Current rate of finished edges per second (average over builds specified by -j or its default) * `%%`: A plain `%` character. * The default progress status is `"[%s/%t] "` (note the trailing space to separate from the build rule). Another example of possible progress status diff --git a/src/build.cc b/src/build.cc index 0fc387c..48e5c4b 100644 --- a/src/build.cc +++ b/src/build.cc @@ -37,7 +37,9 @@ BuildStatus::BuildStatus(const BuildConfig& config) : config_(config), start_time_millis_(GetTimeMillis()), started_edges_(0), finished_edges_(0), total_edges_(0), - have_blank_line_(true), progress_status_format_(NULL) { + have_blank_line_(true), progress_status_format_(NULL), + overall_rate_(), current_rate_(), + current_rate_average_count_(config.parallelism) { #ifndef _WIN32 const char* term = getenv("TERM"); smart_terminal_ = isatty(1) && term && string(term) != "dumb"; @@ -171,6 +173,25 @@ string BuildStatus::FormatProgressStatus(const char* progress_status_format) con out += buf; break; + // Overall finished edges per second. + case 'o': + overall_rate_.UpdateRate(finished_edges_, finished_edges_); + overall_rate_.snprinfRate(buf, "%.1f"); + out += buf; + break; + + // Current rate, average over the last '-j' jobs. + case 'c': + // TODO use sliding window? + if (finished_edges_ > current_rate_.last_update() && + finished_edges_ - current_rate_.last_update() == current_rate_average_count_) { + current_rate_.UpdateRate(current_rate_average_count_, finished_edges_); + current_rate_.Restart(); + } + current_rate_.snprinfRate(buf, "%.0f"); + out += buf; + break; + default: { Fatal("unknown placeholder '%%%c' in $NINJA_STATUS", *s); return ""; @@ -208,6 +229,10 @@ void BuildStatus::PrintStatus(Edge* edge) { #endif } + if (finished_edges_ == 0) { + overall_rate_.Restart(); + current_rate_.Restart(); + } to_print = FormatProgressStatus(progress_status_format_) + to_print; if (smart_terminal_ && !force_full_command) { @@ -770,3 +795,4 @@ void Builder::FinishEdge(Edge* edge, bool success, const string& output) { if (success && log_) log_->RecordCommand(edge, start_time, end_time, restat_mtime); } + diff --git a/src/build.h b/src/build.h index c9ee4ac..4859c29 100644 --- a/src/build.h +++ b/src/build.h @@ -24,6 +24,7 @@ using namespace std; #include "exit_status.h" +#include "metrics.h" #include "util.h" // int64_t struct BuildLog; @@ -191,9 +192,43 @@ struct BuildStatus { /// The custom progress status format to use. const char* progress_status_format_; + struct RateInfo { + RateInfo() : last_update_(0), rate_(-1) {} + + double rate() const { return rate_; } + int last_update() const { return last_update_; } + void Restart() { return stopwatch_.Restart(); } + + double UpdateRate(int edges, int update_hint) { + if (update_hint != last_update_) { + rate_ = edges / stopwatch_.Elapsed() + 0.5; + last_update_ = update_hint; + } + return rate_; + } + + template + void snprinfRate(T buf, const char* format) { + if (rate_ == -1) + snprintf(buf, sizeof(buf), "?"); + else + snprintf(buf, sizeof(buf), format, rate_); + } + + private: + Stopwatch stopwatch_; + int last_update_; + double rate_; + }; + + mutable RateInfo overall_rate_; + mutable RateInfo current_rate_; + const int current_rate_average_count_; + #ifdef _WIN32 void* console_; #endif }; #endif // NINJA_BUILD_H_ + diff --git a/src/build_log_perftest.cc b/src/build_log_perftest.cc index 02f4c60..5755079 100644 --- a/src/build_log_perftest.cc +++ b/src/build_log_perftest.cc @@ -20,6 +20,7 @@ #include "manifest_parser.h" #include "state.h" #include "util.h" +#include "metrics.h" const char kTestFilename[] = "BuildLogPerfTest-tempfile"; diff --git a/src/canon_perftest.cc b/src/canon_perftest.cc index 6248937..d0ed397 100644 --- a/src/canon_perftest.cc +++ b/src/canon_perftest.cc @@ -16,6 +16,7 @@ #include #include "util.h" +#include "metrics.h" const char kPath[] = "../../third_party/WebKit/Source/WebCore/" diff --git a/src/metrics.cc b/src/metrics.cc index fb44868..8407717 100644 --- a/src/metrics.cc +++ b/src/metrics.cc @@ -72,6 +72,7 @@ int64_t TimerToMicros(int64_t dt) { } // anonymous namespace + ScopedMetric::ScopedMetric(Metric* metric) { metric_ = metric; if (!metric_) @@ -113,3 +114,12 @@ void Metrics::Report() { metric->count, avg, total); } } + +uint64_t Stopwatch::Now() const { + return TimerToMicros(HighResTimer()); +} + +int64_t GetTimeMillis() { + return 1000 * TimerToMicros(HighResTimer()); +} + diff --git a/src/metrics.h b/src/metrics.h index af6e9a2..dae6b9f 100644 --- a/src/metrics.h +++ b/src/metrics.h @@ -33,6 +33,7 @@ struct Metric { int64_t sum; }; + /// A scoped object for recording a metric across the body of a function. /// Used by the METRIC_RECORD macro. struct ScopedMetric { @@ -57,6 +58,30 @@ private: vector metrics_; }; +/// Get the current time as relative to some epoch. +/// Epoch varies between platforms; only useful for measuring elapsed +/// time. +int64_t GetTimeMillis(); + + +/// A simple stopwatch which retruns the time +// in seconds since Restart() was called +class Stopwatch +{ +public: + Stopwatch() : started_(0) {} + + /// Seconds since Restart() call + double Elapsed() const { return 1e-6 * (Now() - started_); } + + void Restart() { started_ = Now(); } + +private: + uint64_t started_; + uint64_t Now() const; +}; + + /// 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) \ diff --git a/src/parser_perftest.cc b/src/parser_perftest.cc index b1d5bf0..b215221 100644 --- a/src/parser_perftest.cc +++ b/src/parser_perftest.cc @@ -17,6 +17,7 @@ #include "depfile_parser.h" #include "util.h" +#include "metrics.h" int main(int argc, char* argv[]) { if (argc < 2) { diff --git a/src/util.cc b/src/util.cc index d8d7fb3..ab3275a 100644 --- a/src/util.cc +++ b/src/util.cc @@ -204,16 +204,6 @@ void SetCloseOnExec(int fd) { #endif // ! _WIN32 } -int64_t GetTimeMillis() { -#ifdef _WIN32 - // GetTickCount64 is only available on Vista or later. - return GetTickCount(); -#else - timeval now; - gettimeofday(&now, NULL); - return ((int64_t)now.tv_sec * 1000) + (now.tv_usec / 1000); -#endif -} const char* SpellcheckStringV(const string& text, const vector& words) { diff --git a/src/util.h b/src/util.h index 82f4850..b108c25 100644 --- a/src/util.h +++ b/src/util.h @@ -53,11 +53,6 @@ int ReadFile(const string& path, string* contents, string* err); /// Mark a file descriptor to not be inherited on exec()s. void SetCloseOnExec(int fd); -/// Get the current time as relative to some epoch. -/// Epoch varies between platforms; only useful for measuring elapsed -/// time. -int64_t GetTimeMillis(); - /// Given a misspelled string and a list of correct spellings, returns /// the closest match or NULL if there is no close enough match. const char* SpellcheckStringV(const string& text, const vector& words); -- cgit v0.12