В предыдущей статье этой серии мы рассмотрели несколько методов, которые помогут вам предотвратить задержки цикла событий; однако даже лучший программист допускает ошибки. Что делать, если приложение Vert.x не работает должным образом? Как узнать, какая часть вашего кода блокирует потоки цикла событий? В заключительной части этой серии мы сосредоточимся на устранении задержек в цикле событий.
Модель потока цикла событий сильно отличается от модели потока на запрос, используемой стандартными средами JEE или Spring. Исходя из моего опыта, я могу сообщить, что разработчикам требуется некоторое время, чтобы обдумать это, и что вначале они склонны делать ошибку, вводя блокирующие вызовы в путь кода цикла событий. В следующих разделах мы обсудим несколько методов устранения неполадок в таких ситуациях.
Проверка заблокированной нити
Vert.x поставляется со встроенным механизмом обнаружения задержек в цикле событий и рабочих потоках путем проверки времени выполнения обработчиков, которые вы зарегистрировали с помощью API-интерфейсов Vert.x. Этот механизм работает в два этапа. На первом этапе Vert.x сохраняет временную метку момента, когда начинается выполнение обработчика. Эта временная метка запуска сохраняется в хранилище, прикрепленном к потоку, выполняющему обработчик. Всякий раз, когда выполнение обработчика завершено, отметка времени сбрасывается. На втором этапе Vert.x периодически проверяет временные метки, используя выделенный поток, который называется vertx-blocked-thread-checker. Этот поток порождается Vert.x при создании экземпляра Vert.x, например, при вызове Vertx.vertx(). Поток vertx-block-thread-checker можно увидеть в VisualVM :
Средство проверки заблокированных потоков служит средством контроля, которое периодически проверяет потоки Vert.x. Он перебирает все потоки Vert.x и для каждого потока вычитает метку времени начала потоков из текущего времени, чтобы вычислить, как долго поток уже выполнял код обработчика. Если время выполнения превышает указанный порог, в журналы сбрасывается предупреждающее сообщение:
Mar 01, 2019 11:53:24 AM io.vertx.core.impl.BlockedThreadChecker
WARNING: Thread Thread[vert.x-eventloop-thread-5,5,main] has been blocked for 39 ms, time limit is 10 ms
Mar 01, 2019 11:53:24 AM io.vertx.core.impl.BlockedThreadChecker
WARNING: Thread Thread[vert.x-eventloop-thread-6,5,main] has been blocked for 26 ms, time limit is 10 ms
Mar 01, 2019 11:53:24 AM io.vertx.core.impl.BlockedThreadChecker
WARNING: Thread Thread[vert.x-eventloop-thread-1,5,main] has been blocked for 31 ms, time limit is 10 ms
Mar 01, 2019 11:53:24 AM io.vertx.core.impl.BlockedThreadChecker
WARNING: Thread Thread[vert.x-eventloop-thread-3,5,main] has been blocked for 42 ms, time limit is 10 ms
Mar 01, 2019 11:53:24 AM io.vertx.core.impl.BlockedThreadChecker
WARNING: Thread Thread[vert.x-eventloop-thread-2,5,main] has been blocked for 20 ms, time limit is 10 ms
Mar 01, 2019 11:53:24 AM io.vertx.core.impl.BlockedThreadChecker
WARNING: Thread Thread[vert.x-eventloop-thread-4,5,main] has been blocked for 21 ms, time limit is 10 ms
Mar 01, 2019 11:53:24 AM io.vertx.core.impl.BlockedThreadChecker
WARNING: Thread Thread[vert.x-eventloop-thread-7,5,main] has been blocked for 19 ms, time limit is 10 msВы можете использовать grep для обычного поиска в журналах вашего приложения этого сообщения. Vert.x также может регистрировать всю трассировку стека, чтобы помочь вам определить местоположение в вашем коде, где ваш обработчик блокирует поток:
Mar 24, 2019 9:34:23 AM io.vertx.core.impl.BlockedThreadChecker
WARNING: Thread Thread[vert.x-eventloop-thread-6,5,main] has been blocked for 24915 ms, time limit is 10 ms
io.vertx.core.VertxException: Thread blocked
at java.lang.Thread.sleep(Native Method)
at MyComputingVerticle.start(HelloServer.java:72)
at io.vertx.core.impl.DeploymentManager.lambda$doDeploy$8(DeploymentManager.java:494)
at io.vertx.core.impl.DeploymentManager$$Lambda$8/644460953.handle(Unknown Source)
at io.vertx.core.impl.ContextImpl.executeTask(ContextImpl.java:320)
at io.vertx.core.impl.EventLoopContext.lambda$executeAsync$0(EventLoopContext.java:38)
at io.vertx.core.impl.EventLoopContext$$Lambda$9/1778535015.run(Unknown Source)
at io.netty.util.concurrent.AbstractEventExecutor.safeExecute(AbstractEventExecutor.java:163)
at io.netty.util.concurrent.SingleThreadEventExecutor.runAllTasks(SingleThreadEventExecutor.java:404)
at io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:462)
at io.netty.util.concurrent.SingleThreadEventExecutor$5.run(SingleThreadEventExecutor.java:897)
at io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30)
at java.lang.Thread.run(Thread.java:748)Обратите внимание, что трассировка стека генерируется в тот момент, когда Vert.x обнаруживает, что пороговое значение превышено, что не обязательно является моментом, когда поток фактически блокировался. Другими словами, это вероятно, но не гарантируется, что трассировка стека показывает фактическое местоположение, где блокируется ваш цикл обработки событий. Возможно, вам придется изучить несколько трасс стека, чтобы определить правильное местоположение.
Вы можете настроить период проверки сторожевого таймера и пороги предупреждения. Вот пример:
VertxOptions options = new VertxOptions();
// check for blocked threads every 5s
options.setBlockedThreadCheckInterval(5);
options.setBlockedThreadCheckIntervalUnit(TimeUnit.SECONDS);
// warn if an event loop thread handler took more than 100ms to execute
options.setMaxEventLoopExecuteTime(100);
options.setMaxEventLoopExecuteTimeUnit(TimeUnit.MILLISECONDS);
// warn if an worker thread handler took more than 10s to execute
options.setMaxWorkerExecuteTime(10);
options.setMaxWorkerExecuteTimeUnit(TimeUnit.SECONDS);
// log the stack trace if an event loop or worker handler took more than 20s to execute
options.setWarningExceptionTime(20);
options.setWarningExceptionTimeUnit(TimeUnit.SECONDS);
Vertx vertx = Vertx.vertx(options);Обратите внимание, что первая проверка не выполняется сразу при запуске приложения, а задерживается на один период проверки. В нашем примере первая проверка выполняется через 5 секунд после запуска приложения, за которой следуют проверки, выполняемые каждые 5 секунд. Конкретные пороги, показанные в примере, хорошо сработали для одного из моих проектов, однако ваш пробег может отличаться. Кроме того, первое выполнение обработчиков может быть довольно медленным из-за загрузки класса JVM. Производительность дополнительно улучшается, когда JVM переходит от интерпретации байтового кода к компиляции его в собственный код и запуска непосредственно на ЦП. Следовательно, вы скорее всего достигнете пороговых значений для предупреждения вскоре после запуска приложения, чем позже во время его запуска. Было бы здорово, если бы пороговые значения можно было динамически регулировать, чтобы избежать предупреждений до того, как JVM прогреется.К сожалению, нет способа, как настроить пороги во время выполнения.
Само собой разумеется, что Vert.x проверяет только те потоки, которые были созданы в результате вызова API-интерфейсов Vert.x. Если вы создадите свой собственный пул потоков вне Vert.x, эти потоки не будут проверены. Если вы хотите, чтобы Vert.x проверял потоки в вашем пользовательском пуле потоков, вы можете попросить Vert.x создать для вас проверенный пул потоков следующим образом:
// create a thread pool with 20 threads, set blocked thread warning threshold to 10 seconds
WorkerExecutor executor = vertx.createSharedWorkerExecutor("mypool", 20, 10, TimeUnit.SECONDS);Хорошая вещь о контролере заблокированных потоков состоит в том, что он может обнаруживать задержки потоков независимо от того, были ли они вызваны вызовом блокирующего API или выполнением задачи, требующей больших вычислительных ресурсов. Таким образом, это может служить хорошим индикатором того, что с вашим приложением что-то серьезно не так.
Проверка следов стека
Some event loop delays can be so subtle that they can go unnoticed by the blocked thread checker. Imagine a situation where you have a handler that causes a very short delay. The blocked thread checker won’t catch this short delay because it is not long enough to reach the threshold; however, if this handler is called very frequently, the aggregate delay caused by this handler can have a great impact on the performance of your application. How to uncover this kind of issue?
A good option is to analyze Java thread dumps by hand. You can refer to this article if you want to learn how to do it. Alternatively, you can use a Java profiler like VisualVM to find out in what parts of your code the most processing time is spent. Instead of writing long prose about how to use VisualVM to troubleshoot a Vert.x application, I created a short video for you. You can watch this demo using JMeter and VisualVM to figure out the cause of delays of the Vert.x event loop:
Conclusion
In this article, we talked about the blocked thread checker as a first indicator of the event loop delays. Next, I showed you in the video how to troubleshoot event loop delays in practice using VisualVM.
I hope that I didn’t scare you throughout this series by analyzing all the things that can go wrong when working with the thread model Vert.x is based on. In reality, it’s not so bad. One just has to pay attention to the event loop model while coding. The awesome performance that Vert.x applications can achieve is definitely a sufficient reward for the extra effort.
If you got some battle scars while working with the event loop thread model in Vert.x, I would be interested in hearing your stories. Also, let me know if you found the video demonstration helpful or if you have suggestions for future videos.
If you have any further questions or comments, feel free to add them to the comment section below.