C2 exhausts system memory compiling SSLEngineInputRecord::decodeInputRecord

Thu Aug 4 20:30:18 UTC 2022

I guess this should also go to jdk-updates.

Best regards,
Goetz.

From: Lindenmaier, Goetz
Sent: Thursday, August 4, 2022 10:29 PM
To: Carter Kozak <ckozak at ckozak.net>; hotspot-compiler-dev at openjdk.org
Subject: RE: C2 exhausts system memory compiling SSLEngineInputRecord::decodeInputRecord

Hi,

We ran into the presumable same issue.
We already narrowed it down to the same change.

I had opened [JDK-8291919] [11u] High compiler native memory consumption after 8280799 - Java Bug System (openjdk.org)<https://bugs.openjdk.org/browse/JDK-8291919>
For this.

Best regards,
  Goetz.

From: hotspot-compiler-dev <hotspot-compiler-dev-retn at openjdk.org<mailto:hotspot-compiler-dev-retn at openjdk.org>> On Behalf Of Carter Kozak
Sent: Thursday, August 4, 2022 9:57 PM
To: hotspot-compiler-dev at openjdk.org<mailto:hotspot-compiler-dev at openjdk.org>
Subject: C2 exhausts system memory compiling SSLEngineInputRecord::decodeInputRecord

Hi,

I filed JDK-8291665<https://bugs.openjdk.org/browse/JDK-8291665> [1] which was originally closed as "This is not a java bug, the crash is on zulu build"; however, I've since been able to reproduce the issue on standard OpenJDK builds consistently with a compiler replay log [2]<https://gist.github.com/carterkozak/4aff21e72e74d42320b4427953a56385>. Unfortunately I lack the permissions to update the ticket myself, so I'd like to share my findings here, and hopefully work toward a solution.

This impacts OpenJDK jdk-11.0.16-ga<https://github.com/openjdk/jdk11u/releases/tag/jdk-11.0.16-ga> [3] (Latest OpenJDK 11 hotfix which resolves a cvss 9.8 vulnerability) observed using public builds as well as a build I created from source. The crash impacted dozens of applications repeatedly within the first day of rollout, as the pattern which triggers the failure exists within the JDK itself, used within TLS. The failure presents as a jvm crash after the compiler consumes all physical memory. Some applications crash after 50-90 seconds around ~30% of launches, while others crash less frequently. In all cases I've observed, the failure has been within C2 compilation of SSLEngineInputRecord::decodeInputRecord

The failure is reproducible using the compiler replay log with a debug-enabled jdk-11.0.16-ga and produces an hs_err_pid log as seen below:
./linux-x86_64-normal-server-fastdebug-jdk-11.0.16-ga/bin/java -XX:+ReplayCompiles -XX:ReplayDataFile=replay.log

I have verified that the failure is not reproducible using the previous release jdk-11.0.15-ga. The failure appears to be the result of commit 9ce8530c<https://github.com/openjdk/jdk11u/commit/9ce8530c5d5f179fa42e1060447aead887570124> [4] (JDK-8279219<https://bugs.openjdk.org/browse/JDK-8279219> [REDO] C2 crash when allocating array of size too large [5]), reverting this commit allows the replay to complete successfully (not to imply the commit itself should be reverted as I don't have context on what it resolves, but it should help narrow the search space).

Thanks,
Carter Kozak

[1] https://bugs.openjdk.org/browse/JDK-8291665
[2] Compiler replay log can be found here: https://gist.github.com/carterkozak/4aff21e72e74d42320b4427953a56385
[3] https://github.com/openjdk/jdk11u/releases/tag/jdk-11.0.16-ga
[4] https://github.com/openjdk/jdk11u/commit/9ce8530c5d5f179fa42e1060447aead887570124
[5] https://bugs.openjdk.org/browse/JDK-8279219

# To suppress the following error report, specify this argument

# after -XX: or in .hotspotrc:  SuppressErrorAt=/split_if.cpp:131

#

# A fatal error has been detected by the Java Runtime Environment:

#

#  Internal Error (/home/user/code/openjdk/jdk11u-dev/src/hotspot/share/opto/split_if.cpp:131), pid=165552, tid=165579

#  assert(use->is_If() || use->is_CMove() || use->Opcode() == Op_Opaque1 || use->is_AllocateArray()) failed: unexpected node type

#

# JRE version: OpenJDK Runtime Environment (11.0.16) (fastdebug build 11.0.16-internal+0-adhoc.user.jdk11u-dev)

# Java VM: OpenJDK 64-Bit Server VM (fastdebug 11.0.16-internal+0-adhoc.user.jdk11u-dev, mixed mode, tiered, compressed oops, g1 gc, linux-amd64)

# Core dump will be written. Default location: Core dumps may be processed with "/usr/share/apport/apport -p%p -s%s -c%c -d%d -P%P -u%u -g%g -- %E" (or dumping to /home/user/jvm-debugging/core.165552)

#

# An error report file with more information is saved as:

# /home/user/jvm-debugging/hs_err_pid165552.log

#

# If you would like to submit a bug report, please visit:

#   https://bugreport.java.com/bugreport/crash.jsp<https://eur03.safelinks.protection.outlook.com/?url=https%3A%2F%2Fbugreport.java.com%2Fbugreport%2Fcrash.jsp&data=05%7C01%7Cgoetz.lindenmaier%40sap.com%7C09db704ab96f4d51404608da7653bcf0%7C42f7676cf455423c82f6dc2d99791af7%7C0%7C0%7C637952399293438560%7CUnknown%7CTWFpbGZsb3d8eyJWIjoiMC4wLjAwMDAiLCJQIjoiV2luMzIiLCJBTiI6Ik1haWwiLCJXVCI6Mn0%3D%7C3000%7C%7C%7C&sdata=8Qqto8DWjUV6h4AKrlqzA%2FnT8fzJ0ddKekkHRCqPP30%3D&reserved=0>

#

Current thread is 165579

Dumping core ...

zsh: abort (core dumped)  ./linux-x86_64-normal-server-fastdebug-jdk-11.0.16-ga/bin/jav

#

# A fatal error has been detected by the Java Runtime Environment:

#

#  Internal Error (/home/user/code/openjdk/jdk11u-dev/src/hotspot/share/opto/split_if.cpp:131), pid=165552, tid=165579

#  assert(use->is_If() || use->is_CMove() || use->Opcode() == Op_Opaque1 || use->is_AllocateArray()) failed: unexpected node type

#

# JRE version: OpenJDK Runtime Environment (11.0.16) (fastdebug build 11.0.16-internal+0-adhoc.user.jdk11u-dev)

# Java VM: OpenJDK 64-Bit Server VM (fastdebug 11.0.16-internal+0-adhoc.user.jdk11u-dev, mixed mode, tiered, compressed oops, g1 gc, linux-amd64)

# Core dump will be written. Default location: Core dumps may be processed with "/usr/share/apport/apport -p%p -s%s -c%c -d%d -P%P -u%u -g%g -- %E" (or dumping to /home/user/jvm-debugging/core.165552)

#

# If you would like to submit a bug report, please visit:

#   https://bugreport.java.com/bugreport/crash.jsp<https://eur03.safelinks.protection.outlook.com/?url=https%3A%2F%2Fbugreport.java.com%2Fbugreport%2Fcrash.jsp&data=05%7C01%7Cgoetz.lindenmaier%40sap.com%7C09db704ab96f4d51404608da7653bcf0%7C42f7676cf455423c82f6dc2d99791af7%7C0%7C0%7C637952399293438560%7CUnknown%7CTWFpbGZsb3d8eyJWIjoiMC4wLjAwMDAiLCJQIjoiV2luMzIiLCJBTiI6Ik1haWwiLCJXVCI6Mn0%3D%7C3000%7C%7C%7C&sdata=8Qqto8DWjUV6h4AKrlqzA%2FnT8fzJ0ddKekkHRCqPP30%3D&reserved=0>

#

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

Command Line: -XX:+ReplayCompiles -XX:ReplayDataFile=replay.log

Host: linux, Intel(R) Xeon(R) W-2175 CPU @ 2.50GHz, 28 cores, 62G, Ubuntu 20.04.4 LTS

Time: Thu Aug  4 08:27:42 2022 EDT elapsed time: 0.606943 seconds (0d 0h 0m 0s)

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

Current thread (0x00007f75003c8800):  JavaThread "C2 CompilerThread0" daemon [_thread_in_native, id=165579, stack(0x00007f74b6434000,0x00007f74b6535000)]

Current CompileTask:

C2:    606   27   !b  4       sun.security.ssl.SSLEngineInputRecord::decodeInputRecord (812 bytes)

Stack: [0x00007f74b6434000,0x00007f74b6535000],  sp=0x00007f74b652e030,  free space=1000k

Native frames: (J=compiled Java code, A=aot compiled Java code, j=interpreted, Vv=VM code, C=native code)

V  [libjvm.so+0x1a6ea5a]  VMError::report_and_die(int, char const*, char const*, __va_list_tag*, Thread*, unsigned char*, void*, void*, char const*, int, unsigned long)+0x1ca

V  [libjvm.so+0x1a6fbc5]  VMError::report_and_die(Thread*, void*, char const*, int, char const*, char const*, __va_list_tag*)+0x35

V  [libjvm.so+0xc302aa]  report_vm_error(char const*, int, char const*, char const*, ...)+0x10a

V  [libjvm.so+0x187b68d]  PhaseIdealLoop::split_up(Node*, Node*, Node*) [clone .part.0]+0x173d

V  [libjvm.so+0x187f8e3]  PhaseIdealLoop::do_split_if(Node*)+0x763

V  [libjvm.so+0x1442420]  PhaseIdealLoop::split_if_with_blocks_post(Node*, bool)+0xf20

V  [libjvm.so+0x144267d]  PhaseIdealLoop::split_if_with_blocks(VectorSet&, Node_Stack&, bool)+0x20d

V  [libjvm.so+0x14378a3]  PhaseIdealLoop::build_and_optimize()+0x1133

V  [libjvm.so+0xb3f881]  Compile::optimize_loops(int&, PhaseIterGVN&, LoopOptsMode) [clone .part.0]+0x311

V  [libjvm.so+0xb4418f]  Compile::Optimize()+0xd1f

V  [libjvm.so+0xb46116]  Compile::Compile(ciEnv*, C2Compiler*, ciMethod*, int, bool, bool, bool, bool, DirectiveSet*)+0x1ae6

V  [libjvm.so+0x915c24]  C2Compiler::compile_method(ciEnv*, ciMethod*, int, DirectiveSet*)+0x334

V  [libjvm.so+0xb57250]  CompileBroker::invoke_compiler_on_method(CompileTask*)+0x540

V  [libjvm.so+0xb588f8]  CompileBroker::compiler_thread_loop()+0x678

V  [libjvm.so+0x19a4c52]  JavaThread::thread_main_inner()+0x252

V  [libjvm.so+0x199d62b]  Thread::call_run()+0x7b

V  [libjvm.so+0x1693926]  thread_native_entry(Thread*)+0x106

---------------  P R O C E S S  ---------------

uid  : 1000 euid : 1000 gid  : 1000 egid : 1000

umask: 0002 (-------w-)

Threads class SMR info:

_java_thread_list=0x00007f7500885270, length=9, elements={

0x00007f7500032000, 0x00007f750039e000, 0x00007f75003a0800, 0x00007f75003c3800,

0x00007f75003c6000, 0x00007f75003c8800, 0x00007f75003cb000, 0x00007f75003cd800,

0x00007f7500886000

}

_java_thread_list_alloc_cnt=10, _java_thread_list_free_cnt=9, _java_thread_list_max=9, _nested_thread_list_max=0

_tlh_cnt=34, _tlh_times=0, avg_tlh_time=0.00, _tlh_time_max=0

_delete_lock_wait_cnt=0, _delete_lock_wait_max=0

_to_delete_list_cnt=0, _to_delete_list_max=1

Java Threads: ( => current thread )

  0x00007f7500032000 JavaThread "main" [_thread_blocked, id=165553, stack(0x00007f7505585000,0x00007f7505686000)]

  0x00007f750039e000 JavaThread "Reference Handler" daemon [_thread_blocked, id=165573, stack(0x00007f74b6da8000,0x00007f74b6ea9000)]

  0x00007f75003a0800 JavaThread "Finalizer" daemon [_thread_blocked, id=165574, stack(0x00007f74b6ca7000,0x00007f74b6da8000)]

  0x00007f75003c3800 JavaThread "Signal Dispatcher" daemon [_thread_blocked, id=165577, stack(0x00007f74b6636000,0x00007f74b6737000)]

  0x00007f75003c6000 JavaThread "Service Thread" daemon [_thread_blocked, id=165578, stack(0x00007f74b6535000,0x00007f74b6636000)]

=>0x00007f75003c8800 JavaThread "C2 CompilerThread0" daemon [_thread_in_native, id=165579, stack(0x00007f74b6434000,0x00007f74b6535000)]

  0x00007f75003cb000 JavaThread "C1 CompilerThread0" daemon [_thread_blocked, id=165580, stack(0x00007f74b6333000,0x00007f74b6434000)]

  0x00007f75003cd800 JavaThread "Sweeper thread" daemon [_thread_blocked, id=165581, stack(0x00007f74b6232000,0x00007f74b6333000)]

  0x00007f7500886000 JavaThread "Common-Cleaner" daemon [_thread_blocked, id=165612, stack(0x00007f74b59d1000,0x00007f74b5ad2000)]

Other Threads:

  0x00007f7500388000 VMThread "VM Thread" [stack: 0x00007f74b6eab000,0x00007f74b6fab000] [id=165572]

  0x00007f75004c1800 WatcherThread [stack: 0x00007f74b6132000,0x00007f74b6232000] [id=165586]

  0x00007f7500052000 GCTaskThread "GC Thread#0" [stack: 0x00007f750521e000,0x00007f750531e000] [id=165558]

  0x00007f7500091000 ConcurrentGCThread "G1 Main Marker" [stack: 0x00007f74e8218000,0x00007f74e8318000] [id=165563]

  0x00007f7500093000 ConcurrentGCThread "G1 Conc#0" [stack: 0x00007f74e8116000,0x00007f74e8216000] [id=165564]

  0x00007f750026b800 ConcurrentGCThread "G1 Refine#0" [stack: 0x00007f74b79fb000,0x00007f74b7afb000] [id=165566]

  0x00007f750026e000 ConcurrentGCThread "G1 Young RemSet Sampling" [stack: 0x00007f74b78f9000,0x00007f74b79f9000] [id=165567]

Threads with active compile tasks:

C2 CompilerThread0      614   27   !b  4       sun.security.ssl.SSLEngineInputRecord::decodeInputRecord (812 bytes)

-------------- next part --------------
An HTML attachment was scrubbed...
URL: <https://mail.openjdk.org/pipermail/jdk-updates-dev/attachments/20220804/244872ba/attachment-0001.htm>