Panic Simplifier ticks exhausted with type families
I've tried to compile my vinyl-like records with 7.10.2-rc1 and got:
ghc: panic! (the 'impossible' happened)
(GHC version 7.10.1.20150612 for x86_64-unknown-linux):
Simplifier ticks exhausted
When trying RuleFired Class op rreplace
To increase the limit, use -fsimpl-tick-factor=N (default 100)
If you need to do this, let GHC HQ know, and what factor you needed
To see detailed counts use -ddump-simpl-stats
Total ticks: 225484
Please report this as a GHC bug: http://www.haskell.org/ghc/reportabug
Attached self contained test compiles with 7.10.1, but fails with 7.10.2-rc1 when compiled with optimizations.
Trac metadata
| Trac field | Value |
|---|---|
| Version | 7.10.1-rc1 |
| Type | Bug |
| TypeOfFailure | OtherFailure |
| Priority | normal |
| Resolution | Unresolved |
| Component | Compiler |
| Test case | |
| Differential revisions | |
| BlockedBy | |
| Related | |
| Blocking | |
| CC | |
| Operating system | |
| Architecture |
Activity
mentioned in issue #4945
mentioned in issue #5113 (closed)
added Tbug Trac import labels
Attached file
Bug.hs($1099).testcase
changed milestone to %7.10.2
Confirmed regression from 7.10.1.
$ /opt/ghc/7.10.1/bin/ghc -O -fforce-recomp Bug.hs -fsimpl-tick-factor=50 [1 of 1] Compiling Bug ( Bug.hs, Bug.o ) $ /opt/ghc/7.10.2/bin/ghc -O -fforce-recomp Bug.hs -fsimpl-tick-factor=5000 [1 of 1] Compiling Bug ( Bug.hs, Bug.o ) ghc: panic! (the 'impossible' happened) (GHC version 7.10.1.20150609 for x86_64-unknown-linux): Simplifier ticks exhausted When trying UnfoldingDone $fFunctorConst_$cfmap To increase the limit, use -fsimpl-tick-factor=N (default 100) If you need to do this, let GHC HQ know, and what factor you needed To see detailed counts use -ddump-simpl-stats Total ticks: 11274000Trac metadata
Trac field Value Priority normal → high assigned to @bgamari
mentioned in issue #10565 (closed)
I am still churning through this one but I think I finally have some traction. In 7.10.2 each field added to the records roughly doubles the
simpl-tick-factornecessary to finish.I am now comparing the sequences of inlinings performed by GHC 7.10.1 and 7.10.2. For those following along at home, it is enlightening (albeit verbose) to compile like this,
ghc -fforce-recomp -O -dverbose-core2core -ddump-simpl -ddump-to-file -dshow-passes -ddump-simpl-stats -ddump-inlinings Bug.hs -fsimpl-tick-factor=100 >|ghc.log 2>&1Out pops a few hundred megabytes of text, but you now you have what you need.
You can then easily compare two of these dumps with,
paste <(grep -n "Inlining done" 7.10.1/ghc.log) <(grep -n "Inlining done" 7.10.2/ghc.log) | column -s $'\t' -t | lessOne notices certain patterns in this output. In particular, one finds inlinings of
Data.Functor.Identity.$fFoldableIdentity2are performed far more often in 7.10.1 than 7.10.2. It is worth noting that whenever 7.10.2 considers inlining this definition it does so.More analysis later.
-
Very early in the simplifier run I noticed this difference.
In 7.10.1,
Inlining done: Data.Functor.Identity.$fFoldableIdentity2 Inlined fn: \ (@ a4) (ds [Occ=Once] :: Data.Functor.Identity.Identity a4) -> ds Cont: ApplyToTy (Bug.Rec ss) ApplyToVal nodup ((g x) `cast` (Sym (Nth:0 (<Data.Functor.Identity.Identity (Bug.Rec ss)>_R -> Data.Functor.Identity.NTCo:Identity[0] <Bug.Rec ss>_R)) :: Data.Functor.Identity.Identity (Bug.Rec ss) ~R# Data.Functor.Identity.Identity (Bug.Rec ss))) CastIt Nth:1 (<Data.Functor.Identity.Identity (Bug.Rec ss)>_R -> Data.Functor.Identity.NTCo:Identity[0] <Bug.Rec ss>_R) Stop[BoringCtxt] Bug.Rec ssIn 7.10.2,
Inlining done: Data.Functor.Identity.$fFoldableIdentity2 Inlined fn: \ (@ a4) (ds [Occ=Once] :: Data.Functor.Identity.Identity a4) -> ds Cont: ApplyToTy (Bug.Rec ss) ApplyToVal simpl ((g x) `cast` (Sym (Nth:0 (<Data.Functor.Identity.Identity (Bug.Rec ss)>_R -> Data.Functor.Identity.NTCo:Identity[0] <Bug.Rec ss>_R)) :: Data.Functor.Identity.Identity (Bug.Rec ss) ~R# Data.Functor.Identity.Identity (Bug.Rec ss))) CastIt Nth:1 (<Data.Functor.Identity.Identity (Bug.Rec ss)>_R -> Data.Functor.Identity.NTCo:Identity[0] <Bug.Rec ss>_R) Stop[BoringCtxt] Bug.Rec ssNotice the second "frame" of the context:
ApplyToVal nodup ((g x) ...)(7.10.1) in contrast toApplyToVal simpl ((g x) ...)(7.10.2). I'm not yet sure whether this is significant. -
I have also noticed that GHC 7.10.1 often appears to by simplifying inside of a
castwhen 7.10.2 is just working inside ofConst. For instance, it is common to see theSimplContof 7.10.1 terminates with,CastIt Nth:1 (((forall a6 b. <Control.Applicative.Const a6 b>_R -> Control.Applicative.NTCo:Const[0] <a6>_R <b>_P)@"field1" Bug.:-> Bug.Expr GHC.Types.Int)@Bug.Rec '["field1" Bug.:-> Bug.Expr GHC.Types.Int, "field2" Bug.:-> Bug.Expr GHC.Types.Int, "id" Bug.:-> Bug.Expr GHC.Types.Int, "event_type" Bug.:-> Bug.Expr GHC.Types.Int]) Stop[BoringCtxt] "field1" Bug.:-> Bug.Expr GHC.Types.Intwhereas 7.10.2 will end in,
Stop[BoringCtxt] Control.Applicative.Const ("field1" Bug.:-> Bug.Expr GHC.Types.Int) (Bug.Rec '["field1" Bug.:-> Bug.Expr GHC.Types.Int, "field2" Bug.:-> Bug.Expr GHC.Types.Int, "id" Bug.:-> Bug.Expr GHC.Types.Int, "event_type" Bug.:-> Bug.Expr GHC.Types.Int])with the inner context being essentially identical.
-
Here I compare what the simplifier does to a term of type
"event_type" :-> Intfrom my test program in GHC 7.10.1 and 7.10.2.The test program (found here https://github.com/bgamari/ghc-T10527/blob/master/Bug2.hs) is cut down just enough so that it fails with 7.10.2 and succeeds with 7.10.1 with a sufficiently low
simpl-tick-factor(10). -
One obvious qualitative difference between the two simplifier trajectories is that the 7.10.2 emits its last
SimplBindtrace (for$s$crsubset_s2gQ) somewhere around 13% through the log (measured in lines). In contrast, 7.10.1 emitsSimplBindsevery regularly throughout the log. I suppose this means that 7.10.2 is spending most of its time playing with this one top-level binding? -
Well, I quickly bisected get an idea of what I should be looking for. It seems like the regression was introduced by the fix for the huge space leak in the mighty simplifier (8af219ad). If I understand correctly this patch touched code surrounding the treatment of interesting arguments. Perhaps an inadvertent change here is now resulting in more inlining than we would like. I'll have another look after I've slept on it to see if this revelation gets us any closer to a fix.
-
Reading through the patch it indeed seems that the
NoDuptoSimplifiedchange that I noticed above could have arisen out of this commit. See the treatment ofsimplArgfor https://phabricator.haskell.org/rGHC8af219adb914b292d0f8c737fe0a1e3f7fb19cf3#C60694NL1193 for how. That being said, usingdup_flaginstead ofSimplifiedon line 1203 doesn't seem to help. I'll need more sleep to get any further I'm afraid. -
The whittled down test case can be found here, https://github.com/bgamari/ghc-T10527/blob/master/Bug3.hs. It've been testing with,
ghc -fforce-recomp -O Bug3.hs -fsimpl-tick-factor=4 -dshow-passes -dverbose-core2core -ddump-rule-firings -ddump-rules -ddump-rule-rewrites -dsuppress-coercions -ddump-inlinings -ddump-to-file >|ghc.log 2>&1;With both the current state of the
ghc-7.10branch andghc-7.10.1-release. Note that this test case been reduced to the bare minimum to reproduce on 7.10.2 yet not on 7.10.1. Loweringsimpl-tick-factorto 3 causes it to fail on both. -
I've put up some of my notes tracing through the inlinings here, https://github.com/bgamari/ghc-T10527/blob/master/trace-inlines.mkd
-
Another thing I have noticed is that the good commit considers some inlining contexts to be
RuleArgCtxtswhich the bad commits considersBoringCtxt. This difference may be due to the good commit's eagerness to inline$fFoldableIndentity2and friends.Consider, for instance, this inlinig which occurs in a
RuleArgCtxt(which directly follows an inlining offFoldableIdentity2),Considering inlining: $s$crsubset_s2eb arg infos [ValueArg, ValueArg, TrivArg] interesting continuation RuleArgCtxt some_benefit True is exp: True is work-free: True guidance IF_ARGS [30 60 0] 70 0 discounted size = -105 ANSWER = YES Inlining done: $s$crsubset Inlined fn: \ (@ (g :: * -> *)) ($dFunctor_a211 [Occ=Once] :: GHC.Base.Functor g) (eta_B2 [Occ=Once!] :: Bug.Rec '[] -> g (Bug.Rec '[])) (eta_B1 [Occ=OnceL] :: Bug.Rec '["id" Bug.:-> Bug.Expr GHC.Types.Int, "id" Bug.:-> Bug.Expr GHC.Types.Int, "event_type" Bug.:-> Bug.Expr GHC.Types.Int, "field1" Bug.:-> Bug.Expr GHC.Types.Int]) -> GHC.Base.fmap @ g $dFunctor_a211 @ (Bug.Rec '[]) @ (Bug.Rec '["id" Bug.:-> Bug.Expr GHC.Types.Int, "id" Bug.:-> Bug.Expr GHC.Types.Int, "event_type" Bug.:-> Bug.Expr GHC.Types.Int, "field1" Bug.:-> Bug.Expr GHC.Types.Int]) (\ _ [Occ=Dead] -> eta_B1) (eta_B2 Bug.$WRNil) Cont: ApplyToTy Data.Functor.Identity.Identity ApplyToVal nodup Data.Functor.Identity.$fFunctorIdentity ApplyToVal nodup ((\ _ [Occ=Dead] -> rs `cast` ...) `cast` ...) ApplyToVal nodup eta_B1 CastIt Nth:1 ((forall a4. <Data.Functor.Identity.Identity a4>_R -> Data.Functor.Identity.NTCo:Identity[0] <a4>_R)@Bug.Rec '["id" Bug.:-> Bug.Expr GHC.Types.Int, "id" Bug.:-> Bug.Expr GHC.Types.Int, "event_type" Bug.:-> Bug.Expr GHC.Types.Int, "field1" Bug.:-> Bug.Expr GHC.Types.Int]) Stop[RuleArgCtxt] Bug.Rec '["id" Bug.:-> Bug.Expr GHC.Types.Int, "id" Bug.:-> Bug.Expr GHC.Types.Int, "event_type" Bug.:-> Bug.Expr GHC.Types.Int, "field1" Bug.:-> Bug.Expr GHC.Types.Int]Compared to the bad commit, which has not yet inlined
$fFoldableIdentity2and does the same inlining in roughly the same context (up to some casts),Considering inlining: $s$crsubset_s2eb arg infos [ValueArg, ValueArg, TrivArg] interesting continuation BoringCtxt some_benefit True is exp: True is work-free: True guidance IF_ARGS [30 60 0] 70 0 discounted size = -105 ANSWER = YES Inlining done: $s$crsubset Inlined fn: \ (@ (g :: * -> *)) ($dFunctor_a211 [Occ=Once] :: GHC.Base.Functor g) (eta_B2 [Occ=Once!] :: Bug.Rec '[] -> g (Bug.Rec '[])) (eta_B1 [Occ=OnceL] :: Bug.Rec '["id" Bug.:-> Bug.Expr GHC.Types.Int, "id" Bug.:-> Bug.Expr GHC.Types.Int, "event_type" Bug.:-> Bug.Expr GHC.Types.Int, "field1" Bug.:-> Bug.Expr GHC.Types.Int]) -> GHC.Base.fmap @ g $dFunctor_a211 @ (Bug.Rec '[]) @ (Bug.Rec '["id" Bug.:-> Bug.Expr GHC.Types.Int, "id" Bug.:-> Bug.Expr GHC.Types.Int, "event_type" Bug.:-> Bug.Expr GHC.Types.Int, "field1" Bug.:-> Bug.Expr GHC.Types.Int]) (\ _ [Occ=Dead] -> eta_B1) (eta_B2 Bug.$WRNil) Cont: ApplyToTy Data.Functor.Identity.Identity ApplyToVal nodup Data.Functor.Identity.$fFunctorIdentity ApplyToVal nodup ((\ _ [Occ=Dead] -> rs) `cast` ...) ApplyToVal nodup eta_B1 Stop[BoringCtxt] Data.Functor.Identity.Identity (Bug.Rec '["id" Bug.:-> Bug.Expr GHC.Types.Int, "id" Bug.:-> Bug.Expr GHC.Types.Int, "event_type" Bug.:-> Bug.Expr GHC.Types.Int, "field1" Bug.:-> Bug.Expr GHC.Types.Int]) -
Also interesting is this inlining of
$fFunctorIdentity2is completely unchanged between the two commits other than IdInfo of a binding in the context. Namely, both have a context entry that look like this,ApplyToVal simpl ((case xs `cast` ... of _ [Occ=Dead] { Bug.:& @ r @ rs dt_X2fs x xs -> case xs `cast` ... of _ [Occ=Dead] { Bug.:& @ r @ rs dt_d2bT x xs -> case r `cast` ... of nt_s2fs { Bug.Expr ipv ipv -> let { dt_X1PT :: Bug.Rec '["field1" Bug.:-> Bug.Expr GHC.Types.Int] [LclId, Str=DmdType, Unf=Unf{Src=<vanilla>, TopLvl=False, Value=True, ConLike=True, WorkFree=True, Expandable=True, Guidance=IF_ARGS [] 10 30}] dt_X1PT = Bug.:& @ '["field1" Bug.:-> Bug.Expr GHC.Types.Int] @ ("field1" Bug.:-> Bug.Expr GHC.Types.Int) @ '[] @~ <'["field1" Bug.:-> Bug.Expr GHC.Types.Int]>_N (nt_s2fs `cast` ...) (xs `cast` ...) } in (Bug.:& @ '["event_type" Bug.:-> Bug.Expr GHC.Types.Int, "field1" Bug.:-> Bug.Expr GHC.Types.Int] @ ("event_type" Bug.:-> Bug.Expr GHC.Types.Int) @ '["field1" Bug.:-> Bug.Expr GHC.Types.Int] @~ <'["event_type" Bug.:-> Bug.Expr GHC.Types.Int, "field1" Bug.:-> Bug.Expr GHC.Types.Int]>_N (x `cast` ...) dt_X1PT) `cast` ... } } }) `cast` ...)where the bad commit has the Unfolding for
dt_X1PTand the good commit does not. Things of this nature appear to pop up fairly regularly later in the simplifier pass. Moreover it appears that the context contains more bindings (all of which having unfoldings) as the simplifier iteration progresses. See, for instance, this example https://gist.github.com/bgamari/c96e13404f00202f2902 (wheredt_X1PT,dtX1U4,dt_X1U6,dt_X1Uc, anddt_X1Ueall have unfoldings with the bad commit and none with the good commit.Smells very suspicious.
-
The above notes are getting to be a bit of a mess. Here's something of a summary of the current state of things.
I have established that the memory leak patch is the source of the regression. Below I will refer to the commit directly before this patch (9b406cc6) as the working commit and the regression commit (8af219ad) as the failing commit. Looking at verbose-core2core output, it seems there is no difference in the compilation up to the
Float out(FOS {Lam = Just 0, Consts = True, OverSatApps = False})phase. It is apparently during this phase that the simplifier blows up.At this point it's not clear to me whether one or more of these differences are the key to the issue or simply inconsequential fall-out due to the move away from
CoreSubst. In particular the differences are,-
One often sees that terms in the context of inlinings that are marked
as
NoDupin 7.10.1 are marked asSimplifiedin 7.10.2. The newimplementation of
simplArgappears to touch this logic but my testssuggest that this isn't the cause of the difference.
-
$fFoldableIdentity2and$fGeneric1Constare both inlinedsooner in the working commit than in the failing commit. (comment:16 and ticket:10527#comment:101421)
This results in a rather obvious pattern in the differences between the contexts of the inlinings performed by the two commits. For instance, in the working commit one often sees contexts ending with,
CastIt Nth:1 (((forall a6 b. <Const a6 b>_R -> Control.Applicative.NTCo:Const[0] <a6>_R <b>_P) @ "field1" :-> Expr Int) @ Rec '["field1" :-> .Expr Int, "field2" :-> .Expr Int, "id" :-> .Expr Int, "event_type" :-> .Expr Int] ) Stop[BoringCtxt] "field1" Bug.:-> Bug.Expr GHC.Types.Intwhereas the context of the corresponding inlining in the failing commit ends simply with,
Stop[BoringCtxt] Control.Applicative.Const ("field1" :-> Expr Int) (Rec '["field1" :-> Expr Int, "field2" :-> Expr Int, "id" :-> Expr Int, "event_type" :-> Expr Int])Several inlinings further are performed in this state until eventually
$fFoldableIdentity2or$fGeneric1Constare inlined by the bad commit, which wipes away the difference.-
One sees
letbindings in inlining contexts which have unfoldings in the bad commit and no inlinings in the good commit. (comment:17) -
One occasionally sees inlinings being consider in continuations
which are considered interesting for different reasons: namely the
good commit often considers continuations to be
RuleArgCtxtwhilethe bad commit considers it to be.
BoringCtxt -
Interesting but unlikely to be the cause: the failing commit
considers (and rejects) a few inlinings that the
working commit does not. These typically look like,
Considering inlining: g_a2cv arg infos [TrivArg] interesting continuation BoringCtxt some_benefit True is exp: False is work-free: False guidance IF_ARGS [] 50 0 discounted size = 40 ANSWER = NOg_a2cvis a let binding defined in several different bindings (namely$dmrreplace,$dmrcast, and$dmrput. It appears always be of the formRec ss_a1LQ -> m (Rec ss_a1LQ)withmof eitherConst _orIdentitydepending upon the context. It's interesting that the failing commit considers and rejects inlining this binding in all three cases, whereas the working commit doesn't even consider it.There are a few other bindings (e.g. variants of
lens) which also exhibit this difference.Anyways, all of this is likely very difficult to grasp without playing around with it. The whittled down test case can be found here, https://github.com/bgamari/ghc-T10527/blob/master/Bug3.hs. I have been testing with,
ghc -fforce-recomp -O Bug3.hs -fsimpl-tick-factor=4 -dshow-passes \ -dverbose-core2core -ddump-rule-firings -ddump-rules -ddump-rule-rewrites \ -dsuppress-coercions -ddump-inlinings -ddump-to-file >|ghc.log 2>&1With both the good and bad commit. Note that this test case been reduced to the bare minimum to reproduce on the bad commit yet not on the good commit. However, it is very sensitive: lowering
simpl-tick-factorto 3 causes it to fail on both. -
-
Simon has identified that the issue is the simplifier expending a great deal of effort simplifying an argument which is ultimately ignored by the callee.
I have merged 07a1f32e into the
ghc-7.10branch which should resolve this for 7.10.2. Simonpj is working on a more thorough fix formaster. I'll leave this open until the latter fix has been merged. -
Unfortunately the fix on 7.10 regresses the test-case for #5113 (closed). I'm looking into why.
-
It appears that the following failures are triggered by the fix on
ghc-7.10,simplCore/should_compile T4945 [bad stdout] (normal)
=====> T4945(normal) 1533 of 4449 [0, 1, 0] cd ./simplCore/should_compile && $MAKE -s --no-print-directory T4945 </dev/null > T4945.run.stdout 2> T4945.run.stderr Actual stdout output differs from expected: --- ./simplCore/should_compile/T4945.stdout 2015-07-06 17:16:38.859135774 -0400 +++ ./simplCore/should_compile/T4945.run.stdout 2015-07-07 03:57:30.592499506 -0400 @@ -1,7 +0,0 @@ - -> STUArray RealWorld Int Int - (ipv3 [OS=OneShot] :: STUArray RealWorld Int Int) -> - case ipv3 of _ [Occ=Dead] { STUArray ds5 ds6 dt ds7 -> - (Data.Array.Base.STUArray - (Data.Array.Base.STUArray - (Data.Array.Base.STUArray - (Data.Array.Base.STUArray *** unexpected failure for T4945(normal)perf/should_run T5113 [stat not good enough] (normal)
=====> T5113(normal) 2426 of 4449 [0, 2, 0] cd ./perf/should_run && "/home/ben/trees/ghc/ghc-7.10/inplace/bin/ghc-stage2" -o T5113 T5113.hs -fforce-recomp -dcore-lint -dcmm-lint -dno-debug-output -no-user-package-db -rtsopts -fno-warn-tabs -fno-ghci-history -O > T5113.comp.stderr 2>&1 cd ./perf/should_run && ./T5113 +RTS -V0 -tT5113.stats --machine-readable -RTS </dev/null > T5113.run.stdout 2> T5113.run.stderr bytes allocated value is too high: Expected T5113(normal) bytes allocated: 8000000 +/-5% Lower bound T5113(normal) bytes allocated: 7600000 Upper bound T5113(normal) bytes allocated: 8400000 Actual T5113(normal) bytes allocated: 806747568 Deviation T5113(normal) bytes allocated: 9984.3 % *** unexpected stat test failure for T5113(normal)perf/compiler T9961 [stat too good] (normal)
=====> T9961(normal) 2474 of 4449 [0, 2, 0] cd ./perf/compiler && "/home/ben/trees/ghc/ghc-7.10/inplace/bin/ghc-stage2" -c T9961.hs -fforce-recomp -dno-debug-output -no-user-package-db -rtsopts -fno-warn-tabs -fno-ghci-history -O +RTS -V0 -tT9961.comp.stats --machine-readable -RTS > T9961.comp.stderr 2>&1 bytes allocated value is too low: (If this is because you have improved GHC, please update the test so that GHC doesn't regress again) Expected T9961(normal) bytes allocated: 663978160 +/-5% Lower bound T9961(normal) bytes allocated: 630779252 Upper bound T9961(normal) bytes allocated: 697177068 Actual T9961(normal) bytes allocated: 616521968 Deviation T9961(normal) bytes allocated: -7.1 % *** unexpected stat test failure for T9961(normal) -
#4945 has been accounted for (the test-case was wrong; see the ticket for details).
-
Simon, I've left a comment on #5113 (closed):ticket:10527#comment:101453 describing a concern I have with your patch against
ghc-7.10. When you get a chance, could you briefly explain how argument expressions are supposed to now make it to the rebuilder? Currently it appears that we merely perform substitutions on them, which means rules won't fire on them. -
Simon has written another patch addressing this issue which I have merged to the
ghc-7.10branch (1171d420). This still needs a fix onmaster. mentioned in issue #10657 (closed)
changed milestone to %8.0.1
mentioned in issue #11263
added Phighest label
