Windows CI test is extremely long (~3 hours)

[Jefffrey]

Describe the bug

Some examples:

• https://github.com/apache/arrow-datafusion/actions/runs/7369048334/job/20053938917
• https://github.com/apache/arrow-datafusion/actions/runs/7364543678/job/20045028037
• https://github.com/apache/arrow-datafusion/actions/runs/7358744456/job/20032462383

To Reproduce

No response

Expected behavior

No response

Additional context

Not sure if it was like this in the past too? But a 3hr runtime seems odd

[Jefffrey]

From logs in https://github.com/apache/arrow-datafusion/actions/runs/7358744456/job/20032462383

     Running tests\tpcds_planning.rs (target\debug\deps\tpcds_planning-b7c04ff6bee7c82a.exe)
...
test result: ok. 190 passed; 0 failed; 8 ignored; 0 measured; 0 filtered out; finished in 5068.19s

Seems would be a good start point for investigating this, as accounts for almost half that runtime.

Skimming through the logs, can't see any other part that significantly contributes to the runtime

Edit: might be an issue with the windows runner itself, see actions/runner-images#9085

First started occurring here: https://github.com/apache/arrow-datafusion/actions/runs/7350344666

But don't think it's issue on datafusion side, considering contents of that PR

Edit2: Some other references:

• Windows runners are consistently extremely slow compared to Linux and macOS actions/runner-images#7320
• Windows Server 2022 builds are taking 4x longer than on Windows Server 2019 actions/runner-images#5166

Seem to suggest switching to windows-2019 could improve speed, will test

Edit3: for comparison, the CI used to take no more than 30min

[Jefffrey]

CI is still taking extremely long after switching to windows-2019 runner

[Jefffrey]

Some debugging thoughts:

Due to image change

Unlikely.

27min runtime: https://github.com/apache/arrow-datafusion/actions/runs/7347591698/job/20004278779#step:1:1

Current runner version: '2.311.0'
Operating System
  Microsoft Windows Server 2022
  10.0.20348
  Datacenter
Runner Image
  Image: windows-2022
  Version: 20231217.2.0
  Included Software: https://github.com/actions/runner-images/blob/win22/20231217.2/images/windows/Windows2022-Readme.md
  Image Release: https://github.com/actions/runner-images/releases/tag/win22%2F20231217.2
Runner Image Provisioner
  2.0.321.1

3hr 20min run: https://github.com/apache/arrow-datafusion/actions/runs/7351057731/job/20013780063#step:1:1

Current runner version: '2.311.0'
Operating System
  Microsoft Windows Server 2022
  10.0.20348
  Datacenter
Runner Image
  Image: windows-2022
  Version: 20231217.2.0
  Included Software: https://github.com/actions/runner-images/blob/win22/20231217.2/images/windows/Windows2022-Readme.md
  Image Release: https://github.com/actions/runner-images/releases/tag/win22%2F20231217.2
Runner Image Provisioner
  2.0.321.1

Runner image versions are the exact same.

Some regression in Datafusion code

Probably unlikely? I don't have a Windows machine to test to be certain that it's not only CI.

Given example run: https://github.com/apache/arrow-datafusion/actions/runs/7390088229/job/20104324232

• 3hr 16min runtime

The tests that have extreme runtime are:

• sqllogictests
  • https://github.com/apache/arrow-datafusion/actions/runs/7390088229/job/20104324232#step:5:5719
  • Turn on timestamps via cog wheel
  • Starts Tue, 02 Jan 2024 21:44:15 GMT and last log from it is Tue, 02 Jan 2024 22:05:57 GMT (but next test doesn't start until Tue, 02 Jan 2024 23:27:39 GMT leaving a 1hr 42min gap)
• tests\tpcds_planning.rs
  • https://github.com/apache/arrow-datafusion/actions/runs/7390088229/job/20104324232#step:5:2124
  • Takes about 1hr 20min

Rest of the run doesn't have any major anomalies, so these are the offending tests.

Some other runner issue

Not sure how to debug this, might need to raise another issue with runner repo?

Edit: pretty certain its not due to code change on DataFusion side, as this PR run was the first to exhibit >3hr win runtime: https://github.com/apache/arrow-datafusion/actions/runs/7349660365/job/20009991842

And it happens independently of the next commit to main which also exhibits slowness

[Jefffrey]

Actually, another thing that changed was Rust version from 1.74.1 to 1.75.0 (which also aligned exactly with the slowdown)

Testing switching back to 1.74.1 to see if this is the root cause: #8728

[comphead]

@Jefffrey thanks for creating this, do you have windows machine to run tests locally?

[Jefffrey]

@Jefffrey thanks for creating this, do you have windows machine to run tests locally?

I don't have access to a Windows machine easily unfortunately. Can try get access to one if necessary, will see how latest CI test pans out

[comphead]

I'm also trying to find a solution in #8730

[Jefffrey]

#8728

Windows test finished in 28min @comphead

Looks like its due to Rust 1.75.0 upgrade, will check its changelog

[comphead]

good finding, on 1.75.0 even the compilation is way slower

[Jefffrey]

After a bunch of debugging, I found this:

Tests run fast on toolchain: nightly-2023-10-29 (rust e5cfc5547)

• Test commit: c85e67c
• Action log: https://github.com/apache/arrow-datafusion/actions/runs/7394674719/job/20116418078

Tests run extremely slow on toolchain: nightly-2023-10-30 (rust 608e9682f)

• Test commit: 2e99e21
• Action log: https://github.com/apache/arrow-datafusion/actions/runs/7394848426/job/20116910586

I might raise an issue on rust lang repo, after checking if a similar issue hasn't already been raised

• When checking the commits (rust-lang/rust@e5cfc55...608e968), I think the most likely cause would be See through aggregates in GVN rust-lang/rust#116270 (rest seem unrelated)