Skip to content

Commit

Permalink
Reliable ETA and progress percentage.
Browse files Browse the repository at this point in the history
This has been bugging me for *years*. :)
Count of finished edges isn't a great statistic, it isn't
really obvious if LLVM will take 8 minues to build, or 10 minutes.

But, it's actually pretty straight-forward to get some
more useful information. We already know how much time each edge
has taken, so we could just do the dumb thing, and assume that
every edge in the plan takes the same amount of time.

Or, we can do better. `.ninja_log` already contains
the historical data on how long each edge took to produce it's outs,
so we simply need to ensure that we populate edges with that info,
and then we can greatly improve our predictions.
The math is pretty simple i think.

This is largely a port of a similar change i did to LLVM LIT:
https://reviews.llvm.org/D99073

With this, i get something quite lovely:
```
llvm-project/build-Clang12$ NINJA_STATUS="[%f/%t %p %P][%w + %W] " /repositories/ninja/build-Clang-debug/ninja opt
[288/2527  11%   4%][00:27 + 08:52] Building CXX object lib/DebugInfo/CodeView/CMakeFiles/LLVMDebugInfoCodeView.dir/AppendingTypeTableBuilder.cpp.o
```

I hope people will find this useful, and it could be merged.
  • Loading branch information
LebedevRI committed Oct 24, 2022
1 parent 023d8a8 commit 4a0e197
Show file tree
Hide file tree
Showing 8 changed files with 294 additions and 38 deletions.
6 changes: 5 additions & 1 deletion doc/manual.asciidoc
Original file line number Diff line number Diff line change
Expand Up @@ -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.0.)_
`%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.0.)_
`%P`:: The percentage (in ppp% format) of time elapsed out of predicted total runtime. _(Available since Ninja 1.12.0.)_
`%%`:: A plain `%` character.
The default progress status is `"[%f/%t] "` (note the trailing space
Expand Down
22 changes: 10 additions & 12 deletions src/build.cc
Original file line number Diff line number Diff line change
Expand Up @@ -144,8 +144,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() {
Expand Down Expand Up @@ -294,8 +297,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);
}
}
}
}
Expand Down Expand Up @@ -607,7 +613,6 @@ bool Builder::AlreadyUpToDate() const {
bool Builder::Build(string* err) {
assert(!AlreadyUpToDate());

status_->PlanHasTotalEdges(plan_.command_edge_count());
int pending_commands = 0;
int failures_allowed = config_.failures_allowed;

Expand Down Expand Up @@ -780,8 +785,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()) {
Expand Down Expand Up @@ -821,10 +826,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());
}
}

Expand Down Expand Up @@ -938,8 +939,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;
}
23 changes: 20 additions & 3 deletions src/build_test.cc
Original file line number Diff line number Diff line change
Expand Up @@ -2197,11 +2197,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) {
Expand Down
4 changes: 4 additions & 0 deletions src/graph.h
Original file line number Diff line number Diff line change
Expand Up @@ -250,6 +250,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 {
Expand Down
19 changes: 19 additions & 0 deletions src/ninja.cc
Original file line number Diff line number Diff line change
Expand Up @@ -156,6 +156,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);
Expand Down Expand Up @@ -289,6 +293,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()) {
Expand Down Expand Up @@ -1588,6 +1605,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();
Expand Down
Loading

0 comments on commit 4a0e197

Please sign in to comment.