Build and run limited tests (windows, 9.6) extremely slow

[martijnbastiaan]

It's pretty consistent across multiple PRs. Windows on 9.6 takes ~5 times longer than other platforms/GHC versions.

[leonschoorl]

Weird
As reference, here is a run that shows this: https://github.com/clash-lang/clash-compiler/actions/runs/8077053137
It's just the step Run Vector testsuite that takes very long.

But on more recent runs it seems fine again:
https://github.com/clash-lang/clash-compiler/actions/runs/8110284399

[martijnbastiaan]

Seems like the "fast" jobs skip the tests (because they run on master?). Here's a PR run where it's slow again: https://github.com/clash-lang/clash-compiler/actions/runs/8112625759/job/22174261031?pr=2687.

[leonschoorl]

It's not just a CI thing, Clash compiled with GHC 9.6 just runs really slowly on Windows (11).

9.6

$ echo ":quit" | time stack run -- clashi
when making flags consistent: warning:
    Optimization flags are incompatible with the byte-code interpreter; optimization flags ignored.
Clashi, version 1.9.0 (using clash-lib, version 1.9.0):
https://clash-lang.org/  :? for help
[long pause here]
clashi> Leaving GHCi.
0.01user 0.00system 0:40.83elapsed 0%CPU (0avgtext+0avgdata 5672maxresident)k
0inputs+0outputs (1528major+0minor)pagefaults 0swaps

$ time stack run -- clash --vhdl examples/ALU.hs -fforce-recomp -fclash-no-cache
[long pause here]
GHC: Setting up GHC took: 0.110s
GHC: Compiling and loading modules took: 0.564s
Clash: Parsing and compiling primitives took 0.280s
GHC+Clash: Loading modules cumulatively took 1.049s
Clash: Ignoring previously made caches
Clash: Compiling ALU.topEntity
Clash: Normalization took 0.000s
Clash: Netlist generation took 0.000s
Clash: Compiling ALU.topEntity took 0.015s
Clash: Total compilation took 1.065s

real    0m42.039s
user    0m0.000s
sys     0m0.015s

9.4

$ echo ":quit" | time stack run -- clashi
Clashi, version 1.9.0 (using clash-lib, version 1.9.0):
https://clash-lang.org/  :? for help
clashi> Leaving Clashi.
0.00user 0.01system 0:03.66elapsed 0%CPU (0avgtext+0avgdata 5652maxresident)k
0inputs+0outputs (1507major+0minor)pagefaults 0swaps

$ time stack run -- clash --vhdl examples/ALU.hs -fforce-recomp -fclash-no-cache
GHC: Setting up GHC took: 0.797s
GHC: Compiling and loading modules took: 0.437s
Clash: Parsing and compiling primitives took 0.218s
GHC+Clash: Loading modules cumulatively took 1.516s
Clash: Ignoring previously made caches
Clash: Compiling ALU.topEntity
Clash: Normalization took 0.000s
Clash: Netlist generation took 0.000s
Clash: Compiling ALU.topEntity took 0.015s
Clash: Total compilation took 1.532s

real    0m3.792s
user    0m0.015s
sys     0m0.046s

All the timing measurements that clash prints seems normal.
But with 9.6 there is just a ~40 second pause before anything happens.

With clashi it will first print the greeting and that there is a long pause the prompt appears.

[christiaanb]

Maybe we need to look at dynamic linking on windows for GHC 9.6

[DigitalBrains1]

This isn't the first time something like this happened, is it? (And even if it would be...)

We should think about whether we can regression-test these slowdowns. Maybe set an upper bound on how long we believe CI is allowed to spend on something trivial like Leon's first example, and if it goes over that bound, fail the test.

[martijnbastiaan]

I've gone ahead an published a PR disabling 9.6 on Windows for now. My latest run took 1h 41m, which seems like a massive waste of time/energy 🥴

[leonschoorl]

@christiaanb I understood from this section of stack manual that dynamic executables aren't supported on Windows.

[leonschoorl]

The plot thickens, using ghc-9.4 via cabal is also slow:

$ echo :quit | time cabal run -w ghc-9.4.8 clashi
[...]
0.00user 0.01system 0:37.98elapsed 0%CPU (0avgtext+0avgdata 4788maxresident)k
0inputs+0outputs (1312major+0minor)pagefaults 0swaps

[leonschoorl]

The slow part is the loading of the plugins, and it doesn't affect just clash.
Just doing ghci -fplugin GHC.TypeLits.Extra.Solver -fplugin GHC.TypeLits.Normalise -fplugin GHC.TypeLits.KnownNat.Solver can also show the slowness.

It's fast using the stack version of ghci-9.4.
But slow using the ghcup version of ghci-9.4 and both versions of ghc-9.6.

Not sure yet if that's a difference in how the compiler is build/configured, or with how the plugins get build by cabal vs stack.

[DigitalBrains1]

Hrm counterexample on gronau:

$ echo :quit | time cabal run -w ghc-9.6.4 clashi
[...]
0.65user 0.19system 0:00.85elapsed 98%CPU (0avgtext+0avgdata 351552maxresident)k
0inputs+72outputs (0major+80928minor)pagefaults 0swaps

It's perfectly quick

[edit]
Or are you using Windows and WSL or something? The $ prompt led me to conclude you were probably testing under Linux, but I now realise I now nothing whatsoever about WSL, it probably has a bash prompt too :-)
[/edit]

[leonschoorl]

So far I was testing on Windows 11, with GHC and stack installed via GHCup.
Which uses mingw/msys2 and no WSL as far as I know.

[leonschoorl]

But I've now also ran into the same slowness under Linux (Ubuntu 22.04).
Using ghc-9.4.8 installed via ghcup.

[DigitalBrains1]

Weird... not on gronau

$ echo :quit | time cabal run -w ghc-9.4.8 clashi
[...]
0.61user 0.25system 0:00.87elapsed 98%CPU (0avgtext+0avgdata 349248maxresident)k
0inputs+72outputs (0major+80086minor)pagefaults 0swaps

[leonschoorl]

Was testing user wide installed clash binaries for #2695
I did the naive cabal install clash-ghc, which gives you a non dynamic executable.
That with ghc-9.4.8 that gave me a clashi that takes ~45s to start.
Interestingly using ghc-9.6.4 it only takes ~4s.

Doing cabal install --enable-executable-dynamic clash-ghc bring it down to ~0.5s.

So the slowness I saw under Linux was nothing new.
Just user error and/or bad defaults.