From 036003d20e80cbb044a3f0f0b41e2fdefcde66af Mon Sep 17 00:00:00 2001 From: Colin Cross Date: Mon, 22 May 2017 11:27:14 -0700 Subject: Move stat metric to DiskInterface Stat is not always used through Node::Stat, it is often used directly through DiskInterface. THe next patches will cause it to be called even more often through DiskInterface, so move the metrics to DiskInterface. --- src/disk_interface.cc | 2 ++ src/graph.cc | 1 - 2 files changed, 2 insertions(+), 1 deletion(-) diff --git a/src/disk_interface.cc b/src/disk_interface.cc index 1b4135f..b418e04 100644 --- a/src/disk_interface.cc +++ b/src/disk_interface.cc @@ -28,6 +28,7 @@ #include // _mkdir #endif +#include "metrics.h" #include "util.h" namespace { @@ -148,6 +149,7 @@ bool DiskInterface::MakeDirs(const string& path) { // RealDiskInterface ----------------------------------------------------------- TimeStamp RealDiskInterface::Stat(const string& path, string* err) const { + METRIC_RECORD("node stat"); #ifdef _WIN32 // MSDN: "Naming Files, Paths, and Namespaces" // http://msdn.microsoft.com/en-us/library/windows/desktop/aa365247(v=vs.85).aspx diff --git a/src/graph.cc b/src/graph.cc index b4c8619..76d996b 100644 --- a/src/graph.cc +++ b/src/graph.cc @@ -28,7 +28,6 @@ #include "util.h" bool Node::Stat(DiskInterface* disk_interface, string* err) { - METRIC_RECORD("node stat"); return (mtime_ = disk_interface->Stat(path_, err)) != -1; } -- cgit v0.12 From a127dda3ee92916ef459b3da7aa9f2920ff1a5ab Mon Sep 17 00:00:00 2001 From: Colin Cross Date: Thu, 18 May 2017 21:29:45 -0700 Subject: Add a test that fails if a rule updates it output file but fails https://groups.google.com/forum/#!msg/ninja-build/YQuGNrECI-4/ti-lAs9SPv8J discusses a case where an rule updates its output file and then fails. The next run of ninja considers the ouptut file clean and doesn't rebuild it. Add a test for this case, which currently fails. --- src/build.cc | 7 +++++++ src/build.h | 3 +++ src/build_test.cc | 51 +++++++++++++++++++++++++++++++++++++++++++++++++-- 3 files changed, 59 insertions(+), 2 deletions(-) diff --git a/src/build.cc b/src/build.cc index a0c7ec8..44d0663 100644 --- a/src/build.cc +++ b/src/build.cc @@ -275,6 +275,13 @@ void BuildStatus::PrintStatus(Edge* edge, EdgeStatus status) { Plan::Plan() : command_edges_(0), wanted_edges_(0) {} +void Plan::Reset() { + command_edges_ = 0; + wanted_edges_ = 0; + ready_.clear(); + want_.clear(); +} + bool Plan::AddTarget(Node* node, string* err) { vector stack; return AddSubTarget(node, &stack, err); diff --git a/src/build.h b/src/build.h index 66ce607..f97d67e 100644 --- a/src/build.h +++ b/src/build.h @@ -71,6 +71,9 @@ struct Plan { /// Number of edges with commands to run. int command_edge_count() const { return command_edges_; } + /// Reset state. Clears want and ready sets. + void Reset(); + private: bool AddSubTarget(Node* node, vector* stack, string* err); bool CheckDependencyCycle(Node* node, const vector& stack, diff --git a/src/build_test.cc b/src/build_test.cc index 640e1b0..d617143 100644 --- a/src/build_test.cc +++ b/src/build_test.cc @@ -608,7 +608,8 @@ bool FakeCommandRunner::StartCommand(Edge* edge) { edge->rule().name() == "cat_rsp_out" || edge->rule().name() == "cc" || edge->rule().name() == "touch" || - edge->rule().name() == "touch-interrupt") { + edge->rule().name() == "touch-interrupt" || + edge->rule().name() == "touch-fail-tick2") { for (vector::iterator out = edge->outputs_.begin(); out != edge->outputs_.end(); ++out) { fs_->Create((*out)->path(), ""); @@ -649,7 +650,8 @@ bool FakeCommandRunner::WaitForCommand(Result* result) { return true; } - if (edge->rule().name() == "fail") + if (edge->rule().name() == "fail" || + (edge->rule().name() == "touch-fail-tick2" && fs_->now_ == 2)) result->status = ExitFailure; else result->status = ExitSuccess; @@ -1258,6 +1260,51 @@ TEST_F(BuildWithLogTest, NotInLogButOnDisk) { EXPECT_TRUE(builder_.AlreadyUpToDate()); } +TEST_F(BuildWithLogTest, RebuildAfterFailure) { + ASSERT_NO_FATAL_FAILURE(AssertParse(&state_, +"rule touch-fail-tick2\n" +" command = touch-fail-tick2\n" +"build out1: touch-fail-tick2 in\n")); + + string err; + + fs_.Create("in", ""); + + // Run once successfully to get out1 in the log + EXPECT_TRUE(builder_.AddTarget("out1", &err)); + EXPECT_TRUE(builder_.Build(&err)); + EXPECT_EQ("", err); + EXPECT_EQ(1u, command_runner_.commands_ran_.size()); + + command_runner_.commands_ran_.clear(); + state_.Reset(); + builder_.Cleanup(); + builder_.plan_.Reset(); + + fs_.Tick(); + fs_.Create("in", ""); + + // Run again with a failure that updates the output file timestamp + EXPECT_TRUE(builder_.AddTarget("out1", &err)); + EXPECT_FALSE(builder_.Build(&err)); + EXPECT_EQ("subcommand failed", err); + EXPECT_EQ(1u, command_runner_.commands_ran_.size()); + + command_runner_.commands_ran_.clear(); + state_.Reset(); + builder_.Cleanup(); + builder_.plan_.Reset(); + + fs_.Tick(); + + // Run again, should rerun even though the output file is up to date on disk + EXPECT_TRUE(builder_.AddTarget("out1", &err)); + EXPECT_FALSE(builder_.AlreadyUpToDate()); + EXPECT_TRUE(builder_.Build(&err)); + EXPECT_EQ(1u, command_runner_.commands_ran_.size()); + EXPECT_EQ("", err); +} + TEST_F(BuildWithLogTest, RestatTest) { ASSERT_NO_FATAL_FAILURE(AssertParse(&state_, "rule true\n" -- cgit v0.12 From 04d886b11041bb59d01df794cce7a1e8cad2250d Mon Sep 17 00:00:00 2001 From: Colin Cross Date: Thu, 18 May 2017 17:34:51 -0700 Subject: Always rebuild on errors https://groups.google.com/forum/#!msg/ninja-build/YQuGNrECI-4/ti-lAs9SPv8J discusses a case where an rule updates its output file and then fails. The next run of ninja considers the ouptut file clean and doesn't rebuild it. Always stat output files after they are built, and write the mtime into .ninja_log. Consider output files dirty if the recorded mtime is older than the most recent input file. --- src/build.cc | 16 +++++++++++----- src/build_log.cc | 10 +++++----- src/build_log.h | 6 +++--- src/build_log_perftest.cc | 2 +- src/build_log_test.cc | 8 ++++---- src/build_test.cc | 4 ++-- src/graph.cc | 26 +++++++++++++++++++------- 7 files changed, 45 insertions(+), 27 deletions(-) diff --git a/src/build.cc b/src/build.cc index 44d0663..1cce981 100644 --- a/src/build.cc +++ b/src/build.cc @@ -800,9 +800,10 @@ bool Builder::FinishCommand(CommandRunner::Result* result, string* err) { return true; } - // Restat the edge outputs, if necessary. - TimeStamp restat_mtime = 0; - if (edge->GetBindingBool("restat") && !config_.dry_run) { + // Restat the edge outputs + TimeStamp output_mtime = 0; + bool restat = edge->GetBindingBool("restat"); + if (!config_.dry_run) { bool node_cleaned = false; for (vector::iterator o = edge->outputs_.begin(); @@ -810,7 +811,9 @@ bool Builder::FinishCommand(CommandRunner::Result* result, string* err) { TimeStamp new_mtime = disk_interface_->Stat((*o)->path(), err); if (new_mtime == -1) return false; - if ((*o)->mtime() == new_mtime) { + if (new_mtime > output_mtime) + output_mtime = new_mtime; + if ((*o)->mtime() == new_mtime && restat) { // The rule command did not change the output. Propagate the clean // state through the build graph. // Note that this also applies to nonexistent outputs (mtime == 0). @@ -821,6 +824,7 @@ bool Builder::FinishCommand(CommandRunner::Result* result, string* err) { } if (node_cleaned) { + TimeStamp restat_mtime = 0; // If any output was cleaned, find the most recent mtime of any // (existing) non-order-only input or the depfile. for (vector::iterator i = edge->inputs_.begin(); @@ -844,6 +848,8 @@ bool Builder::FinishCommand(CommandRunner::Result* result, string* err) { // The total number of edges in the plan may have changed as a result // of a restat. status_->PlanHasTotalEdges(plan_.command_edge_count()); + + output_mtime = restat_mtime; } } @@ -856,7 +862,7 @@ bool Builder::FinishCommand(CommandRunner::Result* result, string* err) { if (scan_.build_log()) { if (!scan_.build_log()->RecordCommand(edge, start_time, end_time, - restat_mtime)) { + output_mtime)) { *err = string("Error writing to build log: ") + strerror(errno); return false; } diff --git a/src/build_log.cc b/src/build_log.cc index 8a52514..333915a 100644 --- a/src/build_log.cc +++ b/src/build_log.cc @@ -105,7 +105,7 @@ BuildLog::LogEntry::LogEntry(const string& output) BuildLog::LogEntry::LogEntry(const string& output, uint64_t command_hash, int start_time, int end_time, TimeStamp restat_mtime) : output(output), command_hash(command_hash), - start_time(start_time), end_time(end_time), restat_mtime(restat_mtime) + start_time(start_time), end_time(end_time), mtime(restat_mtime) {} BuildLog::BuildLog() @@ -145,7 +145,7 @@ bool BuildLog::OpenForWrite(const string& path, const BuildLogUser& user, } bool BuildLog::RecordCommand(Edge* edge, int start_time, int end_time, - TimeStamp restat_mtime) { + TimeStamp mtime) { string command = edge->EvaluateCommand(true); uint64_t command_hash = LogEntry::HashCommand(command); for (vector::iterator out = edge->outputs_.begin(); @@ -162,7 +162,7 @@ bool BuildLog::RecordCommand(Edge* edge, int start_time, int end_time, log_entry->command_hash = command_hash; log_entry->start_time = start_time; log_entry->end_time = end_time; - log_entry->restat_mtime = restat_mtime; + log_entry->mtime = mtime; if (log_file_) { if (!WriteEntry(log_file_, *log_entry)) @@ -314,7 +314,7 @@ bool BuildLog::Load(const string& path, string* err) { entry->start_time = start_time; entry->end_time = end_time; - entry->restat_mtime = restat_mtime; + entry->mtime = restat_mtime; if (log_version >= 5) { char c = *end; *end = '\0'; entry->command_hash = (uint64_t)strtoull(start, NULL, 16); @@ -354,7 +354,7 @@ BuildLog::LogEntry* BuildLog::LookupByOutput(const string& path) { bool BuildLog::WriteEntry(FILE* f, const LogEntry& entry) { return fprintf(f, "%d\t%d\t%d\t%s\t%" PRIx64 "\n", - entry.start_time, entry.end_time, entry.restat_mtime, + entry.start_time, entry.end_time, entry.mtime, entry.output.c_str(), entry.command_hash) > 0; } diff --git a/src/build_log.h b/src/build_log.h index 785961e..5268fab 100644 --- a/src/build_log.h +++ b/src/build_log.h @@ -45,7 +45,7 @@ struct BuildLog { bool OpenForWrite(const string& path, const BuildLogUser& user, string* err); bool RecordCommand(Edge* edge, int start_time, int end_time, - TimeStamp restat_mtime = 0); + TimeStamp mtime = 0); void Close(); /// Load the on-disk log. @@ -56,7 +56,7 @@ struct BuildLog { uint64_t command_hash; int start_time; int end_time; - TimeStamp restat_mtime; + TimeStamp mtime; static uint64_t HashCommand(StringPiece command); @@ -64,7 +64,7 @@ struct BuildLog { bool operator==(const LogEntry& o) { return output == o.output && command_hash == o.command_hash && start_time == o.start_time && end_time == o.end_time && - restat_mtime == o.restat_mtime; + mtime == o.mtime; } explicit LogEntry(const string& output); diff --git a/src/build_log_perftest.cc b/src/build_log_perftest.cc index 185c512..b4efb1d 100644 --- a/src/build_log_perftest.cc +++ b/src/build_log_perftest.cc @@ -92,7 +92,7 @@ bool WriteTestData(string* err) { log.RecordCommand(state.edges_[i], /*start_time=*/100 * i, /*end_time=*/100 * i + 1, - /*restat_mtime=*/0); + /*mtime=*/0); } return true; diff --git a/src/build_log_test.cc b/src/build_log_test.cc index f4c9044..ad30380 100644 --- a/src/build_log_test.cc +++ b/src/build_log_test.cc @@ -181,7 +181,7 @@ TEST_F(BuildLogTest, SpacesInOutputV4) { ASSERT_TRUE(e); ASSERT_EQ(123, e->start_time); ASSERT_EQ(456, e->end_time); - ASSERT_EQ(456, e->restat_mtime); + ASSERT_EQ(456, e->mtime); ASSERT_NO_FATAL_FAILURE(AssertHash("command", e->command_hash)); } @@ -205,14 +205,14 @@ TEST_F(BuildLogTest, DuplicateVersionHeader) { ASSERT_TRUE(e); ASSERT_EQ(123, e->start_time); ASSERT_EQ(456, e->end_time); - ASSERT_EQ(456, e->restat_mtime); + ASSERT_EQ(456, e->mtime); ASSERT_NO_FATAL_FAILURE(AssertHash("command", e->command_hash)); e = log.LookupByOutput("out2"); ASSERT_TRUE(e); ASSERT_EQ(456, e->start_time); ASSERT_EQ(789, e->end_time); - ASSERT_EQ(789, e->restat_mtime); + ASSERT_EQ(789, e->mtime); ASSERT_NO_FATAL_FAILURE(AssertHash("command2", e->command_hash)); } @@ -240,7 +240,7 @@ TEST_F(BuildLogTest, VeryLongInputLine) { ASSERT_TRUE(e); ASSERT_EQ(456, e->start_time); ASSERT_EQ(789, e->end_time); - ASSERT_EQ(789, e->restat_mtime); + ASSERT_EQ(789, e->mtime); ASSERT_NO_FATAL_FAILURE(AssertHash("command2", e->command_hash)); } diff --git a/src/build_test.cc b/src/build_test.cc index d617143..0eb9aaa 100644 --- a/src/build_test.cc +++ b/src/build_test.cc @@ -1485,7 +1485,7 @@ TEST_F(BuildWithLogTest, RestatMissingInput) { // the right mtime BuildLog::LogEntry* log_entry = build_log_.LookupByOutput("out1"); ASSERT_TRUE(NULL != log_entry); - ASSERT_EQ(restat_mtime, log_entry->restat_mtime); + ASSERT_EQ(restat_mtime, log_entry->mtime); // Now remove a file, referenced from depfile, so that target becomes // dirty, but the output does not change @@ -1502,7 +1502,7 @@ TEST_F(BuildWithLogTest, RestatMissingInput) { // Check that the logfile entry remains correctly set log_entry = build_log_.LookupByOutput("out1"); ASSERT_TRUE(NULL != log_entry); - ASSERT_EQ(restat_mtime, log_entry->restat_mtime); + ASSERT_EQ(restat_mtime, log_entry->mtime); } struct BuildDryRun : public BuildWithLogTest { diff --git a/src/graph.cc b/src/graph.cc index 76d996b..27013d5 100644 --- a/src/graph.cc +++ b/src/graph.cc @@ -168,7 +168,7 @@ bool DependencyScan::RecomputeOutputDirty(Edge* edge, bool used_restat = false; if (edge->GetBindingBool("restat") && build_log() && (entry = build_log()->LookupByOutput(output->path()))) { - output_mtime = entry->restat_mtime; + output_mtime = entry->mtime; used_restat = true; } @@ -182,17 +182,29 @@ bool DependencyScan::RecomputeOutputDirty(Edge* edge, } } - // May also be dirty due to the command changing since the last build. - // But if this is a generator rule, the command changing does not make us - // dirty. - if (!edge->GetBindingBool("generator") && build_log()) { + if (build_log()) { + bool generator = edge->GetBindingBool("generator"); if (entry || (entry = build_log()->LookupByOutput(output->path()))) { - if (BuildLog::LogEntry::HashCommand(command) != entry->command_hash) { + if (!generator && + BuildLog::LogEntry::HashCommand(command) != entry->command_hash) { + // May also be dirty due to the command changing since the last build. + // But if this is a generator rule, the command changing does not make us + // dirty. EXPLAIN("command line changed for %s", output->path().c_str()); return true; } + if (entry->mtime < most_recent_input->mtime()) { + // May also be dirty due to the mtime in the log being older than the + // mtime of the most recent input. This can occur even when the mtime + // on disk is newer if a previous run wrote to the output file but + // exited with an error or was interrupted. + EXPLAIN("recorded mtime of %s older than most recent input %s (%d vs %d)", + output->path().c_str(), most_recent_input->path().c_str(), + entry->mtime, most_recent_input->mtime()); + return true; + } } - if (!entry) { + if (!entry && !generator) { EXPLAIN("command line not found in log for %s", output->path().c_str()); return true; } -- cgit v0.12