OOM Error Direct Buffer when using mong-java-driver's MongoClients.create

[Frank van Meeuwen]

Hello,

We are using the synchronous mongo-java-driver client and recently switched to version 3.9.0 without any problems. (We use mongo server version 3.4.14)

In a separate attempt we tried to switched to the recommended way of creating a mongoClient, by using "com.mongodb.client.MongoClients.create()" , which was before: "new com.mongodb.MongoClient()

Old way which is working ok: 

new com.mongodb.MongoClient(new MongoClientURI(config.mongoDbUri, MongoClientOptions.builder().applicationName("APP")))

Recommended way, causing memory leak: 

com.mongodb.client.MongoClients.create(MongoClientSettings.builder().applicationName("APP").applyConnectionString(new ConnectionString(config.mongoDbUri)).build())

Quite suprisingly, after this change we started noticing OOM exception related to DirectBuffer memory throughout the application: "Exception in thread "XNIO-1 task-90" java.lang.OutOfMemoryError: Direct buffer memory".

When monitoring the direct buffer memory usage jmx metric, we started to notice that with this change the direct buffer memory usage grows quite rapidly, until eventually reaching the limit of 2GB and causing OOM exceptions. Without the change the direct memory usage is constant 30mb.

A couple of questions arise

Wat exactly is the difference between those two ways of constructing a MongoClient? Are there different defaults when using MongoClientOptions versus MongoClientSettings? What could possibly cause this memory leak? etc.

Kind regards,

Frank van Meeuwen

[Jeff Yemin]

This is definitely not something we've seen before.  And it's quite surprising because in neither case does the driver call java.nio.ByteBuffer#allocateDirect.  All ByteBuffer instances are allocated via java.nio.ByteBuffer#allocate

To help us diagnose, can you please share your connection string (replacing host names and credentials with fake values, of course)?  I want to make sure there aren't any query parameters that are being ignored in one configuration and applied in the other.

Also, what's the full name of the direct memory usage JMX metric that you are monitoring?  It's not something that I'm familiar with.

Regards,

Jeff Yemin

[Frank van Meeuwen]

Hey Yeff,

Thanks for helping out, it is indeed strange. We encountered the OOM Exception in different places of the application, both in the mongo client and in undertow, which also uses direct buffers. Below are two stracktraces which I think comes from the mongo client.

ConnectionString:

 mongodb://user:password@host1:27001,host2:27001,host2:27001/?replicaSet=replicaSet&authSource=admin&authMechanism=SCRAM-SHA-1"

JMX Metric:

We use the prometheus client, where we monitor the metric 'jvm_buffer_pool_used_bytes{pool="direct"}'. Looking at the PrometheusClient code it seems this is the "java.lang.management.BufferPoolMXBean" with the name "direct" and the value of the metric populated by "getMemoryUsed".

Here is a full stack trace:

Nov 18 03:41:53 host1 docker||[1890]: 2018-11-18 03:41:53,323 [APP-akka.actor.default-dispatcher-102] WARN akka.stream.scaladsl.RestartWithBackoffSource Restarting graph due to failure. stack_trace:
Nov 18 03:41:53 host1 docker||[1890]: com.mongodb.MongoInternalException: Unexpected exception
Nov 18 03:41:53 host1 docker||[1890]: at com.mongodb.internal.connection.InternalStreamConnection.translateReadException(InternalStreamConnection.java:549)
Nov 18 03:41:53 host1 docker||[1890]: at com.mongodb.internal.connection.InternalStreamConnection.receiveMessage(InternalStreamConnection.java:428)
Nov 18 03:41:53 host1 docker||[1890]: at com.mongodb.internal.connection.InternalStreamConnection.receiveCommandMessageResponse(InternalStreamConnection.java:289)
Nov 18 03:41:53 host1 docker||[1890]: at com.mongodb.internal.connection.InternalStreamConnection.sendAndReceive(InternalStreamConnection.java:255)
Nov 18 03:41:53 host1 docker||[1890]: at com.mongodb.internal.connection.UsageTrackingInternalConnection.sendAndReceive(UsageTrackingInternalConnection.java:99)
Nov 18 03:41:53 host1 docker||[1890]: at com.mongodb.internal.connection.DefaultConnectionPool$PooledConnection.sendAndReceive(DefaultConnectionPool.java:444)
Nov 18 03:41:53 host1 docker||[1890]: at com.mongodb.internal.connection.CommandProtocolImpl.execute(CommandProtocolImpl.java:72)
Nov 18 03:41:53 host1 docker||[1890]: at com.mongodb.internal.connection.DefaultServer$DefaultServerProtocolExecutor.execute(DefaultServer.java:200)
Nov 18 03:41:53 host1 docker||[1890]: at com.mongodb.internal.connection.DefaultServerConnection.executeProtocol(DefaultServerConnection.java:269)
Nov 18 03:41:53 host1 docker||[1890]: at com.mongodb.internal.connection.DefaultServerConnection.command(DefaultServerConnection.java:131)
Nov 18 03:41:53 host1 docker||[1890]: at com.mongodb.internal.connection.DefaultServerConnection.command(DefaultServerConnection.java:123)
Nov 18 03:41:53 host1 docker||[1890]: at com.mongodb.operation.QueryBatchCursor.getMore(QueryBatchCursor.java:222)
Nov 18 03:41:53 host1 docker||[1890]: at com.mongodb.operation.QueryBatchCursor.hasNext(QueryBatchCursor.java:115)
Nov 18 03:41:53 host1 docker||[1890]: at com.mongodb.client.internal.MongoBatchCursorAdapter.hasNext(MongoBatchCursorAdapter.java:54)
Nov 18 03:41:53 host1 docker||[1890]: at scala.collection.convert.Wrappers$JIteratorWrapper.hasNext(Wrappers.scala:39)
Nov 18 03:41:53 host1 docker||[1890]: at scala.collection.Iterator.foreach(Iterator.scala:929)
Nov 18 03:41:53 host1 docker||[1890]: at scala.collection.Iterator.foreach$(Iterator.scala:929)
Nov 18 03:41:53 host1 docker||[1890]: at scala.collection.AbstractIterator.foreach(Iterator.scala:1417)
Nov 18 03:41:53 host1 docker||[1890]: at scala.collection.IterableLike.foreach(IterableLike.scala:71)
Nov 18 03:41:53 host1 docker||[1890]: at scala.collection.IterableLike.foreach$(IterableLike.scala:70)
Nov 18 03:41:53 host1 docker||[1890]: at scala.collection.AbstractIterable.foreach(Iterable.scala:54)
Nov 18 03:41:53 host1 docker||[1890]: at scala.collection.TraversableLike.map(TraversableLike.scala:234)
Nov 18 03:41:53 host1 docker||[1890]: at scala.collection.TraversableLike.map$(TraversableLike.scala:227)
Nov 18 03:41:53 host1 docker||[1890]: at scala.collection.AbstractTraversable.map(Traversable.scala:104)
Nov 18 03:41:53 host1 docker||[1890]: at io.dhlparcel.sources.ExpiredSourcesRemover.deleteBatch(ExpiredSourcesRemover.scala:43)
Nov 18 03:41:53 host1 docker||[1890]: at io.dhlparcel.sources.ExpiredSourcesRemover.$anonfun$source$1(ExpiredSourcesRemover.scala:59)
Nov 18 03:41:53 host1 docker||[1890]: at io.dhlparcel.sources.ExpiredSourcesRemover.$anonfun$source$1$adapted(ExpiredSourcesRemover.scala:59)
Nov 18 03:41:53 host1 docker||[1890]: at akka.stream.impl.fusing.Map$$anon$9.onPush(Ops.scala:51)
Nov 18 03:41:53 host1 docker||[1890]: at akka.stream.impl.fusing.GraphInterpreter.processPush(GraphInterpreter.scala:519)
Nov 18 03:41:53 host1 docker||[1890]: at akka.stream.impl.fusing.GraphInterpreter.processEvent(GraphInterpreter.scala:482)
Nov 18 03:41:53 host1 docker||[1890]: at akka.stream.impl.fusing.GraphInterpreter.execute(GraphInterpreter.scala:378)
Nov 18 03:41:53 host1 docker||[1890]: at akka.stream.impl.fusing.GraphInterpreterShell.runBatch(ActorGraphInterpreter.scala:588)
Nov 18 03:41:53 host1 docker||[1890]: at akka.stream.impl.fusing.GraphInterpreterShell$AsyncInput.execute(ActorGraphInterpreter.scala:472)
Nov 18 03:41:53 host1 docker||[1890]: at akka.stream.impl.fusing.GraphInterpreterShell.processEvent(ActorGraphInterpreter.scala:563)
Nov 18 03:41:53 host1 docker||[1890]: at akka.stream.impl.fusing.ActorGraphInterpreter.akka$stream$impl$fusing$ActorGraphInterpreter$$processEvent(ActorGraphInterpreter.scala:745)
Nov 18 03:41:53 host1 docker||[1890]: at akka.stream.impl.fusing.ActorGraphInterpreter$$anonfun$receive$1.applyOrElse(ActorGraphInterpreter.scala:760)
Nov 18 03:41:53 host1 docker||[1890]: at akka.actor.Actor.aroundReceive(Actor.scala:517)
Nov 18 03:41:53 host1 docker||[1890]: at akka.actor.Actor.aroundReceive$(Actor.scala:515)
Nov 18 03:41:53 host1 docker||[1890]: at akka.stream.impl.fusing.ActorGraphInterpreter.aroundReceive(ActorGraphInterpreter.scala:670)
Nov 18 03:41:53 host1 docker||[1890]: at akka.actor.ActorCell.receiveMessage(ActorCell.scala:588)
Nov 18 03:41:53 host1 docker||[1890]: at akka.actor.ActorCell.invoke(ActorCell.scala:557)
Nov 18 03:41:53 host1 docker||[1890]: at akka.dispatch.Mailbox.processMailbox(Mailbox.scala:258)
Nov 18 03:41:53 host1 docker||[1890]: at akka.dispatch.Mailbox.run(Mailbox.scala:225)
Nov 18 03:41:53 host1 docker||[1890]: at akka.dispatch.Mailbox.exec(Mailbox.scala:235)
Nov 18 03:41:53 host1 docker||[1890]: at akka.dispatch.forkjoin.ForkJoinTask.doExec(ForkJoinTask.java:260)
Nov 18 03:41:53 host1 docker||[1890]: at akka.dispatch.forkjoin.ForkJoinPool$WorkQueue.runTask(ForkJoinPool.java:1339)
Nov 18 03:41:53 host1 docker||[1890]: at akka.dispatch.forkjoin.ForkJoinPool.runWorker(ForkJoinPool.java:1979)
Nov 18 03:41:53 host1 docker||[1890]: at akka.dispatch.forkjoin.ForkJoinWorkerThread.run(ForkJoinWorkerThread.java:107)
Nov 18 03:41:53 host1 docker||[1890]: Caused by: java.lang.OutOfMemoryError: Direct buffer memory
Nov 18 03:41:53 host1 docker||[1890]: at java.nio.Bits.reserveMemory(Bits.java:694)
Nov 18 03:41:53 host1 docker||[1890]: at java.nio.DirectByteBuffer.<init>(DirectByteBuffer.java:123)
Nov 18 03:41:53 host1 docker||[1890]: at java.nio.ByteBuffer.allocateDirect(ByteBuffer.java:311)
Nov 18 03:41:53 host1 docker||[1890]: at sun.nio.ch.Util.getTemporaryDirectBuffer(Util.java:241)
Nov 18 03:41:53 host1 docker||[1890]: at sun.nio.ch.IOUtil.read(IOUtil.java:195)
Nov 18 03:41:53 host1 docker||[1890]: at sun.nio.ch.SocketChannelImpl.read(SocketChannelImpl.java:380)
Nov 18 03:41:53 host1 docker||[1890]: at com.mongodb.internal.connection.SocketChannelStream.read(SocketChannelStream.java:113)
Nov 18 03:41:53 host1 docker||[1890]: at com.mongodb.internal.connection.InternalStreamConnection.receiveResponseBuffers(InternalStreamConnection.java:562)
Nov 18 03:41:53 host1 docker||[1890]: at com.mongodb.internal.connection.InternalStreamConnection.receiveMessage(InternalStreamConnection.java:425)
Nov 18 03:41:53 host1 docker||[1890]: ... 46 more
Nov 18 03:41:53 host1 docker||[1890]:

And another one:

Nov 17 16:16:23 host1 docker||22e811e5d94a[1890]: 2018-11-17 16:16:23,203 [XNIO-2 task-49] ERROR Handler com.mongodb.MongoInternalException ,for request: "".
Nov 17 16:16:23 host1 docker||22e811e5d94a[1890]: com.mongodb.MongoInternalException: Unexpected exception
Nov 17 16:16:23 host1 docker||22e811e5d94a[1890]: at com.mongodb.internal.connection.InternalStreamConnection.translateReadException(InternalStreamConnection.java:549)
Nov 17 16:16:23 host1 docker||22e811e5d94a[1890]: at com.mongodb.internal.connection.InternalStreamConnection.receiveMessage(InternalStreamConnection.java:428)
Nov 17 16:16:23 host1 docker||22e811e5d94a[1890]: at com.mongodb.internal.connection.InternalStreamConnection.receiveCommandMessageResponse(InternalStreamConnection.java:289)
Nov 17 16:16:23 host1 docker||22e811e5d94a[1890]: at com.mongodb.internal.connection.InternalStreamConnection.sendAndReceive(InternalStreamConnection.java:255)
Nov 17 16:16:23 host1 docker||22e811e5d94a[1890]: at com.mongodb.internal.connection.UsageTrackingInternalConnection.sendAndReceive(UsageTrackingInternalConnection.java:99)
Nov 17 16:16:23 host1 docker||22e811e5d94a[1890]: at com.mongodb.internal.connection.DefaultConnectionPool$PooledConnection.sendAndReceive(DefaultConnectionPool.java:444)
Nov 17 16:16:23 host1 docker||22e811e5d94a[1890]: at com.mongodb.internal.connection.CommandProtocolImpl.execute(CommandProtocolImpl.java:72)
Nov 17 16:16:23 host1 docker||22e811e5d94a[1890]: at com.mongodb.internal.connection.DefaultServer$DefaultServerProtocolExecutor.execute(DefaultServer.java:200)
Nov 17 16:16:23 host1 docker||22e811e5d94a[1890]: at com.mongodb.internal.connection.DefaultServerConnection.executeProtocol(DefaultServerConnection.java:269)
Nov 17 16:16:23 host1 docker||22e811e5d94a[1890]: at com.mongodb.internal.connection.DefaultServerConnection.command(DefaultServerConnection.java:131)
Nov 17 16:16:23 host1 docker||22e811e5d94a[1890]: at com.mongodb.internal.connection.DefaultServerConnection.command(DefaultServerConnection.java:123)
Nov 17 16:16:23 host1 docker||22e811e5d94a[1890]: at com.mongodb.operation.CommandOperationHelper.executeWrappedCommandProtocol(CommandOperationHelper.java:242)
Nov 17 16:16:23 host1 docker||22e811e5d94a[1890]: at com.mongodb.operation.CommandOperationHelper.executeWrappedCommandProtocol(CommandOperationHelper.java:233)
Nov 17 16:16:23 host1 docker||22e811e5d94a[1890]: at com.mongodb.operation.CommandOperationHelper.executeWrappedCommandProtocol(CommandOperationHelper.java:136)
Nov 17 16:16:23 host1 docker||22e811e5d94a[1890]: at com.mongodb.operation.FindOperation$1.call(FindOperation.java:702)
Nov 17 16:16:23 host1 docker||22e811e5d94a[1890]: at com.mongodb.operation.FindOperation$1.call(FindOperation.java:696)
Nov 17 16:16:23 host1 docker||22e811e5d94a[1890]: at com.mongodb.operation.OperationHelper.withConnectionSource(OperationHelper.java:462)
Nov 17 16:16:23 host1 docker||22e811e5d94a[1890]: at com.mongodb.operation.OperationHelper.withConnection(OperationHelper.java:406)
Nov 17 16:16:23 host1 docker||22e811e5d94a[1890]: at com.mongodb.operation.FindOperation.execute(FindOperation.java:696)
Nov 17 16:16:23 host1 docker||22e811e5d94a[1890]: at com.mongodb.operation.FindOperation.execute(FindOperation.java:83)
Nov 17 16:16:23 host1 docker||22e811e5d94a[1890]: at com.mongodb.client.internal.MongoClientDelegate$DelegateOperationExecutor.execute(MongoClientDelegate.java:179)
Nov 17 16:16:23 host1 docker||22e811e5d94a[1890]: at com.mongodb.client.internal.MongoIterableImpl.execute(MongoIterableImpl.java:132)
Nov 17 16:16:23 host1 docker||22e811e5d94a[1890]: at com.mongodb.client.internal.MongoIterableImpl.iterator(MongoIterableImpl.java:86)
Nov 17 16:16:23 host1 docker||22e811e5d94a[1890]: at com.mongodb.client.internal.MongoIterableImpl.iterator(MongoIterableImpl.java:39)
Nov 17 16:16:23 host1 docker||22e811e5d94a[1890]:   ....
Nov 17 16:16:23 host1 docker||22e811e5d94a[1890]: at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
Nov 17 16:16:23 host1 docker||22e811e5d94a[1890]: at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
Nov 17 16:16:23 host1 docker||22e811e5d94a[1890]: at java.lang.Thread.run(Thread.java:748)
Nov 17 16:16:23 host1 docker||22e811e5d94a[1890]: Caused by: java.lang.OutOfMemoryError: Direct buffer memory
Nov 17 16:16:23 host1 docker||22e811e5d94a[1890]: at java.nio.Bits.reserveMemory(Bits.java:694)
Nov 17 16:16:23 host1 docker||22e811e5d94a[1890]: at java.nio.DirectByteBuffer.<init>(DirectByteBuffer.java:123)
Nov 17 16:16:23 host1 docker||22e811e5d94a[1890]: at java.nio.ByteBuffer.allocateDirect(ByteBuffer.java:311)
Nov 17 16:16:23 host1 docker||22e811e5d94a[1890]: at sun.nio.ch.Util.getTemporaryDirectBuffer(Util.java:241)
Nov 17 16:16:23 host1 docker||22e811e5d94a[1890]: at sun.nio.ch.IOUtil.read(IOUtil.java:195)
Nov 17 16:16:23 host1 docker||22e811e5d94a[1890]: at sun.nio.ch.SocketChannelImpl.read(SocketChannelImpl.java:380)
Nov 17 16:16:23 host1 docker||22e811e5d94a[1890]: at com.mongodb.internal.connection.SocketChannelStream.read(SocketChannelStream.java:113)
Nov 17 16:16:23 host1 docker||22e811e5d94a[1890]: at com.mongodb.internal.connection.InternalStreamConnection.receiveResponseBuffers(InternalStreamConnection.java:562)
Nov 17 16:16:23 host1 docker||22e811e5d94a[1890]: at com.mongodb.internal.connection.InternalStreamConnection.receiveMessage(InternalStreamConnection.java:425)
Nov 17 16:16:23 host1 docker||22e811e5d94a[1890]: ... 46 common frames omitted

Kind regards,

Frank van Meeuwen

[Jeff Yemin]

I see what the difference is.  By default the legacy MongoClient ends up using instances of java.net.Socket, while the new MongoClient ends up using instances of java.nio.channels.SocketChannel.  From the stack trace, it's evident that the SocketChannel class is responsible for the allocations of direct buffers.  

In order to further diagnose, please let me know:

* What version of the JDK you are using.  I'm having trouble matching up the line numbers with the versions I have installed locally.

* Whether the jdk.nio.maxCachedBufferSize system property is set, and if so what its value is

* Approximately how many threads that may be executing queries against MongoDB

* Approximate size of the expected query responses (e.g. are you doing large range queries or returning large documents)

One thing to try as well: increase the value of 

-XX:MaxDirectMemorySize

, which I believe defaults to 64M. See https://docs.oracle.com/javase/8/docs/technotes/tools/windows/java.html for a description of this flag.

Regards,

Jeff

[Frank van Meeuwen]

Hey Jeff,

* What version of the JDK you are using.  I'm having trouble matching up the line numbers with the versions I have installed locally.

java -version

java version "1.8.0_181"

Java(TM) SE Runtime Environment (build 1.8.0_181-b13)

Java HotSpot(TM) 64-Bit Server VM (build 25.181-b13, mixed mode)

* Whether the jdk.nio.maxCachedBufferSize system property is set, and if so what its value is

This property is not set. (null)

* Approximately how many threads that may be executing queries against MongoDB

Not sure if I can answer that question accurately, but I do have some jmx metrics from the mongo client itself on the connection pool and commands.

For instance we have between 50-80 open connections, and  the number of checked out connections sometimes reaches 3 and max. 7. The number of commands executed per second varies between 50 and 250.

* Approximate size of the expected query responses (e.g. are you doing large range queries or returning large documents)

The gross of the queries are updates to a single document, insertion of a single document or retrieves of a single document. 

In addition there are frequent delete queries, which will delete around the 5k records every 10 seconds, which are looked up by id.

There are also some large range queries executed but not frequently, they also sometimes lead to a timeout. (We configured 15 sec timeout for them on the client side)

We tried the -XX: MaxDirectMemorySize, but it only restricted the memory size further. Because when leaving it out the limit was 2GB, the same as we have set the-Xmx flag.

Kind regards,

Frank van Meeuwen

[Robert Cochran]

Hi!

What is the output of 

'javac -version'

What version of the MongoDB server are you using? 

What versions of other software are you using?

I don't know much about Docker, but it appears you are using containers based on the output you are posting. Can you give more information about the operating system(s) and version(s) you are using on both the clients and server?

I'm in no way trying to interfere with Jeff's dialogue with you. I just thought it would be useful to clarify the above points. I'll lapse back into silence now and just watch this thread. (Smile)

Thanks so much

Bob

[Frank van Meeuwen]

No problem Bob, I will try to answer most of your questions.

• What is the output of  'javac -version'?
• javac 1.8.0_191
  

• What version of the MongoDB server are you using? 

• 3.4.14
  

• What versions of other software are you using?

• The software is written in scala 2.12.4, most notable other libraries are probably undertow of which we use version 1.4.21.Final, we also use akka version 2.5.16 and jackson version 2.9.1, guava 23.0 and commons-lang3 version 3.7.

• I don't know much about Docker, but it appears you are using containers based on the output you are posting. Can you give more information about the operating system(s) and version(s) you are using on both the clients and server?
  

• A docker image is build for the client application, with as base image `anapsix/alpine-java:8`. The jar is copied there and set as entrypoint. This container runs on a host RedHat Enterprise linux server, with docker version 17.04.0-ce, build 4845c56 installed.

kind regards,

Frank van Meeuwen

Op vr 23 nov. 2018 om 13:35 schreef Robert Cochran <r2coc...@gmail.com>:

--
You received this message because you are subscribed to the Google Groups "mongodb-user"
group.
 
For other MongoDB technical support options, see: https://docs.mongodb.com/manual/support/
---
You received this message because you are subscribed to a topic in the Google Groups "mongodb-user" group.
To unsubscribe from this topic, visit https://groups.google.com/d/topic/mongodb-user/fpe1iBADnIM/unsubscribe.
To unsubscribe from this group and all its topics, send an email to mongodb-user...@googlegroups.com.
To post to this group, send email to mongod...@googlegroups.com.
Visit this group at https://groups.google.com/group/mongodb-user.
To view this discussion on the web visit https://groups.google.com/d/msgid/mongodb-user/8b2dce8f-543f-43a2-9d59-9eee4ed04e03%40googlegroups.com.
For more options, visit https://groups.google.com/d/optout.

[Jeff Yemin]

Have a look at http://www.evanjones.ca/java-bytebuffer-leak.html.  It recommends limiting the size of the cached buffers via the jdk.nio.maxCachedBufferSize system property.  From the comment thread it looks like the setting is available in later patches of Java 8.

Regards,

Jeff

To unsubscribe from this group and all its topics, send an email to mongodb-user+unsubscribe@googlegroups.com.