|
| 1 | +--- |
| 2 | +layout: post |
| 3 | +title: 'Testing virtual thread applications' |
| 4 | +date: 2023-10-02 |
| 5 | +tags: virtual threads, reactive, test |
| 6 | +synopsis: 'How to detect pinning while running tests.' |
| 7 | +author: cescoffier |
| 8 | +--- |
| 9 | +:imagesdir: /assets/images/posts/virtual-threads |
| 10 | + |
| 11 | +https://quarkus.io/blog/virtual-threads-2/[In a previous post], we have seen how to implement a CRUD application using virtual threads in Quarkus. |
| 12 | +The following video shows how to test this application and, specifically, how to detect pinning. |
| 13 | + |
| 14 | ++++ |
| 15 | +<iframestyle="margin-left: auto; margin-right: auto; display: block;" width="560" height="315" src="https://www.youtube.com/embed/GOHAEh3Ujh8?si=t8n8jLek0X7JC4MR" title="YouTube video player" frameborder="0" allow="accelerometer; autoplay; clipboard-write; encrypted-media; gyroscope; picture-in-picture; web-share" allowfullscreen></iframe> |
| 16 | ++++ |
| 17 | + |
| 18 | +The complete code of the application and the tests are available in the https://github.com/quarkusio/virtual-threads-demos/tree/main/crud-example[virtual threads demos repository]. |
| 19 | + |
| 20 | +## Pinning and Monopolization |
| 21 | + |
| 22 | +Virtual threads combine an imperative development model with a reactive execution mode. |
| 23 | +It may provide a simple way to increase the concurrency of an application. |
| 24 | +However, this might not always be the case. |
| 25 | + |
| 26 | +As described in https://quarkus.io/blog/virtual-thread-1/[another blog post], there are a few limitations, including monopolizing and pinning carrier threads. |
| 27 | +When this happens, the application's performance can drastically decrease and increase memory usage. |
| 28 | +Pinning for a short period can be tolerated, but it can be dramatic under load. |
| 29 | + |
| 30 | +While, at the moment, there are no reliable ways to detect monopolization, there are mechanisms to detect pinning. |
| 31 | + |
| 32 | +## Printing stack traces when a carrier thread gets pinned |
| 33 | + |
| 34 | +Suppose you have your application, and your code base contains tests. |
| 35 | +You can configure Surefire (or the plugin you use to execute your tests) to dump a stack trace as soon as a virtual thread is going to pin the carrier thread (instead of being unmounted smoothly). |
| 36 | +You must set the `jdk.tracePinnedThreads` system property to achieve this. |
| 37 | +For the Surefire Maven plugin, add the `argLine` parameter to the configuration: |
| 38 | + |
| 39 | +[source, xml] |
| 40 | +---- |
| 41 | +<argLine>-Djdk.tracePinnedThreads</argLine> |
| 42 | +---- |
| 43 | + |
| 44 | +With this configuration, when, while running your test, a carrier thread is pinned, the stack trace is dumped in the console: |
| 45 | + |
| 46 | +[source,text] |
| 47 | +---- |
| 48 | +2023-09-15 07:51:18,312 INFO [org.acm.cru.TodoResource] (quarkus-virtual-thread-0) Called on VirtualThread[#140,quarkus-virtual-thread-0]/runnable@ForkJoinPool-1-worker-1 |
| 49 | +Thread[#141,ForkJoinPool-1-worker-1,5,CarrierThreads] |
| 50 | + java.base/java.lang.VirtualThread$VThreadContinuation.onPinned(VirtualThread.java:185) |
| 51 | + java.base/jdk.internal.vm.Continuation.onPinned0(Continuation.java:393) |
| 52 | + java.base/java.lang.VirtualThread.parkNanos(VirtualThread.java:631) |
| 53 | + java.base/java.lang.VirtualThread.sleepNanos(VirtualThread.java:803) |
| 54 | + java.base/java.lang.Thread.sleep(Thread.java:507) |
| 55 | + org.acme.crud.TodoResource.pinTheCarrierThread(TodoResource.java:93) <== monitors:1 |
| 56 | + org.acme.crud.TodoResource.getAll(TodoResource.java:32) |
| 57 | + org.acme.crud.TodoResource$quarkusrestinvoker$getAll_0e9c86666ef01bafda5560c4bf86952c6cf09993.invoke(Unknown Source) |
| 58 | + org.jboss.resteasy.reactive.server.handlers.InvocationHandler.handle(InvocationHandler.java:29) |
| 59 | + io.quarkus.resteasy.reactive.server.runtime.QuarkusResteasyReactiveRequestContext.invokeHandler(QuarkusResteasyReactiveRequestContext.java:141) |
| 60 | + org.jboss.resteasy.reactive.common.core.AbstractResteasyReactiveContext.run(AbstractResteasyReactiveContext.java:147) |
| 61 | + io.quarkus.virtual.threads.ContextPreservingExecutorService$1.run(ContextPreservingExecutorService.java:36) |
| 62 | + java.base/java.util.concurrent.ThreadPerTaskExecutor$TaskRunner.run(ThreadPerTaskExecutor.java:314) |
| 63 | + java.base/java.lang.VirtualThread.run(VirtualThread.java:311) |
| 64 | +---- |
| 65 | + |
| 66 | +Analyzing the application logs will tell you whether your application is pinning. |
| 67 | +Furthermore, a closer look at the stack trace will give you the reason. |
| 68 | +In our example, the `pinTheCarrierThread` method is taking a lock. |
| 69 | +This is indicated by the `monitors:1` text: |
| 70 | + |
| 71 | +[source, text] |
| 72 | +---- |
| 73 | + org.acme.crud.TodoResource.pinTheCarrierThread(TodoResource.java:93) <== monitors:1 |
| 74 | +---- |
| 75 | + |
| 76 | +This approach can also be used in production (so, not only in tests). |
| 77 | +You can also determine how long the carrier thread was blocked by correlating the pinned stack trace with other log events (like what happened just after in the same thread). |
| 78 | + |
| 79 | +## Failing tests |
| 80 | + |
| 81 | +Dumping the stack trace may not be very convenient when your logs are already long. |
| 82 | +Fortunately, we released a small Junit 5 extension that allows you to fail the tests when pinning is detected. |
| 83 | +It's advantageous when you integrate a third-party library, and you need to know how virtual-thread-friendly it is (to decide between regular worker threads and virtual threads) |
| 84 | + |
| 85 | +The loom-unit Junit5 extension is currently a separated project. |
| 86 | +We are integrating it into the Quarkus test framework (under the `junit5-virtual-threads` name), so some of the steps mentioned below won't be necessary anymore or will be changed slightly. |
| 87 | + |
| 88 | +To use this extension, make sure you have the loom-unit extension in your project: |
| 89 | + |
| 90 | +[source, xml] |
| 91 | +---- |
| 92 | +<dependency> |
| 93 | + <groupId>me.escoffier.loom</groupId> <!-- Will become io.quarkus.junit5 --> |
| 94 | + <artifactId>loom-unit</artifactId> <!-- Will become junit5-virtual-threads --> |
| 95 | + <version>0.3.0</version> <!-- Will become unnecessary --> |
| 96 | + <scope>test</scope> |
| 97 | +</dependency> |
| 98 | +---- |
| 99 | + |
| 100 | +Then, in your test, use `@ExtendWith` to enable the extension: |
| 101 | + |
| 102 | +[source, java] |
| 103 | +---- |
| 104 | +@QuarkusTest |
| 105 | +@TestMethodOrder(MethodOrderer.OrderAnnotation.class) |
| 106 | +@ExtendWith(LoomUnitExtension.class) // <--- Enable the extension (will become @VirtualThreadUnit) |
| 107 | +@ShouldNotPin // <--- Detect pinning |
| 108 | +class TodoResourceTest { |
| 109 | + // ... |
| 110 | +} |
| 111 | +---- |
| 112 | + |
| 113 | +Finally, use the `@ShouldNotPin` annotation to indicate to fail the test if any of the methods of the test case pins the carrier thread. |
| 114 | +You can also use the `@ShouldNotPin` annotation on methods. |
| 115 | + |
| 116 | +If, during the execution of a test, a pinning event is captured, the test fails. |
| 117 | +The stack trace of the event is attached to the test failure: |
| 118 | + |
| 119 | +[source, text] |
| 120 | +---- |
| 121 | +java.lang.AssertionError: The test testInitialItems() was expected to NOT pin the carrier thread, but we collected 1 event(s) |
| 122 | +* Pinning event captured: |
| 123 | + java.lang.VirtualThread.parkOnCarrierThread(java.lang.VirtualThread.java:687) |
| 124 | + java.lang.VirtualThread.parkNanos(java.lang.VirtualThread.java:646) |
| 125 | + java.lang.VirtualThread.sleepNanos(java.lang.VirtualThread.java:803) |
| 126 | + java.lang.Thread.sleep(java.lang.Thread.java:507) |
| 127 | + org.acme.crud.TodoResource.pinTheCarrierThread(org.acme.crud.TodoResource.java:93) |
| 128 | + org.acme.crud.TodoResource.getAll(org.acme.crud.TodoResource.java:32) |
| 129 | + org.acme.crud.TodoResource$quarkusrestinvoker$getAll_0e9c86666ef01bafda5560c4bf86952c6cf09993.invoke(org.acme.crud.TodoResource$quarkusrestinvoker$getAll_0e9c86666ef01bafda5560c4bf86952c6cf09993.java:-1) |
| 130 | + org.jboss.resteasy.reactive.server.handlers.InvocationHandler.handle(org.jboss.resteasy.reactive.server.handlers.InvocationHandler.java:29) |
| 131 | + io.quarkus.resteasy.reactive.server.runtime.QuarkusResteasyReactiveRequestContext.invokeHandler(io.quarkus.resteasy.reactive.server.runtime.QuarkusResteasyReactiveRequestContext.java:141) |
| 132 | + org.jboss.resteasy.reactive.common.core.AbstractResteasyReactiveContext.run(org.jboss.resteasy.reactive.common.core.AbstractResteasyReactiveContext.java:147) |
| 133 | + io.quarkus.virtual.threads.ContextPreservingExecutorService$1.run(io.quarkus.virtual.threads.ContextPreservingExecutorService$1.java:36) |
| 134 | + java.util.concurrent.ThreadPerTaskExecutor$TaskRunner.run(java.util.concurrent.ThreadPerTaskExecutor$TaskRunner.java:314) |
| 135 | + java.lang.VirtualThread.runWith(java.lang.VirtualThread.java:341) |
| 136 | + java.lang.VirtualThread.run(java.lang.VirtualThread.java:311) |
| 137 | + java.lang.VirtualThread$VThreadContinuation$1.run(java.lang.VirtualThread$VThreadContinuation$1.java:192) |
| 138 | + jdk.internal.vm.Continuation.enter0(jdk.internal.vm.Continuation.java:320) |
| 139 | + jdk.internal.vm.Continuation.enter(jdk.internal.vm.Continuation.java:312) |
| 140 | + jdk.internal.vm.Continuation.enterSpecial(jdk.internal.vm.Continuation.java:-1) |
| 141 | +---- |
| 142 | + |
| 143 | +Find more about the loom-unit extension on https://github.com/cescoffier/loom-unit[the project repository] or its https://github.com/quarkusio/quarkus/tree/main/independent-projects/junit5-virtual-threads[Quarkus sibling]. |
| 144 | + |
| 145 | +## Summary |
| 146 | + |
| 147 | +This blog explains how you can detect pinning events while running your tests. |
| 148 | +First, you can dump the stack trace in the log. |
| 149 | +Second, you can use the `@ShouldNotPin` annotation to fail the tests if a pinning event is captured. |
| 150 | +Thanks to this https://github.com/quarkusio/quarkus/pull/35992[PR], the loom-unit extension will be integrated into the `@QuarkusTest` to provide a simpler developer experience. |
| 151 | +It will be part of Quarkus in the next release (3.5.x). |
0 commit comments