From 4bd8db1fa8287ec0b828e98a7d2bcdf3d6b1904f Mon Sep 17 00:00:00 2001 From: Peter Bell Date: Tue, 8 Mar 2022 01:40:43 +0000 Subject: Add test and fix priority bug AddTarget cannot add edges to the ready queue before the critical time has been computed. --- src/build.cc | 69 +++++++++++++++++--- src/build.h | 9 ++- src/build_test.cc | 190 ++++++++++++++++++++++++++++++++++++++++++++++-------- 3 files changed, 231 insertions(+), 37 deletions(-) diff --git a/src/build.cc b/src/build.cc index ec71bf3..1f1e153 100644 --- a/src/build.cc +++ b/src/build.cc @@ -124,8 +124,6 @@ bool Plan::AddSubTarget(const Node* node, const Node* dependent, string* err, if (node->dirty() && want == kWantNothing) { want = kWantToStart; EdgeWanted(edge); - if (!dyndep_walk && edge->AllInputsReady()) - ScheduleWork(want_ins.first); } if (dyndep_walk) @@ -514,14 +512,27 @@ int64_t AssignEdgeRuntime(BuildLog* build_log, return total_time; } +int64_t AssignDefaultEdgeRuntime(std::map &want) { + int64_t total_time = 0; + + for (std::map::const_iterator it = want.begin(), + end = want.end(); + it != end; ++it) { + Edge* edge = it->first; + if (edge->is_phony()) { + continue; + } + + edge->set_run_time_ms(1); + ++total_time; + } + return total_time; +} + } // namespace void Plan::ComputeCriticalTime(BuildLog* build_log) { - // testcases have no build_log - if (!build_log) - return; - - METRIC_RECORD("ComputePriorityList"); + METRIC_RECORD("ComputeCriticalTime"); // Remove duplicate targets { std::set seen; @@ -533,7 +544,10 @@ void Plan::ComputeCriticalTime(BuildLog* build_log) { // total time if building all edges in serial. This value is big // enough to ensure higher priority target's initial critical time // is always bigger than lower ones - int64_t total_time = AssignEdgeRuntime(build_log, want_); + const int64_t total_time = build_log ? + AssignEdgeRuntime(build_log, want_) : + AssignDefaultEdgeRuntime(want_); // Plan tests have no build_log + // Use backflow algorithm to compute critical times for all nodes, starting // from the destination nodes. @@ -582,6 +596,42 @@ void Plan::ComputeCriticalTime(BuildLog* build_log) { } } +void Plan::ScheduleInitialEdges() { + // Add ready edges to queue. + assert(ready_.empty()); + std::set pools; + + for (std::map::iterator it = want_.begin(), + end = want_.end(); it != end; ++it) { + Edge* edge = it->first; + Plan::Want want = it->second; + if (!(want == kWantToStart && edge->AllInputsReady())) { + continue; + } + + Pool* pool = edge->pool(); + if (pool->ShouldDelayEdge()) { + pool->DelayEdge(edge); + pools.insert(pool); + } else { + ScheduleWork(it); + } + } + + // Call RetrieveReadyEdges only once at the end so higher priority + // edges are retrieved first, not the ones that happen to be first + // in the want_ map. + for (std::set::iterator it=pools.begin(), + end = pools.end(); it != end; ++it) { + (*it)->RetrieveReadyEdges(&ready_); + } +} + +void Plan::PrepareQueue(BuildLog* build_log) { + ComputeCriticalTime(build_log); + ScheduleInitialEdges(); +} + void Plan::Dump() const { printf("pending: %d\n", (int)want_.size()); for (map::const_iterator e = want_.begin(); e != want_.end(); ++e) { @@ -743,8 +793,7 @@ bool Builder::AlreadyUpToDate() const { bool Builder::Build(string* err) { assert(!AlreadyUpToDate()); - - plan_.ComputeCriticalTime(scan_.build_log()); + plan_.PrepareQueue(scan_.build_log()); status_->PlanHasTotalEdges(plan_.command_edge_count()); int pending_commands = 0; diff --git a/src/build.h b/src/build.h index 0d7c01a..7719d9a 100644 --- a/src/build.h +++ b/src/build.h @@ -74,7 +74,9 @@ struct Plan { /// Reset state. Clears want and ready sets. void Reset(); - void ComputeCriticalTime(BuildLog* build_log); + + // After all targets have been added, prepares the ready queue for find work. + void PrepareQueue(BuildLog* build_log); /// Update the build plan to account for modifications made to the graph /// by information loaded from a dyndep file. @@ -95,11 +97,16 @@ struct Plan { }; private: + void ComputeCriticalTime(BuildLog* build_log); bool RefreshDyndepDependents(DependencyScan* scan, const Node* node, std::string* err); void UnmarkDependents(const Node* node, std::set* dependents); bool AddSubTarget(const Node* node, const Node* dependent, std::string* err, std::set* dyndep_walk); + // Add edges that kWantToStart into the ready queue + // Must be called after ComputeCriticalTime and before FindWork + void ScheduleInitialEdges(); + /// Update plan with knowledge that the given node is up to date. /// If the node is a dyndep binding on any of its dependents, this /// loads dynamic dependencies from the node's path. diff --git a/src/build_test.cc b/src/build_test.cc index 4ef62b2..50a5394 100644 --- a/src/build_test.cc +++ b/src/build_test.cc @@ -50,6 +50,14 @@ struct PlanTest : public StateTestWithBuiltinRules { sort(ret->begin(), ret->end(), CompareEdgesByOutput::cmp); } + void PrepareForTarget(const char* node, BuildLog *log=NULL) { + string err; + EXPECT_TRUE(plan_.AddTarget(GetNode(node), &err)); + ASSERT_EQ("", err); + plan_.PrepareQueue(log); + ASSERT_TRUE(plan_.more_to_do()); + } + void TestPoolWithDepthOne(const char *test_case); }; @@ -59,10 +67,7 @@ TEST_F(PlanTest, Basic) { "build mid: cat in\n")); GetNode("mid")->MarkDirty(); GetNode("out")->MarkDirty(); - string err; - EXPECT_TRUE(plan_.AddTarget(GetNode("out"), &err)); - ASSERT_EQ("", err); - ASSERT_TRUE(plan_.more_to_do()); + PrepareForTarget("out"); Edge* edge = plan_.FindWork(); ASSERT_TRUE(edge); @@ -71,6 +76,7 @@ TEST_F(PlanTest, Basic) { ASSERT_FALSE(plan_.FindWork()); + string err; plan_.EdgeFinished(edge, Plan::kEdgeSucceeded, &err); ASSERT_EQ("", err); @@ -95,15 +101,12 @@ TEST_F(PlanTest, DoubleOutputDirect) { GetNode("mid1")->MarkDirty(); GetNode("mid2")->MarkDirty(); GetNode("out")->MarkDirty(); - - string err; - EXPECT_TRUE(plan_.AddTarget(GetNode("out"), &err)); - ASSERT_EQ("", err); - ASSERT_TRUE(plan_.more_to_do()); + PrepareForTarget("out"); Edge* edge; edge = plan_.FindWork(); ASSERT_TRUE(edge); // cat in + string err; plan_.EdgeFinished(edge, Plan::kEdgeSucceeded, &err); ASSERT_EQ("", err); @@ -128,14 +131,12 @@ TEST_F(PlanTest, DoubleOutputIndirect) { GetNode("b1")->MarkDirty(); GetNode("b2")->MarkDirty(); GetNode("out")->MarkDirty(); - string err; - EXPECT_TRUE(plan_.AddTarget(GetNode("out"), &err)); - ASSERT_EQ("", err); - ASSERT_TRUE(plan_.more_to_do()); + PrepareForTarget("out"); Edge* edge; edge = plan_.FindWork(); ASSERT_TRUE(edge); // cat in + string err; plan_.EdgeFinished(edge, Plan::kEdgeSucceeded, &err); ASSERT_EQ("", err); @@ -169,15 +170,12 @@ TEST_F(PlanTest, DoubleDependent) { GetNode("a1")->MarkDirty(); GetNode("a2")->MarkDirty(); GetNode("out")->MarkDirty(); - - string err; - EXPECT_TRUE(plan_.AddTarget(GetNode("out"), &err)); - ASSERT_EQ("", err); - ASSERT_TRUE(plan_.more_to_do()); + PrepareForTarget("out"); Edge* edge; edge = plan_.FindWork(); ASSERT_TRUE(edge); // cat in + string err; plan_.EdgeFinished(edge, Plan::kEdgeSucceeded, &err); ASSERT_EQ("", err); @@ -209,6 +207,7 @@ void PlanTest::TestPoolWithDepthOne(const char* test_case) { ASSERT_EQ("", err); EXPECT_TRUE(plan_.AddTarget(GetNode("out2"), &err)); ASSERT_EQ("", err); + plan_.PrepareQueue(NULL); ASSERT_TRUE(plan_.more_to_do()); Edge* edge = plan_.FindWork(); @@ -284,10 +283,7 @@ TEST_F(PlanTest, PoolsWithDepthTwo) { GetNode("outb" + string(1, '1' + static_cast(i)))->MarkDirty(); } GetNode("allTheThings")->MarkDirty(); - - string err; - EXPECT_TRUE(plan_.AddTarget(GetNode("allTheThings"), &err)); - ASSERT_EQ("", err); + PrepareForTarget("allTheThings"); deque edges; FindWorkSorted(&edges, 5); @@ -306,6 +302,7 @@ TEST_F(PlanTest, PoolsWithDepthTwo) { ASSERT_EQ("outb3", edge->outputs_[0]->path()); // finish out1 + string err; plan_.EdgeFinished(edges.front(), Plan::kEdgeSucceeded, &err); ASSERT_EQ("", err); edges.pop_front(); @@ -363,10 +360,7 @@ TEST_F(PlanTest, PoolWithRedundantEdges) { GetNode("bar.cpp.obj")->MarkDirty(); GetNode("libfoo.a")->MarkDirty(); GetNode("all")->MarkDirty(); - string err; - EXPECT_TRUE(plan_.AddTarget(GetNode("all"), &err)); - ASSERT_EQ("", err); - ASSERT_TRUE(plan_.more_to_do()); + PrepareForTarget("all"); Edge* edge = NULL; @@ -375,6 +369,7 @@ TEST_F(PlanTest, PoolWithRedundantEdges) { edge = initial_edges[1]; // Foo first ASSERT_EQ("foo.cpp", edge->outputs_[0]->path()); + string err; plan_.EdgeFinished(edge, Plan::kEdgeSucceeded, &err); ASSERT_EQ("", err); @@ -439,6 +434,7 @@ TEST_F(PlanTest, PoolWithFailingEdge) { ASSERT_EQ("", err); EXPECT_TRUE(plan_.AddTarget(GetNode("out2"), &err)); ASSERT_EQ("", err); + plan_.PrepareQueue(NULL); ASSERT_TRUE(plan_.more_to_do()); Edge* edge = plan_.FindWork(); @@ -467,6 +463,148 @@ TEST_F(PlanTest, PoolWithFailingEdge) { ASSERT_EQ(0, edge); } +TEST_F(PlanTest, PriorityWithoutBuildLog) { + // Without a build log, the critical time is equivalent to graph + // depth. Test with the following graph: + // a2 + // | + // a1 b1 + // | | | + // a0 b0 c0 + // \ | / + // out + + ASSERT_NO_FATAL_FAILURE(AssertParse(&state_, + "rule r\n" + " command = unused\n" + "build out: r a0 b0 c0\n" + "build a0: r a1\n" + "build a1: r a2\n" + "build b0: r b1\n" + "build c0: r b1\n" + )); + GetNode("a1")->MarkDirty(); + GetNode("a0")->MarkDirty(); + GetNode("b0")->MarkDirty(); + GetNode("c0")->MarkDirty(); + GetNode("out")->MarkDirty(); + BuildLog log; + PrepareForTarget("out", &log); + + EXPECT_EQ(GetNode("out")->in_edge()->critical_time(), 1); + EXPECT_EQ(GetNode("a0")->in_edge()->critical_time(), 2); + EXPECT_EQ(GetNode("b0")->in_edge()->critical_time(), 2); + EXPECT_EQ(GetNode("c0")->in_edge()->critical_time(), 2); + EXPECT_EQ(GetNode("a1")->in_edge()->critical_time(), 3); + + const int n_edges = 5; + const char *expected_order[n_edges] = { + "a1", "a0", "b0", "c0", "out"}; + for (int i = 0; i < n_edges; ++i) { + Edge* edge = plan_.FindWork(); + ASSERT_NE(edge, NULL); + EXPECT_EQ(expected_order[i], edge->outputs_[0]->path()); + + std::string err; + ASSERT_TRUE(plan_.EdgeFinished(edge, Plan::kEdgeSucceeded, &err)); + EXPECT_EQ(err, ""); + } + + EXPECT_FALSE(plan_.FindWork()); +} + +TEST_F(PlanTest, PriorityWithBuildLog) { + // With a build log, the critical time is longest weighted path. + // Test with the following graph: + // a2 + // | + // a1 b1 + // | | | + // a0 b0 c0 + // \ | / + // out + + ASSERT_NO_FATAL_FAILURE(AssertParse(&state_, + "rule r\n" + " command = unused\n" + "build out: r a0 b0 c0\n" + "build a0: r a1\n" + "build a1: r a2\n" + "build b0: r b1\n" + "build c0: r b1\n" + )); + GetNode("a1")->MarkDirty(); + GetNode("a0")->MarkDirty(); + GetNode("b0")->MarkDirty(); + GetNode("c0")->MarkDirty(); + GetNode("out")->MarkDirty(); + + BuildLog log; + log.RecordCommand(GetNode("out")->in_edge(), 0, 100); // time = 100 + log.RecordCommand(GetNode("a0")->in_edge(), 10, 20); // time = 10 + log.RecordCommand(GetNode("a1")->in_edge(), 20, 40); // time = 20 + log.RecordCommand(GetNode("b0")->in_edge(), 10, 30); // time = 20 + log.RecordCommand(GetNode("c0")->in_edge(), 20, 70); // time = 50 + + PrepareForTarget("out", &log); + + EXPECT_EQ(GetNode("out")->in_edge()->critical_time(), 100); + EXPECT_EQ(GetNode("a0")->in_edge()->critical_time(), 110); + EXPECT_EQ(GetNode("b0")->in_edge()->critical_time(), 120); + EXPECT_EQ(GetNode("c0")->in_edge()->critical_time(), 150); + EXPECT_EQ(GetNode("a1")->in_edge()->critical_time(), 130); + + const int n_edges = 5; + const char *expected_order[n_edges] = { + "c0", "a1", "b0", "a0", "out"}; + for (int i = 0; i < n_edges; ++i) { + Edge* edge = plan_.FindWork(); + ASSERT_NE(edge, NULL); + EXPECT_EQ(expected_order[i], edge->outputs_[0]->path()); + + std::string err; + ASSERT_TRUE(plan_.EdgeFinished(edge, Plan::kEdgeSucceeded, &err)); + EXPECT_EQ(err, ""); + } + EXPECT_FALSE(plan_.FindWork()); +} + +TEST_F(PlanTest, RuntimePartialBuildLog) { + // Test the edge->run_time_ms() estimate when no build log is available + + ASSERT_NO_FATAL_FAILURE(AssertParse(&state_, + "rule r\n" + " command = unused\n" + "build out: r a0 b0 c0 d0\n" + "build a0: r a1\n" + "build b0: r b1\n" + "build c0: r c1\n" + "build d0: r d1\n" + )); + GetNode("a0")->MarkDirty(); + GetNode("b0")->MarkDirty(); + GetNode("c0")->MarkDirty(); + GetNode("d0")->MarkDirty(); + GetNode("out")->MarkDirty(); + + BuildLog log; + log.RecordCommand(GetNode("out")->in_edge(), 0, 100); // time = 40 + log.RecordCommand(GetNode("a0")->in_edge(), 10, 20); // time = 10 + log.RecordCommand(GetNode("b0")->in_edge(), 20, 40); // time = 20 + log.RecordCommand(GetNode("c0")->in_edge(), 10, 40); // time = 30 + + PrepareForTarget("out", &log); + + // These edges times are read from the build log + EXPECT_EQ(GetNode("out")->in_edge()->run_time_ms(), 100); + EXPECT_EQ(GetNode("a0")->in_edge()->run_time_ms(), 10); + EXPECT_EQ(GetNode("b0")->in_edge()->run_time_ms(), 20); + EXPECT_EQ(GetNode("c0")->in_edge()->run_time_ms(), 30); + + // The missing data is taken from the 3rd quintile of known data + EXPECT_EQ(GetNode("d0")->in_edge()->run_time_ms(), 30); +} + /// Fake implementation of CommandRunner, useful for tests. struct FakeCommandRunner : public CommandRunner { explicit FakeCommandRunner(VirtualFileSystem* fs) : -- cgit v0.12