Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

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

Open
wants to merge 4 commits into
base: main
Choose a base branch
from
Open

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

wants to merge 4 commits into from

Conversation

jbescos
Copy link
Member

@jbescos jbescos commented Jun 12, 2024 •
edited by romain-grecourt
Loading

Description

Fail HelidonTests by default when pinning jfr event is detected

Fixes #8857

Documentation

None.

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

@oracle-contributor-agreement oracle-contributor-agreement bot added the OCA Verified All contributors have signed the Oracle Contributor Agreement. label Jun 12, 2024
@jbescos jbescos requested a review from danielkec June 12, 2024 12:31
@jbescos jbescos marked this pull request as draft June 12, 2024 12:31
@jbescos jbescos force-pushed the issue8857 branch 4 times, most recently from a6e3136 to 558245f Compare June 12, 2024 14:08
@jbescos
Copy link
Member Author

jbescos commented Jun 12, 2024 •
edited
Loading

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
Copy link
Member Author

jbescos commented Jun 13, 2024 •
edited
Loading

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)

@jbescos
Create PinnedThreadValidation
37e3cbf 
Signed-off-by: Jorge Bescos Gascon <[email protected]>
@jbescos jbescos marked this pull request as ready for review June 19, 2024 05:28
@jbescos jbescos self-assigned this Jun 20, 2024
@jbescos
Merge main
5584c6a 
Signed-off-by: Jorge Bescos Gascon <[email protected]>
@jbescos
Merge with main
8649cee 
Signed-off-by: Jorge Bescos Gascon <[email protected]>
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Reviewers

@danielkec danielkec Awaiting requested review from danielkec

@tomas-langer tomas-langer Awaiting requested review from tomas-langer

At least 1 approving review is required to merge this pull request.

Assignees

@jbescos jbescos

Labels
OCA Verified All contributors have signed the Oracle Contributor Agreement.
Projects
None yet
Milestone
No milestone
Development

Successfully merging this pull request may close these issues.

Fail HelidonTests by default when pinning jfr event is detected
1 participant
@jbescos