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.

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

Improper use of Servlet InputStream Async I/O results in 100% CPU #5153

Closed
jwalker-highspot opened this issue Aug 13, 2020 · 6 comments
Closed
Assignees
Labels
Third Party Issues with third party libraries or projects

Comments

@jwalker-highspot
Copy link

jwalker-highspot commented Aug 13, 2020

Jetty version
9.4.28.v20200408

Java version
openjdk version "11.0.5" 2019-10-15
OpenJDK Runtime Environment (build 11.0.5+10-post-Ubuntu-2ubuntu116.04)
OpenJDK 64-Bit Server VM (build 11.0.5+10-post-Ubuntu-2ubuntu116.04, mixed mode, sharing)

OS type/version

Ubuntu 16.04.6 LTS

Description

I have a jetty server listening for web socket requests ultimately handled by an implementation of sockjs as a servlet:

https://github.com/projectodd/sockjs-servlet

Over time, typically immediately after finishing with a request, more and more threads begin to hang. While hung, they use 100% of a single CPU core, and appear to just be spinning around in a loop within Jetty. Eventually, the zombie threads monopolize all cores.

The thread keeps going and CPU usage remains elevated even if I take the server out of the load balancer.

There seem to be many tickets describing vaguely similar issues, including:
#5090
#4537
#4717

jstack output varies slightly from case to case, but here's one example:

"qtp424598392-16540" #16540 prio=5 os_prio=0 cpu=13978395.35ms elapsed=14637.43s allocated=62012G defined_classes=3 tid=0x00007f3370d3e800 nid=0x1038 runnable  [0x00007f33209dd000]
   java.lang.Thread.State: RUNNABLE
	at org.eclipse.jetty.server.HttpInput.read(HttpInput.java:304)
	- locked <0x0000000632c02e78> (a java.util.ArrayDeque)
	at java.io.InputStream.read(java.base@11.0.5/InputStream.java:205)
	at org.projectodd.sockjs.servlet.SockJsServletRequest.onDataAvailable(SockJsServletRequest.java:93)
	at org.eclipse.jetty.server.HttpInput.run(HttpInput.java:907)
	at org.eclipse.jetty.server.handler.ContextHandler.handle(ContextHandler.java:1448)
	at org.eclipse.jetty.server.HttpChannel.handle(HttpChannel.java:468)
	at org.eclipse.jetty.server.HttpConnection.onFillable(HttpConnection.java:273)
	at org.eclipse.jetty.io.AbstractConnection$ReadCallback.succeeded(AbstractConnection.java:311)
	at org.eclipse.jetty.io.FillInterest.fillable(FillInterest.java:103)
	at org.eclipse.jetty.io.ChannelEndPoint$2.run(ChannelEndPoint.java:117)
	at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.runTask(EatWhatYouKill.java:336)
	at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.doProduce(EatWhatYouKill.java:313)
	at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.tryProduce(EatWhatYouKill.java:171)
	at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.run(EatWhatYouKill.java:129)
	at org.eclipse.jetty.util.thread.ReservedThreadExecutor$ReservedThread.run(ReservedThreadExecutor.java:375)
	at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:806)
	at org.eclipse.jetty.util.thread.QueuedThreadPool$Runner.run(QueuedThreadPool.java:938)
	at java.lang.Thread.run(java.base@11.0.5/Thread.java:834)

   Locked ownable synchronizers:
	- None

Strace of one of the stuck threads (it just loops through this same basic set of operations):

strace: Process 4152 attached
strace: [ Process PID=4152 runs in x32 mode. ]
strace: [ Process PID=4152 runs in 64 bit mode. ]
futex(0x7f33e026fe54, FUTEX_WAKE_OP_PRIVATE, 1, 1, 0x7f33e026fe50, {FUTEX_OP_SET, 0, FUTEX_OP_CMP_GT, 1}) = 1
futex(0x7f33e1c87b54, FUTEX_WAIT_PRIVATE, 206581, NULL) = 0
futex(0x7f33e1c87b28, FUTEX_WAKE_PRIVATE, 1) = 0
futex(0x7f33e0272f54, FUTEX_WAKE_OP_PRIVATE, 1, 1, 0x7f33e0272f50, {FUTEX_OP_SET, 0, FUTEX_OP_CMP_GT, 1}) = 1
futex(0x7f33e026fe54, FUTEX_WAKE_OP_PRIVATE, 1, 1, 0x7f33e026fe50, {FUTEX_OP_SET, 0, FUTEX_OP_CMP_GT, 1}) = 1
futex(0x7f33e1c87b54, FUTEX_WAIT_PRIVATE, 206583, NULL) = 0
futex(0x7f33e1c87b28, FUTEX_WAKE_PRIVATE, 1) = 0
futex(0x7f33e0272f54, FUTEX_WAKE_OP_PRIVATE, 1, 1, 0x7f33e0272f50, {FUTEX_OP_SET, 0, FUTEX_OP_CMP_GT, 1}) = 1
futex(0x7f33e026fe54, FUTEX_WAKE_OP_PRIVATE, 1, 1, 0x7f33e026fe50, {FUTEX_OP_SET, 0, FUTEX_OP_CMP_GT, 1}) = 1
gettid()                                = 4152
futex(0x7f33e1c87b54, FUTEX_WAIT_PRIVATE, 206585, NULL) = 0
futex(0x7f33e1c87b28, FUTEX_WAKE_PRIVATE, 1) = 0
futex(0x7f33e026fe54, FUTEX_WAKE_OP_PRIVATE, 1, 1, 0x7f33e026fe50, {FUTEX_OP_SET, 0, FUTEX_OP_CMP_GT, 1}) = 1
futex(0x7f33e0272f54, FUTEX_WAKE_OP_PRIVATE, 1, 1, 0x7f33e0272f50, {FUTEX_OP_SET, 0, FUTEX_OP_CMP_GT, 1}) = 1
futex(0x7f33e1bafd54, FUTEX_WAKE_OP_PRIVATE, 1, 1, 0x7f33e1bafd50, {FUTEX_OP_SET, 0, FUTEX_OP_CMP_GT, 1}) = 1
futex(0x7f33e026fe54, FUTEX_WAKE_OP_PRIVATE, 1, 1, 0x7f33e026fe50, {FUTEX_OP_SET, 0, FUTEX_OP_CMP_GT, 1}) = 1
futex(0x7f33e1c87b54, FUTEX_WAIT_PRIVATE, 206587, NULL) = 0
futex(0x7f33e1c87b28, FUTEX_WAKE_PRIVATE, 1) = 0
futex(0x7f33e0272f54, FUTEX_WAKE_OP_PRIVATE, 1, 1, 0x7f33e0272f50, {FUTEX_OP_SET, 0, FUTEX_OP_CMP_GT, 1}) = 1
futex(0x7f33e026fe54, FUTEX_WAKE_OP_PRIVATE, 1, 1, 0x7f33e026fe50, {FUTEX_OP_SET, 0, FUTEX_OP_CMP_GT, 1}) = 1
futex(0x7f33e1c87b54, FUTEX_WAIT_PRIVATE, 206589, NULL) = 0
futex(0x7f33e1c87b28, FUTEX_WAKE_PRIVATE, 1) = 0
futex(0x7f33e0272f54, FUTEX_WAKE_OP_PRIVATE, 1, 1, 0x7f33e0272f50, {FUTEX_OP_SET, 0, FUTEX_OP_CMP_GT, 1}) = 1
futex(0x7f33e026fe54, FUTEX_WAKE_OP_PRIVATE, 1, 1, 0x7f33e026fe50, {FUTEX_OP_SET, 0, FUTEX_OP_CMP_GT, 1}) = 1
futex(0x7f33e1c87b54, FUTEX_WAIT_PRIVATE, 206591, NULL) = 0
futex(0x7f33e1c87b28, FUTEX_WAKE_PRIVATE, 1) = 0
futex(0x7f33e0272f54, FUTEX_WAKE_OP_PRIVATE, 1, 1, 0x7f33e0272f50, {FUTEX_OP_SET, 0, FUTEX_OP_CMP_GT, 1}) = 1
futex(0x7f33e026fe54, FUTEX_WAKE_OP_PRIVATE, 1, 1, 0x7f33e026fe50, {FUTEX_OP_SET, 0, FUTEX_OP_CMP_GT, 1}) = 1
gettid()                                = 4152
futex(0x7f33e026fe54, FUTEX_WAKE_OP_PRIVATE, 1, 1, 0x7f33e026fe50, {FUTEX_OP_SET, 0, FUTEX_OP_CMP_GT, 1}) = 1
futex(0x7f33e1c87b54, FUTEX_WAIT_PRIVATE, 206593, NULL) = 0
futex(0x7f33e1c87b28, FUTEX_WAKE_PRIVATE, 1) = 0
futex(0x7f33e026fe54, FUTEX_WAKE_OP_PRIVATE, 1, 1, 0x7f33e026fe50, {FUTEX_OP_SET, 0, FUTEX_OP_CMP_GT, 1}) = 1
futex(0x7f33e0272f54, FUTEX_WAKE_OP_PRIVATE, 1, 1, 0x7f33e0272f50, {FUTEX_OP_SET, 0, FUTEX_OP_CMP_GT, 1}) = 1
--- SIGSEGV {si_signo=SIGSEGV, si_code=SEGV_ACCERR, si_addr=0x7f33e8bf3008} ---
rt_sigreturn({mask=[QUIT]})             = 0
gettid()                                = 4152
futex(0x7f33e026fe54, FUTEX_WAKE_OP_PRIVATE, 1, 1, 0x7f33e026fe50, {FUTEX_OP_SET, 0, FUTEX_OP_CMP_GT, 1}) = 1
... continues on like this...

To me the segfault seems significant, but I don't know what to make of it.

Thanks!

@jwalker-highspot jwalker-highspot changed the title Zombie Websocket Threads Slowly Monopolize CPU Hung Websocket Threads Slowly Monopolize CPU Aug 13, 2020
@joakime
Copy link
Contributor

joakime commented Aug 13, 2020

9.4.28.v20200408

That version of Eclipse Jetty is subject to some security reports.
Be aware of them.

https://www.eclipse.org/jetty/security-reports.html

Eclipse Jetty 9.4.31.v20200723 is available has many fixes, some even in websocket.

 "qtp424598392-16540" #16540 prio=5 os_prio=0 cpu=13978395.35ms elapsed=14637.43s allocated=62012G defined_classes=3 tid=0x00007f3370d3e800 nid=0x1038 runnable [0x00007f33209dd000]
   java.lang.Thread.State: RUNNABLE
	at org.eclipse.jetty.server.HttpInput.read(HttpInput.java:304)
	- locked <0x0000000632c02e78> (a java.util.ArrayDeque)
	at java.io.InputStream.read(java.base@11.0.5/InputStream.java:205)
	at org.projectodd.sockjs.servlet.SockJsServletRequest.onDataAvailable(SockJsServletRequest.java:93)

That stacktrace shows code that is doing a Servlet spec Async I/O read of HTTP Servlet Request bytes.
That has nothing to do with WebSocket.

There seem to be many tickets describing vaguely similar issues, including:
#5090

Issue #5090 is unique to the UnixSocket server connector. And is unrelated to your described issue.

#4537

This has to do with Winstone behaviors in Jenkins.
This is also unrelated to your described issue.

#4717

The current status of this one is about a SelectorProvider bug on the JVM / OS combo.
This could be related to your issue.

Two pieces of information will help us narrow things down for you.

  1. DEBUG logs - Run with DEBUG logging turned on and capture a minute or two of when the CPU is experiencing the excess load.
  2. Capture thread dumps - a few in a row, wait 10 seconds between each requested thread dump.

Those logs will hopefully tell us both where the problem is occurring, and what the nature of the problem is.

Example: those DEBUG logs will tell us if you have the OS networking bug (or not).
In this case, usually we look for a selector that is woken with no progress or nothing selected.

This will be logged at DEBUG level on the org.eclipse.jetty.io.ManagedSelector as ...

https://github.com/eclipse/jetty.project/blob/jetty-9.4.31.v20200723/jetty-io/src/main/java/org/eclipse/jetty/io/ManagedSelector.java#L160
https://github.com/eclipse/jetty.project/blob/450ba27947e13e66baa8cd1ce7e85a4461cacc1d/jetty-io/src/main/java/org/eclipse/jetty/io/ManagedSelector.java#L160

@joakime joakime self-assigned this Aug 13, 2020
@joakime
Copy link
Contributor

joakime commented Aug 13, 2020

I have a jetty server listening for web socket requests ultimately handled by an implementation of sockjs as a servlet:

https://github.com/projectodd/sockjs-servlet

Can you describe the steps you take to reproduce the problem with this project?

@jwalker-highspot
Copy link
Author

jwalker-highspot commented Aug 13, 2020

@joakime

Here are 10 thread dumps taken with jstack -l -e taken 10 seconds apart. I've clipped everything except one of the hung threads.

It looks like it's reading data from the stack trace but other things suggest it might not be. For example, in the netstat -n -e -t output, no established tcp connections on the server's port are listed. (This server has been removed from load balancer and is not accepting new incoming connections.)

In this case, you can see the loop it's stuck in involves SockJS.

Can you describe the steps you take to reproduce the problem with this project?

I'll get you more info here ASAP (along with debug logs), but very vaguely speaking:

handler =  WebSocketServerContainerInitializer.configureContext
handler.addServlet(sockJsServlet)
server.setHandler(handler)
// start server
// everything runs well for hours
// first hung thread
// everything runs along for more hours
// second hung thread
// rinse and repeat until cpu pegged
Run 1
"qtp1722907060-12256" #12256 prio=5 os_prio=0 cpu=29481600.34ms elapsed=30990.61s allocated=127534G defined_classes=3 tid=0x00007f6644c4a000 nid=0x60d9 runnable  [0x00007f657b6f4000]
   java.lang.Thread.State: RUNNABLE
        at org.eclipse.jetty.server.HttpInput.nextNonSentinelContent(HttpInput.java:386)
        at org.eclipse.jetty.server.HttpInput.nextContent(HttpInput.java:367)
        at org.eclipse.jetty.server.HttpInput.read(HttpInput.java:304)
        - locked <0x000000062c0240a0> (a java.util.ArrayDeque)
        at java.io.InputStream.read(java.base@11.0.5/InputStream.java:205)
        at org.projectodd.sockjs.servlet.SockJsServletRequest.onDataAvailable(SockJsServletRequest.java:93)
        at org.eclipse.jetty.server.HttpInput.run(HttpInput.java:907)
        at org.eclipse.jetty.server.handler.ContextHandler.handle(ContextHandler.java:1448)
        at org.eclipse.jetty.server.HttpChannel.handle(HttpChannel.java:468)
        at org.eclipse.jetty.server.HttpConnection.onFillable(HttpConnection.java:273)
        at org.eclipse.jetty.io.AbstractConnection$ReadCallback.succeeded(AbstractConnection.java:311)
        at org.eclipse.jetty.io.FillInterest.fillable(FillInterest.java:103)
        at org.eclipse.jetty.io.ChannelEndPoint$2.run(ChannelEndPoint.java:117)
        at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.runTask(EatWhatYouKill.java:336)
        at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.doProduce(EatWhatYouKill.java:313)
        at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.tryProduce(EatWhatYouKill.java:171)
        at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.run(EatWhatYouKill.java:129)
        at org.eclipse.jetty.util.thread.ReservedThreadExecutor$ReservedThread.run(ReservedThreadExecutor.java:375)
        at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:806)
        at org.eclipse.jetty.util.thread.QueuedThreadPool$Runner.run(QueuedThreadPool.java:938)
        at java.lang.Thread.run(java.base@11.0.5/Thread.java:834)

   Locked ownable synchronizers:
       - None
End Run 1
Run 2
"qtp1722907060-12256" #12256 prio=5 os_prio=0 cpu=29491663.07ms elapsed=31001.27s allocated=127577G defined_classes=3 tid=0x00007f6644c4a000 nid=0x60d9 runnable  [0x00007f657b6f4000]
   java.lang.Thread.State: RUNNABLE
        at java.io.InputStream.read(java.base@11.0.5/InputStream.java:205)
        at org.projectodd.sockjs.servlet.SockJsServletRequest.onDataAvailable(SockJsServletRequest.java:93)
        at org.eclipse.jetty.server.HttpInput.run(HttpInput.java:907)
        at org.eclipse.jetty.server.handler.ContextHandler.handle(ContextHandler.java:1448)
        at org.eclipse.jetty.server.HttpChannel.handle(HttpChannel.java:468)
        at org.eclipse.jetty.server.HttpConnection.onFillable(HttpConnection.java:273)
        at org.eclipse.jetty.io.AbstractConnection$ReadCallback.succeeded(AbstractConnection.java:311)
        at org.eclipse.jetty.io.FillInterest.fillable(FillInterest.java:103)
        at org.eclipse.jetty.io.ChannelEndPoint$2.run(ChannelEndPoint.java:117)
        at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.runTask(EatWhatYouKill.java:336)
        at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.doProduce(EatWhatYouKill.java:313)
        at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.tryProduce(EatWhatYouKill.java:171)
        at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.run(EatWhatYouKill.java:129)
        at org.eclipse.jetty.util.thread.ReservedThreadExecutor$ReservedThread.run(ReservedThreadExecutor.java:375)
        at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:806)
        at org.eclipse.jetty.util.thread.QueuedThreadPool$Runner.run(QueuedThreadPool.java:938)
        at java.lang.Thread.run(java.base@11.0.5/Thread.java:834)

   Locked ownable synchronizers:
       - None

End Run 2
Run 3
"qtp1722907060-12256" #12256 prio=5 os_prio=0 cpu=29501772.87ms elapsed=31012.09s allocated=127620G defined_classes=3 tid=0x00007f6644c4a000 nid=0x60d9 runnable  [0x00007f657b6f5000]
   java.lang.Thread.State: RUNNABLE
        at org.projectodd.sockjs.servlet.SockJsServletRequest.onDataAvailable(SockJsServletRequest.java:92)
        at org.eclipse.jetty.server.HttpInput.run(HttpInput.java:907)
        at org.eclipse.jetty.server.handler.ContextHandler.handle(ContextHandler.java:1448)
        at org.eclipse.jetty.server.HttpChannel.handle(HttpChannel.java:468)
        at org.eclipse.jetty.server.HttpConnection.onFillable(HttpConnection.java:273)
        at org.eclipse.jetty.io.AbstractConnection$ReadCallback.succeeded(AbstractConnection.java:311)
        at org.eclipse.jetty.io.FillInterest.fillable(FillInterest.java:103)
        at org.eclipse.jetty.io.ChannelEndPoint$2.run(ChannelEndPoint.java:117)
        at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.runTask(EatWhatYouKill.java:336)
        at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.doProduce(EatWhatYouKill.java:313)
        at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.tryProduce(EatWhatYouKill.java:171)
        at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.run(EatWhatYouKill.java:129)
        at org.eclipse.jetty.util.thread.ReservedThreadExecutor$ReservedThread.run(ReservedThreadExecutor.java:375)
        at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:806)
        at org.eclipse.jetty.util.thread.QueuedThreadPool$Runner.run(QueuedThreadPool.java:938)
        at java.lang.Thread.run(java.base@11.0.5/Thread.java:834)

   Locked ownable synchronizers:
        - None

End Run 3
Run 4
"qtp1722907060-12256" #12256 prio=5 os_prio=0 cpu=29511855.07ms elapsed=31022.91s allocated=127663G defined_classes=3 tid=0x00007f6644c4a000 nid=0x60d9 runnable  [0x00007f657b6f4000]
   java.lang.Thread.State: RUNNABLE
        at org.eclipse.jetty.server.HttpInput.nextNonSentinelContent(HttpInput.java:386)
        at org.eclipse.jetty.server.HttpInput.nextContent(HttpInput.java:367)
        at org.eclipse.jetty.server.HttpInput.read(HttpInput.java:304)
        - locked <0x000000062c0240a0> (a java.util.ArrayDeque)
        at java.io.InputStream.read(java.base@11.0.5/InputStream.java:205)
        at org.projectodd.sockjs.servlet.SockJsServletRequest.onDataAvailable(SockJsServletRequest.java:93)
        at org.eclipse.jetty.server.HttpInput.run(HttpInput.java:907)
        at org.eclipse.jetty.server.handler.ContextHandler.handle(ContextHandler.java:1448)
        at org.eclipse.jetty.server.HttpChannel.handle(HttpChannel.java:468)
        at org.eclipse.jetty.server.HttpConnection.onFillable(HttpConnection.java:273)
        at org.eclipse.jetty.io.AbstractConnection$ReadCallback.succeeded(AbstractConnection.java:311)
        at org.eclipse.jetty.io.FillInterest.fillable(FillInterest.java:103)
        at org.eclipse.jetty.io.ChannelEndPoint$2.run(ChannelEndPoint.java:117)
        at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.runTask(EatWhatYouKill.java:336)
        at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.doProduce(EatWhatYouKill.java:313)
        at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.tryProduce(EatWhatYouKill.java:171)
        at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.run(EatWhatYouKill.java:129)
        at org.eclipse.jetty.util.thread.ReservedThreadExecutor$ReservedThread.run(ReservedThreadExecutor.java:375)
        at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:806)
        at org.eclipse.jetty.util.thread.QueuedThreadPool$Runner.run(QueuedThreadPool.java:938)
        at java.lang.Thread.run(java.base@11.0.5/Thread.java:834)

   Locked ownable synchronizers:
        - None
End Run 4
Run 5
"qtp1722907060-12256" #12256 prio=5 os_prio=0 cpu=29521879.23ms elapsed=31033.61s allocated=127705G defined_classes=3 tid=0x00007f6644c4a000 nid=0x60d9 runnable  [0x00007f657b6f4000]
   java.lang.Thread.State: RUNNABLE
        at org.eclipse.jetty.server.HttpInput.nextNonSentinelContent(HttpInput.java:386)
        at org.eclipse.jetty.server.HttpInput.nextContent(HttpInput.java:367)
        at org.eclipse.jetty.server.HttpInput.read(HttpInput.java:304)
        - locked <0x000000062c0240a0> (a java.util.ArrayDeque)
        at java.io.InputStream.read(java.base@11.0.5/InputStream.java:205)
        at org.projectodd.sockjs.servlet.SockJsServletRequest.onDataAvailable(SockJsServletRequest.java:93)
        at org.eclipse.jetty.server.HttpInput.run(HttpInput.java:907)
        at org.eclipse.jetty.server.handler.ContextHandler.handle(ContextHandler.java:1448)
        at org.eclipse.jetty.server.HttpChannel.handle(HttpChannel.java:468)
        at org.eclipse.jetty.server.HttpConnection.onFillable(HttpConnection.java:273)
        at org.eclipse.jetty.io.AbstractConnection$ReadCallback.succeeded(AbstractConnection.java:311)
        at org.eclipse.jetty.io.FillInterest.fillable(FillInterest.java:103)
        at org.eclipse.jetty.io.ChannelEndPoint$2.run(ChannelEndPoint.java:117)
        at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.runTask(EatWhatYouKill.java:336)
        at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.doProduce(EatWhatYouKill.java:313)
        at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.tryProduce(EatWhatYouKill.java:171)
        at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.run(EatWhatYouKill.java:129)
        at org.eclipse.jetty.util.thread.ReservedThreadExecutor$ReservedThread.run(ReservedThreadExecutor.java:375)
        at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:806)
        at org.eclipse.jetty.util.thread.QueuedThreadPool$Runner.run(QueuedThreadPool.java:938)
        at java.lang.Thread.run(java.base@11.0.5/Thread.java:834)

   Locked ownable synchronizers:
        - None
End Run 5
Run 6
"qtp1722907060-12256" #12256 prio=5 os_prio=0 cpu=29531887.94ms elapsed=31044.26s allocated=127748G defined_classes=3 tid=0x00007f6644c4a000 nid=0x60d9 runnable  [0x00007f657b6f4000]
   java.lang.Thread.State: RUNNABLE
        at org.eclipse.jetty.server.HttpInput.nextNonSentinelContent(HttpInput.java:386)
        at org.eclipse.jetty.server.HttpInput.nextContent(HttpInput.java:367)
        at org.eclipse.jetty.server.HttpInput.read(HttpInput.java:304)
        - locked <0x000000062c0240a0> (a java.util.ArrayDeque)
        at java.io.InputStream.read(java.base@11.0.5/InputStream.java:205)
        at org.projectodd.sockjs.servlet.SockJsServletRequest.onDataAvailable(SockJsServletRequest.java:93)
        at org.eclipse.jetty.server.HttpInput.run(HttpInput.java:907)
        at org.eclipse.jetty.server.handler.ContextHandler.handle(ContextHandler.java:1448)
        at org.eclipse.jetty.server.HttpChannel.handle(HttpChannel.java:468)
        at org.eclipse.jetty.server.HttpConnection.onFillable(HttpConnection.java:273)
        at org.eclipse.jetty.io.AbstractConnection$ReadCallback.succeeded(AbstractConnection.java:311)
        at org.eclipse.jetty.io.FillInterest.fillable(FillInterest.java:103)
        at org.eclipse.jetty.io.ChannelEndPoint$2.run(ChannelEndPoint.java:117)
        at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.runTask(EatWhatYouKill.java:336)
        at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.doProduce(EatWhatYouKill.java:313)
        at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.tryProduce(EatWhatYouKill.java:171)
        at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.run(EatWhatYouKill.java:129)
        at org.eclipse.jetty.util.thread.ReservedThreadExecutor$ReservedThread.run(ReservedThreadExecutor.java:375)
        at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:806)
        at org.eclipse.jetty.util.thread.QueuedThreadPool$Runner.run(QueuedThreadPool.java:938)
        at java.lang.Thread.run(java.base@11.0.5/Thread.java:834)

   Locked ownable synchronizers:
        - None
End Run 6
Run 7
"qtp1722907060-12256" #12256 prio=5 os_prio=0 cpu=29541923.63ms elapsed=31054.97s allocated=127791G defined_classes=3 tid=0x00007f6644c4a000 nid=0x60d9 runnable  [0x00007f657b6f4000]
   java.lang.Thread.State: RUNNABLE
        at org.eclipse.jetty.server.HttpInput.nextNonSentinelContent(HttpInput.java:386)
        at org.eclipse.jetty.server.HttpInput.nextContent(HttpInput.java:367)
        at org.eclipse.jetty.server.HttpInput.read(HttpInput.java:304)
        - locked <0x000000062c0240a0> (a java.util.ArrayDeque)
        at java.io.InputStream.read(java.base@11.0.5/InputStream.java:205)
        at org.projectodd.sockjs.servlet.SockJsServletRequest.onDataAvailable(SockJsServletRequest.java:93)
        at org.eclipse.jetty.server.HttpInput.run(HttpInput.java:907)
        at org.eclipse.jetty.server.handler.ContextHandler.handle(ContextHandler.java:1448)
        at org.eclipse.jetty.server.HttpChannel.handle(HttpChannel.java:468)
        at org.eclipse.jetty.server.HttpConnection.onFillable(HttpConnection.java:273)
        at org.eclipse.jetty.io.AbstractConnection$ReadCallback.succeeded(AbstractConnection.java:311)
        at org.eclipse.jetty.io.FillInterest.fillable(FillInterest.java:103)
        at org.eclipse.jetty.io.ChannelEndPoint$2.run(ChannelEndPoint.java:117)
        at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.runTask(EatWhatYouKill.java:336)
        at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.doProduce(EatWhatYouKill.java:313)
        at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.tryProduce(EatWhatYouKill.java:171)
        at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.run(EatWhatYouKill.java:129)
        at org.eclipse.jetty.util.thread.ReservedThreadExecutor$ReservedThread.run(ReservedThreadExecutor.java:375)
        at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:806)
        at org.eclipse.jetty.util.thread.QueuedThreadPool$Runner.run(QueuedThreadPool.java:938)
        at java.lang.Thread.run(java.base@11.0.5/Thread.java:834)

   Locked ownable synchronizers:
        - None
End Run 7
Run 8
"qtp1722907060-12256" #12256 prio=5 os_prio=0 cpu=29551952.44ms elapsed=31065.72s allocated=127834G defined_classes=3 tid=0x00007f6644c4a000 nid=0x60d9 runnable  [0x00007f657b6f4000]
   java.lang.Thread.State: RUNNABLE
        at java.io.InputStream.read(java.base@11.0.5/InputStream.java:205)
        at org.projectodd.sockjs.servlet.SockJsServletRequest.onDataAvailable(SockJsServletRequest.java:93)
        at org.eclipse.jetty.server.HttpInput.run(HttpInput.java:907)
        at org.eclipse.jetty.server.handler.ContextHandler.handle(ContextHandler.java:1448)
        at org.eclipse.jetty.server.HttpChannel.handle(HttpChannel.java:468)
        at org.eclipse.jetty.server.HttpConnection.onFillable(HttpConnection.java:273)
        at org.eclipse.jetty.io.AbstractConnection$ReadCallback.succeeded(AbstractConnection.java:311)
        at org.eclipse.jetty.io.FillInterest.fillable(FillInterest.java:103)
        at org.eclipse.jetty.io.ChannelEndPoint$2.run(ChannelEndPoint.java:117)
        at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.runTask(EatWhatYouKill.java:336)
        at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.doProduce(EatWhatYouKill.java:313)
        at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.tryProduce(EatWhatYouKill.java:171)
        at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.run(EatWhatYouKill.java:129)
        at org.eclipse.jetty.util.thread.ReservedThreadExecutor$ReservedThread.run(ReservedThreadExecutor.java:375)
        at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:806)
        at org.eclipse.jetty.util.thread.QueuedThreadPool$Runner.run(QueuedThreadPool.java:938)
        at java.lang.Thread.run(java.base@11.0.5/Thread.java:834)

   Locked ownable synchronizers:
        - None
End Run 8
Run 9
"qtp1722907060-12256" #12256 prio=5 os_prio=0 cpu=29562001.64ms elapsed=31076.53s allocated=127877G defined_classes=3 tid=0x00007f6644c4a000 nid=0x60d9 runnable  [0x00007f657b6f4000]
   java.lang.Thread.State: RUNNABLE
        at java.io.InputStream.read(java.base@11.0.5/InputStream.java:205)
        at org.projectodd.sockjs.servlet.SockJsServletRequest.onDataAvailable(SockJsServletRequest.java:93)
        at org.eclipse.jetty.server.HttpInput.run(HttpInput.java:907)
        at org.eclipse.jetty.server.handler.ContextHandler.handle(ContextHandler.java:1448)
        at org.eclipse.jetty.server.HttpChannel.handle(HttpChannel.java:468)
        at org.eclipse.jetty.server.HttpConnection.onFillable(HttpConnection.java:273)
        at org.eclipse.jetty.io.AbstractConnection$ReadCallback.succeeded(AbstractConnection.java:311)
        at org.eclipse.jetty.io.FillInterest.fillable(FillInterest.java:103)
        at org.eclipse.jetty.io.ChannelEndPoint$2.run(ChannelEndPoint.java:117)
        at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.runTask(EatWhatYouKill.java:336)
        at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.doProduce(EatWhatYouKill.java:313)
        at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.tryProduce(EatWhatYouKill.java:171)
        at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.run(EatWhatYouKill.java:129)
        at org.eclipse.jetty.util.thread.ReservedThreadExecutor$ReservedThread.run(ReservedThreadExecutor.java:375)
        at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:806)
        at org.eclipse.jetty.util.thread.QueuedThreadPool$Runner.run(QueuedThreadPool.java:938)
        at java.lang.Thread.run(java.base@11.0.5/Thread.java:834)

   Locked ownable synchronizers:
        - None
End Run 9
Run 10
"qtp1722907060-12256" #12256 prio=5 os_prio=0 cpu=29572152.09ms elapsed=31087.38s allocated=127921G defined_classes=3 tid=0x00007f6644c4a000 nid=0x60d9 runnable  [0x00007f657b6f4000]
   java.lang.Thread.State: RUNNABLE
        at org.projectodd.sockjs.servlet.SockJsServletRequest.onDataAvailable(SockJsServletRequest.java:103)
        at org.eclipse.jetty.server.HttpInput.run(HttpInput.java:907)
        at org.eclipse.jetty.server.handler.ContextHandler.handle(ContextHandler.java:1448)
        at org.eclipse.jetty.server.HttpChannel.handle(HttpChannel.java:468)
        at org.eclipse.jetty.server.HttpConnection.onFillable(HttpConnection.java:273)
        at org.eclipse.jetty.io.AbstractConnection$ReadCallback.succeeded(AbstractConnection.java:311)
        at org.eclipse.jetty.io.FillInterest.fillable(FillInterest.java:103)
        at org.eclipse.jetty.io.ChannelEndPoint$2.run(ChannelEndPoint.java:117)
        at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.runTask(EatWhatYouKill.java:336)
        at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.doProduce(EatWhatYouKill.java:313)
        at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.tryProduce(EatWhatYouKill.java:171)
        at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.run(EatWhatYouKill.java:129)
        at org.eclipse.jetty.util.thread.ReservedThreadExecutor$ReservedThread.run(ReservedThreadExecutor.java:375)
        at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:806)
        at org.eclipse.jetty.util.thread.QueuedThreadPool$Runner.run(QueuedThreadPool.java:938)
        at java.lang.Thread.run(java.base@11.0.5/Thread.java:834)

   Locked ownable synchronizers:
        - None
End Run 10

@joakime
Copy link
Contributor

joakime commented Aug 14, 2020

The code at https://github.com/projectodd/sockjs-servlet/blob/master/src/main/java/org/projectodd/sockjs/servlet/SockJsServletRequest.java#L89-L104

... has a few bugs with how it's using Servlet Async I/O.
And one of them causes an infinite loop.

Servlet Async I/O has many gotchas, and your code for Async I/O read definitely has a few.

Read this https://www.slideshare.net/SimoneBordet/servlet-31-async-io (read is covered starting at slide 42)
Or watch his talk about it ...

@joakime joakime added Third Party Issues with third party libraries or projects and removed More Info Required labels Aug 14, 2020
@joakime joakime changed the title Hung Websocket Threads Slowly Monopolize CPU Improper use of Servlet InputStream Async I/O results in 100% CPU Aug 14, 2020
@jwalker-highspot
Copy link
Author

jwalker-highspot commented Aug 14, 2020

@joakime

Thanks for the quick and thorough response!

We will look at patching sockjs-servlet or moving to a different sockjs implementation.

@janbartel
Copy link
Contributor

Closing this issue, as it seems it's been addressed.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
Third Party Issues with third party libraries or projects
Projects
None yet
Development

No branches or pull requests

3 participants