Bookkeeper Direct Memory Consumption is High

[sourabhaggrawal]

We have observed that in bookkeeper Direct Memory which was set to 4GB for a long time (2-3 years), is getting consumed fully (may be after upgrading to 2.10.1) , we noticed this 3 months back thats when we upgraded the cluster to 2.10.1.

We went ahead and beefed up the server with double capacity and allocated 20GB of Direct Memory (because thats where it got stabilised). But now we see that even 20GB was also getting fully consumed and bookkeeper kept restarting

We also have a problem of our ledger disk getting full and not deleting the expired ledgers or not reclaiming the free space and I believe Direct Memory could be a reason of this problem too. Because GC also make use of Memory to delete ledgers.

I have attached a screenshot of DirectMemory of one node and the pattern is same for other nodes too.

Any leads on what could be the reason and how to fix it ?

[yuweisung]

1. bookie server ram size?
2. heap size? -Xmx, -Xms?
3. max direct memory size?
4. bookie log shows why bookie restart? oom killed?

[yuweisung]

"looks like" memory leak from broker or autorecovery (assuming you have autorecovery thread). What's bookie doing before the oom killed?

[sourabhaggrawal]

It could be because of autorecovery, I have disabled autorecovery thread for a while to see if it still use that much of memory.
BTW my read cache is at 5GB which is more than 25% of Direct Memory (which bk assign by default) & write Cache is not more than 15MB. I am not sure where rest of the memory is being utilised.

[yuweisung]

Can you share your bookie jvm ops? number of io threads?
For further troubleshooting, you can turn on -XX:NativeMemoryTracking=summary (or detail)

[yuweisung]

or you can run jcmd jfr.start duration=5m filename=bookie.jfr

[sourabhaggrawal]

Hi @yuweisung here is my bookie jvm ops.

/usr/bin/java -cp /opt/apache-pulsar-2.10.1/conf:::/opt/apache-pulsar-2.10.1/lib/: -Dlog4j.configurationFile=log4j2.yaml -Djute.maxbuffer=10485760 -Djava.net.preferIPv4Stack=true -Dzookeeper.clientTcpKeepAlive=true -Dio.netty.tryReflectionSetAccessible=true -Xms8g -Xmx8g -XX:MaxDirectMemorySize=20g -XX:+UseG1GC -XX:MaxGCPauseMillis=10 -XX:+ParallelRefProcEnabled -XX:+UnlockExperimentalVMOptions -XX:+DoEscapeAnalysis -XX:ParallelGCThreads=32 -XX:ConcGCThreads=32 -XX:G1NewSizePercent=50 -XX:+DisableExplicitGC -Xlog:gc:logs/pulsar_bookie_gc_%p.log:time,uptime,level,tags:filecount=10,filesize=20M -Dio.netty.leakDetectionLevel=disabled -Dio.netty.recycler.maxCapacityPerThread=4096 -Dlog4j2.formatMsgNoLookups=true -Xms8g -Xmx8g -XX:MaxDirectMemorySize=20g -XX:+UseG1GC -XX:MaxGCPauseMillis=10 -XX:+ParallelRefProcEnabled -XX:+UnlockExperimentalVMOptions -XX:+DoEscapeAnalysis -XX:ParallelGCThreads=32 -XX:ConcGCThreads=32 -XX:G1NewSizePercent=50 -XX:+DisableExplicitGC -Dpulsar.log.appender=RoutingAppender -Dpulsar.log.dir=/opt/apache-pulsar-2.10.1/logs -Dpulsar.log.level=info -Dpulsar.log.root.level=info -Dpulsar.routing.appender.default=Console -Dlog4j2.is.webapp=false -Dpulsar.functions.process.container.log.dir=/opt/apache-pulsar-2.10.1/logs -Dpulsar.functions.java.instance.jar=/opt/apache-pulsar-2.10.1/instances/java-instance.jar -Dpulsar.functions.python.instance.file=/opt/apache-pulsar-2.10.1/instances/python-instance/python_instance_main.py -Dpulsar.functions.extra.dependencies.dir=/opt/apache-pulsar-2.10.1/instances/deps -Dpulsar.functions.instance.classpath=/opt/apache-pulsar-2.10.1/conf:::/opt/apache-pulsar-2.10.1/lib/*: -Dpulsar.functions.log.conf=/opt/apache-pulsar-2.10.1/conf/functions_log4j2.xml -Dbookkeeper.metadata.bookie.drivers=org.apache.pulsar.metadata.bookkeeper.PulsarMetadataBookieDriver -Dbookkeeper.metadata.client.drivers=org.apache.pulsar.metadata.bookkeeper.PulsarMetadataClientDriver -Dpulsar.log.file=bookkeeper.log org.apache.bookkeeper.server.Main --conf /opt/apache-pulsar-2.10.1/conf/bookkeeper.conf

[david-streamlio]

I recommend scanning the 2.10.x release notes to see if there have been any fixes related to direct memory issues since the 2.10.1 release. Perhaps upgrading to a newer version of Pulsar would fix this issue if it was introduced from the upgrade.

[sourabhaggrawal]

Hi @david-streamlio BK version is same 4.14.5 in pulsar 2.10.X version after 2.10.1 release, I have also scanned the release notes couple of times but could not find any change related to memory leak fix.

We have 2 cluster with same config and I am seeing this problem in our stage cluster where workload is also low.

[muni-chada]

https://github.com/apache/bookkeeper/releases/tag/release-4.14.7

[sourabhaggrawal]

Thanks @muni-chada for the reference, 4.14.7 has memory fix related to when bk is in read mode. In my cluster I dont have any bookie which is in read mode.

[lhotari]

Enabling the Netty leak detector is a way to find out where things leak with Netty buffers (which use direct memory). Passing -Dpulsar.allocator.leak_detection=Simple -Dio.netty.leakDetectionLevel=simple in JVM options is a way to configure it, this solution works for both Pulsar and Bookkeeper (however the other parameter is not used).

[lhotari]

Netty leak detection is explained in https://netty.io/wiki/reference-counted-objects.html#wiki-h2-10 . Search for "LEAK" in the logs to find the log entries.

[sourabhaggrawal]

Hi @lhotari, I have enabled the leak detection log with simple and after running it for 3 days I don't see anything when I search for LEAK.
I am looking for it in bookkeeper component logs, I hope I am searching for it at right place.
Is there anything else I should do or look for.

[sourabhaggrawal]

I see many request to non existing namespace coming to my broker cluster, I am checking with internal team on it already.
Is it possible so many request can lead to consumption of so much memory ? Because broker heap memory is also high.

[sourabhaggrawal]

Hi @lhotari I am also seeing this error in my broker logs
10:02:31.667 [BookKeeperClientWorker-OrderedExecutor-1-0] INFO org.apache.bookkeeper.client.PendingReadOp - Error: Bookie handle is not available while reading L495083 E0 from bookie :

Bookie node cpu, heap and direct memory was normal at the moment.
When I looked at the metadata of ledger, it was closed and ensemble had 2 bookie node reference where ledger is expected.
I have confirmed that ledger is present on both bookie nodes.

[hangc0276]

Hi @sourabhaggrawal, thank you for raising this issue. I have a few questions.

• Which version are you upgrading from? Before upgrading, does the BookKeeper's direct memory issue exist?
• BookKeeper 4.14.7 fixed many direct memory leak bugs, would you please upgrade the BookKeeper version to 4.14.7 to see if the direct memory issue still exists? You can upgrade the Pulsar to 2.10.4, which uses BookKeeper 4.14.7
• Would you please share your BookKeeper configuration?

[sourabhaggrawal]

Hi @hangc0276 , apologies for the late reply.

• upgraded the cluster from 2.8.3 to 2.10.1 and issue did not exist before the upgrade.
• I have upgraded my cluster 2.10.4 which seems to have fixed the issue.
  Thank you for recommending.