Intermittent coverage failures (some test runs not counted)

[scole66]

I have a large-ish project with ~6000 testcases, and for a long time now, code coverage has been hit-or-miss. The issue is that some of the test cases don't seem to get their data included in the profraw files, and so don't show up as having an effect on coverage. The unrecorded tests seem to be essentially random, but with thousands of tests, single-digit-percentage failures are noticed on every test run.

It's been annoying. So I finally sat down to try and reduce to a simplest error, but it still takes multiple files, so is difficult to include inline in a GitHub issue.

The tree:

.
├── Cargo.lock
├── Cargo.toml
├── check_bug.sh
└── src
    ├── main.rs
    └── statething.rs

When I run a test via:

tst ()
{
    rm -f res-*.profraw;
    RUST_BACKTRACE=1 RUSTFLAGS="-Zinstrument-coverage" LLVM_PROFILE_FILE="res-%m.profraw" cargo test "$@";
    cargo profdata -- merge res-*.profraw --output=res.profdata
}
tst statething

which shows 2 tests run:

    Finished test [unoptimized + debuginfo] target(s) in 0.00s
     Running unittests (target/debug/deps/res-6177536c73daf6cd)

running 2 tests
test statething::tests::state_has_false ... ok
test statething::tests::state_has_true ... ok

test result: ok. 2 passed; 0 failed; 0 ignored; 0 measured; 0 filtered out; finished in 0.00s

Then report on that particular function via:

report ()
{
    cargo cov -- show --use-color --ignore-filename-regex='/rustc/|/\.cargo/|\.rustup/toolchains' --instr-profile=res.profdata $(objects) --show-line-counts-or-regions -Xdemangler=rustfilt "$@"
}
report --name 5State3has

Most of the time, I see the correct result:

<res::statething::State>::has:
    8|      2|    pub fn has(&self, needle: &str) -> bool {
    9|      2|        self.0 == needle
   10|      2|    }

But sometimes (about 1 in 170 times), I see this:

<res::statething::State>::has:
    8|      1|    pub fn has(&self, needle: &str) -> bool {
    9|      1|        self.0 == needle
   10|      1|    }

It seems to be related to having multiple source files; I could not get similar behavior with only a main.rs. I've seen the problem appear on both MacOS (Mohave) and on Windows (in Windows Subsystem for Linux 2)

The two-source-file tree mentioned up above (including the script I run to repeat the test until a failure happens), is on a bug-report branch here: https://github.com/scole66/rust-e262/tree/reduction-for-bugreport

This really feels like whichever thread is controlling writes to the profraw file is missing messages. Queue overrun maybe? (I haven't looked.)

Meta

rustc --version --verbose:

rustc 1.58.0-nightly (a77da2d45 2021-11-19)
binary: rustc
commit-hash: a77da2d454e6caa227a85b16410b95f93495e7e0
commit-date: 2021-11-19
host: x86_64-unknown-linux-gnu
release: 1.58.0-nightly
LLVM version: 13.0.0

[scole66]

@rustbot label A-code-coverage

[Swatinem]

I see you are using the %m placeholder for the profile file, which talks about locking and merging these files at runtime. Maybe adding the %p PID placeholder as well might avoid conflicts here. Can you give that a try?

[scole66]

Gave it a try; still exhibits the same behavior.

[scole66]

%m is definitely an indication to "please merge"; and %p doesn't do that, but %p is really about processes, not threads. I suspect whatever is doing the merging of thread data is what's got the issue here. (Though I get the same effect when I tell the test runner to just use one thread, as well.)

[scole66]

Just learned that the -j option of cargo test is not the same thing as -- --test-threads=1 (which sends that flag to the test-runner). Adding -- --test-threads=1 to my harness removes the intermittent results.

Not closing this issue, though. Rust is supposed to be "fearless concurrency" so this should work correctly even if the test runner is using multiple threads.