OpenJDK13容器应用NMT Other段原生内存占用过高排查

问题背景 #

应用部署在Docker容器内，运行环境为OpenJDK 13.0.1，使用的JVM启动参数如下：

-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

执行jcmd 1 VM.native_memory命令获取NMT统计结果，输出如下：

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)

从统计结果可以看到，Other段已提交内存达446581KB，占总已提交内存1900002KB的23%，且应用运行期间这部分内存始终不会释放。
为定位内存分配来源，将JVM参数-XX:NativeMemoryTracking=summary调整为-XX:NativeMemoryTracking=detail，观测到两块异常内存分配均来自Unsafe_AllocateMemory0调用，对应输出如下：

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

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

排查过程 #

• 挂载async-profiler作为Java Agent，采集Unsafe_AllocateMemory0事件，启动命令如下：

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

  采集生成的火焰图未定位到明确业务调用来源。后续补充采集malloc、mmap、mprotect事件，其中malloc事件火焰图与Unsafe_AllocateMemory0结果一致，mmap、mprotect事件无相关异常数据。排查初期曾怀疑问题与C2编译器有关，禁用C2后重启应用验证，Other段内存占用无明显变化，且禁用C2会大幅影响长驻应用性能，方案不适用于生产环境。
• 采用jeprof追踪os.malloc调用来源，通过预加载jemalloc的方式启动应用，命令如下：

  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
  

  应用运行10分钟后通过jeprof分析采集结果，仍只能观测到两块大内存占用，无法定位到具体的内存分配代码位置。

定位结果 #

经社区开发者指导，使用async-profiler实验性native模式采集原生内存分配事件，启动命令如下：

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

最终定位到异常高内存占用来自底层依赖Netty的Redisson/Lettuce组件，采集生成的火焰图可清晰看到完整的内存分配调用链路。

内容的提问来源于stack exchange，提问作者Anton Gabov