Find out why vertx was blocked during gis fe

nqminhuit commented 2 years ago

Mar 19, 2022 10:46:01 AM io.vertx.core.impl.BlockedThreadChecker
WARNING: Thread Thread[vert.x-eventloop-thread-0,5,main] has been blocked for 2992 ms, time limit is 2000 ms

WARNING: Thread Thread[vert.x-eventloop-thread-0,5,main] has been blocked for 5990 ms, time limit is 2000 ms
io.vertx.core.VertxException: Thread blocked
        at java.io.FileInputStream.readBytes(FileInputStream.java)
        at java.io.FileInputStream.read(FileInputStream.java:276)
        at java.io.BufferedInputStream.read1(BufferedInputStream.java:282)
        at java.io.BufferedInputStream.read(BufferedInputStream.java:343)
        at sun.nio.cs.StreamDecoder.readBytes(StreamDecoder.java:270)
        at sun.nio.cs.StreamDecoder.implRead(StreamDecoder.java:313)
        at sun.nio.cs.StreamDecoder.read(StreamDecoder.java:188)
        at java.io.InputStreamReader.read(InputStreamReader.java:177)
        at java.io.BufferedReader.fill(BufferedReader.java:162)
        at java.io.BufferedReader.readLine(BufferedReader.java:329)
        at java.io.BufferedReader.readLine(BufferedReader.java:396)
        at org.nqm.vertx.CommandVerticle.safelyPrint(CommandVerticle.java:69)
        at java.util.Optional.ifPresent(Optional.java:178)
        at org.nqm.vertx.CommandVerticle.lambda$start$1(CommandVerticle.java:59)
        at io.vertx.core.impl.future.FutureImpl$3.onSuccess(FutureImpl.java:141)
        at io.vertx.core.impl.future.FutureBase.lambda$emitSuccess$0(FutureBase.java:54)
        at io.netty.util.concurrent.AbstractEventExecutor.safeExecute(AbstractEventExecutor.java:164)
        at io.netty.util.concurrent.SingleThreadEventExecutor.runAllTasks(SingleThreadEventExecutor.java:469)
        at io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:503)
        at io.netty.util.concurrent.SingleThreadEventExecutor$4.run(SingleThreadEventExecutor.java:986)
        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:833)
        at com.oracle.svm.core.thread.JavaThreads.threadStartRoutine(JavaThreads.java:597)
        at com.oracle.svm.core.posix.thread.PosixJavaThreads.pthreadStartRoutine(PosixJavaThreads.java:194)

nqminhuit commented 2 years ago


Mar 30, 2022 8:45:43 AM io.vertx.core.impl.BlockedThreadChecker
WARNING: Thread Thread[vert.x-eventloop-thread-0,5,main] has been blocked for 6990 ms, time limit is 2000 ms
io.vertx.core.VertxException: Thread blocked
        at java.io.FileInputStream.readBytes(FileInputStream.java)
        at java.io.FileInputStream.read(FileInputStream.java:276)
        at java.io.BufferedInputStream.read1(BufferedInputStream.java:282)
        at java.io.BufferedInputStream.read(BufferedInputStream.java:343)
        at sun.nio.cs.StreamDecoder.readBytes(StreamDecoder.java:270)
        at sun.nio.cs.StreamDecoder.implRead(StreamDecoder.java:313)
        at sun.nio.cs.StreamDecoder.read(StreamDecoder.java:188)
        at java.io.InputStreamReader.read(InputStreamReader.java:177)
        at java.io.BufferedReader.fill(BufferedReader.java:162)
        at java.io.BufferedReader.readLine(BufferedReader.java:329)
        at java.io.BufferedReader.readLine(BufferedReader.java:396)
        at org.nqm.vertx.CommandVerticle.safelyPrint(CommandVerticle.java:69)
        at java.util.Optional.ifPresent(Optional.java:178)
        at org.nqm.vertx.CommandVerticle.lambda$start$1(CommandVerticle.java:59)
        at io.vertx.core.impl.future.FutureImpl$3.onSuccess(FutureImpl.java:141)
        at io.vertx.core.impl.future.FutureBase.lambda$emitSuccess$0(FutureBase.java:54)
        at io.netty.util.concurrent.AbstractEventExecutor.safeExecute(AbstractEventExecutor.java:164)
        at io.netty.util.concurrent.SingleThreadEventExecutor.runAllTasks(SingleThreadEventExecutor.java:469)
        at io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:503)
        at io.netty.util.concurrent.SingleThreadEventExecutor$4.run(SingleThreadEventExecutor.java:986)
        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:833)
        at com.oracle.svm.core.thread.JavaThreads.threadStartRoutine(JavaThreads.java:597)
        at com.oracle.svm.core.posix.thread.PosixJavaThreads.pthreadStartRoutine(PosixJavaThreads.java:194)

Mar 30, 2022 8:45:44 AM io.vertx.core.impl.BlockedThreadChecker
WARNING: Thread Thread[vert.x-eventloop-thread-0,5,main] has been blocked for 7990 ms, time limit is 2000 ms
io.vertx.core.VertxException: Thread blocked
        at java.io.FileInputStream.readBytes(FileInputStream.java)
        at java.io.FileInputStream.read(FileInputStream.java:276)
        at java.io.BufferedInputStream.read1(BufferedInputStream.java:282)
        at java.io.BufferedInputStream.read(BufferedInputStream.java:343)
        at sun.nio.cs.StreamDecoder.readBytes(StreamDecoder.java:270)
        at sun.nio.cs.StreamDecoder.implRead(StreamDecoder.java:313)
        at sun.nio.cs.StreamDecoder.read(StreamDecoder.java:188)
        at java.io.InputStreamReader.read(InputStreamReader.java:177)
        at java.io.BufferedReader.fill(BufferedReader.java:162)
        at java.io.BufferedReader.readLine(BufferedReader.java:329)
        at java.io.BufferedReader.readLine(BufferedReader.java:396)
        at org.nqm.vertx.CommandVerticle.safelyPrint(CommandVerticle.java:69)
        at java.util.Optional.ifPresent(Optional.java:178)
        at org.nqm.vertx.CommandVerticle.lambda$start$1(CommandVerticle.java:59)
        at io.vertx.core.impl.future.FutureImpl$3.onSuccess(FutureImpl.java:141)
        at io.vertx.core.impl.future.FutureBase.lambda$emitSuccess$0(FutureBase.java:54)
        at io.netty.util.concurrent.AbstractEventExecutor.safeExecute(AbstractEventExecutor.java:164)
        at io.netty.util.concurrent.SingleThreadEventExecutor.runAllTasks(SingleThreadEventExecutor.java:469)
        at io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:503)
        at io.netty.util.concurrent.SingleThreadEventExecutor$4.run(SingleThreadEventExecutor.java:986)
        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:833)
        at com.oracle.svm.core.thread.JavaThreads.threadStartRoutine(JavaThreads.java:597)
        at com.oracle.svm.core.posix.thread.PosixJavaThreads.pthreadStartRoutine(PosixJavaThreads.java:194)

nqminhuit commented 2 years ago

with the verbose mode enabled:

$ gis fe -v
[DEBUG] executing command '/usr/bin/git fetch' under directory '...a'
[DEBUG] executing command '/usr/bin/git fetch' under directory '...b'
[DEBUG] executing command '/usr/bin/git fetch' under directory '...c'
[DEBUG] executing command '/usr/bin/git fetch' under directory '...d'
[DEBUG] executing command '/usr/bin/git fetch' under directory '...e'
[DEBUG] executing command '/usr/bin/git fetch' under directory '...f'
[DEBUG] executing command '/usr/bin/git fetch' under directory '...g'
Apr 03, 2022 12:57:02 PM io.vertx.core.impl.BlockedThreadChecker
WARNING: Thread Thread[vert.x-eventloop-thread-0,5,main] has been blocked for 2998 ms, time limit is 2000 ms
Apr 03, 2022 12:57:03 PM io.vertx.core.impl.BlockedThreadChecker
WARNING: Thread Thread[vert.x-eventloop-thread-0,5,main] has been blocked for 3998 ms, time limit is 2000 ms
...

git fetch takes very long time to execute, we can see that all of the modules has deployed the verticle
the blocking code is because the BufferedReader is waiting for fetch results.
a proper fix is to deploy a verticle for the buffered reader. Due to limited knowledge of Vertx, there can be no fix at the moment,
only to increase the time limit warning in Vertx.

nqminhuit commented 3 months ago

after the switch from VertX to Virtual Threads: #80, this bug is invalid

nqminhuit / gis

Find out why vertx was blocked during gis fe #16