JDK-8324205 : Excessive C2 compilation time when parsing allocation of large object
  • Type: Bug
  • Component: hotspot
  • Sub-Component: compiler
  • Affected Version: 11,17,21,22,23
  • Priority: P4
  • Status: Open
  • Resolution: Unresolved
  • Submitted: 2024-01-19
  • Updated: 2024-01-22
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.
Other
tbdUnresolved
Related Reports
Relates :  
JDK-8307788 - vmTestbase/gc/gctests/LargeObjects/large003/TestDescription.java timed out
Relates :  
JDK-8258553 - Limit number of fields in instance to be considered for scalar replacement
Relates :  
JDK-8324171 - assert failed: Live Node limit exceeded limit
Relates :  
JDK-8308094 - Add a compilation timeout flag to catch long running compilations
Description
With a modified version of the test from JDK-8324171 / JDK-8258553, C2 spends an excessive amount of time just during parsing:

java  -XX:CompileCommand=quiet -XX:CompileCommand=compileonly,TestBigObj::test -XX:-TieredCompilation -XX:+PrintCompilation -XX:+PrintInlining -Xbatch -XX:+CITime TestBigObj.java

    C2 Compile Time:       47,055 s
       Parse:                47,045 s
       Optimize:              0,002 s

We seem to spend most time in:

#0  0x00007ffff653badd in UNSIGNED5::read_uint<unsigned char const*, int, UNSIGNED5::ArrayGetSet<unsigned char const*, int> > (array=<optimized out>, offset_rw=@0x7fffe058c2b4: 434923, limit=<optimized out>, get=...)
    at /oracle/jdk3/open/src/hotspot/share/utilities/unsigned5.hpp:130
#1  0x00007ffff6542603 in UNSIGNED5::Reader<unsigned char const*, int, UNSIGNED5::ArrayGetSet<unsigned char const*, int> >::next_uint (this=0x7fffe058c2a8) at /oracle/jdk3/open/src/hotspot/share/utilities/unsigned5.hpp:270
#2  FieldInfoReader::next_uint (this=0x7fffe058c2a8) at /oracle/jdk3/open/src/hotspot/share/oops/fieldInfo.hpp:238
#3  FieldInfoReader::read_field_info (this=0x7fffe058c2a8, fi=...) at /oracle/jdk3/open/src/hotspot/share/oops/fieldInfo.inline.hpp:104
#4  0x00007ffff6aa833f in FieldStreamBase::next (this=0x7fffe058c2a0) at /oracle/jdk3/open/src/hotspot/share/oops/fieldStreams.hpp:80
#5  InstanceKlass::field (this=this@entry=0x7f208000, index=index@entry=58120) at /oracle/jdk3/open/src/hotspot/share/oops/instanceKlass.cpp:1659
#6  0x00007ffff684a77c in fieldDescriptor::reinitialize (this=this@entry=0x7fffe058c488, ik=0x7f208000, index=58120) at /oracle/jdk3/open/src/hotspot/share/runtime/fieldDescriptor.cpp:98
#7  0x00007ffff6540e2c in FieldStreamBase::field_descriptor (this=0x7fffe058c430) at /oracle/jdk3/open/src/hotspot/share/oops/constantPool.hpp:219
#8  ciInstanceKlass::compute_nonstatic_fields_impl (this=this@entry=0x7ffff11d0258, super_fields=super_fields@entry=0x0) at /oracle/jdk3/open/src/hotspot/share/ci/ciInstanceKlass.cpp:532
#9  0x00007ffff65416f1 in ciInstanceKlass::compute_nonstatic_fields (this=<optimized out>) at /oracle/jdk3/open/src/hotspot/share/ci/ciInstanceKlass.cpp:482
#10 ciInstanceKlass::compute_nonstatic_fields (this=0x7ffff11d0258) at /oracle/jdk3/open/src/hotspot/share/ci/ciInstanceKlass.cpp:460
#11 0x00007ffff65417b5 in ciInstanceKlass::nof_nonstatic_fields (this=0x7ffff11d0258) at /oracle/jdk3/open/src/hotspot/share/ci/ciInstanceKlass.hpp:214
#12 ciInstanceKlass::compute_nonstatic_fields (this=<optimized out>) at /oracle/jdk3/open/src/hotspot/share/ci/ciInstanceKlass.cpp:476
#13 ciInstanceKlass::compute_nonstatic_fields (this=this@entry=0x7ffff11cc100) at /oracle/jdk3/open/src/hotspot/share/ci/ciInstanceKlass.cpp:460
#14 0x00007ffff6a08f8c in ciInstanceKlass::nof_nonstatic_fields (this=<optimized out>) at /oracle/jdk3/open/src/hotspot/share/ci/ciInstanceKlass.hpp:214
#15 GraphKit::set_output_for_allocation (this=this@entry=0x7fffe058c960, alloc=0x7ffff11ac4b0, oop_type=0x7ffff11c5cc8, oop_type@entry=0x7ffff11cc100, deoptimize_on_exception=deoptimize_on_exception@entry=255)
    at /oracle/jdk3/open/src/hotspot/share/opto/graphKit.cpp:3656
#16 0x00007ffff6a09635 in GraphKit::new_instance (this=this@entry=0x7fffe058c960, klass_node=<optimized out>, extra_slow_test=<optimized out>, extra_slow_test@entry=0x0, return_size_val=return_size_val@entry=0x0, 
    deoptimize_on_exception=255, deoptimize_on_exception@entry=false) at /oracle/jdk3/open/src/hotspot/share/opto/graphKit.cpp:3772
#17 0x00007ffff7188dc4 in Parse::do_new (this=this@entry=0x7fffe058c960) at /oracle/jdk3/open/src/hotspot/share/opto/parseHelper.cpp:266
#18 0x00007ffff717fa48 in Parse::do_one_bytecode (this=this@entry=0x7fffe058c960) at /oracle/jdk3/open/src/hotspot/share/opto/parse2.cpp:2745
#19 0x00007ffff716ad0a in Parse::do_one_block (this=0x7fffe058c960) at /oracle/jdk3/open/src/hotspot/share/opto/parse1.cpp:1592
#20 0x00007ffff716c1c5 in Parse::do_all_blocks (this=this@entry=0x7fffe058c960) at /oracle/jdk3/open/src/hotspot/share/opto/parse1.cpp:712
#21 0x00007ffff71704a5 in Parse::Parse (this=this@entry=0x7fffe058c960, caller=caller@entry=0x7ffff11b7420, parse_method=<optimized out>, expected_uses=<optimized out>) at /oracle/jdk3/open/src/hotspot/share/opto/parse1.cpp:616
#22 0x00007ffff64b3659 in ParseGenerator::generate (this=0x7ffff11b7408, jvms=0x7ffff11b7420) at /oracle/jdk3/open/src/hotspot/share/opto/callGenerator.hpp:53
#23 0x00007ffff665bfce in Compile::Compile (this=this@entry=0x7fffe058d840, ci_env=ci_env@entry=0x7fffe058e6f0, target=target@entry=0x7ffff11cc1b0, osr_bci=osr_bci@entry=-1, options=..., options@entry=..., 
    directive=directive@entry=0x7ffff01cf1f0) at /oracle/jdk3/open/src/hotspot/share/opto/compile.cpp:791
#24 0x00007ffff64b13c5 in C2Compiler::compile_method (this=<optimized out>, env=0x7fffe058e6f0, target=0x7ffff11cc1b0, entry_bci=-1, install_code=<optimized out>, directive=0x7ffff01cf1f0)

With -XX:EliminateAllocationFieldsLimit=100000 we also hit the node limit:

# A fatal error has been detected by the Java Runtime Environment:
#
#  Internal Error (/opt/mach5/mesos/work_dir/slaves/0db9c48f-6638-40d0-9a4b-bd9cc7533eb8-S10108/frameworks/1735e8a2-a1db-478c-8104-60c8b0af87dd-0196/executors/64ecc42e-c311-4cbc-9f8c-cdb54670fe43/runs/6ce1ca2a-f2b6-4d79-a919-946bcfa599e7/workspace/open/src/hotspot/share/opto/node.cpp:78), pid=3632360, tid=3632375
#  assert(C->live_nodes() <= C->max_node_limit()) failed: Live Node limit exceeded limit
#
# JRE version: Java(TM) SE Runtime Environment (23.0+4) (fastdebug build 23-ea+4-173)
# Java VM: Java HotSpot(TM) 64-Bit Server VM (fastdebug 23-ea+4-173, mixed mode, sharing, compressed oops, compressed class ptrs, g1 gc, linux-amd64)
# Problematic frame:
# V  [libjvm.so+0x1434bb7]  Node::verify_construction()+0x1a7
#
# No core dump will be written. Core dumps have been disabled. To enable core dumping, try "ulimit -c unlimited" before starting Java again

Current CompileTask:
C2:141893   82    b        TestBigObj::test (49 bytes)

Stack: [0x00007f1847335000,0x00007f1847436000],  sp=0x00007f1847430eb0,  free space=1007k
Native frames: (J=compiled Java code, j=interpreted, Vv=VM code, C=native code)
V  [libjvm.so+0x1434bb7]  Node::verify_construction()+0x1a7  (node.cpp:78)
V  [libjvm.so+0x1435923]  Node::Node(unsigned int)+0x43
V  [libjvm.so+0x12da52a]  PhaseMacroExpand::value_from_mem_phi(Node*, BasicType, Type const*, TypeOopPtr const*, AllocateNode*, Node_Stack*, int)+0x45a
V  [libjvm.so+0x12dbd0e]  PhaseMacroExpand::value_from_mem(Node*, Node*, BasicType, Type const*, TypeOopPtr const*, AllocateNode*)+0x86e
V  [libjvm.so+0x12dcb64]  PhaseMacroExpand::create_scalarized_object_description(AllocateNode*, SafePointNode*)+0x224
V  [libjvm.so+0x12de56a]  PhaseMacroExpand::scalar_replacement(AllocateNode*, GrowableArray<SafePointNode*>&)+0xfa
V  [libjvm.so+0x12deb5e]  PhaseMacroExpand::eliminate_allocate_node(AllocateNode*)+0x1ce
V  [libjvm.so+0x12df2f2]  PhaseMacroExpand::eliminate_macro_nodes()+0x3b2
V  [libjvm.so+0x9ed2ae]  Compile::Optimize()+0x135e
V  [libjvm.so+0x9f050b]  Compile::Compile(ciEnv*, ciMethod*, int, Options, DirectiveSet*)+0x1beb
V  [libjvm.so+0x83dc57]  C2Compiler::compile_method(ciEnv*, ciMethod*, int, bool, DirectiveSet*)+0x1e7
V  [libjvm.so+0x9fbacc]  CompileBroker::invoke_compiler_on_method(CompileTask*)+0x92c
V  [libjvm.so+0x9fc758]  CompileBroker::compiler_thread_loop()+0x468
V  [libjvm.so+0xeb99ec]  JavaThread::thread_main_inner()+0xcc
V  [libjvm.so+0x179ea66]  Thread::call_run()+0xb6
V  [libjvm.so+0x14a92e7]  thread_native_entry(Thread*)+0x127

It's probably expected and not easy to avoid, but we should double-check.
Comments
Thanks for the details. I leave it to Daniel to evaluate if that's worth doing.
22-01-2024
There is a way to get the number more quickly by using the code that ciInstanceKlass::compute_nonstatic_fields_impl does: int flen = 0; InstanceKlass* k = get_instanceKlass(); for (JavaFieldStream fs(k); !fs.done(); fs.next()) { if (fs.access_flags().is_static()) continue; flen += 1; } but you will have to get the super classes too. It should be possible to add an API to initialize the length without having to grab all the fields too.
22-01-2024
Yes, the fieldstream implementation seems to be the issue. But then again we don't even access individual field information here but only query nof_nonstatic_fields. Is there a way to get the number without iterating over all the fields?
22-01-2024
Do these large objects have massive numbers of field as per the tests referenced in JDK-8307788? If so this is the impact of the fieldstream implementation.
21-01-2024
ILW = Excessive C2 compilation time, edge case, no workaround but disable compilation of affected method = MLM = P4
19-01-2024
We should add a compilation timeout (JDK-8308094) to catch issues like this.
19-01-2024