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

100% CPU usage in Selector using Jetty on Windows #2205

Closed
joemokos opened this issue Feb 20, 2018 · 102 comments
Closed

100% CPU usage in Selector using Jetty on Windows #2205

joemokos opened this issue Feb 20, 2018 · 102 comments
Labels
JVM Issue Issue present in a JVM Runtime Microsoft Windows For issues unique to Microsoft Windows Stale For auto-closed stale issues and pull requests

Comments

@joemokos
Copy link

joemokos commented Feb 20, 2018 •
edited by joakime

I am running embedded jetty 9.4.8.v20171121. My app runs fine for a period of time, usually about 2 hours, with very little CPU usage. Then, 2 threads, both named WebSocketContainer@1861866092-, start to consume 100% CPU when idle. A stack trace at this point yields the following:

 Thread id32:WebSocketContainer@1861866092-32     RUNNABLE     55.84375s
 sun.nio.ch.WindowsSelectorImpl$SubSelector.poll0(Native Method)
 sun.nio.ch.WindowsSelectorImpl$SubSelector.poll(WindowsSelectorImpl.java:296)
 sun.nio.ch.WindowsSelectorImpl$SubSelector.access$400(WindowsSelectorImpl.java:278)
 sun.nio.ch.WindowsSelectorImpl.doSelect(WindowsSelectorImpl.java:159)
 sun.nio.ch.SelectorImpl.lockAndDoSelect(SelectorImpl.java:86)
 sun.nio.ch.SelectorImpl.select(SelectorImpl.java:97)
 sun.nio.ch.SelectorImpl.select(SelectorImpl.java:101)
 org.eclipse.jetty.io.ManagedSelector$SelectorProducer.select(ManagedSelector.java:375)
 org.eclipse.jetty.io.ManagedSelector$SelectorProducer.produce(ManagedSelector.java:304)
 org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.doProduce(EatWhatYouKill.java:179)
 org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.produce(EatWhatYouKill.java:140)
 org.eclipse.jetty.io.ManagedSelector$$Lambda$23/663060787.run(Unknown Source)
 org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:708)
 org.eclipse.jetty.util.thread.QueuedThreadPool$2.run(QueuedThreadPool.java:626)
 java.lang.Thread.run(Thread.java:748)

This seems very similar to: #1446

but I am running a newer version of jetty.

I can only get this problem to occur on servers running Windows 2012R2. I am running java jdk1.8.0_162 although I have also seen the problem with jdk1.8.0_131.

Does anyone have any ideas what could be causing this?
@joakime
Copy link
Contributor

joakime commented Feb 23, 2018

This seems to reference Issue #1446 (using github syntax to trigger reference link)

@joakime joakime added the Microsoft Windows For issues unique to Microsoft Windows label Feb 23, 2018
@joemokos
Copy link
Author

Agreed, it does seem to reference #1446. However #1446 says problem seemed to be corrected by jetty 9.4.6.v20170531. I have been running with 9.4.7.v20170914 and recently upgraded to 9.4.8.v20171121 in hopes that in would correct the problem. But it does not. So if the problem was corrected in 9.4.6, it looks like it returned in 9.4.7 and 9.4.8

@sbordet sbordet mentioned this issue Feb 23, 2018
Closed
@joemokos
Copy link
Author

I was able to get some debug logging turned on when the problem occurred. It looks like the same pattern is repeated constantly. Here's a snippet. Full logs are also available if you need them:

03/14/2018 18:04:58.782 DEBUG jetty WebSocketContainer@1018635868-36: Selector sun.nio.ch.WindowsSelectorImpl@142a7d96 woken up from select, 0/0 selected
03/14/2018 18:04:58.829 DEBUG jetty WebSocketContainer@1018635868-36: Selector sun.nio.ch.WindowsSelectorImpl@142a7d96 processing 0 keys, 0 actions
03/14/2018 18:04:58.829 DEBUG jetty WebSocketContainer@1018635868-36: action=null wakeup=false
03/14/2018 18:04:58.829 DEBUG jetty WebSocketContainer@1018635868-36: Selector sun.nio.ch.WindowsSelectorImpl@142a7d96 waiting on select
03/14/2018 18:04:58.782 DEBUG jetty WebSocketContainer@1018635868-31: Selector sun.nio.ch.WindowsSelectorImpl@4193294a woken up from select, 0/0 selected
03/14/2018 18:04:58.829 DEBUG jetty WebSocketContainer@1018635868-31: Selector sun.nio.ch.WindowsSelectorImpl@4193294a processing 0 keys, 0 actions
03/14/2018 18:04:58.829 DEBUG jetty WebSocketContainer@1018635868-31: action=null wakeup=false
03/14/2018 18:04:58.829 DEBUG jetty WebSocketContainer@1018635868-31: Selector sun.nio.ch.WindowsSelectorImpl@4193294a waiting on select
03/14/2018 18:04:58.829 DEBUG jetty WebSocketContainer@1018635868-36: Selector sun.nio.ch.WindowsSelectorImpl@142a7d96 woken up from select, 0/0 selected
03/14/2018 18:04:58.829 DEBUG jetty WebSocketContainer@1018635868-36: Selector sun.nio.ch.WindowsSelectorImpl@142a7d96 processing 0 keys, 0 actions
03/14/2018 18:04:58.829 DEBUG jetty WebSocketContainer@1018635868-36: action=null wakeup=false
03/14/2018 18:04:58.829 DEBUG jetty WebSocketContainer@1018635868-36: Selector sun.nio.ch.WindowsSelectorImpl@142a7d96 waiting on select
03/14/2018 18:04:58.829 DEBUG jetty WebSocketContainer@1018635868-76: action=null wakeup=false
03/14/2018 18:04:58.829 DEBUG jetty WebSocketContainer@1018635868-76: Selector sun.nio.ch.WindowsSelectorImpl@38021066 waiting on select
03/14/2018 18:04:58.829 DEBUG jetty WebSocketContainer@1018635868-76: Selector sun.nio.ch.WindowsSelectorImpl@38021066 woken up from select, 0/0 selected
03/14/2018 18:04:58.829 DEBUG jetty WebSocketContainer@1018635868-76: Selector sun.nio.ch.WindowsSelectorImpl@38021066 processing 0 keys, 0 actions
03/14/2018 18:04:58.829 DEBUG jetty WebSocketContainer@1018635868-76: action=null wakeup=false
03/14/2018 18:04:58.829 DEBUG jetty WebSocketContainer@1018635868-76: Selector sun.nio.ch.WindowsSelectorImpl@38021066 waiting on select
03/14/2018 18:04:58.829 DEBUG jetty WebSocketContainer@1018635868-76: Selector sun.nio.ch.WindowsSelectorImpl@38021066 woken up from select, 0/0 selected
03/14/2018 18:04:58.829 DEBUG jetty WebSocketContainer@1018635868-32: Selector sun.nio.ch.WindowsSelectorImpl@3ae48017 woken up from select, 0/0 selected
03/14/2018 18:04:58.829 DEBUG jetty WebSocketContainer@1018635868-32: Selector sun.nio.ch.WindowsSelectorImpl@3ae48017 processing 0 keys, 0 actions
03/14/2018 18:04:58.829 DEBUG jetty WebSocketContainer@1018635868-32: action=null wakeup=false
03/14/2018 18:04:58.829 DEBUG jetty WebSocketContainer@1018635868-32: Selector sun.nio.ch.WindowsSelectorImpl@3ae48017 waiting on select
03/14/2018 18:04:58.829 DEBUG jetty WebSocketContainer@1018635868-53: Selector sun.nio.ch.WindowsSelectorImpl@72f12611 woken up from select, 0/0 selected
03/14/2018 18:04:58.829 DEBUG jetty WebSocketContainer@1018635868-53: Selector sun.nio.ch.WindowsSelectorImpl@72f12611 processing 0 keys, 0 actions
03/14/2018 18:04:58.829 DEBUG jetty WebSocketContainer@1018635868-53: action=null wakeup=false
03/14/2018 18:04:58.829 DEBUG jetty WebSocketContainer@1018635868-53: Selector sun.nio.ch.WindowsSelectorImpl@72f12611 waiting on select
03/14/2018 18:04:58.829 DEBUG jetty WebSocketContainer@1018635868-32: Selector sun.nio.ch.WindowsSelectorImpl@3ae48017 woken up from select, 0/0 selected
03/14/2018 18:04:58.829 DEBUG jetty WebSocketContainer@1018635868-32: Selector sun.nio.ch.WindowsSelectorImpl@3ae48017 processing 0 keys, 0 actions
03/14/2018 18:04:58.829 DEBUG jetty WebSocketContainer@1018635868-32: action=null wakeup=false
03/14/2018 18:04:58.829 DEBUG jetty WebSocketContainer@1018635868-32: Selector sun.nio.ch.WindowsSelectorImpl@3ae48017 waiting on select
03/14/2018 18:04:58.829 DEBUG jetty WebSocketContainer@1018635868-76: Selector sun.nio.ch.WindowsSelectorImpl@38021066 processing 0 keys, 0 actions
03/14/2018 18:04:58.829 DEBUG jetty WebSocketContainer@1018635868-76: action=null wakeup=false
03/14/2018 18:04:58.829 DEBUG jetty WebSocketContainer@1018635868-36: Selector sun.nio.ch.WindowsSelectorImpl@142a7d96 woken up from select, 0/0 selected
03/14/2018 18:04:58.829 DEBUG jetty WebSocketContainer@1018635868-36: Selector sun.nio.ch.WindowsSelectorImpl@142a7d96 processing 0 keys, 0 actions
03/14/2018 18:04:58.829 DEBUG jetty WebSocketContainer@1018635868-36: action=null wakeup=false
03/14/2018 18:04:58.829 DEBUG jetty WebSocketContainer@1018635868-36: Selector sun.nio.ch.WindowsSelectorImpl@142a7d96 waiting on select
03/14/2018 18:04:58.829 DEBUG jetty WebSocketContainer@1018635868-31: Selector sun.nio.ch.WindowsSelectorImpl@4193294a woken up from select, 0/0 selected
03/14/2018 18:04:58.829 DEBUG jetty WebSocketContainer@1018635868-31: Selector sun.nio.ch.WindowsSelectorImpl@4193294a processing 0 keys, 0 actions
03/14/2018 18:04:58.829 DEBUG jetty WebSocketContainer@1018635868-31: action=null wakeup=false
03/14/2018 18:04:58.829 DEBUG jetty WebSocketContainer@1018635868-31: Selector sun.nio.ch.WindowsSelectorImpl@4193294a waiting on select
03/14/2018 18:04:58.829 DEBUG jetty WebSocketContainer@1018635868-31: Selector sun.nio.ch.WindowsSelectorImpl@4193294a woken up from select, 0/0 selected
03/14/2018 18:04:58.829 DEBUG jetty WebSocketContainer@1018635868-31: Selector sun.nio.ch.WindowsSelectorImpl@4193294a processing 0 keys, 0 actions
03/14/2018 18:04:58.829 DEBUG jetty WebSocketContainer@1018635868-31: action=null wakeup=false

@joakime
Copy link
Contributor

joakime commented Mar 15, 2018

If you can build the jetty source, please try the current jetty-9.4.x (branch) HEAD. - commit 44546e5
Or, if you can be a little patient, we are currently staging a potential 9.4.9 release with a possible hack for a recently identified Windows NIO bug.

@joemokos
Copy link
Author

Thanks Joakim. I'll try to build the HEAD from source. Do you have an ETA on 9.4.9?

@joemokos
Copy link
Author

Is the fix you're referring to for bug #2335?

@joakime
Copy link
Contributor

joakime commented Mar 15, 2018

Yes, PR #2335 is the source of the fix.

The 9.4.9 staged release should be available on oss.sonatype.org in a few hours.

@joakime
Copy link
Contributor

joakime commented Mar 15, 2018

The Jetty 9.4.9 stage is available.

Note: this is not an official release, and only represents a potential release.
It will only be official once adequate testing has been performed and then promoted to general release.

https://github.com/eclipse/jetty.project/releases/tag/jetty-9.4.9.v20180315
Many many fixes, see above link for list.

Staging Repository: https://oss.sonatype.org/content/repositories/jetty-1370/

@joemokos
Copy link
Author

joemokos commented Mar 15, 2018 via email

@joemokos
Copy link
Author

Converted over to 9.4.9. Will have to send update to our customer to determine if the 100% CPU problem is fixed. We were never able to recreate in-house. Assuming this fixes the problem, do you have any idea when 9.4.9 will be GA?

@joakime
Copy link
Contributor

joakime commented Mar 21, 2018

Jetty 9.4.9.v20180320 has been released with a hack for the identified Windows JVM Selector NIO Bug.

@joakime joakime closed this as completed Mar 21, 2018
@joemokos
Copy link
Author

joemokos commented Apr 2, 2018

Finally got a chance to test 9.4.9 at client site and am still running into the same issue. Following is a snippet from the log that was taken while the 100% CPU was occurring:

03/30/2018 18:15:47.202 DEBUG jetty WebSocketContainer@1444944344-39: Selector sun.nio.ch.WindowsSelectorImpl@a0305fd woken up from select, 0/0 selected
03/30/2018 18:15:47.314 DEBUG jetty WebSocketContainer@1444944344-39: Selector sun.nio.ch.WindowsSelectorImpl@a0305fd processing 0 keys, 0 updates
03/30/2018 18:15:47.314 DEBUG jetty WebSocketContainer@1444944344-39: updateable 0
03/30/2018 18:15:47.314 DEBUG jetty WebSocketContainer@1444944344-39: updates 0
03/30/2018 18:15:47.314 DEBUG jetty WebSocketContainer@1444944344-39: Selector sun.nio.ch.WindowsSelectorImpl@a0305fd waiting on select
03/30/2018 18:15:47.202 DEBUG jetty WebSocketContainer@1444944344-36: Selector sun.nio.ch.WindowsSelectorImpl@d94c4f5 woken up from select, 0/0 selected
03/30/2018 18:15:47.315 DEBUG jetty WebSocketContainer@1444944344-36: Selector sun.nio.ch.WindowsSelectorImpl@d94c4f5 processing 0 keys, 0 updates
03/30/2018 18:15:47.315 DEBUG jetty WebSocketContainer@1444944344-36: updateable 0
03/30/2018 18:15:47.315 DEBUG jetty WebSocketContainer@1444944344-36: updates 0
03/30/2018 18:15:47.315 DEBUG jetty WebSocketContainer@1444944344-36: Selector sun.nio.ch.WindowsSelectorImpl@d94c4f5 waiting on select
03/30/2018 18:15:47.314 DEBUG jetty WebSocketContainer@1444944344-39: Selector sun.nio.ch.WindowsSelectorImpl@a0305fd woken up from select, 0/0 selected
03/30/2018 18:15:47.315 DEBUG jetty WebSocketContainer@1444944344-39: Selector sun.nio.ch.WindowsSelectorImpl@a0305fd processing 0 keys, 0 updates
03/30/2018 18:15:47.315 DEBUG jetty WebSocketContainer@1444944344-39: updateable 0
03/30/2018 18:15:47.315 DEBUG jetty WebSocketContainer@1444944344-39: updates 0
03/30/2018 18:15:47.315 DEBUG jetty WebSocketContainer@1444944344-39: Selector sun.nio.ch.WindowsSelectorImpl@a0305fd waiting on select
03/30/2018 18:15:47.314 DEBUG jetty WebSocketContainer@1444944344-37: updateable 0
03/30/2018 18:15:47.315 DEBUG jetty WebSocketContainer@1444944344-37: updates 0
03/30/2018 18:15:47.315 DEBUG jetty WebSocketContainer@1444944344-37: Selector sun.nio.ch.WindowsSelectorImpl@3b6ce69c waiting on select
03/30/2018 18:15:47.203 DEBUG jetty WebSocketContainer@1444944344-41: Selector sun.nio.ch.WindowsSelectorImpl@3c509ad3 woken up from select, 0/0 selected
03/30/2018 18:15:47.315 DEBUG jetty WebSocketContainer@1444944344-41: Selector sun.nio.ch.WindowsSelectorImpl@3c509ad3 processing 0 keys, 0 updates
03/30/2018 18:15:47.315 DEBUG jetty WebSocketContainer@1444944344-41: updateable 0
03/30/2018 18:15:47.316 DEBUG jetty WebSocketContainer@1444944344-41: updates 0
03/30/2018 18:15:47.316 DEBUG jetty WebSocketContainer@1444944344-41: Selector sun.nio.ch.WindowsSelectorImpl@3c509ad3 waiting on select
03/30/2018 18:15:47.315 DEBUG jetty WebSocketContainer@1444944344-37: Selector sun.nio.ch.WindowsSelectorImpl@3b6ce69c woken up from select, 0/0 selected
03/30/2018 18:15:47.316 DEBUG jetty WebSocketContainer@1444944344-37: Selector sun.nio.ch.WindowsSelectorImpl@3b6ce69c processing 0 keys, 0 updates
03/30/2018 18:15:47.316 DEBUG jetty WebSocketContainer@1444944344-37: updateable 0
03/30/2018 18:15:47.316 DEBUG jetty WebSocketContainer@1444944344-37: updates 0
03/30/2018 18:15:47.316 DEBUG jetty WebSocketContainer@1444944344-37: Selector sun.nio.ch.WindowsSelectorImpl@3b6ce69c waiting on select
03/30/2018 18:15:47.315 DEBUG jetty WebSocketContainer@1444944344-39: Selector sun.nio.ch.WindowsSelectorImpl@a0305fd woken up from select, 0/0 selected
03/30/2018 18:15:47.316 DEBUG jetty WebSocketContainer@1444944344-39: Selector sun.nio.ch.WindowsSelectorImpl@a0305fd processing 0 keys, 0 updates
03/30/2018 18:15:47.316 DEBUG jetty WebSocketContainer@1444944344-39: updateable 0
03/30/2018 18:15:47.316 DEBUG jetty WebSocketContainer@1444944344-39: updates 0
03/30/2018 18:15:47.316 DEBUG jetty WebSocketContainer@1444944344-39: Selector sun.nio.ch.WindowsSelectorImpl@a0305fd waiting on select
03/30/2018 18:15:47.315 DEBUG jetty WebSocketContainer@1444944344-36: Selector sun.nio.ch.WindowsSelectorImpl@d94c4f5 woken up from select, 0/0 selected
03/30/2018 18:15:47.316 DEBUG jetty WebSocketContainer@1444944344-36: Selector sun.nio.ch.WindowsSelectorImpl@d94c4f5 processing 0 keys, 0 updates
03/30/2018 18:15:47.316 DEBUG jetty WebSocketContainer@1444944344-36: updateable 0
03/30/2018 18:15:47.316 DEBUG jetty WebSocketContainer@1444944344-36: updates 0
03/30/2018 18:15:47.316 DEBUG jetty WebSocketContainer@1444944344-36: Selector sun.nio.ch.WindowsSelectorImpl@d94c4f5 waiting on select
03/30/2018 18:15:47.316 DEBUG jetty WebSocketContainer@1444944344-39: Selector sun.nio.ch.WindowsSelectorImpl@a0305fd woken up from select, 0/0 selected
03/30/2018 18:15:47.316 DEBUG jetty WebSocketContainer@1444944344-39: Selector sun.nio.ch.WindowsSelectorImpl@a0305fd processing 0 keys, 0 updates
03/30/2018 18:15:47.317 DEBUG jetty WebSocketContainer@1444944344-39: updateable 0
03/30/2018 18:15:47.317 DEBUG jetty WebSocketContainer@1444944344-39: updates 0
03/30/2018 18:15:47.317 DEBUG jetty WebSocketContainer@1444944344-39: Selector sun.nio.ch.WindowsSelectorImpl@a0305fd waiting on select
03/30/2018 18:15:47.316 DEBUG jetty WebSocketContainer@1444944344-37: Selector sun.nio.ch.WindowsSelectorImpl@3b6ce69c woken up from select, 0/0 selected
03/30/2018 18:15:47.317 DEBUG jetty WebSocketContainer@1444944344-37: Selector sun.nio.ch.WindowsSelectorImpl@3b6ce69c processing 0 keys, 0 updates
03/30/2018 18:15:47.317 DEBUG jetty WebSocketContainer@1444944344-37: updateable 0
03/30/2018 18:15:47.317 DEBUG jetty WebSocketContainer@1444944344-37: updates 0
03/30/2018 18:15:47.316 DEBUG jetty WebSocketContainer@1444944344-41: Selector sun.nio.ch.WindowsSelectorImpl@3c509ad3 woken up from select, 0/0 selected
03/30/2018 18:15:47.317 DEBUG jetty WebSocketContainer@1444944344-41: Selector sun.nio.ch.WindowsSelectorImpl@3c509ad3 processing 0 keys, 0 updates
03/30/2018 18:15:47.317 DEBUG jetty WebSocketContainer@1444944344-41: updateable 0
03/30/2018 18:15:47.317 DEBUG jetty WebSocketContainer@1444944344-41: updates 0
03/30/2018

@joakime
Copy link
Contributor

joakime commented Apr 2, 2018

Do you have a testcase that can cause this?

@joemokos
Copy link
Author

joemokos commented Apr 2, 2018

Unfortunately, no. So far, I have not been able to recreate this in-house. I have only seen it at one of our customer's and only on Windows 2012 R2 machines.

@joakime
Copy link
Contributor

joakime commented Apr 2, 2018

What version of Java?

@joemokos
Copy link
Author

joemokos commented Apr 2, 2018

jdk1.8.0_162 currently but we also saw the problem with jdk1.8.0_131

@joakime joakime reopened this Apr 2, 2018
@gregw
Copy link
Contributor

gregw commented Apr 2, 2018

Here is that log sorted by thread:

03/30/2018 18:15:47.202 DEBUG jetty WebSocketContainer@1444944344-36: Selector sun.nio.ch.WindowsSelectorImpl@d94c4f5 woken up from select, 0/0 selected
03/30/2018 18:15:47.315 DEBUG jetty WebSocketContainer@1444944344-36: Selector sun.nio.ch.WindowsSelectorImpl@d94c4f5 processing 0 keys, 0 updates 
03/30/2018 18:15:47.315 DEBUG jetty WebSocketContainer@1444944344-36: Selector sun.nio.ch.WindowsSelectorImpl@d94c4f5 waiting on select
03/30/2018 18:15:47.315 DEBUG jetty WebSocketContainer@1444944344-36: Selector sun.nio.ch.WindowsSelectorImpl@d94c4f5 woken up from select, 0/0 selected
03/30/2018 18:15:47.315 DEBUG jetty WebSocketContainer@1444944344-36: updateable 0
03/30/2018 18:15:47.315 DEBUG jetty WebSocketContainer@1444944344-36: updates 0
03/30/2018 18:15:47.316 DEBUG jetty WebSocketContainer@1444944344-36: Selector sun.nio.ch.WindowsSelectorImpl@d94c4f5 processing 0 keys, 0 updates 
03/30/2018 18:15:47.316 DEBUG jetty WebSocketContainer@1444944344-36: Selector sun.nio.ch.WindowsSelectorImpl@d94c4f5 waiting on select
03/30/2018 18:15:47.316 DEBUG jetty WebSocketContainer@1444944344-36: updateable 0
03/30/2018 18:15:47.316 DEBUG jetty WebSocketContainer@1444944344-36: updates 0

03/30/2018 18:15:47.314 DEBUG jetty WebSocketContainer@1444944344-37: updateable 0
03/30/2018 18:15:47.315 DEBUG jetty WebSocketContainer@1444944344-37: Selector sun.nio.ch.WindowsSelectorImpl@3b6ce69c waiting on select
03/30/2018 18:15:47.315 DEBUG jetty WebSocketContainer@1444944344-37: Selector sun.nio.ch.WindowsSelectorImpl@3b6ce69c woken up from select, 0/0 selected
03/30/2018 18:15:47.315 DEBUG jetty WebSocketContainer@1444944344-37: updates 0
03/30/2018 18:15:47.316 DEBUG jetty WebSocketContainer@1444944344-37: Selector sun.nio.ch.WindowsSelectorImpl@3b6ce69c processing 0 keys, 0 updates 
03/30/2018 18:15:47.316 DEBUG jetty WebSocketContainer@1444944344-37: Selector sun.nio.ch.WindowsSelectorImpl@3b6ce69c waiting on select
03/30/2018 18:15:47.316 DEBUG jetty WebSocketContainer@1444944344-37: Selector sun.nio.ch.WindowsSelectorImpl@3b6ce69c woken up from select, 0/0 selected
03/30/2018 18:15:47.316 DEBUG jetty WebSocketContainer@1444944344-37: updateable 0
03/30/2018 18:15:47.316 DEBUG jetty WebSocketContainer@1444944344-37: updates 0
03/30/2018 18:15:47.317 DEBUG jetty WebSocketContainer@1444944344-37: Selector sun.nio.ch.WindowsSelectorImpl@3b6ce69c processing 0 keys, 0 updates 
03/30/2018 18:15:47.317 DEBUG jetty WebSocketContainer@1444944344-37: updateable 0
03/30/2018 18:15:47.317 DEBUG jetty WebSocketContainer@1444944344-37: updates 0

03/30/2018 18:15:47.202 DEBUG jetty WebSocketContainer@1444944344-39: Selector sun.nio.ch.WindowsSelectorImpl@a0305fd woken up from select, 0/0 selected
03/30/2018 18:15:47.314 DEBUG jetty WebSocketContainer@1444944344-39: Selector sun.nio.ch.WindowsSelectorImpl@a0305fd processing 0 keys, 0 updates 
03/30/2018 18:15:47.314 DEBUG jetty WebSocketContainer@1444944344-39: Selector sun.nio.ch.WindowsSelectorImpl@a0305fd waiting on select
03/30/2018 18:15:47.314 DEBUG jetty WebSocketContainer@1444944344-39: Selector sun.nio.ch.WindowsSelectorImpl@a0305fd woken up from select, 0/0 selected
03/30/2018 18:15:47.314 DEBUG jetty WebSocketContainer@1444944344-39: updateable 0
03/30/2018 18:15:47.314 DEBUG jetty WebSocketContainer@1444944344-39: updates 0
03/30/2018 18:15:47.315 DEBUG jetty WebSocketContainer@1444944344-39: Selector sun.nio.ch.WindowsSelectorImpl@a0305fd processing 0 keys, 0 updates 
03/30/2018 18:15:47.315 DEBUG jetty WebSocketContainer@1444944344-39: Selector sun.nio.ch.WindowsSelectorImpl@a0305fd waiting on select
03/30/2018 18:15:47.315 DEBUG jetty WebSocketContainer@1444944344-39: Selector sun.nio.ch.WindowsSelectorImpl@a0305fd woken up from select, 0/0 selected
03/30/2018 18:15:47.315 DEBUG jetty WebSocketContainer@1444944344-39: updateable 0
03/30/2018 18:15:47.315 DEBUG jetty WebSocketContainer@1444944344-39: updates 0
03/30/2018 18:15:47.316 DEBUG jetty WebSocketContainer@1444944344-39: Selector sun.nio.ch.WindowsSelectorImpl@a0305fd processing 0 keys, 0 updates 
03/30/2018 18:15:47.316 DEBUG jetty WebSocketContainer@1444944344-39: Selector sun.nio.ch.WindowsSelectorImpl@a0305fd processing 0 keys, 0 updates 
03/30/2018 18:15:47.316 DEBUG jetty WebSocketContainer@1444944344-39: Selector sun.nio.ch.WindowsSelectorImpl@a0305fd waiting on select
03/30/2018 18:15:47.316 DEBUG jetty WebSocketContainer@1444944344-39: Selector sun.nio.ch.WindowsSelectorImpl@a0305fd woken up from select, 0/0 selected
03/30/2018 18:15:47.316 DEBUG jetty WebSocketContainer@1444944344-39: updateable 0
03/30/2018 18:15:47.316 DEBUG jetty WebSocketContainer@1444944344-39: updates 0
03/30/2018 18:15:47.317 DEBUG jetty WebSocketContainer@1444944344-39: Selector sun.nio.ch.WindowsSelectorImpl@a0305fd waiting on select
03/30/2018 18:15:47.317 DEBUG jetty WebSocketContainer@1444944344-39: updateable 0
03/30/2018 18:15:47.317 DEBUG jetty WebSocketContainer@1444944344-39: updates 0

03/30/2018 18:15:47.203 DEBUG jetty WebSocketContainer@1444944344-41: Selector sun.nio.ch.WindowsSelectorImpl@3c509ad3 woken up from select, 0/0 selected
03/30/2018 18:15:47.315 DEBUG jetty WebSocketContainer@1444944344-41: Selector sun.nio.ch.WindowsSelectorImpl@3c509ad3 processing 0 keys, 0 updates 
03/30/2018 18:15:47.315 DEBUG jetty WebSocketContainer@1444944344-41: updateable 0
03/30/2018 18:15:47.316 DEBUG jetty WebSocketContainer@1444944344-41: Selector sun.nio.ch.WindowsSelectorImpl@3c509ad3 waiting on select
03/30/2018 18:15:47.316 DEBUG jetty WebSocketContainer@1444944344-41: Selector sun.nio.ch.WindowsSelectorImpl@3c509ad3 woken up from select, 0/0 selected
03/30/2018 18:15:47.316 DEBUG jetty WebSocketContainer@1444944344-41: updates 0
03/30/2018 18:15:47.317 DEBUG jetty WebSocketContainer@1444944344-41: Selector sun.nio.ch.WindowsSelectorImpl@3c509ad3 processing 0 keys, 0 updates 
03/30/2018 18:15:47.317 DEBUG jetty WebSocketContainer@1444944344-41: updateable 0
03/30/2018 18:15:47.317 DEBUG jetty WebSocketContainer@1444944344-41: updates 0

@gregw
Copy link
Contributor

gregw commented Apr 2, 2018

I cannot see how this is not a JVM bug. These are 4 idle selectors with each having no keys at all, so they should all definitely block in select until it is woken up. I guess conceivably we have a bug were we are waking up the selector when there is nothing to do?? If we gave you a version with extra instrumentation could you run that on your clients site to capture more info?

However, I'm really dubious we will be able to fix this in the main line of the project. We already have some code to work around windows bugs and I'll really loath to add more work arounds in such a core part of the code. In this case it looks like if there are zero keys then we'd need to wait on a separate mutex... but then we'd have a race, so we'd have to synchronize and we'd kill performance for the 99.999% of other users. At best I'm seeing a branch with a work around that you'd have to build/update yourself.

gregw added a commit that referenced this issue Apr 2, 2018
@gregw
extra debug for #2205
426fb95 
Signed-off-by: Greg Wilkins <gregw@webtide.com>
@joemokos
Copy link
Author

joemokos commented Apr 3, 2018

Hi Greg, I can't disagree with anything you're saying. Those selects should block until the socket(s) is readable, are interrupted or are woken via wakeup. Let me check with my client to see if we can run a version with extra instrumentation.

I don't know if this is important or not or just a coincidence, but this only happens on 3 servers (our app is running on many). They are running windows 2012 R2. And it always seems to happen 2 hours after our app starts and the websocket connection is made. This does not happen (or hasn't) on windows 2012 servers.

@joemokos
Copy link
Author

joemokos commented Apr 3, 2018

Hi Greg, I was looking at the log and I noticed threads 36, 37, 39 and 41 are idle and experiencing this problem. The log message generated by these threads says:

Selector sun.nio.ch.WindowsSelectorImpl@3b6ce69c woken up from select, 0/0 selected

The 0/0 shows the (# of keys in the selected keys set)/(# of keys in the key set). I understand why the # of keys in the selected set is 0 but shouldn't the # of keys in the key set be at least 1.

The only selector thread that is actually connected (42) seems to be functioning normally, ie "woken up from select, 1/1 selected".

Is this all normal behavior?

@sbordet
Copy link
Contributor

sbordet commented Apr 3, 2018

That is why we think it's a JVM bug. Having 0/0 and not blocking in select() is abnormal behavior.

@joemokos
Copy link
Author

joemokos commented Apr 3, 2018

Thanks for responding so quickly. Shouldn't the 2nd 0 be > 0. Does that mean the set of sockets we're interested in is empty? I wonder what the behavior is of select when the key set is empty. Would it block or return immediately?

@sbordet
Copy link
Contributor

sbordet commented Apr 3, 2018

Yes the second zero should be > 0, i.e. there are no sockets managed by that selector.
The selector should block in select() if there are no sockets - that is what happens when you start a server but have not yet incoming connections.

@joakime
Copy link
Contributor

joakime commented Apr 3, 2018 •
edited

Looks like the nightly snapshot deployment has the instrumentation that @gregw added in commit 426fb95

Jetty Snapshot Repository URL: https://oss.sonatype.org/content/repositories/jetty-snapshots/

Please use version 9.4.10-20180403.160317-6 and see if there's anything from the logs that could help.

@joemokos
Copy link
Author

joemokos commented Apr 3, 2018

Thanks Joakim. I'll get it deployed to my customer's site as soon as I get the go ahead.

@bhawani1978
Copy link

Hi @joakime,

Yes I can see "woken with none selected" in the debug logs. Its windows 2016 server. We have have similar installation at many customer sites but at this site only we see the issue.

If its infact a OS or network drivers issue, then let me know if have any pointer to pin point this or debug so can get a fix for this.

-Bhawani

@joakime
Copy link
Contributor

joakime commented Sep 28, 2020

I have no advice on upgrading your OS or network drivers.
That's well out of scope for this issue tracker.
You'll have to dig into that yourself.
Know that you can now test it yourself.
If you see "woken with none selected" that means you have a network implementation that is prone to waking up the application even when there is no network activity to operate against. This is the root cause of your 100% spin situation, and is not Java, JVM, or Jetty specific, it's a more fundamental issue on your machine.

@bhawani1978
Copy link

Thanks @joakmine

@diffractious-zz
Copy link

The root cause of which is something on your OS or your network drivers.
It's a bug that neither Jetty nor the JVM can work around.

Hi @joakime, I agree that it is an underlying problem with the OS, but there is a workaround that Jetty could do. Netty has functionality that, when it detects this spinning situation, will rebuild the selector. This is behind a system property, which Jetty could also do. See https://github.com/netty/netty/blob/3.9/src/main/java/org/jboss/netty/channel/socket/nio/AbstractNioSelector.java#L129.

@joakime
Copy link
Contributor

joakime commented Sep 28, 2020

@diffractious We've considered the Netty approach of rebuilding the selector several times, but you wind up losing all of the selector specific attachments when you do that.
There's an attempt to retrieve the keys from the old selector, but that just fails with either selector errors, or an empty key list.

That impacts all of the active connections attached to that selector.
Those impacted connections are essentially hosed, dead, and unable to progress.

We had rebuilding in the Jetty layer for spinning for a short while, but that impacted ALL other non-buggy environment usages far too harshly so it was removed.

@joakime
Copy link
Contributor

joakime commented Sep 29, 2020

@diffractious you can use a workaround ServerConnector to rebuild on spurious select 0.

See https://github.com/jetty-project/selector-hack

@diffractious-zz
Copy link

@joakime nice! Thank you!

@joakime
Copy link
Contributor

joakime commented Oct 2, 2020

One other update here.

We've received reports that running Jetty behind IIS and it's HttpPlatformHandler as a cause of this behavior/issue as well (apparently this setup uses some shortcuts / loopback network connector which triggers this bug on Windows).

@horizonzy horizonzy mentioned this issue Oct 15, 2020
Closed
@horizonzy
Copy link

maybe this is the reason. https://bugs.java.com/bugdatabase/view_bug.do?bug_id=6778476

@joakime
Copy link
Contributor

joakime commented Oct 15, 2020

maybe this is the reason. https://bugs.java.com/bugdatabase/view_bug.do?bug_id=6778476

I don't think a selector.select() in a hung state would result in extra CPU usage.

@horizonzy
Copy link

horizonzy commented Oct 15, 2020 •
edited

I have no advice on upgrading your OS or network drivers.
That's well out of scope for this issue tracker.
You'll have to dig into that yourself.
Know that you can now test it yourself.
If you see "woken with none selected" that means you have a network implementation that is prone to waking up the application even when there is no network activity to operate against. This is the root cause of your 100% spin situation, and is not Java, JVM, or Jetty specific, it's a more fundamental issue on your machine.

thanks, I got it😁

@horizonzy horizonzy mentioned this issue Oct 16, 2020
Closed
@horizonzy
Copy link

Another example came up recently for us, and should assist in reproducing this problem for anyone interested.

HttpDebugger looks to be an application that uses Windows Layered Service Provider or Windows Filtering Platform to do proxy-less network interception. From the LSP wikipedia page:

Corruption issues

A major issue with LSPs is that any bugs in the LSP can cause applications to break. For example, an LSP that returns the wrong number of bytes sent through an interface can cause applications to go into an infinite loop while waiting for the network stack to indicate that data has been sent.
Another major common issue with LSPs was that if they were to be removed or unregistered improperly or if the LSP was buggy, it would result in corruption of the Winsock catalog in the registry, and the entire TCP/IP stack would break and the computer could no longer access the network.

Perhaps unrelated, but 2 hours is the default value for HKEY_LOCAL_MACHINE\SYSTEM\CurrentControlSet\Services\Tcpip\Parameters\KeepAliveTime.

I find a quick way to reproduce it.
just uninstal httpdebugger when your nio program is running, nio bug occur immediately.
Now, oracle jdk team is tracing it. https://bugs.java.com/bugdatabase/view_bug.do?bug_id=JDK-8255627

@bhawani1978
Copy link

bhawani1978 commented Mar 4, 2021 •
edited by sbordet

@diffractious you can use a workaround ServerConnector to rebuild on spurious select 0.

See https://github.com/jetty-project/selector-hack

Hi @joakime , we tried the workaround, it seems it worked in our labs. But when in production, it started breaking.

[2021-03-04 06:05:04.585+0000] [DEBUG] [qtp352359770-16190] [org.eclipse.jetty.io.ManagedSelector] <##[{user=xxxxxx}]##> - Selector sun.nio.ch.WindowsSelectorImpl@5b1bf8a7 processing 0 keys, 1 updates
[2021-03-04 06:05:04.585+0000] [DEBUG] [qtp352359770-16190] [org.eclipse.jetty.io.ManagedSelector] <##[{user=xxxxxx}]##> - updateable 1
[2021-03-04 06:05:04.585+0000] [DEBUG] [qtp352359770-16190] [org.eclipse.jetty.io.ManagedSelector] <##[{user=xxxxxx}]##> - update org.eclipse.jetty.io.ChannelEndPoint$$Lambda$53/10032797@5b5b5da5
[2021-03-04 06:05:04.585+0000] [DEBUG] [qtp352359770-16419] [org.eclipse.jetty.util.thread.ReservedThreadExecutor] <##[{user=xxxxxx}]##> - ReservedThreadExecutor@31edaa7d{s=3/8,p=0}@27cade01 waiting
[2021-03-04 06:05:04.586+0000] [DEBUG] [qtp352359770-16190] [org.eclipse.jetty.io.ChannelEndPoint] <##[{user=xxxxxx}]##> - Key interests updated 0 -> 1 on SocketChannelEndPoint@2071aaaa{l=/127.0.0.1:29170,r=/127.0.0.1:50762,OPEN,fill=FI,flush=-,to=0/30000}{io=1/1,kio=1,kro=1}->HttpConnection@3d598344[p=HttpParser{s=START,0 of -1},g=HttpGenerator@514c9975{s=START}]=>HttpChannelOverHttp@7763d496{s=HttpChannelState@73b9c41d{s=IDLE rs=BLOCKING os=OPEN is=IDLE awp=false se=false i=true al=0},r=363602,c=false/false,a=IDLE,uri=null,age=0}
[2021-03-04 06:05:04.586+0000] [DEBUG] [qtp352359770-16190] [org.eclipse.jetty.io.ManagedSelector] <##[{user=xxxxxx}]##> - updates 0
[2021-03-04 06:05:04.586+0000] [DEBUG] [qtp352359770-16190] [org.eclipse.jetty.io.ManagedSelector] <##[{user=xxxxxx}]##> - Selector sun.nio.ch.WindowsSelectorImpl@5b1bf8a7 waiting with 2 keys
[2021-03-04 08:02:04.918+0000] [DEBUG] [qtp352359770-16729] [org.eclipse.jetty.util.thread.ReservedThreadExecutor] <##[{user=xxxxxx}]##> - ReservedThreadExecutor@31edaa7d{s=5/8,p=0}@629b0623 task=null
[2021-03-04 08:02:04.948+0000] [DEBUG] [qtp352359770-16729] [org.eclipse.jetty.util.thread.ReservedThreadExecutor] <##[{user=xxxxxx}]##> - ReservedThreadExecutor@31edaa7d{s=5/8,p=0}@629b0623 IDLE
[2021-03-04 08:02:04.948+0000] [DEBUG] [qtp352359770-16729] [org.eclipse.jetty.util.thread.ReservedThreadExecutor] <##[{user=xxxxxx}]##> - ReservedThreadExecutor@31edaa7d{s=4/8,p=0}@629b0623 Exited
[2021-03-04 08:02:04.948+0000] [DEBUG] [qtp352359770-16729] [org.eclipse.jetty.util.thread.QueuedThreadPool] <##[{user=xxxxxx}]##> - ran ReservedThreadExecutor@31edaa7d{s=4/8,p=0}@629b0623 in QueuedThreadPool[qtp352359770]@1500955a{STARTED,8<=9<=150,i=2,r=8,q=0}[ReservedThreadExecutor@31edaa7d{s=4/8,p=0}]
[2021-03-04 08:02:04.948+0000] [DEBUG] [qtp352359770-16729] [org.eclipse.jetty.util.thread.QueuedThreadPool] <##[{user=xxxxxx}]##> - shrinking QueuedThreadPool[qtp352359770]@1500955a{STARTED,8<=9<=150,i=3,r=8,q=0}[ReservedThreadExecutor@31edaa7d{s=4/8,p=0}]
[2021-03-04 08:02:04.948+0000] [DEBUG] [qtp352359770-16729] [org.eclipse.jetty.util.thread.QueuedThreadPool] <##[{user=xxxxxx}]##> - Thread[qtp352359770-16729,5,main] exited for QueuedThreadPool[qtp352359770]@1500955a{STARTED,8<=8<=150,i=2,r=8,q=0}[ReservedThreadExecutor@31edaa7d{s=4/8,p=0}]
[2021-03-04 08:02:14.268+0000] [DEBUG] [Connector-Scheduler-382db087-1] [org.eclipse.jetty.io.IdleTimeout] <##[{user=xxxxxx}]##> - SocketChannelEndPoint@19103f98{l=/127.0.0.1:29170,r=/127.0.0.1:63307,OSHUT,fill=FI,flush=-,to=30001/30000}{io=0/1,kio=0,kro=0}->HttpConnection@6b923e31[p=HttpParser{s=CLOSE,0 of -1},g=HttpGenerator@6555dd33{s=START}]=>HttpChannelOverHttp@616a5541{s=HttpChannelState@2468d708{s=IDLE rs=BLOCKING os=OPEN is=IDLE awp=false se=false i=true al=0},r=0,c=false/false,a=IDLE,uri=null,age=0} idle timeout check, elapsed: 30001 ms, remaining: -1 ms
[2021-03-04 08:02:14.268+0000] [DEBUG] [Connector-Scheduler-382db087-1] [org.eclipse.jetty.io.IdleTimeout] <##[{user=xxxxxx}]##> - SocketChannelEndPoint@19103f98{l=/127.0.0.1:29170,r=/127.0.0.1:63307,OSHUT,fill=FI,flush=-,to=30002/30000}{io=0/1,kio=0,kro=0}->HttpConnection@6b923e31[p=HttpParser{s=CLOSE,0 of -1},g=HttpGenerator@6555dd33{s=START}]=>HttpChannelOverHttp@616a5541{s=HttpChannelState@2468d708{s=IDLE rs=BLOCKING os=OPEN is=IDLE awp=false se=false i=true al=0},r=0,c=false/false,a=IDLE,uri=null,age=0} idle timeout expired
[2021-03-04 08:02:14.269+0000] [DEBUG] [Connector-Scheduler-382db087-1] [org.eclipse.jetty.io.FillInterest] <##[{user=xxxxxx}]##> - onFail FillInterest@5e710602{AC.ReadCB@6b923e31{HttpConnection@6b923e31::SocketChannelEndPoint@19103f98{l=/127.0.0.1:29170,r=/127.0.0.1:63307,OSHUT,fill=FI,flush=-,to=30002/30000}{io=0/1,kio=0,kro=0}->HttpConnection@6b923e31[p=HttpParser{s=CLOSE,0 of -1},g=HttpGenerator@6555dd33{s=START}]=>HttpChannelOverHttp@616a5541{s=HttpChannelState@2468d708{s=IDLE rs=BLOCKING os=OPEN is=IDLE awp=false se=false i=true al=0},r=0,c=false/false,a=IDLE,uri=null,age=0}}}
java.util.concurrent.TimeoutException: Idle timeout expired: 30001/30000 ms
    at org.eclipse.jetty.io.IdleTimeout.checkIdleTimeout(IdleTimeout.java:171)
    at org.eclipse.jetty.io.IdleTimeout.idleCheck(IdleTimeout.java:113)
    at java.util.concurrent.Executors$RunnableAdapter.call(Unknown Source)
    at java.util.concurrent.FutureTask.run(Unknown Source)
    at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$201(Unknown Source)
    at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(Unknown Source)
    at java.util.concurrent.ThreadPoolExecutor.runWorker(Unknown Source)
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(Unknown Source)
    at java.lang.Thread.run(Unknown Source)
[2021-03-04 08:02:14.269+0000] [DEBUG] [Connector-Scheduler-382db087-1] [org.eclipse.jetty.io.AbstractConnection] <##[{user=xxxxxx}]##> - HttpConnection@6b923e31::SocketChannelEndPoint@19103f98{l=/127.0.0.1:29170,r=/127.0.0.1:63307,OSHUT,fill=-,flush=-,to=30002/30000}{io=0/1,kio=0,kro=0}->HttpConnection@6b923e31[p=HttpParser{s=CLOSE,0 of -1},g=HttpGenerator@6555dd33{s=START}]=>HttpChannelOverHttp@616a5541{s=HttpChannelState@2468d708{s=IDLE rs=BLOCKING os=OPEN is=IDLE awp=false se=false i=true al=0},r=0,c=false/false,a=IDLE,uri=null,age=0} onFillInterestedFailed {}
[2021-03-04 08:02:14.269+0000] [DEBUG] [Connector-Scheduler-382db087-1] [org.eclipse.jetty.io.AbstractEndPoint] <##[{user=xxxxxx}]##> - close SocketChannelEndPoint@19103f98{l=/127.0.0.1:29170,r=/127.0.0.1:63307,OSHUT,fill=-,flush=-,to=30002/30000}{io=0/1,kio=0,kro=0}->HttpConnection@6b923e31[p=HttpParser{s=CLOSE,0 of -1},g=HttpGenerator@6555dd33{s=START}]=>HttpChannelOverHttp@616a5541{s=HttpChannelState@2468d708{s=IDLE rs=BLOCKING os=OPEN is=IDLE awp=false se=false i=true al=0},r=0,c=false/false,a=IDLE,uri=null,age=0}
[2021-03-04 08:02:14.269+0000] [DEBUG] [Connector-Scheduler-382db087-1] [org.eclipse.jetty.io.AbstractEndPoint] <##[{user=xxxxxx}]##> - close(null) SocketChannelEndPoint@19103f98{l=/127.0.0.1:29170,r=/127.0.0.1:63307,OSHUT,fill=-,flush=-,to=30002/30000}{io=0/1,kio=0,kro=0}->HttpConnection@6b923e31[p=HttpParser{s=CLOSE,0 of -1},g=HttpGenerator@6555dd33{s=START}]=>HttpChannelOverHttp@616a5541{s=HttpChannelState@2468d708{s=IDLE rs=BLOCKING os=OPEN is=IDLE awp=false se=false i=true al=0},r=0,c=false/false,a=IDLE,uri=null,age=0}
[2021-03-04 08:02:14.269+0000] [DEBUG] [Connector-Scheduler-382db087-1] [org.eclipse.jetty.io.ChannelEndPoint] <##[{user=xxxxxx}]##> - doClose SocketChannelEndPoint@19103f98{l=/127.0.0.1:29170,r=/127.0.0.1:63307,CLOSED,fill=-,flush=-,to=30003/30000}{io=0/1,kio=0,kro=0}->HttpConnection@6b923e31[p=HttpParser{s=CLOSE,0 of -1},g=HttpGenerator@6555dd33{s=START}]=>HttpChannelOverHttp@616a5541{s=HttpChannelState@2468d708{s=IDLE rs=BLOCKING os=OPEN is=IDLE awp=false se=false i=true al=0},r=0,c=false/false,a=IDLE,uri=null,age=0}
[2021-03-04 08:02:14.269+0000] [DEBUG] [Connector-Scheduler-382db087-1] [org.eclipse.jetty.io.FillInterest] <##[{user=xxxxxx}]##> - onClose FillInterest@5e710602{null}
[2021-03-04 08:02:14.269+0000] [DEBUG] [Connector-Scheduler-382db087-1] [org.eclipse.jetty.io.ManagedSelector] <##[{user=xxxxxx}]##> - Wakeup WorkaroundManagedSelector@2a7ed1f{STOPPING} id=1 keys=1 selected=0 updates=4
[2021-03-04 08:02:14.269+0000] [DEBUG] [Connector-Scheduler-382db087-1] [org.eclipse.jetty.util.thread.QueuedThreadPool] <##[{user=xxxxxx}]##> - queue org.eclipse.jetty.io.ManagedSelector$DestroyEndPoint@1506f4ba startThread=0
[2021-03-04 08:02:14.269+0000] [DEBUG] [qtp352359770-16726] [org.eclipse.jetty.util.thread.QueuedThreadPool] <##[{user=xxxxxx}]##> - run org.eclipse.jetty.io.ManagedSelector$DestroyEndPoint@1506f4ba in QueuedThreadPool[qtp352359770]@1500955a{STARTED,8<=8<=150,i=1,r=8,q=0}[ReservedThreadExecutor@31edaa7d{s=4/8,p=0}]
[2021-03-04 08:02:14.269+0000] [DEBUG] [Connector-Scheduler-382db087-1] [org.eclipse.jetty.io.AbstractEndPoint] <##[{user=xxxxxx}]##> - Ignored idle endpoint SocketChannelEndPoint@19103f98{l=0.0.0.0/0.0.0.0:29170,r=/127.0.0.1:63307,CLOSED,fill=-,flush=-,to=30003/30000}{io=0/1,kio=-1,kro=-1}->HttpConnection@6b923e31[p=HttpParser{s=CLOSE,0 of -1},g=HttpGenerator@6555dd33{s=START}]=>HttpChannelOverHttp@616a5541{s=HttpChannelState@2468d708{s=IDLE rs=BLOCKING os=OPEN is=IDLE awp=false se=false i=true al=0},r=0,c=false/false,a=IDLE,uri=null,age=0}
[2021-03-04 08:02:14.269+0000] [DEBUG] [qtp352359770-16726] [org.eclipse.jetty.io.ManagedSelector] <##[{user=xxxxxx}]##> - Destroyed SocketChannelEndPoint@19103f98{l=0.0.0.0/0.0.0.0:29170,r=/127.0.0.1:63307,CLOSED,fill=-,flush=-,to=30003/30000}{io=0/1,kio=-1,kro=-1}->HttpConnection@6b923e31[p=HttpParser{s=CLOSE,0 of -1},g=HttpGenerator@6555dd33{s=START}]=>HttpChannelOverHttp@616a5541{s=HttpChannelState@2468d708{s=IDLE rs=BLOCKING os=OPEN is=IDLE awp=false se=false i=true al=0},r=0,c=false/false,a=IDLE,uri=null,age=0}
[2021-03-04 08:02:14.269+0000] [DEBUG] [qtp352359770-16726] [org.eclipse.jetty.io.AbstractConnection] <##[{user=xxxxxx}]##> - onClose HttpConnection@6b923e31::SocketChannelEndPoint@19103f98{l=0.0.0.0/0.0.0.0:29170,r=/127.0.0.1:63307,CLOSED,fill=-,flush=-,to=0/30000}{io=0/1,kio=-1,kro=-1}->HttpConnection@6b923e31[p=HttpParser{s=CLOSE,0 of -1},g=HttpGenerator@6555dd33{s=START}]=>HttpChannelOverHttp@616a5541{s=HttpChannelState@2468d708{s=IDLE rs=BLOCKING os=OPEN is=IDLE awp=false se=false i=true al=0},r=0,c=false/false,a=IDLE,uri=null,age=0}
[2021-03-04 08:02:14.269+0000] [DEBUG] [qtp352359770-16726] [org.eclipse.jetty.util.thread.QueuedThreadPool] <##[{user=xxxxxx}]##> - ran org.eclipse.jetty.io.ManagedSelector$DestroyEndPoint@1506f4ba in QueuedThreadPool[qtp352359770]@1500955a{STARTED,8<=8<=150,i=1,r=8,q=0}[ReservedThreadExecutor@31edaa7d{s=4/8,p=0}]
[2021-03-04 08:02:24.949+0000] [DEBUG] [qtp352359770-16535] [org.eclipse.jetty.util.thread.ReservedThreadExecutor] <##[{user=xxxxxx}]##> - ReservedThreadExecutor@31edaa7d{s=4/8,p=0}@a8ab953 task=null
[2021-03-04 08:02:24.949+0000] [DEBUG] [qtp352359770-16535] [org.eclipse.jetty.util.thread.ReservedThreadExecutor] <##[{user=xxxxxx}]##> - ReservedThreadExecutor@31edaa7d{s=4/8,p=0}@a8ab953 IDLE
[2021-03-04 08:02:24.949+0000] [DEBUG] [qtp352359770-16535] [org.eclipse.jetty.util.thread.ReservedThreadExecutor] <##[{user=xxxxxx}]##> - ReservedThreadExecutor@31edaa7d{s=3/8,p=0}@a8ab953 Exited
[2021-03-04 08:02:24.949+0000] [DEBUG] [qtp352359770-16535] [org.eclipse.jetty.util.thread.QueuedThreadPool] <##[{user=xxxxxx}]##> - ran ReservedThreadExecutor@31edaa7d{s=3/8,p=0}@a8ab953 in QueuedThreadPool[qtp352359770]@1500955a{STARTED,8<=8<=150,i=2,r=8,q=0}[ReservedThreadExecutor@31edaa7d{s=3/8,p=0}]
[2021-03-04 08:02:33.957+0000] [DEBUG] [qtp352359770-16190] [org.eclipse.jetty.util.thread.ReservedThreadExecutor] <##[{user=xxxxxx}]##> - ReservedThreadExecutor@31edaa7d{s=3/8,p=0}@3d5bee76 task=null
[2021-03-04 08:02:33.957+0000] [DEBUG] [qtp352359770-16190] [org.eclipse.jetty.util.thread.ReservedThreadExecutor] <##[{user=xxxxxx}]##> - ReservedThreadExecutor@31edaa7d{s=3/8,p=0}@3d5bee76 IDLE
[2021-03-04 08:02:33.957+0000] [DEBUG] [qtp352359770-16190] [org.eclipse.jetty.util.thread.ReservedThreadExecutor] <##[{user=xxxxxx}]##> - ReservedThreadExecutor@31edaa7d{s=2/8,p=0}@3d5bee76 Exited
[2021-03-04 08:02:33.957+0000] [DEBUG] [qtp352359770-16190] [org.eclipse.jetty.util.thread.QueuedThreadPool] <##[{user=xxxxxx}]##> - ran ReservedThreadExecutor@31edaa7d{s=2/8,p=0}@3d5bee76 in QueuedThreadPool[qtp352359770]@1500955a{STARTED,8<=8<=150,i=3,r=8,q=0}[ReservedThreadExecutor@31edaa7d{s=2/8,p=0}]

@sbordet
Copy link
Contributor

sbordet commented Mar 4, 2021 •
edited

@bhawani1978 I don't see any problem with your stack trace.
The select wakes up with 1 update.
There is no spinning and I doubt any high CPU usage given the logs show 10+ second pauses between log lines -- the server seems completely idle.

If you have 100% CPU, it's something else.

@bhawani1978
Copy link

@sbordet no high CPU but it just hangs and stops responding

@sbordet
Copy link
Contributor

sbordet commented Mar 4, 2021

@bhawani1978 if you don't have 100% CPU please open a new issue, as this issue is not related to your problem.

@bhawani1978
Copy link

@sbordet I thaught, this would be right place as this happening after applying workaround as provided by @joakime https://github.com/jetty-project/selector-hack if we remove this hack, we most probably will start getting old issue.

@joakime
Copy link
Contributor

joakime commented Mar 5, 2021

The hack just works around a hardware/driver/OS issue on your machine.
An issue that all Java programs that use NIO on that machine will encounter.
In other words, this issue is not Jetty specific.

The new issue you reported is something else that is unrelated to this issue.
It is something new.
And so far, we do not have enough details to even guess at the cause.
Please open a new issue.
Lets troubleshoot there.

@bhawani1978 bhawani1978 mentioned this issue Apr 20, 2021
Closed
@joakime joakime mentioned this issue Apr 27, 2021
Closed
@TheGoesen
Copy link

Hello,
I can join into the chorus of "jetty works everywhere, except for that one customer where it eats all cpu". I have two questions:

  1. Has someone successfully fieldtested the selector-hack branch, or is it more a theory-craft?
  2. Would a workaround be possible by providing a custom ServerConnector that uses blocking io and a few extra threads instead of selectors? Is such a class already available? To me personal that seems like a better workaround, especially since according to oracle selectors "scale horrible" prior to java 17 anyway. https://bugs.openjdk.java.net/browse/JDK-8266382

@joakime
Copy link
Contributor

joakime commented Aug 3, 2021

Hello,
I can join into the chorus of "jetty works everywhere, except for that one customer where it eats all cpu". I have two questions:

Try to gather as much information about their system.
Network hardware they have, Network drivers they have, any kind of network monitoring tools they have active on that server, any kind of "security" services that they have on that server (such as virus scanning, firewalls, etc)

It usually comes down to a few things:

  1. They are using network hardware that has a flaw/bug (replacing with new version of same hardware fixes this scenario)
  2. They are using a network driver that has a flaw/bug (using an up to date version fixes this for many users)
  3. They have some kind of security software running that is impacting their behavior negatively. (disabling the security software temporarily and it starts behaving, then you can point at that security software as the reason for the bad behavior)
  1. Has someone successfully fieldtested the selector-hack branch, or is it more a theory-craft?

There is not enough / adequate testing for that selector-hack branch.
It's such an incredibly rare scenario, we've personally never experienced it, nor have any of our commercial support clients.

  1. Would a workaround be possible by providing a custom ServerConnector that uses blocking io and a few extra threads instead of selectors? Is such a class already available? To me personal that seems like a better workaround,

ServerConnector is not responsible for how the connection is handled.

Jetty is 100% NIO based, there's no support for blocking I/O concepts, in order to accomplish this you would need to rewrite vast swathes of the IO and Threading layers across all of Jetty. Not a trivial task, and one we have no desire to do at this point in time.

especially since according to oracle selectors "scale horrible" prior to java 17 anyway. https://bugs.openjdk.java.net/browse/JDK-8266382

Be aware that Oracle is pushing their Loom thread model agenda with that comment.
Loom isn't a silver bullet anyway.

Note that we have single instances of Jetty handling over 200,000 active connections across a variety of protocols (http/1, http/2, websocket, etc) just fine, we start to hit network interface bandwidth limits way before we hit any kind of selector limits.

@sbordet
Copy link
Contributor

sbordet commented Aug 3, 2021

Note that we have single instances of Jetty handling over 200,000 active connections across a variety of protocols (http/1, http/2, websocket, etc) just fine

On Linux.

@joakime joakime mentioned this issue May 4, 2022
Merged
@github-actions
Copy link

github-actions bot commented Aug 4, 2022

This issue has been automatically marked as stale because it has been a
full year without activity. It will be closed if no further activity occurs.
Thank you for your contributions.

@github-actions github-actions bot added the Stale For auto-closed stale issues and pull requests label Aug 4, 2022
@github-actions
Copy link

github-actions bot commented Sep 6, 2022

This issue has been closed due to it having no activity.

@github-actions github-actions bot closed this as completed Sep 6, 2022
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
JVM Issue Issue present in a JVM Runtime Microsoft Windows For issues unique to Microsoft Windows Stale For auto-closed stale issues and pull requests
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests