[0.12.1] High memory usage in MongoDbSystem history

[Daniel Breed]

Hi,

We are using ReactiveMongo 0.12.1 with Mongo 3.0.12 with CR-auth, and we have seen an issue where some of our nodes have a slow memory leak. The high memory usage has happened on about half of our nodes, and on the affected nodes it has grown slowly over the last 3 weeks.

We took a heap dump and it looks like the problem is that the EvictingQueue named "history" within the MongoDBSystem has grown to have 1 million items within it. Having inspected the queue, I can see items with timestamps from 2 weeks ago. I have attached some screenshots from VisualVM showing the EvictingQueue size.

When adding a history item, the logic says this.size() == this.maxSize when checking if an item needs to be removed, so if the size of the collection is 26 or above, it will seemingly leak slowly forever which matches what we have seen. Is it possible that multiple threads have added to the EvictingQueue causing the size of the underlying collection to surpass 25?

[Cédric Chantepie]

Hi,

Thx for reporting that. Will have a look.

Best regards

[Daniel Breed]

Hi,

Thanks for looking into the last issue, I saw your pull request on GitHub, and gave it a try. It looks okay on most of our nodes, but we did run into the below issue which caused the driver to become unresponsive:

2017-03-13 17:08:53.935 INFO [Supervisor-1] Creating connection: Connection-2
2017-03-13 17:08:54.249 INFO [Supervisor-1/Connection-2] Starting the MongoDBSystem akka://reactivemongo/user/Connection-2
2017-03-13 17:43:24.313 INFO [Supervisor-1/Connection-2] Restarting the MongoDBSystem akka://reactivemongo/user/Connection-2: ConnectAll
java.util.NoSuchElementException: null
        at java.util.ArrayDeque.removeFirst(ArrayDeque.java:280)
        at java.util.ArrayDeque.remove(ArrayDeque.java:447)
        at shaded.google.common.collect.EvictingQueue.add(EvictingQueue.java:107)
        at shaded.google.common.collect.EvictingQueue.offer(EvictingQueue.java:91)
        at reactivemongo.core.actors.MongoDBSystem$class.reactivemongo$core$actors$MongoDBSystem$$updateHistory(actors.scala:240)
        at reactivemongo.core.actors.MongoDBSystem$$anonfun$7$$anonfun$apply$6.apply(actors.scala:216)
        at reactivemongo.core.actors.MongoDBSystem$$anonfun$7$$anonfun$apply$6.apply(actors.scala:215)
        at reactivemongo.core.actors.MongoDBSystem$class.reactivemongo$core$actors$MongoDBSystem$$updateNodeSet(actors.scala:993)
        at reactivemongo.core.actors.MongoDBSystem$$anonfun$2.applyOrElse(actors.scala:581)
        at scala.PartialFunction$OrElse.applyOrElse(PartialFunction.scala:170)
        at akka.actor.Actor$class.aroundReceive(Actor.scala:484)
        at reactivemongo.core.actors.LegacyDBSystem.aroundReceive(actors.scala:1254)
        at akka.actor.ActorCell.receiveMessage(ActorCell.scala:526)
        at akka.actor.ActorCell.invoke(ActorCell.scala:495)
        at akka.dispatch.Mailbox.processMailbox(Mailbox.scala:257)
        at akka.dispatch.Mailbox.run(Mailbox.scala:224)
        at akka.dispatch.Mailbox.exec(Mailbox.scala:234)
        at scala.concurrent.forkjoin.ForkJoinTask.doExec(ForkJoinTask.java:260)
        at scala.concurrent.forkjoin.ForkJoinPool$WorkQueue.runTask(ForkJoinPool.java:1339)
        at scala.concurrent.forkjoin.ForkJoinPool.runWorker(ForkJoinPool.java:1979)
        at scala.concurrent.forkjoin.ForkJoinWorkerThread.run(ForkJoinWorkerThread.java:107)
2017-03-13 17:43:24.315 INFO [Supervisor-1/Connection-2] Stopping the MongoDBSystem akka://reactivemongo/user/Connection-2
2017-03-13 17:43:24.329 INFO [Supervisor-1/Connection-2] The MongoDBSystem is restarted akka://reactivemongo/user/Connection-2 (cause: java.util.NoSuchElementException)
2017-03-13 17:43:24.355 INFO [Supervisor-1/Connection-2] Stopping the MongoDBSystem akka://reactivemongo/deadLetters

Thanks,
Dan

[Cédric Chantepie]

Will have a look

[Dmitry Mikhaylov]

Hello!

We've run into the same issue on 0.12.2. History size is set to 25, yet it has grown to 263621 elements and growing. I can provide screenshots of Eclipse memory Analyzer, if needed.

IMHO the problem is that somehow RM runs EvictingQueue.add concurrently, and this breaks size checks in it:

if(this.size() == this.maxSize) {
    this.delegate.remove();
}

Once this.size() becomes over this.maxSize, size check is broken and queue will grow unbounded. EvictingQueue javadoc specifically says

This class is not thread-safe, and does not accept null elements.

This theory is (to some extent) is supported by heap dump analysis, because history entries at indexes 19 to 27 (and entry at index 25 is the first entry over the limit) have exactly the same timestamp:

Based on this analysis, I do not think this changeset actually fixes the problem. IMHO the proper fix would be to synchronize call to add new history entry:

@inline private def updateHistory(event: String): Unit =
  history.synchronized { history.add(System.currentTimeMillis() -> event); () }

_________

BR, Dmitry

[Cédric Chantepie]

Even if the history size is not strictly enforce, an extra eviction is polling the history on NodeSet refresh until the size limit is restored.

As memory profiling doesn't show unrecoverable issue, without a reproducer more retention won't be added.