Uploaded image for project: 'WildFly'
  1. WildFly
  2. WFLY-19565

Resolve virtual thread pinning issues in CXF code

XMLWordPrintable

    • Icon: Task Task
    • Resolution: Unresolved
    • Icon: Major Major
    • None
    • None
    • Web Services
    • ---
    • ---

      When I was testing executing WildFly workloads on a virtual thread, turning on JVM thread pinning logging (see WFLY-19536) revealed pinning happening in CXF code. This issue is to trace working with the CXF community to resolve these issues and get the fixed code into WildFly.

      See occurrences of 'onPinned' in https://ci.wildfly.org/repository/download/WF_MainNightlyJobs_StandardLinuxJdk21/446569:id/testsuite/integration/ws/target/wildfly/standalone/log/server.log. Lines in the stack trace annotated with "<== monitor" show where a monitor lock was taken that results in pinning when blocking code executes.

      The most common example:

      2024-07-18 04:38:37,137 INFO  [stdout] (ForkJoinPool-1-worker-1) Thread[#147,ForkJoinPool-1-worker-1,5,CarrierThreads]
      2024-07-18 04:38:37,137 INFO  [stdout] (ForkJoinPool-1-worker-1)     java.base/java.lang.VirtualThread$VThreadContinuation.onPinned(VirtualThread.java:185)
      2024-07-18 04:38:37,138 INFO  [stdout] (ForkJoinPool-1-worker-1)     java.base/jdk.internal.vm.Continuation.onPinned0(Continuation.java:393)
      2024-07-18 04:38:37,138 INFO  [stdout] (ForkJoinPool-1-worker-1)     java.base/java.lang.VirtualThread.parkNanos(VirtualThread.java:631)
      2024-07-18 04:38:37,138 INFO  [stdout] (ForkJoinPool-1-worker-1)     java.base/java.lang.System$2.parkVirtualThread(System.java:2648)
      2024-07-18 04:38:37,138 INFO  [stdout] (ForkJoinPool-1-worker-1)     java.base/jdk.internal.misc.VirtualThreads.park(VirtualThreads.java:67)
      2024-07-18 04:38:37,138 INFO  [stdout] (ForkJoinPool-1-worker-1)     java.base/java.util.concurrent.locks.LockSupport.parkNanos(LockSupport.java:408)
      2024-07-18 04:38:37,138 INFO  [stdout] (ForkJoinPool-1-worker-1)     java.base/sun.nio.ch.Poller.pollIndirect(Poller.java:137)
      2024-07-18 04:38:37,138 INFO  [stdout] (ForkJoinPool-1-worker-1)     java.base/sun.nio.ch.Poller.poll(Poller.java:102)
      2024-07-18 04:38:37,139 INFO  [stdout] (ForkJoinPool-1-worker-1)     java.base/sun.nio.ch.Poller.poll(Poller.java:87)
      2024-07-18 04:38:37,139 INFO  [stdout] (ForkJoinPool-1-worker-1)     java.base/sun.nio.ch.NioSocketImpl.park(NioSocketImpl.java:175)
      2024-07-18 04:38:37,139 INFO  [stdout] (ForkJoinPool-1-worker-1)     java.base/sun.nio.ch.NioSocketImpl.timedRead(NioSocketImpl.java:280)
      2024-07-18 04:38:37,139 INFO  [stdout] (ForkJoinPool-1-worker-1)     java.base/sun.nio.ch.NioSocketImpl.implRead(NioSocketImpl.java:304)
      2024-07-18 04:38:37,139 INFO  [stdout] (ForkJoinPool-1-worker-1)     java.base/sun.nio.ch.NioSocketImpl.read(NioSocketImpl.java:346)
      2024-07-18 04:38:37,139 INFO  [stdout] (ForkJoinPool-1-worker-1)     java.base/sun.nio.ch.NioSocketImpl$1.read(NioSocketImpl.java:796)
      2024-07-18 04:38:37,139 INFO  [stdout] (ForkJoinPool-1-worker-1)     java.base/java.net.Socket$SocketInputStream.read(Socket.java:1099)
      2024-07-18 04:38:37,139 INFO  [stdout] (ForkJoinPool-1-worker-1)     java.base/java.io.BufferedInputStream.fill(BufferedInputStream.java:291)
      2024-07-18 04:38:37,140 INFO  [stdout] (ForkJoinPool-1-worker-1)     java.base/java.io.BufferedInputStream.read1(BufferedInputStream.java:347)
      2024-07-18 04:38:37,140 INFO  [stdout] (ForkJoinPool-1-worker-1)     java.base/java.io.BufferedInputStream.implRead(BufferedInputStream.java:420)
      2024-07-18 04:38:37,140 INFO  [stdout] (ForkJoinPool-1-worker-1)     java.base/java.io.BufferedInputStream.read(BufferedInputStream.java:399)
      2024-07-18 04:38:37,140 INFO  [stdout] (ForkJoinPool-1-worker-1)     java.base/sun.net.www.http.HttpClient.parseHTTPHeader(HttpClient.java:827)
      2024-07-18 04:38:37,140 INFO  [stdout] (ForkJoinPool-1-worker-1)     java.base/sun.net.www.http.HttpClient.parseHTTP(HttpClient.java:759)
      2024-07-18 04:38:37,140 INFO  [stdout] (ForkJoinPool-1-worker-1)     java.base/sun.net.www.protocol.http.HttpURLConnection.getInputStream0(HttpURLConnection.java:1690)
      2024-07-18 04:38:37,140 INFO  [stdout] (ForkJoinPool-1-worker-1)     java.base/sun.net.www.protocol.http.HttpURLConnection.getInputStream(HttpURLConnection.java:1599)
      2024-07-18 04:38:37,140 INFO  [stdout] (ForkJoinPool-1-worker-1)     java.base/java.net.HttpURLConnection.getResponseCode(HttpURLConnection.java:531)
      2024-07-18 04:38:37,140 INFO  [stdout] (ForkJoinPool-1-worker-1)     org.apache.cxf.impl//org.apache.cxf.transport.http.URLConnectionHTTPConduit$URLConnectionWrappedOutputStream$2.run(URLConnectionHTTPConduit.java:370)
      2024-07-18 04:38:37,140 INFO  [stdout] (ForkJoinPool-1-worker-1)     org.apache.cxf.impl//org.apache.cxf.transport.http.URLConnectionHTTPConduit$URLConnectionWrappedOutputStream$2.run(URLConnectionHTTPConduit.java:366)
      2024-07-18 04:38:37,140 INFO  [stdout] (ForkJoinPool-1-worker-1)     java.base/java.security.AccessController.doPrivileged(AccessController.java:571)
      2024-07-18 04:38:37,140 INFO  [stdout] (ForkJoinPool-1-worker-1)     org.apache.cxf.impl//org.apache.cxf.transport.http.URLConnectionHTTPConduit$URLConnectionWrappedOutputStream.getResponseCode(URLConnectionHTTPConduit.java:366)
      2024-07-18 04:38:37,141 INFO  [stdout] (ForkJoinPool-1-worker-1)     org.apache.cxf.impl//org.apache.cxf.transport.http.HTTPConduit$WrappedOutputStream.doProcessResponseCode(HTTPConduit.java:1653)
      2024-07-18 04:38:37,141 INFO  [stdout] (ForkJoinPool-1-worker-1)     org.apache.cxf.impl//org.apache.cxf.transport.http.HTTPConduit$WrappedOutputStream.handleResponseInternal(HTTPConduit.java:1684)
      2024-07-18 04:38:37,141 INFO  [stdout] (ForkJoinPool-1-worker-1)     org.apache.cxf.impl//org.apache.cxf.transport.http.HTTPConduit$WrappedOutputStream.handleResponse(HTTPConduit.java:1626)
      2024-07-18 04:38:37,141 INFO  [stdout] (ForkJoinPool-1-worker-1)     org.apache.cxf.impl//org.apache.cxf.transport.http.HTTPConduit$WrappedOutputStream.close(HTTPConduit.java:1420)
      2024-07-18 04:38:37,141 INFO  [stdout] (ForkJoinPool-1-worker-1)     org.apache.cxf@4.0.4//org.apache.cxf.transport.AbstractConduit.close(AbstractConduit.java:56)
      2024-07-18 04:38:37,141 INFO  [stdout] (ForkJoinPool-1-worker-1)     org.apache.cxf.impl//org.apache.cxf.transport.http.HTTPConduit.close(HTTPConduit.java:717)
      2024-07-18 04:38:37,141 INFO  [stdout] (ForkJoinPool-1-worker-1)     org.apache.cxf.impl//org.apache.cxf.transport.http.HttpClientHTTPConduit.close(HttpClientHTTPConduit.java:115)
      2024-07-18 04:38:37,141 INFO  [stdout] (ForkJoinPool-1-worker-1)     org.apache.cxf@4.0.4//org.apache.cxf.interceptor.MessageSenderInterceptor$MessageSenderEndingInterceptor.handleMessage(MessageSenderInterceptor.java:63)
      2024-07-18 04:38:37,141 INFO  [stdout] (ForkJoinPool-1-worker-1)     org.apache.cxf@4.0.4//org.apache.cxf.phase.PhaseInterceptorChain.doIntercept(PhaseInterceptorChain.java:307) <== monitors:1
      

      To reproduce build https://github.com/bstansberry/wildfly/tree/pinning_check on SE 21.

            rhn-engineering-ema Jim Ma
            bstansbe@redhat.com Brian Stansberry
            Votes:
            0 Vote for this issue
            Watchers:
            2 Start watching this issue

              Created:
              Updated: