Vertx thread blocked warnings

1
votes

I am running a vert.x application on ubuntu server. It has an HTTPServer running on port 3000. Application is working fine but sometimes I am seeing following warnings:

Dec 08, 2017 1:23:43 AM io.vertx.core.impl.BlockedThreadChecker
WARNING: Thread Thread[vert.x-worker-thread-2,5,main] has been blocked for 138013 ms, time limit is 60000
io.vertx.core.VertxException: Thread blocked
    at java.io.FileInputStream.readBytes(Native Method)
    at java.io.FileInputStream.read(FileInputStream.java:255)
    at sun.security.provider.NativePRNG$RandomIO.readFully(NativePRNG.java:424)
    at sun.security.provider.NativePRNG$RandomIO.implGenerateSeed(NativePRNG.java:441)
    at sun.security.provider.NativePRNG$RandomIO.access$500(NativePRNG.java:331)
    at sun.security.provider.NativePRNG.engineGenerateSeed(NativePRNG.java:226)
    at java.security.SecureRandom.generateSeed(SecureRandom.java:533)
    at io.vertx.ext.auth.PRNG.lambda$null$0(PRNG.java:78)
    at io.vertx.ext.auth.PRNG$$Lambda$204/767088095.handle(Unknown Source)
    at io.vertx.core.impl.ContextImpl.lambda$executeBlocking$1(ContextImpl.java:271)
    at io.vertx.core.impl.ContextImpl$$Lambda$206/1202956360.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)

Dec 08, 2017 1:23:44 AM io.vertx.core.impl.BlockedThreadChecker
WARNING: Thread Thread[vert.x-worker-thread-2,5,main] has been blocked for 139014 ms, time limit is 60000
io.vertx.core.VertxException: Thread blocked
    at java.io.FileInputStream.readBytes(Native Method)
    at java.io.FileInputStream.read(FileInputStream.java:255)
    at sun.security.provider.NativePRNG$RandomIO.readFully(NativePRNG.java:424)
    at sun.security.provider.NativePRNG$RandomIO.implGenerateSeed(NativePRNG.java:441)
    at sun.security.provider.NativePRNG$RandomIO.access$500(NativePRNG.java:331)
    at sun.security.provider.NativePRNG.engineGenerateSeed(NativePRNG.java:226)
    at java.security.SecureRandom.generateSeed(SecureRandom.java:533)
    at io.vertx.ext.auth.PRNG.lambda$null$0(PRNG.java:78)
    at io.vertx.ext.auth.PRNG$$Lambda$204/767088095.handle(Unknown Source)
    at io.vertx.core.impl.ContextImpl.lambda$executeBlocking$1(ContextImpl.java:271)
    at io.vertx.core.impl.ContextImpl$$Lambda$206/1202956360.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)

Dec 08, 2017 1:23:45 AM io.vertx.core.impl.BlockedThreadChecker
WARNING: Thread Thread[vert.x-worker-thread-2,5,main] has been blocked for 140013 ms, time limit is 60000
io.vertx.core.VertxException: Thread blocked
    at java.io.FileInputStream.readBytes(Native Method)
    at java.io.FileInputStream.read(FileInputStream.java:255)
    at sun.security.provider.NativePRNG$RandomIO.readFully(NativePRNG.java:424)
    at sun.security.provider.NativePRNG$RandomIO.implGenerateSeed(NativePRNG.java:441)
    at sun.security.provider.NativePRNG$RandomIO.access$500(NativePRNG.java:331)
    at sun.security.provider.NativePRNG.engineGenerateSeed(NativePRNG.java:226)
    at java.security.SecureRandom.generateSeed(SecureRandom.java:533)
    at io.vertx.ext.auth.PRNG.lambda$null$0(PRNG.java:78)
    at io.vertx.ext.auth.PRNG$$Lambda$204/767088095.handle(Unknown Source)
    at io.vertx.core.impl.ContextImpl.lambda$executeBlocking$1(ContextImpl.java:271)
    at io.vertx.core.impl.ContextImpl$$Lambda$206/1202956360.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)

Dec 08, 2017 1:23:46 AM io.vertx.core.impl.BlockedThreadChecker
WARNING: Thread Thread[vert.x-worker-thread-2,5,main] has been blocked for 141013 ms, time limit is 60000
io.vertx.core.VertxException: Thread blocked
    at java.io.FileInputStream.readBytes(Native Method)
    at java.io.FileInputStream.read(FileInputStream.java:255)
    at sun.security.provider.NativePRNG$RandomIO.readFully(NativePRNG.java:424)
    at sun.security.provider.NativePRNG$RandomIO.implGenerateSeed(NativePRNG.java:441)
    at sun.security.provider.NativePRNG$RandomIO.access$500(NativePRNG.java:331)
    at sun.security.provider.NativePRNG.engineGenerateSeed(NativePRNG.java:226)
    at java.security.SecureRandom.generateSeed(SecureRandom.java:533)
    at io.vertx.ext.auth.PRNG.lambda$null$0(PRNG.java:78)
    at io.vertx.ext.auth.PRNG$$Lambda$204/767088095.handle(Unknown Source)
    at io.vertx.core.impl.ContextImpl.lambda$executeBlocking$1(ContextImpl.java:271)
    at io.vertx.core.impl.ContextImpl$$Lambda$206/1202956360.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)

Dec 08, 2017 1:23:47 AM io.vertx.core.impl.BlockedThreadChecker
WARNING: Thread Thread[vert.x-worker-thread-2,5,main] has been blocked for 142013 ms, time limit is 60000
io.vertx.core.VertxException: Thread blocked
    at java.io.FileInputStream.readBytes(Native Method)
    at java.io.FileInputStream.read(FileInputStream.java:255)
    at sun.security.provider.NativePRNG$RandomIO.readFully(NativePRNG.java:424)
    at sun.security.provider.NativePRNG$RandomIO.implGenerateSeed(NativePRNG.java:441)
    at sun.security.provider.NativePRNG$RandomIO.access$500(NativePRNG.java:331)
    at sun.security.provider.NativePRNG.engineGenerateSeed(NativePRNG.java:226)
    at java.security.SecureRandom.generateSeed(SecureRandom.java:533)
    at io.vertx.ext.auth.PRNG.lambda$null$0(PRNG.java:78)
    at io.vertx.ext.auth.PRNG$$Lambda$204/767088095.handle(Unknown Source)
    at io.vertx.core.impl.ContextImpl.lambda$executeBlocking$1(ContextImpl.java:271)
    at io.vertx.core.impl.ContextImpl$$Lambda$206/1202956360.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)

Dec 08, 2017 1:23:48 AM io.vertx.core.impl.BlockedThreadChecker
WARNING: Thread Thread[vert.x-worker-thread-2,5,main] has been blocked for 143013 ms, time limit is 60000
io.vertx.core.VertxException: Thread blocked
    at java.io.FileInputStream.readBytes(Native Method)
    at java.io.FileInputStream.read(FileInputStream.java:255)
    at sun.security.provider.NativePRNG$RandomIO.readFully(NativePRNG.java:424)
    at sun.security.provider.NativePRNG$RandomIO.implGenerateSeed(NativePRNG.java:441)
    at sun.security.provider.NativePRNG$RandomIO.access$500(NativePRNG.java:331)
    at sun.security.provider.NativePRNG.engineGenerateSeed(NativePRNG.java:226)
    at java.security.SecureRandom.generateSeed(SecureRandom.java:533)
    at io.vertx.ext.auth.PRNG.lambda$null$0(PRNG.java:78)
    at io.vertx.ext.auth.PRNG$$Lambda$204/767088095.handle(Unknown Source)
    at io.vertx.core.impl.ContextImpl.lambda$executeBlocking$1(ContextImpl.java:271)
    at io.vertx.core.impl.ContextImpl$$Lambda$206/1202956360.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)

Dec 08, 2017 1:23:49 AM io.vertx.core.impl.BlockedThreadChecker
WARNING: Thread Thread[vert.x-worker-thread-2,5,main] has been blocked for 144013 ms, time limit is 60000
io.vertx.core.VertxException: Thread blocked
    at java.io.FileInputStream.readBytes(Native Method)
    at java.io.FileInputStream.read(FileInputStream.java:255)
    at sun.security.provider.NativePRNG$RandomIO.readFully(NativePRNG.java:424)
    at sun.security.provider.NativePRNG$RandomIO.implGenerateSeed(NativePRNG.java:441)
    at sun.security.provider.NativePRNG$RandomIO.access$500(NativePRNG.java:331)
    at sun.security.provider.NativePRNG.engineGenerateSeed(NativePRNG.java:226)
    at java.security.SecureRandom.generateSeed(SecureRandom.java:533)
    at io.vertx.ext.auth.PRNG.lambda$null$0(PRNG.java:78)
    at io.vertx.ext.auth.PRNG$$Lambda$204/767088095.handle(Unknown Source)
    at io.vertx.core.impl.ContextImpl.lambda$executeBlocking$1(ContextImpl.java:271)
    at io.vertx.core.impl.ContextImpl$$Lambda$206/1202956360.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)

Dec 08, 2017 1:23:50 AM io.vertx.core.impl.BlockedThreadChecker
WARNING: Thread Thread[vert.x-worker-thread-2,5,main] has been blocked for 145013 ms, time limit is 60000
io.vertx.core.VertxException: Thread blocked
    at java.io.FileInputStream.readBytes(Native Method)
    at java.io.FileInputStream.read(FileInputStream.java:255)
    at sun.security.provider.NativePRNG$RandomIO.readFully(NativePRNG.java:424)
    at sun.security.provider.NativePRNG$RandomIO.implGenerateSeed(NativePRNG.java:441)
    at sun.security.provider.NativePRNG$RandomIO.access$500(NativePRNG.java:331)
    at sun.security.provider.NativePRNG.engineGenerateSeed(NativePRNG.java:226)
    at java.security.SecureRandom.generateSeed(SecureRandom.java:533)
    at io.vertx.ext.auth.PRNG.lambda$null$0(PRNG.java:78)
    at io.vertx.ext.auth.PRNG$$Lambda$204/767088095.handle(Unknown Source)
    at io.vertx.core.impl.ContextImpl.lambda$executeBlocking$1(ContextImpl.java:271)
    at io.vertx.core.impl.ContextImpl$$Lambda$206/1202956360.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)

I am not able to understand what is causing these warnings to appear. At the time of warnings, the server was idle with 0 traffic on the application. Also, I am running a scheduler using vertx periodic, which makes query to mongo every 15 secs.

vertx.setPeriodic(15000, r -> someService.check()); // Every 15 seconds
2
vert.x
Please show the code in the .check(). It is possible for something in it to be blocking. For example in my case I was doing large json serialization which caused the Warnings. - Xargos

2 Answers

6
votes

It seems there is not enough entropy (server idle) to feed the PRNG. So instead of returning quickly the SecureRandom.generateSeed method blocks until it gets enough data.

Depending on your hardware, you may be able to speed up the process with rng-tools.

0
votes

Are you executing blocking api calls using vertx.executeBlocking() ? It appears to me you might have a blocking API call somewhere in your someService.check() or anywhere else