High CPU on Jetty Websocket thread

[jbfru45]

Jetty version
9.4.25.v20191220

Java version
OpenJDK 11.0.3

OS type/version
Amazon Linux 2

Description
One of our Spring websocket servers in production reported 100% CPU usage (one core on a 4 core machine). The instance had been running for several days. The CPU spike occurred instantly and remained until the instance was terminated.

top -H output showed a jetty server thread using 100% CPU. Here is the jstack output for that thread:

jetty-server-2892" #2892 prio=5 os_prio=0 cpu=5735370.42ms elapsed=5936.68s tid=0x00007fa543a42800 nid=0x17e9 runnable  [0x00007fa55c36b000]
   java.lang.Thread.State: RUNNABLE
	at org.eclipse.jetty.websocket.common.io.AbstractWebSocketConnection.onFillable(AbstractWebSocketConnection.java:451)
	at org.eclipse.jetty.websocket.common.io.AbstractWebSocketConnection.onFillable(AbstractWebSocketConnection.java:441)
	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.ssl.SslConnection$DecryptedEndPoint.onFillable(SslConnection.java:543)
	at org.eclipse.jetty.io.ssl.SslConnection.onFillable(SslConnection.java:398)
	at org.eclipse.jetty.io.ssl.SslConnection$2.succeeded(SslConnection.java:161)
	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:388)
	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([email protected]/Thread.java:834)

Please let me know if you need any more information.

[lachlan-roberts]

@jbfru45 there is not quite enough information to know whats happening.

Could you get multiple jstack traces to help figure out what the thread is doing?
After doing that it would also be helpful if you could enable jetty debug logging to get some logs to help identify exactly why this is happening.

[jbfru45]

I ran jstack a dozen times and it was always in the method above, so it seems like it was stuck looping in that method. I will grab debug jetty logs the next time it happens which seems to be about once a week for us.

[jbfru45]

We had this reproduce in production again this morning. I grabbed multiple jstacks and every one was the same as above. I turned logs for the AbstractWebSocketConnection class to DEBUG for a couple minutes, and it traced these 2 messages several million times on the thread that was spinning:

"ReadState Action: DISCARD"

"Discarded buffer - DirectByteBuffer@5a06d4ef[p=0,l=17408,c=17408,r=17408]={<<<\\xC1\\xAb\\xDf\\xB61\\x96}(\ \\xBb\\xD2\\xFb\\x1c\\x1a\\x8d\\xFa\\x1c\\xE3\\x12\\xA5|\\x16\\x1a2\\xA0...\\x00\\x00\\x00\\x00\\x00\\x00\\x00\\x00\\x00\\x00\\x00\\x00\\x00\\x00\\x00\\x00\\x00\\x00\\x00\\x00\\x00\\x00\\x00>>>}"

The discarded buffer is the exact same in every message. If you still need other logs at debug, please let me know exactly which packages/classes you need as I cannot turn all logging to debug in production. We found that was too much load in our scale test environment.

[lachlan-roberts]

@jbfru45 Thanks for the extra info, I understand what is happening now.
I should be able to get a fix for this into the 9.4.27 release which should be coming soon.

[lachlan-roberts]

@jbfru45 thanks for reporting this. The fix from #4555 has been merged into the 9.4.x branch, and there should be a 9.4.27 release sometime next week.

[satyagv557]

We are still seeing the high CPU issue with 9.4.27,
we are using Jenkins 2.225 in Mac OS Mojave 10.14.6

Hundred's of Jetty (winstone) threads are filing up not getting closed with the method sun.nio.ch.FileDispatcherImpl.preClose0(Native Method)

Jetty (winstone)-66537
sun.nio.ch.FileDispatcherImpl.preClose0(Native Method)
sun.nio.ch.SocketDispatcher.preClose(SocketDispatcher.java:59)
sun.nio.ch.SocketChannelImpl.implCloseSelectableChannel(SocketChannelImpl.java:838)
java.nio.channels.spi.AbstractSelectableChannel.implCloseChannel(AbstractSelectableChannel.java:234)
java.nio.channels.spi.AbstractInterruptibleChannel.close(AbstractInterruptibleChannel.java:115)
org.eclipse.jetty.io.ChannelEndPoint.doClose(ChannelEndPoint.java:197)
org.eclipse.jetty.io.AbstractEndPoint.doOnClose(AbstractEndPoint.java:220)
org.eclipse.jetty.io.AbstractEndPoint.close(AbstractEndPoint.java:192)
org.eclipse.jetty.io.AbstractEndPoint.close(AbstractEndPoint.java:175)
org.eclipse.jetty.io.ssl.SslConnection$DecryptedEndPoint.doClose(SslConnection.java:1366)
org.eclipse.jetty.io.AbstractEndPoint.doOnClose(AbstractEndPoint.java:220)
org.eclipse.jetty.io.AbstractEndPoint.close(AbstractEndPoint.java:192)
org.eclipse.jetty.io.AbstractEndPoint.close(AbstractEndPoint.java:175)
org.eclipse.jetty.io.AbstractConnection.close(AbstractConnection.java:254)
org.eclipse.jetty.server.HttpConnection.onFillable(HttpConnection.java:258)
org.eclipse.jetty.io.AbstractConnection$ReadCallback.succeeded(AbstractConnection.java:311)
org.eclipse.jetty.io.FillInterest.fillable(FillInterest.java:103)
org.eclipse.jetty.io.ssl.SslConnection$DecryptedEndPoint.onFillable(SslConnection.java:543)
org.eclipse.jetty.io.ssl.SslConnection.onFillable(SslConnection.java:398)
org.eclipse.jetty.io.ssl.SslConnection$2.succeeded(SslConnection.java:161)
org.eclipse.jetty.io.FillInterest.fillable(FillInterest.java:103)
org.eclipse.jetty.io.ChannelEndPoint$2.run(ChannelEndPoint.java:117)
org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.runTask(EatWhatYouKill.java:336)
org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.doProduce(EatWhatYouKill.java:313)
org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.tryProduce(EatWhatYouKill.java:171)
org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.run(EatWhatYouKill.java:129)
org.eclipse.jetty.util.thread.ReservedThreadExecutor$ReservedThread.run(ReservedThreadExecutor.java:375)
org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:806)
org.eclipse.jetty.util.thread.QueuedThreadPool$Runner.run(QueuedThreadPool.java:938)

[satyagv557]

When normal state we are seeing below for winstone thread

Jetty (winstone)-14
sun.misc.Unsafe.park(Native Method)
java.util.concurrent.locks.LockSupport.parkNanos(LockSupport.java:215)
java.util.concurrent.SynchronousQueue$TransferStack.awaitFulfill(SynchronousQueue.java:460)
java.util.concurrent.SynchronousQueue$TransferStack.transfer(SynchronousQueue.java:362)
java.util.concurrent.SynchronousQueue.poll(SynchronousQueue.java:941)
org.eclipse.jetty.util.thread.ReservedThreadExecutor$ReservedThread.reservedWait(ReservedThreadExecutor.java:304)
org.eclipse.jetty.util.thread.ReservedThreadExecutor$ReservedThread.run(ReservedThreadExecutor.java:366)
org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:806)
org.eclipse.jetty.util.thread.QueuedThreadPool$Runner.run(QueuedThreadPool.java:938)
java.lang.Thread.run(Thread.java:748)

[lachlan-roberts]

@satyagv557 this stacktrace has nothing to do with websocket, I would suggest opening a new issue if you are having a problem.

[satyagv557]

Opened #4717, let me know any information needed.