GHCi.Message seems to have quite poor compilation time characteristics
While watching the build output I noticed that the GHCi.Message
module seems to take an extraordinarily long time to compile (over a minute on my machine).
The majority of the time appears to be due to simplification, each iteration of which takes around second
`ghc -v3` output
$ time /nix/store/k7fc62729rl3s8z0s80wra3mcd4lldiw-ghc-8.6.4/lib/ghc-8.6.4/bin/ghc -B/nix/store/k7fc62729rl3s8z0s80wra3mcd4lldiw-ghc-8.6.4/lib/ghc-8.6.4 -Wall -hisuf hi -osuf o -hcsuf hc -static -hide-all-packages -no-user-package-db -package-db buildvalidate/stage0/lib/package.conf.d -this-unit-id ghci-8.11.0.20191201 -package-id array-0.5.3.0 -package-id base-4.12.0.0 -package-id binary-0.8.7.0 -package-id bytestring-0.10.8.2 -package-id containers-0.6.0.1 -package-id deepseq-1.4.4.0 -package-id filepath-1.4.2.1 -package-id ghc-boot-8.11.0.20191201 -package-id ghc-boot-th-8.11.0.20191201 -package-id ghc-heap-8.11.0.20191201 -package-id template-haskell-2.16.0.0 -package-id transformers-0.5.6.2 -package-id unix-2.7.2.2 -i -ibuildvalidate/stage0/libraries/ghci/build -ibuildvalidate/stage0/libraries/ghci/build/autogen -ilibraries/ghci/. -Ibuildvalidate/stage0/lib -Ibuildvalidate/stage0/libraries/ghci/build -I/nix/store/k7fc62729rl3s8z0s80wra3mcd4lldiw-ghc-8.6.4/lib/ghc-8.6.4/unix-2.7.2.2/include -I/nix/store/k7fc62729rl3s8z0s80wra3mcd4lldiw-ghc-8.6.4/lib/ghc-8.6.4/time-1.8.0.2/include -I/nix/store/k7fc62729rl3s8z0s80wra3mcd4lldiw-ghc-8.6.4/lib/ghc-8.6.4/bytestring-0.10.8.2/include -I/nix/store/k7fc62729rl3s8z0s80wra3mcd4lldiw-ghc-8.6.4/lib/ghc-8.6.4/base-4.12.0.0/include -I/nix/store/17sf771rkjhma23pl04ycdqjrw8592l9-gmp-6.1.2-dev/include -I/nix/store/k7fc62729rl3s8z0s80wra3mcd4lldiw-ghc-8.6.4/lib/ghc-8.6.4/integer-gmp-1.0.2.0/include -I/nix/store/k7fc62729rl3s8z0s80wra3mcd4lldiw-ghc-8.6.4/lib/ghc-8.6.4/include -I/nix/store/8977h7yhy20ncal4aqh2057n58yndf2n-libffi-3.2.1-dev/include -Ibuildvalidate/stage0/lib -optc-Ibuildvalidate/stage0/lib -optP-include -optPbuildvalidate/stage0/libraries/ghci/build/autogen/cabal_macros.h -outputdir buildvalidate/stage0/libraries/ghci/build -optc-Wno-error=inline -c libraries/ghci/GHCi/Message.hs -o buildvalidate/stage0/libraries/ghci/build/GHCi/Message.o -O0 -H64m -XHaskell2010 -XNoImplicitPrelude -O -dcore-lint -dno-debug-output -fno-warn-deprecated-flags -fforce-recomp -v3 |& nix run nixpkgs.moreutils -c ts -i "%.s" 0.000011 Glasgow Haskell Compiler, Version 8.6.4, stage 2 booted by GHC version 8.2.2 0.000065 Using binary package database: /nix/store/k7fc62729rl3s8z0s80wra3mcd4lldiw-ghc-8.6.4/lib/ghc-8.6.4/package.conf.d/package.cache 0.000029 Using binary package database: buildvalidate/stage0/lib/package.conf.d/package.cache 0.000018 package flags [-package-id array-0.5.3.0{unit array-0.5.3.0 True ([])}, 0.000018 -package-id base-4.12.0.0{unit base-4.12.0.0 True ([])}, 0.000016 -package-id binary-0.8.7.0{unit binary-0.8.7.0 True ([])}, 0.000015 -package-id bytestring-0.10.8.2{unit bytestring-0.10.8.2 True ([])}, 0.000015 -package-id containers-0.6.0.1{unit containers-0.6.0.1 True ([])}, 0.000025 -package-id deepseq-1.4.4.0{unit deepseq-1.4.4.0 True ([])}, 0.000016 -package-id filepath-1.4.2.1{unit filepath-1.4.2.1 True ([])}, 0.000013 -package-id ghc-boot-8.11.0.20191201{unit ghc-boot-8.11.0.20191201 True ([])}, 0.000015 -package-id ghc-boot-th-8.11.0.20191201{unit ghc-boot-th-8.11.0.20191201 True ([])}, 0.000014 -package-id ghc-heap-8.11.0.20191201{unit ghc-heap-8.11.0.20191201 True ([])}, 0.000014 -package-id template-haskell-2.16.0.0{unit template-haskell-2.16.0.0 True ([])}, 0.000014 -package-id transformers-0.5.6.2{unit transformers-0.5.6.2 True ([])}, 0.000013 -package-id unix-2.7.2.2{unit unix-2.7.2.2 True ([])}] 0.000013 loading package database /nix/store/k7fc62729rl3s8z0s80wra3mcd4lldiw-ghc-8.6.4/lib/ghc-8.6.4/package.conf.d 0.000015 loading package database buildvalidate/stage0/lib/package.conf.d 0.000016 package array-0.5.3.0 overrides a previously defined package 0.000015 package base-4.12.0.0 overrides a previously defined package 0.000015 package bytestring-0.10.8.2 overrides a previously defined package 0.000016 package containers-0.6.0.1 overrides a previously defined package 0.000014 package deepseq-1.4.4.0 overrides a previously defined package 0.000014 package directory-1.3.3.0 overrides a previously defined package 0.000012 package filepath-1.4.2.1 overrides a previously defined package 0.000010 package ghc-prim-0.5.3 overrides a previously defined package 0.000009 package integer-gmp-1.0.2.0 overrides a previously defined package 0.000033 package mtl-2.2.2 overrides a previously defined package 0.000014 package pretty-1.1.3.6 overrides a previously defined package 0.000012 package rts overrides a previously defined package 0.000013 package time-1.8.0.2 overrides a previously defined package 0.000012 package transformers-0.5.6.2 overrides a previously defined package 0.000011 package unix-2.7.2.2 overrides a previously defined package 0.000011 wired-in package ghc-prim mapped to ghc-prim-0.5.3 0.000011 wired-in package integer-gmp mapped to integer-gmp-1.0.2.0 0.000011 wired-in package base mapped to base-4.12.0.0 0.000011 wired-in package rts mapped to rts 0.000010 wired-in package template-haskell mapped to template-haskell-2.16.0.0 0.000011 wired-in package ghc mapped to ghc-8.6.4 0.000011 *** Checking old interface for GHCi.Message (use -ddump-hi-diffs for more details): 0.000010 *** Parser [GHCi.Message]: 0.000011 !!! Parser [GHCi.Message]: finished in 5.76 milliseconds, allocated 14.880 megabytes 0.000011 *** Renamer/typechecker [GHCi.Message]: 0.319739 !!! Renamer/typechecker [GHCi.Message]: finished in 594.47 milliseconds, allocated 391.283 megabytes 0.000058 *** Desugar [GHCi.Message]: 0.069954 Result size of Desugar (before optimization) 0.000063 = {terms: 14,319, types: 163,478, coercions: 1,855, joins: 0/2,120} 0.000017 *** Core Linted result of Desugar (before optimization): 0.401169 Result size of Desugar (after optimization) 0.000208 = {terms: 10,246, types: 109,020, coercions: 3,495, joins: 3/634} 0.000050 *** Core Linted result of Desugar (after optimization): 0.155759 !!! Desugar [GHCi.Message]: finished in 627.83 milliseconds, allocated 772.823 megabytes 0.000157 *** Simplifier [GHCi.Message]: 0.436414 Result size of Simplifier iteration=1 0.000052 = {terms: 21,457, types: 157,013, coercions: 122,758, joins: 3/910} 0.000016 *** Core Linted result of Simplifier: 0.446605 Result size of Simplifier iteration=2 0.000052 = {terms: 17,104, types: 105,348, coercions: 78,057, joins: 2/544} 0.000021 *** Core Linted result of Simplifier: 0.335232 Result size of Simplifier iteration=3 0.000056 = {terms: 16,489, types: 82,301, coercions: 77,779, joins: 2/330} 0.000020 *** Core Linted result of Simplifier: 0.289821 Result size of Simplifier iteration=4 0.000062 = {terms: 16,485, types: 82,284, coercions: 77,758, joins: 4/330} 0.000025 *** Core Linted result of Simplifier: 0.207809 Result size of Simplifier 0.000055 = {terms: 16,485, types: 82,284, coercions: 77,758, joins: 4/330} 0.000028 *** Core Linted result of Simplifier: 0.185859 !!! Simplifier [GHCi.Message]: finished in 1903.70 milliseconds, allocated 2901.909 megabytes 0.000056 *** Specialise [GHCi.Message]: 0.176574 Result size of Specialise 0.000082 = {terms: 30,873, types: 210,977, coercions: 223,848, joins: 4/665} 0.000021 *** Core Linted result of Specialise: 0.589943 !!! Specialise [GHCi.Message]: finished in 767.17 milliseconds, allocated 1418.915 megabytes 0.000054 *** Float out(FOS {Lam = Just 0, 0.000015 Consts = True, 0.000011 OverSatApps = False}) [GHCi.Message]: 0.000012 Result size of Float out(FOS {Lam = Just 0, 0.000012 Consts = True, 0.375335 OverSatApps = False}) 0.000062 = {terms: 35,653, types: 265,757, coercions: 223,848, joins: 4/531} 0.000021 *** Core Linted result of Float out(FOS {Lam = Just 0, Consts = True, OverSatApps = False}): 0.694714 !!! Float out(FOS {Lam = Just 0, 0.000056 Consts = True, 0.000018 OverSatApps = False}) [GHCi.Message]: finished in 1071.15 milliseconds, allocated 1459.880 megabytes 0.000017 *** Simplifier [GHCi.Message]: 0.821198 Result size of Simplifier iteration=1 0.000079 = {terms: 78,967, 0.000020 types: 348,979, 0.000018 coercions: 200,752, 0.000015 joins: 13/2,448} 0.000013 *** Core Linted result of Simplifier: 1.457505 Result size of Simplifier iteration=2 0.000065 = {terms: 87,589, 0.000020 types: 315,192, 0.000016 coercions: 173,375, 0.000014 joins: 11/2,125} 0.000014 *** Core Linted result of Simplifier: 1.549405 Result size of Simplifier iteration=3 0.000056 = {terms: 72,727, 0.000022 types: 304,139, 0.000021 coercions: 172,783, 0.000013 joins: 9/1,727} 0.000015 *** Core Linted result of Simplifier: 1.196127 Result size of Simplifier iteration=4 0.000064 = {terms: 72,721, 0.000026 types: 304,121, 0.000025 coercions: 172,783, 0.000016 joins: 53/1,725} 0.000015 *** Core Linted result of Simplifier: 0.733834 Result size of Simplifier 0.000074 = {terms: 72,721, 0.000035 types: 304,121, 0.000015 coercions: 172,783, 0.000017 joins: 53/1,725} 0.000012 *** Core Linted result of Simplifier: 0.757205 !!! Simplifier [GHCi.Message]: finished in 6520.74 milliseconds, allocated 9445.460 megabytes 0.000068 *** Simplifier [GHCi.Message]: 0.844681 Result size of Simplifier iteration=1 0.000073 = {terms: 144,664, 0.000020 types: 331,560, 0.000018 coercions: 198,035, 0.000016 joins: 174/3,237} 0.000016 *** Core Linted result of Simplifier: 1.832080 Result size of Simplifier iteration=2 0.000058 = {terms: 114,015, 0.000024 types: 311,560, 0.000021 coercions: 185,121, 0.000014 joins: 52/1,991} 0.000015 *** Core Linted result of Simplifier: 1.405855 Result size of Simplifier iteration=3 0.000061 = {terms: 115,691, 0.000021 types: 312,010, 0.000038 coercions: 183,302, 0.000016 joins: 52/2,965} 0.000016 *** Core Linted result of Simplifier: 1.412919 Result size of Simplifier 0.000083 = {terms: 113,669, 0.000024 types: 310,999, 0.000014 coercions: 183,302, 0.000014 joins: 52/1,954} 0.000014 *** Core Linted result of Simplifier: 0.848602 !!! Simplifier [GHCi.Message]: finished in 6350.65 milliseconds, allocated 8805.315 megabytes 0.000077 *** Simplifier [GHCi.Message]: 0.668566 Result size of Simplifier iteration=1 0.000092 = {terms: 124,016, 0.000027 types: 328,674, 0.000018 coercions: 192,753, 0.000016 joins: 52/2,493} 0.000015 *** Core Linted result of Simplifier: 1.687996 Result size of Simplifier iteration=2 0.000077 = {terms: 123,290, 0.000027 types: 327,341, 0.000026 coercions: 192,760, 0.000018 joins: 52/2,234} 0.000016 *** Core Linted result of Simplifier: 1.537303 Result size of Simplifier 0.000103 = {terms: 123,290, 0.000062 types: 327,341, 0.000042 coercions: 192,760, 0.000031 joins: 52/2,234} 0.000020 *** Core Linted result of Simplifier: 0.892147 !!! Simplifier [GHCi.Message]: finished in 4787.03 milliseconds, allocated 6611.671 megabytes 0.000064 *** Float inwards [GHCi.Message]: 0.093461 Result size of Float inwards 0.000084 = {terms: 123,290, 0.000018 types: 327,341, 0.000026 coercions: 192,760, 0.000017 joins: 52/2,234} 0.000015 *** Core Linted result of Float inwards: 0.869917 !!! Float inwards [GHCi.Message]: finished in 964.06 milliseconds, allocated 1797.198 megabytes 0.000066 *** Called arity analysis [GHCi.Message]: 0.333439 Result size of Called arity analysis 0.000080 = {terms: 123,290, 0.000043 types: 327,341, 0.000030 coercions: 192,760, 0.000027 joins: 52/2,234} 0.000026 *** Core Linted result of Called arity analysis: 0.898854 !!! Called arity analysis [GHCi.Message]: finished in 1233.47 milliseconds, allocated 1820.739 megabytes 0.000066 *** Simplifier [GHCi.Message]: 0.661738 Result size of Simplifier iteration=1 0.000091 = {terms: 123,372, 0.000022 types: 327,419, 0.000017 coercions: 192,760, 0.000029 joins: 54/2,238} 0.000018 *** Core Linted result of Simplifier: 1.487483 Result size of Simplifier iteration=2 0.000057 = {terms: 123,253, 0.000020 types: 327,238, 0.000020 coercions: 192,749, 0.000014 joins: 54/2,205} 0.000015 *** Core Linted result of Simplifier: 1.730837 Result size of Simplifier iteration=3 0.000077 = {terms: 123,217, 0.000024 types: 327,153, 0.000034 coercions: 192,731, 0.000019 joins: 53/2,201} 0.000019 *** Core Linted result of Simplifier: 1.452464 Result size of Simplifier 0.000062 = {terms: 123,217, 0.000030 types: 327,153, 0.000024 coercions: 192,731, 0.000017 joins: 53/2,201} 0.000016 *** Core Linted result of Simplifier: 0.883434 !!! Simplifier [GHCi.Message]: finished in 6221.32 milliseconds, allocated 8784.897 megabytes 0.000053 *** Demand analysis [GHCi.Message]: 0.372278 Result size of Demand analysis 0.000061 = {terms: 123,217, 0.000037 types: 327,153, 0.000027 coercions: 192,731, 0.000021 joins: 53/2,201} 0.000018 *** Core Linted result of Demand analysis: 0.968998 !!! Demand analysis [GHCi.Message]: finished in 1342.32 milliseconds, allocated 2184.600 megabytes 0.000059 *** Worker Wrapper binds [GHCi.Message]: 0.044067 Result size of Worker Wrapper binds 0.000065 = {terms: 144,333, 0.000021 types: 407,134, 0.000020 coercions: 194,258, 0.000014 joins: 99/6,277} 0.000015 *** Core Linted result of Worker Wrapper binds: 1.350777 !!! Worker Wrapper binds [GHCi.Message]: finished in 1396.18 milliseconds, allocated 2185.917 megabytes 0.000057 *** Simplifier [GHCi.Message]: 1.048920 Result size of Simplifier iteration=1 0.000068 = {terms: 134,655, 0.000017 types: 385,554, 0.000013 coercions: 195,110, 0.000013 joins: 99/2,936} 0.000014 *** Core Linted result of Simplifier: 2.727704 Result size of Simplifier iteration=2 0.000091 = {terms: 128,957, 0.000026 types: 360,921, 0.000021 coercions: 193,206, 0.000019 joins: 53/2,255} 0.000017 *** Core Linted result of Simplifier: 1.834991 Result size of Simplifier iteration=3 0.000082 = {terms: 128,774, 0.000020 types: 360,135, 0.000028 coercions: 192,550, 0.000018 joins: 53/2,234} 0.000017 *** Core Linted result of Simplifier: 1.824703 Result size of Simplifier iteration=4 0.000120 = {terms: 128,772, 0.000047 types: 360,133, 0.000044 coercions: 192,550, 0.000035 joins: 53/2,233} 0.000052 *** Core Linted result of Simplifier: 1.349173 Result size of Simplifier 0.000084 = {terms: 128,772, 0.000023 types: 360,133, 0.000016 coercions: 192,550, 0.000027 joins: 53/2,233} 0.000018 *** Core Linted result of Simplifier: 1.127790 !!! Simplifier [GHCi.Message]: finished in 9608.89 milliseconds, allocated 12607.591 megabytes 0.000063 *** Exitification transformation [GHCi.Message]: 0.043706 Result size of Exitification transformation 0.000080 = {terms: 129,434, 0.000023 types: 361,745, 0.000031 coercions: 192,550, 0.000021 joins: 149/2,329} 0.000018 *** Core Linted result of Exitification transformation: 1.341618 !!! Exitification transformation [GHCi.Message]: finished in 1386.97 milliseconds, allocated 1973.484 megabytes 0.000064 *** Float out(FOS {Lam = Just 0, 0.000016 Consts = True, 0.000024 OverSatApps = True}) [GHCi.Message]: 0.000016 Result size of Float out(FOS {Lam = Just 0, 0.000013 Consts = True, 0.626250 OverSatApps = True}) 0.000098 = {terms: 130,758, 0.000033 types: 366,589, 0.000032 coercions: 192,550, 0.000023 joins: 146/2,342} 0.000025 *** Core Linted result of Float out(FOS {Lam = Just 0, Consts = True, OverSatApps = True}): 1.138562 !!! Float out(FOS {Lam = Just 0, 0.000065 Consts = True, 0.000036 OverSatApps = True}) [GHCi.Message]: finished in 1766.62 milliseconds, allocated 2604.813 megabytes 0.000038 *** Common sub-expression [GHCi.Message]: 0.127400 Result size of Common sub-expression 0.000074 = {terms: 121,600, 0.000020 types: 350,484, 0.000016 coercions: 181,243, 0.000016 joins: 104/2,275} 0.000014 *** Core Linted result of Common sub-expression: 1.081781 !!! Common sub-expression [GHCi.Message]: finished in 1210.42 milliseconds, allocated 2032.354 megabytes 0.000065 *** Float inwards [GHCi.Message]: 0.093372 Result size of Float inwards 0.000065 = {terms: 121,590, 0.000018 types: 350,424, 0.000024 coercions: 181,243, 0.000020 joins: 104/2,270} 0.000015 *** Core Linted result of Float inwards: 1.283421 !!! Float inwards [GHCi.Message]: finished in 1361.75 milliseconds, allocated 2032.167 megabytes 0.000073 *** Simplifier [GHCi.Message]: 0.683495 Result size of Simplifier iteration=1 0.000105 = {terms: 121,121, 0.000039 types: 341,978, 0.000017 coercions: 181,903, 0.000017 joins: 104/2,270} 0.000017 *** Core Linted result of Simplifier: 2.146000 Result size of Simplifier 0.000058 = {terms: 121,076, 0.000021 types: 341,845, 0.000013 coercions: 181,903, 0.000012 joins: 104/2,270} 0.000012 *** Core Linted result of Simplifier: 1.125622 !!! Simplifier [GHCi.Message]: finished in 3957.86 milliseconds, allocated 4935.540 megabytes 0.000059 *** Demand analysis [GHCi.Message]: 0.400882 Result size of Demand analysis 0.000090 = {terms: 121,076, 0.000024 types: 341,845, 0.000029 coercions: 181,903, 0.000019 joins: 104/2,270} 0.000042 *** Core Linted result of Demand analysis: 1.076988 !!! Demand analysis [GHCi.Message]: finished in 1478.64 milliseconds, allocated 2358.524 megabytes 0.000066 *** CoreTidy [GHCi.Message]: 0.158370 Result size of Tidy Core 0.000076 = {terms: 70,265, 0.000026 types: 212,206, 0.000017 coercions: 123,775, 0.000015 joins: 41/1,384} 0.000015 *** Core Linted result of Tidy Core: 0.808684 !!! CoreTidy [GHCi.Message]: finished in 960.58 milliseconds, allocated 1186.159 megabytes 0.284412 Created temporary directory: /tmp/ghc3486_0 0.000070 *** CorePrep [GHCi.Message]: 0.202458 Result size of CorePrep 0.000083 = {terms: 100,951, 0.000019 types: 295,195, 0.000022 coercions: 123,836, 0.000018 joins: 41/4,921} 0.000026 *** Core Linted result of CorePrep: 0.832023 !!! CorePrep [GHCi.Message]: finished in 1035.58 milliseconds, allocated 1496.476 megabytes 0.000440 *** Stg2Stg: 0.000037 *** CodeGen [GHCi.Message]: 2.458130 !!! CodeGen [GHCi.Message]: finished in 2456.75 milliseconds, allocated 2523.520 megabytes 0.009381 *** Assembler: 0.000078 /nix/store/7nvy9l5jcp1c6z6n96l1a5x1bwbvamqn-gcc-wrapper-7.4.0/bin/cc -fno-stack-protector -DTABLES_NEXT_TO_CODE -iquotelibraries/ghci/GHCi -Ibuildvalidate/stage0/lib -Ibuildvalidate/stage0/libraries/ghci/build -I/nix/store/k7fc62729rl3s8z0s80wra3mcd4lldiw-ghc-8.6.4/lib/ghc-8.6.4/unix-2.7.2.2/include -I/nix/store/k7fc62729rl3s8z0s80wra3mcd4lldiw-ghc-8.6.4/lib/ghc-8.6.4/time-1.8.0.2/include -I/nix/store/k7fc62729rl3s8z0s80wra3mcd4lldiw-ghc-8.6.4/lib/ghc-8.6.4/bytestring-0.10.8.2/include -I/nix/store/k7fc62729rl3s8z0s80wra3mcd4lldiw-ghc-8.6.4/lib/ghc-8.6.4/base-4.12.0.0/include -I/nix/store/17sf771rkjhma23pl04ycdqjrw8592l9-gmp-6.1.2-dev/include -I/nix/store/k7fc62729rl3s8z0s80wra3mcd4lldiw-ghc-8.6.4/lib/ghc-8.6.4/integer-gmp-1.0.2.0/include -I/nix/store/k7fc62729rl3s8z0s80wra3mcd4lldiw-ghc-8.6.4/lib/ghc-8.6.4/include -I/nix/store/8977h7yhy20ncal4aqh2057n58yndf2n-libffi-3.2.1-dev/include -Ibuildvalidate/stage0/lib -Ibuildvalidate/stage0/libraries/ghci/build -no-pie -x assembler -c /tmp/ghc3486_0/ghc_1.s -o buildvalidate/stage0/libraries/ghci/build/GHCi/Message.o 0.768624 *** Deleting temp files: 0.000066 Deleting: /tmp/ghc3486_0/ghc_1.s /tmp/ghc3486_0/ghc_2.c 0.000738 Warning: deleting non-existent /tmp/ghc3486_0/ghc_2.c 0.000049 *** Deleting temp dirs: 0.000025 Deleting: /tmp/ghc3486_0real 1m0.611s user 1m0.226s sys 0m0.485s