JDK-8234355 : Buffer overflow in jcmd GC.class_stats due to too many classes
  • Type: Bug
  • Component: hotspot
  • Sub-Component: runtime
  • Affected Version: 11,14
  • Priority: P2
  • Status: Closed
  • Resolution: Fixed
  • Submitted: 2019-11-18
  • Updated: 2021-03-16
  • Resolved: 2019-12-04
The Version table provides details related to the release that this issue/RFE will be addressed.

Unresolved : Release in which this issue/RFE will be addressed.
Resolved: Release in which this issue/RFE has been resolved.
Fixed : Release in which this issue/RFE has been fixed. The release containing this fix may be available for download as an Early Access Release or a General Availability Release.

To download the current JDK release, click here.
JDK 11 JDK 14
11.0.12-oracleFixed 14 b26Fixed
Related Reports
Relates :  
JDK-8232758 - The jcmd GC.class_stats produces warning: Ran out of C-heap; undercounted
Relates :  
JDK-8232759 - Remove GC.class_stats
Relates :  
JDK-8235334 - Deprecate jcmd GC.class_stats
Description
Test failed with 
#
# A fatal error has been detected by the Java Runtime Environment:
#
#  Internal Error (open/src/hotspot/share/utilities/ostream.cpp:997), pid=6734, tid=6766
#  assert(false) failed: Exceeded max buffer size for this string.
#
# JRE version: Java(TM) SE Runtime Environment (14.0+24) (fastdebug build 14-ea+24-1068)
# Java VM: Java HotSpot(TM) 64-Bit Server VM (fastdebug 14-ea+24-1068, mixed mode, tiered, z gc, linux-amd64)
# Problematic frame:
# V  [libjvm.so+0x13b959c]  bufferedStream::write(char const*, unsigned long)+0x17c
#
# Core dump will be written. Default location: Core dumps may be processed with "/opt/core.sh %p" (or dumping to /opt/mach5/mesos/work_dir/slaves/fcf4c0c4-d73e-4321-860c-6613427db92b-S2190/frameworks/1735e8a2-a1db-478c-8104-60c8b0af87dd-0196/executors/6107b495-02d7-4611-83e5-02a265731c06/runs/432907b4-7e05-48ef-991c-54020f3ff8b0/testoutput/test-support/jtreg_closed_test_hotspot_jtreg_applications_runthese_RunThese24H_java/scratch/0/core.6734)
#
# If you would like to submit a bug report, please visit:
#   https://bugreport.java.com/bugreport/crash.jsp
#

---------------  S U M M A R Y ------------

Command Line: -Xbootclasspath/a:. -XX:+UnlockDiagnosticVMOptions -XX:+WhiteBoxAPI -XX:MaxRAMPercentage=6 -XX:+UnlockExperimentalVMOptions -XX:+UseZGC -XX:MaxRAMPercentage=50 -Djava.net.preferIPv6Addresses=false -XX:+DisplayVMOutputToStderr -Xlog:gc*,gc+heap=debug:gc.log:uptime,timemillis,level,tags -XX:+DisableExplicitGC -XX:+StartAttachListener --add-exports=java.base/java.lang=ALL-UNNAMED --add-opens=java.base/java.lang=ALL-UNNAMED --add-exports=java.xml/com.sun.org.apache.xerces.internal.parsers=ALL-UNNAMED --add-exports=java.xml/com.sun.org.apache.xerces.internal.util=ALL-UNNAMED -Djava.io.tmpdir=/opt/mach5/mesos/work_dir/slaves/fcf4c0c4-d73e-4321-860c-6613427db92b-S2190/frameworks/1735e8a2-a1db-478c-8104-60c8b0af87dd-0196/executors/6107b495-02d7-4611-83e5-02a265731c06/runs/432907b4-7e05-48ef-991c-54020f3ff8b0/testoutput/test-support/jtreg_closed_test_hotspot_jtreg_applications_runthese_RunThese24H_java/scratch/0/java.io.tmpdir -Duser.home=/opt/mach5/mesos/work_dir/slaves/fcf4c0c4-d73e-4321-860c-6613427db92b-S2190/frameworks/1735e8a2-a1db-478c-8104-60c8b0af87dd-0196/executors/6107b495-02d7-4611-83e5-02a265731c06/runs/432907b4-7e05-48ef-991c-54020f3ff8b0/testoutput/test-support/jtreg_closed_test_hotspot_jtreg_applications_runthese_RunThese24H_java/scratch/0/user.home -agentpath:/opt/mach5/mesos/work_dir/jib-master/install/jdk-14+24-1068/linux-x64-debug.test/hotspot/jtreg/native/libJvmtiStressModule.so -XX:NativeMemoryTracking=detail applications.kitchensink.process.stress.Main /opt/mach5/mesos/work_dir/slaves/fcf4c0c4-d73e-4321-860c-6613427db92b-S2190/frameworks/1735e8a2-a1db-478c-8104-60c8b0af87dd-0196/executors/6107b495-02d7-4611-83e5-02a265731c06/runs/432907b4-7e05-48ef-991c-54020f3ff8b0/testoutput/test-support/jtreg_closed_test_hotspot_jtreg_applications_runthese_RunThese24H_java/scratch/0/kitchensink.final.properties

Host: Intel(R) Xeon(R) Platinum 8167M CPU @ 2.00GHz, 8 cores, 58G, Oracle Linux Server release 7.6
Time: Sat Nov 16 14:58:16 2019 UTC elapsed time: 53459 seconds (0d 14h 50m 59s)

---------------  T H R E A D  ---------------

Current thread (0x00007fc0fc2d60b0):  VMThread "VM Thread" [stack: 0x00007fbecdf00000,0x00007fbece000000] [id=6766]

Stack: [0x00007fbecdf00000,0x00007fbece000000],  sp=0x00007fbecdffd950,  free space=1014k
Native frames: (J=compiled Java code, A=aot compiled Java code, j=interpreted, Vv=VM code, C=native code)
V  [libjvm.so+0x13b959c]  bufferedStream::write(char const*, unsigned long)+0x17c
V  [libjvm.so+0x13b9a88]  outputStream::do_vsnprintf_and_write_with_automatic_buffer(char const*, __va_list_tag*, bool)+0xf8
V  [libjvm.so+0x13b9da9]  outputStream::print(char const*, ...)+0xd9
V  [libjvm.so+0xcce622]  KlassInfoHisto::print_class_stats(outputStream*, bool, char const*)+0x6d2
V  [libjvm.so+0xccf823]  HeapInspection::heap_inspection(outputStream*)+0x743
V  [libjvm.so+0xc65866]  VM_GC_HeapInspection::doit()+0x86
V  [libjvm.so+0x172c603]  VM_Operation::evaluate()+0x143
V  [libjvm.so+0x175b138]  VMThread::evaluate_operation(VM_Operation*) [clone .constprop.66]+0x2b8
V  [libjvm.so+0x175bb1f]  VMThread::loop()+0x82f
V  [libjvm.so+0x175beaa]  VMThread::run()+0xca
V  [libjvm.so+0x1675656]  Thread::call_run()+0xf6
V  [libjvm.so+0x13a783e]  thread_native_entry(Thread*)+0x10e

Register to memory mapping:

RAX=0x00007fc104897000 points into unknown readable memory: 58 00 00 00 00 00 00 00
RBX=0x00007fbecdbc1d90 is pointing into the stack for thread: 0x00007fc0fc377310
RCX=0x00007fc103766100: <offset 0x0000000001933100> in /opt/mach5/mesos/work_dir/jib-master/install/jdk-14+24-1068/linux-x64-debug.jdk/jdk-14/fastdebug/lib/server/libjvm.so at 0x00007fc101e33000
RDX=0x00007fc1037b39e1: <offset 0x00000000019809e1> in /opt/mach5/mesos/work_dir/jib-master/install/jdk-14+24-1068/linux-x64-debug.jdk/jdk-14/fastdebug/lib/server/libjvm.so at 0x00007fc101e33000
RSP=0x00007fbecdffd950 points into unknown readable memory: 90 1d bc cd be 7f 00 00
RBP=0x00007fbecdffd980 points into unknown readable memory: b0 e1 ff cd be 7f 00 00
RSI=0x00000000000003e5 is an unknown value
RDI=0x00007fc103765f98: <offset 0x0000000001932f98> in /opt/mach5/mesos/work_dir/jib-master/install/jdk-14+24-1068/linux-x64-debug.jdk/jdk-14/fastdebug/lib/server/libjvm.so at 0x00007fc101e33000
R8 =0x00000000000007d0 is an unknown value
R9 =0x000000000000005f is an unknown value
R10=0x2e3130306b636568 is an unknown value
R11=0x00007fc103e02650: <offset 0x000000000018e650> in /lib64/libc.so.6 at 0x00007fc103c74000
R12=0x00007fbecdffd9a0 points into unknown readable memory: 20 6a 61 76 61 73 6f 66
R13=0x000000000000005f is an unknown value
R14=0x0000000006400000 is an unknown value
R15=0x0000000008000000 is an unknown value


Registers:
RAX=0x00007fc104897000, RBX=0x00007fbecdbc1d90, RCX=0x00007fc103766100, RDX=0x00007fc1037b39e1
RSP=0x00007fbecdffd950, RBP=0x00007fbecdffd980, RSI=0x00000000000003e5, RDI=0x00007fc103765f98
R8 =0x00000000000007d0, R9 =0x000000000000005f, R10=0x2e3130306b636568, R11=0x00007fc103e02650
R12=0x00007fbecdffd9a0, R13=0x000000000000005f, R14=0x0000000006400000, R15=0x0000000008000000
RIP=0x00007fc1031ec59c, EFLAGS=0x0000000000010287, CSGSFS=0x002b000000000033, ERR=0x0000000000000006
  TRAPNO=0x000000000000000e

Top of Stack: (sp=0x00007fbecdffd950)
0x00007fbecdffd950:   00007fbecdbc1d90 00007fbecdffd9a0
0x00007fbecdffd960:   0000000000000000 00007fbecdbc1d90
0x00007fbecdffd970:   00000000000007cf 00007fbecdffd9a0
0x00007fbecdffd980:   00007fbecdffe1b0 00007fc1031eca88 

Instructions: (pc=0x00007fc1031ec59c)
0x00007fc1031ec49c:   00 00 00 49 39 d7 76 1c 48 8b 7b 48 31 c9 ba 08
0x00007fc1031ec4ac:   00 00 00 4c 89 fe e8 49 15 21 ff 4c 89 7b 60 48
0x00007fc1031ec4bc:   89 43 48 90 4d 85 ed 75 13 48 83 c4 08 5b 41 5c
0x00007fc1031ec4cc:   41 5d 41 5e 41 5f 5d c3 0f 1f 40 00 48 8b 7b 50
0x00007fc1031ec4dc:   4c 89 ea 4c 89 e6 48 03 7b 48 e8 45 43 f3 fe 4c
0x00007fc1031ec4ec:   01 6b 50 8b 43 20 4c 89 e6 4d 01 e5 b9 08 00 00
0x00007fc1031ec4fc:   00 eb 15 90 80 fa 09 74 33 83 c0 01 89 43 20 48
0x00007fc1031ec50c:   83 c6 01 4c 39 ee 74 b1 0f b6 16 80 fa 0a 75 e4
0x00007fc1031ec51c:   83 c0 01 83 43 24 01 48 98 c7 43 20 00 00 00 00
0x00007fc1031ec52c:   48 01 43 28 31 c0 eb d7 0f 1f 40 00 89 c2 f7 d0
0x00007fc1031ec53c:   83 e2 f8 83 e0 07 48 29 43 28 01 ca 89 53 20 89
0x00007fc1031ec54c:   d0 eb bc 90 c3 0f 1f 80 00 00 00 00 4c 8d 6a ff
0x00007fc1031ec55c:   c6 43 69 01 49 29 cd 4d 85 ed 0f 84 59 ff ff ff
0x00007fc1031ec56c:   e9 67 ff ff ff 0f 1f 80 00 00 00 00 48 8d 05 b9
0x00007fc1031ec57c:   3d 98 00 48 8d 0d 7a 9b 57 00 48 8d 15 54 74 5c
0x00007fc1031ec58c:   00 be e5 03 00 00 48 8d 3d ff 99 57 00 48 8b 00
0x00007fc1031ec59c:   c6 00 58 31 c0 e8 9a ad 63 ff e8 75 5d fe ff 4c
0x00007fc1031ec5ac:   89 f0 48 2b 43 50 49 39 c5 72 08 c6 43 69 01 4c
0x00007fc1031ec5bc:   8d 68 ff 48 8b 53 60 4d 89 f7 e9 d4 fe ff ff 90
0x00007fc1031ec5cc:   0f 1f 40 00 55 48 89 e5 41 54 41 89 f4 53 48 89
0x00007fc1031ec5dc:   fb e8 6e 23 21 ff 48 8d 05 17 e0 95 00 44 89 63
0x00007fc1031ec5ec:   1c 48 89 03 c7 43 18 00 00 00 00 48 c7 43 20 00
0x00007fc1031ec5fc:   00 00 00 48 c7 43 28 00 00 00 00 48 c7 43 30 00
0x00007fc1031ec60c:   00 00 00 48 c7 43 38 00 00 00 00 48 c7 43 40 00
0x00007fc1031ec61c:   00 00 00 5b 41 5c 5d c3 66 66 2e 0f 1f 84 00 00
0x00007fc1031ec62c:   00 00 00 90 55 48 89 e5 41 55 41 89 f5 41 54 41
0x00007fc1031ec63c:   89 d4 53 48 89 fb 48 83 ec 08 e8 05 23 21 ff 48
0x00007fc1031ec64c:   8d 05 ae df 95 00 44 89 6b 1c 48 89 03 c7 43 18
0x00007fc1031ec65c:   00 00 00 00 48 c7 43 20 00 00 00 00 48 c7 43 28
0x00007fc1031ec66c:   00 00 00 00 48 c7 43 30 00 00 00 00 48 c7 43 38
0x00007fc1031ec67c:   00 00 00 00 48 c7 43 40 00 00 00 00 45 84 e4 75
0x00007fc1031ec68c:   13 48 83 c4 08 5b 41 5c 41 5d 5d c3 0f 1f 84 00 


Stack slot to memory mapping:
stack at sp + 0 slots: 0x00007fbecdbc1d90 is pointing into the stack for thread: 0x00007fc0fc377310
stack at sp + 1 slots: 0x00007fbecdffd9a0 points into unknown readable memory: 20 6a 61 76 61 73 6f 66
stack at sp + 2 slots: 0x0 is NULL
stack at sp + 3 slots: 0x00007fbecdbc1d90 is pointing into the stack for thread: 0x00007fc0fc377310
stack at sp + 4 slots: 0x00000000000007cf is an unknown value
stack at sp + 5 slots: 0x00007fbecdffd9a0 points into unknown readable memory: 20 6a 61 76 61 73 6f 66
stack at sp + 6 slots: 0x00007fbecdffe1b0 points into unknown readable memory: a0 e2 ff cd be 7f 00 00
stack at sp + 7 slots: 0x00007fc1031eca88: <offset 0x00000000013b9a88> in /opt/mach5/mesos/work_dir/jib-master/install/jdk-14+24-1068/linux-x64-debug.jdk/jdk-14/fastdebug/lib/server/libjvm.so at 0x00007fc101e33000

VM_Operation (0x00007fbecdbc1ba0): GC_HeapInspection, mode: safepoint, requested by thread 0x00007fc0fc377310
Comments
Fix Request (11u) This eliminates one of the test bug sources, and keeps codebases in sync (I see 11.0.12-oracle). Patch applies cleanly to 11u, passes tier{1,2}.
15-03-2021
We are no longer running these tests with GC.class_stats.
10-12-2019
URL: https://hg.openjdk.java.net/jdk/jdk/rev/86fdc7632b01 User: coleenp Date: 2019-12-04 16:09:26 +0000
04-12-2019
[~iklam] Do you think we can get a CSR through to remove this feature for jdk 14?
03-12-2019
I'm not sure how anyone would learn anything from this feature: coleen@philli$ jcmd 25951 GC.class_stats 25951: WARNING: Ran out of C-heap; undercounted 368 total instances in data below Index Super InstBytes KlassBytes annotations CpAll MethodCount Bytecodes MethodAll ROAll RWAll Total ClassName 1 -1 322888 520 0 0 0 0 0 24 632 656 [B 2 35 166392 680 136 17112 123 5428 35640 23792 31760 55552 java.lang.String 3 35 158720 784 0 23360 147 5815 39376 28960 37184 66144 java.lang.Class 4 -1 86336 520 0 0 0 0 0 24 632 656 [Ljava.lang.Object; 5 35 51776 600 0 1400 7 149 2040 1200 3192 4392 java.util.HashMap$Node 6 -1 33688 520 0 0 0 0 0 24 632 656 [C 7 -1 32472 520 0 0 0 0 0 24 632 656 [I 8 -1 30896 520 0 0 0 0 0 32 632 664 [Ljava.util.HashMap$Node; ... See also JDK-8232759.
03-12-2019
Adding maintainers-pain label: this bug causes our 24h test runs to frequently crash.
03-12-2019
Since this problem seems completely unrelated to GC, I'm going to hand it over to another suitable group. Maybe... runtime?
28-11-2019
I had a look at this with Per. What seems to cause the issue is the following: The test is running with 30 GB heap (quite large), and 8 cores, which with default heuristics gives us 1 concurrent GC thread to walk the whole heap (a weak GC engine). With that setup, it seems from the GC logs that there are 30 minute intervals between GCs, because the allocation pressure is low and the heap is large. The time to perform concurrent marking is 8 seconds. Meanwhile a whole bunch of APIs acquiring class statistics, which keeps all classes in the system alive w.r.t. concurrent marking runs, once every 30 seconds. This has a 27% probability of happening concurrent to marking, and hence keep all classes alive so they can't be unloaded, and conversely there is a 73% chance for each GC that it will successfully be able to unload all unreachable classes in the system. A lot of classes may be loaded in this setup during 30 minutes, so, if we coincidentally hit this unfortunate timing multiple times in a row, we will indeed end up with a lot of classes for a while, until given a chance to unload it all. Any GC that performs concurrent marking (nowadays, G1 and Shenandoah), will have the exact same issue, and there is nothing strange about that. It might be that G1 heuristics have more concurrent GC threads, leading it to mark through the heap faster in this setup, and hence be able to dodge the unfortunate consecutive bad timings you need for the buffer to fill up to 10 M. So the immediate bug seems to be that the max buffer size for printing this class information is too small, and can't assume there will be less than ~300 000 classes in the system at a given point in time. However, we might want to run this test with a smaller heap to make GCs more frequent as well, which would remedy this problem.
28-11-2019
I think the problem is here: http://hg.openjdk.java.net/jdk/jdk/file/ac11b83e0f38/src/hotspot/share/services/attachListener.cpp#l376 where it creates a bufferedStream with no arguments, which results in a bufmax of 10MB. bufferedStream(size_t initial_bufsize = 256, size_t bufmax = 1024*1024*10); From the log file, we have lots of classes (361484 of them!): https://bugs.openjdk.java.net/secure/attachment/85636/hs_err_pid6734.log - Class (reserved=2363913KB, committed=2354769KB) (classes #361484) ( instance classes #333550, array classes #27934) (malloc=174601KB #1959902) (mmap: reserved=2189312KB, committed=2180168KB) ( Metadata: ) ( reserved=2189312KB, committed=2180168KB) ( used=1284144KB) ( free=896024KB) ( waste=0KB =0.00%) so it's very likely that the "jcmd <pid> GC.class_stats" produces more than 10MB of output. We can suppress the assert by adding a flag in the bufferedStream to avoid doing the assert. Instead, the jcmd should just print an additional message to the client. This may be useful for (rare) users that indeed have such a large number of classes. However, I think the GC team should also check if why there are some many classes. Did any recent change cause a bug in the GC of classes?
18-11-2019