Skip to content

cargo test performance regression on Windows on version 1.75.0 #119560

Open
Open
cargo test performance regression on Windows on version 1.75.0#119560
Labels
C-bugCategory: This is a bug.I-slowIssue: Problems and improvements with respect to performance of generated code.O-windowsOperating system: WindowsP-lowLow priorityT-libsRelevant to the library team, which will review and decide on the PR/issue.regression-from-stable-to-stablePerformance or correctness regression from one stable version to another.

Description

@Jefffrey
Jefffrey
opened on Jan 3, 2024

Code

DataFusion issue with complete details: apache/datafusion#8696

arrow-datafusion runs cargo test on Windows runner as part of CI. When on Rust version 1.74.1 (and below), the check takes under 30 minutes. After upgrading to Rust version 1.75.0, it now takes over 3 hours, with no other change in code on our side. This seems to only take effect on Windows, as Linux/Mac tests didn't seem to be affected.

After debugging, I found the regression occurs between toolchains nightly-2023-10-29 (rust e5cfc5547) and nightly-2023-10-30 (rust 608e9682f).

We are running on GitHub actions runner windows-latest.

So expected run is here, on toolchain nightly-2023-10-29: https://github.com/apache/arrow-datafusion/actions/runs/7394674719/job/20116418078

When I bump to toolchain nightly-2023-10-30, with no other code changes: https://github.com/apache/arrow-datafusion/actions/runs/7394848426/job/20116910586

Slow tests

The slowness occurs primarily in two tests.

tpcds_planning

Test code: https://github.com/apache/arrow-datafusion/blob/1179a76567892b259c88f08243ee01f05c4c3d5c/datafusion/core/tests/tpcds_planning.rs

On the good run (before regression):

On the bad run (after regression):

sqllogictest

Test code: https://github.com/apache/arrow-datafusion/tree/1179a76567892b259c88f08243ee01f05c4c3d5c/datafusion/sqllogictest

On the good run (before regression):

On the bad run (after regression):

These two tests are the only ones with a significant delta, the rest don't seem affected by the upgrade.

Version it worked on

Ran fast with Rust 1.74.1 (and nightly-2023-10-29)

Version with regression

Ran slow on Rust 1.75.0 (and nightly-2023-10-30)

Additional context

Apologies if the example is too large to easily determine where the issue is. I'll try to reduce this to a smaller MRE, as I don't have a Windows machine to locally test on, so have had to check via CI.

Activity

  1. Jefffrey
    added
    C-bugCategory: This is a bug.
    regression-untriagedUntriaged performance or correctness regression.
    on Jan 3, 2024
  2. rustbot
    added
    I-prioritizeIssue needs a team member to assess the impact. Will be replaced by P-{low,medium,high,critical}
    needs-triageThis issue may need triage. Remove when done. See docs forge.rust-lang.org/release/issue-triaging
    on Jan 3, 2024

  3. comphead commented on Jan 3, 2024

    @comphead
    comphead
    on Jan 3, 2024

    Maybe this also helps a bit to investigate, if we run datafusion windows CI with

    RUSTFLAGS: "-C debuginfo=0 -C opt-level=1 -C target-feature=+crt-static -C incremental=false -C codegen-units=256"

    it helps to reduce timing from 190m to 60m, but it still way longer than before

  4. ChrisDenton commented on Jan 3, 2024

    @ChrisDenton
    ChrisDenton
    on Jan 3, 2024
    Member

    It might help to look at the raw log and narrow down which steps specifically are taking a long time.

    So the issue is maybe around the generation of debuginfo?

  5. Jefffrey commented on Jan 4, 2024

    @Jefffrey
    Jefffrey
    on Jan 4, 2024
    ContributorAuthor

    Just a quick update, narrowed down the testing:

    Limit to running only tpcds_physical_q44 with backtrace feature:

    good (2023-10-29 nightly) = 70 seconds

    bad (2023-10-30 nightly) = 692 seconds

    Without backtrace:

    • cargo test -p datafusion --test tpcds_planning tpcds_physical_q44

    good (2023-10-29 nightly) = 1.25 seconds

    bad (2023-10-30 nightly) = 1.26 seconds

    Edit:

    Also just to be clear, we are running with env vars:

    • RUSTFLAGS: "-C debuginfo=0"
    • RUST_BACKTRACE: "1"

    For both good & bad runs.

    Maybe this also helps a bit to investigate, if we run datafusion windows CI with

    RUSTFLAGS: "-C debuginfo=0 -C opt-level=1 -C target-feature=+crt-static -C incremental=false -C codegen-units=256"

    it helps to reduce timing from 190m to 60m, but it still way longer than before

    The speedup seems to occur due to adding -C opt-level=1 -C target-feature=+crt-static -C incremental=false -C codegen-units=256 flags as the debuginfo flag was already set previously

  6. saethlin commented on Jan 4, 2024

    @saethlin
    saethlin
    on Jan 4, 2024
    Member

    #117089 was merged in the right window, and the PR description notes that it contains rust-lang/backtrace-rs#569 which sounds relevant.

  7. saethlin
    added
    I-slowIssue: Problems and improvements with respect to performance of generated code.
    T-libsRelevant to the library team, which will review and decide on the PR/issue.
    O-windowsOperating system: Windows
    and removed
    needs-triageThis issue may need triage. Remove when done. See docs forge.rust-lang.org/release/issue-triaging
    on Jan 4, 2024

  8. apiraino commented on Jan 4, 2024

    @apiraino
    apiraino
    on Jan 4, 2024
    Contributor

    cc @wesleywiser who authored #117089 and changes to the backtrace-rs submodule (IIUC)

  9. apiraino
    removed
    I-prioritizeIssue needs a team member to assess the impact. Will be replaced by P-{low,medium,high,critical}
    on Jan 4, 2024

  10. wesleywiser commented on Jan 6, 2024

    @wesleywiser
    wesleywiser
    on Jan 6, 2024
    Member

    I'm able to repro locally:

    > $env:RUSTFLAGS="-Cdebuginfo=0"
>  cargo +nightly-2023-10-29 test -p datafusion --test tpcds_planning tpcds_physical_q44 --features backtrace
...
test tpcds_physical_q44 ... ok

test result: ok. 1 passed; 0 failed; 0 ignored; 0 measured; 197 filtered out; finished in 36.23s

> cargo +nightly-2023-10-30 test -p datafusion --test tpcds_planning tpcds_physical_q44 --features backtrace
...
running 1 test
test tpcds_physical_q44 has been running for over 60 seconds

    Looking at profiling data, the vast majority of time in the regressed case is spent in dbghelp!SymAddrIncludeInlineTrace which is a necessary call I introduced in rust-lang/backtrace-rs#569 when symbolizing the backtrace. I'm investigating if there is some other way to avoid calling that function but haven't had any luck.

    One thing that's very interesting is that if do not set RUSTFLAGS="-Cdebuginfo=0", the regression disappears. This suggests to me we're hitting a pathological issue in dbghelp when there isn't any debug info present. On Windows, debug info is basically required to get any kind of meaningful backtrace so setting both -Cdebuginfo=0 and --feature backtrace in the test case doesn't make much sense to me.

    @Jefffrey do you know why -Cdebuginfo=0 is being set? My assumption is that the intent is to make builds faster while still being able to test --feature backtrace. If that's the case, I would suggest actually setting -Cdebuginfo=line-tables-only which generates the minimal amount of information to give proper backtraces and doesn't have much impact on compile times (especially in comparison to -Cdebuginfo=2 which is the default in this case):

    > $env:RUSTFLAGS="-Cdebuginfo=0"
>  cargo +nightly-2023-10-30 test -p datafusion --test tpcds_planning tpcds_physical_q44 --features backtrace
...
    Finished test [unoptimized + debuginfo] target(s) in 1m 25s

> $env:RUSTFLAGS="-Cdebuginfo=line-tables-only"
> cargo +nightly-2023-10-30 test -p datafusion --test tpcds_planning tpcds_physical_q44 --features backtrace
...
    Finished test [unoptimized + debuginfo] target(s) in 1m 32s

> $env:RUSTFLAGS="-Cdebuginfo=2"
> cargo +nightly-2023-10-30 test -p datafusion --test tpcds_planning tpcds_physical_q44 --features backtrace
...
    Finished test [unoptimized + debuginfo] target(s) in 2m 26s

  11. 1 remaining item

  12. Jefffrey commented on Jan 6, 2024

    @Jefffrey
    Jefffrey
    on Jan 6, 2024
    ContributorAuthor

    Thanks for the config fix suggested @wesleywiser

    This does eliminate the performance regression (or at least bring the times within a more reasonable range of each other).

    Even though it was caused by some weird settings on our end (disabling debuginfo but still using backtrace, on Windows), it was still a significant regression in performance. Let me know if this is the expected behaviour now and I can close this issue, or to keep this open if you're planning to investigate this weird edge case further 👍 (or move it to backtrace repo?)

  13. ChrisDenton commented on Feb 28, 2024

    @ChrisDenton
    ChrisDenton
    on Feb 28, 2024
    Member

    This was discussed in the libs meeting. While this is an edge case and a likely bug in dbghlp, it was suggested that maybe backtrace could workaround it by somehow detecting if there is no debug info present? Even if it can only tell after trying, it could perhaps cache this knowledge so it doesn't try again the next time?

  14. joshtriplett
    added
    regression-from-stable-to-stablePerformance or correctness regression from one stable version to another.
    on Jun 25, 2025
  15. rustbot
    added
    I-prioritizeIssue needs a team member to assess the impact. Will be replaced by P-{low,medium,high,critical}
    on Jun 25, 2025
  16. the8472
    added
    O-windowsOperating system: Windows
    C-bugCategory: This is a bug.
    T-libsRelevant to the library team, which will review and decide on the PR/issue.
    I-slowIssue: Problems and improvements with respect to performance of generated code.
    P-lowLow priority
    and removed
    I-slowIssue: Problems and improvements with respect to performance of generated code.
    O-windowsOperating system: Windows
    C-bugCategory: This is a bug.
    I-prioritizeIssue needs a team member to assess the impact. Will be replaced by P-{low,medium,high,critical}
    T-libsRelevant to the library team, which will review and decide on the PR/issue.
    regression-untriagedUntriaged performance or correctness regression.
    on Jun 25, 2025
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Metadata

Metadata

Assignees

No one assigned

    Labels

    C-bugCategory: This is a bug.I-slowIssue: Problems and improvements with respect to performance of generated code.O-windowsOperating system: WindowsP-lowLow priorityT-libsRelevant to the library team, which will review and decide on the PR/issue.regression-from-stable-to-stablePerformance or correctness regression from one stable version to another.

    Type

    No type

    Projects

    No projects

      Milestone

      No milestone

      Relationships

      None yet

      Development

      No branches or pull requests

      Issue actions