search

commercialhaskell / stack

The Haskell Tool Stack
http://haskellstack.org
BSD 3-Clause "New" or "Revised" License
3.99k stars 843 forks source link

Benchmark terminates with error #5075

Open JRikken opened 4 years ago

JRikken commented 4 years ago

General summary

Stack terminates with "terminateProcess: permission denied (Permission denied)", after running the benchmarks with stack bench

The error seems to be time-related. Also, it seems that this error only occurs when using stack bench, I ran the compiled benchmark executable directly from the command line, this worked as expected.

Steps to reproduce

I have reproduced the issue in a MWE, see the attached files benchTest.zip, or recreate as follows:

  1. Set up new package stack new benchTest & stack setup
  2. Set up benchmark code (in my case the naive Fibonacci sequence), where main = defaultMain [ bgroup "Fib" [ bench "N=5 " $ whnf fib 5, bench "N=6 " $ whnf fib 6, bench "N=15" $ whnf fib 15]]
  3. Modify package.yaml so that it compiles the benchmark as an executable (benchTest-exe) as well as a benchmark (benchTest-bench)
  4. stack bench terminates with error, whereas stack run works as expected, even though they come from the same code

Notes:

Expected

stack bench == stack run == replicating the ghc bench benchTest-bench call

Actual

stack bench produces "terminateProcess: permission denied (Permission denied)" whereas stack run, running the benchmark executable directly from command line or replicating the call from the verbose output do not produce this error. 

$ stack bench -v
Version 2.1.3, Git revision 0fa51b9925decd937e4a993ad90cb686f88fa282 (7739 commits) x86_64 hpack-0.31.2
2019-11-06 15:12:03.148895: [debug] Checking for project config at: C:\Users\jrk\Desktop\bugReport\benchTest\stack.yaml
2019-11-06 15:12:03.150888: [debug] Loading project config file stack.yaml
2019-11-06 15:12:03.166845: [debug] SELECT COUNT(*) FROM "last_performed" WHERE ("action"=?) AND ("timestamp">=?); [PersistInt64 1,PersistUTCTime 2019-11-05 14:12:03.1658486 UTC]
2019-11-06 15:12:03.167842: [debug] Using package location completions from a lock file
2019-11-06 15:12:03.280542: [debug] Running hpack on C:\Users\jrk\Desktop\bugReport\benchTest\package.yaml
2019-11-06 15:12:03.284532: [debug] hpack output unchanged in C:\Users\jrk\Desktop\bugReport\benchTest\benchTest.cabal
2019-11-06 15:12:03.292511: [debug] Asking for a supported GHC version
2019-11-06 15:12:03.293507: [debug] Installed tools:
 - msys2-20180531
 - ghc-8.6.5
2019-11-06 15:12:03.293507: [debug] Potential GHC builds: standard
2019-11-06 15:12:03.293507: [debug] Found already installed GHC builds: standard
2019-11-06 15:12:03.296542: [debug] SELECT "id","actual_version","arch","ghc_path","ghc_size","ghc_modified","ghc_pkg_path","runghc_path","haddock_path","cabal_version","global_db","global_db_cache_size","global_db_cache_modified","info","global_dump" FROM "compiler_cache" WHERE "ghc_path"=?; [PersistText "C:\\Users\\jrk\\AppData\\Local\\Programs\\stack\\x86_64-windows\\ghc-8.6.5\\bin\\ghc-8.6.5.EXE"]
2019-11-06 15:12:03.348396: [debug] Loaded compiler information from cache
2019-11-06 15:12:03.348396: [debug] Asking for a supported GHC version
2019-11-06 15:12:03.350382: [debug] Resolving package entries
2019-11-06 15:12:03.350382: [debug] Parsing the targets
2019-11-06 15:12:03.352377: [debug] Checking flags
2019-11-06 15:12:03.352377: [debug] SourceMap constructed
2019-11-06 15:12:03.357364: [debug] Starting to execute command inside EnvConfig
2019-11-06 15:12:03.358363: [debug] Finding out which packages are already installed
2019-11-06 15:12:03.359359: [debug] Run process: C:\Users\jrk\AppData\Local\Programs\stack\x86_64-windows\ghc-8.6.5\bin\ghc-pkg.exe --global --no-user-package-db dump --expand-pkgroot
2019-11-06 15:12:03.765737: [debug] Process finished in 406ms: C:\Users\jrk\AppData\Local\Programs\stack\x86_64-windows\ghc-8.6.5\bin\ghc-pkg.exe --global --no-user-package-db dump --expand-pkgroot
2019-11-06 15:12:03.767731: [debug] Ignoring package parsec due to wanting version 3.1.14.0 instead of 3.1.13.0
2019-11-06 15:12:03.767731: [debug] Ignoring package haskeline due to wanting version 0.7.5.0 instead of 0.7.4.3
2019-11-06 15:12:03.768729: [debug] Ignoring package Cabal due to wanting version 2.4.1.0 instead of 2.4.0.1
2019-11-06 15:12:03.769725: [debug] Run process: C:\Users\jrk\AppData\Local\Programs\stack\x86_64-windows\ghc-8.6.5\bin\ghc-pkg.exe --user --no-user-package-db --package-db C:\sr\snapshots\5e1d8a69\pkgdb dump --expand-pkgroot
2019-11-06 15:12:04.169891: [debug] Process finished in 400ms: C:\Users\jrk\AppData\Local\Programs\stack\x86_64-windows\ghc-8.6.5\bin\ghc-pkg.exe --user --no-user-package-db --package-db C:\sr\snapshots\5e1d8a69\pkgdb dump --expand-pkgroot
2019-11-06 15:12:04.172884: [debug] Run process: C:\Users\jrk\AppData\Local\Programs\stack\x86_64-windows\ghc-8.6.5\bin\ghc-pkg.exe --user --no-user-package-db --package-db C:\Users\jrk\Desktop\bugReport\benchTest\.stack-work\install\fe5815c2\pkgdb dump --expand-pkgroot
2019-11-06 15:12:04.457662: [debug] Process finished in 285ms: C:\Users\jrk\AppData\Local\Programs\stack\x86_64-windows\ghc-8.6.5\bin\ghc-pkg.exe --user --no-user-package-db --package-db C:\Users\jrk\Desktop\bugReport\benchTest\.stack-work\install\fe5815c2\pkgdb dump --expand-pkgroot
2019-11-06 15:12:04.458658: [debug] Constructing the build plan
2019-11-06 15:12:04.461650: [debug] SELECT "id","directory","type","pkg_src","active","path_env_var","haddock" FROM "config_cache" WHERE "directory"=? AND "type"=?; [PersistText "C:\\Users\\jrk\\Desktop\\bugReport\\benchTest\\.stack-work\\install\\fe5815c2\\",PersistText "exe:benchTest-0.0.0"]
2019-11-06 15:12:04.462648: [debug] SELECT "id", "config_cache_id", "index", "option" FROM "config_cache_dir_option" WHERE ("config_cache_id"=?) ORDER BY "index"; [PersistInt64 25]
2019-11-06 15:12:04.462648: [debug] SELECT "id", "config_cache_id", "index", "option" FROM "config_cache_no_dir_option" WHERE ("config_cache_id"=?) ORDER BY "index"; [PersistInt64 25]
2019-11-06 15:12:04.462648: [debug] SELECT "id", "config_cache_id", "ghc_pkg_id" FROM "config_cache_dep" WHERE ("config_cache_id"=?); [PersistInt64 25]
2019-11-06 15:12:04.463645: [debug] SELECT "id", "config_cache_id", "component" FROM "config_cache_component" WHERE ("config_cache_id"=?); [PersistInt64 25]
2019-11-06 15:12:04.463645: [debug] Start: getPackageFiles C:\Users\jrk\Desktop\bugReport\benchTest\benchTest.cabal
2019-11-06 15:12:04.467658: [debug] Finished in 3ms: getPackageFiles C:\Users\jrk\Desktop\bugReport\benchTest\benchTest.cabal
2019-11-06 15:12:04.477609: [debug] Checking if we are going to build multiple executables with the same name
2019-11-06 15:12:04.477609: [debug] Executing the build plan
2019-11-06 15:12:04.480624: [info] benchTest> benchmarks
2019-11-06 15:12:04.481596: [debug] Run process within C:\Users\jrk\Desktop\bugReport\benchTest\: C:\sr\setup-exe-cache\x86_64-windows\Cabal-simple_Z6RU0evB_2.4.0.1_ghc-8.6.5.exe --builddir=.stack-work\dist\e626a42b bench benchTest-bench
2019-11-06 15:12:04.799085: [info] Running 1 benchmarks...
2019-11-06 15:12:04.799085: [info] Benchmark benchTest-bench: RUNNING...
2019-11-06 15:12:05.221811: [info] benchmarking Fib/N=5
2019-11-06 15:12:10.473810: [info] time                 29.05 ns   (28.99 ns .. 29.11 ns)
2019-11-06 15:12:10.473810: [info]                      1.000 R²   (1.000 R² .. 1.000 R²)
2019-11-06 15:12:10.474802: [info] mean                 29.06 ns   (29.00 ns .. 29.12 ns)
2019-11-06 15:12:10.474802: [info] std dev              219.9 ps   (180.7 ps .. 275.7 ps)
2019-11-06 15:12:10.474802: [info] 
2019-11-06 15:12:10.480785: [info] benchmarking Fib/N=6
2019-11-06 15:12:15.495412: [info] time                 45.21 ns   (45.07 ns .. 45.39 ns)
2019-11-06 15:12:15.496409: [info]                      1.000 R²   (1.000 R² .. 1.000 R²)
2019-11-06 15:12:15.496409: [info] mean                 45.24 ns   (45.11 ns .. 45.60 ns)
2019-11-06 15:12:15.496409: [info] std dev              684.1 ps   (271.6 ps .. 1.198 ns)
2019-11-06 15:12:15.496409: [info] variance introduced by outliers: 18% (moderately inflated)
2019-11-06 15:12:15.497407: [info] 
2019-11-06 15:12:15.503393: [info] benchmarking Fib/N=15
2019-11-06 15:12:20.695825: [info] time                 3.983 2019-11-06 15:12:20.743698: [error] terminateProcess: permission denied (Permission denied)

Stack version

$ stack --version
Version 2.1.3, Git revision 0fa51b9925decd937e4a993ad90cb686f88fa282 (7739 commits) x86_64 hpack-0.31.2

Method of installation

SimonCockx commented 4 years ago

I'm running into the same problem. Running a simple benchmark

import Criterion.Main

main :: IO ()
main = defaultMain [
    bench "squaring 1000 elements" $ nf (map (^2)) ([1..1000] :: [Int])
    ]

causes the same error to occur. When the length of the list is lowered to 10, the problem goes away.

When running the same code as a executable and with the command stack run, everything runs fine.

Also on Window 10 x64, but using the cmd.

Very strange...