diff options
-rw-r--r-- | doc/manual.asciidoc | 6 | ||||
-rwxr-xr-x | misc/output_test.py | 15 | ||||
-rw-r--r-- | src/build.cc | 22 | ||||
-rw-r--r-- | src/build_test.cc | 23 | ||||
-rw-r--r-- | src/depfile_parser.cc | 4 | ||||
-rw-r--r-- | src/depfile_parser.in.cc | 4 | ||||
-rw-r--r-- | src/depfile_parser_test.cc | 21 | ||||
-rw-r--r-- | src/graph.h | 64 | ||||
-rw-r--r-- | src/ninja.cc | 19 | ||||
-rw-r--r-- | src/status.cc | 210 | ||||
-rw-r--r-- | src/status.h | 47 | ||||
-rw-r--r-- | src/status_test.cc | 5 |
12 files changed, 355 insertions, 85 deletions
diff --git a/doc/manual.asciidoc b/doc/manual.asciidoc index 22601e1..d01b75a 100644 --- a/doc/manual.asciidoc +++ b/doc/manual.asciidoc @@ -204,7 +204,11 @@ Several placeholders are available: `%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) -`%e`:: Elapsed time in seconds. _(Available since Ninja 1.2.)_ +`%e`:: Elapsed time in seconds. _(Available since Ninja 1.2.)_ +`%E`:: Remaining time (ETA) in seconds. _(Available since Ninja 1.12.)_ +`%w`:: Elapsed time in [h:]mm:ss format. _(Available since Ninja 1.12.)_ +`%W`:: Remaining time (ETA) in [h:]mm:ss format. _(Available since Ninja 1.12.)_ +`%P`:: The percentage (in ppp% format) of time elapsed out of predicted total runtime. _(Available since Ninja 1.12.)_ `%%`:: A plain `%` character. The default progress status is `"[%f/%t] "` (note the trailing space diff --git a/misc/output_test.py b/misc/output_test.py index a094482..78848cb 100755 --- a/misc/output_test.py +++ b/misc/output_test.py @@ -13,29 +13,26 @@ import tempfile import unittest default_env = dict(os.environ) -if 'NINJA_STATUS' in default_env: - del default_env['NINJA_STATUS'] -if 'CLICOLOR_FORCE' in default_env: - del default_env['CLICOLOR_FORCE'] +default_env.pop('NINJA_STATUS', None) +default_env.pop('CLICOLOR_FORCE', None) default_env['TERM'] = '' NINJA_PATH = os.path.abspath('./ninja') def run(build_ninja, flags='', pipe=False, env=default_env): with tempfile.TemporaryDirectory() as d: - os.chdir(d) - with open('build.ninja', 'w') as f: + with open(os.path.join(d, 'build.ninja'), 'w') as f: f.write(build_ninja) f.flush() ninja_cmd = '{} {}'.format(NINJA_PATH, flags) try: if pipe: - output = subprocess.check_output([ninja_cmd], shell=True, env=env) + output = subprocess.check_output([ninja_cmd], shell=True, cwd=d, env=env) elif platform.system() == 'Darwin': output = subprocess.check_output(['script', '-q', '/dev/null', 'bash', '-c', ninja_cmd], - env=env) + cwd=d, env=env) else: output = subprocess.check_output(['script', '-qfec', ninja_cmd, '/dev/null'], - env=env) + cwd=d, env=env) except subprocess.CalledProcessError as err: sys.stdout.buffer.write(err.output) raise err diff --git a/src/build.cc b/src/build.cc index 9c5cb66..7e2ccfa 100644 --- a/src/build.cc +++ b/src/build.cc @@ -150,8 +150,11 @@ bool Plan::AddSubTarget(const Node* node, const Node* dependent, string* err, void Plan::EdgeWanted(const Edge* edge) { ++wanted_edges_; - if (!edge->is_phony()) + if (!edge->is_phony()) { ++command_edges_; + if (builder_) + builder_->status_->EdgeAddedToPlan(edge); + } } Edge* Plan::FindWork() { @@ -300,8 +303,11 @@ bool Plan::CleanNode(DependencyScan* scan, Node* node, string* err) { want_e->second = kWantNothing; --wanted_edges_; - if (!(*oe)->is_phony()) + if (!(*oe)->is_phony()) { --command_edges_; + if (builder_) + builder_->status_->EdgeRemovedFromPlan(*oe); + } } } } @@ -743,7 +749,6 @@ bool Builder::Build(string* err) { assert(!AlreadyUpToDate()); plan_.PrepareQueue(); - status_->PlanHasTotalEdges(plan_.command_edge_count()); int pending_commands = 0; int failures_allowed = config_.failures_allowed; @@ -929,8 +934,8 @@ bool Builder::FinishCommand(CommandRunner::Result* result, string* err) { end_time_millis = GetTimeMillis() - start_time_millis_; running_edges_.erase(it); - status_->BuildEdgeFinished(edge, end_time_millis, result->success(), - result->output); + status_->BuildEdgeFinished(edge, start_time_millis, end_time_millis, + result->success(), result->output); // The rest of this function only applies to successful commands. if (!result->success()) { @@ -970,10 +975,6 @@ bool Builder::FinishCommand(CommandRunner::Result* result, string* err) { } if (node_cleaned) { record_mtime = edge->command_start_time_; - - // The total number of edges in the plan may have changed as a result - // of a restat. - status_->PlanHasTotalEdges(plan_.command_edge_count()); } } @@ -1087,8 +1088,5 @@ bool Builder::LoadDyndeps(Node* node, string* err) { if (!plan_.DyndepsLoaded(&scan_, node, ddf, err)) return false; - // New command edges may have been added to the plan. - status_->PlanHasTotalEdges(plan_.command_edge_count()); - return true; } diff --git a/src/build_test.cc b/src/build_test.cc index 429e71c..61b0b6a 100644 --- a/src/build_test.cc +++ b/src/build_test.cc @@ -2257,11 +2257,28 @@ TEST_F(BuildTest, DepsGccWithEmptyDepfileErrorsOut) { ASSERT_EQ(1u, command_runner_.commands_ran_.size()); } -TEST_F(BuildTest, StatusFormatElapsed) { +TEST_F(BuildTest, StatusFormatElapsed_e) { status_.BuildStarted(); // Before any task is done, the elapsed time must be zero. - EXPECT_EQ("[%/e0.000]", - status_.FormatProgressStatus("[%%/e%e]", 0)); + EXPECT_EQ("[%/e0.000]", status_.FormatProgressStatus("[%%/e%e]", 0)); +} + +TEST_F(BuildTest, StatusFormatElapsed_w) { + status_.BuildStarted(); + // Before any task is done, the elapsed time must be zero. + EXPECT_EQ("[%/e00:00]", status_.FormatProgressStatus("[%%/e%w]", 0)); +} + +TEST_F(BuildTest, StatusFormatETA) { + status_.BuildStarted(); + // Before any task is done, the ETA time must be unknown. + EXPECT_EQ("[%/E?]", status_.FormatProgressStatus("[%%/E%E]", 0)); +} + +TEST_F(BuildTest, StatusFormatTimeProgress) { + status_.BuildStarted(); + // Before any task is done, the percentage of elapsed time must be zero. + EXPECT_EQ("[%/p 0%]", status_.FormatProgressStatus("[%%/p%p]", 0)); } TEST_F(BuildTest, StatusFormatReplacePlaceholder) { diff --git a/src/depfile_parser.cc b/src/depfile_parser.cc index 98fba2e..7ce7290 100644 --- a/src/depfile_parser.cc +++ b/src/depfile_parser.cc @@ -54,6 +54,7 @@ bool DepfileParser::Parse(string* content, string* err) { bool have_target = false; bool parsing_targets = true; bool poisoned_input = false; + bool is_empty = true; while (in < end) { bool have_newline = false; // out: current output point (typically same as in, but can fall behind @@ -335,6 +336,7 @@ yy32: } if (len > 0) { + is_empty = false; StringPiece piece = StringPiece(filename, len); // If we've seen this as an input before, skip it. std::vector<StringPiece>::iterator pos = std::find(ins_.begin(), ins_.end(), piece); @@ -363,7 +365,7 @@ yy32: poisoned_input = false; } } - if (!have_target) { + if (!have_target && !is_empty) { *err = "expected ':' in depfile"; return false; } diff --git a/src/depfile_parser.in.cc b/src/depfile_parser.in.cc index 75ba982..4b5f5fe 100644 --- a/src/depfile_parser.in.cc +++ b/src/depfile_parser.in.cc @@ -53,6 +53,7 @@ bool DepfileParser::Parse(string* content, string* err) { bool have_target = false; bool parsing_targets = true; bool poisoned_input = false; + bool is_empty = true; while (in < end) { bool have_newline = false; // out: current output point (typically same as in, but can fall behind @@ -171,6 +172,7 @@ bool DepfileParser::Parse(string* content, string* err) { } if (len > 0) { + is_empty = false; StringPiece piece = StringPiece(filename, len); // If we've seen this as an input before, skip it. std::vector<StringPiece>::iterator pos = std::find(ins_.begin(), ins_.end(), piece); @@ -199,7 +201,7 @@ bool DepfileParser::Parse(string* content, string* err) { poisoned_input = false; } } - if (!have_target) { + if (!have_target && !is_empty) { *err = "expected ':' in depfile"; return false; } diff --git a/src/depfile_parser_test.cc b/src/depfile_parser_test.cc index 8886258..947ae76 100644 --- a/src/depfile_parser_test.cc +++ b/src/depfile_parser_test.cc @@ -378,3 +378,24 @@ TEST_F(DepfileParserTest, BuggyMP) { "z:\n", &err)); ASSERT_EQ("inputs may not also have inputs", err); } + +TEST_F(DepfileParserTest, EmptyFile) { + std::string err; + EXPECT_TRUE(Parse("", &err)); + ASSERT_EQ(0u, parser_.outs_.size()); + ASSERT_EQ(0u, parser_.ins_.size()); +} + +TEST_F(DepfileParserTest, EmptyLines) { + std::string err; + EXPECT_TRUE(Parse("\n\n", &err)); + ASSERT_EQ(0u, parser_.outs_.size()); + ASSERT_EQ(0u, parser_.ins_.size()); +} + +TEST_F(DepfileParserTest, MissingColon) { + // The file is not empty but is missing a colon separator. + std::string err; + EXPECT_FALSE(Parse("foo.o foo.c\n", &err)); + EXPECT_EQ("expected ':' in depfile", err); +} diff --git a/src/graph.h b/src/graph.h index d49c309..820a265 100644 --- a/src/graph.h +++ b/src/graph.h @@ -39,14 +39,7 @@ struct State; /// it's dirty, mtime, etc. struct Node { Node(const std::string& path, uint64_t slash_bits) - : path_(path), - slash_bits_(slash_bits), - mtime_(-1), - exists_(ExistenceStatusUnknown), - dirty_(false), - dyndep_pending_(false), - in_edge_(NULL), - id_(-1) {} + : path_(path), slash_bits_(slash_bits) {} /// Return false on error. bool Stat(DiskInterface* disk_interface, std::string* err); @@ -128,13 +121,13 @@ private: /// Set bits starting from lowest for backslashes that were normalized to /// forward slashes by CanonicalizePath. See |PathDecanonicalized|. - uint64_t slash_bits_; + uint64_t slash_bits_ = 0; /// Possible values of mtime_: /// -1: file hasn't been examined /// 0: we looked, and file doesn't exist /// >0: actual file's mtime, or the latest mtime of its dependencies if it doesn't exist - TimeStamp mtime_; + TimeStamp mtime_ = -1; enum ExistenceStatus { /// The file hasn't been examined. @@ -144,16 +137,16 @@ private: /// The path is an actual file. mtime_ will be the file's mtime. ExistenceStatusExists }; - ExistenceStatus exists_; + ExistenceStatus exists_ = ExistenceStatusUnknown; /// Dirty is true when the underlying file is out-of-date. /// But note that Edge::outputs_ready_ is also used in judging which /// edges to build. - bool dirty_; + bool dirty_ = false; /// Store whether dyndep information is expected from this node but /// has not yet been loaded. - bool dyndep_pending_; + bool dyndep_pending_ = false; /// Set to true when this node comes from a depfile, a dyndep file or the /// deps log. If it does not have a producing edge, the build should not @@ -164,7 +157,7 @@ private: /// The Edge that produces this Node, or NULL when there is no /// known edge to produce it. - Edge* in_edge_; + Edge* in_edge_ = nullptr; /// All Edges that use this Node as an input. std::vector<Edge*> out_edges_; @@ -173,7 +166,7 @@ private: std::vector<Edge*> validation_out_edges_; /// A dense integer id for the node, assigned and used by DepsLog. - int id_; + int id_ = -1; }; /// An edge in the dependency graph; links between Nodes using Rules. @@ -184,12 +177,7 @@ struct Edge { VisitDone }; - Edge() - : rule_(NULL), pool_(NULL), dyndep_(NULL), env_(NULL), mark_(VisitNone), - id_(0), outputs_ready_(false), deps_loaded_(false), - deps_missing_(false), generated_by_dep_loader_(false), - command_start_time_(0), implicit_deps_(0), order_only_deps_(0), - critical_path_weight_(-1), implicit_outs_(0) {} + Edge() = default; /// Return true if all inputs' in-edges are ready. bool AllInputsReady() const; @@ -224,21 +212,21 @@ struct Edge { critical_path_weight_ = critical_path_weight; } - const Rule* rule_; - Pool* pool_; + const Rule* rule_ = nullptr; + Pool* pool_ = nullptr; std::vector<Node*> inputs_; std::vector<Node*> outputs_; std::vector<Node*> validations_; - Node* dyndep_; - BindingEnv* env_; - VisitMark mark_; - size_t id_; - int64_t critical_path_weight_; - bool outputs_ready_; - bool deps_loaded_; - bool deps_missing_; - bool generated_by_dep_loader_; - TimeStamp command_start_time_; + Node* dyndep_ = nullptr; + BindingEnv* env_ = nullptr; + VisitMark mark_ = VisitNone; + size_t id_ = 0; + int64_t critical_path_weight_ = -1; + bool outputs_ready_ = false; + bool deps_loaded_ = false; + bool deps_missing_ = false; + bool generated_by_dep_loader_ = false; + TimeStamp command_start_time_ = 0; const Rule& rule() const { return *rule_; } Pool* pool() const { return pool_; } @@ -253,8 +241,8 @@ struct Edge { // don't cause the target to rebuild. // These are stored in inputs_ in that order, and we keep counts of // #2 and #3 when we need to access the various subsets. - int implicit_deps_; - int order_only_deps_; + int implicit_deps_ = 0; + int order_only_deps_ = 0; bool is_implicit(size_t index) { return index >= inputs_.size() - order_only_deps_ - implicit_deps_ && !is_order_only(index); @@ -268,7 +256,7 @@ struct Edge { // 2) implicit outs, which the target generates but are not part of $out. // These are stored in outputs_ in that order, and we keep a count of // #2 to use when we need to access the various subsets. - int implicit_outs_; + int implicit_outs_ = 0; bool is_implicit_out(size_t index) const { return index >= outputs_.size() - implicit_outs_; } @@ -276,6 +264,10 @@ struct Edge { bool is_phony() const; bool use_console() const; bool maybe_phonycycle_diagnostic() const; + + // Historical info: how long did this edge take last time, + // as per .ninja_log, if known? Defaults to -1 if unknown. + int64_t prev_elapsed_time_millis = -1; }; struct EdgeCmp { diff --git a/src/ninja.cc b/src/ninja.cc index 839e9e6..ce1beda 100644 --- a/src/ninja.cc +++ b/src/ninja.cc @@ -153,6 +153,10 @@ struct NinjaMain : public BuildLogUser { /// @return true if the manifest was rebuilt. bool RebuildManifest(const char* input_file, string* err, Status* status); + /// For each edge, lookup in build log how long it took last time, + /// and record that in the edge itself. It will be used for ETA predicton. + void ParsePreviousElapsedTimes(); + /// Build the targets listed on the command line. /// @return an exit code. int RunBuild(int argc, char** argv, Status* status); @@ -286,6 +290,19 @@ bool NinjaMain::RebuildManifest(const char* input_file, string* err, return true; } +void NinjaMain::ParsePreviousElapsedTimes() { + for (Edge* edge : state_.edges_) { + for (Node* out : edge->outputs_) { + BuildLog::LogEntry* log_entry = build_log_.LookupByOutput(out->path()); + if (!log_entry) + continue; // Maybe we'll have log entry for next output of this edge? + edge->prev_elapsed_time_millis = + log_entry->end_time - log_entry->start_time; + break; // Onto next edge. + } + } +} + Node* NinjaMain::CollectTarget(const char* cpath, string* err) { string path = cpath; if (path.empty()) { @@ -1586,6 +1603,8 @@ NORETURN void real_main(int argc, char** argv) { exit(1); } + ninja.ParsePreviousElapsedTimes(); + int result = ninja.RunBuild(argc, argv, status); if (g_metrics) ninja.DumpMetrics(); diff --git a/src/status.cc b/src/status.cc index 88b7781..06f3c20 100644 --- a/src/status.cc +++ b/src/status.cc @@ -14,6 +14,15 @@ #include "status.h" +#ifdef _WIN32 +#include "win32port.h" +#else +#ifndef __STDC_FORMAT_MACROS +#define __STDC_FORMAT_MACROS +#endif +#include <cinttypes> +#endif + #include <stdarg.h> #include <stdlib.h> @@ -27,11 +36,9 @@ using namespace std; StatusPrinter::StatusPrinter(const BuildConfig& config) - : config_(config), - started_edges_(0), finished_edges_(0), total_edges_(0), running_edges_(0), - time_millis_(0), progress_status_format_(NULL), + : config_(config), started_edges_(0), finished_edges_(0), total_edges_(0), + running_edges_(0), progress_status_format_(NULL), current_rate_(config.parallelism) { - // Don't do anything fancy in verbose mode. if (config_.verbosity != BuildConfig::NORMAL) printer_.set_smart_terminal(false); @@ -41,8 +48,32 @@ StatusPrinter::StatusPrinter(const BuildConfig& config) progress_status_format_ = "[%f/%t] "; } -void StatusPrinter::PlanHasTotalEdges(int total) { - total_edges_ = total; +void StatusPrinter::EdgeAddedToPlan(const Edge* edge) { + ++total_edges_; + + // Do we know how long did this edge take last time? + if (edge->prev_elapsed_time_millis != -1) { + ++eta_predictable_edges_total_; + ++eta_predictable_edges_remaining_; + eta_predictable_cpu_time_total_millis_ += edge->prev_elapsed_time_millis; + eta_predictable_cpu_time_remaining_millis_ += + edge->prev_elapsed_time_millis; + } else + ++eta_unpredictable_edges_remaining_; +} + +void StatusPrinter::EdgeRemovedFromPlan(const Edge* edge) { + --total_edges_; + + // Do we know how long did this edge take last time? + if (edge->prev_elapsed_time_millis != -1) { + --eta_predictable_edges_total_; + --eta_predictable_edges_remaining_; + eta_predictable_cpu_time_total_millis_ -= edge->prev_elapsed_time_millis; + eta_predictable_cpu_time_remaining_millis_ -= + edge->prev_elapsed_time_millis; + } else + --eta_unpredictable_edges_remaining_; } void StatusPrinter::BuildEdgeStarted(const Edge* edge, @@ -58,11 +89,102 @@ void StatusPrinter::BuildEdgeStarted(const Edge* edge, printer_.SetConsoleLocked(true); } -void StatusPrinter::BuildEdgeFinished(Edge* edge, int64_t end_time_millis, - bool success, const string& output) { +void StatusPrinter::RecalculateProgressPrediction() { + time_predicted_percentage_ = 0.0; + + // Sometimes, the previous and actual times may be wildly different. + // For example, the previous build may have been fully recovered from ccache, + // so it was blazing fast, while the new build no longer gets hits from ccache + // for whatever reason, so it actually compiles code, which takes much longer. + // We should detect such cases, and avoid using "wrong" previous times. + + // Note that we will only use the previous times if there are edges with + // previous time knowledge remaining. + bool use_previous_times = eta_predictable_edges_remaining_ && + eta_predictable_cpu_time_remaining_millis_; + + // Iff we have sufficient statistical information for the current run, + // that is, if we have took at least 15 sec AND finished at least 5% of edges, + // we can check whether our performance so far matches the previous one. + if (use_previous_times && total_edges_ && finished_edges_ && + (time_millis_ >= 15 * 1e3) && + (((double)finished_edges_ / total_edges_) >= 0.05)) { + // Over the edges we've just run, how long did they take on average? + double actual_average_cpu_time_millis = + (double)cpu_time_millis_ / finished_edges_; + // What is the previous average, for the edges with such knowledge? + double previous_average_cpu_time_millis = + (double)eta_predictable_cpu_time_total_millis_ / + eta_predictable_edges_total_; + + double ratio = std::max(previous_average_cpu_time_millis, + actual_average_cpu_time_millis) / + std::min(previous_average_cpu_time_millis, + actual_average_cpu_time_millis); + + // Let's say that the average times should differ by less than 10x + use_previous_times = ratio < 10; + } + + int edges_with_known_runtime = finished_edges_; + if (use_previous_times) + edges_with_known_runtime += eta_predictable_edges_remaining_; + if (edges_with_known_runtime == 0) + return; + + int edges_with_unknown_runtime = use_previous_times + ? eta_unpredictable_edges_remaining_ + : (total_edges_ - finished_edges_); + + // Given the time elapsed on the edges we've just run, + // and the runtime of the edges for which we know previous runtime, + // what's the edge's average runtime? + int64_t edges_known_runtime_total_millis = cpu_time_millis_; + if (use_previous_times) + edges_known_runtime_total_millis += + eta_predictable_cpu_time_remaining_millis_; + + double average_cpu_time_millis = + (double)edges_known_runtime_total_millis / edges_with_known_runtime; + + // For the edges for which we do not have the previous runtime, + // let's assume that their average runtime is the same as for the other edges, + // and we therefore can predict their remaining runtime. + double unpredictable_cpu_time_remaining_millis = + average_cpu_time_millis * edges_with_unknown_runtime; + + // And therefore we can predict the remaining and total runtimes. + double total_cpu_time_remaining_millis = + unpredictable_cpu_time_remaining_millis; + if (use_previous_times) + total_cpu_time_remaining_millis += + eta_predictable_cpu_time_remaining_millis_; + double total_cpu_time_millis = + cpu_time_millis_ + total_cpu_time_remaining_millis; + if (total_cpu_time_millis == 0.0) + return; + + // After that we can tell how much work we've completed, in time units. + time_predicted_percentage_ = cpu_time_millis_ / total_cpu_time_millis; +} + +void StatusPrinter::BuildEdgeFinished(Edge* edge, int64_t start_time_millis, + int64_t end_time_millis, bool success, + const string& output) { time_millis_ = end_time_millis; ++finished_edges_; + int64_t elapsed = end_time_millis - start_time_millis; + cpu_time_millis_ += elapsed; + + // Do we know how long did this edge take last time? + if (edge->prev_elapsed_time_millis != -1) { + --eta_predictable_edges_remaining_; + eta_predictable_cpu_time_remaining_millis_ -= + edge->prev_elapsed_time_millis; + } else + --eta_unpredictable_edges_remaining_; + if (edge->use_console()) printer_.SetConsoleLocked(false); @@ -201,16 +323,78 @@ string StatusPrinter::FormatProgressStatus(const char* progress_status_format, out += buf; break; - // Percentage + // Percentage of edges completed case 'p': { - int percent = (100 * finished_edges_) / total_edges_; + int percent = 0; + if (finished_edges_ != 0 && total_edges_ != 0) + percent = (100 * finished_edges_) / total_edges_; snprintf(buf, sizeof(buf), "%3i%%", percent); out += buf; break; } - case 'e': { - snprintf(buf, sizeof(buf), "%.3f", time_millis_ / 1e3); +#define FORMAT_TIME_HMMSS(t) \ + "%" PRId64 ":%02" PRId64 ":%02" PRId64 "", (t) / 3600, ((t) % 3600) / 60, \ + (t) % 60 +#define FORMAT_TIME_MMSS(t) "%02" PRId64 ":%02" PRId64 "", (t) / 60, (t) % 60 + + // Wall time + case 'e': // elapsed, seconds + case 'w': // elapsed, human-readable + case 'E': // ETA, seconds + case 'W': // ETA, human-readable + { + double elapsed_sec = time_millis_ / 1e3; + double eta_sec = -1; // To be printed as "?". + if (time_predicted_percentage_ != 0.0) { + // So, we know that we've spent time_millis_ wall clock, + // and that is time_predicted_percentage_ percent. + // How much time will we need to complete 100%? + double total_wall_time = time_millis_ / time_predicted_percentage_; + // Naturally, that gives us the time remaining. + eta_sec = (total_wall_time - time_millis_) / 1e3; + } + + const bool print_with_hours = + elapsed_sec >= 60 * 60 || eta_sec >= 60 * 60; + + double sec = -1; + switch (*s) { + case 'e': // elapsed, seconds + case 'w': // elapsed, human-readable + sec = elapsed_sec; + break; + case 'E': // ETA, seconds + case 'W': // ETA, human-readable + sec = eta_sec; + break; + } + + if (sec < 0) + snprintf(buf, sizeof(buf), "?"); + else { + switch (*s) { + case 'e': // elapsed, seconds + case 'E': // ETA, seconds + snprintf(buf, sizeof(buf), "%.3f", sec); + break; + case 'w': // elapsed, human-readable + case 'W': // ETA, human-readable + if (print_with_hours) + snprintf(buf, sizeof(buf), FORMAT_TIME_HMMSS((int64_t)sec)); + else + snprintf(buf, sizeof(buf), FORMAT_TIME_MMSS((int64_t)sec)); + break; + } + } + out += buf; + break; + } + + // Percentage of time spent out of the predicted time total + case 'P': { + snprintf(buf, sizeof(buf), "%3i%%", + (int)(100. * time_predicted_percentage_)); out += buf; break; } @@ -232,6 +416,8 @@ void StatusPrinter::PrintStatus(const Edge* edge, int64_t time_millis) { || config_.verbosity == BuildConfig::NO_STATUS_UPDATE) return; + RecalculateProgressPrediction(); + bool force_full_command = config_.verbosity == BuildConfig::VERBOSE; string to_print = edge->GetBinding("description"); diff --git a/src/status.h b/src/status.h index b2e50ea..a1a8fdd 100644 --- a/src/status.h +++ b/src/status.h @@ -24,10 +24,13 @@ /// Abstract interface to object that tracks the status of a build: /// completion fraction, printing updates. struct Status { - virtual void PlanHasTotalEdges(int total) = 0; - virtual void BuildEdgeStarted(const Edge* edge, int64_t start_time_millis) = 0; - virtual void BuildEdgeFinished(Edge* edge, int64_t end_time_millis, - bool success, const std::string& output) = 0; + virtual void EdgeAddedToPlan(const Edge* edge) = 0; + virtual void EdgeRemovedFromPlan(const Edge* edge) = 0; + virtual void BuildEdgeStarted(const Edge* edge, + int64_t start_time_millis) = 0; + virtual void BuildEdgeFinished(Edge* edge, int64_t start_time_millis, + int64_t end_time_millis, bool success, + const std::string& output) = 0; virtual void BuildLoadDyndeps() = 0; virtual void BuildStarted() = 0; virtual void BuildFinished() = 0; @@ -43,10 +46,15 @@ struct Status { /// human-readable strings to stdout struct StatusPrinter : Status { explicit StatusPrinter(const BuildConfig& config); - virtual void PlanHasTotalEdges(int total); + + /// Callbacks for the Plan to notify us about adding/removing Edge's. + virtual void EdgeAddedToPlan(const Edge* edge); + virtual void EdgeRemovedFromPlan(const Edge* edge); + virtual void BuildEdgeStarted(const Edge* edge, int64_t start_time_millis); - virtual void BuildEdgeFinished(Edge* edge, int64_t end_time_millis, - bool success, const std::string& output); + virtual void BuildEdgeFinished(Edge* edge, int64_t start_time_millis, + int64_t end_time_millis, bool success, + const std::string& output); virtual void BuildLoadDyndeps(); virtual void BuildStarted(); virtual void BuildFinished(); @@ -71,7 +79,30 @@ struct StatusPrinter : Status { const BuildConfig& config_; int started_edges_, finished_edges_, total_edges_, running_edges_; - int64_t time_millis_; + + /// How much wall clock elapsed so far? + int64_t time_millis_ = 0; + + /// How much cpu clock elapsed so far? + int64_t cpu_time_millis_ = 0; + + /// What percentage of predicted total time have elapsed already? + double time_predicted_percentage_ = 0.0; + + /// Out of all the edges, for how many do we know previous time? + int eta_predictable_edges_total_ = 0; + /// And how much time did they all take? + int64_t eta_predictable_cpu_time_total_millis_ = 0; + + /// Out of all the non-finished edges, for how many do we know previous time? + int eta_predictable_edges_remaining_ = 0; + /// And how much time will they all take? + int64_t eta_predictable_cpu_time_remaining_millis_ = 0; + + /// For how many edges we don't know the previous run time? + int eta_unpredictable_edges_remaining_ = 0; + + void RecalculateProgressPrediction(); /// Prints progress output. LinePrinter printer_; diff --git a/src/status_test.cc b/src/status_test.cc index 6e42490..411d3ed 100644 --- a/src/status_test.cc +++ b/src/status_test.cc @@ -22,8 +22,9 @@ TEST(StatusTest, StatusFormatElapsed) { status.BuildStarted(); // Before any task is done, the elapsed time must be zero. - EXPECT_EQ("[%/e0.000]", - status.FormatProgressStatus("[%%/e%e]", 0)); + EXPECT_EQ("[%/e0.000]", status.FormatProgressStatus("[%%/e%e]", 0)); + // Before any task is done, the elapsed time must be zero. + EXPECT_EQ("[%/e00:00]", status.FormatProgressStatus("[%%/e%w]", 0)); } TEST(StatusTest, StatusFormatReplacePlaceholder) { |