Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Feature: disable blocked thread warnings until application is started #1379

Open
mmindenhall opened this issue Apr 14, 2016 · 21 comments
Open

Comments

@mmindenhall
Copy link

tl;dr: Following the "golden rule" during application startup and initialization may be unimportant. Therefore please provide a way to disable warnings until application is fully deployed and started.

The reason I am requesting this is because my company has a large vert.x 2 ruby application (ported from rails/sinatra) that is being upgraded to vert.x 3. We do a lot of pre-loading during application startup, and it would be difficult to make all of that asynchronous or wrapped with execute_blocking. We're getting the multiple warnings and large stacktrace during application startup.

But during application startup, I don't mind blocking the event loop, because there's no other work the application could be doing that's being blocked. Once verticles are started and accepting requests, I do want to see the warnings.

Therefore, I'd like to have some mechanism to disable event loop warnings/stacktraces until the application has been fully deployed.

A few ideas for how this could be done:

  1. Add more general disableBlockedThreadWarnings and enableBlockedThreadWarnings methods to Vertx. Those would call new setter on BlockedThreadChecker to set value on a final AtomicBoolean. Within the timer task run() method, check value before logging. I like this solution the best.
  2. Add a ready() (for example) method to Vertx, along with a new option to disable warnings until ready() is called. Less flexible, but same effect during application startup.
  3. Extract the 4 options that affect this (blockedThreadCheckInterval, maxEventLoopExecuteTime, maxWorkerExecuteTime, warningExceptionTime) into their own class, and provide a static instance with defaults. Provide a way to replace the instance at runtime.
@AshPlop
Copy link

AshPlop commented Feb 6, 2017

I have the same issue when starting multiple microservices on the same node at the same time.
When starting them one by one, everything is fine with the startup. The microservice load within 6 sec. But when starting them all at once, they start in 26 sec, mainly due to I/O waits (loading classes takes more time, checking JCE jar signature when building the EventBus also takes a lot more time).
Currently the number of dummy microservices you can start concurrently depends on the host's performance.
The thing is that we only need extra performances at startup and we don't need that much when the microservices are running.

2017-02-06 11:24:37 [WARN ] i.v.core.impl.BlockedThreadChecker - Thread Thread[vert.x-eventloop-thread-0,5,main] has been blocked for 5856 ms, time limit is 2000
io.vertx.core.VertxException: Thread blocked
        at sun.security.provider.DigestBase.implCompressMultiBlock(DigestBase.java:140)
        at sun.security.provider.DigestBase.engineUpdate(DigestBase.java:127)
        at java.security.MessageDigest$Delegate.engineUpdate(MessageDigest.java:584)
        at java.security.MessageDigest.update(MessageDigest.java:325)
        at sun.security.util.ManifestEntryVerifier.update(ManifestEntryVerifier.java:172)
        at java.util.jar.JarVerifier.update(JarVerifier.java:225)
        at java.util.jar.JarVerifier$VerifierStream.read(JarVerifier.java:479)
        at java.io.BufferedInputStream.read1(BufferedInputStream.java:284)
        at java.io.BufferedInputStream.read(BufferedInputStream.java:345)
        at javax.crypto.JarVerifier.verifySingleJar(JarVerifier.java:429)
        at javax.crypto.JarVerifier.verifyJars(JarVerifier.java:322)
        at javax.crypto.JarVerifier.verify(JarVerifier.java:250)
        at javax.crypto.JceSecurity.verifyProviderJar(JceSecurity.java:160)
        at javax.crypto.JceSecurity.getVerificationResult(JceSecurity.java:186)
        at javax.crypto.JceSecurity.canUseProvider(JceSecurity.java:200)
        at javax.crypto.Cipher.getInstance(Cipher.java:515)
        at sun.security.ssl.JsseJce.getCipher(JsseJce.java:229)
        at sun.security.ssl.CipherBox.<init>(CipherBox.java:179)
        at sun.security.ssl.CipherBox.newCipherBox(CipherBox.java:263)
        at sun.security.ssl.CipherSuite$BulkCipher.newCipher(CipherSuite.java:505)
        at sun.security.ssl.CipherSuite$BulkCipher.isAvailable(CipherSuite.java:572)
        at sun.security.ssl.CipherSuite$BulkCipher.isAvailable(CipherSuite.java:527)
        at sun.security.ssl.CipherSuite.isAvailable(CipherSuite.java:194)
        at sun.security.ssl.SSLContextImpl.getApplicableCipherSuiteList(SSLContextImpl.java:346)
        at sun.security.ssl.SSLContextImpl.getDefaultCipherSuiteList(SSLContextImpl.java:297)
        at sun.security.ssl.SSLEngineImpl.init(SSLEngineImpl.java:402)
        at sun.security.ssl.SSLEngineImpl.<init>(SSLEngineImpl.java:349)
        at sun.security.ssl.SSLContextImpl.engineCreateSSLEngine(SSLContextImpl.java:201)
        at javax.net.ssl.SSLContext.createSSLEngine(SSLContext.java:329)
        at io.vertx.core.net.impl.SSLHelper.<clinit>(SSLHelper.java:109)
        at io.vertx.core.net.impl.NetServerImpl.<init>(NetServerImpl.java:85)
        at io.vertx.core.impl.VertxImpl.createNetServer(VertxImpl.java:220)
        at io.vertx.core.eventbus.impl.clustered.ClusteredEventBus.lambda$start$1(ClusteredEventBus.java:119)
        at io.vertx.core.eventbus.impl.clustered.ClusteredEventBus$$Lambda$31/386161235.handle(Unknown Source)
        at io.vertx.core.impl.FutureImpl.checkCallHandler(FutureImpl.java:158)
        at io.vertx.core.impl.FutureImpl.setHandler(FutureImpl.java:100)
        at io.vertx.core.impl.ContextImpl.lambda$null$0(ContextImpl.java:271)
        at io.vertx.core.impl.ContextImpl$$Lambda$25/495218292.handle(Unknown Source)
        at io.vertx.core.impl.ContextImpl.lambda$wrapTask$2(ContextImpl.java:316)
        at io.vertx.core.impl.ContextImpl$$Lambda$26/1627887138.run(Unknown Source)
        at io.netty.util.concurrent.AbstractEventExecutor.safeExecute(AbstractEventExecutor.java:163)
        at io.netty.util.concurrent.SingleThreadEventExecutor.runAllTasks(SingleThreadEventExecutor.java:418)
        at io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:440)
        at io.netty.util.concurrent.SingleThreadEventExecutor$5.run(SingleThreadEventExecutor.java:873)
        at java.lang.Thread.run(Thread.java:745)```

@erhard
Copy link

erhard commented Feb 6, 2017

I have the same issue and as you can see in this post from 2015 https://groups.google.com/forum/#!searchin/vertx/Karger/vertx/rbvgHUDWcsE/iQspUifkAAAJ
Tim Fox said that it is very easy to fix.....
This is my second approach to use vertx (current version) with ruby and I have the same problem since 2015....it really annoying. Can I fix it myself with ruby means ?

Thread[vert.x-eventloop-thread-3,5,main] has been blocked for 9821 ms, time limit is 2000 io.vertx.core.VertxException: Thread blocked at java.io.UnixFileSystem.getBooleanAttributes0(Native Method) at java.io.UnixFileSystem.getBooleanAttributes(UnixFileSystem.java:242) at java.io.File.exists(File.java:819) at jnr.posix.JavaSecuredFile.exists(JavaSecuredFile.java:97) at org.jruby.util.RegularFileResource.exists(RegularFileResource.java:71) at org.jruby.runtime.load.LibrarySearcher.findFileResourceWithLoadPath(LibrarySearcher.java:169) at org.jruby.runtime.load.LibrarySearcher.findResourceLibrary(LibrarySearcher.java:129) at org.jruby.runtime.load.LibrarySearcher.findLibrary(LibrarySearcher.java:65) at org.jruby.runtime.load.LibrarySearcher.findBySearchState(LibrarySearcher.java:54) at org.jruby.runtime.load.LoadService.findLibraryBySearchState(LoadService.java:967) at org.jruby.runtime.load.LoadService.findFileForLoad(LoadService.java:390) at org.jruby.runtime.load.LoadService.smartLoadInternal(LoadService.java:489) at org.jruby.runtime.load.LoadService.require(LoadService.java:396) at org.jruby.RubyKernel.requireCommon(RubyKernel.java:963) at org.jruby.RubyKernel.require19(RubyKernel.java:956) at org.jruby.RubyKernel$INVOKER$s$1$0$require19.call(RubyKernel$INVOKER$s$1$0$require19.gen) at org.jruby.internal.runtime.methods.JavaMethod$JavaMethodOneOrNBlock.call(JavaMethod.java:383)

@vietj
Copy link
Member

vietj commented Feb 6, 2017

in some cases it might be a good thing that Vert.x performs some operation using a worker.

I remember I checked for Ruby and I think something was preventing that though.

@erhard
Copy link

erhard commented Feb 16, 2017

OK. Can I filter those Messages somehow. Its very hard to find my own errors in that bulk of output.

@erhard
Copy link

erhard commented Feb 16, 2017

I have found it yeah !!

Here my startup script for development :
Keep an eye on VERTX_OPTS !

`export VERTX_HOME="$HOME/.local/bin/vertx3"
export PATH="$PATH:$VERTX_HOME/bin"

export VERTX_OPTS='-Dvertx.options.maxEventLoopExecuteTime=100000000000'

vertx version
vertx run server_app.rb -conf dev.json`

@AshPlop
Copy link

AshPlop commented Feb 16, 2017

@erhard The thing is that proceeding this way, you will never be warned when an operation takes too much time on the event loop.
As your database grows or your input files or whathever, you might need to improve the performance of your code.
The option you used should only be activated while debugging.

@erhard
Copy link

erhard commented Feb 16, 2017

@AshPlop
Of course at the moment I do it while debugging. (Thanks for the hint) I would wish this feature to be able to set for the startup and for the verticles I write itself and not as a global setting. The problem is at the moment that only at startup all that output comes up an I do not find my own error messages any more. (Now I do) Even during production that stacktrace is in my opinion a little bit oversized But this is is a fundamental thing of java to get kilometers of stack trace I think which is not changeable. A very good feature in my opinion would be if some lines of warning were logged in production in a separate log file . To see what is blocking So you can check the "blocking.log". For example

time - verticlename id duration

The problem is here blocking is not a real error it just slows down the processing and should be avoided.

@AshPlop
Copy link

AshPlop commented Feb 16, 2017

@erhard I don't know which logging implementation you are using but you can configure it to log everything comming from the BlockedThreadChecker in a separate file and limit the stacktrace to the number of lines you need to see if you code is at stake.

Here is an example using logback.

<property name="five_lines_stack_traces_pattern" value="%d{yyyy-MM-dd HH:mm:ss} [%-5level] %logger{36} - %msg%n%ex{5}"/>

<appender name="blocking_issues" class="ch.qos.logback.core.rolling.RollingFileAppender">
    <file>${destination}</file>
    <rollingPolicy class="ch.qos.logback.core.rolling.SizeAndTimeBasedRollingPolicy">
        <fileNamePattern>${destination}-%d{yyyy-MM-dd}.%i.txt</fileNamePattern>
        <maxFileSize>15MB</maxFileSize>
        <maxHistory>20</maxHistory>
    </rollingPolicy>
    <encoder>
        <Pattern>${five_lines_stack_traces_pattern}</Pattern>
    </encoder>
</appender>

<logger name="io.vertx.core.impl.BlockedThreadChecker" level="info" additivity="false">
    <appender-ref ref="blocking_issues"/>
</logger>

@erhard
Copy link

erhard commented Feb 16, 2017

@AshPlop
Oh great thanks a lot I am a ruby guy.....I will google howto put logback into vertx and configure it according your post. If you have some links or hints I would appreciate it.

@erhard
Copy link

erhard commented Feb 16, 2017

@AshPlop I did what you said an have now the blocking messages in a separate rotating log file. I used logback from the startup script:

#!/usr/bin/env bash

export VERTX_HOME="$HOME/.local/bin/vertx3"
export PATH="$PATH:$VERTX_HOME/bin"
export LOG_DESTINATION=./log

export VERTX_OPTS='-Dvertx.logger-delegate-factory-class-
name=io.vertx.core.logging.SLF4JLogDelegateFactory -Dlogback.configurationFile=file:./logback.xml'

vertx run server_app.rb -conf dev.json

Thanks for your hints

@greggwon
Copy link

greggwon commented Mar 8, 2017

Ultimately developers don't need this kind of nonsense being done for them and being in their face. You are wasting CPU cycles by doing this continuously and it so interferes with debugging as to be useless. Developers who don't understand performance and threading/locking/blocking issues are doomed to failure no matter what you try to do to hold their hand. Please just disable this stupid attempt at hand holding and try something else if you really feel you are more of an expert at software that the rest of the developers own the world are. For those looking for the simple solution, just put this in your code:

Logger.getLogger("io.vertx.core.impl.BlockedThreadChecker").setLevel(Level.OFF);

or if you have a logging properties file just do

io.vertx.core.impl.BlockedThreadChecker.Level=OFF

@trajano
Copy link

trajano commented Sep 25, 2017

I was curious what was causing it so I did

        final VertxOptions vertOptions = new VertxOptions();
        vertOptions.setWarningExceptionTime(1);

Based on the output below, I sort of like this idea because I'm getting the warning message simply starting up an HTTPS server.

00:11:06.746 [vertx-blocked-thread-checker] WARN  i.v.core.impl.BlockedThreadChecker - Thread Thread[vert.x-eventloop-thread-0,5,main] has been blocked for 2414 ms, time limit is 2000
io.vertx.core.VertxException: Thread blocked
	at io.netty.handler.ssl.ReferenceCountedOpenSslServerContext.newSessionContext(ReferenceCountedOpenSslServerContext.java:123)
	at io.netty.handler.ssl.OpenSslServerContext.<init>(OpenSslServerContext.java:349)
	at io.netty.handler.ssl.OpenSslServerContext.<init>(OpenSslServerContext.java:334)
	at io.netty.handler.ssl.SslContext.newServerContextInternal(SslContext.java:414)
	at io.netty.handler.ssl.SslContextBuilder.build(SslContextBuilder.java:402)
	at io.vertx.core.net.impl.SSLHelper.createContext(SSLHelper.java:295)
	at io.vertx.core.net.impl.SSLHelper.getContext(SSLHelper.java:446)
	at io.vertx.core.net.impl.SSLHelper.validate(SSLHelper.java:466)
	at io.vertx.core.http.impl.HttpServerImpl.listen(HttpServerImpl.java:255)
	at io.vertx.core.http.impl.HttpServerImpl.listen(HttpServerImpl.java:222)
	at net.trajano.ms.engine.JaxRsVerticle.start(JaxRsVerticle.java:42)
	at io.vertx.core.AbstractVerticle.start(AbstractVerticle.java:111)
	at io.vertx.core.impl.DeploymentManager.lambda$doDeploy$8(DeploymentManager.java:434)
	at io.vertx.core.impl.DeploymentManager$$Lambda$8/2141179775.handle(Unknown Source)
	at io.vertx.core.impl.ContextImpl.lambda$wrapTask$2(ContextImpl.java:337)
	at io.vertx.core.impl.ContextImpl$$Lambda$9/48914743.run(Unknown Source)
	at io.netty.util.concurrent.AbstractEventExecutor.safeExecute(AbstractEventExecutor.java:163)
	at io.netty.util.concurrent.SingleThreadEventExecutor.runAllTasks(SingleThreadEventExecutor.java:403)
	at io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:445)
	at io.netty.util.concurrent.SingleThreadEventExecutor$5.run(SingleThreadEventExecutor.java:858)
	at java.lang.Thread.run(Thread.java:748)

@trajano
Copy link

trajano commented Sep 25, 2017

For the most part I would think just setting

    final VertxOptions vertOptions = new VertxOptions();
    vertOptions.setMaxEventLoopExecuteTime(3000000000L);

Should be more than sufficient and adjust accordingly to your environment. However, you have to make sure that it is an environment timing itself. If it is something that does take a while I think I'd move it out of the event loop and push it into a worker when possible. (Enabling SSL in the worker isn't really something that I can be easily done from what I can tell).

@vietj
Copy link
Member

vietj commented Sep 25, 2017 via email

@trajano
Copy link

trajano commented Sep 25, 2017

I think a more "proper" but less performant fix would be to have it start up in a blocking context so it is not initialized as part of the event loop.

@greggwon
Copy link

greggwon commented Sep 25, 2017 via email

@mmindenhall
Copy link
Author

The issue I filed concerns the ability to change these settings at runtime, so that the extremely verbose blocked thread logging can be disabled while the application is starting, and then enabled once all verticles are started. I suggested three possible ways to accomplish this, and so far nobody has commented on pros/cons of any of those approaches (which is what I was hoping for before submitting a PR).

Would any of those approaches adequately solve the other issues that are being discussed?

@trajano
Copy link

trajano commented Sep 25, 2017

Well for my case I put some of the larger initialization on a blocking queue and enable the route once it is fully initialized. In my case creating a Jersey application handler can take upwards of 5 seconds so I didn't like the thread block warning message since I have it set to 1.5 second (lower than the default) with stack trace.

    vertx.executeBlocking(future -> {
        future.complete(new ApplicationHandler(resourceConfig));
    }, false,
        res -> {
            if (res.succeeded()) {
                appHandler = (ApplicationHandler) res.result();
                router.route(baseUri.getPath() + "*").handler(this);
            }
        });

Since I don't active the route until the requisite data is ready the code won't get a null pointer exception.

@luxiaoxun
Copy link

In Vertx.3 try this:
VertxOptions options = new VertxOptions();
options.setBlockedThreadCheckInterval(3601000);
Vertx.vertx(options).deployVerticle()

But actually I don't like this idea.

@hutchig
Copy link
Contributor

hutchig commented May 27, 2020

Worth remembering this issue when thinking about what BlockedThreadChecker does in the context of #1539

@st-h
Copy link

st-h commented Nov 10, 2021

I just started to use AWS Fargate to deploy a vertx application and I suddenly see those warnings and exceptions as well. I have never seen those warnings at startup, when launching on an ubuntu server directly or during local development. I can also start the same docker container (that is deployed on Fargate) locally and the warnings are gone. Having a way to disable the blocked thread checker on startup would be so helpful.
Even if there just would be a method to programmatically enable or disable the blocked thread checker, that would help immensely.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

No branches or pull requests

9 participants