RFR: 8308614: Enabling JVMTI ClassLoad event slows down vthread creation by factor 10 [v3]

Serguei Spitsyn sspitsyn at openjdk.org
Sun Nov 19 09:44:28 UTC 2023 

On Sun, 19 Nov 2023 09:22:43 GMT, Serguei Spitsyn <sspitsyn at openjdk.org> wrote:

>> @sspitsyn - Please point me at the code where these JavaThreads are newly created?
>
> @dcubed-ojdk
> I don't know FJP implementation well enough to point at the code where it happens. However, I observe that new `JavaThread `is being created between two points of the execution path.
>  - First point is in the `JvmtiEventControllerPrivate::recompute_enabled()` at the line where a `ThreadsListHandle` is set. I've added a trap checking if any `JavaThread` pointed by `state->get_thread()` is not protected by the `tlh`. I can see this trap is not fired (I can't say it has never been fired).
>  - Second point is in the `JvmtiEventControllerPrivate::enter_interp_only_mode()`. If  a `ThreadsListHandle` is NOT set then I can observe a `JavaThread` referenced by the state->get_thread() which is not protected by any TLH. It a TLH added into `JvmtiEventControllerPrivate::enter_interp_only_mode()` then this `JavaThread` is observed as protected by TLH.
> I can provide a full stack trace for this `JavaThread` consisting of two parts: carrier thread and virtual thread frames. The name of carrier thread is  `ForkJoinPool-1-worker-1`. The virtual thread is a tested virtual thread. 
> The thread dump looks las below:
> 
> DBG: enter_interp_only_mode: target: 0x7f93f8043d00 <unnamed> virt: 1 carrier: ForkJoinPool-1-worker-1
> DBG: ##### NATIVE stacktrace of JavaThread: 0x7f93f8043d00 #####
> Native frames: (J=compiled Java code, j=interpreted, Vv=VM code, C=native code)
> j  fieldacc02.check(Ljava/lang/Object;)I+0
> j  fieldacc02.lambda$testVirtualThread$0()V+12
> j  fieldacc02$$Lambda+0x00007f943b001428.run()V+0
> j  java.lang.Thread.runWith(Ljava/lang/Object;Ljava/lang/Runnable;)V+5 java.base at 22-internal
> j  java.lang.VirtualThread.run(Ljava/lang/Runnable;)V+66 java.base at 22-internal
> j  java.lang.VirtualThread$VThreadContinuation$1.run()V+8 java.base at 22-internal
> j  jdk.internal.vm.Continuation.enter0()V+4 java.base at 22-internal
> j  jdk.internal.vm.Continuation.enter(Ljdk/internal/vm/Continuation;Z)V+1 java.base at 22-internal
> J 124  jdk.internal.vm.Continuation.enterSpecial(Ljdk/internal/vm/Continuation;ZZ)V java.base at 22-internal (0 bytes) @ 0x00007f94c7cdf744 [0x00007f94c7cdf5e0+0x0000000000000164]
> j  jdk.internal.vm.Continuation.run()V+122 java.base at 22-internal
> j  java.lang.VirtualThread.runContinuation()V+70 java.base at 22-internal
> j  java.lang.VirtualThread$$Lambda+0x00007f943b0496c0.run()V+4 java.base at 22-internal
> j  java.util.concurrent.ForkJoinTask$RunnableExecuteAction.compute()Ljava/lang/Void;+4 java.base at 22-internal
> j  java.util.concurrent.ForkJoinTask$RunnableExecuteAction.compute(...

The stack trace of current thread (where the assert was fired) can explain what is going on a little bit:

Current thread (0x00007f93f8043d00):  JavaThread "ForkJoinPool-1-worker-1" daemon [_thread_in_vm, id=16779, stack(0x00007f948a597000,0x00007f948a697000) (1024K)]

Stack: [0x00007f948a597000,0x00007f948a697000],  sp=0x00007f948a6949e0,  free space=1014k
Native frames: (J=compiled Java code, j=interpreted, Vv=VM code, C=native code)
V  [libjvm.so+0x117937d]  JvmtiEventControllerPrivate::enter_interp_only_mode(JvmtiThreadState*)+0x45d  (jvmtiEventController.cpp:402)
V  [libjvm.so+0x1179520]  JvmtiEventControllerPrivate::recompute_thread_enabled(JvmtiThreadState*) [clone .part.0]+0x190  (jvmtiEventController.cpp:632)
V  [libjvm.so+0x117a1e1]  JvmtiEventControllerPrivate::thread_started(JavaThread*)+0x351  (jvmtiEventController.cpp:1174)
V  [libjvm.so+0x117e608]  JvmtiExport::get_jvmti_thread_state(JavaThread*)+0x98  (jvmtiExport.cpp:424)
V  [libjvm.so+0x118a86c]  JvmtiExport::post_field_access(JavaThread*, Method*, unsigned char*, Klass*, Handle, _jfieldID*)+0x6c  (jvmtiExport.cpp:2214)
V  [libjvm.so+0x118b3a1]  JvmtiExport::post_field_access_by_jni(JavaThread*, oop, Klass*, _jfieldID*, bool)+0x321  (jvmtiExport.cpp:2202)
V  [libjvm.so+0x118b4e9]  JvmtiExport::jni_GetField_probe(JavaThread*, _jobject*, oop, Klass*, _jfieldID*, bool)+0x79  (jvmtiExport.cpp:2168)
V  [libjvm.so+0xf83847]  jni_GetStaticBooleanField+0x257  (jni.cpp:2047)
C  [libfieldacc02.so+0x379b]  Java_fieldacc02_check+0x6b  (jni.h:1546)
j  fieldacc02.check(Ljava/lang/Object;)I+0
j  fieldacc02.lambda$testVirtualThread$0()V+12
j  fieldacc02$$Lambda+0x00007f943b001428.run()V+0
j  java.lang.Thread.runWith(Ljava/lang/Object;Ljava/lang/Runnable;)V+5 java.base at 22-internal
j  java.lang.VirtualThread.run(Ljava/lang/Runnable;)V+66 java.base at 22-internal
j  java.lang.VirtualThread$VThreadContinuation$1.run()V+8 java.base at 22-internal
j  jdk.internal.vm.Continuation.enter0()V+4 java.base at 22-internal
j  jdk.internal.vm.Continuation.enter(Ljdk/internal/vm/Continuation;Z)V+1 java.base at 22-internal
J 124  jdk.internal.vm.Continuation.enterSpecial(Ljdk/internal/vm/Continuation;ZZ)V java.base at 22-internal (0 bytes) @ 0x00007f94c7cdf744 [0x00007f94c7cdf5e0+0x0000000000000164]
j  jdk.internal.vm.Continuation.run()V+122 java.base at 22-internal
j  java.lang.VirtualThread.runContinuation()V+70 java.base at 22-internal
j  java.lang.VirtualThread$$Lambda+0x00007f943b0496c0.run()V+4 java.base at 22-internal
j  java.util.concurrent.ForkJoinTask$RunnableExecuteAction.compute()Ljava/lang/Void;+4 java.base at 22-internal
j  java.util.concurrent.ForkJoinTask$RunnableExecuteAction.compute()Ljava/lang/Object;+1 java.base at 22-internal
j  java.util.concurrent.ForkJoinTask$InterruptibleTask.exec()Z+51 java.base at 22-internal
j  java.util.concurrent.ForkJoinTask.doExec()V+10 java.base at 22-internal
j  java.util.concurrent.ForkJoinPool$WorkQueue.topLevelExec(Ljava/util/concurrent/ForkJoinTask;Ljava/util/concurrent/ForkJoinPool$WorkQueue;I)V+49 java.base at 22-internal
j  java.util.concurrent.ForkJoinPool.scan(Ljava/util/concurrent/ForkJoinPool$WorkQueue;JI)J+271 java.base at 22-internal
j  java.util.concurrent.ForkJoinPool.runWorker(Ljava/util/concurrent/ForkJoinPool$WorkQueue;)V+68 java.base at 22-internal
j  java.util.concurrent.ForkJoinWorkerThread.run()V+31 java.base at 22-internal
v  ~StubRoutines::call_stub 0x00007f94c7505d21
V  [libjvm.so+0xe7b719]  JavaCalls::call_helper(JavaValue*, methodHandle const&, JavaCallArguments*, JavaThread*)+0x4a9  (javaCalls.cpp:415)
V  [libjvm.so+0xe7bdd5]  JavaCalls::call_virtual(JavaValue*, Klass*, Symbol*, Symbol*, JavaCallArguments*, JavaThread*)+0x345  (javaCalls.cpp:329)
V  [libjvm.so+0xe7bff6]  JavaCalls::call_virtual(JavaValue*, Handle, Klass*, Symbol*, Symbol*, JavaThread*)+0x76  (javaCalls.cpp:191)
V  [libjvm.so+0xfd9723]  thread_entry(JavaThread*, JavaThread*)+0x93  (jvm.cpp:2937)
V  [libjvm.so+0xeb06ac]  JavaThread::thread_main_inner()+0xcc  (javaThread.cpp:720)
V  [libjvm.so+0x1789496]  Thread::call_run()+0xb6  (thread.cpp:220)
V  [libjvm.so+0x1493b27]  thread_native_entry(Thread*)+0x127  (os_linux.cpp:787)

-------------

PR Review Comment: https://git.openjdk.org/jdk/pull/16686#discussion_r1398365938

More information about the serviceability-dev mailing list