Metaspace leak with instrumentation.retransform

Jean-Philippe Bempel jean-philippe.bempel at datadoghq.com
Wed May 24 15:15:26 UTC 2023


I have a lead when running with "-Xlog:redefine*" the output is like this:
[0.083s][info][redefine,class,constantpool] old_cp_len=33, scratch_cp_len=33
[0.084s][info][redefine,class,constantpool] merge_cp_len=35, index_map_len=2
[0.084s][info][redefine,class,load        ] redefined name=MyClass,
count=1 (avail_mem=2276324K)
[0.084s][info][redefine,class,update      ] adjust: name=MyClass
[0.084s][info][redefine,class,timer       ] vm_op: all=0  prologue=0  doit=0
[0.084s][info][redefine,class,timer       ] redefine_single_class:
phase1=0  phase2=0
[0.085s][info][redefine,class,constantpool] old_cp_len=35, scratch_cp_len=35
[0.085s][info][redefine,class,constantpool] merge_cp_len=37, index_map_len=2
[0.085s][info][redefine,class,load        ] redefined name=MyClass,
count=2 (avail_mem=2276324K)
[0.085s][info][redefine,class,update      ] adjust: name=MyClass
[0.085s][info][redefine,class,timer       ] vm_op: all=0  prologue=0  doit=0
[0.085s][info][redefine,class,timer       ] redefine_single_class:
phase1=0  phase2=0
[0.085s][info][redefine,class,constantpool] old_cp_len=37, scratch_cp_len=37
[0.085s][info][redefine,class,constantpool] merge_cp_len=39, index_map_len=2
[0.086s][info][redefine,class,load        ] redefined name=MyClass,
count=3 (avail_mem=2276324K)
[0.086s][info][redefine,class,update      ] adjust: name=MyClass
[0.086s][info][redefine,class,timer       ] vm_op: all=0  prologue=0  doit=0
[0.086s][info][redefine,class,timer       ] redefine_single_class:
phase1=0  phase2=0
...
[2.566s][info][redefine,class,load        ] redefined name=MyClass,
count=1920 (avail_mem=2193668K)
[2.566s][info][redefine,class,update      ] adjust: name=MyClass
[2.567s][info][redefine,class,timer       ] vm_op: all=1  prologue=1  doit=0
[2.567s][info][redefine,class,timer       ] redefine_single_class:
phase1=0  phase2=0
[2.567s][info][redefine,class,constantpool] old_cp_len=3873, scratch_cp_len=3873
[2.568s][info][redefine,class,constantpool] merge_cp_len=3875, index_map_len=2
[2.575s][info][redefine,class,load        ] redefined name=MyClass,
count=1921 (avail_mem=2192912K)
[2.575s][info][redefine,class,update      ] adjust: name=MyClass
[2.576s][info][redefine,class,timer       ] vm_op: all=8  prologue=7  doit=1
[2.576s][info][redefine,class,timer       ] redefine_single_class:
phase1=0  phase2=0
[2.585s][info][redefine,class,load,exceptions] merge_cp_and_rewrite
exception: 'java/lang/OutOfMemoryError'
// end of log
while when there is no leak:

...
[12.143s][info][redefine,class,timer       ] vm_op: all=0  prologue=0  doit=0
[12.143s][info][redefine,class,timer       ] redefine_single_class:
phase1=0  phase2=0
[12.143s][info][redefine,class,constantpool] old_cp_len=29, scratch_cp_len=29
[12.143s][info][redefine,class,constantpool] merge_cp_len=29, index_map_len=0
[12.144s][info][redefine,class,load        ] redefined name=MyClass,
count=16435 (avail_mem=2308328K)
[12.144s][info][redefine,class,update      ] adjust: name=MyClass
[12.144s][info][redefine,class,timer       ] vm_op: all=0  prologue=0  doit=0
[12.144s][info][redefine,class,timer       ] redefine_single_class:
phase1=0  phase2=0
// end of log

The constant pool is linearly increasing by 2 for each redefine for
the leak version.

On Wed, May 24, 2023 at 4:57 PM Thomas Stüfe <thomas.stuefe at gmail.com> wrote:
>
>
>
> On Wed, May 24, 2023 at 2:53 PM <coleen.phillimore at oracle.com> wrote:
>>
>> You could also try -Xlog:redefine+class+iklass+purge=trace
>>
>> It might think the previous versions of these methods are still alive.
>>
>> Coleen
>
>
> Good point. But in this particular case we see the "missing" 128m pretty much all in the internal freeblocks structure, so its all released bytecode:
>
> "Deallocated from chunks in use:    127.36 MB (>99%) (11785 blocks)"
>
> This may be difficult to solve, unless there is a simple answer like "when redefining, if new bytecode would fit into old bytecode, overwrite old bytecode with new bytecode and don't bother metaspace"
>
>
>>
>>
>> On 5/24/23 5:26 AM, Jean-Philippe Bempel wrote:
>> > Here the JBS: https://bugs.openjdk.org/browse/JDK-8308762 with the
>> > output of "-Xlog:metaspace=trace"
>> >
>> > Thanks
>> > Jean-Philippe Bempel
>> >
>> > On Wed, May 24, 2023 at 9:10 AM Thomas Stüfe <thomas.stuefe at gmail.com> wrote:
>> >> Yes, that's the space for the old bytecode sitting around waiting to be re-used:
>> >>
>> >> ` Deallocated from chunks in use:    127.36 MB (>99%) (11785 blocks) `
>> >>
>> >> It would be nice if you could open a JBS issue and attach the program and a log produced with "-Xlog:metaspace=trace"; you may have to zip the thing if it gets too large.
>> >>
>> >>
>> >>
>> >> On Wed, May 24, 2023 at 9:06 AM Jean-Philippe Bempel <jean-philippe.bempel at datadoghq.com> wrote:
>> >>> On Wed, May 24, 2023 at 8:21 AM Thomas Stüfe <thomas.stuefe at gmail.com> wrote:
>> >>>>
>> >>>> My first thought was that this is not a leak but a case of class redefinition, where the bytecode is rewritten. The space for the old bytecode gets salvaged and would be re-used for metaspace allocations from the same loader, save that said re-use never happens for some reason. The output of "jcmd VM.metaspace" at the end of the program run would be helpful too.
>> >>>>
>> >>> Here the output of VM.metaspace:
>> >>>
>> >>> $ jcmd 6940 VM.metaspace
>> >>> 6940:
>> >>>
>> >>> Total Usage - 6 loaders, 809 classes (776 shared):
>> >>>    Non-Class: 2605 chunks,    131.55 MB capacity,  127.87 MB ( 97%)
>> >>> committed,   127.83 MB ( 97%) used,    37.94 KB ( <1%) free,     8
>> >>> bytes ( <1%) waste , deallocated: 11783 blocks with 127.36 MB
>> >>>        Class:    8 chunks,    266.00 KB capacity,   74.00 KB ( 28%)
>> >>> committed,    17.48 KB (  7%) used,    56.52 KB ( 21%) free,     0
>> >>> bytes (  0%) waste , deallocated: 2 blocks with 512 bytes
>> >>>         Both: 2613 chunks,    131.81 MB capacity,  127.94 MB ( 97%)
>> >>> committed,   127.85 MB ( 97%) used,    94.45 KB ( <1%) free,     8
>> >>> bytes ( <1%) waste , deallocated: 11785 blocks with 127.36 MB
>> >>>
>> >>>
>> >>> Virtual space:
>> >>>    Non-class space:      192.00 MB reserved,     127.88 MB ( 67%)
>> >>> committed,  3 nodes.
>> >>>        Class space:      104.00 MB reserved,     128.00 KB ( <1%)
>> >>> committed,  1 nodes.
>> >>>               Both:      296.00 MB reserved,     128.00 MB ( 43%) committed.
>> >>>
>> >>>
>> >>> Chunk freelists:
>> >>>     Non-Class:
>> >>>
>> >>>    4m: (none)
>> >>>    2m: (none)
>> >>>    1m: (none)
>> >>> 512k: (none)
>> >>> 256k:    2, capacity=512.00 KB, committed=0 bytes (  0%)
>> >>> 128k:    2, capacity=256.00 KB, committed=0 bytes (  0%)
>> >>>   64k:    2, capacity=128.00 KB, committed=0 bytes (  0%)
>> >>>   32k: (none)
>> >>>   16k: (none)
>> >>>    8k: (none)
>> >>>    4k:    2, capacity=8.00 KB, committed=8.00 KB (100%)
>> >>>    2k:    6, capacity=12.00 KB, committed=12.00 KB (100%)
>> >>>    1k: (none)
>> >>> Total word size: 916.00 KB, committed: 20.00 KB (  2%)
>> >>>
>> >>>         Class:
>> >>>
>> >>>    4m: (none)
>> >>>    2m:    1, capacity=2.00 MB, committed=0 bytes (  0%)
>> >>>    1m:    1, capacity=1.00 MB, committed=0 bytes (  0%)
>> >>> 512k:    1, capacity=512.00 KB, committed=0 bytes (  0%)
>> >>> 256k: (none)
>> >>> 128k:    1, capacity=128.00 KB, committed=0 bytes (  0%)
>> >>>   64k:    1, capacity=64.00 KB, committed=0 bytes (  0%)
>> >>>   32k:    1, capacity=32.00 KB, committed=0 bytes (  0%)
>> >>>   16k:    1, capacity=16.00 KB, committed=0 bytes (  0%)
>> >>>    8k: (none)
>> >>>    4k: (none)
>> >>>    2k:    1, capacity=2.00 KB, committed=2.00 KB (100%)
>> >>>    1k:    3, capacity=3.00 KB, committed=3.00 KB (100%)
>> >>> Total word size: 3.74 MB, committed: 5.00 KB ( <1%)
>> >>>
>> >>>          Both:
>> >>>
>> >>>    4m: (none)
>> >>>    2m:    1, capacity=2.00 MB, committed=0 bytes (  0%)
>> >>>    1m:    1, capacity=1.00 MB, committed=0 bytes (  0%)
>> >>> 512k:    1, capacity=512.00 KB, committed=0 bytes (  0%)
>> >>> 256k:    2, capacity=512.00 KB, committed=0 bytes (  0%)
>> >>> 128k:    3, capacity=384.00 KB, committed=0 bytes (  0%)
>> >>>   64k:    3, capacity=192.00 KB, committed=0 bytes (  0%)
>> >>>   32k:    1, capacity=32.00 KB, committed=0 bytes (  0%)
>> >>>   16k:    1, capacity=16.00 KB, committed=0 bytes (  0%)
>> >>>    8k: (none)
>> >>>    4k:    2, capacity=8.00 KB, committed=8.00 KB (100%)
>> >>>    2k:    7, capacity=14.00 KB, committed=14.00 KB (100%)
>> >>>    1k:    3, capacity=3.00 KB, committed=3.00 KB (100%)
>> >>> Total word size: 4.63 MB, committed: 25.00 KB ( <1%)
>> >>>
>> >>>
>> >>>
>> >>> Waste (unused committed space):(percentages refer to total committed
>> >>> size 128.00 MB):
>> >>>          Waste in chunks in use:      8 bytes ( <1%)
>> >>>          Free in chunks in use:     94.45 KB ( <1%)
>> >>>                  In free chunks:     25.00 KB ( <1%)
>> >>> Deallocated from chunks in use:    127.36 MB (>99%) (11785 blocks)
>> >>>                         -total-:    127.48 MB (>99%)
>> >>>
>> >>> chunk header pool: 2632 items, 189.33 KB.
>> >>>
>> >>> Internal statistics:
>> >>>
>> >>> num_allocs_failed_limit: 23.
>> >>> num_arena_births: 22.
>> >>> num_arena_deaths: 10.
>> >>> num_vsnodes_births: 4.
>> >>> num_vsnodes_deaths: 0.
>> >>> num_space_committed: 2048.
>> >>> num_space_uncommitted: 0.
>> >>> num_chunks_returned_to_freelist: 33.
>> >>> num_chunks_taken_from_freelist: 2624.
>> >>> num_chunk_merges: 11.
>> >>> num_chunk_splits: 1456.
>> >>> num_chunks_enlarged: 276.
>> >>> num_inconsistent_stats: 0.
>> >>>
>> >>>
>> >>> Settings:
>> >>> MaxMetaspaceSize: 128.00 MB
>> >>> CompressedClassSpaceSize: 104.00 MB
>> >>> Initial GC threshold: 21.00 MB
>> >>> Current GC threshold: 128.00 MB
>> >>> CDS: on
>> >>> MetaspaceReclaimPolicy: balanced
>> >>>   - commit_granule_bytes: 65536.
>> >>>   - commit_granule_words: 8192.
>> >>>   - virtual_space_node_default_size: 8388608.
>> >>>   - enlarge_chunks_in_place: 1.
>> >>>   - new_chunks_are_fully_committed: 0.
>> >>>   - uncommit_free_chunks: 1.
>> >>>   - use_allocation_guard: 0.
>> >>>
>> >>> Also I have run it with -XX:+CrashOnOutOfMemoryError to have  stacktrace:
>> >>> Stack: [0x00007f8d9c400000,0x00007f8d9c500000],
>> >>> sp=0x00007f8d9c4fdb80,  free space=1014k
>> >>> Native frames: (J=compiled Java code, j=interpreted, Vv=VM code, C=native code)
>> >>> V  [libjvm.so+0xf9f4e7]  VMError::report_and_die(int, char const*,
>> >>> char const*, __va_list_tag*, Thread*, unsigned char*, void*, void*,
>> >>> char const*, int, unsigned long)+0x197  (debug.cpp:368)
>> >>> V  [libjvm.so+0x672eab]  report_fatal(VMErrorType, char const*, int,
>> >>> char const*, ...)+0x12b
>> >>> V  [libjvm.so+0x67315d]  report_java_out_of_memory(char const*)+0xed
>> >>> V  [libjvm.so+0xc238d0]
>> >>> Metaspace::report_metadata_oome(ClassLoaderData*, unsigned long,
>> >>> MetaspaceObj::Type, Metaspace::MetadataType, JavaThread*)+0x260
>> >>> V  [libjvm.so+0xc23b33]  Metaspace::allocate(ClassLoaderData*,
>> >>> unsigned long, MetaspaceObj::Type, JavaThread*)+0x133
>> >>> V  [libjvm.so+0x650e8b]  ConstantPool::allocate(ClassLoaderData*, int,
>> >>> JavaThread*)+0x7b
>> >>> V  [libjvm.so+0xae518c]
>> >>> VM_RedefineClasses::merge_cp_and_rewrite(InstanceKlass*,
>> >>> InstanceKlass*, JavaThread*)+0x4c
>> >>> V  [libjvm.so+0xae6e6d]  VM_RedefineClasses::load_new_class_versions()
>> >>> [clone .part.0]+0x34d
>> >>> V  [libjvm.so+0xae794f]  VM_RedefineClasses::doit_prologue()+0x17f
>> >>> V  [libjvm.so+0xfa8ee0]  VMThread::execute(VM_Operation*)+0x40
>> >>> V  [libjvm.so+0xab416f]  JvmtiEnv::RetransformClasses(int, _jclass*
>> >>> const*)+0x2bf
>> >>> V  [libjvm.so+0xa5f04c]  jvmti_RetransformClasses+0xfc
>> >>> C  [libinstrument.so+0x4e86]  retransformClasses+0x1b6
>> >>> J 182  sun.instrument.InstrumentationImpl.retransformClasses0(J[Ljava/lang/Class;)V
>> >>> java.instrument at 20.0.1 (0 bytes) @ 0x00007f8d886d8077
>> >>> [0x00007f8d886d7fa0+0x00000000000000d7]
>> >>> J 181 c1 sun.instrument.InstrumentationImpl.retransformClasses([Ljava/lang/Class;)V
>> >>> java.instrument at 20.0.1 (33 bytes) @ 0x00007f8d80c29a5c
>> >>> [0x00007f8d80c29860+0x00000000000001fc]
>> >>> j  Agent.retransformLoop(Ljava/lang/instrument/Instrumentation;Ljava/lang/String;)V+82
>> >>> j  Agent.lambda$premain$0(Ljava/lang/instrument/Instrumentation;Ljava/lang/String;)V+2
>> >>> j  Agent$$Lambda$14+0x0000000801002c00.run()V+8
>> >>> j  java.lang.Thread.runWith(Ljava/lang/Object;Ljava/lang/Runnable;)V+5
>> >>> java.base at 20.0.1
>> >>> j  java.lang.Thread.run()V+19 java.base at 20.0.1
>> >>> v  ~StubRoutines::call_stub 0x00007f8d88138cc6
>> >>> V  [libjvm.so+0x8c9c85]  JavaCalls::call_helper(JavaValue*,
>> >>> methodHandle const&, JavaCallArguments*, JavaThread*)+0x315
>> >>> V  [libjvm.so+0x8cb5f2]  JavaCalls::call_virtual(JavaValue*, Handle,
>> >>> Klass*, Symbol*, Symbol*, JavaThread*)+0x1d2
>> >>> V  [libjvm.so+0x99debe]  thread_entry(JavaThread*, JavaThread*)+0x8e
>> >>> V  [libjvm.so+0x8e1578]  JavaThread::thread_main_inner() [clone .part.0]+0xb8
>> >>> V  [libjvm.so+0xf18736]  Thread::call_run()+0xa6
>> >>> V  [libjvm.so+0xcae8d8]  thread_native_entry(Thread*)+0xd8
>> >>> Java frames: (J=compiled Java code, j=interpreted, Vv=VM code)
>> >>> J 182  sun.instrument.InstrumentationImpl.retransformClasses0(J[Ljava/lang/Class;)V
>> >>> java.instrument at 20.0.1 (0 bytes) @ 0x00007f8d886d8004
>> >>> [0x00007f8d886d7fa0+0x0000000000000064]
>> >>> J 181 c1 sun.instrument.InstrumentationImpl.retransformClasses([Ljava/lang/Class;)V
>> >>> java.instrument at 20.0.1 (33 bytes) @ 0x00007f8d80c29a5c
>> >>> [0x00007f8d80c29860+0x00000000000001fc]
>> >>> j  Agent.retransformLoop(Ljava/lang/instrument/Instrumentation;Ljava/lang/String;)V+82
>> >>> j  Agent.lambda$premain$0(Ljava/lang/instrument/Instrumentation;Ljava/lang/String;)V+2
>> >>> j  Agent$$Lambda$14+0x0000000801002c00.run()V+8
>> >>> j  java.lang.Thread.runWith(Ljava/lang/Object;Ljava/lang/Runnable;)V+5
>> >>> java.base at 20.0.1
>> >>> j  java.lang.Thread.run()V+19 java.base at 20.0.1
>> >>> v  ~StubRoutines::call_stub 0x00007f8d88138cc6
>> >>>
>> >>> I will continue to investigate on my side, but If you need more
>> >>> details, please ask.
>> >>> Jean-Philippe Bempel
>>


More information about the hotspot-dev mailing list