servicecomb-java-chassis icon indicating copy to clipboard operation
servicecomb-java-chassis copied to clipboard

vertx-blocked-thread-checker出现超长时间阻塞

Open njhw12 opened this issue 1 year ago • 8 comments

线程堆栈目前发现有两类: 1. Thread Thread[transport-vert.x-eventloop-thread-1,5,main] has been blocked for 11900 ms, time limit is 2000 ms|io.vertx.core.impl.BlockedThreadChecker io.vertx.core.VertxException: Thread blocked at sun.misc.Unsafe.unpark(Native Method) at java.util.concurrent.locks.LockSupport.unpark(LockSupport.java:141) at java.util.concurrent.locks.AbstractQueuedSynchronizer.unparkSuccessor(AbstractQueuedSynchronizer.java:662) at java.util.concurrent.locks.AbstractQueuedSynchronizer.release(AbstractQueuedSynchronizer.java:1266) at java.util.concurrent.locks.ReentrantLock.unlock(ReentrantLock.java:457) at java.util.concurrent.LinkedBlockingQueue.signalNotEmpty(LinkedBlockingQueue.java:176) at java.util.concurrent.LinkedBlockingQueue.offer(LinkedBlockingQueue.java:430) at org.apache.servicecomb.core.executor.LinkedBlockingQueueEx.offer(LinkedBlockingQueueEx.java:47) at org.apache.servicecomb.core.executor.LinkedBlockingQueueEx.offer(LinkedBlockingQueueEx.java:22) at java.util.concurrent.ThreadPoolExecutor.execute(ThreadPoolExecutor.java:1371) at org.apache.servicecomb.core.executor.ThreadPoolExecutorEx.execute(ThreadPoolExecutorEx.java:46) at org.apache.servicecomb.core.executor.GroupExecutor.execute(GroupExecutor.java:141) at org.apache.servicecomb.common.rest.AbstractRestInvocation.scheduleInvocation(AbstractRestInvocation.java:147) at org.apache.servicecomb.common.rest.RestProducerInvocation.invoke(RestProducerInvocation.java:52) at org.apache.servicecomb.transport.rest.vertx.VertxRestDispatcher.onRequest(VertxRestDispatcher.java:219) at org.apache.servicecomb.transport.rest.vertx.VertxRestDispatcher$$Lambda$4251/1027787170.handle(Unknown Source) at io.vertx.ext.web.impl.RouteState.handleContext(RouteState.java:1127) at io.vertx.ext.web.impl.RoutingContextImplBase.iterateNext(RoutingContextImplBase.java:151) at io.vertx.ext.web.impl.RoutingContextImpl.next(RoutingContextImpl.java:133) at org.apache.servicecomb.transport.rest.vertx.RestBodyHandler$BHandler.doEnd(RestBodyHandler.java:362) at org.apache.servicecomb.transport.rest.vertx.RestBodyHandler$BHandler.end(RestBodyHandler.java:339) at org.apache.servicecomb.transport.rest.vertx.RestBodyHandler.lambda$handle$0(RestBodyHandler.java:112) at org.apache.servicecomb.transport.rest.vertx.RestBodyHandler$$Lambda$4506/2073179658.handle(Unknown Source) at io.vertx.core.impl.AbstractContext.dispatch(AbstractContext.java:100) at io.vertx.core.impl.AbstractContext.dispatch(AbstractContext.java:63) at io.vertx.core.http.impl.HttpEventHandler.handleEnd(HttpEventHandler.java:76) at io.vertx.core.http.impl.Http1xServerRequest.onEnd(Http1xServerRequest.java:565) at io.vertx.core.http.impl.Http1xServerRequest.handleEnd(Http1xServerRequest.java:548) at io.vertx.core.http.impl.Http1xServerConnection$$Lambda$4509/1354880134.handle(Unknown Source) at io.vertx.core.impl.EventLoopContext.execute(EventLoopContext.java:71) at io.vertx.core.impl.DuplicatedContext.execute(DuplicatedContext.java:163) at io.vertx.core.http.impl.Http1xServerConnection.onEnd(Http1xServerConnection.java:189) at io.vertx.core.http.impl.Http1xServerConnection.onContent(Http1xServerConnection.java:179) at io.vertx.core.http.impl.Http1xServerConnection.handleOther(Http1xServerConnection.java:159) at io.vertx.core.http.impl.Http1xServerConnection.handleMessage(Http1xServerConnection.java:147) at io.vertx.core.net.impl.ConnectionBase.read(ConnectionBase.java:155) at io.vertx.core.net.impl.VertxHandler.channelRead(VertxHandler.java:154) at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:379) at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:365) at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:357) at io.netty.channel.ChannelInboundHandlerAdapter.channelRead(ChannelInboundHandlerAdapter.java:93) at io.netty.handler.codec.http.websocketx.extensions.WebSocketServerExtensionHandler.channelRead(WebSocketServerExtensionHandler.java:99) at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:379) at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:365) at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:357) at io.netty.handler.timeout.IdleStateHandler.channelRead(IdleStateHandler.java:286) at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:379) at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:365) at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:357) at io.netty.handler.codec.ByteToMessageDecoder.fireChannelRead(ByteToMessageDecoder.java:327) at io.netty.handler.codec.ByteToMessageDecoder.channelRead(ByteToMessageDecoder.java:299) at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:379) at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:365) at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:357) at io.vertx.core.http.impl.Http1xOrH2CHandler.end(Http1xOrH2CHandler.java:61) at io.vertx.core.http.impl.Http1xOrH2CHandler.channelRead(Http1xOrH2CHandler.java:38) at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:379) at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:365) at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:357) at io.netty.handler.timeout.IdleStateHandler.channelRead(IdleStateHandler.java:286) at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:379) at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:365) at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:357) at io.netty.channel.DefaultChannelPipeline$HeadContext.channelRead(DefaultChannelPipeline.java:1410) at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:379) at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:365) at io.netty.channel.DefaultChannelPipeline.fireChannelRead(DefaultChannelPipeline.java:919) at io.netty.channel.nio.AbstractNioByteChannel$NioByteUnsafe.read(AbstractNioByteChannel.java:166) at io.netty.channel.nio.NioEventLoop.processSelectedKey(NioEventLoop.java:722) at io.netty.channel.nio.NioEventLoop.processSelectedKeysOptimized(NioEventLoop.java:658) at io.netty.channel.nio.NioEventLoop.processSelectedKeys(NioEventLoop.java:584) at io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:496) at io.netty.util.concurrent.SingleThreadEventExecutor$4.run(SingleThreadEventExecutor.java:995) at io.netty.util.internal.ThreadExecutorMap$2.run(ThreadExecutorMap.java:74) at io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30) at java.lang.Thread.run(Thread.java:750)

Thread Thread[transport-vert.x-eventloop-thread-4,5,main] has been blocked for 12089 ms, time limit is 2000 ms|io.vertx.core.impl.BlockedThreadChecker io.vertx.core.VertxException: Thread blocked at sun.nio.ch.EPollArrayWrapper.epollWait(Native Method) at sun.nio.ch.EPollArrayWrapper.poll(EPollArrayWrapper.java:269) at sun.nio.ch.EPollSelectorImpl.doSelect(EPollSelectorImpl.java:93) at sun.nio.ch.SelectorImpl.lockAndDoSelect(SelectorImpl.java:86) at sun.nio.ch.SelectorImpl.select(SelectorImpl.java:97) at io.netty.channel.nio.SelectedSelectionKeySetSelector.select(SelectedSelectionKeySetSelector.java:62) at io.netty.channel.nio.NioEventLoop.select(NioEventLoop.java:817) at io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:460) at io.netty.util.concurrent.SingleThreadEventExecutor$4.run(SingleThreadEventExecutor.java:995) at io.netty.util.internal.ThreadExecutorMap$2.run(ThreadExecutorMap.java:74) at io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30) at java.lang.Thread.run(Thread.java:750)

njhw12 avatar Aug 16 '22 11:08 njhw12

看起来是排队请求太多,队列都满了。

liubao68 avatar Aug 17 '22 09:08 liubao68

这个不是排队请求过多吧,目前我们业务使用的是cse的默认配置,是无界队列 根据异常堆栈结合jdk的代码看是入队成功了,只是入队前队列为空,发送队列变为非空通知时,最后释放锁时阻塞了,而且如果怀疑是内存fullgc类的,也不该阻塞近12秒吧

njhw12 avatar Aug 18 '22 08:08 njhw12

最后有结论吧吗??

我也遇到了这个问题, 时延增加导致请求排队过多,队列阻塞。 阻塞了几百秒。 奇怪的是:后端时延恢复以后,还是继续阻塞。服务重启后,就立刻恢复了。

lvorytower avatar Aug 27 '22 06:08 lvorytower

I also encountered the same problem, the service is restored after restart, is there a solution?

wyhluckydog avatar Feb 05 '24 09:02 wyhluckydog

I also encountered the same problem, the service is restored after restart, is there a solution?

Do you have the same stack-trace?

liubao68 avatar Feb 05 '24 09:02 liubao68

yes

wyhluckydog avatar Feb 05 '24 10:02 wyhluckydog

But I don't know how to deal with it. Disappointment

wyhluckydog avatar Feb 05 '24 10:02 wyhluckydog

yes

Can you comment with your full stack trace? And if possible, you can try to dump the full stack with jstack.

liubao68 avatar Feb 17 '24 03:02 liubao68