event loop blocked during load testing

[Jian Liu]

Found various thread block WARNING during load testing in our performance env. The number of event loop threads is 2*cores (=80). There are also many WARNINGs without stacktrace (these seems to be blocked for shorter time comparing with the ones with stacktrace, all of them are 2000+ms). Wondering how others manage these blocking issues. Thanks.

1) 

WARNING: Thread Thread[vert.x-eventloop-thread-40,5,main] has been blocked for 5046 ms, time limit is 2000

io.vertx.core.VertxException: Thread blocked

        at java.util.concurrent.ConcurrentHashMap.put(ConcurrentHashMap.java:1006)

        at io.vertx.core.impl.VertxImpl.scheduleTimeout(VertxImpl.java:389)

        at io.vertx.core.impl.VertxImpl.setTimer(VertxImpl.java:267)

        at io.vertx.core.eventbus.impl.HandlerRegistration.<init>(HandlerRegistration.java:62)

        at io.vertx.core.eventbus.impl.EventBusImpl.createReplyHandlerRegistration(EventBusImpl.java:401)

        at io.vertx.core.eventbus.impl.EventBusImpl.sendOrPubInternal(EventBusImpl.java:413)

        at io.vertx.core.eventbus.impl.EventBusImpl.send(EventBusImpl.java:94)

        ...

2) 

WARNING: Thread Thread[vert.x-eventloop-thread-45,5,main] has been blocked for 14278 ms, time limit is 2000

io.vertx.core.VertxException: Thread blocked

        at com.codahale.metrics.Counter.inc(Counter.java:26)

        at io.vertx.ext.dropwizard.impl.EventBusMetricsImpl.messageReceived(EventBusMetricsImpl.java:156)

        at io.vertx.core.eventbus.impl.EventBusImpl.deliverMessageLocally(EventBusImpl.java:366)

        at io.vertx.core.eventbus.impl.EventBusImpl.deliverMessageLocally(EventBusImpl.java:344)

        at io.vertx.core.eventbus.impl.EventBusImpl.sendOrPub(EventBusImpl.java:319)

        at io.vertx.core.eventbus.impl.EventBusImpl$SendContextImpl.next(EventBusImpl.java:447)

        at io.vertx.core.eventbus.impl.EventBusImpl.sendOrPubInternal(EventBusImpl.java:415)

        at io.vertx.core.eventbus.impl.EventBusImpl.send(EventBusImpl.java:94)

        ...

3)

WARNING: Thread Thread[vert.x-eventloop-thread-16,5,main] has been blocked for 7657 ms, time limit is 2000

io.vertx.core.VertxException: Thread blocked

        at java.util.Formatter$FormatSpecifier.printString(Formatter.java:2886)

        at java.util.Formatter$FormatSpecifier.print(Formatter.java:2763)

        at java.util.Formatter.format(Formatter.java:2520)

        at java.util.Formatter.format(Formatter.java:2455)

        at java.lang.String.format(String.java:2928)

        at io.vertx.ext.web.handler.impl.LoggerHandlerImpl.log(LoggerHandlerImpl.java:109)

        at io.vertx.ext.web.handler.impl.LoggerHandlerImpl.lambda$handle$27(LoggerHandlerImpl.java:164)

        at io.vertx.ext.web.handler.impl.LoggerHandlerImpl$$Lambda$439/1602064305.handle(Unknown Source)

        at io.vertx.ext.web.impl.RoutingContextImpl.lambda$null$110(RoutingContextImpl.java:334)

        at io.vertx.ext.web.impl.RoutingContextImpl$$Lambda$451/649470196.accept(Unknown Source)

        at java.util.LinkedHashMap$LinkedValues.forEach(LinkedHashMap.java:600)

        at io.vertx.ext.web.impl.RoutingContextImpl.lambda$getBodyEndHandlers$111(RoutingContextImpl.java:334)

        at io.vertx.ext.web.impl.RoutingContextImpl$$Lambda$440/1488146342.handle(Unknown Source)

        at io.vertx.core.http.impl.HttpServerResponseImpl.end0(HttpServerResponseImpl.java:427)

        at io.vertx.core.http.impl.HttpServerResponseImpl.end(HttpServerResponseImpl.java:307)

        at io.vertx.core.http.impl.HttpServerResponseImpl.end(HttpServerResponseImpl.java:292)

        ...

 

4) This maybe a bug in Netty per https://github.com/netty/netty/issues/327.

WARNING: Thread Thread[vert.x-eventloop-thread-79,5,main] has been blocked for 5046 ms, time limit is 2000

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:79)

        at sun.nio.ch.SelectorImpl.lockAndDoSelect(SelectorImpl.java:86)

        at sun.nio.ch.SelectorImpl.select(SelectorImpl.java:97)

        at io.netty.channel.nio.NioEventLoop.select(NioEventLoop.java:622)

        at io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:310)

        at io.netty.util.concurrent.SingleThreadEventExecutor$2.run(SingleThreadEventExecutor.java:112)

        at java.lang.Thread.run(Thread.java:745)

[pron]

Hi Jian!

This isn't related to Quasar, so perhaps you'd want to ask this on the Vert.x mailing list, but in any event, aside from the Netty thing (which may be related to that bug, but can also be an artifact of Vert.x's reporting), the rest of the methods really should never block for that long for any reason, so without knowing anything, I would guess this may simply be garbage collection events. Check against the GC for pauses at the same time.

Ron

[Jian Liu]

Thanks Ron!

Yeah, I realized that right after I posted. Sorry about that. I linked to this post from vertx topic: https://groups.google.com/forum/#!topic/vertx/MjWMdVsCODg.