A noob question about weird sequence of `*synchronization entry` in a C2 compiled code
Jaroslav Bachorík
jaroslav.bachorik at datadoghq.com
Fri Feb 4 11:59:44 UTC 2022
Hello,
First I want to apologize if I am asking in the wrong mailing list or
the situation is stupidly obvious - feel free to just direct me to any
FAQs in such case.
Now, to the problem - we at Datadog profiling team noticed a
significant number of CPU samples with stacktraces ending in frames
with BCI == -1. Just for reference - we might see up to 60% of samples
ending in frames of a particular method to have BCI set to -1.
While we were using JFR to collect those stacktraces the problem went
largely unnoticed because what JFR (or any other stacktrace generating
code in JDK) does is to attribute all such frames to the first
bytecode instruction of that method. This becomes very confusing when
the first instruction is something like `ICONST_0` which is a part of
the corresponding Java source like `int x = 0`.
When using AGCT via async-profiler directly we see the problem
manifested as missing source line and as such it becomes more visible.
>From what I read it is obvious that having BCI set to -1 is a normal
situation for eg. method prologue. However, spending several tens of
percent on a method prologue feels somehow wrong.
Further experiments confirmed that this is only happening after C2
compilation - all profiles collected during the time the method is
only C1 compiled look correct.
We managed to get the full compilation log of the service which is
exhibiting this behaviour and when looking at the C2 assembly code the
amount and the distribution of the `*synchronization entry` points
seems rather confusing.
For the sake of brevity I am going to post here only one small part of
the assembly which is demonstrating the problem. The full compilation
log is pretty large but I could share it if someone would be willing
to take a look at it.
So, here we go
====
Verified Entry Point]
# {method} {0x00007f2ce3495e18} 'parseJfr'
'(Lorg/openjdk/jmc/common/item/IItemCollection;Ljava/time/Duration;ZZZLorg/openjdk/jmc/common/item/IItemFilter;Ljava/util/function/Predicate;[Ljava/lang/String;)Lcom/datadog/profiling/aggregation/ParsedProfile;'
in 'com/datadog/profiling/aggregation/parser/jfr/JfrParser'
0x00007f2dc98db580: call 0x00007f2ddef241c0 ; {no_reloc}
0x00007f2dc98db585: data16 data16 nop WORD PTR [rax+rax*1+0x0]
0x00007f2dc98db590: mov DWORD PTR [rsp-0x14000],eax
0x00007f2dc98db597: push rbp
0x00007f2dc98db598: sub rsp,0x390 ;*iload
{reexecute=0 rethrow=0 return_oop=0}
; -
com.datadog.profiling.aggregation.parser.jfr.JfrParser::parseJfr at 995
(line 331)
0x00007f2dc98db59f: mov r13,QWORD PTR [rsi+0x1d0]
;*invokeinterface hasNext {reexecute=0 rethrow=0 return_oop=0}
; -
com.datadog.profiling.aggregation.parser.jfr.JfrParser::parseJfr at 474
(line 227)
0x00007f2dc98db5a6: mov r14,QWORD PTR [rsi+0x1c8]
;*synchronization entry
; -
com.datadog.profiling.aggregation.parser.jfr.JfrParser::parseJfr at -1
(line 165)
0x00007f2dc98db5ad: mov r11d,DWORD PTR [rsi+0x40]
;*invokeinterface next {reexecute=0 rethrow=0 return_oop=0}
; -
com.datadog.profiling.aggregation.parser.jfr.JfrParser::parseJfr at 484
(line 227)
0x00007f2dc98db5b1: mov DWORD PTR [rsp+0x198],r11d
;*synchronization entry
; -
com.datadog.profiling.aggregation.parser.jfr.JfrParser::parseJfr at -1
(line 165)
0x00007f2dc98db5b9: mov r10,QWORD PTR [rsi+0x1c0]
;*invokeinterface hasNext {reexecute=0 rethrow=0 return_oop=0}
; -
com.datadog.profiling.aggregation.parser.jfr.JfrParser::parseJfr at 474
(line 227)
0x00007f2dc98db5c0: mov QWORD PTR [rsp+0x50],r10
;*synchronization entry
; -
com.datadog.profiling.aggregation.parser.jfr.JfrParser::parseJfr at -1
(line 165)
0x00007f2dc98db5c5: mov r10,QWORD PTR [rsi+0x1a0]
;*invokeinterface hasNext {reexecute=0 rethrow=0 return_oop=0}
; -
com.datadog.profiling.aggregation.parser.jfr.JfrParser::parseJfr at 474
(line 227)
0x00007f2dc98db5cc: mov QWORD PTR [rsp+0x58],r10
;*synchronization entry
; -
com.datadog.profiling.aggregation.parser.jfr.JfrParser::parseJfr at -1
(line 165)
0x00007f2dc98db5d1: mov r10,QWORD PTR [rsi+0x198]
;*invokeinterface hasNext {reexecute=0 rethrow=0 return_oop=0}
; -
com.datadog.profiling.aggregation.parser.jfr.JfrParser::parseJfr at 474
(line 227)
0x00007f2dc98db5d8: mov QWORD PTR [rsp+0x60],r10
0x00007f2dc98db5dd: mov r10,QWORD PTR [rsi+0x190]
0x00007f2dc98db5e4: mov QWORD PTR [rsp+0x68],r10
;*synchronization entry
; -
com.datadog.profiling.aggregation.parser.jfr.JfrParser::parseJfr at -1
(line 165)
0x00007f2dc98db5e9: mov r10,QWORD PTR [rsi+0x188]
;*invokeinterface hasNext {reexecute=0 rethrow=0 return_oop=0}
; -
com.datadog.profiling.aggregation.parser.jfr.JfrParser::parseJfr at 474
(line 227)
0x00007f2dc98db5f0: mov QWORD PTR [rsp+0x70],r10
0x00007f2dc98db5f5: mov r10,QWORD PTR [rsi+0x180]
0x00007f2dc98db5fc: mov QWORD PTR [rsp+0x78],r10
;*synchronization entry
; -
com.datadog.profiling.aggregation.parser.jfr.JfrParser::parseJfr at -1
(line 165)
0x00007f2dc98db601: mov r10,QWORD PTR [rsi+0x178]
;*invokeinterface hasNext {reexecute=0 rethrow=0 return_oop=0}
; -
com.datadog.profiling.aggregation.parser.jfr.JfrParser::parseJfr at 474
(line 227)
0x00007f2dc98db608: mov QWORD PTR [rsp+0x80],r10
;*synchronization entry
; -
com.datadog.profiling.aggregation.parser.jfr.JfrParser::parseJfr at -1
(line 165)
0x00007f2dc98db610: mov r10,QWORD PTR [rsi+0x170]
;*invokeinterface hasNext {reexecute=0 rethrow=0 return_oop=0}
; -
com.datadog.profiling.aggregation.parser.jfr.JfrParser::parseJfr at 474
(line 227)
0x00007f2dc98db617: mov QWORD PTR [rsp+0x88],r10
;*synchronization entry
; -
com.datadog.profiling.aggregation.parser.jfr.JfrParser::parseJfr at -1
(line 165)
0x00007f2dc98db61f: mov rbx,QWORD PTR [rsi+0x168]
;*invokeinterface hasNext {reexecute=0 rethrow=0 return_oop=0}
; -
com.datadog.profiling.aggregation.parser.jfr.JfrParser::parseJfr at 474
(line 227)
0x00007f2dc98db626: mov QWORD PTR [rsp+0x90],rbx
;*synchronization entry
; -
com.datadog.profiling.aggregation.parser.jfr.JfrParser::parseJfr at -1
(line 165)
0x00007f2dc98db62e: mov rbx,QWORD PTR [rsi+0x160]
;*invokeinterface hasNext {reexecute=0 rethrow=0 return_oop=0}
; -
com.datadog.profiling.aggregation.parser.jfr.JfrParser::parseJfr at 474
(line 227)
0x00007f2dc98db635: mov QWORD PTR [rsp+0x98],rbx
;*synchronization entry
; -
com.datadog.profiling.aggregation.parser.jfr.JfrParser::parseJfr at -1
(line 165)
0x00007f2dc98db63d: mov rbx,QWORD PTR [rsi+0x158]
;*invokeinterface hasNext {reexecute=0 rethrow=0 return_oop=0}
; -
com.datadog.profiling.aggregation.parser.jfr.JfrParser::parseJfr at 474
(line 227)
0x00007f2dc98db644: mov QWORD PTR [rsp+0xa0],rbx
;*synchronization entry
; -
com.datadog.profiling.aggregation.parser.jfr.JfrParser::parseJfr at -1
(line 165)
0x00007f2dc98db64c: mov rbx,QWORD PTR [rsi+0x148]
;*synchronization entry
; -
org.openjdk.jmc.common.collection.AbstractIterator::hasNext at -1 (line
58)
; -
com.datadog.profiling.aggregation.parser.jfr.JfrParser::parseJfr at 474
(line 227)
0x00007f2dc98db653: mov QWORD PTR [rsp+0xa8],rbx
;*synchronization entry
; -
com.datadog.profiling.aggregation.parser.jfr.JfrParser::parseJfr at -1
(line 165)
0x00007f2dc98db65b: mov rbx,QWORD PTR [rsi+0x140]
;*invokeinterface hasNext {reexecute=0 rethrow=0 return_oop=0}
; -
com.datadog.profiling.aggregation.parser.jfr.JfrParser::parseJfr at 474
(line 227)
0x00007f2dc98db662: mov QWORD PTR [rsp+0xb0],rbx
;*synchronization entry
; -
com.datadog.profiling.aggregation.parser.jfr.JfrParser::parseJfr at -1
(line 165)
0x00007f2dc98db66a: mov rbx,QWORD PTR [rsi+0x138] ;*getfield
next {reexecute=0 rethrow=0 return_oop=0}
; -
org.openjdk.jmc.common.collection.AbstractIterator::hasNext at 1 (line
58)
; -
com.datadog.profiling.aggregation.parser.jfr.JfrParser::parseJfr at 474
(line 227)
0x00007f2dc98db671: mov QWORD PTR [rsp+0xb8],rbx
;*synchronization entry
; -
com.datadog.profiling.aggregation.parser.jfr.JfrParser::parseJfr at -1
(line 165)
0x00007f2dc98db679: mov rbx,QWORD PTR [rsi+0x130] ;*getfield
next {reexecute=0 rethrow=0 return_oop=0}
; -
org.openjdk.jmc.common.collection.AbstractIterator::hasNext at 1 (line
58)
; -
com.datadog.profiling.aggregation.parser.jfr.JfrParser::parseJfr at 474
(line 227)
0x00007f2dc98db680: mov QWORD PTR [rsp+0xc0],rbx
;*synchronization entry
; -
com.datadog.profiling.aggregation.parser.jfr.JfrParser::parseJfr at -1
(line 165)
0x00007f2dc98db688: mov rbx,QWORD PTR [rsi+0x128] ;*getfield
next {reexecute=0 rethrow=0 return_oop=0}
; -
org.openjdk.jmc.common.collection.AbstractIterator::hasNext at 1 (line
58)
; -
com.datadog.profiling.aggregation.parser.jfr.JfrParser::parseJfr at 474
(line 227)
0x00007f2dc98db68f: mov QWORD PTR [rsp+0xc8],rbx
;*synchronization entry
; -
com.datadog.profiling.aggregation.parser.jfr.JfrParser::parseJfr at -1
(line 165)
0x00007f2dc98db697: mov rbx,QWORD PTR [rsi+0x120] ;*getfield
NO_MORE_ELEMENTS {reexecute=0 rethrow=0 return_oop=0}
; -
org.openjdk.jmc.common.collection.AbstractIterator::hasNext at 5 (line
58)
; -
com.datadog.profiling.aggregation.parser.jfr.JfrParser::parseJfr at 474
(line 227)
0x00007f2dc98db69e: mov QWORD PTR [rsp+0xd0],rbx
;*synchronization entry
; -
com.datadog.profiling.aggregation.parser.jfr.JfrParser::parseJfr at -1
(line 165)
0x00007f2dc98db6a6: mov rbx,QWORD PTR [rsi+0x118] ;*getfield
NO_MORE_ELEMENTS {reexecute=0 rethrow=0 return_oop=0}
; -
org.openjdk.jmc.common.collection.AbstractIterator::hasNext at 5 (line
58)
; -
com.datadog.profiling.aggregation.parser.jfr.JfrParser::parseJfr at 474
(line 227)
0x00007f2dc98db6ad: mov QWORD PTR [rsp+0xd8],rbx
;*synchronization entry
; -
com.datadog.profiling.aggregation.parser.jfr.JfrParser::parseJfr at -1
(line 165)
0x00007f2dc98db6b5: mov rbx,QWORD PTR [rsi+0x110] ;*getfield
NO_MORE_ELEMENTS {reexecute=0 rethrow=0 return_oop=0}
; -
org.openjdk.jmc.common.collection.AbstractIterator::hasNext at 5 (line
58)
; -
com.datadog.profiling.aggregation.parser.jfr.JfrParser::parseJfr at 474
(line 227)
0x00007f2dc98db6bc: mov QWORD PTR [rsp+0xe0],rbx
;*synchronization entry
; -
com.datadog.profiling.aggregation.parser.jfr.JfrParser::parseJfr at -1
(line 165)
0x00007f2dc98db6c4: mov rbx,QWORD PTR [rsi+0x108]
;*if_acmpeq {reexecute=0 rethrow=0 return_oop=0}
; -
org.openjdk.jmc.common.collection.AbstractIterator::hasNext at 8 (line
58)
; -
com.datadog.profiling.aggregation.parser.jfr.JfrParser::parseJfr at 474
(line 227)
0x00007f2dc98db6cb: mov QWORD PTR [rsp+0xe8],rbx
;*synchronization entry
; -
com.datadog.profiling.aggregation.parser.jfr.JfrParser::parseJfr at -1
(line 165)
0x00007f2dc98db6d3: mov rbx,QWORD PTR [rsi+0xf0]
;*if_acmpeq {reexecute=0 rethrow=0 return_oop=0}
; -
org.openjdk.jmc.common.collection.AbstractIterator::hasNext at 8 (line
58)
; -
com.datadog.profiling.aggregation.parser.jfr.JfrParser::parseJfr at 474
(line 227)
0x00007f2dc98db6da: mov QWORD PTR [rsp+0xf0],rbx
;*synchronization entry
; -
com.datadog.profiling.aggregation.parser.jfr.JfrParser::parseJfr at -1
(line 165)
0x00007f2dc98db6e2: mov rbx,QWORD PTR [rsi+0xe8]
;*if_acmpeq {reexecute=0 rethrow=0 return_oop=0}
; -
org.openjdk.jmc.common.collection.AbstractIterator::hasNext at 8 (line
58)
; -
com.datadog.profiling.aggregation.parser.jfr.JfrParser::parseJfr at 474
(line 227)
0x00007f2dc98db6e9: mov QWORD PTR [rsp+0xf8],rbx
;*synchronization entry
; -
com.datadog.profiling.aggregation.parser.jfr.JfrParser::parseJfr at -1
(line 165)
0x00007f2dc98db6f1: mov rbx,QWORD PTR [rsi+0xe0]
;*if_acmpeq {reexecute=0 rethrow=0 return_oop=0}
; -
org.openjdk.jmc.common.collection.AbstractIterator::hasNext at 8 (line
58)
; -
com.datadog.profiling.aggregation.parser.jfr.JfrParser::parseJfr at 474
(line 227)
0x00007f2dc98db6f8: mov QWORD PTR [rsp+0x100],rbx
;*synchronization entry
; -
com.datadog.profiling.aggregation.parser.jfr.JfrParser::parseJfr at -1
(line 165)
0x00007f2dc98db700: mov rbx,QWORD PTR [rsi+0xd8]
;*if_acmpeq {reexecute=0 rethrow=0 return_oop=0}
; -
org.openjdk.jmc.common.collection.AbstractIterator::hasNext at 8 (line
58)
; -
com.datadog.profiling.aggregation.parser.jfr.JfrParser::parseJfr at 474
(line 227)
0x00007f2dc98db707: mov QWORD PTR [rsp+0x108],rbx
;*synchronization entry
; -
com.datadog.profiling.aggregation.parser.jfr.JfrParser::parseJfr at -1
(line 165)
0x00007f2dc98db70f: mov rbx,QWORD PTR [rsi+0xd0]
;*invokeinterface hasNext {reexecute=0 rethrow=0 return_oop=0}
; -
com.datadog.profiling.aggregation.parser.jfr.JfrParser::parseJfr at 474
(line 227)
0x00007f2dc98db716: mov QWORD PTR [rsp+0x110],rbx
;*synchronization entry
; -
com.datadog.profiling.aggregation.parser.jfr.JfrParser::parseJfr at -1
(line 165)
0x00007f2dc98db71e: mov rbx,QWORD PTR [rsi+0xc8] ;*ireturn
{reexecute=0 rethrow=0 return_oop=0}
; -
org.openjdk.jmc.common.collection.AbstractIterator::hasNext at 16 (line
58)
; -
com.datadog.profiling.aggregation.parser.jfr.JfrParser::parseJfr at 474
(line 227)
0x00007f2dc98db725: mov QWORD PTR [rsp+0x118],rbx
;*synchronization entry
; -
com.datadog.profiling.aggregation.parser.jfr.JfrParser::parseJfr at -1
(line 165)
0x00007f2dc98db72d: mov rbx,QWORD PTR [rsi+0xc0] ;*ireturn
{reexecute=0 rethrow=0 return_oop=0}
; -
org.openjdk.jmc.common.collection.AbstractIterator::hasNext at 16 (line
58)
; -
com.datadog.profiling.aggregation.parser.jfr.JfrParser::parseJfr at 474
(line 227)
0x00007f2dc98db734: mov QWORD PTR [rsp+0x120],rbx
;*synchronization entry
; -
com.datadog.profiling.aggregation.parser.jfr.JfrParser::parseJfr at -1
(line 165)
0x00007f2dc98db73c: mov rbx,QWORD PTR [rsi+0xb8]
;*invokeinterface hasNext {reexecute=0 rethrow=0 return_oop=0}
; -
com.datadog.profiling.aggregation.parser.jfr.JfrParser::parseJfr at 474
(line 227)
====
Similar sequences are repeated basically everywhere in the compiled method body.
If someone could shed some light on this phenomenon and how it could
be interpreted from the end user point of view (eg. someone looking at
the CPU profiles) it would be very much welcomed.
I am sorry for the lengthy post and I hope to hear from someone soon.
Cheers,
-JB-
More information about the hotspot-compiler-dev
mailing list