BLD: build times in Windows CI entries are variable and take longer than they should

[andyfaff]

Describe your issue.

When looking at the build times for the entries in .github/workflows/windows.yml I notice that there is a large difference in build times for each of the jobs. See e.g. https://github.com/scipy/scipy/actions/runs/9102530684.

The comparison:

• python -m build --no-isolation -x -Csetup-args="-Duse-pythran=false" takes 12 mins
• python dev.py build --with-scipy-openblas takes 33/34 mins

The discrepancy in build time is consistent. An extra 20 mins of run time indicates a problem that we should fix.

@rgommers. Ping also @mattip in case it's an issue with how scipy_openblas32 is used in the build process.

Reproducing Code Example

N/A

Error message

N/A

SciPy/NumPy/Python version and system information

N/A

[mattip]

In the slow log you point to there is a 15 minute pause between this line and the next one. Weird. Does that show up in all builds or just this one?

Wed, 15 May 2024 20:58:21 GMT
Run python dev.py build --with-scipy-openblas
Wed, 15 May 2024 20:58:21 GMT   python dev.py build --with-scipy-openblas
Wed, 15 May 2024 20:58:21 GMT   shell: C:\Program Files\PowerShell\7\pwsh.EXE -command ". '{0}'"
Wed, 15 May 2024 20:58:21 GMT   env:
Wed, 15 May 2024 20:58:21 GMT     pythonLocation: C:\hostedtoolcache\windows\Python\3.9.13\x64
Wed, 15 May 2024 20:58:21 GMT     PKG_CONFIG_PATH: C:\hostedtoolcache\windows\Python\3.9.13\x64/lib/pkgconfig
Wed, 15 May 2024 20:58:21 GMT     Python_ROOT_DIR: C:\hostedtoolcache\windows\Python\3.9.13\x64
Wed, 15 May 2024 20:58:21 GMT     Python2_ROOT_DIR: C:\hostedtoolcache\windows\Python\3.9.13\x64
Wed, 15 May 2024 20:58:21 GMT     Python3_ROOT_DIR: C:\hostedtoolcache\windows\Python\3.9.13\x64
Wed, 15 May 2024 20:58:23 GMT >  meson setup D:\a\scipy\scipy\build --prefix D:\a\scipy\scipy\build-install
Wed, 15 May 2024 21:13:23 GMT The Meson build system

[andyfaff]

It doesn't show up when the CI uses python -m build, but it appears when python dev.py build --with-scipy-openblas is used.

[mattip]

A 13 minute pause happened here as well (to see time stamps, click on the gear in the ci run)

Thu, 16 May 2024 03:30:12 GMT
Run python dev.py build --with-scipy-openblas
Thu, 16 May 2024 03:30:12 GMT   python dev.py build --with-scipy-openblas
Thu, 16 May 2024 03:30:12 GMT   shell: C:\Program Files\PowerShell\7\pwsh.EXE -command ". '{0}'"
Thu, 16 May 2024 03:30:12 GMT   env:
Thu, 16 May 2024 03:30:12 GMT     pythonLocation: C:\hostedtoolcache\windows\Python\3.12.3\x64
Thu, 16 May 2024 03:30:12 GMT     PKG_CONFIG_PATH: C:\hostedtoolcache\windows\Python\3.12.3\x64/lib/pkgconfig
Thu, 16 May 2024 03:30:12 GMT     Python_ROOT_DIR: C:\hostedtoolcache\windows\Python\3.12.3\x64
Thu, 16 May 2024 03:30:12 GMT     Python2_ROOT_DIR: C:\hostedtoolcache\windows\Python\3.12.3\x64
Thu, 16 May 2024 03:30:12 GMT     Python3_ROOT_DIR: C:\hostedtoolcache\windows\Python\3.12.3\x64
Thu, 16 May 2024 03:30:14 GMT >  meson setup D:\a\scipy\scipy\build --prefix D:\a\scipy\scipy\build-install
Thu, 16 May 2024 03:43:39 GMT The Meson build system
Thu, 16 May 2024 03:43:39 GMT Version: 1.4.0
Thu, 16 May 2024 03:43:39 GMT Source dir: D:\a\scipy\scipy
Thu, 16 May 2024 03:43:39 GMT Build dir: D:\a\scipy\scipy\build
Thu, 16 May 2024 03:43:39 GMT Build type: native build

[andyfaff]

I don't know if it's to do with meson, dev.py, or the way we use scipy-openblas.

[mattip]

Hmm. I don't see a similar pause in NumPy, which uses spin --with-scipy-openblas

[mattip]

I also don't see a pause on macos or linux (in the PR to use scipy-openblas wheels)

[mattip]

Here is a dev.py run without the pause, the build takes 20 minutes.

[mattip]

I cannot reproduce the pause locally.

[andyfaff]

Weird, but it's definitely consistent in ci

[rgommers]

It's not a pause, but the whole configure stage of the build being very slow for some reason. Note that all lines of the configure stage have the exact same timestamp. That means they're only coming through at once, not that there's a pause and then everything running without a second.

On Linux/macOS the meson setup call takes about five seconds. On Windows it's several times slower normally, because Windows is just slow for build tasks (file system, virus scanner, etc.). I don't know why it's taking 2-10 minutes though, it should still run within 30 seconds I expect.

[mattip]

In the slower build I see

Build targets in project: 199

scipy 1.14.0.dev0

  User defined options
    prefix: D:\a\scipy\scipy\build-install

In the faster build I see

Build targets in project: 197

scipy 1.14.0.dev0

  User defined options
    Native files: D:\a\scipy\scipy\.mesonpy-0t8eptps\meson-python-native-file.ini
    buildtype   : release
    b_ndebug    : if-release
    b_vscrt     : md
    use-pythran : false

Maybe the dev.py build should be specifying buildtype: release for windows?

[rgommers]

Ah, nice catch. That's worth a try. The audience for debug builds on Windows is extremely limited.

[mattip]

I don't see a place where dev.py chooses a buildtype nor where the pip build chooses buildtype=release. Where would be a place to touch this?

[rgommers]

The default for dev.py is set in the top-level meson.build file. For wheels, the default in meson-python is to pass -Dbuildtype=release, which overrides the value in meson.build. If we want dev.py builds to default to release, then we should pass -Dbuildtype=release from within dev.py to meson setup.

[mattip]

I tried using the release configuration in #20774, the times did not change significantly.