Profiling and Optimization

[DanielG]

The home module graph resolution, Stack and cabal-helper really made things quite slow. We should add timestamps to log messages and add a bunch of tracing all over that code so we can find the hot spots. (Or try getting profiling working with ghc but that always turns out to be a huge pain because TH doesn't work with a profiled compiler)

[DanielG]

ts "%.s" adds timestamps to stuff

[DanielG]

$ (echo begin; ghc-mod -v7 check src/GHCMod.hs 2>&1; echo done) | ts "%.s" > log
# compute deltas
$ cat log | awk 'NR==1 { last=$1 }; { printf "%f\n", ($1 - last); last = $1 }'
# remove absolute timestamp
$ cat log | cut -d" " -f2- > log2
# concat columns together
$ paste ts log2

[DanielG]

Huh, looks like the problem is in GHC after all, I'm not getting any stable BCOs and it's just recompiling everything.. probably something to do with us changing the dynflags before calling load or something.

[DanielG]

HAHA! The fix turned out to be downright trivial. I forgot to update world in legacyInteractiveLoop if it changed and there's a race condition with the thread that updates the symboldb: the first call to getCurrentWorld will return the symboldb as Nothing (since it's being created) but later calls will return Just so the frontend keep dropping the session hence ghc reloading everything.

[DanielG]

@kazu-yamamoto check should be reasonably fast again now.

[DanielG]

1442460186.796361 begin
1442460186.992353 DEBUG: reading cache: /home/aaron/sites-programs/snowdrift/.stack-work/dist/x86_64-linux/Cabal-1.18.1.5/setup-config.ghc-mod.cabal-components
1442460187.020864 DEBUG: resolveEntrypoint:
1442460187.021804        ["-i","-i.stack-work/dist/x86_64-linux/Cabal-1.18.1.5/build","-i.","-i.stack-work/dist/x86_64-linux/Cabal-1.18.1.5/build/autogen","-I.stack-work/dist/x86_64-linux/Cabal-1.18.1.5/build/autogen","-I.stack-work/dist/x86_64-linux/Cabal-1.18.1.5/build","-optP-DDEVELOPMENT","-optP-include","-optP.stack-work/dist/x86_64-linux/Cabal-1.18.1.5/build/autogen/cabal_macros.h"]
1442460187.047359 DEBUG: resolveEntrypoint:
1442460187.048597        ["-i","-i.stack-work/dist/x86_64-linux/Cabal-1.18.1.5/build/Snowdrift/Snowdrift-tmp","-iapp","-i.stack-work/dist/x86_64-linux/Cabal-1.18.1.5/build/autogen","-I.stack-work/dist/x86_64-linux/Cabal-1.18.1.5/build/autogen","-I.stack-work/dist/x86_64-linux/Cabal-1.18.1.5/build/Snowdrift/Snowdrift-tmp","-optP-include","-optP.stack-work/dist/x86_64-linux/Cabal-1.18.1.5/build/autogen/cabal_macros.h"]
1442460187.058970 DEBUG: resolveEntrypoint:
1442460187.060365        ["-i","-i.stack-work/dist/x86_64-linux/Cabal-1.18.1.5/build/SnowdriftProcessPayments/SnowdriftProcessPayments-tmp","-iapp","-i.stack-work/dist/x86_64-linux/Cabal-1.18.1.5/build/autogen","-I.stack-work/dist/x86_64-linux/Cabal-1.18.1.5/build/autogen","-I.stack-work/dist/x86_64-linux/Cabal-1.18.1.5/build/SnowdriftProcessPayments/SnowdriftProcessPayments-tmp","-optP-include","-optP.stack-work/dist/x86_64-linux/Cabal-1.18.1.5/build/autogen/cabal_macros.h"]
1442460187.079739 DEBUG: resolveEntrypoint:
1442460187.081054        ["-i","-i.stack-work/dist/x86_64-linux/Cabal-1.18.1.5/build/SnowdriftEmailDaemon/SnowdriftEmailDaemon-tmp","-iapp","-i.stack-work/dist/x86_64-linux/Cabal-1.18.1.5/build/autogen","-I.stack-work/dist/x86_64-linux/Cabal-1.18.1.5/build/autogen","-I.stack-work/dist/x86_64-linux/Cabal-1.18.1.5/build/SnowdriftEmailDaemon/SnowdriftEmailDaemon-tmp","-optP-include","-optP.stack-work/dist/x86_64-linux/Cabal-1.18.1.5/build/autogen/cabal_macros.h"]
1442460187.103256 DEBUG: resolveEntrypoint:
1442460187.104442        ["-i","-i.stack-work/dist/x86_64-linux/Cabal-1.18.1.5/build/sdm/sdm-tmp","-idev","-i.stack-work/dist/x86_64-linux/Cabal-1.18.1.5/build/autogen","-I.stack-work/dist/x86_64-linux/Cabal-1.18.1.5/build/autogen","-I.stack-work/dist/x86_64-linux/Cabal-1.18.1.5/build/sdm/sdm-tmp","-optP-include","-optP.stack-work/dist/x86_64-linux/Cabal-1.18.1.5/build/autogen/cabal_macros.h"]
1442460187.116142 DEBUG: resolveEntrypoint:
1442460187.117570        ["-i","-i.stack-work/dist/x86_64-linux/Cabal-1.18.1.5/build/SnowdriftSendmail/SnowdriftSendmail-tmp","-i.","-i.stack-work/dist/x86_64-linux/Cabal-1.18.1.5/build/autogen","-I.stack-work/dist/x86_64-linux/Cabal-1.18.1.5/build/autogen","-I.stack-work/dist/x86_64-linux/Cabal-1.18.1.5/build/SnowdriftSendmail/SnowdriftSendmail-tmp","-optP-include","-optP.stack-work/dist/x86_64-linux/Cabal-1.18.1.5/build/autogen/cabal_macros.h"]
1442460187.128307 DEBUG: resolveEntrypoint:
1442460187.130241        ["-i","-i.stack-work/dist/x86_64-linux/Cabal-1.18.1.5/build/test/test-tmp","-itests","-i.stack-work/dist/x86_64-linux/Cabal-1.18.1.5/build/autogen","-I.stack-work/dist/x86_64-linux/Cabal-1.18.1.5/build/autogen","-I.stack-work/dist/x86_64-linux/Cabal-1.18.1.5/build/test/test-tmp","-optP-include","-optP.stack-work/dist/x86_64-linux/Cabal-1.18.1.5/build/autogen/cabal_macros.h"]
1442460187.152697 DEBUG: resolveEntrypoint: []
1442460187.162453 DEBUG: reading cache: .stack-work/dist/x86_64-linux/Cabal-1.18.1.5/setup-config.ghc-mod.resolved-components
1442460187.210922 VOMIT: Initializing GHC session with following options: "-fbuilding-cabal-package" "-O" "-outputdir" ".stack-work/dist/x86_64-linux/Cabal-1.18.1.5/build" "-odir" ".stack-work/dist/x86_64-linux/Cabal-1.18.1.5/build" "-hidir" ".stack-work/dist/x86_64-linux/Cabal-1.18.1.5/build" "-stubdir" ".stack-work/dist/x86_64-linux/Cabal-1.18.1.5/build" "-i" "-i.stack-work/dist/x86_64-linux/Cabal-1.18.1.5/build" "-i." "-i.stack-work/dist/x86_64-linux/Cabal-1.18.1.5/build/autogen" "-I.stack-work/dist/x86_64-linux/Cabal-1.18.1.5/build/autogen" "-I.stack-work/dist/x86_64-linux/Cabal-1.18.1.5/build" "-optP-DDEVELOPMENT" "-optP-include" "-optP.stack-work/dist/x86_64-linux/Cabal-1.18.1.5/build/autogen/cabal_macros.h" "-hide-all-packages" "-no-user-package-db" "-package-db" "/home/aaron/.stack/snapshots/x86_64-linux/lts-2.22/7.8.4/pkgdb/" "-package-db" "/home/aaron/sites-programs/snowdrift/.stack-work/install/x86_64-linux/lts-2.22/7.8.4/pkgdb/" "-package-id" "Diff-0.3.2-1b07b9df8494a4fae9f5ffb63a2c286a" "-package-id" "async-2.0.2-8eeaa974e7375a529dd6320cf5f8ab24" "-package-id" "attoparsec-0.12.1.6-08470f8f26c31d06c638dcc7274df5c2" "-package-id" "authenticate-1.3.2.11-50297d94586c2b83d7bcd7fcf2cd5ecd" "-package-id" "base-4.7.0.2-bfd89587617e381ae01b8dd7b6c7f1c1" "-package-id" "blaze-builder-0.4.0.1-5608cf602c2a433c5018ce06c3dfd8ee" "-package-id" "blaze-html-0.8.1.0-1bd9760d0bf5833cc98ba32c1eb786e7" "-package-id" "blaze-markup-0.7.0.2-2049f31534d67a33589861e694abb167" "-package-id" "bytestring-0.10.4.0-d6f1d17d717e8652498cab8269a0acd5" "-package-id" "conduit-1.2.5-839a6e77ce2a46eadf5d49e79c602648" "-package-id" "containers-0.5.5.1-d4bd887fb97aa3a46cbadc13709b7653" "-package-id" "data-default-0.5.3-080d154f8a51830037b99cc610c6c441" "-package-id" "directory-1.2.1.0-07cd1f59e3c6cac5e3e180019c59a115" "-package-id" "esqueleto-2.1.3-62fa9129601bfac7227af0c3c48f5dcb" "-package-id" "fast-logger-2.3.1-91db032db8f220d0a5281025c27f1828" "-package-id" "github-0.13.2-9e2df1468864735f0ed1798d131618a3" "-package-id" "hit-0.6.3-27711aa62f0dfe1f91ccbc2c3a27f810" "-package-id" "hjsmin-0.1.5.0-a567d06084030357a0e10f6d5da9d8fa" "-package-id" "hourglass-0.2.9-78e5bc8bdeaf388758cba2f9d5097349" "-package-id" "http-conduit-2.1.7.2-9bbf9a96eb9a30810f2de0fd8411467d" "-package-id" "http-types-0.8.6-c546be3a27dd5572caeed968da3569ac" "-package-id" "lens-4.7.0.1-0fdac9c342a357b7120514e52fb253af" "-package-id" "libravatar-0.1.0.1-dc1fc763c0a50793805170662f9146aa" "-package-id" "lifted-base-0.2.3.6-d4a276efe0b04220a30c2b9c19c2705c" "-package-id" "mime-mail-0.4.9-c0a69bc8fba5a15f0de667651297810a" "-package-id" "monad-logger-0.3.13.2-355a5876a46a39e17df0939a638af278" "-package-id" "mtl-2.1.3.1-96f1a7910a7553352339ed05fb61c269" "-package-id" "old-locale-1.0.0.6-50b0125c49f76af85dc7aa22975cdc34" "-package-id" "pandoc-1.13.2.1-25d8f45e81d9b764d8ea701590dfe311" "-package-id" "path-pieces-0.2.0-7bdef032fa51e1e41fe2d16fcab068b1" "-package-id" "persistent-2.1.6-becef6c0e16e7ab334a0ca810035549b" "-package-id" "persistent-postgresql-2.1.6-c902823582b558a44efd0da2a75f5388" "-package-id" "persistent-template-2.1.3.4-f04ba96e1ad2cd102942cfb053fe15a4" "-package-id" "process-1.2.0.0-06c3215a79834ce4886ae686a0f81122" "-package-id" "random-1.1-092becd083af689459dfd417368314bf" "-package-id" "regex-tdfa-1.2.0-9d4c17fa380f1eca74bec75df876ffc9" "-package-id" "resourcet-1.1.6-7231fc94ec8a07a2e3055485957ecabe" "-package-id" "semigroups-0.16.2.2-a7757dba068a60f81374b18301ade2bc" "-package-id" "shakespeare-2.0.5-4b361d3a0b3040ed72a0c92c967cabe4" "-package-id" "stm-2.4.4-c36cb8072081a12d13d98a3b4449e55c" "-package-id" "template-haskell-2.9.0.0-6d27c2b362b15abb1822f2f34b9ae7f9" "-package-id" "temporary-1.2.0.3-e93c3d6dccb5d4c3e488935a7467c84d" "-package-id" "text-1.2.0.6-4e16e52c9cd5d8806f25a2436848dc85" "-package-id" "time-1.4.2-9b3076800c33f8382c38628f35717951" "-package-id" "titlecase-0.1.0.1-b3d18e93d963ba01f4c04df9bf9fe0c8" "-package-id" "transformers-0.3.0.0-6458c21515cab7c1cf21e53141557a1c" "-package-id" "wai-extra-3.0.10-c02bf0001acbc744fd07fdbf3d285b90" "-package-id" "wai-logger-2.2.4.1-3300ab1b0499955bcd992aefe165c077" "-package-id" "warp-3.0.13.1-2906194e1a737dd0add89080119909c6" "-package-id" "yaml-0.8.12-4f66a88ad1c90c8ac244ac7801b140a7" "-package-id" "yesod-1.4.1.5-6190474db5116834ec42fc4095ab7ea7" "-package-id" "yesod-auth-1.4.6-944dad333e24c265bc19f9bd5c5d40dd" "-package-id" "yesod-auth-hashdb-1.4.2.2-74d36b21a04d33a8cfce3ecee219f147" "-package-id" "yesod-core-1.4.12-b8cd1fe0835e12fc6fb5907a17211f96" "-package-id" "yesod-form-1.4.4.1-42be70fe9c23d897594257363edd7a5c" "-package-id" "yesod-markdown-0.9.4-d31bfd1792156e118794be9510c12273" "-package-id" "yesod-newsfeed-1.4.0.1-499d273ce1e9479c1e4c5c98a235c745" "-package-id" "yesod-static-1.4.0.4-ba7ed5dbb1eddc38f276f3587118c08c" "-XHaskell98" "-XConstraintKinds" "-XDeriveDataTypeable" "-XDeriveFunctor" "-XEmptyDataDecls" "-XExistentialQuantification" "-XFlexibleContexts" "-XFlexibleInstances" "-XGADTs" "-XGeneralizedNewtypeDeriving" "-XLambdaCase" "-XMultiParamTypeClasses" "-XMultiWayIf" "-XNoImplicitPrelude" "-XNoMonomorphismRestriction" "-XQuasiQuotes" "-XOverloadedStrings" "-XRankNTypes" "-XRecordWildCards" "-XScopedTypeVariables" "-XTemplateHaskell" "-XTupleSections" "-XTypeFamilies" "-XViewPatterns" "-Wall" "-O0" "-fobject-code" "-O0"
1442460187.211125 DEBUG: initSession: Session not initialized, creating new one
1442460187.400799 DEBUG: loadTargets: Loading: Foundation.hs
1442460187.564596 info: loadTargets:
1442460187.565185       Target needs interpeter, switching to LinkInMemory/HscInterpreted. Perfectly normal if anything is using TemplateHaskell, QuasiQuotes or PatternSynonyms.
1442460215.760197 DEBUG: loadTargets: Loading done
1442460216.006328 done

[parsonsmatt]

I'm getting some pretty big slowdown in my larger projects. ghc-mod type runs pretty fast on a file with 0 dependencies. No time stamps, but it's comparable with hdevtools. In another project (code itself isn't much, but has lens/pipes/persistent dependencies), it takes about 2 seconds to do ghc-mod type where hdevtools is still as fast as it was on the other. Is there some way I can get more reliable information to you about this to help debug it?

[DanielG]

@parsonsmatt Please open a separate issue about that problem.

[PierreR]

@parsonsmatt Did you open a separate issue for this because I have the same problem (using stack)

[DanielG]

Some progress: https://github.com/kazu-yamamoto/ghc-mod/commit/89b1ac2d1ed70bd8f042f9bc4c8ee8b22984acfe :D