Hi Egor,
While trying to write a JDI test to reproduce this issue (and having
trouble getting it to fail), I learned a bit more about why your test
case is failing. It's not the call to System.out.println() that is
triggering the problem, it is the constant pool resolution for
java.lang.System. JVMTI has some special logic to disable single
stepping during class loading triggered by constant pool resolution,
but the debug agent still considers single stepping to be enabled, so
"threadControl_getInstructionStepMode(thread) == JVMTI_ENABLE". If
you do a System.out.println() right before the one you are stepping
over, then the problem goes away (for the 2nd println() that you are
stepping over). Given that in order to reproduce the problem you both
have to have MethodEntry events enabled and step over a line of code
that results in constant pool resolution, I can see now why this
problem has not been reported in a the past. It's probably very rare.
There could be an argument that not only should JVMTI be disabling
single stepping during class loading, but also MethodEntry/Exit
events. Doing so would prevent the problem you are seeing.
The following seems to fix the issue. Let me know if it works for you:
diff --git a/src/jdk.jdwp.agent/share/native/libjdwp/eventHandler.c
b/src/jdk.jdwp.agent/share/native/libjdwp/eventHandler.c
index 26c11ea6501..19eb801362d 100644
--- a/src/jdk.jdwp.agent/share/native/libjdwp/eventHandler.c
+++ b/src/jdk.jdwp.agent/share/native/libjdwp/eventHandler.c
@@ -334,9 +334,14 @@ deferEventReport(JNIEnv *env, jthread thread,
jlocation end;
error = methodLocation(method, &start, &end);
if (error == JVMTI_ERROR_NONE) {
- deferring = isBreakpointSet(clazz, method,
start) ||
- threadControl_getInstructionStepMode(thread)
- == JVMTI_ENABLE;
+ if (isBreakpointSet(clazz, method, start)) {
+ deferring = JNI_TRUE;
+ } else {
+ StepRequest* step =
threadControl_getStepRequest(thread);
+ if (step->pending && step->depth ==
JDWP_STEP_DEPTH(INTO)) {
+ deferring = JNI_TRUE;
+ }
+ }
if (!deferring) {
threadControl_saveCLEInfo(env, thread, ei,
clazz, method,
start);
Chris
On 8/8/22 12:50 AM, 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 =
{methodentryev...@java.lang.ClassLoader:521 in thread main,
MethodEntryEvent@jdk.internal.loader.ClassLoaders$AppClassLoader:180
in thread main, methodentryev...@java.lang.System:497 in thread
main, methodentryev...@java.lang.System:205 in thread main,
methodexitev...@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 =
{methodentryev...@java.lang.ClassLoader:522 in thread main}
event set, policy:1, count:1 =
{MethodEntryEvent@jdk.internal.loader.ClassLoaders$AppClassLoader:170
in thread main}
event set, policy:1, count:1 =
{methodentryev...@java.lang.System:375 in thread main}
event set, policy:1, count:1 =
{MethodEntryEvent@jdk.internal.loader.BuiltinClassLoader:579 in
thread main}
event set, policy:1, count:1 =
{MethodEntryEvent@jdk.internal.loader.BuiltinClassLoader:591 in
thread main}
event set, policy:1, count:1 =
{methodentryev...@java.lang.ClassLoader:665 in thread main}
event set, policy:1, count:1 =
{methodentryev...@java.lang.Object:50 in thread main}
event set, policy:1, count:1 =
{methodentryev...@java.util.concurrent.ConcurrentHashMap:1541 in
thread main}
event set, policy:1, count:1 =
{methodentryev...@java.util.concurrent.ConcurrentHashMap:1011 in
thread main}
event set, policy:1, count:1 =
{methodentryev...@java.lang.String:1502 in thread main}
event set, policy:1, count:1 =
{methodentryev...@java.lang.String:3266 in thread main}
event set, policy:1, count:1 =
{methodentryev...@java.lang.StringLatin1:194 in thread main}
...
In jdk 18 they are grouped now!
event set, policy:1, count:17 =
{methodentryev...@java.lang.ClassLoader:521 in thread main,
MethodEntryEvent@jdk.internal.loader.ClassLoaders$AppClassLoader:180
in thread main, methodentryev...@java.lang.System:490 in thread
main, methodentryev...@java.lang.System:198 in thread main,
MethodEntryEvent@jdk.internal.loader.BuiltinClassLoader:639 in
thread main,
MethodEntryEvent@jdk.internal.loader.BuiltinClassLoader:651 in
thread main, methodentryev...@java.lang.ClassLoader:664 in
thread main, methodentryev...@java.lang.Object:44 in thread
main,
methodentryev...@java.util.concurrent.ConcurrentHashMap:1541 in
thread main,
methodentryev...@java.util.concurrent.ConcurrentHashMap:1011 in
thread main, methodentryev...@java.lang.String:2336 in thread
main, methodentryev...@java.lang.String:4546 in thread main,
methodentryev...@java.lang.StringLatin1:192 in thread main,
methodentryev...@java.util.concurrent.ConcurrentHashMap:697 in
thread main,
methodentryev...@java.util.concurrent.ConcurrentHashMap:760 in
thread main, methodentryev...@jdk.internal.misc.Unsafe:2153 in
thread main,
methodentryev...@jdk.internal.misc.Unsafe.getReferenceVolatile(java.lang.Object,
long)+-1 in thread main}
event set, policy:1, count:4 =
{methodentryev...@java.util.concurrent.ConcurrentHashMap$Node:631
in thread main, methodentryev...@java.lang.Object:44 in thread
main,
methodentryev...@java.util.concurrent.ConcurrentHashMap:765 in
thread main,
methodentryev...@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 =
{methodentryev...@java.util.concurrent.ConcurrentHashMap:2326 in
thread main,
methodentryev...@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 =
{methodentryev...@java.lang.ClassLoader:521 in thread main}
event set, policy:1, count:1 =
{MethodEntryEvent@jdk.internal.loader.ClassLoaders$AppClassLoader:180
in thread main}
event set, policy:1, count:1 =
{methodentryev...@java.lang.System:490 in thread main}
event set, policy:1, count:1 =
{methodentryev...@java.lang.System:198 in thread main}
event set, policy:1, count:1 =
{MethodEntryEvent@jdk.internal.loader.BuiltinClassLoader:639 in
thread main}
event set, policy:1, count:1 =
{MethodEntryEvent@jdk.internal.loader.BuiltinClassLoader:651 in
thread main}
event set, policy:1, count:1 =
{methodentryev...@java.lang.ClassLoader:664 in thread main}
event set, policy:1, count:1 =
{methodentryev...@java.lang.Object:44 in thread main}
event set, policy:1, count:1 =
{methodentryev...@java.util.concurrent.ConcurrentHashMap:1541 in
thread main}
event set, policy:1, count:1 =
{methodentryev...@java.util.concurrent.ConcurrentHashMap:1011 in
thread main}
event set, policy:1, count:1 =
{methodentryev...@java.lang.String:2336 in thread main}
event set, policy:1, count:1 =
{methodentryev...@java.lang.String:4546 in thread main}
event set, policy:1, count:1 =
{methodentryev...@java.lang.StringLatin1:192 in thread main}
Could anyone have a look please.
Thanks,
Egor
