Cabal startup is slow

[nh2]

I just run the almost-noop command: time cabal build asdf

cabal: Unknown build target 'asdf'.   
There is no component 'asdf' or module 'asdf'.
cabal build asdf  3.82s user 0.08s system 99% cpu 3.903 total

What is cabal doing in these 4 seconds?

When I run time cabal build asdf -v3, I get the output

Using internal setup method with build-type Simple and args:
["build","--verbose=3","--builddir=dist","--jobs=1","asdf"]

after 2 seconds, and then the rest of the output after another 2 seconds.

I also noticed that this time seems to grow the longer I make the build-depends section in my cabal file.

What is going on behind the scenes, and can we make this no-op time faster?

This startup time seems to add to all cabal build commands; it is especially painful for builds with nothing to do, where the penalty is quite high versus the actual time needed to compile: A no-op build only takes 6.8 seconds for me.

[tibbe]

That's an interesting observation. Since -v3 doesn't give you much, could you try with time profiling to see roughly what cabal is doing?

[UnkindPartition]

    Thu Jul 24 02:16 2014 Time and Allocation Profiling Report  (Final)

       cabal +RTS -p -RTS build --only asdf

    total time  =        3.32 secs   (3317 ticks @ 1000 us, 1 processor)
    total alloc = 1,910,155,320 bytes  (excludes profiling overheads)

COST CENTRE             MODULE                            %time %alloc

readListPrec            Distribution.Package               33.1   36.9
readListPrec            Distribution.InstalledPackageInfo  25.4   26.4
readPrec                Distribution.ModuleName            16.4   14.3
readPrec                Language.Haskell.Extension          8.7    7.8
tryGetConfigStateFile.\ Distribution.Simple.Configure       4.3    5.8
readPrec                Distribution.Version                3.6    2.6
readPrec                Distribution.Simple.InstallDirs     1.6    0.0
withFileContents.\      Distribution.Simple.Utils           1.4    1.8

Full profile: https://gist.github.com/08f25e0fa907e239be9f

This is with current cabal master (d35bf72).

[nh2]

Oh well, read, what pleasure.

[23Skidoo]

@dcoutts's new parser would probably help here.

[UnkindPartition]

Correct me if I'm wrong, but the time is spent in parsing internal structures, not .cabal file. So some kind of efficient binary serialization seems to be the right solution.

[23Skidoo]

Yes, it may also be dist/setup-config, where we are basically doing a single read.

[23Skidoo]

@nh2 Is the package that you're experiencing this with on Hackage? On my system, the no-op time is a bit faster (I tested with lens):

cabal build asdf  0,82s user 0,04s system 85% cpu 1,001 total

[UnkindPartition]

@23Skidoo try this in a sandbox with many packages installed

[23Skidoo]

Then it's likely the add-source deps check, which reads the installed package index. So we should be optimising getPackageDBContents.

[UnkindPartition]

Well...

% time cabal build --only -v asdf
Skipping add-source deps check...
Using a sandbox located at /home/feuerbach/work/.cabal-sandbox
cabal: Unknown build target 'asdf'.
There is no component 'asdf' or module 'asdf'.
cabal build --only -v asdf  1.91s user 0.02s system 100% cpu 1.928 total

[23Skidoo]

I just tried with a larger sandbox (installed snap, haskell-src-exts and all lens dependencies + a single add-source dep), but it didn't make a big difference:

cabal build asdf  0,82s user 0,04s system 91% cpu 0,938 total

build --only time is the same:

cabal build --only asdf  0,83s user 0,04s system 90% cpu 0,957 total

[UnkindPartition]

Can you take a look at the full profile that I published above? It should point exactly to where the time is spent.

[23Skidoo]

Well, it does look like half of the time is spent in parsing dist/setup-config.

            tryGetPersistBuildConfig
            Distribution.Simple.Configure                    907           1    0.0    0.0    50.0   49.8

So the larger that file is (which depends on how many dependencies you have), the longer it should take.

[23Skidoo]

OK, I tested this theory, and the do-nothing cabal build indeed takes longer on packages with large sets of dependencies, such as snap:

cabal build asdf  2,94s user 0,18s system 93% cpu 3,333 total

So the problem is inefficient parsing of LocalBuildInfo.

[nh2]

Could Cabal depend on binary if it wanted?

[23Skidoo]

Maybe. GHC ships with binary.

[ttuegel]

@23Skidoo GHC ships with binary, and since GHC 7.2, binary has a generic instance. GHC 7.2.1 was released 9 August 2011, so it just fell within our 3 year backward-compatible window! That means we can migrate to Binary instead of Read/Show with no boilerplate.

@dcoutts @tibbe Any objections to deriving Generic on all the LocalBuildInfo-related types, and switching to a binary setup-config?

[tibbe]

@ttuegel not from my perspective.

[23Skidoo]

Fixed by #2076. Thanks to @feuerbach for helping to diagnose the problem and @ttuegel for actually writing the code.