Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

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

Closed
wants to merge 1 commit into from

Conversation

jdrouhard
Copy link
Contributor

@jdrouhard jdrouhard commented Mar 24, 2021

This is the same PR as #1753 but includes the fixes from #1933. Some additional discussion about the slight performance regression this introduces should be done. The tradeoff this PR introduces is improved robustness against external processes modifying build input files during the build at the cost of a stat() on each input just before an edge's command is run.

Commit message follows:


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 is running its command 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.

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 is running its command 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
Copy link
Contributor Author

cc: @bradking @jhasse

Copy link
Contributor

@bradking bradking left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I've confirmed that CMake's test suite is happy with this PR as of commit b0f83c32.

The goal of the change in this PR is to improve robustness against changes to sources that are made during the build by processes that are not part of the build, such as a human with an external editor. The performance cost is an extra stat for every input of every edge that executes during each build.

}

// Take into account the mtime of the depfile. Special depfiles (denoted with a "deps"
// binding) are handled above
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

The "Special depfiles" are just depfiles that are loaded into the DepsLog. Perhaps:

// If we have 'depfile' but not 'deps' then the depfile is not
// loaded into the deps log.  Take its mtime into account.

if (depfile_mtime == -1)
return false;
if (depfile_mtime > record_mtime)
record_mtime = depfile_mtime;
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

What if the depfile names an implicit dependency that is newer than itself or any other known input? In that case we won't log the proper mtime for the edge. With the most-recent-input-mtime approach, we do need to load each depfile immediately after it is written even when not using the deps log. It is no longer sufficient to defer loading it to future builds.

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

True, parsing the depfile and discovering new inputs during FinishCommand() is likely necessary, now. I can work on that in the next week.

// If there were any added deps, compute the most recent input mtime
for (vector<Node*>::iterator i = deps_nodes.begin();
i != deps_nodes.end(); ++i) {
(*i)->StatIfNecessary(disk_interface_, err);
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

What if the newly-known input was modified externally between the time that the edge's command actually used it, and the time that we are now stat-ing it?

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Since we didn't know about it when we started, the best we can do is get the time now. It's why the PR isn't 100% robust around external input modification during the build. The only way to get 100% correctness is to use dyndep to discover all inputs before the actual edge command is started. To be fair, doing it this way is no worse than what currently exists in ninja (other than the possibility of an unneeded rebuild on a subsequent run - if this input wasn't known to this edge specifically but was known during the initial build plan generation).

We can't make this Stat() as it defeats the purpose of the PR. Since deps_nodes contains all dependencies from the "special" dep file (not only those that weren't known at edge command start time), using Stat() here would mean that changes to the input while the edge command is run would be lost on future builds.

A better way to do this would be to somehow track which deps were discovered that are "new" and were not counted for during the initial edge start input dep list. We could Stat() only those, and simply bypass doing anything with the ones we know we counted for when edge was started.

Unfortunately, the RecordDeps() function used below this short circuits actually figuring out which deps are new in favor of simply replacing the list with the new one if they are detected as different. I could take a crack at improving this dependency discovery/updating to be a bit more intelligent without sacrificing any performance, but I'm not sure where that will take me.

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))
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

For reference, this being Stat rather than StatIfNecessary is the crux of the performance impact of this approach. It is needed to account for cases in which an input is modified after the build plan was created but before an edge runs.

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

@bradking I had another thought this morning. What if, instead of trying to be intelligent about tracking the most recent input mtime for an output, we simply touch the output file just prior to starting the edge command, and remember the mtime of the file at that point (and record it when processing the successful command later)? If the output doesn't exist yet, we can simply delete it immediately after grabbing the mtime. We'd probably only have to do this for the first output of the edge (instead of attempting to do it for all outputs).

If the command fails, we won't record any new output mtime in the log file, so subsequent runs would still use the last-successful recorded mtime to compare against current inputs.

I think this solves the performance issue (touch/stat of one file per edge vs a stat of all input files per edge) as well as the hole this PR currently has related to inputs not known to the edge when the command is started.

Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Interesting idea. Do we even need to touch the actual output? We could touch another file, or even try to just compute the current time ourselves.

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I started with computing the time ourselves, but determined it's bad to compare filesystem mtimes to system times. This at least keeps ninja comparing filesystem times to each other.

We could touch another file, but I was concerned that a destination file on one filesystem might have different time stamping granularity (or times, in the case of NFS) than whatever temporary file we decided to use.

Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

It feels risky to touch the actual output in case the build is interrupted.

Another approach is to touch a .ninja_tmp file in the same directory as the first output, get its mtime, and then remove it.

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Yep, that's exactly what I'm trying in a separate branch right now.

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

This is working. I'm pretty excited about this alternative, it's much less intrusive than this change, is more performant, and I think is correct even more of the time.

Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Great! That approach should probably be in a new PR.

@jdrouhard
Copy link
Contributor Author

Closed in favor of #1943.

@jdrouhard jdrouhard closed this Mar 28, 2021
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

Successfully merging this pull request may close these issues.

2 participants