Follow up fixes to #1753 #1933

jdrouhard · 2021-03-22T17:13:27Z

These are followup fixes for #1753 and fixes #1932.

Check the output file's mtime against the most recent input time before checking the build log
For outputs created by generator rules, record the restat'd output's mtime in the build log
Always include depfile mtime in build log mtime if special deps binding isn't specified
Fix performance regression (change Stat() to StatIfNecessary() in StartEdge())

jdrouhard · 2021-03-22T17:13:48Z

bradking · 2021-03-22T17:46:42Z

I've confirmed this fixes #1932, but some of CMake's test suite still fails. I'll track down the next case.

…re checking the build log This is a followup fix for ninja-build#1753. Fixes ninja-build#1932 `build_log()` will always be valid (even for new builds). We should be checking for the output being older than the input before we check the build log for additional possible conditions that would make the output dirty.

bradking · 2021-03-22T18:01:39Z

See additional case posted in #1932 (comment).

bradking · 2021-03-22T20:09:57Z

@jdrouhard as of commit 9fb5867362 all but one of CMake's tests pass. I'm still tracking down the remaining failure.

bradking · 2021-03-22T21:14:04Z

See additional case posted in #1932 (comment).

…mtime in the build log Generator rules may create inputs before creating the outputs. To avoid possible infinite loops, record the actual mtime of the output file in build log instead of the most recent input when the edge started building, since the edge's rule could create newer inputs.

…ng isn't specified Since the edge command might produce the depfile (implicit input) along with the output(s), it should be taken into account when determining the mtime to record in the build log for the outputs. If it's not, then the next run could see a stale mtime since the previous run would have recorded the most recent mtime excluding the depfile itself. For special depfiles (msvcc and gcc as of this commit), the depfiles are themselves parsed when the edge command is finished and the most recent input time of the parsed implicit deps is directly used instead.

jdrouhard · 2021-03-23T02:05:42Z

src/build.cc

@@ -692,7 +692,7 @@ bool Builder::StartEdge(Edge* edge, string* err) {
  Node* most_recent_input = NULL;
  for (vector<Node*>::iterator i = edge->inputs_.begin();
       i != edge->inputs_.end() - edge->order_only_deps_; ++i) {
-    if (!(*i)->Stat(disk_interface_, err))
+    if (!(*i)->StatIfNecessary(disk_interface_, err))


This was discussed in #1753 but I think the performance tradeoff should lean toward speed over correctness. If we err on the side of speed, we just might have unnecessary rebuilds on future runs (as opposed to the alternative which is thinking outputs are up to date when they are actually dirty).

A build system should not re-run commands when not needed. We don't know how many downstream dependencies might need to rebuild unnecessarily.

We discussed this on the original PR, I think you actually wondered why this wasn't StatIfNecessary() to begin with.

This shouldn't cause ninja to rerun commands if the inputs don't change, which is identical behavior to what was here before #1753.

Here is an example that change affects:

rm -f .ninja_deps .ninja_log out1 out2 in1 in2imp >in1 echo >build.ninja ' rule touch_out_discovered_during_build command = touch $out $discovered rule touch_dep_discovered_during_build command = touch $out; echo "$out: $discovered" > $depfile build out1: touch_out_discovered_during_build in1 discovered = in2imp build out2: touch_dep_discovered_during_build in1 || out1 discovered = in2imp depfile = out2.d deps = gcc default out2' ninja >/dev/null 2>&1 sleep 1 >in1 ninja ninja -d explain

With Stat, or prior to #1753, the output is:

[1/2] touch out1 in2imp [2/2] touch out2; echo "out2: in2imp" > out2.d ninja: no work to do.

With StatIfNecessary after #1753, the output is:

[1/2] touch out1 in2imp [2/2] touch out2; echo "out2: in2imp" > out2.d ninja explain: recorded mtime of out2 older than most recent input in2imp (... vs ...) [1/1] touch out2; echo "out2: in2imp" > out2.d

Yeah, this test is unfortunate. Using StatIfNecessary() could lead to infinite rebuild loops (target would never be clean) with this specific relationship of rules and implicit dependencies being updated by the rules. out1 has no specific knowledge that it updated in2imp so there's nothing we can do when finishing the command for out1 to update the cached mtime for in2imp.

If we want to keep the better build correctness that #1753 provides, it looks like there's no way to avoid Stat() when edges are started which does have a performance penalty.

IIUC #1753 provides robustness against edits made to the source tree during the build by processes outside the build system. We need to decide if supporting that is worth making everyone pay for the extra Stat on every build just in case someone does that.

This investigation led me to find that CMake Issue 20025 has the same root cause, even with Ninja 1.10 (which does not have #1753). Cases like this might be resolvable using a dyndep binding to declare the dynamically-discovered implicit output so that Ninja knows about it. I still need to try that out to be sure.

However, CMake's cases are just examples of existing cases that may exist in the wild. Many projects would have had no choice but to express things as in my above example because dyndep support is recent.

I suggest dropping commit 53f96fed for now so we can get everything else fixed. Then open an issue to discuss this optimization.

Yeah, that sounds good. I'm going to go ahead and add regression tests for this case anyhow.

might be resolvable using a dyndep binding... I still need to try that out to be sure.

Unfortunately that won't work without additional changes to Ninja. See the explanation I posted in the CMake issue.

bradking · 2021-03-23T11:58:51Z

As of commit f2205713 all of CMake's tests pass. However, commit 53f96fed breaks one again.

jdrouhard · 2021-03-23T12:41:09Z

As of commit f2205713 all of CMake's tests pass. However, commit 53f96fed breaks one again.

What test? We really should port more of CMake's ninja tests to native ninja tests.

bradking · 2021-03-23T12:44:43Z

commit 53f96fe breaks one again.
What test?

It's the Qt5Autogen.RerunMocBasic test. I won't have time until later to try to narrow it down to a ninja-only example.

These expose some quirky behavior of implicit deps that are not directly known to the ninja build system.

jhasse · 2021-03-23T19:59:08Z

Hi! Thanks for your work. I haven't followed everything yet.

I think a good idea would be to actually revert the merge commit of #1753, then add the test cases (except those for #1753) and then draft a new version of #1753 with the fixups. What do you think?

We could also merge this PR, but then the actual change (and the fixes for it) would be scattered.

jdrouhard · 2021-03-23T20:20:03Z

I can do that. I'll open another PR with the revert + new tests, and a second one that re-lands the change along with the fixes.

This reverts commit 67fbbee. There were a few missing test cases exposed by CMake's test suite that need slight adjustments. Better to revert the original attempt, add the test cases, and then re-land the change with the fixes. Fixes ninja-build#1933

These expose some behavior related to implicit deps unknown to ninja and timestamps with generating them as part of a rule. See discussions in ninja-build#1932 and ninja-build#1933.

jdrouhard changed the title ~~Check the output file's mtime against the most recent input time before checking the build log (Fixes #1932)~~ Check the output file's mtime against the most recent input time before checking build log Mar 22, 2021

bradking mentioned this pull request Mar 22, 2021

build.ninja generator not re-running when it should #1932

Closed

jdrouhard force-pushed the fix_dirty_status_computation branch from 46202d4 to 8884066 Compare March 22, 2021 18:01

jdrouhard changed the title ~~Check the output file's mtime against the most recent input time before checking build log~~ Fix dirty status computation for generator rules and first runs with implicit deps Mar 22, 2021

jdrouhard added 2 commits March 22, 2021 19:35

jdrouhard force-pushed the fix_dirty_status_computation branch from 5fa40fe to f220571 Compare March 23, 2021 00:36

jdrouhard changed the title ~~Fix dirty status computation for generator rules and first runs with implicit deps~~ Follow up fixes to #1753 Mar 23, 2021

jdrouhard commented Mar 23, 2021

View reviewed changes

Add some regression tests for additional use cases

7b04cd7

These expose some quirky behavior of implicit deps that are not directly known to the ninja build system.

jdrouhard force-pushed the fix_dirty_status_computation branch from 53f96fe to 7b04cd7 Compare March 23, 2021 19:38

jdrouhard closed this Mar 23, 2021

jdrouhard mentioned this pull request Mar 23, 2021

Revert #1753 and add additional tests to expose previously untested behavior #1935

Merged

jdrouhard deleted the fix_dirty_status_computation branch March 23, 2021 20:24

jdrouhard mentioned this pull request Mar 24, 2021

Change build log to always log the most recent input mtime #1936

Closed

bradking mentioned this pull request Mar 24, 2021

dyndep: reconcile dyndep-specified outputs with depfile-specified inputs #1937

Merged

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Follow up fixes to #1753 #1933

Follow up fixes to #1753 #1933

jdrouhard commented Mar 22, 2021 •

edited

Loading

jdrouhard commented Mar 22, 2021

bradking commented Mar 22, 2021

bradking commented Mar 22, 2021

bradking commented Mar 22, 2021

bradking commented Mar 22, 2021

jdrouhard Mar 23, 2021

bradking Mar 23, 2021

jdrouhard Mar 23, 2021

bradking Mar 23, 2021

jdrouhard Mar 23, 2021

bradking Mar 23, 2021

bradking Mar 23, 2021

bradking Mar 23, 2021

jdrouhard Mar 23, 2021

bradking Mar 24, 2021

bradking commented Mar 23, 2021

jdrouhard commented Mar 23, 2021

bradking commented Mar 23, 2021

jhasse commented Mar 23, 2021

jdrouhard commented Mar 23, 2021

Follow up fixes to #1753 #1933

Follow up fixes to #1753 #1933

Conversation

jdrouhard commented Mar 22, 2021 • edited Loading

jdrouhard commented Mar 22, 2021

bradking commented Mar 22, 2021

bradking commented Mar 22, 2021

bradking commented Mar 22, 2021

bradking commented Mar 22, 2021

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

bradking commented Mar 23, 2021

jdrouhard commented Mar 23, 2021

bradking commented Mar 23, 2021

jhasse commented Mar 23, 2021

jdrouhard commented Mar 23, 2021

jdrouhard commented Mar 22, 2021 •

edited

Loading