Java Native Memory 'Other' section consumes a lot of memory

Question

Prerequisites

Application is run in docker-container with Java openjdk version "13.0.1" with these options:

-Xmx6G -XX:MaxHeapFreeRatio=30 -XX:MinHeapFreeRatio=10 -XX:+AlwaysActAsServerClassMachine -XX:+UseContainerSupport -XX:+HeapDumpOnOutOfMemoryError -XX:+ExitOnOutOfMemoryError -XX:HeapDumpPath==/.../crush.hprof -XX:+UnlockDiagnosticVMOptions -XX:NativeMemoryTracking=summary -XX:+PrintNMTStatistics -Xlog:gc*:file=/var/log/.../log.gc.log:time::filecount=5,filesize=100000

When I run jcmd 1 VM.native_memory, I get this:

Total: reserved=9081562KB, committed=1900002KB
-                 Java Heap (reserved=6291456KB, committed=896000KB)
                            (mmap: reserved=6291456KB, committed=896000KB) 
 
-                     Class (reserved=1221794KB, committed=197034KB)
                            (classes #34434)
                            (  instance classes #32536, array classes #1898)
                            (malloc=7330KB #121979) 
                            (mmap: reserved=1214464KB, committed=189704KB) 
                            (  Metadata:   )
                            (    reserved=165888KB, committed=165752KB)
                            (    used=161911KB)
                            (    free=3841KB)
                            (    waste=0KB =0.00%)
                            (  Class space:)
                            (    reserved=1048576KB, committed=23952KB)
                            (    used=21501KB)
                            (    free=2451KB)
                            (    waste=0KB =0.00%)
 
-                    Thread (reserved=456661KB, committed=50141KB)
                            (thread #442)
                            (stack: reserved=454236KB, committed=47716KB)
                            (malloc=1572KB #2654) 
                            (arena=853KB #882)
 
-                      Code (reserved=255027KB, committed=100419KB)
                            (malloc=7343KB #26005) 
                            (mmap: reserved=247684KB, committed=93076KB) 
 
-                        GC (reserved=316675KB, committed=116459KB)
                            (malloc=47311KB #70516) 
                            (mmap: reserved=269364KB, committed=69148KB) 
 
-                  Compiler (reserved=1429KB, committed=1429KB)
                            (malloc=1634KB #2498) 
                            (arena=18014398509481779KB #5)
 
-                  Internal (reserved=2998KB, committed=2998KB)
                            (malloc=2962KB #5480) 
                            (mmap: reserved=36KB, committed=36KB) 
 
-                     Other (reserved=446581KB, committed=446581KB)
                            (malloc=446581KB #368) 
 
-                    Symbol (reserved=36418KB, committed=36418KB)
                            (malloc=34460KB #906917) 
                            (arena=1958KB #1)
 
-    Native Memory Tracking (reserved=18786KB, committed=18786KB)
                            (malloc=587KB #8291) 
                            (tracking overhead=18199KB)
 
-        Shared class space (reserved=11180KB, committed=11180KB)
                            (mmap: reserved=11180KB, committed=11180KB) 
 
-               Arena Chunk (reserved=19480KB, committed=19480KB)
                            (malloc=19480KB) 
 
-                   Logging (reserved=7KB, committed=7KB)
                            (malloc=7KB #271) 
 
-                 Arguments (reserved=17KB, committed=17KB)
                            (malloc=17KB #471) 
 
-                    Module (reserved=1909KB, committed=1909KB)
                            (malloc=1909KB #11057) 
 
-                 Safepoint (reserved=8KB, committed=8KB)
                            (mmap: reserved=8KB, committed=8KB) 
 
-           Synchronization (reserved=1136KB, committed=1136KB)
                            (malloc=1136KB #6628)

Here we can see that 'Other' section consumes 446581 KB whereas total committed memory is 1900002 KB.

So, 'Other' section takes 23% of all committed memory!

Also this memory is not freed when application is running.

Because of this I changed java flag -XX:NativeMemoryTracking=summary to -XX:NativeMemoryTracking=detail to check where memory is allocated and got this 2 strange blocks of memory:

[0x00007f8db4b32bae] Unsafe_AllocateMemory0+0x8e
[0x00007f8da416e7db]
                             (malloc=298470KB type=Other #286)

[0x00007f8db4b32bae] Unsafe_AllocateMemory0+0x8e
[0x00007f8d9b84bc90]
                             (malloc=148111KB type=Other #82)

Analyze

I tried to use async-profiler to check event Unsafe_AllocateMemory0.

I run async-profiler as agent like this:

java -agentpath:/async-profiler/build/libasyncProfiler.so=start,event=itimer,Unsafe_AllocateMemory0,file=/var/log/.../unsafe_allocate_memory.html

And got this flamegraph: https://i.stack.imgur.com/PbE5D.png

Also, I tried to profile events malloc,mmap,mprotect. malloc showed the same flamegraph as event Unsafe_AllocateMemory0, but flamegraphs for mmap and mprotect were empty.

I thought that problem can be related with C2 compiler and disabled it, but after restart nothing changed - the 'Other' section still occupied a lot of memory memory. Moreover, this application is long-living and I'm not sure that disabling C2 can be a good idea.

I tried to use jeprof to check which part of code executes os.malloc

I run java application like this:

LD_PRELOAD=/usr/local/lib/libjemalloc.so MALLOC_CONF=prof:true,lg_prof_interval:30,lg_prof_sample:17 exec java -jar /srv/app/myapp.jar

After 10+ minutes I used jeprof and got this: https://i.stack.imgur.com/45adD.gif

And again there are 2 blocks of memory which occupied many native memory.

Result

I cannot find the place, which allocates so much memory.

Maybe someone can recommend how to spot the root cause of this problem? And what steps do I need to take to avoid this problem?

UPDATE 1

Thanks to apangin I have finally found the place, where so much memory is occupied!

It's related to Redisson/Lettuce, which are using Netty under the hood: flamegraph

I used experimental native mode and run java:

java -agentpath:/async-profiler/build/libasyncProfiler.so=start,event=nativemem,file=/var/log/.../profile.jfr -jar /srv/app/myapp.jar

https://stackoverflow.com/questions/40119/how-to-find-a-java-memory-leak — LMC, Jun 06 '22 at 23:40

score 2 · Accepted Answer · answered Jun 07 '22 at 00:29

2

Your async-profilers arguments seem wrong.
Change event=itimer,Unsafe_AllocateMemory0 to event=Unsafe_AllocateMemory0

async-profiler also has an experimental nativemem mode specifically for finding native memory leaks. See https://github.com/jvm-profiling-tools/async-profiler/discussions/491 for the details.

Other section in NMT typically includes off-heap memory allocated with Unsafe.allocateMemory, in particular, Direct ByteBuffers.

answered Jun 07 '22 at 00:29

apangin

92,924
10
193
247

hm...I have never heard about `nativemem` mode. I'll try to use it and write update! Thanks for the advice! As for `event=itimer,Unsafe_AllocateMemory0`, I used `itimer` as java application resides in a docker container and this option is pointed out in the documentation. – Anton Gabov Jun 07 '22 at 23:11
1

`itimer` and native function profiling are completely different modes, they cannot be mixed. – apangin Jun 08 '22 at 15:58
1

thank you so much for the help! I wrote update on the initial question. So, now only need to find why Redisson/Lettuce use so much memory :) – Anton Gabov Jun 13 '22 at 22:28

Java Native Memory 'Other' section consumes a lot of memory

1 Answers1