OOM on Light and Bridge nodes

[Wondertan]

I found my mainnet LN getting OOMed a day ago on 8GB DO instance. @renaynay, found here BN ooming on BN with 16GB instance. There is definitely a leak somewhere, and it's likely to exist in the FN as well.

At this point, there is not much info on why it happens, as well as why we haven't seen this on other networks like Arabica, Mocha, and Robusta

[Wondertan]

Right now, I am collecting profiles for further investigation

[Wondertan]

Running it with pprof for a day. No suspicious memory growth was noticed, as well nothing leaky in the profiles.

The only concerning thing is that Badger eats 80% of RAM in various formse

[Wondertan]

Running for another 24 hours with continuous profiling. RAM usage is stable at 1.22 GB with a single spike to 1.91 GB.

Clearly, the leak does not happen under normal conditions, and some edge case has to be triggered to see it. It's unclear what exactly one has to do to trigger it, and I don't see any better idea than to continue profiling and observing.

[Wondertan]

New update. My node oomed again during badger compaction, which bursts ram usage. The node uses around 3GB of RAM right before the compaction, and most of the profiles lead to badger allocations. We have yet to investigate if this is a badgerv4 bug or if we incorrectly use it.

Talking to @Jorropo, he said they observe similar behavior with badger.

[boobcactus]

Just wanted to add that I am experiencing this issue on Arabica using rc6.1. My server has 16GB of memory and the celestia light process will slowly consume until it's OOM

[Wondertan]

I am running the binary again with gomemlimit=2gib and gogc=25 to make runtime more conservative about ram usage

[Jorropo]

Such a low GOMEMLIMIT is equal to:

for {
 runtime.Gc()
 time.Sleep(time.Second)
}

[Wondertan]

@Jorropo, I meant Gib, updated the comment

[Wondertan]

This so far seems to be the leakiest of them all. It looks like badger txs are not cleaned up after Commit. Particularly, the trace comes from peerstoreds's flush.

So seems like there might be a bug in the DS-backed store, or it's the bug in Badger that was fixed in main, but not in the release we use.

[Wondertan]

• I tried with the latest master of Badger to test if the bug has anything to do with this, but it kept leaking
• Out of curiosity, I tried to switch to Pebble, yielding results worth exploring.
  • LN kept syncing with no more than 500mib in use
  • It's not clear if, CPU-wise, the Pebble is more efficient than the Badger
  • Pebble looks like a much better maintained and more approachable code. It's easier to read, and it's very well documented.
  • Pebble provides more knobs to tune up things going further.
  • Code executing sampling eats 3mb instead of 170mb
    • This does not make any sense to me, but that's what profiles show

[boobcactus]

Did you notice any instability after switching to pebble? I'd be interested in building rc6.1 with pebble swapped in if that's possible by an end user (like with a go.mod dependency swap)

(I need to keep my LN running 24/7 for Dymension and it keeps going down, so I'm excited for a solution)

[Wondertan]

Did you notice any instability after switching to pebble

I think it's too early to make any conclusions on stability. I need to run it for at least a week to be sure we don't have any side-effects after switching.

[Wondertan]

Update on the badger: The code leaks in places where we write a single value to the Badger datastore directly, with Put. In places where we use Batch with multiple written it works well.

As an experiment, I tried using Batch inside of Put in go-ds-badger4 adapter, but it didn't yield any result. Profiles show that badger still leaks transactions inside of used batches.

At this point, the only clue we have is a single entry written vs multiple at the same time and this is likely to be a bug inside of the Badger.

[Wondertan]

On pebble:

Simply migrating to pebble made our node consume constantly around 300mibs for LN even during compactions. This is a good result, but we should not rush with migrating as its very disruptive. Also, considering that LNs won't have a high write-load we may also consider a different KV store engine that is not LSM-tree based and much simpler, likely B+ tree.

For now, I think we should focus on figuring out a simple patch for Badger and considering KV store migration in a separate issue.

[Wondertan]

New update on badger:

We were able to break the following by writing an additional entry every time we did a single Put. Even when we write two entries it still leaks.

At this point, the only clue we have is a single entry written vs multiple at the same time and this is likely to be a bug inside of the Badger.

However, there is good news. We were able to accelerate the memory growth by rewriting the value for the same key over and over again. This also aligns with leaking code paths, where we update the state of something with a constant key. So there is enough proof at this point that the bug is in Badger.

The next step is to write a unit test for Badger that shows that and open an issue on their side.

[Wondertan]

The bug is in DetectConflicts feature of Badger. By disabling it, I could get stable RAM usage for over an hour already. 🎉

This aligns with the observation that rewriting the same key causes issues.

[Wondertan]

New final update:

The bug is not in DetectConflicts as I thought. Disabling DetectsConflicts just removes one of the leaks caused by the bug and it still had to be accompanied by some other case because everything was fine when I worked with Badger directly. A pure Badger test for overwriting the same key didn't show any leaks.

But right after DetectConflicts finding, I kept playing with the Badger to the point where I reduced RAM usage during sync up to 10 times(more on that later). This allowed me to detect another more minor leak in Badger that I hadn't realized but had seen before.

After a day of pure debugging, I found the true culprit of all the problems: an edge case in Badger. Check the patch for it here. Basically, when we flush an empty Batch, the transaction inside of the leak is not marked as read. Flushing of an empty Batch happens in DHT's provider manager. When the manager loads the provider set via ds.Query , internally the autobatch wrapper does the Flush. As this query happens on startup, the batch is empty and thus the issue.(cc @Jorropo, this should explain why IPFS observes the leak with Badger as well)

Badger internals of the bug: When we flush a datastore Batch with no data, it would not notify the internal synchronization primitive(Watermark) that the read side of the transaction has ended. The bug surprisingly does not leak the transaction or batch directly, but does not free up resources inside of the Watermark and does not progress the Watermark internal monotonic counter. The leak inside of the Watermark is the minor leak I mentioned in the previous paragraph, and the stalled counter causes the DetectConflicts feature to leak, which is the original leak.

The mystery is solved, and now we need to land the patch and apply all the optimizations I've collected along the way.

P.S. Debug branches:

• https://github.com/celestiaorg/celestia-node/tree/badger-reproducible-bug
• https://github.com/celestiaorg/celestia-node/tree/badger-bump - fixed with optimization and history of all the debug attempts
• https://github.com/celestiaorg/go-ds-badger4/tree/debug - debug branch on datastore adapter
• https://github.com/Wondertan/badger/tree/debug - debug branch on the Badger itself

[Wondertan]

This bug has existed since the start of the celestia-node, literally. We faced it multiple times whenever we played with Badger:

• When we played with an inverted index. It would never have worked out without using a separate badger instance. This bug slows down compaction significantly,
• I remember seeing high y.Watermark mem usage in various profiles in the life span of celestia-node, but I never really analyzed this nor realized it's an issue. Just thought it was a Badger thing. In fact, the y.Watermark should not be visible in profiles.
• I remember @distractedm1nd observed some leak inside Badger that varied based on config values. I am pretty sure it's related to the bug.

[distractedm1nd]

Yes the watermark has to do w GC and we explored seeing watermark in pyroscope before. We fixed the leak but then we changed the badger parameters again recently so it's no longer fixed I assume

[Wondertan]

We fixed the leak but then we changed the badger parameters again recently so it's no longer fixed I assume

The leak has always been there(see above) various badger params only make it less or more severe.