Grouped method entry events

Sat Aug 6 09:18:12 UTC 2022

Hi Chris,

I was able to somewhat reproduce it with jdb:
compile any simple samle app like

public class A {
     public static void main(String[] args) {
         System.out.println("A"); // line 3
     }
}

now debug with jdb:

  % jdb A
Initializing jdb ...
 > stop at A:3
Deferring breakpoint A:3.
It will be set after the class is loaded.
 > run
run A
Set uncaught java.lang.Throwable
Set deferred uncaught java.lang.Throwable
 >
VM Started: Set deferred breakpoint A:3

Breakpoint hit: "thread=main", A.main(), line=3 bci=0

main[1] exclude none
main[1] trace methods
main[1] next
 >
*Method entered: **
**Method entered: **
**Method entered: **
**Method entered: *
Method exited: return value = false, "thread=main", 
java.lang.System.allowSecurityManager(), line=198 bci=12

main[1] next
 >
Method exited: return value = null, "thread=main", 
java.lang.System.getSecurityManager(), line=493 bci=11

main[1] next
 >
*Method entered: **
**Method entered: **
**Method entered: **
**Method entered:*
Method exited: return value = <void value>, "thread=main", 
java.lang.Object.<init>(), line=44 bci=0

main[1] next
 >
*Method entered: **
**Method entered: **
**Method entered: **
**Method entered: *
Method exited: return value = true, "thread=main", 
java.lang.String.isLatin1(), line=4,546 bci=18

Unfortunately jdb does not show method description for the events with 
suspend policy thread (except for the last one), but you can see that 
there are 5 events in one set here.

Hope it helps,
Egor

On 05.08.2022 22:02, Chris Plummer wrote:
>
> Hi Egor,
>
> That is odd, and clearly wrong. It means that MethodEntryEvents are 
> being delivered when no longer even executing in the method. And you 
> are using the EVENT_THREAD suspend policy, so there should be a 
> suspend for each event. Offhand I can't think of any changes that 
> would have caused this. I also don't see how our testing would passed 
> with this behavior. I'm suspecting a faulty interaction with the debug 
> agent and IDEA (possibly the IDEA version of JDI).
>
> Can you see where the thread is actually suspended at when you get the 
> event set?
>
> Does this happen with 17 also? It would be nice to know what version 
> introduced this problem.
>
> Can you create a JDI test case for this?
>
> > Without the active step request it works in jdk 18 as in jdk 11:
>
> I'm not sure what you mean by "active step". Do you mean single 
> stepping is enabled? The JDWP spec does allow BreakPoint, SingleStep, 
> MethodEntry, and MethodExit events to be combined into the same 
> composite event (which should translate to the same JDI event set) if 
> they occur at the same location and in the same thread. So I can see 
> enabling single stepping having an impact on the behavior you are seeing.
>
> Chris
>
> On 8/5/22 9:59 AM, Egor Ushakov wrote:
>> Hi,
>>
>> we're experiencing strange grouping of method entry/exit events, is 
>> this a bug or a feature?
>> We have one method entry request active with suspend policy 1 
>> (suspend thread).
>> important: we also have one active step request (step over)
>>
>> In jdk 11 we have one composite event for each event, which is what's 
>> expected:
>> event set, policy:1, count:1 = 
>> {MethodEntryEvent at java.lang.ClassLoader:522 in thread main}
>> event set, policy:1, count:1 = 
>> {MethodEntryEvent at jdk.internal.loader.ClassLoaders$AppClassLoader:170 
>> in thread main}
>> event set, policy:1, count:1 = {MethodEntryEvent at java.lang.System:375 
>> in thread main}
>> event set, policy:1, count:1 = 
>> {MethodEntryEvent at jdk.internal.loader.BuiltinClassLoader:579 in 
>> thread main}
>> event set, policy:1, count:1 = 
>> {MethodEntryEvent at jdk.internal.loader.BuiltinClassLoader:591 in 
>> thread main}
>> event set, policy:1, count:1 = 
>> {MethodEntryEvent at java.lang.ClassLoader:665 in thread main}
>> event set, policy:1, count:1 = {MethodEntryEvent at java.lang.Object:50 
>> in thread main}
>> event set, policy:1, count:1 = 
>> {MethodEntryEvent at java.util.concurrent.ConcurrentHashMap:1541 in 
>> thread main}
>> event set, policy:1, count:1 = 
>> {MethodEntryEvent at java.util.concurrent.ConcurrentHashMap:1011 in 
>> thread main}
>> event set, policy:1, count:1 = 
>> {MethodEntryEvent at java.lang.String:1502 in thread main}
>> event set, policy:1, count:1 = 
>> {MethodEntryEvent at java.lang.String:3266 in thread main}
>> event set, policy:1, count:1 = 
>> {MethodEntryEvent at java.lang.StringLatin1:194 in thread main}
>> ...
>>
>> In jdk 18 they are grouped now!
>> event set, policy:1, count:17 = 
>> {MethodEntryEvent at java.lang.ClassLoader:521 in thread main, 
>> MethodEntryEvent at jdk.internal.loader.ClassLoaders$AppClassLoader:180 
>> in thread main, MethodEntryEvent at java.lang.System:490 in thread main, 
>> MethodEntryEvent at java.lang.System:198 in thread main, 
>> MethodEntryEvent at jdk.internal.loader.BuiltinClassLoader:639 in thread 
>> main, MethodEntryEvent at jdk.internal.loader.BuiltinClassLoader:651 in 
>> thread main, MethodEntryEvent at java.lang.ClassLoader:664 in thread 
>> main, MethodEntryEvent at java.lang.Object:44 in thread main, 
>> MethodEntryEvent at java.util.concurrent.ConcurrentHashMap:1541 in 
>> thread main, 
>> MethodEntryEvent at java.util.concurrent.ConcurrentHashMap:1011 in 
>> thread main, MethodEntryEvent at java.lang.String:2336 in thread main, 
>> MethodEntryEvent at java.lang.String:4546 in thread main, 
>> MethodEntryEvent at java.lang.StringLatin1:192 in thread main, 
>> MethodEntryEvent at java.util.concurrent.ConcurrentHashMap:697 in thread 
>> main, MethodEntryEvent at java.util.concurrent.ConcurrentHashMap:760 in 
>> thread main, MethodEntryEvent at jdk.internal.misc.Unsafe:2153 in thread 
>> main, 
>> MethodEntryEvent at jdk.internal.misc.Unsafe.getReferenceVolatile(java.lang.Object, 
>> long)+-1 in thread main}
>> event set, policy:1, count:4 = 
>> {MethodEntryEvent at java.util.concurrent.ConcurrentHashMap$Node:631 in 
>> thread main, MethodEntryEvent at java.lang.Object:44 in thread main, 
>> MethodEntryEvent at java.util.concurrent.ConcurrentHashMap:765 in thread 
>> main, 
>> MethodEntryEvent at jdk.internal.misc.Unsafe.compareAndSetReference(java.lang.Object, 
>> long, java.lang.Object, java.lang.Object)+-1 in thread main}
>> event set, policy:1, count:2 = 
>> {MethodEntryEvent at java.util.concurrent.ConcurrentHashMap:2326 in 
>> thread main, 
>> MethodEntryEvent at jdk.internal.misc.Unsafe.compareAndSetLong(java.lang.Object, 
>> long, long, long)+-1 in thread main}
>>
>> Which is really strange and breaks some login in IDEA debugger.
>>
>> Without the active step request it works in jdk 18 as in jdk 11:
>> event set, policy:1, count:1 = 
>> {MethodEntryEvent at java.lang.ClassLoader:521 in thread main}
>> event set, policy:1, count:1 = 
>> {MethodEntryEvent at jdk.internal.loader.ClassLoaders$AppClassLoader:180 
>> in thread main}
>> event set, policy:1, count:1 = {MethodEntryEvent at java.lang.System:490 
>> in thread main}
>> event set, policy:1, count:1 = {MethodEntryEvent at java.lang.System:198 
>> in thread main}
>> event set, policy:1, count:1 = 
>> {MethodEntryEvent at jdk.internal.loader.BuiltinClassLoader:639 in 
>> thread main}
>> event set, policy:1, count:1 = 
>> {MethodEntryEvent at jdk.internal.loader.BuiltinClassLoader:651 in 
>> thread main}
>> event set, policy:1, count:1 = 
>> {MethodEntryEvent at java.lang.ClassLoader:664 in thread main}
>> event set, policy:1, count:1 = {MethodEntryEvent at java.lang.Object:44 
>> in thread main}
>> event set, policy:1, count:1 = 
>> {MethodEntryEvent at java.util.concurrent.ConcurrentHashMap:1541 in 
>> thread main}
>> event set, policy:1, count:1 = 
>> {MethodEntryEvent at java.util.concurrent.ConcurrentHashMap:1011 in 
>> thread main}
>> event set, policy:1, count:1 = 
>> {MethodEntryEvent at java.lang.String:2336 in thread main}
>> event set, policy:1, count:1 = 
>> {MethodEntryEvent at java.lang.String:4546 in thread main}
>> event set, policy:1, count:1 = 
>> {MethodEntryEvent at java.lang.StringLatin1:192 in thread main}
>>
>> Could anyone have a look please.
>> Thanks,
>> Egor
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <https://mail.openjdk.org/pipermail/serviceability-dev/attachments/20220806/32fc9636/attachment-0001.htm>