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

jdrouhard · 2020-03-15T21:37:30Z

Fixes #1162 and is a continuation of the original idea in #1165.

If an edge's output files' mtimes are compared to the most recent
input's mtime, edges might be calculated as clean even if they are
actually dirty. While an edge's command is running its rule to produce
its outputs and an input to the edge is updated before the outputs are
written to disk, then subsequent runs will think that the outputs are
newer than the inputs, even though the inputs have actually been updated
and may be different than what were used to produce those outputs.

Ninja will now restat all inputs just prior to running an edge's command
and remember the most recent input mtime. When the command completes,
it will stat any discovered dependencies from dep files (if necessary),
recalculate the most recent input mtime, and log it to the build log
file. On subsequent runs, ninja will use this value to compare to the
edge's most recent input's mtime to determine whether the outputs are
dirty.

This extends the methodology used by restat rules to work in all cases.
Restat rules are still unique in that they will clean the edge's output
nodes recursively if the edge's command did not change the output, but
in all cases, the mtime recorded in the log file is now the most recent
input mtime. See the new tests for more clarification.

jdrouhard · 2020-03-16T00:39:02Z

@jhasse let me know when you get a chance to review this or if you have any questions about it.

@bradking you might be interested in this as well. I know you have quite a bit of knowledge about the dependency system of ninja, and the dyndep functionality should make this change work even better.

src/build_test.cc

src/build.cc

bradking · 2020-03-16T14:54:18Z

src/build.cc

+         i != deps_nodes.end(); ++i) {
+      (*i)->StatIfNecessary(disk_interface_, err);
+      if ((*i)->mtime() > most_recent_input)
+        most_recent_input = (*i)->mtime();


What if one of the just-discovered inputs was updated while the command was running, but after the command loaded it? That's the same race. I don't think we can do much about it though. We have no way to know what its mtime was when the command loaded it.

One possible way to address this would be to have the depfile generated by the compiler somehow encode the mtime the file had when the compiler read it. That's way beyond the scope of this PR though.

I have a test that explicitly shows this scenario. Unfortunately like you say, there's nothing we can do. The only way this will work 100% is to use the dyndep functionality to know what the inputs are before running the command.

This code here is just to ensure that discovered deps don't cause subsequent runs to immediately find the output dirty (since a discovered dep might have a newer time than the ones known to the command initially).

bradking · 2020-03-16T15:07:26Z

src/build.cc

+  for (vector<Node*>::iterator i = edge->inputs_.begin();
+        i != edge->inputs_.end() - edge->order_only_deps_; ++i) {
+    if (!(*i)->Stat(disk_interface_, err))
+      return false;


Previously this extra stat() call was made only on restat edge inputs in FinishCommand's node_cleaned case. Now we're calling stat() a second time on every input of every edge that runs. This may not matter because in practice the stat() result will probably be in the filesystem's hot cache, and the time it takes is likely small compared to the time it will take the edge's command to run (whose child process will normally actually open and read the whole input file).

I wonder if we can get away with StatIfNecessary here. Even if the input has been updated since our original stat round when ninja started, we still know that the outputs will not be older than that.

I thought hard about using StatIfNecessary here for awhile. I opted to re-stat because input nodes might be on multiple edges and later edges might be reading a different version of the input if that input is changed after one edge runs but before another begins.

This would cause a false positive on the subsequent run since the recorded mtime would reflect that input's original mtime even though the edge actually ran with the most recent version.

I suppose it's a tradeoff between saving unnecessary rebuilds on subsequent runs vs stat'ing more often while building.

Thanks for explaining. If a performance problem surfaces we can re-consider. Otherwise I think Stat() is fine for now.

bradking

@jhasse I've completed a basic review of this and in principle it LGTM and the tests look adequate.

bradking · 2020-03-16T16:37:29Z

src/build.cc

+  for (vector<Node*>::iterator i = edge->inputs_.begin();
+        i != edge->inputs_.end() - edge->order_only_deps_; ++i) {
+    if (!(*i)->Stat(disk_interface_, err))
+      return false;


Thanks for explaining. If a performance problem surfaces we can re-consider. Otherwise I think Stat() is fine for now.

jdrouhard · 2020-03-16T17:21:52Z

I'm going to squash these review commits. Should be good to go in a sec.

jdrouhard · 2020-03-25T16:04:30Z

@jhasse ping, this is ready for merging!

jhasse

I want to take a closer look and really understand the changes. I don't know when I will find the time to do that, sorry.

src/build.cc

src/build_log.cc

jhasse · 2020-04-15T09:36:44Z

Should we bump the build_log version for this?

jdrouhard · 2020-04-15T14:06:16Z

Should we bump the build_log version for this?

Maybe? The actual format of the log file didn't change, just the interpretation of one of the fields. Going forward, this code can still use build logs generated by previous versions just fine. But if we want to bump it because of the semantic difference, I'm ok with that too.

jhasse · 2020-04-15T14:13:14Z

Could older ninja versions use the log generated by this PR though?

jdrouhard · 2020-04-15T14:39:25Z

Could older ninja versions use the log generated by this PR though?

Yes. Older versions would simply interpret the output mtime column as the output file's actual mtime when the command completed. Since this PR changes that time to be an earlier time than the current code, ninja versions that don't have this PR will be more aggressive at deciding outputs are older and therefore dirty.

jdrouhard · 2021-02-07T19:31:11Z

@jhasse any word on when you can merge this? I just rebased onto current master so it should all be up to date again. Let me know if there's anything else you'd like to see first.

jhasse · 2021-02-11T16:39:04Z

Thanks for rebasing. I'll test your PR in the coming weeks and then merge it if I don't find anything.

jdrouhard · 2021-03-03T16:15:50Z

@jhasse rebased again. I've been using this branch at work in our large codebase for months and it's been working perfectly, how has your testing with it been going?

jhasse

Also no issues on my site :)

src/graph.cc

jdrouhard · 2021-03-05T15:23:46Z

@jhasse ready to merge soon? :D

jdrouhard · 2021-03-09T02:56:03Z

@jhasse are you waiting on anything else before merging this?

jdrouhard · 2021-03-12T14:58:03Z

@jhasse rebased this on master

If an edge's output files' mtimes are compared to the most recent input's mtime, edges might be calculated as clean even if they are actually dirty. While an edge's command is running its rule to produce its outputs and an input to the edge is updated before the outputs are written to disk, then subsequent runs will think that the outputs are newer than the inputs, even though the inputs have actually been updated and may be different than what were used to produce those outputs. Ninja will now restat all inputs just prior to running an edge's command and remember the most recent input mtime. When the command completes, it will stat any discovered dependencies from dep files (if necessary), recalculate the most recent input mtime, and log it to the build log file. On subsequent runs, ninja will use this value to compare to the edge's most recent input's mtime to determine whether the outputs are dirty. This extends the methodology used by restat rules to work in all cases. Restat rules are still unique in that they will clean the edge's output nodes recursively if the edge's command did not change the output, but in all cases, the mtime recorded in the log file is now the most recent input mtime. See the new tests for more clarification.

jhasse · 2021-03-20T14:07:17Z

Thanks!

I'm a little bit unsure about increasing the log version.

It would also be interesting to know how much this changes performance.

Merging this will actually increase the exposure. Let's see, I can't promise that we won't actually need to rethink this change before the release.

jdrouhard · 2021-03-20T14:55:29Z

It would also be interesting to know how much this changes performance.

If it suffers too much, a simple change to get performance back on par is to use StatIfNecessary() instead of Stat() when starting an edge and looping over all known input nodes to get the most recent input mtime. It would speed things up at the cost of potentially marking things dirty that don't need to be. I believe there was a discussion about this trade off in the PR review.

Merging this will actually increase the exposure. Let's see, I can't promise that we won't actually need to rethink this change before the release.

Let's hope it works out! I've been trying to get this issue fixed in ninja for over 5 years now so I'm pretty excited. Thanks for merging!

…re checking the build log (Fixes ninja-build#1932) This is a followup fix for ninja-build#1753. `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.

…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.

After ninja-build#1753, every file that was a non-order-only input to any edge was being restat for each edge that had that same file as an input. Turns out that's a lot of stat calls, so a simple tradeoff here is to just stat each input file once during the build and use that mtime for each edge that has it as an input when determining the most recent input mtime. This could potentially lead to unnecessary rebuilds (if one edge that shares an input with another edge is started after the input is changed but that input was changed after the first output's edge stat'd it). The significant speed increase is worth it.

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

jdrouhard force-pushed the log_input_mtime branch 2 times, most recently from 8b36c11 to 7df1459 Compare March 15, 2020 21:46

bradking suggested changes Mar 16, 2020

View reviewed changes

bradking approved these changes Mar 16, 2020

View reviewed changes

jdrouhard force-pushed the log_input_mtime branch from 7f396a5 to bd01093 Compare March 16, 2020 17:24

jhasse reviewed Mar 25, 2020

View reviewed changes

src/build.cc Outdated Show resolved Hide resolved

src/build_log.cc Show resolved Hide resolved

jhasse added this to the 1.11.0 milestone Mar 25, 2020

jdrouhard force-pushed the log_input_mtime branch from 4f6e5b4 to 1ee7452 Compare August 12, 2020 18:32

jdrouhard force-pushed the log_input_mtime branch from 1ee7452 to e4918fb Compare February 7, 2021 19:28

jdrouhard force-pushed the log_input_mtime branch from e4918fb to 1af5cf2 Compare March 3, 2021 16:14

jhasse approved these changes Mar 4, 2021

View reviewed changes

src/graph.cc Outdated Show resolved Hide resolved

jdrouhard force-pushed the log_input_mtime branch from 1af5cf2 to 8829aca Compare March 12, 2021 14:57

jdrouhard force-pushed the log_input_mtime branch from 8829aca to 67fbbee Compare March 16, 2021 23:40

jhasse merged commit 2b97efa into ninja-build:master Mar 20, 2021

jdrouhard deleted the log_input_mtime branch March 22, 2021 13:51

bradking mentioned this pull request Mar 22, 2021

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

Closed

jdrouhard mentioned this pull request Mar 22, 2021

Follow up fixes to #1753 #1933

Closed

jdrouhard mentioned this pull request Mar 23, 2021

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

Merged

jhasse added a commit that referenced this pull request Mar 24, 2021

Merge pull request #1935 from jdrouhard/revert_input_mtime

8cd25aa

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

This was referenced Mar 24, 2021

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

Closed

Provide resiliency against inputs changing during the build #1943

Merged

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

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

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

jdrouhard commented Mar 15, 2020

jdrouhard commented Mar 16, 2020

bradking Mar 16, 2020

bradking Mar 16, 2020

jdrouhard Mar 16, 2020

bradking Mar 16, 2020

jdrouhard Mar 16, 2020 •

edited

Loading

bradking Mar 16, 2020

bradking left a comment

bradking Mar 16, 2020

jdrouhard commented Mar 16, 2020

jdrouhard commented Mar 25, 2020

jhasse left a comment

jhasse commented Apr 15, 2020

jdrouhard commented Apr 15, 2020

jhasse commented Apr 15, 2020

jdrouhard commented Apr 15, 2020

jdrouhard commented Feb 7, 2021

jhasse commented Feb 11, 2021

jdrouhard commented Mar 3, 2021

jhasse left a comment

jdrouhard commented Mar 5, 2021

jdrouhard commented Mar 9, 2021

jdrouhard commented Mar 12, 2021

jhasse commented Mar 20, 2021

jdrouhard commented Mar 20, 2021

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

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

Conversation

jdrouhard commented Mar 15, 2020

jdrouhard commented Mar 16, 2020

bradking Mar 16, 2020

Choose a reason for hiding this comment

bradking Mar 16, 2020

Choose a reason for hiding this comment

jdrouhard Mar 16, 2020

Choose a reason for hiding this comment

bradking Mar 16, 2020

Choose a reason for hiding this comment

jdrouhard Mar 16, 2020 • edited Loading

Choose a reason for hiding this comment

bradking Mar 16, 2020

Choose a reason for hiding this comment

bradking left a comment

Choose a reason for hiding this comment

bradking Mar 16, 2020

Choose a reason for hiding this comment

jdrouhard commented Mar 16, 2020

jdrouhard commented Mar 25, 2020

jhasse left a comment

Choose a reason for hiding this comment

jhasse commented Apr 15, 2020

jdrouhard commented Apr 15, 2020

jhasse commented Apr 15, 2020

jdrouhard commented Apr 15, 2020

jdrouhard commented Feb 7, 2021

jhasse commented Feb 11, 2021

jdrouhard commented Mar 3, 2021

jhasse left a comment

Choose a reason for hiding this comment

jdrouhard commented Mar 5, 2021

jdrouhard commented Mar 9, 2021

jdrouhard commented Mar 12, 2021

jhasse commented Mar 20, 2021

jdrouhard commented Mar 20, 2021

jdrouhard Mar 16, 2020 •

edited

Loading