[External] : Re: Grouped method entry events

[Egor Ushakov]

Thanks, Chris!
We'll try to implement a workaround in IDEA to ignore such merged events 
somehow.
Egor

On 08.08.2022 09:50, Chris Plummer wrote:
> I think the issue is that when you issue a "next", jvmti single 
> stepping is enabled. That means when the first MethodEntry event is 
> triggered, it is automatically deferred. See the following in 
> deferEventReport:
>
>         case EI_METHOD_ENTRY:
>                 error = methodLocation(method, &start, &end);
>                 if (error == JVMTI_ERROR_NONE) {
>                     deferring = isBreakpointSet(clazz, method, start) ||
> threadControl_getInstructionStepMode(thread)
>                                     == JVMTI_ENABLE;
>
>
> When using (JDWP) STEP_OVER, JVMTI single stepping is only enabled 
> during the call to the method, which allows the debug agent to stop on 
> the first instruction of the called method. After that it disables 
> JVMTI single stepping (until there is a FramePop). When the above code 
> is executed for METHOD_ENTRY, JVMTI single stepping is enabled. When 
> JVMTI is returned to, it then sends a SINGLE_STEP event, but this is a 
> special one just used by the debug agent, and not sent on the the 
> debugger. So we never hit the code right below the above code that 
> handles colocating the SINGLE_STEP event.
>
>         case EI_SINGLE_STEP:
>             deferring = isBreakpointSet(clazz, method, location);
>             if (deferring) {
>                 threadControl_saveCLEInfo(env, thread, ei,
>                                           clazz, method, location);
>             }
>
> Meanwhile the generated MethodEntry event sits in the thread's event 
> bag, and I guess gets added to when the next MethodEntry happens. This 
> goes on on a MethodExit event is generated, witch seems to push out 
> all pending events (there is actually no logic in the debug agent to 
> colocate MethodExit events, which seems odd).
>
> So bottom line is that the CLE code is wrong when JVMTI single 
> stepping is enabled for the sake of supporting a JDWP STEP_OVER. I 
> think instead of checking if JVMTI single stepping is enabled, it 
> should be checking if the current StepDepth is INTO, although I 
> suspect there might be other factors to consider that will make the 
> check more complicated.
>
> I'll look at this some more tomorrow.
>
> Chris
>
> On 8/7/22 11:50 PM, Chris Plummer wrote:
>> 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
>>>