Make freshness/rebuilding tests more robust #5953

alexcrichton · 2018-08-30T23:50:39Z

This commit implements a new heavy handed strategy in the test suite to avoid
spurious test failures and improve consistency across platforms. Instead of
letting mtimes naturally work as they normally do through out tests we force all
executions of cargo in the tests to, just before cargo is run, deterministically set all mtime values. This way all executions of cargo`
should see the same mtime and hopefully not be susceptible to drift here and
there.

Additionally tests now have the ability to say that a file needs to be created
(to test mtimes and such). This will whitelist the file as having a new mtime
which is known to be a large amount of time in the future (to avoid bugs with
fast or slow tests). This way we also know exactly that we can bust caches in
tests.

Finally, Cargo was outfitted with a new change. Whenever Cargo is tracking mtime
data it will latch onto the newest mtime (even if it's in the future) for the
output. This is meant to handle two cases:

For tests which have files in the far future it allows subsequent rebuilds to
work correctly, otherwise since a test never takes hours it looks like there's
always a file modified in the future.
When a file is edited during a build this should ensure that the mtime
recorded for the build is the mtime before the build starts rather than
after the build finishes, ensuring that we correctly schedule builds for
edited files.

Closes #5940

rust-highfive · 2018-08-30T23:50:44Z

r? @matklad

(rust_highfive has picked a reviewer for you, use r? to override)

alexcrichton · 2018-08-30T23:51:20Z

r? @ehuss and @dwijnand

I'm still trying to run this through the gauntlet locally as well as see the effect of cross platform testing, but this should hopefully be mostly done!

dwijnand · 2018-08-31T05:51:13Z

When a file is edited during a build this should ensure that the mtime
recorded for the build is the mtime before the build starts rather than
after the build finishes, ensuring that we correctly schedule builds for
edited files.

Cool! Sounds like this fixes #2426.

dwijnand

I have a couple of questions, the one about the output changing in path::deep_dependencies_trigger_rebuild being the most important one, which is also the only test that failed on Travis CI. On AppVeyor only 17 test failures!

Overall this looks great to me, thanks!

tests/testsuite/path.rs

dwijnand · 2018-08-31T06:01:11Z

tests/testsuite/path.rs

    p.cargo("build")
        .with_stderr(&format!(
-            "[COMPILING] baz v0.5.0 (CWD/baz)\n\


How come these outputs changed?

Oops! I think I messed something up, wasn't intended to change

dwijnand · 2018-08-31T06:03:06Z

tests/testsuite/support/mod.rs

@@ -202,6 +204,9 @@ impl SymlinkBuilder {

 pub struct Project {
    root: PathBuf,
+    start: FileTime,
+    updates: HashMap<PathBuf, FileTime>,
+    next_update: i64,


Do you think it's worth documenting these?

Oops yes, meant to do that already!

dwijnand · 2018-08-31T06:05:02Z

tests/testsuite/support/mod.rs

+
+    pub fn move_start_back_one_second(&mut self) {
+        self.start = FileTime::from_unix_time(
+            self.start.unix_seconds(),


Is there a "one second" part missing here? Or am I missing something?

Oops, my bad!

tests/testsuite/freshness.rs

dwijnand · 2018-08-31T08:42:06Z

src/cargo/core/compiler/fingerprint.rs

+                    filetime::set_file_times(&path, time_to_set, time_to_set)?;
+                    MtimeState::LatestTimeIs(time_to_set)
+                }
+                _ => {


This is kind of general, but I tend to avoid using default cases on sum types because if that algebra every changes (in this case, say an OlderThanOrEqual case is added) it's easy to miss changing these code paths because the exhaustivity checker won't tell you.

In short I'd use

MtimeState::LatestTimeIs(_) | NotAvailable => {

here instead.

Good practice or YAGNI? 🤷‍♂️

Sounds good to me!

ehuss · 2018-08-31T19:37:06Z

Cool! Sounds like this fixes #2426.

It looks like it is mostly fixed. It doesn't handle files being modified during the first build. This is because the fingerprint starts out with MtimeState::NotAvailable and then is updated to the mtime of the dep-info file (here), which has an mtime towards the end of the build. Similarly if you remove a file it doesn't handle mid-build modifications (also NotAvailable). It would need to somehow capture the time when the build starts (similar to your original PR).

ehuss · 2018-08-31T19:37:30Z

There's a problem with it always rebuilding. Example:

cargo new --lib a
cd a
cargo build
touch src/lib.rs
cargo build
cargo build <- this should not rebuild but it does

I'm not entirely sure at this point how to fix, but it looks like the problem is that when the Fingerprint is first created it contains an MtimeState of OlderThan which hashes to None. When the fingerprint is saved to disk, it has a value of LatestTimeIs which won't compare the same.

alexcrichton · 2018-08-31T23:45:36Z

@ehuss oh good points! I don't think this'll close #2426 yet.

I was also hoping to not touch Cargo at all in this change. One possibility is to just avoid touching the two tests that require the changes to Cargo (one is the deep dependencies test). It'd be a bit of a bummer though to not change those tests which have been flaky!

In any case I'll look into the bug when I get a chance and see if the fix is too invasive of if it's just a typo.

bors · 2018-09-03T22:50:59Z

☔ The latest upstream changes (presumably #5966) made this pull request unmergeable. Please resolve the merge conflicts.

alexcrichton · 2018-09-04T21:35:53Z

Ok I think that the changes to Cargo itself probably won't work at this time. There's only two tests which break with the mtime management added here to the test suite, so I've left the sleeps in there and added a method to disable mtime management. This should now hopefully be green and have at least no functional change to Cargo itself!

r? @ehuss

bors · 2018-09-05T00:47:50Z

☔ The latest upstream changes (presumably #5976) made this pull request unmergeable. Please resolve the merge conflicts.

ehuss · 2018-09-05T02:28:58Z

I tried testing the latest commit a little, and I'm still running into a lot of errors. Out of 10 runs, I got the following errors:

Error list

1 bench::bench_dylib
1 build_script::fresh_builds_possible_with_link_libs
1 build_script::optional_build_dep_and_required_normal_dep
1 fix::doesnt_rebuild_dependencies
1 freshness::dont_rebuild_based_on_plugins
1 freshness::no_rebuild_when_rename_dir
1 freshness::same_build_dir_cached_packages
1 freshness::unused_optional_dep
1 patch::nonexistent
1 patch::patch_git
1 patch::unused
1 path::nested_deps_recompile
1 profile_targets::profile_selection_bench
1 profile_targets::profile_selection_build
1 profile_targets::profile_selection_test_release
1 run::specify_name
1 rustflags::cfg_rustflags_precedence
1 test::selective_testing
1 test::test_dylib
2 build::recompile_space_in_name
2 freshness::no_rebuild_if_build_artifacts_move_backwards_in_time
2 metabuild::metabuild_fresh
2 patch::patch_in_virtual
2 profile_targets::profile_selection_build_release
2 profile_targets::profile_selection_check_all_targets
2 profile_targets::profile_selection_check_all_targets_release
2 test::bin_does_not_rebuild_tests
2 workspaces::dep_used_with_separate_features
3 build_script::fresh_builds_possible_with_multiple_metadata_overrides
3 features::many_features_no_rebuilds
3 freshness::changing_lib_features_caches_targets
3 freshness::changing_profiles_caches_targets
3 patch::new_major
3 patch::patch_depends_on_another_patch
3 path::no_rebuild_dependency
3 profile_targets::profile_selection_build_all_targets_release
4 freshness::no_rebuild_transitive_target_deps
4 path::custom_target_no_rebuild
6 path::deep_dependencies_trigger_rebuild
6 rustc::rustc_fingerprint

For example, it looks like deep_dependencies_trigger_rebuild got reverted back to its previous behavior (sleeping before creating the file instead of after). I can review the other tests and try to figure out why they still have issues if you'd like, though it may go slowly.

alexcrichton · 2018-09-05T06:57:24Z

@ehuss do you know what the problems are? I don't know why you're seeing so many errors when I never see any myself

dwijnand · 2018-09-05T07:08:47Z

Perhaps ehuss isn't using APFS?

ehuss · 2018-09-05T15:40:46Z

Perhaps ehuss isn't using APFS?

Correct, this only happens on HFS. APFS has sub-second timestamps.

Here's some examples from a few of them:

rustc_fingerprint

start mtime = N

First compile finishes in under 1 sec, fingerprint mtime = N
Second compile, foo is not fresh because N==N

deep_dependencies_trigger_rebuild

See #5952 (comment)

custom_target_no_rebuild

start mtime = N

First compile finishes in under 1 sec, fingerprint mtime = N
Second compile, a is not fresh because N==N

no_rebuild_transitive_target_deps

start mtime = N

First compile finishes in under 1 sec, fingerprint mtime = N
Second compile, a is not fresh because N==N

alexcrichton · 2018-09-05T16:48:37Z

Hm ok, makes sense! Thinking about it I think the original change I had here with modifying Cargo's own concept of mtime is fundamentally required for 1-second resolution filesystems to run the test suite, otherwise everything is just horribly broken. I'll look into fixing it again.

This commit implements a new heavy handed strategy in the test suite to avoid spurious test failures and improve consistency across platforms. Instead of letting mtimes naturally work as they normally do through out tests we force all executions of `cargo` in the tests to, just before `cargo` is run`, deterministically set all mtime values. This way all executions of `cargo` should see the same mtime and hopefully not be susceptible to drift here and there. Additionally tests now have the ability to say that a file needs to be created (to test mtimes and such). This will whitelist the file as having a new mtime which is known to be a large amount of time in the future (to avoid bugs with fast or slow tests). This way we also know exactly that we can bust caches in tests. Finally, Cargo was outfitted with a new change. Whenever Cargo is tracking mtime data it will latch onto the newest mtime (even if it's in the future) for the output. This is meant to handle two cases: * For tests which have files in the far future it allows subsequent rebuilds to work correctly, otherwise since a test never takes hours it looks like there's always a file modified in the future. * When a file is edited during a build this should ensure that the mtime recorded for the build is the mtime *before* the build starts rather than after the build finishes, ensuring that we correctly schedule builds for edited files. Closes rust-lang#5940

alexcrichton · 2018-09-05T21:35:35Z

Hm so I still don't quite understand how this is causing problems. I just ran cargo test locally on my mac with a locally mounted HFS filesystem and it got zero failures. I suppose this computer could just be too slow, but it's really hard to verify anything if I can't reproduce anything.

alexcrichton · 2018-09-05T21:59:46Z

I'm basically at a loss of what to do. I have no idea how to solve this in a way that doesn't involve overhauling everything which supports all the filesystems and all the way up to one second resolution. If no one else can think of a great way to solve this I'll just close this in the next few days.

dwijnand · 2018-09-05T22:41:01Z

🙁

I'll just close this in the next few days

The .set_root is useful, but I can always reap it from this PR.

alexcrichton · 2018-09-05T22:45:28Z

Ah yeah definitely feel free to! I think I'll actually go ahead and close.

rust-highfive assigned matklad Aug 30, 2018

alexcrichton mentioned this pull request Aug 30, 2018

Timing errors on some cargo tests on macOS #5940

Closed

rust-highfive assigned ehuss and unassigned matklad Aug 30, 2018

dwijnand reviewed Aug 31, 2018

View reviewed changes

alexcrichton force-pushed the urgh-mtimes branch from 47a4c3f to c544a9f Compare August 31, 2018 23:39

alexcrichton force-pushed the urgh-mtimes branch from c544a9f to 0c90b7c Compare September 4, 2018 21:34

alexcrichton force-pushed the urgh-mtimes branch from 0c90b7c to 908645d Compare September 5, 2018 17:14

alexcrichton closed this Sep 5, 2018

alexcrichton deleted the urgh-mtimes branch September 5, 2018 22:45

dwijnand mentioned this pull request Sep 5, 2018

Introduce test/Project#within #5986

Closed

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Make freshness/rebuilding tests more robust #5953

Make freshness/rebuilding tests more robust #5953

alexcrichton commented Aug 30, 2018

rust-highfive commented Aug 30, 2018

alexcrichton commented Aug 30, 2018

dwijnand commented Aug 31, 2018

dwijnand left a comment

dwijnand Aug 31, 2018

alexcrichton Aug 31, 2018

dwijnand Aug 31, 2018

alexcrichton Aug 31, 2018

dwijnand Aug 31, 2018

alexcrichton Aug 31, 2018

dwijnand Aug 31, 2018

alexcrichton Aug 31, 2018

ehuss commented Aug 31, 2018

ehuss commented Aug 31, 2018 •

edited

Loading

alexcrichton commented Aug 31, 2018

bors commented Sep 3, 2018

alexcrichton commented Sep 4, 2018

bors commented Sep 5, 2018

ehuss commented Sep 5, 2018

alexcrichton commented Sep 5, 2018

dwijnand commented Sep 5, 2018

ehuss commented Sep 5, 2018

alexcrichton commented Sep 5, 2018

alexcrichton commented Sep 5, 2018

alexcrichton commented Sep 5, 2018

dwijnand commented Sep 5, 2018

alexcrichton commented Sep 5, 2018

Make freshness/rebuilding tests more robust #5953

Make freshness/rebuilding tests more robust #5953

Conversation

alexcrichton commented Aug 30, 2018

rust-highfive commented Aug 30, 2018

alexcrichton commented Aug 30, 2018

dwijnand commented Aug 31, 2018

dwijnand left a 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

ehuss commented Aug 31, 2018

ehuss commented Aug 31, 2018 • edited Loading

alexcrichton commented Aug 31, 2018

bors commented Sep 3, 2018

alexcrichton commented Sep 4, 2018

bors commented Sep 5, 2018

ehuss commented Sep 5, 2018

alexcrichton commented Sep 5, 2018

dwijnand commented Sep 5, 2018

ehuss commented Sep 5, 2018

rustc_fingerprint

deep_dependencies_trigger_rebuild

custom_target_no_rebuild

no_rebuild_transitive_target_deps

alexcrichton commented Sep 5, 2018

alexcrichton commented Sep 5, 2018

alexcrichton commented Sep 5, 2018

dwijnand commented Sep 5, 2018

alexcrichton commented Sep 5, 2018

ehuss commented Aug 31, 2018 •

edited

Loading