vertx blocking threads logging

[Gadi Eichhorn]

I have this vertx project running in Docker on the slow Raspberry PI as a miniserver to connect few sensors.

I am getting threads blocking warrnings from vertx-thread-pool.

is there a way to ask vertx to log which part of the code is blocking?  A generic flag I can apply to the project.

I might have different parts of the app blocking.

In casses I am calling external service I use executeblocking  block.

Running on a normal hardware (laptop) I dont get any issues even with 10 times the load.

[Gadi Eichhorn]

typical error message is:

19:02:41.839 [vertx-blocked-thread-checker] WARN io.vertx.core.impl.BlockedThreadChecker - Thread Thread[vert.x-eventloop-thread-0,5,main] has been blocked for 2242 ms, time limit is 2000

Is there a way to find the class from where the block happens?

I have many verticals and not easy to pinpoint the issue?

any advise?

G.

[Julien Viet]

Hi,

the checker prints stack trace after 5 seconds you can lower this threshold with a lower VertxOptions#warningExceptionTime value

Julien

--
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.
Visit this group at https://groups.google.com/group/vertx.
To view this discussion on the web, visit https://groups.google.com/d/msgid/vertx/9566adf9-ca57-40c1-b9db-3470d98b5040%40googlegroups.com.
For more options, visit https://groups.google.com/d/optout.

[Gadi Eichhorn]

thanks Julien,

Is there a way to see  which part of the code is blocking?

G.

[Julien Viet]

it will print a java stack trace where the blocking was captured.

To view this discussion on the web, visit https://groups.google.com/d/msgid/vertx/386bbf25-bc40-44ce-a575-28275f7a5727%40googlegroups.com.

[Gadi Eichhorn]

I dont see any stack trace, do I need to set something before?

08:59:59.109 [vertx-blocked-thread-checker] WARN  io.vertx.core.impl.BlockedThreadChecker - Thread Thread[vert.x-eventloop-thread-4,5,main] has been blocked for 2732 ms, time limit is 2000

09:00:00.115 [vertx-blocked-thread-checker] WARN  io.vertx.core.impl.BlockedThreadChecker - Thread Thread[vert.x-eventloop-thread-4,5,main] has been blocked for 3746 ms, time limit is 2000

09:00:01.116 [vertx-blocked-thread-checker] WARN  io.vertx.core.impl.BlockedThreadChecker - Thread Thread[vert.x-eventloop-thread-4,5,main] has been blocked for 4747 ms, time limit is 2000

[Julien Viet]

did you change the warning time to 2 seconds ?

To view this discussion on the web, visit https://groups.google.com/d/msgid/vertx/64ff8a74-d300-4c24-8f1f-ce2b4deee4a2%40googlegroups.com.

[Alexander Lehmann]

the limits for warning without and warning with stack trace are 2 and 5 seconds, if your blocking issue is finished after 4,7 seconds, the stack trace will not be shown. If you set the stack trace block time limit to 2 seconds, it will be printed each time the warning is printed. You can set this with .setWarningExceptionTime(TimeUnit.SECONDS.toNanos(2)) on your VertxOptions, then the stacktrace should be shown each time you see the warning.

[Gadi Eichhorn]

Bingo! thanks Alexander ;)

[Julien Viet]

I think that's what I said, twice :-)

To view this discussion on the web, visit https://groups.google.com/d/msgid/vertx/bca0a756-aaba-46fb-ac1b-89ed59c102bd%40googlegroups.com.

[Gadi Eichhorn]

After setting the Warning Exception Time I get this exception (on Raspberry PI docker). Any idea what is blocking? Thanks.

dcb_1         | Nov 27, 2018 8:06:45 PM io.vertx.core.impl.BlockedThreadChecker
dcb_1         | WARNING: Thread Thread[vert.x-eventloop-thread-0,5,main] has been blocked for 2090 ms, time limit is 2000
dcb_1         | Nov 27, 2018 8:06:46 PM io.vertx.core.impl.BlockedThreadChecker
dcb_1         | WARNING: Thread Thread[vert.x-eventloop-thread-0,5,main] has been blocked for 3090 ms, time limit is 2000
dcb_1         | Nov 27, 2018 8:06:47 PM io.vertx.core.impl.BlockedThreadChecker
dcb_1         | WARNING: Thread Thread[vert.x-eventloop-thread-0,5,main] has been blocked for 4090 ms, time limit is 2000
dcb_1         | Nov 27, 2018 8:06:48 PM io.vertx.mqtt.impl.MqttClientImpl
dcb_1         | INFO: Connection with 192.168.14.187:1883 established successfully
dcb_1         | Nov 27, 2018 8:06:48 PM io.vertx.core.impl.BlockedThreadChecker
dcb_1         | WARNING: Thread Thread[vert.x-eventloop-thread-0,5,main] has been blocked for 5090 ms, time limit is 2000
dcb_1         | io.vertx.core.VertxException: Thread blocked
dcb_1         | at java.io.ByteArrayInputStream.read(ByteArrayInputStream.java:144)
dcb_1         | at java.io.DataInputStream.readInt(DataInputStream.java:389)
dcb_1         | at sun.text.normalizer.IntTrie.unserialize(IntTrie.java:146)
dcb_1         | at sun.text.normalizer.Trie.<init>(Trie.java:135)
dcb_1         | at sun.text.normalizer.IntTrie.<init>(IntTrie.java:69)
dcb_1         | at sun.text.normalizer.NormalizerImpl.<init>(NormalizerImpl.java:284)
dcb_1         | at sun.text.normalizer.NormalizerImpl.<clinit>(NormalizerImpl.java:56)
dcb_1         | at sun.net.idn.StringPrep.<init>(StringPrep.java:230)
dcb_1         | at java.net.IDN.<clinit>(IDN.java:240)
dcb_1         | at io.netty.resolver.dns.DnsNameResolver.hostname(DnsNameResolver.java:818)
dcb_1         | at io.netty.resolver.dns.DnsNameResolver.doResolve(DnsNameResolver.java:585)
dcb_1         | at io.netty.resolver.dns.DnsNameResolver.doResolve(DnsNameResolver.java:527)
dcb_1         | at io.netty.resolver.SimpleNameResolver.resolve(SimpleNameResolver.java:63)
dcb_1         | at io.netty.resolver.dns.InflightNameResolver.resolve(InflightNameResolver.java:100)
dcb_1         | at io.netty.resolver.dns.InflightNameResolver.resolve(InflightNameResolver.java:66)
dcb_1         | at io.netty.resolver.dns.InflightNameResolver.resolve(InflightNameResolver.java:51)
dcb_1         | at io.netty.resolver.InetSocketAddressResolver.doResolve(InetSocketAddressResolver.java:57)
dcb_1         | at io.netty.resolver.InetSocketAddressResolver.doResolve(InetSocketAddressResolver.java:32)
dcb_1         | at io.netty.resolver.AbstractAddressResolver.resolve(AbstractAddressResolver.java:108)
dcb_1         | at io.netty.bootstrap.Bootstrap.doResolveAndConnect0(Bootstrap.java:208)
dcb_1         | at io.netty.bootstrap.Bootstrap.doResolveAndConnect(Bootstrap.java:170)
dcb_1         | at io.netty.bootstrap.Bootstrap.connect(Bootstrap.java:145)
dcb_1         | at io.vertx.core.net.impl.ChannelProvider.connect(ChannelProvider.java:49)
dcb_1         | at io.vertx.core.net.impl.NetClientImpl.doConnect(NetClientImpl.java:230)
dcb_1         | at io.vertx.core.net.impl.NetClientImpl.doConnect(NetClientImpl.java:165)
dcb_1         | at io.vertx.core.net.impl.NetClientImpl.connect(NetClientImpl.java:160)
dcb_1         | at io.vertx.redis.impl.RedisConnection.connect(RedisConnection.java:139)
dcb_1         | at io.netty.util.concurrent.SingleThreadEventExecutor$5.run(SingleThreadEventExecutor.java:886)
dcb_1         | at io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30)
dcb_1         | at java.lang.Thread.run(Thread.java:748)

[Julien Viet]

it seems that you are using the java DNS resolver that is blocking using the system property that disables the non-blocking resolver.

Julien

To view this discussion on the web, visit https://groups.google.com/d/msgid/vertx/237942d1-f30d-419f-96d3-61fb941a628a%40googlegroups.com.

[Gadi Eichhorn]

Thanks, Julien

I am running Vertx inside Docker (Raspberry PI) how can I fix this issue?

I have 2 TCP servers. 

Thanks.

G.

[Julien Viet]

have you set the vertx.disableDnsResolver

 

system property ?

To view this discussion on the web, visit https://groups.google.com/d/msgid/vertx/438ec7f2-8306-47a5-a839-b3b567e23b3e%40googlegroups.com.

[Gadi Eichhorn]

Magic! that worked :) thanks.