Fix laziness while streaming blocks

[kderme]

Currently we noticed a big space leak, where ghc profiling indicated a peak of >2GB PINNED memory used and ps/top reported >4GB memory used.

Checking with noUnexpectedThunks in the LedgerDB this was reported:

"ExtLedgerState (HardForkBlock (': * ByronBlock (': * (ShelleyBlock TPraosStandardCrypto) ('[] *))))","LedgerDB"], 
unexpectedThunkCallStack = [("$dmnoUnexpectedThunks",SrcLoc {srcLocPackage = "ouroboros-consensus-0.1.0.0-inplace", 
srcLocModule = "Ouroboros.Consensus.Ledger.Extended", srcLocFile = "src/Ouroboros/Consensus/Ledger/Extended.hs", 
srcLocStartLine = 76, srcLocStartCol = 10, srcLocEndLine = 76, srcLocEndCol = 79}),("noUnexpectedThunks",SrcLoc 
{srcLocPackage = "cardano-prelude-0.1.0.0-inplace", srcLocModule = "Cardano.Prelude.GHC.Heap.NormalForm.Classy", 
srcLocFile = "src/Cardano/Prelude/GHC/Heap/NormalForm/Classy.hs", srcLocStartLine = 424, srcLocStartCol = 44, 
srcLocEndLine = 424, srcLocEndCol = 70})], unexpectedThunkClosure = Just "ThunkClosure {info = StgInfoTable {entry = 
Nothing, ptrs = 4, nptrs = 0, tipe = THUNK, srtlen = 81781936, code = Nothing}, ptrArgs = 
[0x000000420daeea98,0x000000420daeeb10,0x00000042119f8c68,0x000000420250cb38], dataArgs = []}"}

The leak appears when we open the ChainDB and stream blocks from the Immutable DB to the Ledger DB for validation. I noticed that the older the ledger snapshot we start, the bigger the memory peak.

What actually happens is that because of laziness the validation is basically split in two parts:

• read every block from the db leading to a big memory peak and do all other actions like logging
• apply each block to the ledger db, which is a pure procedure.

Only after the ledger DB application starts, the gc is free to collect the blocks and the PINNED memory starts to decrease after the peak. This is more apparent on this graph

compute, which does all the ledger transitions fires up only after all PINNED memory is allocated.

The fix forces the ledger transitions to happen strictly. The new memory result:

The PINNED memory is quickly garbage collected and never goes above 12MB:

I'll come back with some more details on this.

[mrBliss]

Great find and nice graphs to show it! Strange that we hadn't noticed that before 🤔

I actually think that the cause of this leak is not that obvious and that adding that bang is not the ideal solution, because to me, it doesn't make sense that that bang fixes it. Let me explain:

We replay blocks using initStartWith:

https://github.com/input-output-hk/ouroboros-network/blob/595a4c2b3385b5dac214ba74501d1980e6d14bd6/ouroboros-consensus/src/Ouroboros/Consensus/Storage/LedgerDB/OnDisk.hs#L255-L264

Note the !(!db, !replayed), these bangs (yes, we need all of them, try it out in GHCi!) should already force the result of ledgerDbPush (see definition below) to WHNF, which, for LedgerDB, we know implies NF.
https://github.com/input-output-hk/ouroboros-network/blob/595a4c2b3385b5dac214ba74501d1980e6d14bd6/ouroboros-consensus/src/Ouroboros/Consensus/Storage/LedgerDB/InMemory.hs#L740-L745

which calls pushLedgerState:
https://github.com/input-output-hk/ouroboros-network/blob/a3b0e26733d01ef19e5e22b830586d23ebec8b7c/ouroboros-consensus/src/Ouroboros/Consensus/Storage/LedgerDB/InMemory.hs#L619-L622

which calls prune:
https://github.com/input-output-hk/ouroboros-network/blob/a3b0e26733d01ef19e5e22b830586d23ebec8b7c/ouroboros-consensus/src/Ouroboros/Consensus/Storage/LedgerDB/InMemory.hs#L601-L609

The implementation of prune looks fine. Those bangs in push (in initStartingWith) force the result of ledgerDbPush (remember that it's a loop, see streamAll) to WHNF, which forces the result of pushLedgerState to WHNF, which forces the result of prune and thus the LedgerDB to WHNF. So to me, that extra bang before prune doesn't make much sense. Question: @kderme was this the first bang you added or did you find it by trial & error?

I am convinced that there is no reason for that bang having to be there, instead, I believe (Edsko is not entirely convinced of this), that this is due to a GHC bug! We first described it in: IntersectMBO/ouroboros-consensus#741. See the following two workaround we have in place for it:
https://github.com/input-output-hk/ouroboros-network/blob/a49b29ac8d9bfb7a45e2f15a728ef01ebd790a0f/ouroboros-consensus/src/Ouroboros/Consensus/Protocol/PBFT/State.hs#L654-L661
https://github.com/input-output-hk/ouroboros-network/blob/4772c92500da1fe51e32c8da44ee6dca61b196b2/ouroboros-consensus/src/Ouroboros/Consensus/Storage/ImmutableDB/Impl/Index/Cache.hs#L269-L289

And in this instance, we can apply the same workaround, i.e., remove the extra bang from this PR, add {-# INLINE prune #-} (with the same explanation as the two examples above) or {-# OPTIONS_GHC -fno-strictness #-}. I prefer the former, as it should be better for performance. I have confirmed that either of the two pragmas fix the problem without needing an extra bang. Can you apply the INLINE workaround?

This might also explain why we hadn't noticed it before: I believe it's a bug in the strictness analyser that can be triggered by changes in the related code. So when we made some changes to that module, which shouldn't affect the evaluation of the computation, we might have accidentally triggered the bug from that moment on. Note that this is a very similar piece of code as the other two examples: we're updating a field from a record!

I'm hoping that this bug is fixed in newer GHC versions 🤞 (if I want to report it, I should also reproduce it first with the most recent release). We're slowly working towards switching to a newer GHC version (e.g., IntersectMBO/cardano-prelude#121, IntersectMBO/cardano-base#157).

[kderme]

Question: @kderme was this the first bang you added or did you find it by trial & error?

I first added this bang pattern to the argument pushLedgerState !current' ref, because noUnexpectedThunks shows that ledgerDbCurrent is a thunk (which is weird since it is a strict field). It worked equally well with the pr. I assumed that it was needed because prune is not strict on its argument, so I finally made this strict instead. Actually the bang pattern I add is not really necessary. db' = db { ... works equally well.

I found a very similar issue here https://www.reddit.com/r/haskell/comments/3hvrm9/a_haskell_space_leak/cubp2on
The fix is the same as ours and also not a good explanation is given, why it's needed. I'm also puzzled why it is necessary.

[mrBliss]

Question: @kderme was this the first bang you added or did you find it by trial & error?

I first added this bang pattern to the argument pushLedgerState !current' ref, because noUnexpectedThunks shows that ledgerDbCurrent is a thunk (which is weird since it is a strict field). It worked equally well with the pr.

Yeah, that's fighting the symptom. As you say, it's weird since it's a strict field.

I assumed that it was needed because prune is not strict on its argument, so I finally made this strict instead.

It shouldn't matter that prune is strict in its argument when the eventual caller of prune is strict in the result.

For example:

-- | Lazy in its argument
f :: Int -> Int
f  x = x + 1

-- Strict in the result: it doesn't matter that we're calling a lazy function
-- as long as forcing the result means that we evaluate all thunks in it
> let !y = f undefined in True
*** Exception: Prelude.undefined

Actually the bang pattern I add is not really necessary. db' = db { ... works equally well.

Bingo, this confirms that the bang is not needed and fits with my theory that it's a GHC bug.

I found a very similar issue here https://www.reddit.com/r/haskell/comments/3hvrm9/a_haskell_space_leak/cubp2on
The fix is the same as ours and also not a good explanation is given, why it's needed. I'm also puzzled why it is necessary.

I'm not sure that's the same thing: they refer to values again after traversing it, which means that values must be kept in memory instead of releasing it so it can be GC'ed. In pushLedgerState, we're not holding onto anything unnecessarily.

[kderme]

Actually I compiled a new clone without any profiling flags and I don't see any big memory usage with top. This makes me think that profiling somehow affects laziness in this case. If I'm not mistaken, this shouldn't happen and is a ghc bug. I was wondering if we can do some changes to ensure we don't depend on any ghc optimizations/bugs here, since the result can be pretty ugly.

[mrBliss]

Actually I compiled a new clone without any profiling flags and I don't see any big memory usage with top. This makes me think that profiling somehow affects laziness in this case. If I'm not mistaken, this shouldn't happen and is a ghc bug. I was wondering if we can do some changes to ensure we don't depend on any ghc optimizations/bugs here, since the result can be pretty ugly.

Ideally, yes, but I don't know which changes that would be. It would be great if a newer GHC version just fixes it, then we wouldn't need to do anything. In the meantime, I suggest we do what I have done for the other two instances of this issue: add an INLINE pragma and a comment.

[mrBliss]

bors merge

[iohk-bors]

Build succeeded

• ci/hydra:Cardano:ouroboros-network:required
• buildkite/ouroboros-network

[mrBliss]

I found another instance of this: https://github.com/input-output-hk/ouroboros-network/blob/2988a234ef65f7a7c973fa8dd9d8b234bf910891/ouroboros-consensus/src/Ouroboros/Consensus/MiniProtocol/ChainSync/Client.hs#L18-L21

[nfrisby]

Actually I compiled a new clone without any profiling flags and I don't see any big memory usage with top. This makes me think that profiling somehow affects laziness in this case. If I'm not mistaken, this shouldn't happen and is a ghc bug.

Yikes :(

It has unfortunately been true for many years that compiling with profiling can interfere with some optimizations. (My general assumption is that the special nodes that profiling adds to the AST spoil some tree patterns that would otherwise trigger various optimizations.)

Edit: SPJ said "Profiling disables all sorts of optimisations. Think of it as compiling without -O." on a ticket 9 years ago. I didn't easily find an obvious "profiling disables optimizations" GHC ticket :( -- in particular, I haven't found a list of optimizations that usually suffer.

The description of http://hackage.haskell.org/package/ghc-events-analyze alludes to this.

It is very useful for profiling code when ghc's normal profiling mode is not available, or when using profiling mode would perturb the code too much.

So if I you find a similar enormous space-leak, it may be worthwhile to first attempt to reproduce similar stats without -prof. For example, just with +RTS -s or +RTS -S or the GHC event logs. 🤞 that might save some of your time.

[kderme]

To make matters worse my initial graphs from the .hp format file were kinda distorted towards the left

compared to my first graph above https://user-images.githubusercontent.com/11467473/90975548-d951bd80-e53d-11ea-96c5-4809c0cee53e.png which is from the ghc eventlog. This satanically made the peak appear within a couple seconds of the epoch boundary.

I'm not sure why the .hp format file was wrong, my wild guess is that some time dedicated to profiling is subtracted from the real time, trying to make it more realistic.