Cardano node memory leak in 1.3.0 and 1.4.0

[johnalotoski]

Cardano node 1.3.0 is observed to consume increasing amounts of memory and CPU over time until the process OOMs. The following figure illustrates the typical observation:

This is observed on all chains tested. The problem is observed when using the following flags (other combinations may also result in the issue):

--tracing-verbosity-normal --trace-block-fetch-decisions --trace-chain-db --trace-mempool --trace-forge +RTS -N2 -A10m -qg -qb -M3G -RTS

The following figure illustrates the heap profile from one example, where STACK is increasing with time:

With profiling and the -xc option, the following two logging-related exception traces are observed in the console:

*** Exception (reporting due to +RTS -xc): (IND_STATIC), stack trace: 
  Cardano.BM.Counters.Linux.readProcNet,
  called from Cardano.BM.Counters.Linux.takeMeasurements.selectors,
  called from Cardano.BM.Counters.Linux.takeMeasurements.\,
  called from Cardano.BM.Counters.Linux.takeMeasurements,
  called from Cardano.BM.Counters.Linux.readCounters,
  called from Control.Concurrent.Async.asyncUsing.\.\,
  called from Control.Concurrent.Async.asyncUsing.\,
  called from Control.Concurrent.Async.asyncUsing,
  called from Control.Concurrent.Async.async,
  called from Cardano.Config.Logging.startCapturingMetrics,
  called from Cardano.Config.Logging.loggingCardanoFeatureInit,
  called from Cardano.Config.Logging.createLoggingFeature,
  called from Main.initializeAllFeatures,
  called from Cardano.Common.TopHandler.toplevelExceptionHandler,
  called from Main.main

*** Exception (reporting due to +RTS -xc): (THUNK_STATIC), stack trace: 
  Control.Concurrent.Async.Timer.Internal.timerLoop.readCmd,
  called from Control.Concurrent.Async.Timer.Internal.timerLoop,
  called from Control.Concurrent.Async.withAsyncUsing.\.\,
  called from Control.Concurrent.Async.withAsyncUsing.\,
  called from Control.Concurrent.Async.withAsyncUsing,
  called from Control.Concurrent.Async.withAsync,
  called from UnliftIO.Internals.Async.withAsync.\,
  called from Control.Monad.IO.Unlift.withRunInIO,
  called from UnliftIO.Internals.Async.withAsync,
  called from Control.Concurrent.Async.Timer.Internal.withAsyncTimer,
  called from Cardano.BM.Data.MessageCounter.sendAndResetAfter,
  called from Control.Concurrent.Async.asyncUsing.\.\,
  called from Control.Concurrent.Async.asyncUsing.\,
  called from Control.Concurrent.Async.asyncUsing,
  called from Control.Concurrent.Async.async,
  called from Cardano.BM.Backend.Monitoring.spawnDispatcher,
  called from Cardano.BM.Backend.Monitoring.realizefrom,
  called from Cardano.BM.Backend.Monitoring.plugin,
  called from Cardano.Config.Logging.loggingCardanoFeatureInit,
  called from Cardano.Config.Logging.createLoggingFeature,
  called from Main.initializeAllFeatures,
  called from Cardano.Common.TopHandler.toplevelExceptionHandler,
  called from Main.main

When the logging module is disabled from cardano node using the TurnOnLogging = false flag or through direct code change, the leak does not appear.

[mrBliss]

@karknu has shown me how to reproduce it locally. This is not a self-contained solution, though:

• Use this branch: Chainsync benchmark improvements. #455
• Remove the timeout on the (CPU) time or set it very high
• Add the following line after --trace-chain-db \:

  +RTS -A128m -I0 -N2 -n64m -RTS \

• a. Either sync with mainnet by setting the --topology to ${BASEDIR}/configuration/topology-byron-proxy.yaml. This will take a while, so only do it the first time. Or:
  b. Start a server cardano-node with a prepopulated database (by doing a sync with mainnet) as node 0.
• Start a client cardano-node by running the benchmarking/chain-sync/benchmark-chain-sync-mainnet.sh script.
• After 15 minutes or so, the client will consume more than 1.5 GB of memory and this slowly keeps on increasing.

I think this is the memory leak seen in QA, but I'm not 100%.

Interesting: removing the RTS opts (keeping -N2 in place to speed things up) reduces the memory usage significantly. It's inconclusive that removing them fixes the leak, as it might just manifest itself much slower.

[mrBliss]

I think I may have found a possible leak:

https://github.com/input-output-hk/cardano-node/blob/e69aabb146ca1efff15d7d55d6caa92548c59368/cardano-config/src/Cardano/Config/Logging.hs#L256

When I remove the threadDelay (this line) so that the leak manifests itself sooner, I can see the memory usage growing slowly (~200kB/s, I estimate). If I don't spawn the async thread at all, memory usage remains stable.

Reproducing this is very simple: just start up a new node, it doesn't have to sync or do anything. In fact, it not doing anything makes it much easier to spot the leak.

I'm using input-output-hk/iohk-monitoring-framework@d5eb7ee.

UPDATE 1: after 17 min of doing nothing, memory usage went from 562 MB to 929 MB RAM.

UPDATE 2: after further investigation, I have discovered:

• It seems to be specific to node-metrics, i.e., if I trace the counters to trace0 instead of appendName "node-metrics" trace0, I get:

  Error: Switchboard's queue is full, dropping log items!
  

• It's not specific to the counters (or LogValue), the following has the same leak:

  let !txt = Text.replicate (50 * 1024 * 1024) "leak"
  in traceNamedObject trace (mle, LogMessage txt)

• Moreover, it doesn't seem to be related to the size of the messages, but – I expect – to the number of messages, as the memory usage seems to grow at the same rate, regardless the contents of the message.

UPDATE 3: I noticed some things have changed in cardano-node related to the code I'm using to trigger this leak, so I updated to master (e69aabb). Now instead of leaking, also get:

Error: Switchboard's queue is full, dropping log items!

This is due to a change the log-configuration.yaml file I was using to reproduce it, namely:

     cardano.node-metrics:
-      subtrace: NoTrace
+      subtrace: Neutral

My current thinking is that tracing messages to subtrace: NoTrace is causing a memory leak. As the leak is not proportional to the message size (see above), I believe the messages themselves are not being leaked, but the handler that processes the messages leaks a bit of memory per message.

UPDATE 4: the memory leak I found only manifests itself when the LiveView is enabled, with the SimpleView the memory usage remains stable. As the nodes deployed in QA use SimpleView, this means there must be another memory leak.

[i-o-m]

@mrBliss do we think this is resolved now from the posts in SL Benchmarks : )

[mrBliss]

@mrBliss do we think this is resolved now from the posts in SL Benchmarks : )

To be 100% sure, I would wait until QA confirm the leak is gone in their cluster.

Also, is the minor leak I mentioned in my last comment fixed? cc: @CodiePP.

[jbgi]

Some more graph for syncing nodes from clean state on staging, testnet and mainnet running dd3829f:

Block sync speed:

Amount of live data (max "residency")

Allocated memory in RAM (RSS)

Peak memory the RTS as allocated from OS

Graphs have been extracted from this dashboard: https://monitoring.node-tests.dev.iohkdev.io/grafana/d/Oe0reiHef/cardano-application-metrics-v2?orgId=1&from=1579860550287&to=1579867392276
(using nodes staging-1, testnet-1, mainnet-1)

[jbgi]

For people looking into replicating those graph for other version:

1. connect to dev-deployer
2. screen -x
3. got to screen 6 (ctrl+a 6)
4. change cardano-node revision to the desired one, using: niv update cardano-node -a rev=<revision>
5. deploy to one of staging-1, testnet-1 or mainnet-1, while wiping existing state, eg.:

export MACHINE="mainnet-1"
nixops ssh $MACHINE -- 'systemctl stop cardano-node.service && rm -r /var/lib/cardano-node'
nixops deploy --include $MACHINE

6. connect to https://monitoring.node-tests.dev.iohkdev.io/grafana/d/Oe0reiHef/cardano-application-metrics-v2?orgId=1&from=now-30m&to=now&refresh=30s to see graphs