stack exec is slow

[2chilled]

Steps to reproduce

Outside of a stack project:

time stack exec echo 'hello'
Run from outside a project, using implicit global project config
Using resolver: lts-7.2 from implicit global project's config file: ~/.stack/global-project/stack.yaml
hello

real	0m0.385s
user	0m0.459s
sys	0m0.070s

Inside a small stack project with the only dep being base

time stack exec echo 'hello'
hello

real    0m3.643s
user    0m3.620s
sys     0m0.135s

Any ideas to make this faster? Dev tools like hdevtools using stack to do their job consume very most of their time waiting for stack, which is unfortunate.

Expected

Faster startup time of stack

Stack version

stack --version
Version 1.2.0 x86_64

Method of installation

• Nixpkgs

[domenkozar]

Are you using --nix? Also please post stack.yaml here.

[mgsloan]

Also, please try with a newer version! Not sure, but I think some performance improvements for this happened since 1.2

[NorfairKing]

+1,

I have this problem as well.

stack --version
Version 1.3.0 x86_64 hpack-0.15.0

[decentral1se]

I think you should all use the stack upgrade --git to get performance fixes.

For example, #2896 shows that some useful fixes didn't make it into 1.3.2.

[NorfairKing]

@lwm,

$ stack --version
Version 1.3.2, Git revision 3f675146590da4f3edf768b89355f798229da2a5 (4395 commits) x86_64 hpack-0.15.0

It's about 35% faster after a stack clean, but a 0.75s overhead is still too much in my opinion.
Running a script that has already been run before should happen instantly if it hasn't changed.

[NorfairKing]

Is it possible to ensure that running a script for the second time, as described here happens instantly?
It would be nice to be able to script with Haskell reliably.
I have a use-case for that but it's not going to work well if there is a 0.75s overhead every time.

[decentral1se]

It would be nice to be able to script with Haskell reliably.

It is reliable. Certainly more reliable than ever before with Stack. It just appears to be not as performant as you expect. I admit this 0.75 overhead is a nuisance but Stack has improved in the 1.3.X releases, as I mentioned above.

Stack has few contributors and a mounting load of work to do. There are more pressing priorities (I imagine, I'm not a core dev, just passing by every now and again).

If this is important to you @NorfairKing, please consider submitting a PR.

[NorfairKing]

@lwm, Sounds good. I will try to look into why this is so slow and report back here.

[NorfairKing]

Well, that effort halted quickly: #2917

[NorfairKing]

I've been trying to profile stack to find what's slowing it down but I've run into some problems.

I've built stack from source with stack build --executable-profiling --library-profiling --ghc-options="-fprof-auto -rtsopts" --ghc-options="-fprof-auto -rtsopts" --copy-bins

The thing I'm trying to speed up is scripting, so I have my little script (zifter is not on hackage yet).

$ cat zift.hs
#!/usr/bin/env stack
{- stack
    --install-ghc
    runghc
    --package zifter
    +RTS -p -RTS
-}
{-# LANGUAGE OverloadedStrings #-}

import Zifter

main :: IO ()
main = zift

It looks like stack does not accept RTS flags in a script:

Invalid option `-p'
Error executing interpreter command: stack --install-ghc runghc --package zifter +RTS -p -RTS -- ./zift.hs

because when I just run that command:

$ stack --install-ghc runghc --package zifter +RTS -p -RTS -- ./zift.hs

It works.
however, it's still very slow: (This is what I'm trying to fix)

stack --install-ghc runghc --package zifter +RTS -p -RTS -- ./zift.hs
1.27s user 0.13s system 105% cpu 1.335 total

Now, I'm not very familiar with profiling haskell, but I thought the -p flag was the one that should output some info. Indeed, I get a stack.prof file, but it is empty.

[decentral1se]

From my git blame investigation, @mgsloan might be able to help on the above comment^^!

[2chilled]

@domenkozar

resolver: lts-7.13

packages:
extra-deps: []
flags: {}
extra-package-dbs: []

nix:
  enable: false
  shell-file: shell.nix
  pure: false

Enabling nix is even slower.

I just tried with Version 1.3.2 x86_64 but unfortunately observing no performance improvements.

[jdreaver]

I'm having the exact same issue. I upgraded from 1.2.0 to 1.3.2 recently, and the overhead went from 7.5 seconds to 3 seconds! However, 3 seconds is still kind of long imo.

Here is the beginning of a --verbose call for me:

$ time stack --verbose exec true
Version 1.3.2, Git revision 3f675146590da4f3edf768b89355f798229da2a5 (4395 commits) x86_64 hpack-0.15.0
2017-02-27 20:06:02.481273: [debug] Checking for project config at: /vagrant/backend/stack.yaml
@(Stack/Config.hs:863:9)
2017-02-27 20:06:02.482927: [debug] Loading project config file stack.yaml
@(Stack/Config.hs:881:13)
2017-02-27 20:06:02.486848: [debug] Loading stack-snapshot/frontrowed-5.0.yaml build plan
@(Stack/BuildPlan.hs:959:5)
2017-02-27 20:06:02.530333: [debug] Trying to decode /home/vagrant/.stack/indices/Hackage/00-index.cache
@(Data/Store/VersionTagged.hs:68:5)
2017-02-27 20:06:02.656156: [debug] Success decoding /home/vagrant/.stack/indices/Hackage/00-index.cache
@(Data/Store/VersionTagged.hs:72:13)
2017-02-27 20:06:05.628393: [debug] Run process: /sbin/ldconfig -p
@(System/Process/Read.hs:306:3)
... (more lines below)

As you can see, the slowness is almost entirely between the last two lines (the Success decoding line and the Run process: /sbin/ldconfig -p line).

Does anyone know what stack is doing there? I am running this on a ~85k LOC Haskell project with about 18 local stack targets in stack.yaml and an additional 10 git dependencies, if that info helps.

[mgsloan]

@jdreaver Interesting! I cannot reproduce with the stack repo, I get 0.01 seconds between those steps. I've also tried with a large project with lots of local targets, and got a similar result. Could be all the git dependencies, but I don't think stack exec should care about those.

I've also took a brief look at the code and can't see anything obviously expensive happening.

[jdreaver]

Thanks for taking a look @mgsloan! I tried to make a minimal repro with a stack.yaml filled with lots of git deps, but it was still fast. This might be a tricky problem to track down 😄

I think either myself or a coworker will take a look over the next couple weeks. I'll let you know if we find anything.

[aeruhxi]

I am having the same issue on a fresh project.

stack exec discocurry-exe --verbose  1.87s user 0.10s system 101% cpu 1.930 total

Full verbose log: https://pastebin.com/eM8qZyQP