JDK-8229894 : SEGV during class loading in InstanceKlass::print_class_load_logging
  • Type: Bug
  • Component: hotspot
  • Sub-Component: runtime
  • Affected Version: 14
  • Priority: P3
  • Status: Closed
  • Resolution: Cannot Reproduce
  • Submitted: 2019-08-19
  • Updated: 2019-11-04
  • Resolved: 2019-11-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 14
14Resolved
Related Reports
Relates :  
JDK-8233386 - Initialize NULL fields for unused decorations
Description
Test failed with 
#
# A fatal error has been detected by the Java Runtime Environment:
#
#  SIGSEGV (0xb) at pc=0x00007fbb9a455fb9, pid=32646, tid=11992
#
# JRE version: Java(TM) SE Runtime Environment (14.0+11) (build 14-ea+11-345)
# Java VM: Java HotSpot(TM) 64-Bit Server VM (14-ea+11-345, mixed mode, sharing, tiered, jvmci, jvmci compiler, compressed oops, g1 gc, linux-amd64)
# Problematic frame:
# C  [libc.so.6+0x4cfb9]  _IO_vfprintf+0x4a79
#
# Core dump will be written. Default location: /scratch/opt/mach5/mesos/work_dir/slaves/dd0bab7c-a530-4905-bb6b-daa7153eb2c1-S312/frameworks/1735e8a2-a1db-478c-8104-60c8b0af87dd-0196/executors/0831ae75-5b21-496f-9f65-4d85eb742e70/runs/7e448e75-8051-4bcf-b36a-2a23de02b103/testoutput/test-support/jtreg_closed_test_hotspot_jtreg_applications_runthese_RunThese24H_java/scratch/0/core.32646
#
# If you would like to submit a bug report, please visit:
#   http://bugreport.java.com/bugreport/crash.jsp
#

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

Command Line: -XX:MaxRAMPercentage=6 -XX:+UnlockExperimentalVMOptions -XX:+EnableJVMCI -XX:+TieredCompilation -XX:+UseJVMCICompiler -Djvmci.Compiler=graal -ea -esa --add-opens=java.base/java.net=ALL-UNNAMED -Dseed=5281091281653595 -XX:MaxRAMPercentage=50 applications.runthese.Runner -duration 1440 -runlist /scratch/opt/mach5/mesos/work_dir/slaves/dd0bab7c-a530-4905-bb6b-daa7153eb2c1-S312/frameworks/1735e8a2-a1db-478c-8104-60c8b0af87dd-0196/executors/0831ae75-5b21-496f-9f65-4d85eb742e70/runs/7e448e75-8051-4bcf-b36a-2a23de02b103/testoutput/test-support/jtreg_closed_test_hotspot_jtreg_applications_runthese_RunThese24H_java/scratch/0/./RunTheseTestList.dat

Host: Intel(R) Xeon(R) CPU E5-2690 0 @ 2.90GHz, 8 cores, 28G, Oracle Linux Server release 7.1
Time: Mon Aug 19 12:16:26 2019 UTC elapsed time: 26219 seconds (0d 7h 16m 59s)

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

Current thread (0x00007fbae01ad000):  JavaThread "/scratch/opt/mach5/mesos/work_dir/jib-master/install/com/oracle/jpg/bigapps/jck/9.0/jck-9.0-20170922.165600-1.tar.gz/JCK-runtime-9/classes javasoft.sqe.tests.api.java.util.Hashtable.ValuesParallelStream" daemon [_thread_in_vm, id=11992, stack(0x00007fb9f3eea000,0x00007fb9f3feb000)]

Stack: [0x00007fb9f3eea000,0x00007fb9f3feb000],  sp=0x00007fb9f3fe4460,  free space=1001k
Native frames: (J=compiled Java code, A=aot compiled Java code, j=interpreted, Vv=VM code, C=native code)
C  [libc.so.6+0x4cfb9]  _IO_vfprintf+0x4a79
V  [libjvm.so+0x8db474]  jio_fprintf+0x84
V  [libjvm.so+0xa4e22f]  LogFileStreamOutput::write(LogMessageBuffer::Iterator)+0xcf
V  [libjvm.so+0xa5476e]  LogTagSet::log(LogMessageBuffer const&)+0xce
V  [libjvm.so+0x816dd7]  InstanceKlass::print_class_load_logging(ClassLoaderData*, char const*, ClassFileStream const*) const+0x277
V  [libjvm.so+0x5878a0]  ClassFileParser::fill_instance_klass(InstanceKlass*, bool, Thread*)+0x1010
V  [libjvm.so+0x587cae]  ClassFileParser::create_instance_klass(bool, Thread*)+0x5e
V  [libjvm.so+0xa16774]  KlassFactory::create_from_stream(ClassFileStream*, Symbol*, ClassLoaderData*, Handle, InstanceKlass const*, GrowableArray<Handle>*, Thread*)+0x304
V  [libjvm.so+0xd1e064]  SystemDictionary::resolve_from_stream(Symbol*, Handle, Handle, ClassFileStream*, Thread*)+0x154
V  [libjvm.so+0x8dfd30]  jvm_define_class_common(JNIEnv_*, char const*, _jobject*, signed char const*, int, _jobject*, char const*, Thread*)+0x1d0
V  [libjvm.so+0x8dffd5]  JVM_DefineClassWithSource+0x65
C  [libjava.so+0xe092]  Java_java_lang_ClassLoader_defineClass1+0x182
J 2939  java.lang.ClassLoader.defineClass1(Ljava/lang/ClassLoader;Ljava/lang/String;[BIILjava/security/ProtectionDomain;Ljava/lang/String;)Ljava/lang/Class; java.base@14-ea (0 bytes) @ 0x00007fbb81e2dc7d [0x00007fbb81e2db40+0x000000000000013d]
J 258462 jvmci jdk.internal.reflect.MethodAccessorGenerator$1.run()Ljdk/internal/reflect/MagicAccessorImpl; java.base@14-ea (41 bytes) @ 0x00007fbb84030e7c [0x00007fbb84030c80+0x00000000000001fc]
J 281810 jvmci jdk.internal.reflect.MethodAccessorGenerator.generate(Ljava/lang/Class;Ljava/lang/String;[Ljava/lang/Class;Ljava/lang/Class;[Ljava/lang/Class;IZZLjava/lang/Class;)Ljdk/internal/reflect/MagicAccessorImpl; java.base@14-ea (762 bytes) @ 0x00007fbb848a6b64 [0x00007fbb848a3b40+0x0000000000003024]
J 220424 jvmci jdk.internal.reflect.MethodAccessorGenerator.generateMethod(Ljava/lang/Class;Ljava/lang/String;[Ljava/lang/Class;Ljava/lang/Class;[Ljava/lang/Class;I)Ljdk/internal/reflect/MethodAccessor; java.base@14-ea (20 bytes) @ 0x00007fbb82d34d1c [0x00007fbb82d34ca0+0x000000000000007c]
J 169678 jvmci jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(Ljava/lang/Object;[Ljava/lang/Object;)Ljava/lang/Object; java.base@14-ea (10 bytes) @ 0x00007fbb8275444c [0x00007fbb82753f40+0x000000000000050c]
Comments
I don't think I'm going to be able to reproduce this. Closing as CNR.
04-11-2019
I see no races where we set LogTagSet::_decorators transiently to NULL. We've seen this crash once and I don't know how to reproduce it. I'll check in a patch to make it easier to tell whether LogTagSet::_decorators becomes NULL when creating decorations that's passed down to the output function, or whether it's a stack memory stomp (which I don't see how that's possible either). [~lmesnik] How do I run this test now with this same configuration? It looks like it uses jvmci compiler.
01-11-2019
One thread is turning logging off while the other is trying to write to the log file, still don't see how the decorators get out of sync. Thread 318 (Thread 0x7fb9ea6a9700 (LWP 12466)): #0 wait_until_no_readers (this=<optimized out>) at src/hotspot/share/logging/logOutputList.cpp:46 #1 remove_output (node=<optimized out>, this=<optimized out>) at src/hotspot/share/logging/logOutputList.cpp:93 #2 LogOutputList::set_output_level ( this=0x7fbb9a390448 <LogTagSetMapping<(LogTag::type)16, (LogTag::type)60, (LogTag::type)0, (LogTag::type)0, (LogTag::type)0, (LogTag::type)0>::_tagset+40>, output=0x7fbb9a3bd4a0 <aligned_stdoutmem>, level=<optimized out>) at src/hotspot/share/logging/logOutputList.cpp:54 #3 0x00007fbb99bf35cd in set_output_level (level=LogLevel::Off, output=0x7fbb9a3bd4a0 <aligned_stdoutmem>, this=0x7fbb9a390420 <LogTagSetMapping<(LogTag::type)16, (LogTag::type)60, (LogTag::type)0, (LogTag::type)0, (LogTag::type)0, (LogTag::type)0>::_tagset>) at src/hotspot/share/logging/logTagSet.hpp:102 #4 LogConfiguration::configure_output (idx=idx@entry=0, selections=..., decorators=...) at src/hotspot/share/logging/logConfiguration.cpp:243 #5 0x00007fbb99bf3ab4 in LogConfiguration::configure_stdout (level=level@entry=LogLevel::Off, exact_match=exact_match@entry=0) ... Thread 1 (Thread 0x7fb9f3fea700 (LWP 11992)): #8 <signal handler called> #9 0x00007fbb9a455fb9 in vfprintf () from /lib64/libc.so.6 #10 0x00007fbb99a84474 in jio_fprintf (f=<optimized out>, fmt=fmt@entry=0x7fbb9a026881 "[%-*s]") at src/hotspot/share/prims/jvm.cpp:2674 #11 0x00007fbb99bf722f in write_decorations (decorations=..., this=0x7fbb9a3bd4a0 <aligned_stdoutmem>) at src/hotspot/share/logging/logDecorations.hpp:64 #12 LogFileStreamOutput::write (this=this@entry=0x7fbb9a3bd4a0 <aligned_stdoutmem>, msg_iterator=...) at src/hotspot/share/logging/logFileStreamOutput.cpp:98 #13 0x00007fbb99bfd76e in LogTagSet::log ( this=this@entry=0x7fbb9a390420 <LogTagSetMapping<(LogTag::type)16, (LogTag::type)60, (LogTag::type)0, (LogTag::type)0, (LogTag::type)0, (LogTag::type)0>::_tagset>, msg=...) at src/hotspot/share/logging/logMessageBuffer.hpp:76
11-10-2019
This test has changing logging configurations. At the point of the crash, the LogFileStreamOutput._decorators doesn't match the decorations value passed in. at #11 0x00007fbb99bf722f in write_decorations (decorations=..., this=0x7fbb9a3bd4a0 <aligned_stdoutmem>) at src/hotspot/share/logging/logDecorations.hpp:64 64 return _decoration_offset[decorator]; (gdb) print decorations $34 = (const LogDecorations &) @0x7fb9f3fe4be0: {static DecorationsBufferSize = 256, _decorations_buffer = "\000\...etc"..., _decoration_offset = {0x7fba60200d40 "jdk.internal.reflect.GeneratedMethodAccessor1215103 source: __ClassDefiner__", 0x7fba60200d40 "jdk.internal.reflect.GeneratedMethodAccessor1215103 source: __ClassDefiner__", 0xc <Address 0xc out of bounds>, 0x7fbb9a45620d <vfprintf+19661> "\200\275\360\372\377\377", 0x7fb9f3fe4d30 "\220M\376\363\271\177", 0x7fbb99eb39c4 <Symbol::as_klass_external_name() const+500> "\205\300~!\203\350\001H\211\332H\215D\003\001\017\037D", 0x7fb9f3fe4d70 "\200T\376\363\271\177", 0x807671c40 "\340\376\063\232\273\177", 0x7fbb9a00e4b1 "<unknown>", 0x7fba74362c88 "", 0x7fb9f3fe4d90 "0O\376\363\271\177", 0x7fbb99bbd2e8 <Klass::external_name() const+72> "I\211\304H\213u\310dH34%("}, _level = LogLevel::Info, _tagset = @0x7fbb9a390420, _millis = -1, static _vm_start_time_millis = 1566190766667, static _host_name = 0x0} (gdb) print this $35 = (LogFileStreamOutput * const) 0x7fbb9a3bd4a0 <aligned_stdoutmem> (gdb) print *this $36 = {<LogOutput> = {<CHeapObj<(MemoryType)16>> = {<No data fields>}, _vptr.LogOutput = 0x7fbb9a341b28 <vtable for LogStdoutOutput+16>, static InitialConfigBufferSize = 256, _reconfigured = true, _config_string = 0x7fbb280adf20 "all=warning,class+load*=info,class+unload*=info,gc=off", _config_string_buffer_size = 256, _decorators = {_decorators = 3076, static _name = 0x7fbb9a361760 <LogDecorators::_name>, static DefaultDecoratorsMask = 3076, static None = { _decorators = 0, static _name = <same as static member of an already seen type>, static DefaultDecoratorsMask = 3076, static None = <same as static member of an already seen type>}}}, _stream = 0x7fbb9a7d0400 <_IO_2_1_stdout_>, _decorator_padding = {0, 0, 10, 0, 0, 0, 0, 0, 0, 0, 4, 12}} The decorations were created above and appear to have been created when LogTagSet._decorators is NULL since the fields are essentially uninitialized. void LogTagSet::log(const LogMessageBuffer& msg) { LogDecorations decorations(LogLevel::Invalid, *this, _decorators); for (LogOutputList::Iterator it = _output_list.iterator(msg.least_detailed_level()); it != _output_list.end(); it++) { (*it)->write(msg.iterator(it.level(), decorations)); } }
08-10-2019
It could have been programmatically enabled by the vm. This is an odd set though. Interesting observation though Ioi. (gdb) print this $55 = (LogFileStreamOutput * const) 0x7fbb9a3bd4a0 <aligned_stdoutmem> (gdb) print *this $56 = {<LogOutput> = {<CHeapObj<(MemoryType)16>> = {<No data fields>}, _vptr.LogOutput = 0x7fbb9a341b28 <vtable for LogStdoutOutput+16>, static InitialConfigBufferSize = 256, _reconfigured = true, _config_string = 0x7fbb280adf20 "all=warning,class+load*=info,class+unload*=info,gc=off", _config_string_buffer_size = 256, _decorators = {_decorators = 3076, static _name = 0x7fbb9a361760 <LogDecorators::_name>, static DefaultDecoratorsMask = 3076, static None = { _decorators = 0, static _name = <same as static member of an already seen type>, static DefaultDecoratorsMask = 3076, static None = <same as static member of an already seen type>}}}, _stream = 0x7fbb9a7d0400 <_IO_2_1_stdout_>, _decorator_padding = {0, 0, 10, 0, 0, 0, 0, 0, 0, 0, 4, 12}} The hs_err_pid file says it is set programmatically. I don't know why: Logging: Log output configuration: #0: stdout all=warning,class+load*=info,class+unload*=info,gc=off uptime,level,tags (reconfigured) #1: stderr all=off uptime,level,tags
08-10-2019
According to hs_err file Host: Intel(R) Xeon(R) CPU E5-2690 0 @ 2.90GHz, 8 cores, 28G, Oracle Linux Server release 7.1 Time: Mon Aug 19 12:16:26 2019 UTC elapsed time: 26219 seconds (0d 7h 16m 59s) So this VM has executed for a long time, loading lots of classes. InstanceKlass::print_class_load_logging has been called a lot of times, and would have returned immediately each time, as -Xlog:class+load is not enabled in the command-line: Command Line: -XX:MaxRAMPercentage=6 -XX:+UnlockExperimentalVMOptions -XX:+EnableJVMCI -XX:+TieredCompilation -XX:+UseJVMCICompiler -Djvmci.Compiler=graal -ea -esa --add-opens=java.base/java.net=ALL-UNNAMED -Dseed=5281091281653595 -XX:MaxRAMPercentage=50 applications.runthese.Runner -duration 1440 -runlist /scratch/opt/mach5/mesos/work_dir/slaves/dd0bab7c-a530-4905-bb6b-daa7153eb2c1-S312/frameworks/1735e8a2-a1db-478c-8104-60c8b0af87dd-0196/executors/0831ae75-5b21-496f-9f65-4d85eb742e70/runs/7e448e75-8051-4bcf-b36a-2a23de02b103/testoutput/test-support/jtreg_closed_test_hotspot_jtreg_applications_runthese_RunThese24H_java/scratch/0/./RunTheseTestList.dat void InstanceKlass::print_class_load_logging(ClassLoaderData* loader_data, const char* module_name, const ClassFileStream* cfs) const { if (!log_is_enabled(Info, class, load)) { return; } So probably we had some memory corruption that caused things to go berserk.
08-10-2019
The core file was produced with PRODUCT VM but it appears that it was trying to print the uptime_decorator: (gdb) down #11 0x00007fbb99bf722f in write_decorations (decorations=..., this=0x7fbb9a3bd4a0 <aligned_stdoutmem>) at /scratch/opt/mach5/mesos/work_dir/slaves/00f4d7f9-7805-4b6a-aef8-9bb130db2435-S1250/frameworks/1735e8a2-a1db-478c-8104-60c8b0af87dd-0196/executors/7d7f94a2-c88c-4799-b66a-e39012c064f7/runs/d048fdce-5019-448f-8314-fe0faa48f340/workspace/open/src/hotspot/share/logging/logDecorations.hpp:64 64 return _decoration_offset[decorator]; (gdb) print decorator $51 = LogDecorators::uptime_decorator
07-10-2019
ILW = HLM = P3
20-08-2019