search

helidon-io / helidon

Java libraries for writing microservices
https://helidon.io
Apache License 2.0
3.44k stars 562 forks source link

4.x: Fail HelidonTests by default when pinning jfr event is detected #8877

Open jbescos opened 3 weeks ago

jbescos commented 3 weeks ago

Description

https://github.com/helidon-io/helidon/issues/8857

Documentation

N/A

Few comments:

  1. I created few tests that are disabled because we cannot catch the error, but still they exist to easily verify the test fails with pinned threads.
  2. The stack trace of the event is truncated to 5 lines, and we cannot change that. I have to iterate the whole stack in the code.
  3. It would be useful to show in the stacktrace the monitors. Unfortunately the RecordedFrame does not show that information. I tried to listen monitor events to append it in the class, but some events for some reason didn't arrive.
  4. Errors will look like this:
[ERROR] Failures: 
[ERROR]   TestPinnedThread Some pinned virtual threads were detected:
[jdk.VirtualThreadPinned {
  startTime = 07:02:48.296 (2024-06-19)
  duration = 999 ms
  eventThread = "" (javaThreadId = 261, virtual)
  stackTrace = [
    java.lang.VirtualThread.parkOnCarrierThread(boolean, long) line: 675
    java.lang.VirtualThread.parkNanos(long) line: 634
    java.lang.VirtualThread.sleepNanos(long) line: 791
    java.lang.Thread.sleep(long) line: 507
    io.helidon.microprofile.tests.testing.junit5.TestPinnedThread.lambda$test$0() line: 33
    ...
  ]
}

full-stackTrace = [
    java.lang.VirtualThread#parkOnCarrierThread(675)
    java.lang.VirtualThread#parkNanos(634)
    java.lang.VirtualThread#sleepNanos(791)
    java.lang.Thread#sleep(507)
    io.helidon.microprofile.tests.testing.junit5.TestPinnedThread#lambda$test$0(33)
    io.helidon.microprofile.tests.testing.junit5.TestPinnedThread$$Lambda+0x00007f800857bc30.148018969#run(-1)
    java.lang.Thread#runWith(1596)
    java.lang.VirtualThread#run(309)
    java.lang.VirtualThread$VThreadContinuation$1#run(190)
    jdk.internal.vm.Continuation#enter0(320)
    jdk.internal.vm.Continuation#enter(312)
    jdk.internal.vm.Continuation#enterSpecial(-1)
]]
jbescos commented 3 weeks ago

It is already finding some pinned threads, check the jobs for more examples:

startTime = 2024-06-12T14:17:47.153779225Z
duration = PT0.002448278S
stackTrace = [
    java.lang.VirtualThread#parkOnCarrierThread(675)
    java.lang.VirtualThread#park(593)
    java.lang.System$2#parkVirtualThread(2643)
    jdk.internal.misc.VirtualThreads#park(54)
    java.util.concurrent.locks.LockSupport#park(219)
    java.util.concurrent.locks.AbstractQueuedSynchronizer#acquire(754)
    java.util.concurrent.locks.AbstractQueuedSynchronizer#acquire(990)
    java.util.concurrent.locks.ReentrantLock$Sync#lock(153)
    java.util.concurrent.locks.ReentrantLock#lock(322)
    java.util.concurrent.ScheduledThreadPoolExecutor$DelayedWorkQueue#offer(1100)
    java.util.concurrent.ScheduledThreadPoolExecutor$DelayedWorkQueue#add(1127)
    java.util.concurrent.ScheduledThreadPoolExecutor$DelayedWorkQueue#add(899)
    java.util.concurrent.ScheduledThreadPoolExecutor#delayedExecute(342)
    java.util.concurrent.ScheduledThreadPoolExecutor#schedule(562)
    org.glassfish.tyrus.core.TyrusSession#restartIdleTimeoutExecutor(519)
    org.glassfish.tyrus.core.TyrusRemoteEndpoint$Basic#sendObject(178)
    io.helidon.microprofile.example.websocket.MessageBoardEndpoint#onMessage(70)
    java.lang.invoke.LambdaForm$DMH+0x00007f4db02a8000.1489997716#invokeVirtual(-1)
    java.lang.invoke.LambdaForm$MH+0x00007f4db0604800.1771748575#invoke(-1)
    java.lang.invoke.LambdaForm$MH+0x00007f4db02a9400.1163189762#invokeExact_MT(-1)
    jdk.internal.reflect.DirectMethodHandleAccessor#invokeImpl(155)
    jdk.internal.reflect.DirectMethodHandleAccessor#invoke(103)
    java.lang.reflect.Method#invoke(580)
    org.glassfish.tyrus.core.AnnotatedEndpoint#callMethod(556)
    org.glassfish.tyrus.core.AnnotatedEndpoint$WholeHandler$1#onMessage(655)
    org.glassfish.tyrus.core.TyrusSession#notifyMessageHandlers(590)
    org.glassfish.tyrus.core.TyrusEndpointWrapper#onMessage(866)
    org.glassfish.tyrus.core.TyrusWebSocket#onMessage(196)
    org.glassfish.tyrus.core.frame.TextFrame#respond(116)
    org.glassfish.tyrus.core.ProtocolHandler#process(826)
    org.glassfish.tyrus.core.TyrusWebSocketEngine$TyrusReadHandler#handle(552)
    io.helidon.microprofile.tyrus.TyrusConnection$TyrusListener#writeToTyrus(210)
    io.helidon.microprofile.tyrus.TyrusConnection$TyrusListener#onMessage(169)
    io.helidon.microprofile.tyrus.TyrusConnection#handle(81)
    io.helidon.webserver.http1.Http1Connection#handle(185)
    io.helidon.webserver.ConnectionHandler#run(165)
    io.helidon.common.task.InterruptableTask#call(47)
    io.helidon.webserver.ThreadPerTaskExecutor$ThreadBoundFuture#run(239)
    java.lang.Thread#runWith(1596)
    java.lang.VirtualThread#run(309)
    java.lang.VirtualThread$VThreadContinuation$1#run(190)
    jdk.internal.vm.Continuation#enter0(320)
    jdk.internal.vm.Continuation#enter(312)
    jdk.internal.vm.Continuation#enterSpecial(-1)
]]
jbescos commented 3 weeks ago

Monitor on com.datastax.driver.core.Cluster$Manager#init(1726)

2024-06-13T09:33:43.0710335Z [ERROR] io.helidon.examples.todos.backend.BackendTests  Time elapsed: 14.019 s  <<< 
FAILURE!
2024-06-13T09:33:43.4152415Z    java.lang.VirtualThread#parkOnCarrierThread(675)
2024-06-13T09:33:43.4152547Z    java.lang.VirtualThread#park(593)
2024-06-13T09:33:43.4152687Z    java.lang.System$2#parkVirtualThread(2643)
2024-06-13T09:33:43.4152897Z    jdk.internal.misc.VirtualThreads#park(54)
2024-06-13T09:33:43.4153078Z    java.util.concurrent.locks.LockSupport#park(219)
2024-06-13T09:33:43.4153296Z    com.google.common.util.concurrent.AbstractFuture#get(561)
2024-06-13T09:33:43.4153593Z    com.datastax.driver.core.ControlConnection#refreshNodeListAndTokenMap(760)
2024-06-13T09:33:43.4153806Z    com.datastax.driver.core.ControlConnection#tryConnect(319)
2024-06-13T09:33:43.4154060Z    com.datastax.driver.core.ControlConnection#reconnectInternal(235)
2024-06-13T09:33:43.4154259Z    com.datastax.driver.core.ControlConnection#connect(109)
2024-06-13T09:33:43.4154585Z    com.datastax.driver.core.Cluster$Manager#negotiateProtocolVersionAndConnect(1813)
2024-06-13T09:33:43.4154760Z    com.datastax.driver.core.Cluster$Manager#init(1726) <-------------------------------------- MONITOR
2024-06-13T09:33:43.4154945Z    com.datastax.driver.core.Cluster#init(214)
2024-06-13T09:33:43.4155329Z    com.datastax.driver.core.Cluster#connectAsync(387)
2024-06-13T09:33:43.4155602Z    com.datastax.driver.core.Cluster#connect(338)
2024-06-13T09:33:43.4156042Z    io.helidon.examples.todos.backend.DbService#<init>(80)
2024-06-13T09:33:43.4156644Z    java.lang.invoke.DirectMethodHandle$Holder#newInvokeSpecial(-1)
2024-06-13T09:33:43.4157216Z    java.lang.invoke.LambdaForm$MH+0x00007f31c4014400.985655350#invoke(-1)
2024-06-13T09:33:43.4157626Z    java.lang.invoke.Invokers$Holder#invokeExact_MT(-1)
2024-06-13T09:33:43.4158119Z    jdk.internal.reflect.DirectConstructorHandleAccessor#invokeImpl(87)
2024-06-13T09:33:43.4158612Z    jdk.internal.reflect.DirectConstructorHandleAccessor#newInstance(62)
2024-06-13T09:33:43.4158967Z    java.lang.reflect.Constructor#newInstanceWithCaller(502)
2024-06-13T09:33:43.4159256Z    java.lang.reflect.Constructor#newInstance(486)
2024-06-13T09:33:43.4159724Z    org.jboss.weld.injection.ConstructorInjectionPoint#newInstance(119)
2024-06-13T09:33:43.4160346Z    org.jboss.weld.injection.ConstructorInjectionPoint#invokeAroundConstructCallbacks(92)
2024-06-13T09:33:43.4160815Z    org.jboss.weld.injection.ConstructorInjectionPoint#newInstance(78)
2024-06-13T09:33:43.4161343Z    org.jboss.weld.injection.producer.AbstractInstantiator#newInstance(28)
2024-06-13T09:33:43.4161825Z    org.jboss.weld.injection.producer.BasicInjectionTarget#produce(112)
2024-06-13T09:33:43.4162289Z    org.jboss.weld.injection.producer.BeanInjectionTarget#produce(186)
2024-06-13T09:33:43.4162550Z    org.jboss.weld.bean.ManagedBean#create(160)
2024-06-13T09:33:43.4162850Z    org.jboss.weld.contexts.AbstractContext#get(96)
2024-06-13T09:33:43.4163485Z    org.jboss.weld.bean.ContextualInstanceStrategy$DefaultContextualInstanceStrategy#get(100)
2024-06-13T09:33:43.4164252Z    org.jboss.weld.bean.ContextualInstanceStrategy$ApplicationScopedContextualInstanceStrategy#get(140)
2024-06-13T09:33:43.4164534Z    org.jboss.weld.bean.ContextualInstance#get(50)
2024-06-13T09:33:43.4164962Z    org.jboss.weld.bean.proxy.ContextBeanInstance#getInstance(102)
2024-06-13T09:33:43.4165464Z    org.jboss.weld.bean.proxy.ProxyMethodHandler#invoke(105)
2024-06-13T09:33:43.4166223Z    io.helidon.examples.todos.backend.DbService$Proxy$_$$_WeldClientProxy#insert(-1)
2024-06-13T09:33:43.4166813Z    io.helidon.examples.todos.backend.JaxRsBackendResource#createIt(139)
2024-06-13T09:33:43.4167639Z    io.helidon.examples.todos.backend.JaxRsBackendResource$Proxy$_$$_WeldSubclass#createIt(-1)
2024-06-13T09:33:43.4168431Z    io.helidon.examples.todos.backend.JaxRsBackendResource$Proxy$_$$_WeldClientProxy#createIt(-1)
2024-06-13T09:33:43.4168969Z    java.lang.invoke.LambdaForm$DMH+0x00007f31c45a0400.696411130#invokeVirtual(-1)
2024-06-13T09:33:43.4169443Z    java.lang.invoke.LambdaForm$MH+0x00007f31c475cc00.303787940#invoke(-1)
2024-06-13T09:33:43.4170127Z    java.lang.invoke.LambdaForm$MH+0x00007f31c42bd400.2013853240#invokeExact_MT(-1)
2024-06-13T09:33:43.4170572Z    jdk.internal.reflect.DirectMethodHandleAccessor#invokeImpl(155)
2024-06-13T09:33:43.4170987Z    jdk.internal.reflect.DirectMethodHandleAccessor#invoke(103)
2024-06-13T09:33:43.4171234Z    java.lang.reflect.Method#invoke(580)
2024-06-13T09:33:43.4172072Z    org.glassfish.jersey.server.model.internal.ResourceMethodInvocationHandlerFactory#lambda$static$0(52)
2024-06-13T09:33:43.4173348Z    org.glassfish.jersey.server.model.internal.ResourceMethodInvocationHandlerFactory$$Lambda+0x00007f31c4684220.82565330#invoke(-1)
2024-06-13T09:33:43.4174119Z    org.glassfish.jersey.server.model.internal.AbstractJavaResourceMethodDispatcher$1#run(146)
2024-06-13T09:33:43.4174832Z    org.glassfish.jersey.server.model.internal.AbstractJavaResourceMethodDispatcher#invoke(189)
2024-06-13T09:33:43.4175781Z    org.glassfish.jersey.server.model.internal.JavaResourceMethodDispatcherProvider$ResponseOutInvoker#doDispatch(176)
2024-06-13T09:33:43.4176540Z    org.glassfish.jersey.server.model.internal.AbstractJavaResourceMethodDispatcher#dispatch(93)
2024-06-13T09:33:43.4177029Z    org.glassfish.jersey.server.model.ResourceMethodInvoker#invoke(478)
2024-06-13T09:33:43.4177653Z    org.glassfish.jersey.server.model.ResourceMethodInvoker#apply(400)
2024-06-13T09:33:43.4178133Z    org.glassfish.jersey.server.model.ResourceMethodInvoker#apply(81)
2024-06-13T09:33:43.4179013Z    org.glassfish.jersey.server.ServerRuntime$1#run(274)
2024-06-13T09:33:43.4179352Z    org.glassfish.jersey.internal.Errors$1#call(248)
2024-06-13T09:33:43.4179599Z    org.glassfish.jersey.internal.Errors$1#call(244)
2024-06-13T09:33:43.4179890Z    org.glassfish.jersey.internal.Errors#process(292)
2024-06-13T09:33:43.4180185Z    org.glassfish.jersey.internal.Errors#process(274)
2024-06-13T09:33:43.4180492Z    org.glassfish.jersey.internal.Errors#process(244)
2024-06-13T09:33:43.4180972Z    org.glassfish.jersey.process.internal.RequestScope#runInScope(266)
2024-06-13T09:33:43.4181329Z    org.glassfish.jersey.server.ServerRuntime#process(253)
2024-06-13T09:33:43.4181722Z    org.glassfish.jersey.server.ApplicationHandler#handle(696)