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
