Test Suite Running Very Slowly

[seanpianka]

Lately, I am experiencing significantly slow test execution times using nextest + llvm-cov. Below is an example of a single test and its execution time.

Test Example

#[test]
fn test_auth_req_schema_serialize() {
    let auth_req = Authenticate {
        method: AuthenticateMethod::Password(UserPassAuthenticate {
            email: "sadf.com".to_string(),
            password: "password".to_string(),
        }),
    };
    let serialized = serde_json::to_string(&auth_req).unwrap();
    assert_eq!(
        serialized,
        "{\"method\":{\"Password\":{\"email\":\"sadf.com\",\"password\":\"password\"}}}"
    );
}

Execution Time

From one invocation, the above test takes an excessively long time to execute:

PASS [  42.921s] app-users-types commands::tests::test_auth_req_schema_serialize

Environment

• Nextest Version: 0.9.67
• Rust Version: 1.79.0
• OS: Alpine 3.19, the container environment is docker:26.1.3-dind-alpine3.19, runs within GitLab CI on a self-managed runner (hardware: Intel(R) Core(TM) i7-9700K CPU @ 3.60GHz, 32GB of DDR4 memory)

Steps to Reproduce

1. Create a new Rust project.
2. Add the following dependencies to Cargo.toml:

   [dependencies]
   serde = { version = "1", features = ["derive"] }
   serde_json = "1"

3. Create the following test in src/lib.rs:

   #[cfg(test)]
   mod tests {
       use serde::{Deserialize, Serialize};
   
       #[derive(Serialize, Deserialize)]
       struct UserPassAuthenticate {
           email: String,
           password: String,
       }
   
       #[derive(Serialize, Deserialize)]
       struct Authenticate {
           method: AuthenticateMethod,
       }
   
       #[derive(Serialize, Deserialize)]
       enum AuthenticateMethod {
           Password(UserPassAuthenticate),
       }
   
       #[test]
       fn test_auth_req_schema_serialize() {
           let auth_req = Authenticate {
               method: AuthenticateMethod::Password(UserPassAuthenticate {
                   email: "sadf.com".to_string(),
                   password: "password".to_string(),
               }),
           };
           let serialized = serde_json::to_string(&auth_req).unwrap();
           assert_eq!(
               serialized,
               "{\"method\":{\"Password\":{\"email\":\"sadf.com\",\"password\":\"password\"}}}"
           );
       }
   }

4. Run the test using Nextest and observe the execution time.

Additional Information

• Command:

  cargo llvm-cov nextest \
    --locked \
    --config-file ./.config/nextest.toml \
    --features test_database_backing_impl \
    --bins --examples --tests --all-targets \
    --no-fail-fast \
    --no-report \
    --workspace

• Config:

  
  # This section defines the default nextest profile. Custom profiles are layered
  # on top of the default profile.
  [profile.default]
  slow-timeout = { period = "60s", terminate-after = 3 }

[profile.default.junit]

Output a JUnit report into the given file inside 'store.dir/'.

If unspecified, JUnit is not written out.

path = "results.xml"

The name of the top-level "report" element in JUnit report. If aggregating

reports across different test runs, it may be useful to provide separate names

for each report.

report-name = "nextest-run"

- **Other Tests**:

This test is run within a suite of 415 other tests, however the execution time of the other tests varies wildly. The other tests, which are at the same level of complexity (read: very simple methods set a boolean field from false to true and assert it as such), take different amounts of time and do not appear consistent.

    PASS [  20.025s] domain-users account::password_reset_attempt::tests::should_fail_to_create_reset_pin_of_invalid_length
    PASS [  11.661s] domain-users account::password_reset_attempt::tests::should_fail_to_create_reset_pin_with_invalid_chars
    PASS [   4.373s] domain-users account::password_reset_attempt::tests::should_show_a_new_password_reset_attempt_is_inactive
    PASS [   0.883s] domain-users account::tests::should_authenticate_active_account
    PASS [   3.451s] domain-users account::tests::should_activate_inactive_account
    PASS [   0.981s] domain-users account::tests::should_change_email
    PASS [  10.898s] domain-users account::tests::should_change_active_account_to_the_same_password_and_authenticate

Arbitrary groupings of different tests (i.e. unstable, fast and slow groupings change between invocations) that run within 0.x seconds, while tests of the same complexity within the same module will take 60s+ to run. The same test will take different amounts of time to run between invocations of nextest run.

Please let me know if you need any further information or additional logs.

Thank you for your help!

[sunshowers]

Thanks for the detailed report. Based on what you've described, my first inclination would be to say that your system is stalling under I/O or memory pressure. (Nextest doesn't come with great debugging for this at the moment.)

Could you try the following:

1. Running the test suite with nextest but without llvm-cov. This will help isolate llvm-cov as a factor (which might not be its fault -- llvm-cov necessarily requires additional memory and I/O).
2. Running the test suite with a reduced number of threads (step down by a factor of 2 each time. A 9700K has 8 cores and 8 threads, so step down to 4, 2, 1).
3. Using any other tools to monitor system metrics you might have. https://github.com/holmanb/psimon looks good but I haven't used it.

[seanpianka]

1. Running the test suite with nextest but without llvm-cov. This will help isolate llvm-cov as a factor (which might not be its fault -- llvm-cov necessarily requires additional memory and I/O).

Great intuition. I stripped llvm-cov from the command and the execution time for a majority of tests fell below one second.

cargo nextest run \
      --locked \
      --config-file ./.config/nextest.toml \
      --features test_database_backing_impl \
      --bins --examples --tests --all-targets \
      --no-fail-fast \
      --workspace

It appears that generating the code coverage results puts incredible CPU, memory, and/or I/O load on our CI runner's host. I'll go about filing an issue there and see what I can do about debugging this issue (or see if it simply requires throwing more hardware at the problem).

Thanks again!