Open amesgen opened 8 months ago
A quick comment.
Don't take ledger snapshots around the time the node is elected.
That may prove to be a useful workaround in the short-term, but our separation of concerns-based goal has so far been to avoid this sort of design (anything that changes the node's behavior based on the upcoming leadership schedule).
Incrementalising the creation of ledger snapshots. Specifically, this could be achieved by introducing a delay between writing individual chunks of the snapshot to disk. One hope here is that by spreading out the allocation work over a longer period of time (default GC interval is 72min), the total time spent GCing will be less, but a priori, it might just be the case that we miss as many slots as before, just spread out more evenly over a longer period of time.
It seems fair to assumed the leadership check thread is starved of CPU while the snapshot is being taken. I think there are two a priori suspects who might be occupying the CPU during that time:
If the GC pauses are greater than a second, then it's entirely possible the leadership check doesn't have CPU time during the elected slot. If we incrementalize the snapshotting work, then perhaps the lower allocation rate will allow for smaller GC pauses, ideally sub-second (ie sub-slot).
Generally the RTS scheduler is fair, so I wouldn't expect the snapshotting threads (busy while taking the snapshot) would be able to starve the leadership check thread. But I list them anyway because maybe something about the computation is not playing nice with the RTS's preemption. (Examples include a long-running pure calculation that doesn't allocate, but I don't anticipate that in this particular case. Maybe some "FFI" stuff? I'm unsure how the file is actually written.)
The lack of fairness in STM shouldn't matter here. The leadership check thread only reads the current chain, which shouldn't be changing so rapidly to incur contention among STM transactions that depend on it.
The heap profile shows that the spikes are dominated by pinned memory (ARR_WORDS
):
However, we also see allocations of Data.Map
and Data.Set
:
We will discuss with the Ledger team possible ways to avoid these allocations.
There are possible culprits for the increase in CPU and memory usage, and GC time:
Data.Map
.@lehins will look into 1 and 2, to see how much work they would require. As for 0 this is something we could do at the Consensus side.
@coot suggested we could also use info tables profiling to extract more information.
Regarding 0, we are writing a lazy ByteString
to disk, so we are not building a huge ByteString
before writing it to disk, but instead, we are writing it chunk by chunk:
writeSnapshot ::
forall m blk. MonadThrow m
=> SomeHasFS m
-> (ExtLedgerState blk -> Encoding)
-> DiskSnapshot
-> ExtLedgerState blk -> m ()
writeSnapshot (SomeHasFS hasFS) encLedger ss cs = do
withFile hasFS (snapshotToPath ss) (WriteMode MustBeNew) $ \h ->
void $ hPut hasFS h $ CBOR.toBuilder (encode cs)
where
encode :: ExtLedgerState blk -> Encoding
encode = encodeSnapshot encLedger
-- | This function makes sure that the whole 'Builder' is written.
--
-- The chunk size of the resulting 'BL.ByteString' determines how much memory
-- will be used while writing to the handle.
hPut :: forall m h
. (HasCallStack, Monad m)
=> HasFS m h
-> Handle h
-> Builder
-> m Word64
hPut hasFS g = hPutAll hasFS g . BS.toLazyByteString
I tried using hPutBuilder
(using this branch) to check whether it would reduce memory usage by avoiding the allocation of chunks of bytestrings, but it did not seem to help.
The following screenshot shows the heap profile, which is started before taking a snapshot of the ledger state:
The first spike related to encoders appears on the 3rd page of the "Detailed" tab, and takes only 40 MB
A second of db-analyser
built without the profiling
flag does not seem to exhibit the spikes observed above
We also observe a very low productivity during the run above:
[426.09964258s] Started StoreLedgerStateAt (SlotNo 72436908)
[442.253250968s] BlockNo 7793000 SlotNo 72343251
[473.668029643s] BlockNo 7794000 SlotNo 72364115
[504.554850119s] BlockNo 7795000 SlotNo 72384162
[544.457781846s] BlockNo 7796000 SlotNo 72405218
[568.979508903s] BlockNo 7797000 SlotNo 72425439
....
[933.002690111s] Snapshot stored at SlotNo 72436985
[933.00286017s] Snapshot was created at SlotNo 72436985 because there was no block forged at requested SlotNo 72436908
[933.00319006s] Done
ImmutableDB tip: At (Block {blockPointSlot = SlotNo 109730906, blockPointHash = c51616e6e4eefa40d13f5d0f9a47371f50d01ce760e3b8f0d0add212449e9b12})
216,427,440,776 bytes allocated in the heap
1,487,832,561,768 bytes copied during GC
3,344,035,160 bytes maximum residency (684 sample(s))
122,786,736 bytes maximum slop
6465 MiB total memory in use (0 MiB lost due to fragmentation)
Tot time (elapsed) Avg pause Max pause
Gen 0 6211 colls, 6211 par 22.448s 22.395s 0.0036s 0.0370s
Gen 1 684 colls, 683 par 1208.587s 852.713s 1.2467s 1.8203s
Parallel GC work balance: 90.70% (serial 0%, perfect 100%)
TASKS: 7 (1 bound, 6 peak workers (6 total), using -N2)
SPARKS: 0 (0 converted, 0 overflowed, 0 dud, 0 GC'd, 0 fizzled)
INIT time 0.263s ( 0.263s elapsed)
MUT time 58.518s ( 58.299s elapsed)
GC time 1231.035s (875.108s elapsed)
EXIT time 0.000s ( 0.010s elapsed)
Total time 1289.816s (933.680s elapsed)
Alloc rate 3,698,500,665 bytes per MUT second
Productivity 4.5% of total user, 6.2% of total elapsed
Processing 20K blocks and storing 3 snapshots corresponding to the last 3 blocks that were applied results in the following heap profile:
The "Detailed" tab seems to show PulsingReward
as allocating a large portion of data:
The branch used to obtain these results can be found here.
The profile can be produced by running:
cabal run exe:db-analyser -- cardano --config $NODE_HOME/configuration/cardano/mainnet-config.json --db $NODE_HOME/mainnet/db --analyse-from 72316896 --only-immutable-db --store-ledger 72336896 +RTS -hi -s -l-agu
NODE_HOME
points to the directory where the node was run (which contains the chain database).
@dnadales could you run it once more, with the https://hackage.haskell.org/package/base-4.19.1.0/docs/GHC-Stats.html#v:getRTSStats dump before and after each of the ledger snapshots being written?
A thought for a quick-fix partial mitigation to help out users until we eliminate the underlying performance bug: we could take snapshots much less often. The default interval is 72min. The nominal expectation for that duration is 216 new blocks arising. If we increased the interval to 240 minutes, then the expectation would be 720 blocks. The initializing node should still be able to re-process that many blocks in less than a few minutes (my recollection is that deserializing the ledger state snapshot file is far and away the dominant factor in startup-time).
^^^ that all assumes we're considering a node that is already caught-up. A syncing node would have processed many more blocks than 216 during a 72min interval. But the argument above does suggest it would be relatively harmless for a caught-up node to use a inter-snapshot duration of 240min. (Moreover, I don't immediately see why it couldn't even be 10 times that or more. But that seems like a big change, so I hesitate to bless it without giving it much more thought.)
(The interval is the first DiskPolicyArgs
, exposed as of https://github.com/IntersectMBO/ouroboros-consensus/pull/943 . I'm unsure what name the Node code uses for that in the JSON files etc.)
@dnadales could you run it once more, with the https://hackage.haskell.org/package/base-4.19.1.0/docs/GHC-Stats.html#v:getRTSStats dump before and after each of the ledger snapshots being written?
Sure thing:
GC stats before snapshot
Total number of GCs: 6632
Total number of major GCs: 21
Allocated bytes: 195637928136
Copied bytes: 26769009240
Total GC CPU time: 22224343455
Total elapsed GC time: 18213635966
GC stats afterq snapshot
Total number of GCs: 8939
Total number of major GCs: 26
Allocated bytes: 286259560712
Copied bytes: 60956628280
Total GC CPU time: 47662376906
Total elapsed GC time: 38520211470
[120.563698243s] Snapshot stored at SlotNo 72727294
GC stats before snapshot
Total number of GCs: 8939
Total number of major GCs: 26
Allocated bytes: 286259560712
Copied bytes: 60956628280
Total GC CPU time: 47662376906
Total elapsed GC time: 38520211470
GC stats afterq snapshot
Total number of GCs: 11201
Total number of major GCs: 31
Allocated bytes: 375574341072
Copied bytes: 93958305552
Total GC CPU time: 70104502875
Total elapsed GC time: 57027413813
[155.701501429s] Snapshot stored at SlotNo 72727306
GC stats before snapshot
Total number of GCs: 11201
Total number of major GCs: 31
Allocated bytes: 375574341072
Copied bytes: 93958305552
Total GC CPU time: 70104502875
Total elapsed GC time: 57027413813
GC stats afterq snapshot
Total number of GCs: 13464
Total number of major GCs: 36
Allocated bytes: 464890139512
Copied bytes: 126969005864
Total GC CPU time: 93114399263
Total elapsed GC time: 76153926493
[191.899606387s] Snapshot stored at SlotNo 72727311
Elapsed time after snapshot 1: 20.306575504
Elapsed time between snapshot 1 and 2: 0
Elapsed time after snapshot 2: 18.507202343
Elapsed time between snapshot 2 and 3: 0
Elapsed time after snapshot 3: 19.12651268
I've created:
CC: @teodanciu @lehins @TimSheard
@TimSheard suggested we could try increasing the pulse size in this line (eg by doubling it) , and re-run this experiment again.
@TimSheard would like to know what the protocol parameters are during this run.
We could also re-run the experiment with a GHC build that has info table built into the base libraries, or using different h
options.
And also, it might be useful to make sure we cross epoch boundaries.
FTR, Ledger experiment on avoiding forcing the pulser when serializing a ledger state https://github.com/IntersectMBO/cardano-ledger/pull/4196
Problem description
John Lotoski informed us that currently on Cardano mainnet, adequately resourced nodes (well above minimum specs) are missing lots of leadership checks during ledger snapshots.
Concretely, during every ledger snapshot (performed every
2k seconds = 72min
by default), which takes about ~2min, the node misses ~30 leadership checks with 32GB RAM, and ~100 with 16GB RAM. This means that the node is missing ~0.7-2.3% of its leadership opportunities, and without mitigations, this number will likely grow as the size of the ledger state increases over time.This problem is not a new one, it has existed since at least node 8.0.0 (and likely even before).
Analysis
Various experiments (credits to John Lotoski) indicate that this problem is due to high GC load/long GC pauses while taking a ledger snapshot (current mainnet size is ~2.6GB serialized). The main reasons for this belief are:
Using
--nonmoving-gc
fixes the problem for some time.[^1]Judging from a 6h log excerpt, both GC time and missed slots increase greatly during a ledger snapshot:
(GC time comes from
gc_cpu_ns
)Changing other aspects of the machine running the node (compute, IOPS) has no effect.
[^1]: Quoting from John Lotoski:
Potential mitigations
Several orthogonal mitigation options have been raised:
--nonmoving-gc
on a more recent GHC is enough, see [^1].ByteString
) chunks?Note that UTxO HD will also help, but it will likely not be used for some time by block producers (where this is issue is actually important).
The goal of this ticket is to interact with other teams/stakeholders to identify the best way forward here.