GHCi is slow on first :main
Summary
When loading certain projects into ghci, the first call to main after a :l or a :r will take a few seconds until the main is actually executed.
This makes live reloading in IHP very slow. E.g. when a user changes some haskell code in an IHP project, the IHP dev server will stop the current app in ghci and trigger a :r. The IHP dev server watches for a message such as Ok, 199 modules loaded. and then triggers a :main. This call to :main now takes a couple of seconds to execute, even though ghci already told is that it has reloaded all necessary files.
Here's a video showing the problem:
Bildschirmaufnahme_2023-05-18_um_16.39.04
The Main entered message appears as expected, but there's a long delay between when I enter main and when the message appears. The putStrLn "Main entered" is the first operation in that module:
main :: IO ()
main = do
putStrLn "Main entered"
IHP.Server.run configSteps to reproduce
This problem also happens with the IHP repo itself, so we can use that to reproduce it.
To load IHP into ghci, you need to install nix and devenv.sh first.
Once devenv.sh is installed, run cachix use digitallyinduced to enable our binary cache for a faster build time.
Now you can reproduce it by running these commands:
# Clone the repo
git clone https://github.com/digitallyinduced/ihp.git
cd ihp
# This will enter a shell with all dependencies
nix develop --impure
# Run ghci
ghci
:l Test/Main.hs
# => Ok, 152 modules loaded.
main
# ... now it takes a few seconds until the app starts upExpected behavior
Calling main should directly start the app, without a delay of a few seconds.
Environment
- GHC version used: 9.4.4 + 9.6.2
- Operating System: macOS (This problem might be mac specific, I've not seen similiar behaviour on linux computers)
- System Architecture: x86_64
- Project Size: This problem seems to only appear in projects with more than a few modules. On a fresh IHP project with 20 modules, the
:mainis typically instant.
Activity
This seems to confirm that this only affects macOS. My gut feeling is that it's somehow related to linking (which likely is different on macOS).
Here's the output with
-v2:IHP> main *** Parser [source]: !!! Parser [source]: finished in 0.04 milliseconds, allocated 0.023 megabytes *** Desugar: *** Simplify [expr]: !!! Simplify [expr]: finished in 0.15 milliseconds, allocated 0.081 megabytes *** CorePrep [expr]: !!! CorePrep [expr]: finished in 0.05 milliseconds, allocated 0.029 megabytes *** Stg2Stg: *** GHC.StgToByteCode [Ghci1]: !!! GHC.StgToByteCode [Ghci1]: finished in 0.11 milliseconds, allocated 0.078 megabytes Main entered Server startedThe delay happens after the last debug output line.
assigned to @bgamari
-
@bgamari and I reproduced this at Zurihack; a typical stack during the pause looks like:
(lldb) bt * thread #1, name = 'ghc_worker', queue = 'com.apple.main-thread', stop reason = signal SIGSTOP * frame #0: 0x00007ff811ce8fb2 dyld`dyld3::MachOFile::trieWalk(Diagnostics&, unsigned char const*, unsigned char const*, char const*) + 398 frame #1: 0x00007ff811cb3692 dyld`dyld4::Loader::hasExportedSymbol(Diagnostics&, dyld4::RuntimeState&, char const*, dyld4::Loader::ExportedSymbolMode, dyld4::Loader::ResolvedSymbol*, dyld3::Array<dyld4::Loader const*>*) const + 312 frame #2: 0x00007ff811cd02f5 dyld`invocation function for block in dyld4::APIs::dlsym(void*, char const*) + 125 frame #3: 0x00007ff811ca36f9 dyld`dyld4::RuntimeState::withLoadersReadLock(void () block_pointer) + 41 frame #4: 0x00007ff811ccff44 dyld`dyld4::APIs::dlsym(void*, char const*) + 952 frame #5: 0x00000001021428d2 libHSrts_thr-ghc9.4.4.dylib`lookupDependentSymbol + 354 frame #6: 0x0000000102142c13 libHSrts_thr-ghc9.4.4.dylib`lookupSymbol + 35 frame #7: 0x0000000101cf96a8 libHSghci-9.4.4-ghc9.4.4.dylib`Lc3hC_info + 40 -
Output of
ghci -RTS +Dland thengrep "internal_dlsym" optlog | sort | uniq -c | sort -r | lessfor non optimized build:8480 internal_dlsym: found symbol 'ghczmprim_GHCziCString_unpackCStringzh_closure' in program 3952 internal_dlsym: found symbol 'ghczmprim_GHCziTypes_ZC_con_info' in program 3293 internal_dlsym: found symbol 'textzm1zi2zi5zi0_DataziText_pack_closure' in shared object 2716 internal_dlsym: found symbol 'textzm1zi2zi5zi0_DataziText_zdfIsStringText_closure' in shared object 2565 internal_dlsym: found symbol 'ghczmprim_GHCziTypes_ZMZN_closure' in program 1343 internal_dlsym: found symbol 'ghczmprim_GHCziTuple_Z2T_con_info' in program 974 internal_dlsym: found symbol 'ghczmprim_GHCziTypes_Izh_con_info' in program 916 internal_dlsym: found symbol 'base_GHCziBase_zi_closure' in program 778 internal_dlsym: found symbol 'ghczmprim_GHCziTypes_TrNameS_con_info' in program 765 internal_dlsym: found symbol 'base_GHCziBase_zlzg_closure' in program 689 internal_dlsym: found symbol 'ghczmprim_GHCziTypes_KindRepFun_con_info' in program 678 internal_dlsym: found symbol 'ghczmprim_GHCziTypes_Eqzh_con_info' in program 677 internal_dlsym: found symbol 'base_GHCziShow_showString_closure' in program 646 internal_dlsym: found symbol 'blazzezmmarkupzm0zi8zi2zi8zm5hcoVacOpJu7WU5dNWK1Al_TextziBlazzeziInternal_textTag_closure' in shared object 584 internal_dlsym: found symbol 'ghczmprim_GHCziTypes_KindRepTyConApp_con_info' in program 534 internal_dlsym: found symbol 'ghczmprim_GHCziTypes_TyCon_con_info' in program 523 internal_dlsym: found symbol 'base_GHCziBase_zgzgze_closure' in program 504 internal_dlsym: found symbol 'bytestringzm0zi11zi3zi1_DataziByteStringziInternal_zdfIsStringByteString_closure' in program 483 internal_dlsym: found symbol 'ghczmprim_GHCziClasses_zeze_closure' in program 473 internal_dlsym: found symbol 'base_GHCziBase_zdfMonadIO_closure' in program 374 internal_dlsym: found symbol 'blazzezmmarkupzm0zi8zi2zi8zm5hcoVacOpJu7WU5dNWK1Al_TextziBlazzeziInternal_preEscapedText_closure' in shared object 340 internal_dlsym: found symbol 'base_GHCziBase_pure_closure' in program 323 internal_dlsym: found symbol 'blazzezmmarkupzm0zi8zi2zi8zm5hcoVacOpJu7WU5dNWK1Al_TextziBlazzeziInternal_zdfAttributableMarkupM_closure' in shared object 323 internal_dlsym: found symbol 'blazzezmmarkupzm0zi8zi2zi8zm5hcoVacOpJu7WU5dNWK1Al_TextziBlazzeziInternal_attribute_closure' in shared object 322 internal_dlsym: found symbol 'blazzezmmarkupzm0zi8zi2zi8zm5hcoVacOpJu7WU5dNWK1Al_TextziBlazzeziInternal_preEscapedTextValue_closure' in shared object 299 internal_dlsym: found symbol 'base_GHCziShow_showsPrec_closure' in program 294 internal_dlsym: found symbol 'base_GHCziBase_zgzg_closure' in program 258 internal_dlsym: found symbol 'base_GHCziBase_zd_closure' in program 249 internal_dlsym: found symbol 'base_GHCziBase_zdfApplicativeIO_closure' in program 241 internal_dlsym: found symbol 'ghczmprim_GHCziTypes_False_closure' in program 221 internal_dlsym: found symbol 'bytestringzm0zi11zi3zi1_DataziByteStringziInternal_zdfSemigroupByteString_closure' in program 216 internal_dlsym: found symbol 'ghczmprim_GHCziPrimopWrappers_dataToTagzh_closure' in program 211 internal_dlsym: found symbol 'ghczmprim_GHCziClasses_zaza_closure' in program 205 internal_dlsym: found symbol 'aesonzm2zi0zi3zi0zmJFcvkGjawJ023iFoa0xm17_DataziAesonziKey_fromString_closure' in shared object 203 internal_dlsym: found symbol 'textzm1zi2zi5zi0_DataziText_zdfSemigroupText_closure' in shared object 199 internal_dlsym: found symbol 'stringzmconversionszm0zi4zi0zi1zm4czzE9VwOQnG2ZZDLlaZZQmtf_DataziStringziConversions_cs_closure' in shared object 182 internal_dlsym: found symbol 'base_GHCziShow_showCommaSpace_closure' in program 181 internal_dlsym: found symbol 'base_GHCziBase_mconcat_closure' in program 173 internal_dlsym: found symbol 'base_DataziTypeableziInternal_mkTrCon_closure' in program 168 internal_dlsym: found symbol 'ghczmprim_GHCziTypes_krepzdzt_closure' in program 161 internal_dlsym: found symbol 'base_GHCziMaybe_Just_con_info' in programSame for -O2 build:
9964 internal_dlsym: found symbol 'ghczmprim_GHCziCString_unpackCStringzh_closure' in program 4835 internal_dlsym: found symbol 'ghczmprim_GHCziTypes_ZC_con_info' in program 3607 internal_dlsym: found symbol 'textzm1zi2zi5zi0_DataziText_zdfIsStringText_closure' in shared object 3296 internal_dlsym: found symbol 'textzm1zi2zi5zi0_DataziText_pack_closure' in shared object 2758 internal_dlsym: found symbol 'ghczmprim_GHCziTypes_ZMZN_closure' in program 1449 internal_dlsym: found symbol 'ghczmprim_GHCziTuple_Z2T_con_info' in program 1240 internal_dlsym: found symbol 'ghczmprim_GHCziTypes_Izh_con_info' in program 1027 internal_dlsym: found symbol 'base_GHCziBase_zi_closure' in program 913 internal_dlsym: found symbol 'ghczmprim_GHCziTypes_TrNameS_con_info' in program 834 internal_dlsym: found symbol 'base_GHCziBase_zlzg_closure' in program 804 internal_dlsym: found symbol 'ghczmprim_GHCziTypes_KindRepFun_con_info' in program 738 internal_dlsym: found symbol 'base_GHCziShow_showString_closure' in program 715 internal_dlsym: found symbol 'ghczmprim_GHCziTypes_Eqzh_con_info' in program 689 internal_dlsym: found symbol 'ghczmprim_GHCziTypes_KindRepTyConApp_con_info' in program 654 internal_dlsym: found symbol 'blazzezmmarkupzm0zi8zi2zi8zm5hcoVacOpJu7WU5dNWK1Al_TextziBlazzeziInternal_textTag_closure' in shared object 631 internal_dlsym: found symbol 'ghczmprim_GHCziTypes_TyCon_con_info' in program 591 internal_dlsym: found symbol 'base_GHCziBase_zgzgze_closure' in program 543 internal_dlsym: found symbol 'ghczmprim_GHCziClasses_zeze_closure' in program 514 internal_dlsym: found symbol 'bytestringzm0zi11zi3zi1_DataziByteStringziInternal_zdfIsStringByteString_closure' in program 488 internal_dlsym: found symbol 'base_GHCziBase_zdfMonadIO_closure' in program 388 internal_dlsym: found symbol 'base_GHCziBase_pure_closure' in program 374 internal_dlsym: found symbol 'blazzezmmarkupzm0zi8zi2zi8zm5hcoVacOpJu7WU5dNWK1Al_TextziBlazzeziInternal_preEscapedText_closure' in shared object 347 internal_dlsym: found symbol 'base_GHCziBase_zd_closure' in program 345 internal_dlsym: found symbol 'base_GHCziShow_showsPrec_closure' in program 333 internal_dlsym: found symbol 'base_GHCziBase_zgzg_closure' in program 327 internal_dlsym: found symbol 'blazzezmmarkupzm0zi8zi2zi8zm5hcoVacOpJu7WU5dNWK1Al_TextziBlazzeziInternal_zdfAttributableMarkupM_closure' in shared object 327 internal_dlsym: found symbol 'blazzezmmarkupzm0zi8zi2zi8zm5hcoVacOpJu7WU5dNWK1Al_TextziBlazzeziInternal_attribute_closure' in shared object 322 internal_dlsym: found symbol 'blazzezmmarkupzm0zi8zi2zi8zm5hcoVacOpJu7WU5dNWK1Al_TextziBlazzeziInternal_preEscapedTextValue_closure' in shared object 264 internal_dlsym: found symbol 'ghczmprim_GHCziTypes_False_closure' in program 259 internal_dlsym: found symbol 'base_GHCziBase_zdfApplicativeIO_closure' in program 251 internal_dlsym: found symbol 'stringzmconversionszm0zi4zi0zi1zm4czzE9VwOQnG2ZZDLlaZZQmtf_DataziStringziConversions_cs_closure' in shared object 247 internal_dlsym: found symbol 'ghczmprim_GHCziPrimopWrappers_dataToTagzh_closure' in program 242 internal_dlsym: found symbol 'textzm1zi2zi5zi0_DataziText_zdfSemigroupText_closure' in shared object 226 internal_dlsym: found symbol 'ghczmprim_GHCziClasses_zaza_closure' in program 221 internal_dlsym: found symbol 'bytestringzm0zi11zi3zi1_DataziByteStringziInternal_zdfSemigroupByteString_closure' in program 205 internal_dlsym: found symbol 'aesonzm2zi0zi3zi0zmJFcvkGjawJ023iFoa0xm17_DataziAesonziKey_fromString_closure' in shared object 198 internal_dlsym: found symbol 'ghczmprim_GHCziTypes_krepzdzt_closure' in program 192 internal_dlsym: found symbol 'ghczmprim_GHCziTypes_False_con_info' in program 190 internal_dlsym: found symbol 'base_GHCziShow_showCommaSpace_closure' in program 190 internal_dlsym: found symbol 'base_GHCziMaybe_Just_con_info' in program 189 internal_dlsym: found symbol 'ghczmprim_GHCziClasses_zdfOrdInt_closure' in program -
@bgamari was fun hacking with you on this at ZuriHac! :) Did you get the reproduce steps working on the server? Anything else I can provide to help with this?
-
This issue is now affecting more people in the IHP community https://github.com/digitallyinduced/ihp/pull/1736#issuecomment-1639582129
There's a video reproducing this here https://github.com/digitallyinduced/ihp/pull/1736#issuecomment-1639680376
For the record, this can be reproduced using
ghc-9.2.5using:$ git clone https://github.com/digitallyinduced/ihp.git $ cabal build --write-ghc-environment-file=always -w $GHC $ time $GHC --interactive \ -e ':load Test/Main.hs' \ -e 'putStrLn "<STARTING>"' \ -e 'main' \ -e 'putStrLn "<DONE>"' \ -e ':quit' \ |& nix shell nixpkgs#moreutils -c ts -s '%.S' -m \ | tee log ... $ grep -e '<STARTING>' -e '<DONE>' log 00:00:17.563267 <STARTING> 00:00:29.040297 <DONE>That is, we spent nearly 15 seconds linking (
mainitself takes less than 0.4 seconds). During this time, essentially all symbols are resolved using the system's dynamic linker, which appears to be horrendously slow.However, there also appears to be quite a bit of repeated resolution happening:
$ cut --complement -d' ' -f 1 log | grep found | sort | uniq -c | sort -nr | head 18054 internal_dlsym: found symbol 'ghczmprim_GHCziCString_unpackCStringzh_closure' in program 13872 internal_dlsym: found symbol 'ghczmprim_GHCziTypes_Izh_con_info' in program 6940 internal_dlsym: found symbol 'ghczmprim_GHCziTypes_ZC_con_info' in program 6413 internal_dlsym: found symbol 'textzm2zi0zi2_DataziText_zdfIsStringText_closure' in shared object 5046 internal_dlsym: found symbol 'textzm2zi0zi2_DataziText_unpackCStringLenzh_closure' in shared object 4721 internal_dlsym: found symbol 'ghczmprim_GHCziTypes_ZMZN_con_info' in program 3393 internal_dlsym: found symbol 'ghczmprim_GHCziTuple_Z2T_con_info' in program 2001 internal_dlsym: found symbol 'ihpzmhsxzm1zi0zi1zminplace_IHPziHSXziQQ_textToStaticString_closure' in shared object 1832 internal_dlsym: found symbol 'base_GHCziStackziTypes_SrcLoc_con_info' in program 1813 internal_dlsym: found symbol 'base_GHCziStackziTypes_pushCallStack_closure' in programEdited by Ben Gamari-
Looking more carefully at timings (using this tool: $5728), there appears to be something very wrong with Darwin runtime linker. Specifically, I see
$ sed -n '/START/,$p' log | python3 linker-stats.py 1.8882 748 'hspczmcrzm2zi11zi4zm948c241c_TestziHspecziCoreziSpecziMonad_zdfMonadSpecM_closure' 1.8878 749 'hspczmcrzm2zi11zi4zm948c241c_TestziHspecziCoreziSpec_it_closure' 1.7776 709 'hspczmcrzm2zi11zi4zm948c241c_TestziHspecziCoreziExample_zdfExampleIO_closure' 0.4815 191 'hspczmcrzm2zi11zi4zm948c241c_TestziHspecziCoreziSpec_describe_closure' 0.2779 2001 'ihpzmhsxzm1zi0zi1zminplace_IHPziHSXziQQ_textToStaticString_closure' 0.1694 6413 'textzm2zi0zi2_DataziText_zdfIsStringText_closure' 0.1250 1176 'blzzzmmrkpzm0zi8zi2zi8zmdead8579_TextziBlazzeziInternal_textTag_closure' 0.1133 820 'hspczmxpcttnszm0zi8zi4zmb6ac4d6b_TestziHspecziExpectations_shouldBe_closure' 0.0982 40 'hspczmcrzm2zi11zi4zm948c241c_TestziHspecziCoreziExample_zdfExampleFUN0_closure' 0.0943 18054 'ghczmprim_GHCziCString_unpackCStringzh_closure'where the first column gives the total amount of time spent resolving the symbol and the second gives the number of resolutions.
That is, it seems to have taken only 100ms to resolve
ghczmprim_GHCziCString_unpackCStringzh_closurenearly 18000 times (around 5us/lookup). Meanwhile, it takes 1.8 seconds to resolvehspczmcrzm2zi11zi4zm948c241c_TestziHspecziCoreziSpecziMonad_zdfMonadSpecM_closureandhspczmcrzm2zi11zi4zm948c241c_TestziHspecziCoreziSpec_it_closureonly ~750 times (2 ms/lookup). This seems crazy yet is quite reproducible across runs.I can only guess that their hash-map implementation has some truly horrible collision behavior.
Edited by Ben Gamari -
I can only guess that their hash-map implementation has some truly horrible collision behavior.
Looking a bit deeper into the statistics lends further support to this hypothesis:
Nearly all resolutions take less than 20 us, but there is a wide dispersion with a very clear multi-modal structure. Moreover, there is a small tail where a few symbols take an order of magnitude longer than the larger mode.
Moreover, looking at the individual lookup times confirms that these "bad" cases aren't simply due to a one-time cost (which might be due to, e.g., lots of relocations being lazily performed). Every lookup of a "bad" symbol is of similar (high) cost.
from matplotlib import pyplot as pl import numpy as np x = np.genfromtxt('hi') ts = x[:,2] bins = np.logspace(-6, -2, 100) pl.hist(ts, log=True, bins=bins, density=False) pl.ylabel('number of occurrences') pl.xlabel('time per resolution (seconds)') pl.xscale('log') pl.savefig('hist.svg')Edited by Ben Gamari -
Sorting by decreasing time-per-resolution:
0.0080 2 4.00e-03 'chnkdzmdtzm0zi3zi1zma4d7cb34_DataziChunkedZZip_zdfZZipZMZN_closure' 0.0078 2 3.91e-03 'chnkdzmdtzm0zi3zi1zma4d7cb34_DataziChunkedZZip_zzip_closure' 0.0026 1 2.56e-03 'hspczmcrzm2zi11zi4zm948c241c_TestziHspecziCoreziRunner_hspec_closure' 1.8890 748 2.53e-03 'hspczmcrzm2zi11zi4zm948c241c_TestziHspecziCoreziSpecziMonad_zdfMonadSpecM_closure' 0.4814 191 2.52e-03 'hspczmcrzm2zi11zi4zm948c241c_TestziHspecziCoreziSpec_describe_closure' 1.8874 749 2.52e-03 'hspczmcrzm2zi11zi4zm948c241c_TestziHspecziCoreziSpec_it_closure' 0.0050 2 2.52e-03 'hspczmcrzm2zi11zi4zm948c241c_TestziHspecziCoreziHooks_beforeAll_closure' 1.7801 709 2.51e-03 'hspczmcrzm2zi11zi4zm948c241c_TestziHspecziCoreziExample_zdfExampleIO_closure' 0.0984 40 2.46e-03 'hspczmcrzm2zi11zi4zm948c241c_TestziHspecziCoreziExample_zdfExampleFUN0_closure' 0.0012 1 1.15e-03 'rzmncdzm1zi5zi0zi7zm28796f45_NetworkziURIziEncode_encode_closure' 0.0002 1 2.34e-04 'clssyzmprldzm1zi5zi0zi2zmb5b03565_ClassyPrelude_writeFile_closure' 0.0002 1 2.27e-04 'clssyzmprldzm1zi5zi0zi2zmb5b03565_ClassyPrelude_undefined_closure' 0.0054 26 2.09e-04 'clssyzmprldzm1zi5zi0zi2zmb5b03565_ClassyPrelude_tshow_closure' 0.0006 3 2.08e-04 'clssyzmprldzm1zi5zi0zi2zmb5b03565_ClassyPrelude_putStrLn_closure' 0.0002 1 2.06e-04 'clssyzmprldzm1zi5zi0zi2zmb5b03565_ClassyPrelude_readFile_closure' 0.0014 7 2.05e-04 'clssyzmprldzm1zi5zi0zi2zmb5b03565_ClassyPrelude_readMay_closure'where column 1 is total resolution time, column 2 is number of resolutions, column 3 is time per resolution.
I was hoping we would find here that all "slow" symbols, e.g., share a prefix but this doesn't appear to be the case. There are symbols with high resolution cost from at least three different libraries.
Edited by Ben Gamari
-
Doing a bit more more digging with $5729.
Looking at the non-symbol-aggregated resolution-time histogram reveals the trimodal structure more clearer:
Moreover, looking at the resolution-time histograms of a few individual symbols confirms that the behavior truly is consistent for all resolutions of a given symbol:
-
At this point I am quite certain that the bug here is not in GHC. There is simply no reason why the resolution of one symbol should consistently take three orders of magnitude longer than another. Moreover, the stack traces that I have observed suggest that nearly all of this time is spent in
libSystem.This being Darwin, which a good number of our users rely upon, it is clear that the status quo is not tenable; 15 second link times are simply too long for interactive usage. On the other hand, this being an Apple platform, I have little confidence that this will be fixed by upstream.
I suspect the only way forward here is to hide the problem by caching symbol resolutions. Of course, this then means that we need to deal with invalidation, sizing, and all of the usual problems associated with caches. I suspect this will be a day or two of work.
Edited by Ben Gamari mentioned in merge request !11010 (closed)
-
I prototyped a very simple cache in !11010 (closed). This brought link time from 11 seconds down to less than 3. This is still very poor, but ultimately I suspect that given Darwin's linker implementation this is the best we can do without changing symbol names.
As it seems likely that Darwin's linker is using a trie for symbol lookup, I suspect prepending each symbol with a few bytes of hash content would also likely help.
Edited by Ben Gamari added GHCi runtime perf labels
added Pnormal label
