Grouped method entry events

[Chris Plummer]

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/20220805/c35505a0/attachment.htm>