Example of native allocation tracking from VM.info and Native tracking in OpenJDK

Solution Verified - Updated

Environment

  • Red Hat build of OpenJDK
    • 11
    • 17
    • 21

Issue

  • Example of VM.info usage tracking of native usage?
  • Native usage tracking using Native Tracking?

Resolution

Native allocation

Let's create an example with a native allocation:

import sun.misc.Unsafe;
import java.lang.reflect.Field;
public class NativeExample {
    public static void main(String[] args) throws Exception {
        System.in.read();
        Field f = Unsafe.class.getDeclaredField("theUnsafe");
        f.setAccessible(true);
        Unsafe unsafe = (Unsafe) f.get(null);
        System.out.println("PAGE SIZE: " + unsafe.pageSize());
        System.in.read();
        int memoryBlock = 50 * 1024 * 1024;

And then java -XX:NativeMemoryTracking=detail NativeExample:

Native Memory Tracking:
Total: reserved=5569059KB, committed=396795KB
-                 Java Heap (reserved=3977216KB, committed=251904KB)
                            (mmap: reserved=3977216KB, committed=251904KB) 

-                     Class (reserved=1056888KB, committed=4984KB)
                            (classes #556)
                            (  instance classes #474, array classes #82)
                            (malloc=120KB #605) 
                            (mmap: reserved=1056768KB, committed=4864KB) 
                            (  Metadata:   )
                            (    reserved=8192KB, committed=4352KB)
                            (    used=238KB)
                            (    free=4114KB)
                            (    waste=0KB =0.00%)
                            (  Class space:)
                            (    reserved=1048576KB, committed=512KB)
                            (    used=17KB)
                            (    free=495KB)
                            (    waste=0KB =0.00%)

-                    Thread (reserved=17525KB, committed=861KB)
                            (thread #17)
                            (stack: reserved=17448KB, committed=784KB)
                            (malloc=59KB #104) 
                            (arena=18KB #32)

-                      Code (reserved=247725KB, committed=7585KB)
                            (malloc=37KB #429) 
                            (mmap: reserved=247688KB, committed=7548KB) 

-                        GC (reserved=199184KB, committed=60940KB)
                            (malloc=17820KB #2014) 
                            (mmap: reserved=181364KB, committed=43120KB) 

-                  Compiler (reserved=135KB, committed=135KB)
                            (malloc=3KB #43) 
                            (arena=133KB #5)

-                  Internal (reserved=559KB, committed=559KB)
                            (malloc=527KB #952) 
                            (mmap: reserved=32KB, committed=32KB) 

-                     Other (reserved=51200KB, committed=51200KB) <------------------------------------ 51200 KB == 51.2Mb <---- evidence a
                            (malloc=51200KB #1) 

-                    Symbol (reserved=1041KB, committed=1041KB)
                            (malloc=681KB #64) 
                            (arena=360KB #1)
-    Native Memory Tracking (reserved=301KB, committed=301KB)
                            (malloc=168KB #2381) 
                            (tracking overhead=133KB)

Example with VM.info::

$ jcmd NativeExample VM.info | grep Resident
Resident Set Size: 27132K (peak: 27132K) (anon: 10948K, file: 16184K, shmem: 0K) <-----------------27132K == 27.1mb
$ jcmd NativeExample VM.info | grep Virtual
Virtual space:
Virtual Size: 6989392K (peak: 15530072K)
$ jcmd NativeExample VM.info | grep Resident
Resident Set Size: 78540K (peak: 78540K) (anon: 62072K, file: 16468K, shmem: 0K) <-----------------78540K == 78.5mb <---- evidence b (51.4mb)
$ jcmd NativeExample VM.info | grep Virtual
Virtual space:
Virtual Size: 6989392K (peak: 15530072K)
$ jcmd NativeExample VM.info | grep Resident
Resident Set Size: 27508K (peak: 78540K) (anon: 11040K, file: 16468K, shmem: 0K)
$ jcmd NativeExample VM.info | grep Virtual

But also it will have more compilation events (20 events):

Event: 0.038 Thread 0x00007ff7dc20d800   51       3       jdk.internal.module.ModuleBootstrap$2::next (52 bytes)
Event: 0.038 Thread 0x00007ff7dc20d800 nmethod 51 0x00007ff7c41f5990 code [0x00007ff7c41f5ba0, 0x00007ff7c41f6120]

However, the main difference is on the dynamic libraries:

Dynamic libraries:
70d400000-71c800000 rw-p 00000000 00:00 0 
71c800000-7bfe00000 ---p 00000000 00:00 0 
7bfe00000-7bfe47000 rw-p 01106000 fd:01 919872                           /usr/lib/jvm/java-11-openjdk-11.0.12.0.7-0.el7_9.x86_64/lib/server/classes.jsa
7bfe47000-7bff00000 rw-p 00000000 00:00 0 
7bff00000-7bff6b000 rw-p 0109b000 fd:01 919872                           /usr/lib/jvm/java-11-openjdk-11.0.12.0.7-0.el7_9.x86_64/lib/server/classes.jsa
7bff6b000-7c0000000 rw-p 00000000 00:00 0 
7c0000000-800000000 ---p 00000000 00:00 0 
800000000-800002000 rwxp 00001000 fd:01 919872                           /usr/lib/jvm/java-11-openjdk-11.0.12.0.7-0.el7_9.x86_64/lib/server/classes.jsa
800002000-8003b6000 rw-p 00003000 fd:01 919872                           /usr/lib/jvm/java-11-openjdk-11.0.12.0.7-0.el7_9.x86_64/lib/server/classes.jsa
8003b6000-800a8f000 r--p 003b7000 fd:01 919872                           /usr/lib/jvm/java-11-openjdk-11.0.12.0.7-0.el7_9.x86_64/lib/server/classes.jsa
800a8f000-800a90000 rw-p 00a90000 fd:01 919872                           /usr/lib/jvm/java-11-openjdk-11.0.12.0.7-0.el7_9.x86_64/lib/server/classes.jsa
800a90000-80109a000 r--p 00a91000 fd:01 919872                           /usr/lib/jvm/java-11-openjdk-11.0.12.0.7-0.el7_9.x86_64/lib/server/classes.jsa
840000000-840080000 rw-p 00000000 00:00 0 
840080000-880000000 ---p 00000000 00:00 0 
55c131a7f000-55c131a80000 r-xp 00000000 fd:01 919464                     /usr/lib/jvm/java-11-openjdk-11.0.12.0.7-0.el7_9.x86_64/bin/java
55c131c80000-55c131c81000 r--p 00001000 fd:01 919464                     /usr/lib/jvm/java-11-openjdk-11.0.12.0.7-0.el7_9.x86_64/bin/java
55c131c81000-55c131c82000 rw-p 00002000 fd:01 919464                     /usr/lib/jvm/java-11-openjdk-11.0.12.0.7-0.el7_9.x86_64/bin/java
55c132d5b000-55c132d7c000 rw-p 00000000 00:00 0                          [heap]
7ff768000000-7ff768021000 rw-p 00000000 00:00 0 
7ff768021000-7ff76c000000 ---p 00000000 00:00 0 
7ff76cdff000-7ff770000000 rw-p 00000000 00:00 0 <-------------------------- evidence c (shows 52mb anonymous allocation) 

Evidence b addresses 7ff76cdff000 (hex) to 7ff770000000 (hex) == 140700712697856 (dec) - 140700660264960 (dec)
Let's now do some math: 140700712697856 (dec) - 140700660264960 (dec) = 52432896 bytes == 52.4mb

Address	hex address	decimal address
Initial address	7ff76cdff000 (hex)	140700712697856 (dec)
Final address	7ff770000000 (hex)	140700660264960 (dec)

So then: Difference | 52432896 (bytes) == 52mb. That is exactly the difference above.

Summary:

  • Evidence a, from Native track summary shows ~52mb.
  • Evidence b, VM.info's Resident shows ~52mb
  • Evidence c, VM.info's Dynamic address shows ~52mb.

Clustion: One can conclude that address (evidence c) has 52mb (evidence a and b) and it is allocated on native from the example.

Root Cause

See the solution JVM Native Memory Tracking for JVM native tracking details. And Interpreting VM.info file in OpenJDK/OracleJDK for collection and interpretation of the VM.info file.

Category

This solution is part of Red Hat’s fast-track publication program, providing a huge library of solutions that Red Hat engineers have created while supporting our customers. To give you the knowledge you need the instant it becomes available, these articles may be presented in a raw and unedited form.