Strange behavior of io.vertx.core.impl.BlockedThreadChecker on Ubuntu

[Igor Spasić]

In VertX 3 milestone 6, I have set:

router

.route(HttpMethod.GET, adminPath)

.blockingHandler(new AdminHandler(application))

.failureHandler(failureRoutingContext());

...

router

.route()

.handler(TimeoutHandler.create(serverConfig.getTimeout()));

router.route().handler(ResponseTimeHandler.create());

...

router.route()

.blockingHandler(MAINHANDLER())

.failureHandler(failureRoutingContext());

In other words, we have some Admin handler (on admin path), some check handlers and finally, the main handler (on all paths).

When I run this on Ubuntu, and execute the Amin handler, by sending request to admin path, I get the correct response, but also:

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

io.vertx.core.VertxException: Thread blocked

and the same message repeats (with blocking time increasing, of course). Of course, my admin handler does call .end() to finish the request.

What am I doing here wrong?

[Igor Spasić]

And this does not happens locally on OSX.

[Tim Fox]

Igor,

Do you have a reproducer?

[Igor Spasić]

Well, I can reproduce this fairly easy; I have the tar file containing all the binaries; and this behavior happens on Amazon ES.

However, let me try to find the minimal code that can reproduce this.

[Igor Spasić]

I have it now.

https://www.dropbox.com/s/kq2s53q0hz7vd19/vertx.zip?dl=0

It is very very simple example, but I am doing something terribly wrong.

Thanx!

[Tim Fox]

Igor,

Can you provide some instructions on how this should be run?

Also, can you run it against the latest code (3.0.0-SNAPSHOT) not a
milestone

[Igor Spasić]

Sure, this is gradle project, so all you have to do is:

> gradlew clean run

I am testing this on Ubuntu like this:

1) create archive:

> gradlew assemble

Then i upload tar to amazon, and extract and simply run:

> bin/vertx

After that I send some GET request to /admin using curl. The issue starts to show immediately.

I will check with the snapshot.

[Igor Spasić]

Still the same with SNAPSHOT.

Huh, what is going wrong here? This is really basic code; Ive just create two verticles, and registered /admin route.

Example of log:

un 08, 2015 2:49:10 PM io.vertx.core.impl.BlockedThreadChecker

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

Jun 08, 2015 2:49:11 PM io.vertx.core.impl.BlockedThreadChecker

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

Jun 08, 2015 2:49:12 PM io.vertx.core.impl.BlockedThreadChecker

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

io.vertx.core.VertxException: Thread blocked

at io.vertx.core.http.impl.HttpServerResponseImpl.handleClosed(HttpServerResponseImpl.java:459)

..............

On Monday, June 8, 2015 at 9:13:32 AM UTC+2, Tim Fox wrote:

[Tim Fox]

I tried to update this to run against 3.0.0-SNAPSHOT but it can't find
the deps (I guess because it's using bintray).

If you could a push a version that builds against 3.0.0-SNAPSHOT I will
take a further look :)

[Tim Fox]

I just copy and pasted your classes into the vertx-examples project
(where the web examples are) as it's much easier to run that way.

I then ran the Runner in my IDE and pointed my browser at
http://localhost:8080/admin

It seemed to return a request ok: "Hello!"

Here's the output from the console:

Server is up
Router: 547420485 accepting request GET http://0.0.0.0:8080/admin
Route matches: Route[ path:/admin pattern:null
handler:io.vertx.ext.web.impl.BlockingHandlerDecorator@19e46a3a
failureHandler:io.vertx.example.web.foo.ServerVerticle$$Lambda$8/1233952903@23b8aa88
order:0 methods:[GET]]@2036037964
Calling the handler
Router: 547420485 accepting request GET http://0.0.0.0:8080/favicon.ico

So, it all seems to be working as expected here...

[Igor Spasić]

Yes, it works ok from my mac as well. But then when I upload this to clean amazon ubuntu, this strange things happens.

I will push the source to my repo, and share it here, it will be based on snapshot version.

[Igor Spasić]

This is version that works on SNAPSHOT

https://github.com/igorspasic/vertx

Am I doing everything right, from the code? I really dont know what happens.

[Igor Spasić]

Ok I think I know what happens, its because admin route handler is not calling the next().

But the behavior is very different on osx and ubuntu;that is strange.

I will investigate more...

[Tim Fox]

The admin handler shouldn't call next as it completes the response.

When you get a blocked thread it should log the stack trace to the
output, can you paste that here?

[Igor Spasić]

Ive have errors on this github link, but here it is again:

curl -g -v http://127.0.0.1:8080/admin
* Hostname was NOT found in DNS cache
*   Trying 127.0.0.1...
* Connected to 127.0.0.1 (127.0.0.1) port 8080 (#0)
> GET /admin HTTP/1.1
> User-Agent: curl/7.35.0
> Host: 127.0.0.1:8080
> Accept: */*
>
< HTTP/1.1 200 OK
< Content-Length: 6
<
* Connection #0 to host 127.0.0.1 left intact

curl -g -v http://127.0.0.1:8080/admin
* Hostname was NOT found in DNS cache
*   Trying 127.0.0.1...
* Connected to 127.0.0.1 (127.0.0.1) port 8080 (#0)
> GET /admin HTTP/1.1
> User-Agent: curl/7.35.0
> Host: 127.0.0.1:8080
> Accept: */*
>
< HTTP/1.1 200 OK
< Content-Length: 6
<
* Connection #0 to host 127.0.0.1 left intact
Jun 08, 2015 5:46:25 PM io.vertx.core.impl.BlockedThreadChecker
WARNING: Thread Thread[vert.x-eventloop-thread-0,5,main] has been blocked for 2440 ms, time limit is 2000
Jun 08, 2015 5:46:26 PM io.vertx.core.impl.BlockedThreadChecker
WARNING: Thread Thread[vert.x-eventloop-thread-0,5,main] has been blocked for 3440 ms, time limit is 2000
Jun 08, 2015 5:46:27 PM io.vertx.core.impl.BlockedThreadChecker
WARNING: Thread Thread[vert.x-eventloop-thread-0,5,main] has been blocked for 4440 ms, time limit is 2000
Jun 08, 2015 5:46:28 PM io.vertx.core.impl.BlockedThreadChecker
WARNING: Thread Thread[vert.x-eventloop-thread-0,5,main] has been blocked for 5440 ms, time limit is 2000
io.vertx.core.VertxException: Thread blocked
    at io.vertx.core.http.impl.HttpServerResponseImpl.handleClosed(HttpServerResponseImpl.java:459)
    at io.vertx.core.http.impl.ServerConnection.handleClosed(ServerConnection.java:336)
    at io.vertx.core.net.impl.VertxHandler$$Lambda$24/574370275.run(Unknown Source)
    at io.vertx.core.impl.ContextImpl.lambda$wrapTask$3(ContextImpl.java:310)
    at io.vertx.core.impl.ContextImpl$$Lambda$4/2012232625.run(Unknown Source)
    at io.vertx.core.impl.ContextImpl.executeFromIO(ContextImpl.java:204)
    at io.vertx.core.net.impl.VertxHandler.channelInactive(VertxHandler.java:106)
    at io.netty.channel.AbstractChannelHandlerContext.invokeChannelInactive(AbstractChannelHandlerContext.java:208)
    at io.netty.channel.AbstractChannelHandlerContext.fireChannelInactive(AbstractChannelHandlerContext.java:194)
    at io.netty.handler.stream.ChunkedWriteHandler.channelInactive(ChunkedWriteHandler.java:148)
    at io.netty.channel.AbstractChannelHandlerContext.invokeChannelInactive(AbstractChannelHandlerContext.java:208)
    at io.netty.channel.AbstractChannelHandlerContext.fireChannelInactive(AbstractChannelHandlerContext.java:194)
    at io.netty.channel.ChannelInboundHandlerAdapter.channelInactive(ChannelInboundHandlerAdapter.java:75)
    at io.netty.handler.codec.http.HttpContentEncoder.channelInactive(HttpContentEncoder.java:252)
    at io.netty.channel.AbstractChannelHandlerContext.invokeChannelInactive(AbstractChannelHandlerContext.java:208)
    at io.netty.channel.AbstractChannelHandlerContext.fireChannelInactive(AbstractChannelHandlerContext.java:194)
    at io.netty.handler.codec.ByteToMessageDecoder.channelInactive(ByteToMessageDecoder.java:306)
    at io.netty.channel.AbstractChannelHandlerContext.invokeChannelInactive(AbstractChannelHandlerContext.java:208)
    at io.netty.channel.AbstractChannelHandlerContext.fireChannelInactive(AbstractChannelHandlerContext.java:194)
    at io.netty.channel.DefaultChannelPipeline.fireChannelInactive(DefaultChannelPipeline.java:828)
    at io.netty.channel.AbstractChannel$AbstractUnsafe$7.run(AbstractChannel.java:621)
    at io.netty.util.concurrent.SingleThreadEventExecutor.runAllTasks(SingleThreadEventExecutor.java:357)
    at io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:357)
    at io.netty.util.concurrent.SingleThreadEventExecutor$2.run(SingleThreadEventExecutor.java:111)
    at java.lang.Thread.run(Thread.java:745)

[Tim Fox]

Hmm, I suspect you have a deadlock. Someone else reported a very similar
thing a few days ago on the group.

https://groups.google.com/forum/?fromgroups#!searchin/vertx/deadlock/vertx/oBGU0HRW_1I/K_OWIf-TiiQJ

If you can get a JVM thread dump (send kill -3 to the process) it will
tell you more information about the deadlock (if that's what it is).

I wish I could replicate this...

[Raphael Luta]

If you’re running java 1.8 on ubuntu 14.04 on Haswell hardware, you’re probably hitting the kernel futex bug introduced in kernel 3.14 and fixed in 3.18.

You can find a long discussion thread on this bug and its impact here:
https://groups.google.com/forum/#!topic/mechanical-sympathy/QbmpZxp6C64

Upgrading kernel to release 3.19+ should fix the issue.

> --
> You received this message because you are subscribed to the Google Groups "vert.x" group.
> To unsubscribe from this group and stop receiving emails from it, send an email to vertx+un...@googlegroups.com.
> For more options, visit https://groups.google.com/d/optout.

[Igor Spasić]

uname -a

Linux ip-10-158-150-199 3.13.0-48-generic #80-Ubuntu SMP Thu Mar 12 11:16:15 UTC 2015 x86_64 x86_64 x86_64 GNU/Linux

sb_release -a

No LSB modules are available.

Distributor ID: Ubuntu

Description: Ubuntu 14.04.2 LTS

Release: 14.04

Codename: trusty

So its 3.13.... maybe kernel upgrade should be still performed.

[Igor Spasić]

It is a deadlock.

Since I run 2 verticles, this happens on second request.

ull thread dump Java HotSpot(TM) 64-Bit Server VM (25.45-b02 mixed mode):

"vert.x-worker-thread-1" #15 prio=5 os_prio=0 tid=0x00007f1b900a3000 nid=0x2ac3 waiting for monitor entry [0x00007f1b82efc000]

   java.lang.Thread.State: BLOCKED (on object monitor)

at io.vertx.core.http.impl.ServerConnection.responseComplete(ServerConnection.java:145)

- waiting to lock <0x00000000e29771e8> (a io.vertx.core.http.impl.ServerConnection)

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

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

- locked <0x00000000e2977418> (a io.vertx.core.http.impl.HttpServerResponseImpl)

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

at vertx.AdminHandler.handle(AdminHandler.java:11)

at vertx.AdminHandler.handle(AdminHandler.java:7)

at io.vertx.ext.web.impl.BlockingHandlerDecorator.lambda$handle$71(BlockingHandlerDecorator.java:31)

at io.vertx.ext.web.impl.BlockingHandlerDecorator$$Lambda$15/566708161.handle(Unknown Source)

at io.vertx.core.impl.ContextImpl.lambda$executeBlocking$2(ContextImpl.java:266)

at io.vertx.core.impl.ContextImpl$$Lambda$17/1823208148.run(Unknown Source)

at io.vertx.core.impl.OrderedExecutorFactory$OrderedExecutor.lambda$new$202(OrderedExecutorFactory.java:91)

at io.vertx.core.impl.OrderedExecutorFactory$OrderedExecutor$$Lambda$1/124313277.run(Unknown Source)

at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)

at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)

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

"vert.x-worker-thread-0" #14 prio=5 os_prio=0 tid=0x00007f1b900eb800 nid=0x2ac1 waiting on condition [0x00007f1b82ffd000]

   java.lang.Thread.State: WAITING (parking)

at sun.misc.Unsafe.park(Native Method)

- parking to wait for  <0x00000000e0fdd478> (a java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject)

at java.util.concurrent.locks.LockSupport.park(LockSupport.java:175)

at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(AbstractQueuedSynchronizer.java:2039)

at java.util.concurrent.LinkedBlockingQueue.take(LinkedBlockingQueue.java:442)

at java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:1067)

at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1127)

at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)

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

"threadDeathWatcher-2-1" #13 daemon prio=1 os_prio=0 tid=0x00007f1b900b4800 nid=0x2ac0 waiting on condition [0x00007f1ba032a000]

   java.lang.Thread.State: TIMED_WAITING (sleeping)

at java.lang.Thread.sleep(Native Method)

at io.netty.util.ThreadDeathWatcher$Watcher.run(ThreadDeathWatcher.java:137)

at io.netty.util.concurrent.DefaultThreadFactory$DefaultRunnableDecorator.run(DefaultThreadFactory.java:137)

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

"vert.x-eventloop-thread-1" #11 prio=5 os_prio=0 tid=0x00007f1b9006e800 nid=0x2abd runnable [0x00007f1ba042b000]

   java.lang.Thread.State: RUNNABLE

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)

- locked <0x00000000e0fd7ab0> (a io.netty.channel.nio.SelectedSelectionKeySet)

- locked <0x00000000e0fd6888> (a java.util.Collections$UnmodifiableSet)

- locked <0x00000000e0fd6770> (a sun.nio.ch.EPollSelectorImpl)

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

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

"vert.x-eventloop-thread-0" #10 prio=5 os_prio=0 tid=0x00007f1bb428d000 nid=0x2abb waiting for monitor entry [0x00007f1ba052b000]

   java.lang.Thread.State: BLOCKED (on object monitor)

at io.vertx.core.http.impl.HttpServerResponseImpl.handleClosed(HttpServerResponseImpl.java:459)

- waiting to lock <0x00000000e2977418> (a io.vertx.core.http.impl.HttpServerResponseImpl)

at io.vertx.core.http.impl.ServerConnection.handleClosed(ServerConnection.java:336)

- locked <0x00000000e29771e8> (a io.vertx.core.http.impl.ServerConnection)

at io.vertx.core.net.impl.VertxHandler$$Lambda$23/993659812.run(Unknown Source)

at io.vertx.core.impl.ContextImpl.lambda$wrapTask$3(ContextImpl.java:310)

at io.vertx.core.impl.ContextImpl$$Lambda$4/2012232625.run(Unknown Source)

at io.vertx.core.impl.ContextImpl.executeFromIO(ContextImpl.java:204)

at io.vertx.core.net.impl.VertxHandler.channelInactive(VertxHandler.java:106)

at io.netty.channel.AbstractChannelHandlerContext.invokeChannelInactive(AbstractChannelHandlerContext.java:208)

at io.netty.channel.AbstractChannelHandlerContext.fireChannelInactive(AbstractChannelHandlerContext.java:194)

at io.netty.handler.stream.ChunkedWriteHandler.channelInactive(ChunkedWriteHandler.java:148)

at io.netty.channel.AbstractChannelHandlerContext.invokeChannelInactive(AbstractChannelHandlerContext.java:208)

at io.netty.channel.AbstractChannelHandlerContext.fireChannelInactive(AbstractChannelHandlerContext.java:194)

at io.netty.channel.ChannelInboundHandlerAdapter.channelInactive(ChannelInboundHandlerAdapter.java:75)

at io.netty.handler.codec.http.HttpContentEncoder.channelInactive(HttpContentEncoder.java:252)

at io.netty.channel.AbstractChannelHandlerContext.invokeChannelInactive(AbstractChannelHandlerContext.java:208)

at io.netty.channel.AbstractChannelHandlerContext.fireChannelInactive(AbstractChannelHandlerContext.java:194)

at io.netty.handler.codec.ByteToMessageDecoder.channelInactive(ByteToMessageDecoder.java:306)

at io.netty.channel.AbstractChannelHandlerContext.invokeChannelInactive(AbstractChannelHandlerContext.java:208)

at io.netty.channel.AbstractChannelHandlerContext.fireChannelInactive(AbstractChannelHandlerContext.java:194)

at io.netty.channel.DefaultChannelPipeline.fireChannelInactive(DefaultChannelPipeline.java:828)

at io.netty.channel.AbstractChannel$AbstractUnsafe$7.run(AbstractChannel.java:621)

at io.netty.util.concurrent.SingleThreadEventExecutor.runAllTasks(SingleThreadEventExecutor.java:357)

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

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

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

"vertx-blocked-thread-checker" #9 daemon prio=5 os_prio=0 tid=0x00007f1bb419b000 nid=0x2aba in Object.wait() [0x00007f1ba0a55000]

   java.lang.Thread.State: TIMED_WAITING (on object monitor)

at java.lang.Object.wait(Native Method)

- waiting on <0x00000000e0e7b408> (a java.util.TaskQueue)

at java.util.TimerThread.mainLoop(Timer.java:552)

- locked <0x00000000e0e7b408> (a java.util.TaskQueue)

at java.util.TimerThread.run(Timer.java:505)

"Service Thread" #7 daemon prio=9 os_prio=0 tid=0x00007f1bb40b9800 nid=0x2ab8 runnable [0x0000000000000000]

   java.lang.Thread.State: RUNNABLE

"C1 CompilerThread1" #6 daemon prio=9 os_prio=0 tid=0x00007f1bb40b5000 nid=0x2ab7 waiting on condition [0x0000000000000000]

   java.lang.Thread.State: RUNNABLE

"C2 CompilerThread0" #5 daemon prio=9 os_prio=0 tid=0x00007f1bb40b2000 nid=0x2ab6 waiting on condition [0x0000000000000000]

   java.lang.Thread.State: RUNNABLE

"Signal Dispatcher" #4 daemon prio=9 os_prio=0 tid=0x00007f1bb40b0800 nid=0x2ab5 waiting on condition [0x0000000000000000]

   java.lang.Thread.State: RUNNABLE

"Finalizer" #3 daemon prio=8 os_prio=0 tid=0x00007f1bb4078800 nid=0x2ab4 in Object.wait() [0x00007f1ba1217000]

   java.lang.Thread.State: WAITING (on object monitor)

at java.lang.Object.wait(Native Method)

- waiting on <0x00000000e0c06f58> (a java.lang.ref.ReferenceQueue$Lock)

at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:143)

- locked <0x00000000e0c06f58> (a java.lang.ref.ReferenceQueue$Lock)

at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:164)

at java.lang.ref.Finalizer$FinalizerThread.run(Finalizer.java:209)

"Reference Handler" #2 daemon prio=10 os_prio=0 tid=0x00007f1bb4076800 nid=0x2ab3 in Object.wait() [0x00007f1ba1318000]

   java.lang.Thread.State: WAITING (on object monitor)

at java.lang.Object.wait(Native Method)

- waiting on <0x00000000e0c06998> (a java.lang.ref.Reference$Lock)

at java.lang.Object.wait(Object.java:502)

at java.lang.ref.Reference$ReferenceHandler.run(Reference.java:157)

- locked <0x00000000e0c06998> (a java.lang.ref.Reference$Lock)

"main" #1 prio=5 os_prio=0 tid=0x00007f1bb400a000 nid=0x2ab0 waiting on condition [0x00007f1bbbfcd000]

   java.lang.Thread.State: TIMED_WAITING (sleeping)

at java.lang.Thread.sleep(Native Method)

at vertx.Runner.main(Runner.java:12)

"VM Thread" os_prio=0 tid=0x00007f1bb4071800 nid=0x2ab2 runnable

"GC task thread#0 (ParallelGC)" os_prio=0 tid=0x00007f1bb401f000 nid=0x2ab1 runnable

"VM Periodic Task Thread" os_prio=0 tid=0x00007f1bb40bc800 nid=0x2ab9 waiting on condition

JNI global references: 423

Found one Java-level deadlock:

=============================

"vert.x-worker-thread-1":

  waiting to lock monitor 0x00007f1b98004d78 (object 0x00000000e29771e8, a io.vertx.core.http.impl.ServerConnection),

  which is held by "vert.x-eventloop-thread-0"

"vert.x-eventloop-thread-0":

  waiting to lock monitor 0x00007f1b98003778 (object 0x00000000e2977418, a io.vertx.core.http.impl.HttpServerResponseImpl),

  which is held by "vert.x-worker-thread-1"

Java stack information for the threads listed above:

===================================================

"vert.x-worker-thread-1":

at io.vertx.core.http.impl.ServerConnection.responseComplete(ServerConnection.java:145)

- waiting to lock <0x00000000e29771e8> (a io.vertx.core.http.impl.ServerConnection)

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

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

- locked <0x00000000e2977418> (a io.vertx.core.http.impl.HttpServerResponseImpl)

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

at vertx.AdminHandler.handle(AdminHandler.java:11)

at vertx.AdminHandler.handle(AdminHandler.java:7)

at io.vertx.ext.web.impl.BlockingHandlerDecorator.lambda$handle$71(BlockingHandlerDecorator.java:31)

at io.vertx.ext.web.impl.BlockingHandlerDecorator$$Lambda$15/566708161.handle(Unknown Source)

at io.vertx.core.impl.ContextImpl.lambda$executeBlocking$2(ContextImpl.java:266)

at io.vertx.core.impl.ContextImpl$$Lambda$17/1823208148.run(Unknown Source)

at io.vertx.core.impl.OrderedExecutorFactory$OrderedExecutor.lambda$new$202(OrderedExecutorFactory.java:91)

at io.vertx.core.impl.OrderedExecutorFactory$OrderedExecutor$$Lambda$1/124313277.run(Unknown Source)

at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)

at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)

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

"vert.x-eventloop-thread-0":

at io.vertx.core.http.impl.HttpServerResponseImpl.handleClosed(HttpServerResponseImpl.java:459)

- waiting to lock <0x00000000e2977418> (a io.vertx.core.http.impl.HttpServerResponseImpl)

at io.vertx.core.http.impl.ServerConnection.handleClosed(ServerConnection.java:336)

- locked <0x00000000e29771e8> (a io.vertx.core.http.impl.ServerConnection)

at io.vertx.core.net.impl.VertxHandler$$Lambda$23/993659812.run(Unknown Source)

at io.vertx.core.impl.ContextImpl.lambda$wrapTask$3(ContextImpl.java:310)

at io.vertx.core.impl.ContextImpl$$Lambda$4/2012232625.run(Unknown Source)

at io.vertx.core.impl.ContextImpl.executeFromIO(ContextImpl.java:204)

at io.vertx.core.net.impl.VertxHandler.channelInactive(VertxHandler.java:106)

at io.netty.channel.AbstractChannelHandlerContext.invokeChannelInactive(AbstractChannelHandlerContext.java:208)

at io.netty.channel.AbstractChannelHandlerContext.fireChannelInactive(AbstractChannelHandlerContext.java:194)

at io.netty.handler.stream.ChunkedWriteHandler.channelInactive(ChunkedWriteHandler.java:148)

at io.netty.channel.AbstractChannelHandlerContext.invokeChannelInactive(AbstractChannelHandlerContext.java:208)

at io.netty.channel.AbstractChannelHandlerContext.fireChannelInactive(AbstractChannelHandlerContext.java:194)

at io.netty.channel.ChannelInboundHandlerAdapter.channelInactive(ChannelInboundHandlerAdapter.java:75)

at io.netty.handler.codec.http.HttpContentEncoder.channelInactive(HttpContentEncoder.java:252)

at io.netty.channel.AbstractChannelHandlerContext.invokeChannelInactive(AbstractChannelHandlerContext.java:208)

at io.netty.channel.AbstractChannelHandlerContext.fireChannelInactive(AbstractChannelHandlerContext.java:194)

at io.netty.handler.codec.ByteToMessageDecoder.channelInactive(ByteToMessageDecoder.java:306)

at io.netty.channel.AbstractChannelHandlerContext.invokeChannelInactive(AbstractChannelHandlerContext.java:208)

at io.netty.channel.AbstractChannelHandlerContext.fireChannelInactive(AbstractChannelHandlerContext.java:194)

at io.netty.channel.DefaultChannelPipeline.fireChannelInactive(DefaultChannelPipeline.java:828)

at io.netty.channel.AbstractChannel$AbstractUnsafe$7.run(AbstractChannel.java:621)

at io.netty.util.concurrent.SingleThreadEventExecutor.runAllTasks(SingleThreadEventExecutor.java:357)

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

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

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

Found 1 deadlock.

Heap

 PSYoungGen      total 448000K, used 76801K [0x00000000e0c00000, 0x0000000100000000, 0x0000000100000000)

  eden space 384000K, 20% used [0x00000000e0c00000,0x00000000e5700550,0x00000000f8300000)

  from space 64000K, 0% used [0x00000000fc180000,0x00000000fc180000,0x0000000100000000)

  to   space 64000K, 0% used [0x00000000f8300000,0x00000000f8300000,0x00000000fc180000)

 ParOldGen       total 1024000K, used 0K [0x00000000a2400000, 0x00000000e0c00000, 0x00000000e0c00000)

  object space 1024000K, 0% used [0x00000000a2400000,0x00000000a2400000,0x00000000e0c00000)

 Metaspace       used 9900K, capacity 10120K, committed 10240K, reserved 1058816K

  class space    used 1187K, capacity 1252K, committed 1280K, reserved 1048576K

[Tim Fox]

I'm not convinced it's a kernel issue - but I think we should first
determine if it's a deadlock and if so, what is deadlocking.

If you could get the deadlock thread dumps (kill -3 or jhat) (assuming
it's a deadlock) and send them to me I will investigate further.

I want to get to the bottom of this as it doesn't appear to be an
isolated occurrence.

On 08/06/15 20:37, Igor Spasić wrote:
> uname -a
>
> Linux ip-10-158-150-199 *3.13.0-48-generic* #80-Ubuntu SMP Thu Mar 12

> 11:16:15 UTC 2015 x86_64 x86_64 x86_64 GNU/Linux
>
> sb_release -a
>
> No LSB modules are available.
> Distributor ID: Ubuntu
> Description: Ubuntu 14.04.2 LTS
> Release: 14.04
> Codename: trusty
>
>
> So its 3.13.... maybe kernel upgrade should be still performed.
>
>
> On Monday, June 8, 2015 at 9:29:23 PM UTC+2, Raphael Luta wrote:
>> If you’re running java 1.8 on ubuntu 14.04 on Haswell hardware, you’re
>> probably hitting the kernel futex bug introduced in kernel 3.14 and fixed
>> in 3.18.
>>
>> You can find a long discussion thread on this bug and its impact here:
>> https://groups.google.com/forum/#!topic/mechanical-sympathy/QbmpZxp6C64
>>
>> Upgrading kernel to release 3.19+ should fix the issue.
>>
>>

>>> Le 8 juin 2015 à 21:21, Tim Fox <timv...@gmail.com <javascript:>> a

>> an email to vertx+un...@googlegroups.com <javascript:>.

[Tim Fox]

Thanks - I can see what is happening now.

You are ending the response from the blocking handler using a worker
thread, this is causing the connection to be closed (probably curl is
using http 1.0 with no keep-alive header), and that gets executed on an
event loop thread and gets in before the end on the worker thread is
complete.

I need to think some more about how to resolve it.

[Igor Spasić]

Glad I could help - this seems exactly the problem.

We actually started to 'feel' this before, on OSX, but not so dramatical. When we start clicking on our UI we noticed that some requests simply get stuck (like there is a deadlock); but only on Amazon Ubuntu this issue appears so dramatical.

Thanks!

[Tim Fox]

Thanks, if it's any help you should be able to workaround the issue by
not using a blocking handler, but I'll work on a proper solution.

[Tim Fox]

Igor,

I have just committed a potential fix for this in master.

Could you please try it and see if it solves the problem?

On 08/06/15 21:45, Igor Spasić wrote:

[Igor Spasić]

Sure!

 It is not on snapshot right? I need to build jars manually?

[Tim Fox]

On 09/06/15 12:23, Igor Spasić wrote:
> Sure!
>
> It is not on snapshot right? I need to build jars manually?

It's just vertx-core (one jar)

git clone https://github.com/eclipse/vert.x
cd vert.x
mvn clean package

the jar will be created in the target directory

[Igor Spasić]

sure, just checking!

[Igor Spasić]

Looking good!

I've just tested it twice, and it works!!

Thank you! When do you build the next snapshot?

[Tim Fox]

Great.

Snapshots are built on CI so probably it's already been pushing.

CI is here https://vertx.ci.cloudbees.com/view/vert.x-3/job/vert.x3-core/