[External] : Re: Grouped method entry events

[Chris Plummer]

Hi Egor,

The reason only the last event prints location information is because 
there is special logic in jdb that assumes if the suspend type is not 
SUSPEND_NONE, then we will be stopping, and that will result in the 
location info being printed.

         if (me.request().suspendPolicy() != EventRequest.SUSPEND_NONE) {
             // We are stopping; the name will be shown by the normal 
mechanism
             MessageOutput.lnprint("Method entered:");
         } else {
             // We aren't stopping, show the name
             MessageOutput.print("Method entered:");
             printLocationOfEvent(me);
         }

The assumption here is wrong with co-located events, since there could 
be more than one. However, normally it shouldn't matter since all 
colocated events are suppose to be at the same location, and if one is 
stopping then they all are. Yet clearly we are seeing that they are not 
all at the same location. When I enable location tracing for the first 
part of the "if" block, I get:

 > Method entered: "thread=main", java.lang.ClassLoader.loadClass(), 
line=521 bci=0
Method entered: "thread=main", 
jdk.internal.loader.ClassLoaders$AppClassLoader.loadClass(), line=180 bci=0
Method entered: "thread=main", java.lang.System.getSecurityManager(), 
line=497 bci=0
Method entered: "thread=main", java.lang.System.allowSecurityManager(), 
line=205 bci=0
Method exited: return value = false, "thread=main", 
java.lang.System.allowSecurityManager(), line=205 bci=12

I also printed out the EventSet, which confirms the same:

event set, policy:2, count:5 = 
{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:497 in thread main, 
MethodEntryEvent at java.lang.System:205 in thread main, 
MethodExitEvent at java.lang.System:205 in thread main}

The JDWP spec says:

Several events may occur at a given time in the target VM. For example, 
there may be more than one breakpoint request for a given location or 
you might single step to the same location as a breakpoint request. 
These events are delivered together as a composite event.
...
The events that are grouped in a composite event are restricted in the 
following ways:
...
   � Only with other members of this group, at the same location and in 
the same thread:
         Breakpoint Event
         Step Event
         Method Entry Event
         Method Exit Event

So there seems to be a debug agent bug that is grouping all the 
MethodEntry events until a MethodExit is hit. But I don't think this is 
new. I see the same thing in JDK11, but as Alan pointed out, there are 
fewer method calls.

Chris

On 8/6/22 2:18 AM, Egor Ushakov wrote:
> 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
>