New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Benchmarks are run in parallel #3663

Closed
AndreasPK opened this Issue Dec 16, 2017 · 2 comments

Comments

Projects
None yet
3 participants
@AndreasPK
Contributor

AndreasPK commented Dec 16, 2017

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 added a commit that referenced this issue Dec 17, 2017

Never run benchmarks concurrently #3663
Also generally cleans up code related to parallel execution of tasks. Instead of
locking happening among "final tasks" (tests and benchmark running), it's now
possible to mark some tasks as work that shouldn't be done in parallel with
anything else.  This is what makes sense for benchmark running - they shouldn't
be run concurrently with either building or running tests.

Previously benchmarks and tests shared the same final task. The mechanism to
execute one task exclusively is part of Control.Concurrent.Execute. If they were
kept in the same task, then if any benchmarks were enabled, then tests would be
run without any concurrency. In order to have as much concurrency as possible,
they are now split into two different "final" tasks.

mgsloan added a commit that referenced this issue Dec 17, 2017

Never run benchmarks concurrently, always output to console #3663
Also generally cleans up code related to parallel execution of tasks. Instead of
locking happening among "final tasks" (tests and benchmark running), it's now
possible to mark some tasks as work that shouldn't be done in parallel with
anything else.  This is what makes sense for benchmark running - they shouldn't
be run concurrently with either building or running tests.

Previously benchmarks and tests shared the same final task. The mechanism to
execute one task exclusively is part of Control.Concurrent.Execute. If they were
kept in the same task, then if any benchmarks were enabled, then tests would be
run without any concurrency. In order to have as much concurrency as possible,
they are now split into two different "final" tasks.
@mgsloan

This comment has been minimized.

Collaborator

mgsloan commented Dec 17, 2017

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

@mgsloan mgsloan added this to the P1: Must milestone Dec 17, 2017

mgsloan added a commit that referenced this issue Dec 18, 2017

Never run benchmarks concurrently, always output to console #3663
Also generally cleans up code related to parallel execution of tasks. Instead of
locking happening among "final tasks" (tests and benchmark running), it's now
possible to mark some tasks as work that shouldn't be done in parallel with
anything else.  This is what makes sense for benchmark running - they shouldn't
be run concurrently with either building or running tests.

Previously benchmarks and tests shared the same final task. The mechanism to
execute one task exclusively is part of Control.Concurrent.Execute. If they were
kept in the same task, then if any benchmarks were enabled, then tests would be
run without any concurrency. In order to have as much concurrency as possible,
they are now split into two different "final" tasks.

mgsloan added a commit that referenced this issue Dec 23, 2017

Never run benchmarks concurrently, always output to console #3663
Also generally cleans up code related to parallel execution of tasks. Instead of
locking happening among "final tasks" (tests and benchmark running), it's now
possible to mark some tasks as work that shouldn't be done in parallel with
anything else.  This is what makes sense for benchmark running - they shouldn't
be run concurrently with either building or running tests.

Previously benchmarks and tests shared the same final task. The mechanism to
execute one task exclusively is part of Control.Concurrent.Execute. If they were
kept in the same task, then if any benchmarks were enabled, then tests would be
run without any concurrency. In order to have as much concurrency as possible,
they are now split into two different "final" tasks.

mgsloan added a commit that referenced this issue Dec 23, 2017

Never run benchmarks concurrently, always output to console #3663
Also generally cleans up code related to parallel execution of tasks. Instead of
locking happening among "final tasks" (tests and benchmark running), it's now
possible to mark some tasks as work that shouldn't be done in parallel with
anything else.  This is what makes sense for benchmark running - they shouldn't
be run concurrently with either building or running tests.

Previously benchmarks and tests shared the same final task. The mechanism to
execute one task exclusively is part of Control.Concurrent.Execute. If they were
kept in the same task, then if any benchmarks were enabled, then tests would be
run without any concurrency. In order to have as much concurrency as possible,
they are now split into two different "final" tasks.

mgsloan added a commit that referenced this issue Dec 24, 2017

Merge pull request #3666 from commercialhaskell/fix-parallel-final-ta…
…sks-3663

Never run benchmarks concurrently, always output to console #3663
@snoyberg

This comment has been minimized.

Contributor

snoyberg commented Jun 6, 2018

Looks like this was resolved by #3666.

@snoyberg snoyberg closed this Jun 6, 2018

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment