[External] : Re: Grouped method entry events

Chris Plummer chris.plummer at oracle.com
Mon Aug 8 07:50:49 UTC 2022 

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
>>

More information about the serviceability-dev mailing list