Benchmarks are run in parallel

[AndreasPK]

General summary/comments (optional)

This seems to be a regression (#1913)

Steps to reproduce

git clone https://github.com/snoyberg/mono-traversable/tree/96d188bd6d7ba065aeff5ed9b3519107202069d3 mono
cd mono
stack bench
stack bench

Expected

That stack runs the benchmarks in sequence.

Actual

Stack runs the benchmarks in parallel.

$ stack bench --verbose
PS C:\ghc\test-stack\mono-trav2> stack bench --verbose
Version 1.6.1, Git revision f25811329bbc40b0c21053a8160c56f923e1201b (5435 commits) x86_64 hpack-0.20.0
2017-12-16 23:04:33.129747: [debug] Checking for project config at: C:\ghc\test-stack\mono-trav2\stack.yaml
@(Stack\Config.hs:842:9)
2017-12-16 23:04:33.132551: [debug] Loading project config file stack.yaml
@(Stack\Config.hs:868:13)
2017-12-16 23:04:33.135088: [debug] Decoding build plan from: C:\stack\build-plan\lts-9.9.yaml
@(Stack\Snapshot.hs:150:5)
2017-12-16 23:04:33.135088: [debug] Trying to decode C:\stack\build-plan-cache\lts-9.9.cache
@(Data\Store\VersionTagged.hs:66:5)
2017-12-16 23:04:33.138676: [debug] Success decoding C:\stack\build-plan-cache\lts-9.9.cache
@(Data\Store\VersionTagged.hs:70:13)
2017-12-16 23:04:33.143665: [debug] Using standard GHC build
@(Stack\Setup.hs:619:9)
2017-12-16 23:04:33.146171: [debug] Getting global package database location
@(Stack\GhcPkg.hs:46:5)
2017-12-16 23:04:33.147175: [debug] Getting Cabal package version
@(Stack\GhcPkg.hs:185:5)
2017-12-16 23:04:33.147675: [debug] Asking GHC for its version
@(Stack\Setup\Installed.hs:98:13)
2017-12-16 23:04:33.148177: [debug] Run process: C:\Users\Andi\AppData\Local\Programs\stack\x86_64-windows\ghc-8.0.2\bin\ghc-pkg.EXE --no-user-package-db list --global
@(System\Process\Log.hs:37:3)
2017-12-16 23:04:33.149708: [debug] Run process: C:\Users\Andi\AppData\Local\Programs\stack\x86_64-windows\ghc-8.0.2\bin\ghc-pkg.EXE --no-user-package-db field --simple-output Cabal version
@(System\Process\Log.hs:37:3)
2017-12-16 23:04:33.151185: [debug] Run process: C:\Users\Andi\AppData\Local\Programs\stack\x86_64-windows\ghc-8.0.2\bin\ghc.EXE --numeric-version
@(System\Process\Log.hs:37:3)
2017-12-16 23:04:33.167453: [debug] Process finished in 15ms: C:\Users\Andi\AppData\Local\Programs\stack\x86_64-windows\ghc-8.0.2\bin\ghc.EXE --numeric-version
@(System\Process\Log.hs:44:3)
2017-12-16 23:04:33.169458: [debug] GHC version is: ghc-8.0.2
@(Stack\Setup\Installed.hs:102:13)
2017-12-16 23:04:33.199129: [debug] Process finished in 50ms: C:\Users\Andi\AppData\Local\Programs\stack\x86_64-windows\ghc-8.0.2\bin\ghc-pkg.EXE --no-user-package-db list --global
@(System\Process\Log.hs:44:3)
2017-12-16 23:04:33.199632: [debug] Process finished in 49ms: C:\Users\Andi\AppData\Local\Programs\stack\x86_64-windows\ghc-8.0.2\bin\ghc-pkg.EXE --no-user-package-db field --simple-output Cabal version
@(System\Process\Log.hs:44:3)
2017-12-16 23:04:33.201637: [debug] Resolving package entries
@(Stack\Setup.hs:252:5)
2017-12-16 23:04:33.202138: [debug] Trying to decode C:\stack\loaded-snapshot-cache\x86_64-windows\ghc-8.0.2\lts-9.9.cache
@(Data\Store\VersionTagged.hs:66:5)
2017-12-16 23:04:33.227227: [debug] Success decoding C:\stack\loaded-snapshot-cache\x86_64-windows\ghc-8.0.2\lts-9.9.cache
@(Data\Store\VersionTagged.hs:70:13)
2017-12-16 23:04:33.229281: [debug] Starting to execute command inside EnvConfig
@(Stack\Runners.hs:170:18)
2017-12-16 23:04:33.229281: [debug] Parsing the targets
@(Stack\Build\Target.hs:460:3)
2017-12-16 23:04:33.229757: [debug] Running hpack on C:\ghc\test-stack\mono-trav2\minlen\package.yaml
@(Stack\PrettyPrint.hs:63:22)
2017-12-16 23:04:33.236921: [debug] hpack output unchanged in C:\ghc\test-stack\mono-trav2\minlen\minlen.cabal
@(Stack\PrettyPrint.hs:63:22)
2017-12-16 23:04:33.239441: [debug] Running hpack on C:\ghc\test-stack\mono-trav2\mono-traversable\package.yaml
@(Stack\PrettyPrint.hs:63:22)
2017-12-16 23:04:33.244956: [debug] hpack output unchanged in C:\ghc\test-stack\mono-trav2\mono-traversable\mono-traversable.cabal
@(Stack\PrettyPrint.hs:63:22)
2017-12-16 23:04:33.247491: [debug] Running hpack on C:\ghc\test-stack\mono-trav2\mono-traversable-instances\package.yaml
@(Stack\PrettyPrint.hs:63:22)
2017-12-16 23:04:33.250472: [debug] hpack output unchanged in
C:\ghc\test-stack\mono-trav2\mono-traversable-instances\mono-traversable-instances.cabal
@(Stack\PrettyPrint.hs:63:22)
2017-12-16 23:04:33.252476: [debug] Running hpack on C:\ghc\test-stack\mono-trav2\chunked-data\package.yaml
@(Stack\PrettyPrint.hs:63:22)
2017-12-16 23:04:33.255484: [debug] hpack output unchanged in C:\ghc\test-stack\mono-trav2\chunked-data\chunked-data.cabal
@(Stack\PrettyPrint.hs:63:22)
2017-12-16 23:04:33.257489: [debug] Running hpack on C:\ghc\test-stack\mono-trav2\classy-prelude\package.yaml
@(Stack\PrettyPrint.hs:63:22)
2017-12-16 23:04:33.261527: [debug] hpack output unchanged in C:\ghc\test-stack\mono-trav2\classy-prelude\classy-prelude.cabal
@(Stack\PrettyPrint.hs:63:22)
2017-12-16 23:04:33.264006: [debug] Running hpack on C:\ghc\test-stack\mono-trav2\classy-prelude-conduit\package.yaml
@(Stack\PrettyPrint.hs:63:22)
2017-12-16 23:04:33.268520: [debug] hpack output unchanged in
C:\ghc\test-stack\mono-trav2\classy-prelude-conduit\classy-prelude-conduit.cabal
@(Stack\PrettyPrint.hs:63:22)
2017-12-16 23:04:33.271025: [debug] Running hpack on C:\ghc\test-stack\mono-trav2\classy-prelude-yesod\package.yaml
@(Stack\PrettyPrint.hs:63:22)
2017-12-16 23:04:33.274034: [debug] hpack output unchanged in
C:\ghc\test-stack\mono-trav2\classy-prelude-yesod\classy-prelude-yesod.cabal
@(Stack\PrettyPrint.hs:63:22)
2017-12-16 23:04:33.276065: [debug] Running hpack on C:\ghc\test-stack\mono-trav2\conduit-combinators\package.yaml
@(Stack\PrettyPrint.hs:63:22)
2017-12-16 23:04:33.283489: [debug] hpack output unchanged in C:\ghc\test-stack\mono-trav2\conduit-combinators\conduit-combinators.cabal
@(Stack\PrettyPrint.hs:63:22)
2017-12-16 23:04:33.286460: [debug] Running hpack on C:\ghc\test-stack\mono-trav2\mutable-containers\package.yaml
@(Stack\PrettyPrint.hs:63:22)
2017-12-16 23:04:33.292966: [debug] hpack output unchanged in C:\ghc\test-stack\mono-trav2\mutable-containers\mutable-containers.cabal
@(Stack\PrettyPrint.hs:63:22)
2017-12-16 23:04:33.320040: [debug] Start: getPackageFiles C:\ghc\test-stack\mono-trav2\chunked-data\chunked-data.cabal
@(Stack\PrettyPrint.hs:134:16)
2017-12-16 23:04:33.339617: [debug] Finished in 18ms: getPackageFiles C:\ghc\test-stack\mono-trav2\chunked-data\chunked-data.cabal
@(Stack\PrettyPrint.hs:134:16)
2017-12-16 23:04:33.340594: [debug] Start: getPackageFiles C:\ghc\test-stack\mono-trav2\classy-prelude\classy-prelude.cabal
@(Stack\PrettyPrint.hs:134:16)
2017-12-16 23:04:33.348142: [debug] Finished in 7ms: getPackageFiles C:\ghc\test-stack\mono-trav2\classy-prelude\classy-prelude.cabal
@(Stack\PrettyPrint.hs:134:16)
2017-12-16 23:04:33.348614: [debug] Start: getPackageFiles C:\ghc\test-stack\mono-trav2\classy-prelude-conduit\classy-prelude-conduit.cabal
@(Stack\PrettyPrint.hs:134:16)
2017-12-16 23:04:33.357187: [debug] Finished in 7ms: getPackageFiles C:\ghc\test-stack\mono-trav2\classy-prelude-conduit\classy-prelude-conduit.cabal
@(Stack\PrettyPrint.hs:134:16)
2017-12-16 23:04:33.357689: [debug] Start: getPackageFiles C:\ghc\test-stack\mono-trav2\classy-prelude-yesod\classy-prelude-yesod.cabal
@(Stack\PrettyPrint.hs:134:16)
2017-12-16 23:04:33.363731: [debug] Finished in 4ms: getPackageFiles C:\ghc\test-stack\mono-trav2\classy-prelude-yesod\classy-prelude-yesod.cabal
@(Stack\PrettyPrint.hs:134:16)
2017-12-16 23:04:33.364097: [debug] Start: getPackageFiles C:\ghc\test-stack\mono-trav2\conduit-combinators\conduit-combinators.cabal
@(Stack\PrettyPrint.hs:134:16)
2017-12-16 23:04:33.382931: [debug] Finished in 18ms: getPackageFiles C:\ghc\test-stack\mono-trav2\conduit-combinators\conduit-combinators.cabal
@(Stack\PrettyPrint.hs:134:16)
2017-12-16 23:04:33.384936: [debug] Start: getPackageFiles C:\ghc\test-stack\mono-trav2\minlen\minlen.cabal
@(Stack\PrettyPrint.hs:134:16)
2017-12-16 23:04:33.389242: [debug] Finished in 4ms: getPackageFiles C:\ghc\test-stack\mono-trav2\minlen\minlen.cabal
@(Stack\PrettyPrint.hs:134:16)
2017-12-16 23:04:33.389745: [debug] Start: getPackageFiles C:\ghc\test-stack\mono-trav2\mono-traversable\mono-traversable.cabal
@(Stack\PrettyPrint.hs:134:16)
2017-12-16 23:04:33.428873: [debug] Finished in 38ms: getPackageFiles C:\ghc\test-stack\mono-trav2\mono-traversable\mono-traversable.cabal
@(Stack\PrettyPrint.hs:134:16)
2017-12-16 23:04:33.430375: [debug] Start: getPackageFiles C:\ghc\test-stack\mono-trav2\mono-traversable-instances\mono-traversable-instances.cabal
@(Stack\PrettyPrint.hs:134:16)
2017-12-16 23:04:33.435890: [debug] Finished in 5ms: getPackageFiles C:\ghc\test-stack\mono-trav2\mono-traversable-instances\mono-traversable-instances.cabal
@(Stack\PrettyPrint.hs:134:16)
2017-12-16 23:04:33.436586: [debug] Start: getPackageFiles C:\ghc\test-stack\mono-trav2\mutable-containers\mutable-containers.cabal
@(Stack\PrettyPrint.hs:134:16)
2017-12-16 23:04:33.460150: [debug] Finished in 23ms: getPackageFiles C:\ghc\test-stack\mono-trav2\mutable-containers\mutable-containers.cabal
@(Stack\PrettyPrint.hs:134:16)
2017-12-16 23:04:33.464048: [debug] Finding out which packages are already installed
@(Stack\Build\Installed.hs:60:5)
2017-12-16 23:04:33.465051: [debug] Run process: C:\Users\Andi\AppData\Local\Programs\stack\x86_64-windows\ghc-8.0.2\bin\ghc-pkg.EXE --global --no-user-package-db dump --expand-pkgroot
@(System\Process\Log.hs:37:3)
2017-12-16 23:04:33.514214: [debug] Process finished in 48ms: C:\Users\Andi\AppData\Local\Programs\stack\x86_64-windows\ghc-8.0.2\bin\ghc-pkg.EXE --global --no-user-package-db dump --expand-pkgroot
@(System\Process\Log.hs:44:3)
2017-12-16 23:04:33.516245: [debug] Ignoring package xhtml due to wanting version 3000.2.2 instead of 3000.2.1
@(Stack\Build\Installed.hs:190:5)
2017-12-16 23:04:33.516744: [debug] Ignoring package haskeline due to wanting version 0.7.4.0 instead of 0.7.3.0
@(Stack\Build\Installed.hs:190:5)
2017-12-16 23:04:33.517222: [debug] Run process: C:\Users\Andi\AppData\Local\Programs\stack\x86_64-windows\ghc-8.0.2\bin\ghc-pkg.EXE --user --no-user-package-db --package-db C:\stack\snapshots\1602ab97\pkgdb dump --expand-pkgroot
@(System\Process\Log.hs:37:3)
2017-12-16 23:04:33.648029: [debug] Process finished in 130ms: C:\Users\Andi\AppData\Local\Programs\stack\x86_64-windows\ghc-8.0.2\bin\ghc-pkg.EXE --user --no-user-package-db --package-db C:\stack\snapshots\1602ab97\pkgdb dump --expand-pkgroot
@(System\Process\Log.hs:44:3)
2017-12-16 23:04:33.650597: [debug] Run process: C:\Users\Andi\AppData\Local\Programs\stack\x86_64-windows\ghc-8.0.2\bin\ghc-pkg.EXE --user --no-user-package-db --package-db C:\ghc\test-stack\mono-trav2\.stack-work\install\d7a37d2f\pkgdb dump --expand-pkgroot
@(System\Process\Log.hs:37:3)
2017-12-16 23:04:33.698917: [debug] Process finished in 48ms: C:\Users\Andi\AppData\Local\Programs\stack\x86_64-windows\ghc-8.0.2\bin\ghc-pkg.EXE --user --no-user-package-db --package-db C:\ghc\test-stack\mono-trav2\.stack-work\install\d7a37d2f\pkgdb dump --expand-pkgroot
@(System\Process\Log.hs:44:3)
2017-12-16 23:04:33.701424: [debug] Constructing the build plan
@(Stack\Build\ConstructPlan.hs:180:5)
2017-12-16 23:04:33.709947: [debug] Checking if we are going to build multiple executables with the same name
@(Stack\Build.hs:177:5)
2017-12-16 23:04:33.710449: [debug] Executing the build plan
@(Stack\Build\Execute.hs:490:5)
2017-12-16 23:04:33.711451: [debug] Getting global package database location
@(Stack\GhcPkg.hs:46:5)
2017-12-16 23:04:33.711451: [debug] Run process: C:\Users\Andi\AppData\Local\Programs\stack\x86_64-windows\ghc-8.0.2\bin\ghc-pkg.EXE --no-user-package-db list --global
@(System\Process\Log.hs:37:3)
2017-12-16 23:04:33.757528: [debug] Process finished in 45ms: C:\Users\Andi\AppData\Local\Programs\stack\x86_64-windows\ghc-8.0.2\bin\ghc-pkg.EXE --no-user-package-db list --global
@(System\Process\Log.hs:44:3)
2017-12-16 23:04:33.760537: [info] mutable-containers-0.3.3: benchmarks
@(Stack\Build\Execute.hs:859:23)
2017-12-16 23:04:33.761039: [info] mono-traversable-1.0.5.0: benchmarks
@(Stack\Build\Execute.hs:859:23)
2017-12-16 23:04:33.761540: [debug] Run process: C:\stack\setup-exe-cache\x86_64-windows\Cabal-simple_Z6RU0evB_1.24.2.0_ghc-8.0.2.exe --builddir=.stack-work\dist\ca59d0ab bench deque ref
@(System\Process\Log.hs:37:3)
2017-12-16 23:04:33.762637: [debug] Run process: C:\stack\setup-exe-cache\x86_64-windows\Cabal-simple_Z6RU0evB_1.24.2.0_ghc-8.0.2.exe --builddir=.stack-work\dist\ca59d0ab bench sorting
@(System\Process\Log.hs:37:3)
2017-12-16 23:05:17.123763: [info] Log files have been written to: C:\ghc\test-stack\mono-trav2\.stack-work\logs\
@(Stack\Build\Execute.hs:412:17)
Progress: 0/2
PS C:\ghc\test-stack\mono-trav2>

Stack version

$ stack --version
Version 1.6.1, Git revision f25811329bbc40b0c21053a8160c56f923e1201b (5435 commits) x86_64 hpack-0.20.0

Method of installation

• stack update

[mgsloan]

Thanks for reporting this! I have created a PR fixing it and generally cleaning up concurrent task execution - #3666 .

A happy consequence of this is that benchmark console output will always be visible. It also made me think about how we can clean up build output further #3667

[snoyberg]

Looks like this was resolved by #3666.