search

apache / pulsar

Apache Pulsar - distributed pub-sub messaging system
https://pulsar.apache.org/
Apache License 2.0
14.23k stars 3.58k forks source link

Out of Memory with many consumers #5896

Closed andrekramer1 closed 1 year ago

andrekramer1 commented 4 years ago

Load testing on one standalone Pulsar with 4 producers and many consumers (1000s) we are getting out of memory errors - failing to allocate direct memory. Increasing memory has not helped with enough producers, Pulsar is failing with exceptions like the following when there are many consumers:

[pulsar-client-io-1-1] WARN org.apache.pulsar.client.impl.ClientCnx - [minnow.apama.com/10.42.100.81:6650] Got exception OutOfMemoryError : GC overhead limit exceeded
java.lang.OutOfMemoryError: GC overhead limit exceeded
        at org.apache.pulsar.shade.io.netty.util.Recycler$Stack.newHandle(Recycler.java:658)
        at org.apache.pulsar.shade.io.netty.util.Recycler.get(Recycler.java:163)
        at org.apache.pulsar.common.api.proto.PulsarApi$MessageIdData$Builder.buildPartial(PulsarApi.java:1339)
        at org.apache.pulsar.common.api.proto.PulsarApi$CommandMessage$Builder.mergeFrom(PulsarApi.java:15892)
        at org.apache.pulsar.common.api.proto.PulsarApi$CommandMessage$Builder.mergeFrom(PulsarApi.java:15745)
        at org.apache.pulsar.common.util.protobuf.ByteBufCodedInputStream.readMessage(ByteBufCodedInputStream.java:124)
        at org.apache.pulsar.common.api.proto.PulsarApi$BaseCommand$Builder.mergeFrom(PulsarApi.java:28839)
        at org.apache.pulsar.common.protocol.PulsarDecoder.channelRead(PulsarDecoder.java:83)
        at org.apache.pulsar.shade.io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:362)
        at org.apache.pulsar.shade.io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:348)
        at org.apache.pulsar.shade.io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:340)
        at org.apache.pulsar.shade.io.netty.handler.codec.ByteToMessageDecoder.fireChannelRead(ByteToMessageDecoder.java:323)
        at org.apache.pulsar.shade.io.netty.handler.codec.ByteToMessageDecoder.fireChannelRead(ByteToMessageDecoder.java:310)
        at org.apache.pulsar.shade.io.netty.handler.codec.ByteToMessageDecoder.callDecode(ByteToMessageDecoder.java:426)
        at org.apache.pulsar.shade.io.netty.handler.codec.ByteToMessageDecoder.channelRead(ByteToMessageDecoder.java:278)
        at org.apache.pulsar.shade.io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:362)
        at org.apache.pulsar.shade.io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:348)
        at org.apache.pulsar.shade.io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:340)
        at org.apache.pulsar.shade.io.netty.channel.DefaultChannelPipeline$HeadContext.channelRead(DefaultChannelPipeline.java:1434)
        at org.apache.pulsar.shade.io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:362)
        at org.apache.pulsar.shade.io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:348)
        at org.apache.pulsar.shade.io.netty.channel.DefaultChannelPipeline.fireChannelRead(DefaultChannelPipeline.java:965)
        at org.apache.pulsar.shade.io.netty.channel.epoll.AbstractEpollStreamChannel$EpollStreamUnsafe.epollInReady(AbstractEpollStreamChannel.java:799)
        at org.apache.pulsar.shade.io.netty.channel.epoll.AbstractEpollChannel$AbstractEpollUnsafe$1.run(AbstractEpollChannel.java:382)
        at org.apache.pulsar.shade.io.netty.util.concurrent.AbstractEventExecutor.safeExecute(AbstractEventExecutor.java:163)
        at org.apache.pulsar.shade.io.netty.util.concurrent.SingleThreadEventExecutor.runAllTasks(SingleThreadEventExecutor.java:404)
        at org.apache.pulsar.shade.io.netty.channel.epoll.EpollEventLoop.run(EpollEventLoop.java:335)
        at org.apache.pulsar.shade.io.netty.util.concurrent.SingleThreadEventExecutor$5.run(SingleThreadEventExecutor.java:909)
        at org.apache.pulsar.shade.io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30)
        at java.lang.Thread.run(Thread.java:745)

Looking into a memory dump showed many buffers allocated to nio/netty.

This issue could be related to #5751, #5720.

We were load testing on a single Linux host with plenty of physical memory.

Possibly related to issues #5513, #4196, #4632, we've also seen one crash due to Direct memory error but that seemed related to Bookkeeper processing:

9:50:46.759 [BookieShutdownTrigger] ERROR org.apache.bookkeeper.bookie.BookieThread - Uncaught exception in thread BookieShutdownTrigger
io.netty.util.internal.OutOfDirectMemoryError: failed to allocate 16777216 byte(s) of direct memory (used: 134217728, max: 134217728)
        at io.netty.util.internal.PlatformDependent.incrementMemoryCounter(PlatformDependent.java:655) ~[io.netty-netty-all-4.1.32.Final.jar:4.1.32.Final]
        at io.netty.util.internal.PlatformDependent.allocateDirectNoCleaner(PlatformDependent.java:610) ~[io.netty-netty-all-4.1.32.Final.jar:4.1.32.Final]
        at io.netty.buffer.PoolArena$DirectArena.allocateDirect(PoolArena.java:769) ~[io.netty-netty-all-4.1.32.Final.jar:4.1.32.Final]
        at io.netty.buffer.PoolArena$DirectArena.newChunk(PoolArena.java:745) ~[io.netty-netty-all-4.1.32.Final.jar:4.1.32.Final]
        at io.netty.buffer.PoolArena.allocateNormal(PoolArena.java:244) ~[io.netty-netty-all-4.1.32.Final.jar:4.1.32.Final]
        at io.netty.buffer.PoolArena.allocate(PoolArena.java:226) ~[io.netty-netty-all-4.1.32.Final.jar:4.1.32.Final]
        at io.netty.buffer.PoolArena.allocate(PoolArena.java:146) ~[io.netty-netty-all-4.1.32.Final.jar:4.1.32.Final]
        at io.netty.buffer.PooledByteBufAllocator.newDirectBuffer(PooledByteBufAllocator.java:324) ~[io.netty-netty-all-4.1.32.Final.jar:4.1.32.Final]
        at io.netty.buffer.AbstractByteBufAllocator.directBuffer(AbstractByteBufAllocator.java:185) ~[io.netty-netty-all-4.1.32.Final.jar:4.1.32.Final]
        at io.netty.buffer.AbstractByteBufAllocator.directBuffer(AbstractByteBufAllocator.java:176) ~[io.netty-netty-all-4.1.32.Final.jar:4.1.32.Final]
        at io.netty.buffer.AbstractByteBufAllocator.buffer(AbstractByteBufAllocator.java:113) ~[io.netty-netty-all-4.1.32.Final.jar:4.1.32.Final]
        at org.apache.bookkeeper.bookie.EntryLogger$BufferedLogChannel.appendLedgersMap(EntryLogger.java:145) ~[org.apache.bookkeeper-bookkeeper-server-4.9.2.jar:4.9.2]
        at org.apache.bookkeeper.bookie.EntryLogManagerBase.createNewLog(EntryLogManagerBase.java:159) ~[org.apache.bookkeeper-bookkeeper-server-4.9.2.jar:4.9.2]
        at org.apache.bookkeeper.bookie.EntryLogManagerForSingleEntryLog.getCurrentLogForLedgerForAddEntry(EntryLogManagerForSingleEntryLog.java:106) ~[org.apache.bookkeeper-bookkeeper-server-4.9.2.jar:4.9.2]
        at org.apache.bookkeeper.bookie.EntryLogManagerBase.addEntry(EntryLogManagerBase.java:72) ~[org.apache.bookkeeper-bookkeeper-server-4.9.2.jar:4.9.2]
        at org.apache.bookkeeper.bookie.EntryLogManagerForSingleEntryLog.addEntry(EntryLogManagerForSingleEntryLog.java:87) ~[org.apache.bookkeeper-bookkeeper-server-4.9.2.jar:4.9.2]
        at org.apache.bookkeeper.bookie.EntryLogger.addEntry(EntryLogger.java:619) ~[org.apache.bookkeeper-bookkeeper-server-4.9.2.jar:4.9.2]
        at org.apache.bookkeeper.bookie.storage.ldb.SingleDirectoryDbLedgerStorage.lambda$checkpoint$6(SingleDirectoryDbLedgerStorage.java:597) ~[org.apache.bookkeeper-bookkeeper-server-4.9.2.jar:4.9.2]
        at org.apache.bookkeeper.bookie.storage.ldb.WriteCache.forEach(WriteCache.java:268) ~[org.apache.bookkeeper-bookkeeper-server-4.9.2.jar:4.9.2]
        at org.apache.bookkeeper.bookie.storage.ldb.SingleDirectoryDbLedgerStorage.checkpoint(SingleDirectoryDbLedgerStorage.java:595) ~[org.apache.bookkeeper-bookkeeper-server-4.9.2.jar:4.9.2]
        at org.apache.bookkeeper.bookie.storage.ldb.SingleDirectoryDbLedgerStorage.flush(SingleDirectoryDbLedgerStorage.java:686) ~[org.apache.bookkeeper-bookkeeper-server-4.9.2.jar:4.9.2]
        at org.apache.bookkeeper.bookie.storage.ldb.SingleDirectoryDbLedgerStorage.shutdown(SingleDirectoryDbLedgerStorage.java:221) ~[org.apache.bookkeeper-bookkeeper-server-4.9.2.jar:4.9.2]
        at org.apache.bookkeeper.bookie.storage.ldb.DbLedgerStorage.shutdown(DbLedgerStorage.java:161) ~[org.apache.bookkeeper-bookkeeper-server-4.9.2.jar:4.9.2]
        at org.apache.bookkeeper.bookie.Bookie.shutdown(Bookie.java:1172) ~[org.apache.bookkeeper-bookkeeper-server-4.9.2.jar:4.9.2]
        at org.apache.bookkeeper.bookie.Bookie$6.run(Bookie.java:1132) ~[org.apache.bookkeeper-bookkeeper-server-4.9.2.jar:4.9.2]
250.253: Total time for which application threads were stopped: 0.0002466 seconds, Stopping threads took: 0.0000837 seconds
09:50:46.839 [BookieDeathWatcher-3181] INFO  org.apache.bookkeeper.proto.BookieServer - BookieDeathWatcher noticed the bookie is not running any more, exiting the watch loop!
250.325: Total time for which application threads were stopped: 0.0013974 seconds, Stopping threads took: 0.0011630 seconds
09:50:46.842 [component-shutdown-thread] INFO  org.apache.bookkeeper.common.component.ComponentStarter - Closing component bookie-server in shutdown hook.
09:50:46.846 [component-shutdown-thread] INFO  org.apache.bookkeeper.proto.BookieServer - Shutting down BookieServer
jiazhai commented 4 years ago

@andrekramer1 . Thanks for reporting this issue. This could be reproduce by these steps?

  1. start standalone.
  2. create 4 producer, and 1000 consumer.
  3. find OOM in client.

Is there any configurations changed? How many topics and partitions used in each producer? Is there any information regarding the message size and message produce/consume rate?

Increasing memory has not helped

Is there any change details for this memory increasing?

andrekramer1 commented 4 years ago

10000 consumers leads to the OOM happening quite quickly for standard configuration and one topic / no partitions. Messages were about 200 bytes and rate is "as fast as possible" (we did not use pulsar-perf) with each producer sending 1000 messages.

andrekramer1 commented 4 years ago

The OOM appear to be in reading from Bookkeeper and possibly the broker is issuing too many read requests at a time. We've had some limited success with the dispatcher throttling introduced in 2.5. Using both: ./bin/pulsar-admin namespaces set-dispatch-rate public/default \ --msg-dispatch-rate 500 \ --dispatch-rate-period 1 ./bin/pulsar-admin namespaces set-subscription-dispatch-rate public/default \ --msg-dispatch-rate 50 \ --dispatch-rate-period 1 allows runs to not OOM most but not all of the time.

A rate limit is difficult to use as the number of topics and subscriptions will not be known and we would have to plan for the worst case scenario.

One or more new limits on bookie parallel reads seem to be required?

lhotari commented 4 years ago

Just in case anyone else is interested in high memory consumption issues, I filed an issue where there is an OOM with many consumers that are originating from Reader API usage, that is #8138 . It is a case since there the Readers are closed after usage, but the related consumer instances don't get GCd. When I was looking for related issues I also found #7680 . That might be directly related to this "OOM with many consumers" case.

tisonkun commented 1 year ago

Closed as stale. Please open a new issue if it's still relevant to the maintained versions.