[GHC] #15938: Hadrian's recompilation check is extremely slow
#15938: Hadrian's recompilation check is extremely slow -------------------------------------+------------------------------------- Reporter: bgamari | Owner: (none) Type: bug | Status: new Priority: high | Milestone: 8.8.1 Component: Build System | Version: 8.6.2 (Hadrian) | Keywords: | Operating System: Unknown/Multiple Architecture: | Type of failure: None/Unknown Unknown/Multiple | Test Case: | Blocked By: Blocking: | Related Tickets: Differential Rev(s): | Wiki Page: -------------------------------------+------------------------------------- I just Ctrl-C'd hadrian while it was building `libraries/base`, having noticed that I forgot to start it with `-j`. I then immediately restarted it and noticed that Hadrian needed to think for 45 seconds before it started even a single build. This is orders of magnitude worse than `make` so something must be wrong. I'm setting this at high priority since 45 seconds is longer than many complete `make` rebuilds. -- Ticket URL: http://ghc.haskell.org/trac/ghc/ticket/15938 GHC http://www.haskell.org/ghc/ The Glasgow Haskell Compiler
#15938: Hadrian's recompilation check is extremely slow -------------------------------------+------------------------------------- Reporter: bgamari | Owner: (none) Type: bug | Status: new Priority: high | Milestone: 8.8.1 Component: Build System | Version: 8.6.2 (Hadrian) | Resolution: | Keywords: Operating System: Unknown/Multiple | Architecture: | Unknown/Multiple Type of failure: None/Unknown | Test Case: Blocked By: | Blocking: Related Tickets: | Differential Rev(s): Wiki Page: | -------------------------------------+------------------------------------- Changes (by bgamari): * cc: alpmestan, snowleopard (added) -- Ticket URL: http://ghc.haskell.org/trac/ghc/ticket/15938#comment:1 GHC http://www.haskell.org/ghc/ The Glasgow Haskell Compiler
#15938: Hadrian's recompilation check is extremely slow -------------------------------------+------------------------------------- Reporter: bgamari | Owner: (none) Type: bug | Status: new Priority: high | Milestone: 8.8.1 Component: Build System | Version: 8.6.2 (Hadrian) | Resolution: | Keywords: Operating System: Unknown/Multiple | Architecture: | Unknown/Multiple Type of failure: None/Unknown | Test Case: Blocked By: | Blocking: Related Tickets: | Differential Rev(s): Wiki Page: | -------------------------------------+------------------------------------- Comment (by mpickering): It gets faster for subsequent rebuilds. I think it got down to about 10s on my machine after running it 3-4 times. -- Ticket URL: http://ghc.haskell.org/trac/ghc/ticket/15938#comment:2 GHC http://www.haskell.org/ghc/ The Glasgow Haskell Compiler
#15938: Hadrian's recompilation check is extremely slow -------------------------------------+------------------------------------- Reporter: bgamari | Owner: (none) Type: bug | Status: new Priority: high | Milestone: 8.8.1 Component: Build System | Version: 8.6.2 (Hadrian) | Resolution: | Keywords: Operating System: Unknown/Multiple | Architecture: | Unknown/Multiple Type of failure: None/Unknown | Test Case: Blocked By: | Blocking: Related Tickets: | Differential Rev(s): Wiki Page: | -------------------------------------+------------------------------------- Changes (by snowleopard): * cc: NeilMitchell (added) Comment: Thank for reporting. 45 seconds of doing nothing sounds strange, I'm not sure how/why this happened. Is this something you can reliably reproduce by `Ctrl-C`'ing the full build in the middle of building `libraries/base`? Zero build currently takes around 7 seconds on my machine. Neil was optimistic that we'll be able to substantially improve this, so I'm tagging him too. -- Ticket URL: http://ghc.haskell.org/trac/ghc/ticket/15938#comment:3 GHC http://www.haskell.org/ghc/ The Glasgow Haskell Compiler
#15938: Hadrian's recompilation check is extremely slow -------------------------------------+------------------------------------- Reporter: bgamari | Owner: (none) Type: bug | Status: new Priority: high | Milestone: 8.8.1 Component: Build System | Version: 8.6.2 (Hadrian) | Resolution: | Keywords: Operating System: Unknown/Multiple | Architecture: | Unknown/Multiple Type of failure: None/Unknown | Test Case: Blocked By: | Blocking: Related Tickets: | Differential Rev(s): Wiki Page: | -------------------------------------+------------------------------------- Comment (by alpmestan): @snowleopard: Ben reported the following to me in private: - when re-running hadrian the second time with `-VVV`, Ben saw: {{{ | Building Stage1 libraries: binary, Cabal, ghc, ghc-boot, ghc-boot- th, ghc-heap, ghci, hpc, mtl, parsec, template-haskell, text, transformers, terminfo, array, base, bytestring, containers, deepseq, directory, filepath, ghc-compact, ghc-prim, haskeline, integer-gmp, pretty, process, rts, stm, time, xhtml, libiserv, unix | Building Stage1 programs : ghc, ghc-pkg, hsc2hs, unlit, hpc, ghc- iserv, runghc # _build/stage1/lib/package.conf.d/ghc-8.7.conf # _build/stage1/lib/package.conf.d/Cabal-2.4.0.1.conf # _build/stage1/lib/package.conf.d/ghci-8.7.conf # _build/stage2/bin/ghctags # _build/stage2/bin/haddock # _build/stage1/lib/package.conf.d/text-1.2.3.1.conf # _build/stage1/lib/package.conf.d/parsec-3.1.13.0.conf # _build/stage1/lib/bin/ghc-iserv # _build/stage1/bin/hsc2hs # _build/stage1/bin/ghc # _build/stage1/lib/package.conf.d/haskeline-0.7.4.3.conf # _build/stage1/lib/package.conf.d/libiserv-8.7.1.conf # _build/stage1/bin/ghc-pkg # _build/stage0/lib/package.conf.d/directory-1.3.1.5.conf }}} and it just pauses there for ~15 seconds before it finally starts issuing build commands. - using -j16 or -j1 doesn't seem to affect the "pause" time -- Ticket URL: http://ghc.haskell.org/trac/ghc/ticket/15938#comment:4 GHC http://www.haskell.org/ghc/ The Glasgow Haskell Compiler
#15938: Hadrian's recompilation check is extremely slow -------------------------------------+------------------------------------- Reporter: bgamari | Owner: (none) Type: bug | Status: new Priority: high | Milestone: 8.8.1 Component: Build System | Version: 8.6.2 (Hadrian) | Resolution: | Keywords: Operating System: Unknown/Multiple | Architecture: | Unknown/Multiple Type of failure: None/Unknown | Test Case: Blocked By: | Blocking: Related Tickets: | Differential Rev(s): Wiki Page: | -------------------------------------+------------------------------------- Changes (by RyanGlScott): * cc: RyanGlScott (added) -- Ticket URL: http://ghc.haskell.org/trac/ghc/ticket/15938#comment:5 GHC http://www.haskell.org/ghc/ The Glasgow Haskell Compiler
#15938: Hadrian's recompilation check is extremely slow -------------------------------------+------------------------------------- Reporter: bgamari | Owner: (none) Type: bug | Status: new Priority: high | Milestone: 8.8.1 Component: Build System | Version: 8.6.2 (Hadrian) | Resolution: | Keywords: Operating System: Unknown/Multiple | Architecture: | Unknown/Multiple Type of failure: None/Unknown | Test Case: Blocked By: | Blocking: Related Tickets: | Differential Rev(s): Wiki Page: | -------------------------------------+------------------------------------- Comment (by snowleopard): Aha, I see. One theory I have is that the cache oracles we added for various Cabal parsing actions [1] have not been recorded in the database on `Ctrl-C`, hence we need to rerun them. Perhaps, Shake saves these cached oracles only on successful completion of a build? [1] https://github.com/snowleopard/hadrian/pull/692 -- Ticket URL: http://ghc.haskell.org/trac/ghc/ticket/15938#comment:6 GHC http://www.haskell.org/ghc/ The Glasgow Haskell Compiler
#15938: Hadrian's recompilation check is extremely slow -------------------------------------+------------------------------------- Reporter: bgamari | Owner: (none) Type: bug | Status: new Priority: high | Milestone: 8.8.1 Component: Build System | Version: 8.6.2 (Hadrian) | Resolution: | Keywords: Operating System: Unknown/Multiple | Architecture: | Unknown/Multiple Type of failure: None/Unknown | Test Case: Blocked By: | Blocking: Related Tickets: | Differential Rev(s): Wiki Page: | -------------------------------------+------------------------------------- Changes (by harpocrates): * cc: harpocrates (added) -- Ticket URL: http://ghc.haskell.org/trac/ghc/ticket/15938#comment:7 GHC http://www.haskell.org/ghc/ The Glasgow Haskell Compiler
#15938: Hadrian's recompilation check is extremely slow -------------------------------------+------------------------------------- Reporter: bgamari | Owner: (none) Type: bug | Status: new Priority: high | Milestone: 8.8.1 Component: Build System | Version: 8.6.2 (Hadrian) | Resolution: | Keywords: Operating System: Unknown/Multiple | Architecture: | Unknown/Multiple Type of failure: None/Unknown | Test Case: Blocked By: | Blocking: Related Tickets: | Differential Rev(s): Wiki Page: | -------------------------------------+------------------------------------- Comment (by NeilMitchell): Shake records cached oracles immediately and even if the build fails (but not if the parsing of the metadata fails, as you might expect). I'd treat the pause and the slow rebuild as entirely separate issues, since they likely have different causes. Of these, slow rebuild is the easiest one to reproduce - generally you shouldn't be running any command line tools during a rebuild, and if you do, you failed to cache something properly. -- Ticket URL: http://ghc.haskell.org/trac/ghc/ticket/15938#comment:8 GHC http://www.haskell.org/ghc/ The Glasgow Haskell Compiler
#15938: Hadrian's recompilation check is extremely slow -------------------------------------+------------------------------------- Reporter: bgamari | Owner: (none) Type: bug | Status: new Priority: high | Milestone: 8.8.1 Component: Build System | Version: 8.6.2 (Hadrian) | Resolution: | Keywords: Operating System: Unknown/Multiple | Architecture: | Unknown/Multiple Type of failure: None/Unknown | Test Case: Blocked By: | Blocking: Related Tickets: | Differential Rev(s): Wiki Page: | -------------------------------------+------------------------------------- Comment (by tdammers): I'm trying to reproduce this, but can't seem to - I tried starting a fresh build, aborting it, and then restarting, but I'm not observing any unusual pauses. Do you have more specific reproduction steps? -- Ticket URL: http://ghc.haskell.org/trac/ghc/ticket/15938#comment:9 GHC http://www.haskell.org/ghc/ The Glasgow Haskell Compiler
#15938: Hadrian's recompilation check is extremely slow -------------------------------------+------------------------------------- Reporter: bgamari | Owner: (none) Type: bug | Status: new Priority: high | Milestone: 8.8.1 Component: Build System | Version: 8.6.2 (Hadrian) | Resolution: | Keywords: Operating System: Unknown/Multiple | Architecture: | Unknown/Multiple Type of failure: None/Unknown | Test Case: Blocked By: | Blocking: Related Tickets: | Differential Rev(s): Wiki Page: | -------------------------------------+------------------------------------- Comment (by bgamari): tdammers, how long did you let the build run for before aborting it? -- Ticket URL: http://ghc.haskell.org/trac/ghc/ticket/15938#comment:10 GHC http://www.haskell.org/ghc/ The Glasgow Haskell Compiler
#15938: Hadrian's recompilation check is extremely slow -------------------------------------+------------------------------------- Reporter: bgamari | Owner: (none) Type: bug | Status: new Priority: high | Milestone: 8.8.1 Component: Build System | Version: 8.6.2 (Hadrian) | Resolution: | Keywords: Operating System: Unknown/Multiple | Architecture: | Unknown/Multiple Type of failure: None/Unknown | Test Case: Blocked By: | Blocking: Related Tickets: | Differential Rev(s): Wiki Page: | -------------------------------------+------------------------------------- Comment (by bgamari): I quickly rebuilt Hadrian with profiling and reproduced this. I used `hadrian/build.cabal.sh +RTS -p` to start Hadrian in a half-built tree and Ctrl-C'd it as soon as it started producing output (which took roughly 30 seconds of wall clock time): {{{ $ hadrian/build.cabal.sh +RTS -p Up to date Up to date | Run Ghc FindHsDependencies Stage0: libraries/ghc-heap/GHC/Exts/Heap.hs (and 7 more) => _build/stage0/libraries/ghc-heap/.dependencies.mk | Remove file _build/stage0/libraries/ghc-heap/.dependencies.mk.bak | Run Ghc CompileHs Stage0: _build/stage0/libraries/ghc- heap/build/GHC/Exts/Heap/Constants.hs => _build/stage0/libraries/ghc- heap/build/GHC/Exts/Heap/Constants.o | Run Ghc CompileHs Stage0: libraries/ghc- heap/GHC/Exts/Heap/ClosureTypes.hs => _build/stage0/libraries/ghc- heap/build/GHC/Exts/Heap/ClosureTypes.o ^CshakeArgsWith 0.000s 0% Function shake 0.465s 1% Database read 0.072s 0% With database 0.001s 0% Running rules 31.903s 98% ========================= Total 32.442s 100% user interrupt }}} I will attach the profile in a moment. -- Ticket URL: http://ghc.haskell.org/trac/ghc/ticket/15938#comment:11 GHC http://www.haskell.org/ghc/ The Glasgow Haskell Compiler
#15938: Hadrian's recompilation check is extremely slow -------------------------------------+------------------------------------- Reporter: bgamari | Owner: (none) Type: bug | Status: new Priority: high | Milestone: 8.8.1 Component: Build System | Version: 8.6.2 (Hadrian) | Resolution: | Keywords: Operating System: Unknown/Multiple | Architecture: | Unknown/Multiple Type of failure: None/Unknown | Test Case: Blocked By: | Blocking: Related Tickets: | Differential Rev(s): Wiki Page: | -------------------------------------+------------------------------------- Changes (by bgamari): * Attachment "hadrian.prof.xz" added. Profile from the initialization phase of a Hadrian run on a half-built tree. Wall clock runtime was approximately 30 seconds. -- Ticket URL: http://ghc.haskell.org/trac/ghc/ticket/15938 GHC http://www.haskell.org/ghc/ The Glasgow Haskell Compiler
#15938: Hadrian's recompilation check is extremely slow -------------------------------------+------------------------------------- Reporter: bgamari | Owner: (none) Type: bug | Status: new Priority: high | Milestone: 8.8.1 Component: Build System | Version: 8.6.2 (Hadrian) | Resolution: | Keywords: Operating System: Unknown/Multiple | Architecture: | Unknown/Multiple Type of failure: None/Unknown | Test Case: Blocked By: | Blocking: Related Tickets: | Differential Rev(s): Wiki Page: | -------------------------------------+------------------------------------- Comment (by bgamari): Given how the cost center profile accounts for only around a third of the wall clock runtime, I reran with `+RTS -s`. This suggests that we are doing an absurd amount of GC: {{{ shakeArgsWith 0.000s 0% Function shake 0.460s 1% Database read 0.074s 0% With database 0.002s 0% Running rules 34.779s 98% ========================= Total 35.315s 100% user interrupt 51,232,883,504 bytes allocated in the heap 36,169,578,656 bytes copied during GC 141,089,464 bytes maximum residency (222 sample(s)) 800,072 bytes maximum slop 401 MB total memory in use (0 MB lost due to fragmentation) Tot time (elapsed) Avg pause Max pause Gen 0 36298 colls, 0 par 9.398s 9.311s 0.0003s 0.0021s Gen 1 222 colls, 0 par 11.252s 11.215s 0.0505s 0.1005s TASKS: 5 (1 bound, 4 peak workers (4 total), using -N1) SPARKS: 0 (0 converted, 0 overflowed, 0 dud, 0 GC'd, 0 fizzled) INIT time 0.001s ( 0.001s elapsed) MUT time 13.275s ( 14.804s elapsed) GC time 20.650s ( 20.526s elapsed) RP time 0.000s ( 0.000s elapsed) PROF time 0.000s ( 0.000s elapsed) EXIT time 0.001s ( 0.001s elapsed) Total time 33.926s ( 35.331s elapsed) Alloc rate 3,859,448,027 bytes per MUT second Productivity 39.1% of total user, 41.9% of total elapsed gc_alloc_block_sync: 0 whitehole_spin: 0 gen[0].sync: 0 gen[1].sync: 0 }}} -- Ticket URL: http://ghc.haskell.org/trac/ghc/ticket/15938#comment:12 GHC http://www.haskell.org/ghc/ The Glasgow Haskell Compiler
#15938: Hadrian's recompilation check is extremely slow -------------------------------------+------------------------------------- Reporter: bgamari | Owner: (none) Type: bug | Status: new Priority: high | Milestone: 8.8.1 Component: Build System | Version: 8.6.2 (Hadrian) | Resolution: | Keywords: Operating System: Unknown/Multiple | Architecture: | Unknown/Multiple Type of failure: None/Unknown | Test Case: Blocked By: | Blocking: Related Tickets: | Differential Rev(s): Wiki Page: | -------------------------------------+------------------------------------- Comment (by bgamari): Looking at the eventlog under threadscope suggests that we are hitting some very peculiar GC behavior. Hadrian is linked against the threaded, profiled, eventlog-enabled RTS but with `+RTS -N1`. From t=1 until around t=22 seconds we have very frequent GCs, with time roughly roughly evenly between major and minor collections. The productivity during this period is roughly 20%. Intriguingly, increasing the allocation area size to 30MB reduces the start-up GC time to around 1.5 seconds, with mutator time remaining around 12 seconds (a productivity of roughly 90%). By the way, I am bootstrapping and building Hadrian with GHC 8.4.3. -- Ticket URL: http://ghc.haskell.org/trac/ghc/ticket/15938#comment:13 GHC http://www.haskell.org/ghc/ The Glasgow Haskell Compiler
#15938: Hadrian's recompilation check is extremely slow -------------------------------------+------------------------------------- Reporter: bgamari | Owner: (none) Type: bug | Status: new Priority: high | Milestone: 8.8.1 Component: Build System | Version: 8.6.2 (Hadrian) | Resolution: | Keywords: Operating System: Unknown/Multiple | Architecture: | Unknown/Multiple Type of failure: None/Unknown | Test Case: Blocked By: | Blocking: Related Tickets: | Differential Rev(s): Wiki Page: | -------------------------------------+------------------------------------- Comment (by bgamari): Putting aside the GC strangeness for a bit, it still seems like Hadrian is rather slow to start. The 12 second mutator time during start-up is still rather sluggish. The profile shows the following: {{{ Thu Nov 29 17:59 2018 Time and Allocation Profiling Report (Final) hadrian +RTS -I0 -qg -l -s -p -A32M -RTS --lint --directory /home/ben/ghc/ghc total time = 16.60 secs (16598 ticks @ 1000 us, 1 processor) total alloc = 26,405,461,216 bytes (excludes profiling overheads) COST CENTRE MODULE SRC %time %alloc unionWith General.TypeMap src/General/TypeMap.hs:34:1-97 37.1 53.2 ?== Development.Shake.Internal.FilePattern src/Development/Shake/Internal/FilePattern.hs:(226,1)-(230,34) 32.3 10.4 split Data.List.Extra src/Data/List/Extra.hs:(569,1)-(571,48) 15.5 20.6 getUserRuleInternal Development.Shake.Internal.Core.Rules src/Development/Shake/Internal/Core/Rules.hs:(62,1)-(75,48) 3.1 2.2 foldr Data.ByteString.UTF8 Data/ByteString/UTF8.hs:(171,1)-(173,40) 2.6 4.1 defaultRuleFile Development.Shake.Internal.Rules.File src/Development/Shake/Internal/Rules/File.hs:(191,1)-(194,96) 1.6 0.0 decode Data.ByteString.UTF8 Data/ByteString/UTF8.hs:(68,1)-(124,32) 1.4 5.4 &%> Development.Shake.Internal.Rules.Files src/Development/Shake/Internal/Rules/Files.hs:(163,1)-(180,42) 1.1 0.7 }}} Is this what you would expect during start-up, ndmitchell? -- Ticket URL: http://ghc.haskell.org/trac/ghc/ticket/15938#comment:14 GHC http://www.haskell.org/ghc/ The Glasgow Haskell Compiler
#15938: Hadrian's recompilation check is extremely slow -------------------------------------+------------------------------------- Reporter: bgamari | Owner: (none) Type: bug | Status: new Priority: high | Milestone: 8.8.1 Component: Build System | Version: 8.6.2 (Hadrian) | Resolution: | Keywords: Operating System: Unknown/Multiple | Architecture: | Unknown/Multiple Type of failure: None/Unknown | Test Case: Blocked By: | Blocking: Related Tickets: | Differential Rev(s): Wiki Page: | -------------------------------------+------------------------------------- Comment (by snowleopard): Thanks for investigating, Ben! `Data.List.Extra.split` is used in a few places for `FilePattern` matching in `Development.Shake.Internal.FilePattern`, so I'd say this is consistent with the rest of the profiling report. We do seem to spend a large part of the startup time on various string manipulation. -- Ticket URL: http://ghc.haskell.org/trac/ghc/ticket/15938#comment:15 GHC http://www.haskell.org/ghc/ The Glasgow Haskell Compiler
#15938: Hadrian's recompilation check is extremely slow -------------------------------------+------------------------------------- Reporter: bgamari | Owner: (none) Type: bug | Status: new Priority: high | Milestone: 8.8.1 Component: Build System | Version: 8.6.2 (Hadrian) | Resolution: | Keywords: Operating System: Unknown/Multiple | Architecture: | Unknown/Multiple Type of failure: None/Unknown | Test Case: Blocked By: | Blocking: Related Tickets: | Differential Rev(s): Wiki Page: | -------------------------------------+------------------------------------- Comment (by bgamari): Hmm, if I'm not mistake the problem gets worse the farther into the build you get. For instance, I let the build continue and interrupted it at what I would guess is the 50% mark (while building `libraries/pretty`). Restarting it takes now around 40 seconds before any output is produced. The profile looks somewhat similar to the previous profiles, {{{ Thu Nov 29 18:32 2018 Time and Allocation Profiling Report (Final) hadrian +RTS -I0 -qg -l -s -p -A32M -RTS --lint --directory /home/ben/ghc/ghc total time = 39.23 secs (39231 ticks @ 1000 us, 1 processor) total alloc = 51,375,453,360 bytes (excludes profiling overheads) COST CENTRE MODULE SRC %time %alloc ?== Development.Shake.Internal.FilePattern src/Development/Shake/Internal/FilePattern.hs:(226,1)-(230,34) 34.4 15.8 split Data.List.Extra src/Data/List/Extra.hs:(569,1)-(571,48) 18.0 24.2 unionWith General.TypeMap src/General/TypeMap.hs:34:1-97 17.6 27.4 foldr Data.ByteString.UTF8 Data/ByteString/UTF8.hs:(171,1)-(173,40) 4.7 7.5 getUserRuleInternal Development.Shake.Internal.Core.Rules src/Development/Shake/Internal/Core/Rules.hs:(62,1)-(75,48) 3.4 2.3 decode Data.ByteString.UTF8 Data/ByteString/UTF8.hs:(68,1)-(124,32) 2.4 10.1 catch_ Control.Exception.Extra src/Control/Exception/Extra.hs:106:1-32 2.0 1.7 &%> Development.Shake.Internal.Rules.Files src/Development/Shake/Internal/Rules/Files.hs:(163,1)-(180,42) 1.8 1.3 firstJustM Control.Monad.Extra src/Control/Monad/Extra.hs:(243,1)-(244,69) 1.7 1.3 defaultRuleFile Development.Shake.Internal.Rules.File src/Development/Shake/Internal/Rules/File.hs:(191,1)-(194,96) 1.2 0.0 hashPtrWithSalt Data.Hashable.Class Data/Hashable/Class.hs:(723,1)-(725,23) 1.1 0.0 }}} For what it's worth, a very significant fraction of the profile weight comes from: {{{ packageRules Rules src/Rules.hs:(88,1)-(123,46) 4045 0 0.0 0.0 62.5 58.3 compilePackage Rules.Compile src/Rules/Compile.hs:(13,1)-(36,77) 4046 0 0.0 0.0 61.4 57.4 %> Development.Shake.Internal.Rules.File src/Development/Shake/Internal/Rules/File.hs:566:1-143 4047 0 0.3 0.0 13.4 8.3 ?== Development.Shake.Internal.FilePattern src/Development/Shake/Internal/FilePattern.hs:(226,1)-(230,34) 4053 0 8.0 1.2 13.1 8.3 split Data.List.Extra src/Data/List/Extra.hs:(569,1)-(571,48) 4054 78480846 5.1 7.1 5.1 7.1 shakeOpenDatabase Development.Shake.Database src/Development/Shake/Database.hs:(58,1)-(69,24) 4051 0 0.0 0.0 0.0 0.0 open Development.Shake.Internal.Core.Run src/Development/Shake/Internal/Core/Run.hs:(73,1)-(81,23) 4052 0 0.0 0.0 0.0 0.0 &%> Development.Shake.Internal.Rules.Files src/Development/Shake/Internal/Rules/Files.hs:(163,1)-(180,42) 4055 0 1.8 1.3 48.1 49.1 ?== Development.Shake.Internal.FilePattern src/Development/Shake/Internal/FilePattern.hs:(226,1)-(230,34) 4062 2225801 25.6 14.2 37.8 30.3 split Data.List.Extra src/Data/List/Extra.hs:(569,1)-(571,48) 4063 184314560 12.1 16.0 12.1 16.0 isRelativePattern Development.Shake.Internal.FilePattern src/Development/Shake/Internal/FilePattern.hs:(152,1)-(155,27) 12746 2225801 0.0 0.0 0.0 0.0 fileNameToString Development.Shake.Internal.FileName src/Development/Shake/Internal/FileName.hs:38:1-55 12747 0 0.1 0.0 8.0 17.5 fileNameToByteString Development.Shake.Internal.FileName src/Development/Shake/Internal/FileName.hs:41:1-37 12748 2225801 0.0 0.0 0.0 0.0 toString Data.ByteString.UTF8 Data/ByteString/UTF8.hs:53:1-29 12750 2225801 0.1 0.0 7.9 17.5 foldr Data.ByteString.UTF8 Data/ByteString/UTF8.hs:(171,1)-(173,40) 12751 40082494 4.7 7.5 7.9 17.5 uncons Data.ByteString.UTF8 Data/ByteString/UTF8.hs:(166,1)-(167,38) 12752 40082494 0.8 0.0 3.1 10.0 decode Data.ByteString.UTF8 Data/ByteString/UTF8.hs:(68,1)-(124,32) 12753 40082494 2.3 10.0 2.3 10.0 }}} -- Ticket URL: http://ghc.haskell.org/trac/ghc/ticket/15938#comment:16 GHC http://www.haskell.org/ghc/ The Glasgow Haskell Compiler
#15938: Hadrian's recompilation check is extremely slow -------------------------------------+------------------------------------- Reporter: bgamari | Owner: (none) Type: bug | Status: new Priority: high | Milestone: 8.8.1 Component: Build System | Version: 8.6.2 (Hadrian) | Resolution: | Keywords: Operating System: Unknown/Multiple | Architecture: | Unknown/Multiple Type of failure: None/Unknown | Test Case: Blocked By: | Blocking: Related Tickets: | Differential Rev(s): Wiki Page: | -------------------------------------+------------------------------------- Comment (by bgamari): I suspect to really solve this changes in Shake will be necessary. On quickly looking at the implementation a few things stood out: * paths are split on the directory separator every time we attempt to match it against a `FilePattern`. This is apparently how we end up with 180 million calls to `split`. * paths are represented as `ByteString`. Given the storage overhead and pinned nature of `ByteString`, I suspect there is a small amount of money on the table here -- Ticket URL: http://ghc.haskell.org/trac/ghc/ticket/15938#comment:17 GHC http://www.haskell.org/ghc/ The Glasgow Haskell Compiler
#15938: Hadrian's recompilation check is extremely slow -------------------------------------+------------------------------------- Reporter: bgamari | Owner: (none) Type: bug | Status: new Priority: high | Milestone: 8.8.1 Component: Build System | Version: 8.6.2 (Hadrian) | Resolution: | Keywords: Operating System: Unknown/Multiple | Architecture: | Unknown/Multiple Type of failure: None/Unknown | Test Case: Blocked By: | Blocking: Related Tickets: | Differential Rev(s): Wiki Page: | -------------------------------------+------------------------------------- Comment (by bgamari): Thankfully, while things get quite bad in half-built trees (as seen in comment:16), they appear to get better once the build has finished (as suggested by mpickering in comment:1). After finishing the build the no-op rebuild time is around 15 seconds. Still bad, but at least it's not 45 seconds -- Ticket URL: http://ghc.haskell.org/trac/ghc/ticket/15938#comment:18 GHC http://www.haskell.org/ghc/ The Glasgow Haskell Compiler
#15938: Hadrian's recompilation check is extremely slow -------------------------------------+------------------------------------- Reporter: bgamari | Owner: (none) Type: bug | Status: new Priority: high | Milestone: 8.8.1 Component: Build System | Version: 8.6.2 (Hadrian) | Resolution: | Keywords: Operating System: Unknown/Multiple | Architecture: | Unknown/Multiple Type of failure: None/Unknown | Test Case: Blocked By: | Blocking: Related Tickets: | Differential Rev(s): Wiki Page: | -------------------------------------+------------------------------------- Comment (by bgamari): Anyways, I should move on to other things. Tobias will pick it up from here tomorrow. -- Ticket URL: http://ghc.haskell.org/trac/ghc/ticket/15938#comment:19 GHC http://www.haskell.org/ghc/ The Glasgow Haskell Compiler
#15938: Hadrian's recompilation check is extremely slow -------------------------------------+------------------------------------- Reporter: bgamari | Owner: (none) Type: bug | Status: new Priority: high | Milestone: 8.8.1 Component: Build System | Version: 8.6.2 (Hadrian) | Resolution: | Keywords: Operating System: Unknown/Multiple | Architecture: | Unknown/Multiple Type of failure: None/Unknown | Test Case: Blocked By: | Blocking: Related Tickets: | Differential Rev(s): Wiki Page: | -------------------------------------+------------------------------------- Comment (by tdammers): Replying to [comment:10 bgamari]:
tdammers, how long did you let the build run for before aborting it?
I made multiple attempts from a freshly git-cleaned tree, aborting at various points during library compilation. A rebuild after any of these started to produce output within under 2 seconds, and started to perform actual compilation within 3 seconds. There is a significant delay (on the order of ~5-7 seconds) on the "Configure package 'ghc'" step, but nowhere near the reported 15-45 seconds. -- Ticket URL: http://ghc.haskell.org/trac/ghc/ticket/15938#comment:20 GHC http://www.haskell.org/ghc/ The Glasgow Haskell Compiler
#15938: Hadrian's recompilation check is extremely slow -------------------------------------+------------------------------------- Reporter: bgamari | Owner: (none) Type: bug | Status: new Priority: high | Milestone: 8.8.1 Component: Build System | Version: 8.6.2 (Hadrian) | Resolution: | Keywords: Operating System: Unknown/Multiple | Architecture: | Unknown/Multiple Type of failure: None/Unknown | Test Case: Blocked By: | Blocking: Related Tickets: | Differential Rev(s): Wiki Page: | -------------------------------------+------------------------------------- Comment (by tdammers): Actually, I just realized that you are using the cabal build flavor (`build.cabal.sh`), whereas I tried to reproduce with the vanilla one (`build.sh`). I'll try again with cabal. -- Ticket URL: http://ghc.haskell.org/trac/ghc/ticket/15938#comment:21 GHC http://www.haskell.org/ghc/ The Glasgow Haskell Compiler
#15938: Hadrian's recompilation check is extremely slow -------------------------------------+------------------------------------- Reporter: bgamari | Owner: (none) Type: bug | Status: new Priority: high | Milestone: 8.8.1 Component: Build System | Version: 8.6.2 (Hadrian) | Resolution: | Keywords: Operating System: Unknown/Multiple | Architecture: | Unknown/Multiple Type of failure: None/Unknown | Test Case: Blocked By: | Blocking: Related Tickets: | Differential Rev(s): Wiki Page: | -------------------------------------+------------------------------------- Comment (by tdammers): Aha! `build.cabal.sh` does indeed show a big pause between {{{Up to date}}} and the first {{{| Run}}} output (~25 seconds). -- Ticket URL: http://ghc.haskell.org/trac/ghc/ticket/15938#comment:22 GHC http://www.haskell.org/ghc/ The Glasgow Haskell Compiler
#15938: Hadrian's recompilation check is extremely slow -------------------------------------+------------------------------------- Reporter: bgamari | Owner: (none) Type: bug | Status: new Priority: high | Milestone: 8.8.1 Component: Build System | Version: 8.6.2 (Hadrian) | Resolution: | Keywords: Operating System: Unknown/Multiple | Architecture: | Unknown/Multiple Type of failure: None/Unknown | Test Case: Blocked By: | Blocking: Related Tickets: | Differential Rev(s): Wiki Page: | -------------------------------------+------------------------------------- Comment (by NeilMitchell): If you are spending all the time in file pattern matching, I'd say that's a strong suggestion you are doing a lot more file pattern matching that is desirable. Yes, it could be faster, but in a normal build system I'd expect it to be in the weeds - less than 1%. The real culprit though is almost certainly TypeMap.unionWith, which corresponds to adding a user rule during startup (e.g. with %>). In a normal build system I'd expect perhaps 100 user rules. If you want to match on a million rules you have, you put them in a dictionary yourself and add a predicate rule. My guess is Hadrian probably has a list and unrolls it into Shake one at a time. Once you have a huge number of user rules, and match on each linearly, you become quadratic in a huge number. -- Ticket URL: http://ghc.haskell.org/trac/ghc/ticket/15938#comment:23 GHC http://www.haskell.org/ghc/ The Glasgow Haskell Compiler
#15938: Hadrian's recompilation check is extremely slow -------------------------------------+------------------------------------- Reporter: bgamari | Owner: (none) Type: bug | Status: new Priority: high | Milestone: 8.8.1 Component: Build System | Version: 8.6.2 (Hadrian) | Resolution: | Keywords: Operating System: Unknown/Multiple | Architecture: | Unknown/Multiple Type of failure: None/Unknown | Test Case: Blocked By: | Blocking: Related Tickets: | Differential Rev(s): Wiki Page: | -------------------------------------+------------------------------------- Comment (by snowleopard): I think I know a way to reduce the number of file pattern matchings in Hadrian. Currently we generate build rules for each build context and there are hundreds of contexts, e.g. see generation of `Rules.Compile.compilePackage`: https://github.com/ghc/ghc/blob/master/hadrian/src/Rules.hs#L108 Instead, we should generate just one build rule per logical target and parse various context parameters from the path, as implemented in `libraryRules`: https://github.com/ghc/ghc/blob/master/hadrian/src/Rules/Library.hs#L22 We need to rewrite all build rules in the same manner. This will essentially replace hundred-long linear chains of file pattern matchings with a single matching and subsequent parsing. This is an obvious optimisation, but requires a good understanding of Hadrian internals. I am happy to volunteer to implement this, but I'm unlikely to find time until the end of teaching term in the university (end of December). If anyone has a chance to do this earlier, please go ahead, I can review a patch. P.S.: I still have no idea where the long pauses after `Ctrl-C`-ing come from. -- Ticket URL: http://ghc.haskell.org/trac/ghc/ticket/15938#comment:24 GHC http://www.haskell.org/ghc/ The Glasgow Haskell Compiler
#15938: Hadrian's recompilation check is extremely slow -------------------------------------+------------------------------------- Reporter: bgamari | Owner: (none) Type: bug | Status: new Priority: high | Milestone: 8.8.1 Component: Build System | Version: 8.6.2 (Hadrian) | Resolution: | Keywords: Operating System: Unknown/Multiple | Architecture: | Unknown/Multiple Type of failure: None/Unknown | Test Case: Blocked By: | Blocking: Related Tickets: | Differential Rev(s): Wiki Page: | -------------------------------------+------------------------------------- Comment (by tdammers): `+RTS -s` output when starting on a half-built tree; kept hadrian running until the first proper compilations happen ("Run Ghc CompileHs ..."): {{{ 16,130,616,376 bytes allocated in the heap 1,080,660,392 bytes copied during GC 149,548,072 bytes maximum residency (12 sample(s)) 1,189,912 bytes maximum slop 339 MB total memory in use (0 MB lost due to fragmentation) Tot time (elapsed) Avg pause Max pause Gen 0 14677 colls, 0 par 0.952s 1.016s 0.0001s 0.0022s Gen 1 12 colls, 0 par 0.532s 0.640s 0.0533s 0.1704s TASKS: 5 (1 bound, 4 peak workers (4 total), using -N1) SPARKS: 0 (0 converted, 0 overflowed, 0 dud, 0 GC'd, 0 fizzled) INIT time 0.000s ( 0.000s elapsed) MUT time 9.544s ( 13.735s elapsed) GC time 1.484s ( 1.656s elapsed) EXIT time 0.000s ( 0.009s elapsed) Total time 11.028s ( 15.400s elapsed) Alloc rate 1,690,131,640 bytes per MUT second Productivity 86.5% of total user, 89.2% of total elapsed }}} -- Ticket URL: http://ghc.haskell.org/trac/ghc/ticket/15938#comment:25 GHC http://www.haskell.org/ghc/ The Glasgow Haskell Compiler
#15938: Hadrian's recompilation check is extremely slow -------------------------------------+------------------------------------- Reporter: bgamari | Owner: alpmestan Type: bug | Status: new Priority: high | Milestone: 8.8.1 Component: Build System | Version: 8.6.2 (Hadrian) | Resolution: | Keywords: Operating System: Unknown/Multiple | Architecture: | Unknown/Multiple Type of failure: None/Unknown | Test Case: Blocked By: | Blocking: Related Tickets: | Differential Rev(s): Wiki Page: | -------------------------------------+------------------------------------- Changes (by alpmestan): * owner: (none) => alpmestan -- Ticket URL: http://ghc.haskell.org/trac/ghc/ticket/15938#comment:26 GHC http://www.haskell.org/ghc/ The Glasgow Haskell Compiler
#15938: Hadrian's recompilation check is extremely slow -------------------------------------+------------------------------------- Reporter: bgamari | Owner: alpmestan Type: bug | Status: new Priority: high | Milestone: 8.8.1 Component: Build System | Version: 8.6.2 (Hadrian) | Resolution: | Keywords: Operating System: Unknown/Multiple | Architecture: | Unknown/Multiple Type of failure: None/Unknown | Test Case: Blocked By: | Blocking: Related Tickets: | Differential Rev(s): Wiki Page: | -------------------------------------+------------------------------------- Comment (by alpmestan): I'm looking into Andrey's suggestion (which I have been meaning to do for a while, ever since we implemented the "new" `Rules.Library` module). I did some profiling myself and the picture becomes even clearer if we hide shake from it: {{{ COST CENTRE MODULE SRC %time %alloc compilePackage Rules.Compile src/Rules/Compile.hs:(13,1)-(36,77) 49.2 78.4 split Data.List.Extra src/Data/List/Extra.hs:(569,1)-(571,48) 41.7 8.6 modifyVar Control.Concurrent.Extra src/Control/Concurrent/Extra.hs:191:1-36 2.3 1.1 buildPackageDependencies Rules.Dependencies src/Rules/Dependencies.hs:(15,1)-(35,52) 1.5 2.9 generatePackageCode Rules.Generate src/Rules/Generate.hs:(102,1)-(150,49) 0.5 1.6 configurePackage Rules.Register src/Rules/Register.hs:(24,1)-(27,38) 0.4 1.5 }}} While Shake itself might benefit from some optimisations for those paths manipulations that are involved here, clearly our number one problem is the enumeration of contexts for `compilePackage` that we do in `Rules.hs`, as you pointed out @snowleopard. I'm going to migrate `Rules.Compile` over to the enumeration-less, parsing-based style the best I can and report back. -- Ticket URL: http://ghc.haskell.org/trac/ghc/ticket/15938#comment:27 GHC http://www.haskell.org/ghc/ The Glasgow Haskell Compiler
#15938: Hadrian's recompilation check is extremely slow -------------------------------------+------------------------------------- Reporter: bgamari | Owner: alpmestan Type: bug | Status: new Priority: high | Milestone: 8.8.1 Component: Build System | Version: 8.6.2 (Hadrian) | Resolution: | Keywords: Operating System: Unknown/Multiple | Architecture: | Unknown/Multiple Type of failure: None/Unknown | Test Case: Blocked By: | Blocking: Related Tickets: | Differential Rev(s): Wiki Page: | -------------------------------------+------------------------------------- Comment (by snowleopard): @alpmestan Many thanks for checking my conjecture and going ahead with the implementation! I hope this will bring our zero build times closer to zero :) -- Ticket URL: http://ghc.haskell.org/trac/ghc/ticket/15938#comment:28 GHC http://www.haskell.org/ghc/ The Glasgow Haskell Compiler
#15938: Hadrian's recompilation check is extremely slow -------------------------------------+------------------------------------- Reporter: bgamari | Owner: alpmestan Type: bug | Status: new Priority: high | Milestone: 8.8.1 Component: Build System | Version: 8.6.2 (Hadrian) | Resolution: | Keywords: Operating System: Unknown/Multiple | Architecture: | Unknown/Multiple Type of failure: None/Unknown | Test Case: Blocked By: | Blocking: Related Tickets: | Differential Rev(s): Wiki Page: | -------------------------------------+------------------------------------- Comment (by NeilMitchell): I just added a feature to Shake HEAD when running in diagnostic mode {{{-VVV}}} prints out the number of actions, rules and user rules: {{{ % Number of actions = 0 % Number of builtin rules = 20 [OracleQ Generator,OracleQ ModuleFiles,OracleQ PackageConfigurationKey,FilesQ,FileQ,GetDirectoryFilesQ,OracleQ WindowsPath,OracleQ DirectoryContents,OracleQ KeyValue,OracleQ LookupInPath,OracleQ KeyValues,OracleQ ContextDataKey,DoesDirectoryExistQ,AlwaysRerunQ,GetDirectoryContentsQ,OracleQ (ArgsHash Context Builder),DoesFileExistQ,GetDirectoryDirsQ,OracleQ PackageDataKey,GetEnvQ] % Number of user rule types = 2 % Number of user rules = 36790 }}} The number of user rules at 36K is way higher than Shake can deal with nicely. I see one for every directory (e.g. {{{_build/stage3/libraries/containers/build/cmm}}}, {{{_build/stage3/libraries/containers/build/c}}}, {{{_build/stage3/libraries/containers/build/s}}}) cross product with every extension (e.g. {{{.l_o}}}, {{{.thr_debug_o}}}, {{{.thr_dyn_o}}}). -- Ticket URL: http://ghc.haskell.org/trac/ghc/ticket/15938#comment:29 GHC http://www.haskell.org/ghc/ The Glasgow Haskell Compiler
#15938: Hadrian's recompilation check is extremely slow -------------------------------------+------------------------------------- Reporter: bgamari | Owner: alpmestan Type: bug | Status: new Priority: high | Milestone: 8.8.1 Component: Build System | Version: 8.6.2 (Hadrian) | Resolution: | Keywords: Operating System: Unknown/Multiple | Architecture: | Unknown/Multiple Type of failure: None/Unknown | Test Case: Blocked By: | Blocking: Related Tickets: | Differential Rev(s): Wiki Page: | -------------------------------------+------------------------------------- Comment (by NeilMitchell): To measure the performance impact of those rules, I did: * {{{--no-build}}} which takes 0.31s * {{{--no-build -VVV}}} which forces it to count (and thus create) all the rules which takes 9.10s So creating the rules takes about 9s on my machine, and is suggestive of the zero-build performance we would gain. -- Ticket URL: http://ghc.haskell.org/trac/ghc/ticket/15938#comment:30 GHC http://www.haskell.org/ghc/ The Glasgow Haskell Compiler
#15938: Hadrian's recompilation check is extremely slow -------------------------------------+------------------------------------- Reporter: bgamari | Owner: alpmestan Type: bug | Status: new Priority: high | Milestone: 8.8.1 Component: Build System | Version: 8.6.2 (Hadrian) | Resolution: | Keywords: Operating System: Unknown/Multiple | Architecture: | Unknown/Multiple Type of failure: None/Unknown | Test Case: Blocked By: | Blocking: Related Tickets: | Differential Rev(s): Wiki Page: | -------------------------------------+------------------------------------- Comment (by snowleopard): Thanks Neil -- cool stats :) I believe with Alp's refactoring we'll go below 100 rules for the whole Hadrian. -- Ticket URL: http://ghc.haskell.org/trac/ghc/ticket/15938#comment:31 GHC http://www.haskell.org/ghc/ The Glasgow Haskell Compiler
#15938: Hadrian's recompilation check is extremely slow -------------------------------------+------------------------------------- Reporter: bgamari | Owner: alpmestan Type: bug | Status: new Priority: high | Milestone: 8.8.1 Component: Build System | Version: 8.6.2 (Hadrian) | Resolution: | Keywords: Operating System: Unknown/Multiple | Architecture: | Unknown/Multiple Type of failure: None/Unknown | Test Case: Blocked By: | Blocking: Related Tickets: | Differential Rev(s): Wiki Page: | -------------------------------------+------------------------------------- Comment (by alpmestan): I'm hoping I'll be able to report some numbers by tonight. I have most of the parsing and "infrastructure" sorted out already. This will require some refactoring I think (e.g right now, to go straight to the point, I'm importing `Rules.Library` from `Rules.Compile` just to be able to reuse some of my parsers) but the performance improvement should be there. -- Ticket URL: http://ghc.haskell.org/trac/ghc/ticket/15938#comment:32 GHC http://www.haskell.org/ghc/ The Glasgow Haskell Compiler
#15938: Hadrian's recompilation check is extremely slow -------------------------------------+------------------------------------- Reporter: bgamari | Owner: alpmestan Type: bug | Status: new Priority: high | Milestone: 8.8.1 Component: Build System | Version: 8.6.2 (Hadrian) | Resolution: | Keywords: Operating System: Unknown/Multiple | Architecture: | Unknown/Multiple Type of failure: None/Unknown | Test Case: Blocked By: | Blocking: Related Tickets: | Differential Rev(s): Wiki Page: | -------------------------------------+------------------------------------- Comment (by NeilMitchell): I investigated further, the issue is that adding a user rule match is ''O(n)'', so adding ''n'' rules is ''O(n^2^)''. I have raised a ticket to fix that at https://github.com/ndmitchell/shake/issues/632, so in time the construction in Hadrian might become efficient. But I still recommend fixing it since it's better to not enumerate all the possible paths in advance. -- Ticket URL: http://ghc.haskell.org/trac/ghc/ticket/15938#comment:33 GHC http://www.haskell.org/ghc/ The Glasgow Haskell Compiler
#15938: Hadrian's recompilation check is extremely slow -------------------------------------+------------------------------------- Reporter: bgamari | Owner: alpmestan Type: bug | Status: new Priority: high | Milestone: 8.8.1 Component: Build System | Version: 8.6.2 (Hadrian) | Resolution: | Keywords: Operating System: Unknown/Multiple | Architecture: | Unknown/Multiple Type of failure: None/Unknown | Test Case: Blocked By: | Blocking: Related Tickets: | Differential Rev(s): Wiki Page: | -------------------------------------+------------------------------------- Comment (by NeilMitchell): I actually managed to eliminate the ''O(n^2^)'' much more easily than expected. Now both builds take the same 0.31s. Having many rules is still going to be expensive for every file you match, but the cost is now not prohibitive. I'd still encourage the refactoring Alp is doing. I'll release a new Shake later today. -- Ticket URL: http://ghc.haskell.org/trac/ghc/ticket/15938#comment:34 GHC http://www.haskell.org/ghc/ The Glasgow Haskell Compiler
#15938: Hadrian's recompilation check is extremely slow -------------------------------------+------------------------------------- Reporter: bgamari | Owner: alpmestan Type: bug | Status: patch Priority: high | Milestone: 8.8.1 Component: Build System | Version: 8.6.2 (Hadrian) | Resolution: | Keywords: Operating System: Unknown/Multiple | Architecture: | Unknown/Multiple Type of failure: None/Unknown | Test Case: Blocked By: | Blocking: Related Tickets: | Differential Rev(s): Phab:D5412 Wiki Page: | -------------------------------------+------------------------------------- Changes (by alpmestan): * status: new => patch * differential: => Phab:D5412 Comment: Got a patch up at https://phabricator.haskell.org/D5412. This cuts the pauses quite significantly, as expected. From 45-60s down to <5s, when resuming the build from a similar point. With Neil's shake changes mentionned above (which I have not tried yet), I'm confident we won't be seeing those pauses again before quite some time. The next bottleneck seems to be our program lookup in `Rules.Program.buildProgram`. We're also still doing a similarly "big" (not as big as the `compilePackage` one that my patch fixes) listing of contexts and generation of rules in `Rules.hs`, see `vanillaContexts`. Finally, my patch does require to lookup the `Package` from its `pkgPath` that we parse from the file path, but at least it's not at rule generation time. -- Ticket URL: http://ghc.haskell.org/trac/ghc/ticket/15938#comment:35 GHC http://www.haskell.org/ghc/ The Glasgow Haskell Compiler
#15938: Hadrian's recompilation check is extremely slow -------------------------------------+------------------------------------- Reporter: bgamari | Owner: alpmestan Type: bug | Status: patch Priority: high | Milestone: 8.8.1 Component: Build System | Version: 8.6.2 (Hadrian) | Resolution: | Keywords: Operating System: Unknown/Multiple | Architecture: | Unknown/Multiple Type of failure: None/Unknown | Test Case: Blocked By: | Blocking: Related Tickets: | Differential Rev(s): Phab:D5412 Wiki Page: | -------------------------------------+------------------------------------- Comment (by alpmestan): I ran a (profiled) hadrian build with shake `0.17.3` _and_ [https://phabricator.haskell.org/D5412 D5412], stopped it while hadrian was building `_build/stage1/libraries/base/`, resumed it and killed the program one I saw the first `| Run [...]` appear. I excluded all profiling symbols but the ones from hadrian itself (and only toplevel functions), and here is what the top of the profile looks like for that last short run I mentionned: {{{ Wed Dec 5 12:38 2018 Time and Allocation Profiling Report (Final) hadrian +RTS -I0 -qg -p -RTS --lint --directory /home/alp/WT /ghc-landing -j8 total time = 1.96 secs (7280 ticks @ 1000 us, 8 processors) total alloc = 4,152,119,656 bytes (excludes profiling overheads) COST CENTRE MODULE SRC %time %alloc buildProgram Rules.Program src/Rules/Program.hs:(19,1)-(73,51) 39.9 43.4 generatePackageCode Rules.Generate src/Rules/Generate.hs:(102,1)-(150,49) 6.1 2.9 buildPackageDependencies Rules.Dependencies src/Rules/Dependencies.hs:(15,1)-(35,52) 5.5 3.1 libraryObjects Rules.Library src/Rules/Library.hs:(113,1)-(127,67) 5.3 3.2 textFileOracle Hadrian.Oracles.TextFile src/Hadrian/Oracles/TextFile.hs:(88,1)-(100,83) 4.9 1.6 configurePackage Rules.Register src/Rules/Register.hs:(24,1)-(27,38) 3.2 1.7 argsHashOracle Hadrian.Oracles.ArgsHash src/Hadrian/Oracles/ArgsHash.hs:(47,1)-(51,36) 2.2 1.9 readContextData Hadrian.Oracles.Cabal src/Hadrian/Oracles/Cabal.hs:34:1-44 2.2 2.4 get Hadrian.Oracles.Cabal.Type src/Hadrian/Oracles/Cabal/Type.hs:43:15-20 2.2 1.5 ? Hadrian.Expression src/Hadrian/Expression.hs:(74,1)-(76,30) 1.7 2.1 unifyPath Hadrian.Utilities src/Hadrian/Utilities.hs:132:1-36 1.7 3.2 main Main src/Main.hs:(20,1)-(58,65) 1.4 3.8 == Hadrian.Oracles.TextFile src/Hadrian/Oracles/TextFile.hs:70:23-24 1.2 0.0 readPackageData Hadrian.Oracles.Cabal src/Hadrian/Oracles/Cabal.hs:28:1-44 1.1 0.9 lookupValue Hadrian.Oracles.TextFile src/Hadrian/Oracles/TextFile.hs:30:1-55 1.1 1.7 <> Hadrian.Expression src/Hadrian/Expression.hs:35:5-46 0.9 1.1 -/- Hadrian.Utilities src/Hadrian/Utilities.hs:(136,1)-(139,34) 0.8 2.4 input Hadrian.Expression src/Hadrian/Expression.hs:134:1-35 0.6 1.2 rtsPackageArgs Settings.Packages src/Settings/Packages.hs:(170,1)-(301,73) 0.4 1.0 mappend Hadrian.Expression src/Hadrian/Expression.hs:40:5-18 0.4 1.1 cabalOracle Hadrian.Oracles.Cabal.Rules src/Hadrian/Oracles/Cabal/Rules.hs:(38,1)-(60,58) 0.3 1.2 get Hadrian.Oracles.ArgsHash src/Hadrian/Oracles/ArgsHash.hs:41:15-20 0.2 2.2 }}} `buildProgram` stands out, as we seem to be spending more than a third of our time there. Everything else looks perfectly reasonable. I will give a very quick shot at trying to understand why we spend so much time in `buildProgram`, and if I do understand and see a way to cut this down, I'll write a patch, otherwise we can probably work with few-seconds pauses for now. -- Ticket URL: http://ghc.haskell.org/trac/ghc/ticket/15938#comment:36 GHC http://www.haskell.org/ghc/ The Glasgow Haskell Compiler
#15938: Hadrian's recompilation check is extremely slow
-------------------------------------+-------------------------------------
Reporter: bgamari | Owner: alpmestan
Type: bug | Status: patch
Priority: high | Milestone: 8.8.1
Component: Build System | Version: 8.6.2
(Hadrian) |
Resolution: | Keywords:
Operating System: Unknown/Multiple | Architecture:
| Unknown/Multiple
Type of failure: None/Unknown | Test Case:
Blocked By: | Blocking:
Related Tickets: | Differential Rev(s): Phab:D5412
Wiki Page: |
-------------------------------------+-------------------------------------
Comment (by Alp Mestanogullari
#15938: Hadrian's recompilation check is extremely slow -------------------------------------+------------------------------------- Reporter: bgamari | Owner: alpmestan Type: bug | Status: patch Priority: high | Milestone: 8.8.1 Component: Build System | Version: 8.6.2 (Hadrian) | Resolution: | Keywords: Operating System: Unknown/Multiple | Architecture: | Unknown/Multiple Type of failure: None/Unknown | Test Case: Blocked By: | Blocking: Related Tickets: | Differential Rev(s): Phab:D5412, Wiki Page: | Phab:D5422 -------------------------------------+------------------------------------- Changes (by alpmestan): * differential: Phab:D5412 => Phab:D5412, Phab:D5422 Comment: I just submitted [https://phabricator.haskell.org/D5422 D5422] which kills all the big enumerations but the ones for `Rules.Generate`. That last module is more involved so it probably deserves its own patch, and it's perhaps less urgent now that we got rid of hundreds of rules already. -- Ticket URL: http://ghc.haskell.org/trac/ghc/ticket/15938#comment:38 GHC http://www.haskell.org/ghc/ The Glasgow Haskell Compiler
#15938: Hadrian's recompilation check is extremely slow
-------------------------------------+-------------------------------------
Reporter: bgamari | Owner: alpmestan
Type: bug | Status: patch
Priority: high | Milestone: 8.8.1
Component: Build System | Version: 8.6.2
(Hadrian) |
Resolution: | Keywords:
Operating System: Unknown/Multiple | Architecture:
| Unknown/Multiple
Type of failure: None/Unknown | Test Case:
Blocked By: | Blocking:
Related Tickets: | Differential Rev(s): Phab:D5412,
Wiki Page: | Phab:D5422
-------------------------------------+-------------------------------------
Comment (by Ben Gamari
#15938: Hadrian's recompilation check is extremely slow -------------------------------------+------------------------------------- Reporter: bgamari | Owner: alpmestan Type: bug | Status: patch Priority: high | Milestone: 8.8.1 Component: Build System | Version: 8.6.2 (Hadrian) | Resolution: | Keywords: Operating System: Unknown/Multiple | Architecture: | Unknown/Multiple Type of failure: None/Unknown | Test Case: Blocked By: | Blocking: Related Tickets: | Differential Rev(s): Phab:D5412, Wiki Page: | Phab:D5422 -------------------------------------+------------------------------------- Comment (by alpmestan): Both D5412 and D5422 have landed on master. When I now resume builds that I stopped while building base (`_build/stage1/libraries/base/*`), hadrian gets back to work pretty quickly on my machine, never above 5 seconds for sure, and it seems to me it's back on track within 2-3 seconds in general now. Is this acceptable? Can we consider this problem solved and close the ticket? (We might want to get rid of the only big rule enumeration we have left -- the ones for generated files, `Rules.Generate` -- but I'd say it's not worth the trouble right now. The impact would quite likely be minor, while requiring some non trivial effort.) -- Ticket URL: http://ghc.haskell.org/trac/ghc/ticket/15938#comment:40 GHC http://www.haskell.org/ghc/ The Glasgow Haskell Compiler
#15938: Hadrian's recompilation check is extremely slow -------------------------------------+------------------------------------- Reporter: bgamari | Owner: alpmestan Type: bug | Status: patch Priority: high | Milestone: 8.8.1 Component: Build System | Version: 8.6.2 (Hadrian) | Resolution: | Keywords: Operating System: Unknown/Multiple | Architecture: | Unknown/Multiple Type of failure: None/Unknown | Test Case: Blocked By: | Blocking: Related Tickets: | Differential Rev(s): Phab:D5412, Wiki Page: | Phab:D5422 -------------------------------------+------------------------------------- Comment (by snowleopard): Many thanks, Alp! I agree that rewriting `Rules.Generate` is most likely unnecessary. I think the worst-case startup time of 5 seconds is acceptable, although we might come back to optimising Hadrian further at some point. This probably deserves a separate, lower priority ticket. @bgamari: Could you check Alp's results on your setup? -- Ticket URL: http://ghc.haskell.org/trac/ghc/ticket/15938#comment:41 GHC http://www.haskell.org/ghc/ The Glasgow Haskell Compiler
#15938: Hadrian's recompilation check is extremely slow -------------------------------------+------------------------------------- Reporter: bgamari | Owner: alpmestan Type: bug | Status: closed Priority: high | Milestone: 8.8.1 Component: Build System | Version: 8.6.2 (Hadrian) | Resolution: fixed | Keywords: Operating System: Unknown/Multiple | Architecture: | Unknown/Multiple Type of failure: None/Unknown | Test Case: Blocked By: | Blocking: Related Tickets: | Differential Rev(s): Phab:D5412, Wiki Page: | Phab:D5422 -------------------------------------+------------------------------------- Changes (by alpmestan): * status: patch => closed * resolution: => fixed Comment: We eliminated all the costly enumerations and the recompilation check is now reasonably fast (I'm sure it can be improved further), so let's close this and open specific tickets if some performance problems show up elsewhere. -- Ticket URL: http://ghc.haskell.org/trac/ghc/ticket/15938#comment:42 GHC http://www.haskell.org/ghc/ The Glasgow Haskell Compiler
participants (1)
-
GHC