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

HttpInput.blockForContent() makes CPU high #5435

Closed
KevinGit585 opened this issue Oct 12, 2020 · 4 comments
Closed

HttpInput.blockForContent() makes CPU high #5435

KevinGit585 opened this issue Oct 12, 2020 · 4 comments
Assignees
@lorban
Labels
Stale For auto-closed stale issues and pull requests

Comments

@KevinGit585
Copy link

KevinGit585 commented Oct 12, 2020 •
edited
Loading

Jetty version
9.4.28.v20200408
Java version
1.8
OS type/version
CentOS
Description
I set up a jetty server to process multipart request. The multipart request contains two parts:

--boundary
text
--boundary
audio
--boundary--

I use Apache Commons FileUpload to parse the request. Sometimes it blocked when read the audio data. even though the client has closed the connection. The thread does not exist after a long time consuming high CPU. The thread stack trace is here:

"taskThreadPool-139" #517 prio=5 os_prio=0 tid=0x00005563350fb000 nid=0xb1f in Object.wait() [0x00007ff05de14000]
   java.lang.Thread.State: WAITING (on object monitor)
	at java.lang.Object.wait(Native Method)
	at java.lang.Object.wait(Object.java:502)
	at org.eclipse.jetty.server.HttpInput.blockForContent(HttpInput.java:568)
	at org.eclipse.jetty.server.HttpInput$1.blockForContent(HttpInput.java:1098)
	at org.eclipse.jetty.server.HttpInput.read(HttpInput.java:318)
	- locked <0x00000003ce0aafc0> (a java.util.ArrayDeque)
	at org.apache.commons.fileupload.MultipartStream$ItemInputStream.makeAvailable(MultipartStream.java:1027)
	at org.apache.commons.fileupload.MultipartStream$ItemInputStream.read(MultipartStream.java:931)
	at java.io.InputStream.read(InputStream.java:101)
	at com.hello.world.handler.impl.StreamingVoiceHandler.parseMultipartData(StreamingVoiceHandler.java:119)
	at com.hello.world.handler.impl.StreamingVoiceHandler.handle(StreamingVoiceHandler.java:65)
	at com.hello.world.api.VoiceController.lambda$null$5(VoiceController.java:150)
	at com.hello.world.api.VoiceController$$Lambda$858/1005983882.run(Unknown Source)
	at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)
	at java.util.concurrent.FutureTask.run(FutureTask.java:266)
	at com.hello.world.configuration.TaskConfiguration$ThreadTaskDecorator.lambda$decorate$0(TaskConfiguration.java:74)
	at com.hello.world.configuration.TaskConfiguration$ThreadTaskDecorator$$Lambda$854/233351608.run(Unknown Source)
	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
	at java.lang.Thread.run(Thread.java:748)

The VisualVM shows the thread is active also:
image

I turn on the DEBUG level of jetty log. It shows the code is loop itself even though the client has CLOSED the connection as below:

2020-10-12 15:26:48.915 | DEBUG | taskThreadPool-139 | HttpInput.java:564 | HttpInputOverHTTP@49b49203[c=0,q=0,[0]=null,s=STREAM] blocking for content timeout=0
2020-10-12 15:26:48.916 | DEBUG | taskThreadPool-139 | FillInterest.java:79 | interested FillInterest@6b637e7{org.eclipse.jetty.server.HttpConnection$BlockingReadCallback@1d5ff4a7}
2020-10-12 15:26:48.916 | DEBUG | taskThreadPool-139 | ChannelEndPoint.java:418 | changeInterests p=true 0->1 for SocketChannelEndPoint@1561c95b{/10.33.204.38:38638<->/10.33.204.119:8888,ISHUT,fill=FI,flush=-,to=0/4000}{io=1/1,kio=1,kro=1}->HttpConnection@69f3eacf[p=HttpParser{s=CLOSED,41835 of -1},g=HttpGenerator@72c3cdbb{s=START}]=>HttpChannelOverHttp@27ea6d61{s=HttpChannelState@69794f12{s=IDLE rs=BLOCKING os=OPEN is=IDLE awp=false se=false i=true al=0},r=1,c=false/false,a=IDLE,uri=null,age=0}
2020-10-12 15:26:48.916 | DEBUG | taskThreadPool-139 | HttpInput.java:564 | HttpInputOverHTTP@49b49203[c=0,q=0,[0]=null,s=STREAM] blocking for content timeout=0
2020-10-12 15:26:48.916 | DEBUG | taskThreadPool-139 | FillInterest.java:79 | interested FillInterest@6b637e7{org.eclipse.jetty.server.HttpConnection$BlockingReadCallback@1d5ff4a7}
2020-10-12 15:26:48.916 | DEBUG | taskThreadPool-139 | ChannelEndPoint.java:418 | changeInterests p=true 0->1 for SocketChannelEndPoint@1561c95b{/10.33.204.38:38638<->/10.33.204.119:8888,ISHUT,fill=FI,flush=-,to=0/4000}{io=1/1,kio=1,kro=1}->HttpConnection@69f3eacf[p=HttpParser{s=CLOSED,41835 of -1},g=HttpGenerator@72c3cdbb{s=START}]=>HttpChannelOverHttp@27ea6d61{s=HttpChannelState@69794f12{s=IDLE rs=BLOCKING os=OPEN is=IDLE awp=false se=false i=true al=0},r=1,c=false/false,a=IDLE,uri=null,age=0}
2020-10-12 15:26:48.916 | DEBUG | taskThreadPool-139 | HttpInput.java:564 | HttpInputOverHTTP@49b49203[c=0,q=0,[0]=null,s=STREAM] blocking for content timeout=0
2020-10-12 15:26:48.916 | DEBUG | taskThreadPool-139 | FillInterest.java:79 | interested FillInterest@6b637e7{org.eclipse.jetty.server.HttpConnection$BlockingReadCallback@1d5ff4a7}
2020-10-12 15:26:48.916 | DEBUG | taskThreadPool-139 | ChannelEndPoint.java:418 | changeInterests p=false 0->1 for SocketChannelEndPoint@1561c95b{/10.33.204.38:38638<->/10.33.204.119:8888,ISHUT,fill=FI,flush=-,to=0/4000}{io=0/1,kio=0,kro=1}->HttpConnection@69f3eacf[p=HttpParser{s=CLOSED,41835 of -1},g=HttpGenerator@72c3cdbb{s=START}]=>HttpChannelOverHttp@27ea6d61{s=HttpChannelState@69794f12{s=IDLE rs=BLOCKING os=OPEN is=IDLE awp=false se=false i=true al=0},r=1,c=false/false,a=IDLE,uri=null,age=0}
2020-10-12 15:26:48.916 | DEBUG | taskThreadPool-139 | ManagedSelector.java:171 | Queued change org.eclipse.jetty.io.ChannelEndPoint$1@2594e9fc on ManagedSelector@5fecb385{STARTED} id=2 keys=1 selected=0 updates=0
2020-10-12 15:26:48.916 | DEBUG | taskThreadPool-139 | ManagedSelector.java:189 | Wakeup on submit ManagedSelector@5fecb385{STARTED} id=2 keys=1 selected=0 updates=1
2020-10-12 15:26:48.916 | DEBUG | taskThreadPool-139 | HttpInput.java:564 | HttpInputOverHTTP@49b49203[c=0,q=0,[0]=null,s=STREAM] blocking for content timeout=0
2020-10-12 15:26:48.917 | DEBUG | taskThreadPool-139 | FillInterest.java:79 | interested FillInterest@6b637e7{org.eclipse.jetty.server.HttpConnection$BlockingReadCallback@1d5ff4a7}
2020-10-12 15:26:48.917 | DEBUG | taskThreadPool-139 | ChannelEndPoint.java:418 | changeInterests p=false 0->1 for SocketChannelEndPoint@1561c95b{/10.33.204.38:38638<->/10.33.204.119:8888,ISHUT,fill=FI,flush=-,to=0/4000}{io=0/1,kio=0,kro=1}->HttpConnection@69f3eacf[p=HttpParser{s=CLOSED,41835 of -1},g=HttpGenerator@72c3cdbb{s=START}]=>HttpChannelOverHttp@27ea6d61{s=HttpChannelState@69794f12{s=IDLE rs=BLOCKING os=OPEN is=IDLE awp=false se=false i=true al=0},r=1,c=false/false,a=IDLE,uri=null,age=0}
2020-10-12 15:26:48.917 | DEBUG | taskThreadPool-139 | ManagedSelector.java:171 | Queued change org.eclipse.jetty.io.ChannelEndPoint$1@2594e9fc on ManagedSelector@5fecb385{STARTED} id=2 keys=1 selected=0 updates=0
2020-10-12 15:26:48.917 | DEBUG | taskThreadPool-139 | ManagedSelector.java:189 | Wakeup on submit ManagedSelector@5fecb385{STARTED} id=2 keys=1 selected=0 updates=1
2020-10-12 15:26:48.917 | DEBUG | taskThreadPool-139 | HttpInput.java:564 | HttpInputOverHTTP@49b49203[c=0,q=0,[0]=null,s=STREAM] blocking for content timeout=0
2020-10-12 15:26:48.918 | DEBUG | taskThreadPool-139 | FillInterest.java:79 | interested FillInterest@6b637e7{org.eclipse.jetty.server.HttpConnection$BlockingReadCallback@1d5ff4a7}
2020-10-12 15:26:48.918 | DEBUG | taskThreadPool-139 | ChannelEndPoint.java:418 | changeInterests p=false 0->1 for SocketChannelEndPoint@1561c95b{/10.33.204.38:38638<->/10.33.204.119:8888,ISHUT,fill=FI,flush=-,to=0/4000}{io=0/1,kio=0,kro=1}->HttpConnection@69f3eacf[p=HttpParser{s=CLOSED,41835 of -1},g=HttpGenerator@72c3cdbb{s=START}]=>HttpChannelOverHttp@27ea6d61{s=HttpChannelState@69794f12{s=IDLE rs=BLOCKING os=OPEN is=IDLE awp=false se=false i=true al=0},r=1,c=false/false,a=IDLE,uri=null,age=0}
2020-10-12 15:26:48.918 | DEBUG | taskThreadPool-139 | ManagedSelector.java:171 | Queued change org.eclipse.jetty.io.ChannelEndPoint$1@2594e9fc on ManagedSelector@5fecb385{STARTED} id=2 keys=1 selected=0 updates=0
2020-10-12 15:26:48.918 | DEBUG | taskThreadPool-139 | ManagedSelector.java:189 | Wakeup on submit ManagedSelector@5fecb385{STARTED} id=2 keys=1 selected=0 updates=1
2020-10-12 15:26:48.918 | DEBUG | taskThreadPool-139 | HttpInput.java:564 | HttpInputOverHTTP@49b49203[c=0,q=0,[0]=null,s=STREAM] blocking for content timeout=0
2020-10-12 15:26:48.918 | DEBUG | taskThreadPool-139 | FillInterest.java:79 | interested FillInterest@6b637e7{org.eclipse.jetty.server.HttpConnection$BlockingReadCallback@1d5ff4a7}
2020-10-12 15:26:48.918 | DEBUG | taskThreadPool-139 | ChannelEndPoint.java:418 | changeInterests p=true 0->1 for SocketChannelEndPoint@1561c95b{/10.33.204.38:38638<->/10.33.204.119:8888,ISHUT,fill=FI,flush=-,to=0/4000}{io=1/1,kio=1,kro=1}->HttpConnection@69f3eacf[p=HttpParser{s=CLOSED,41835 of -1},g=HttpGenerator@72c3cdbb{s=START}]=>HttpChannelOverHttp@27ea6d61{s=HttpChannelState@69794f12{s=IDLE rs=BLOCKING os=OPEN is=IDLE awp=false se=false i=true al=0},r=1,c=false/false,a=IDLE,uri=null,age=0}
2020-10-12 15:26:48.918 | DEBUG | taskThreadPool-139 | HttpInput.java:564 | HttpInputOverHTTP@49b49203[c=0,q=0,[0]=null,s=STREAM] blocking for content timeout=0
2020-10-12 15:26:48.919 | DEBUG | taskThreadPool-139 | FillInterest.java:79 | interested FillInterest@6b637e7{org.eclipse.jetty.server.HttpConnection$BlockingReadCallback@1d5ff4a7}
2020-10-12 15:26:48.919 | DEBUG | taskThreadPool-139 | ChannelEndPoint.java:418 | changeInterests p=true 0->1 for SocketChannelEndPoint@1561c95b{/10.33.204.38:38638<->/10.33.204.119:8888,ISHUT,fill=FI,flush=-,to=0/4000}{io=1/1,kio=1,kro=1}->HttpConnection@69f3eacf[p=HttpParser{s=CLOSED,41835 of -1},g=HttpGenerator@72c3cdbb{s=START}]=>HttpChannelOverHttp@27ea6d61{s=HttpChannelState@69794f12{s=IDLE rs=BLOCKING os=OPEN is=IDLE awp=false se=false i=true al=0},r=1,c=false/false,a=IDLE,uri=null,age=0}
2020-10-12 15:26:48.919 | DEBUG | taskThreadPool-139 | HttpInput.java:564 | HttpInputOverHTTP@49b49203[c=0,q=0,[0]=null,s=STREAM] blocking for content timeout=0
2020-10-12 15:26:48.919 | DEBUG | taskThreadPool-139 | FillInterest.java:79 | interested FillInterest@6b637e7{org.eclipse.jetty.server.HttpConnection$BlockingReadCallback@1d5ff4a7}
2020-10-12 15:26:48.919 | DEBUG | taskThreadPool-139 | ChannelEndPoint.java:418 | changeInterests p=true 0->1 for SocketChannelEndPoint@1561c95b{/10.33.204.38:38638<->/10.33.204.119:8888,ISHUT,fill=FI,flush=-,to=0/4000}{io=1/1,kio=1,kro=1}->HttpConnection@69f3eacf[p=HttpParser{s=CLOSED,41835 of -1},g=HttpGenerator@72c3cdbb{s=START}]=>HttpChannelOverHttp@27ea6d61{s=HttpChannelState@69794f12{s=IDLE rs=BLOCKING os=OPEN is=IDLE awp=false se=false i=true al=0},r=1,c=false/false,a=IDLE,uri=null,age=0}
2020-10-12 15:26:48.919 | DEBUG | taskThreadPool-139 | HttpInput.java:564 | HttpInputOverHTTP@49b49203[c=0,q=0,[0]=null,s=STREAM] blocking for content timeout=0
2020-10-12 15:26:48.919 | DEBUG | taskThreadPool-139 | FillInterest.java:79 | interested FillInterest@6b637e7{org.eclipse.jetty.server.HttpConnection$BlockingReadCallback@1d5ff4a7}
2020-10-12 15:26:48.919 | DEBUG | taskThreadPool-139 | ChannelEndPoint.java:418 | changeInterests p=true 0->1 for SocketChannelEndPoint@1561c95b{/10.33.204.38:38638<->/10.33.204.119:8888,ISHUT,fill=FI,flush=-,to=0/4000}{io=1/1,kio=1,kro=1}->HttpConnection@69f3eacf[p=HttpParser{s=CLOSED,41835 of -1},g=HttpGenerator@72c3cdbb{s=START}]=>HttpChannelOverHttp@27ea6d61{s=HttpChannelState@69794f12{s=IDLE rs=BLOCKING os=OPEN is=IDLE awp=false se=false i=true al=0},r=1,c=false/false,a=IDLE,uri=null,age=0}
2020-10-12 15:26:48.919 | DEBUG | taskThreadPool-139 | HttpInput.java:564 | HttpInputOverHTTP@49b49203[c=0,q=0,[0]=null,s=STREAM] blocking for content timeout=0
2020-10-12 15:26:48.920 | DEBUG | taskThreadPool-139 | FillInterest.java:79 | interested FillInterest@6b637e7{org.eclipse.jetty.server.HttpConnection$BlockingReadCallback@1d5ff4a7}
2020-10-12 15:26:48.920 | DEBUG | taskThreadPool-139 | ChannelEndPoint.java:418 | changeInterests p=false 0->1 for SocketChannelEndPoint@1561c95b{/10.33.204.38:38638<->/10.33.204.119:8888,ISHUT,fill=FI,flush=-,to=0/4000}{io=0/1,kio=0,kro=1}->HttpConnection@69f3eacf[p=HttpParser{s=CLOSED,41835 of -1},g=HttpGenerator@72c3cdbb{s=START}]=>HttpChannelOverHttp@27ea6d61{s=HttpChannelState@69794f12{s=IDLE rs=BLOCKING os=OPEN is=IDLE awp=false se=false i=true al=0},r=1,c=false/false,a=IDLE,uri=null,age=0}
2020-10-12 15:26:48.920 | DEBUG | taskThreadPool-139 | ManagedSelector.java:171 | Queued change org.eclipse.jetty.io.ChannelEndPoint$1@2594e9fc on ManagedSelector@5fecb385{STARTED} id=2 keys=1 selected=0 updates=0
2020-10-12 15:26:48.920 | DEBUG | taskThreadPool-139 | ManagedSelector.java:189 | Wakeup on submit ManagedSelector@5fecb385{STARTED} id=2 keys=1 selected=0 updates=1
2020-10-12 15:26:48.920 | DEBUG | taskThreadPool-139 | HttpInput.java:564 | HttpInputOverHTTP@49b49203[c=0,q=0,[0]=null,s=STREAM] blocking for content timeout=0
2020-10-12 15:26:48.920 | DEBUG | taskThreadPool-139 | FillInterest.java:79 | interested FillInterest@6b637e7{org.eclipse.jetty.server.HttpConnection$BlockingReadCallback@1d5ff4a7}
2020-10-12 15:26:48.921 | DEBUG | taskThreadPool-139 | ChannelEndPoint.java:418 | changeInterests p=true 0->1 for SocketChannelEndPoint@1561c95b{/10.33.204.38:38638<->/10.33.204.119:8888,ISHUT,fill=FI,flush=-,to=0/4000}{io=1/1,kio=1,kro=1}->HttpConnection@69f3eacf[p=HttpParser{s=CLOSED,41835 of -1},g=HttpGenerator@72c3cdbb{s=START}]=>HttpChannelOverHttp@27ea6d61{s=HttpChannelState@69794f12{s=IDLE rs=BLOCKING os=OPEN is=IDLE awp=false se=false i=true al=0},r=1,c=false/false,a=IDLE,uri=null,age=0}
2020-10-12 15:26:48.921 | DEBUG | taskThreadPool-139 | HttpInput.java:564 | HttpInputOverHTTP@49b49203[c=0,q=0,[0]=null,s=STREAM] blocking for content timeout=0
2020-10-12 15:26:48.921 | DEBUG | taskThreadPool-139 | FillInterest.java:79 | interested FillInterest@6b637e7{org.eclipse.jetty.server.HttpConnection$BlockingReadCallback@1d5ff4a7}
2020-10-12 15:26:48.921 | DEBUG | taskThreadPool-139 | ChannelEndPoint.java:418 | changeInterests p=true 0->1 for SocketChannelEndPoint@1561c95b{/10.33.204.38:38638<->/10.33.204.119:8888,ISHUT,fill=FI,flush=-,to=0/4000}{io=1/1,kio=1,kro=1}->HttpConnection@69f3eacf[p=HttpParser{s=CLOSED,41835 of -1},g=HttpGenerator@72c3cdbb{s=START}]=>HttpChannelOverHttp@27ea6d61{s=HttpChannelState@69794f12{s=IDLE rs=BLOCKING os=OPEN is=IDLE awp=false se=false i=true al=0},r=1,c=false/false,a=IDLE,uri=null,age=0}

Do you have any idea what could be the reason?
Thanks.
@lorban
Copy link
Contributor

lorban commented Oct 12, 2020

It looks like that thread got stuck in a weird state: the channel is marked as ISHUT, the parser is CLOSED but the HttpChannelState is IDLE for some reason and the HttpInput is in STREAM mode, has seen 0 byte consumed and has an empty content queue.

It looks like the input stream was remotely shut down which should have resulted in the server reading EOF but somehow that message got lost and the thread is busy asking to be awoken when new data arrives and being awoken to notify it that the input stream is shut down.

Unfortunately, the log snippet you included doesn't contain enough details to figure out what could have caused this invalid state.
Could you please try to collect a debug log that contains the traces of what the server did at the time this problem occurred, or even better: upload somewhere on github a sample project that we could use to reproduce the problem?

Thanks!

@gregw
Copy link
Contributor

gregw commented Oct 26, 2020

@kissLife any more info? Perhaps try the just released 9.4.33 (which includes an important security fix anyway)

@dimas dimas mentioned this issue Oct 8, 2021
Closed
@github-actions
Copy link

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 Dec 15, 2021
@github-actions
Copy link

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

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees

@lorban lorban

Labels
Stale For auto-closed stale issues and pull requests
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
4 participants
@gregw @lorban @KevinGit585 @lachlan-roberts