Build time minimum log level

[galderz]

FAO @dmlloyd @Sanne. This is a follow up to #13102 PR. Closes #12938.

It adds a new optional build time per category configuration called min-level. It controls the minimum level of logging defined at build time.

By default all categories' min-level is set to INFO, in which case the code generates an substratevm substitution that folds isTraceEnabled and isDebugEnabled calls to return false.

To keep things simple, the moment any min-level is configured, a different substitution is created that computes whether a given log level is enabled based on a combination of both the min-level set and the runtime log level. So, as an example, if you want to get TRACE on a given category, say org.example.table, you need to provide both:

• Build time quarkus.log.category."org.example.table".min-level=TRACE
• Run time quarkus.log.category."org.example.table".level=TRACE

When deciding the logic 👆, I pondered about the need for the runtime log level to be set, but it felt awkward to have code that had been built with min-level set to TRACE, and runtime log level to be say INFO and for isTraceEnabled to return true but nothing be logged when calling log.trace.

To exercise this, I've been using this project to test the behaviour when no min-level has been set, and this other with the example above. I'd like to convert these two into Quarkus integration tests, but first I'd like to make sure we have agreement on the logic.

Further optimisations are also applicable:

1. If all min-level set in config are INFO or above, the same logic as with no min-level set could be applied. The moment min-level is configured, the current logic does attempt to fold any calls.
2. If all min-level set in config are WARN or above and the logic in 👆 was applied, one could also fold isInfoEnabled calls to false.

Unit testing wise, I had the following doubt: to test both the branches of the logic (no min-level set and a min-level set to TRACE or some other), it seems to me that I'd need 2 maven integration test projects. Is that right? Could it be somehow done in a single one? Not sure...

Aside from unit testing, and possible further optimisations, documentation needs to be updated.

[ghost]

Thanks for your pull request!

The title of your pull request does not follow our editorial rules. Could you have a look?

• title should not contain an issue number (use 'Fix Allow * expression for quarkus:add-extension #1234' in the description instead)

This message is automatically generated by a bot.

[danberindei]

One problem with setting the default min-level to INFO is that it's not obvious why DEBUG messages are not logged when a user changes only the runtime level to DEBUG.

Maybe you can log a warning when the runtime level is lower than the build-time min-level.

[Sanne]

One problem with setting the default min-level to INFO is that it's not obvious why DEBUG messages are not logged when a user changes only the runtime level to DEBUG.

Maybe you can log a warning when the runtime level is lower than the build-time min-level.

Agreed!

To be fair that's the kind of warning you get when attempting to changinge a build-time option in Quarkus at runtime; this should be consistent with that.

I believe there also was a recent PR to make such a warning ugpraded to a failure to start - which greatly helps in certain testing and IT tests. @ppalaga , I don't seem able to find it - could you point @galderz to the right code?

[ppalaga]

It is in this PR #13154

[galderz]

@danberindei Agreed, I'll look into adding that warning.

I'm working to finish up this PR (add unit tests and documentation) next few days. I did some benchmarking with Infinispan native server and this change had a consistent positive impact. In Infinispan's case, it was combined with removing static and instance level cache of static calls to isTraceEnabled/isDebugEnabled. This calls are fast and can just be done in the code directly.

[galderz]

Ignore CI failures until done, I'm pushing temporary commits to add unit testing :)

[galderz]

@danberindei @Sanne I've looked at the warning, but I'm hesitant to add it at this stage since I'm unsure how to best deal with it. I don't want to have the gizmo generated code for the substituted isLoggable method having to print such a warning, it'd be very noisy. You could try to maybe do it in LoggingResourceProcessor but this is just a warning that should be printed for native mode and I don't know how that could be done. Maybe the feature needs to be present for jvm mode too, but that's beyond the scope of this right now... any ideas @dmlloyd?

[Sanne]

To be fair that's the kind of warning you get when attempting to changinge a build-time option in Quarkus at runtime; this should be consistent with that.

Did you check my previous suggestion? ^

I don't remember where this code lives and how it works, but I believe we already have a similar check for build-time configuration properties - including JVM mode.

Please have a look at that and try making this consistent with it?

[dmlloyd]

@danberindei @Sanne I've looked at the warning, but I'm hesitant to add it at this stage since I'm unsure how to best deal with it. I don't want to have the gizmo generated code for the substituted isLoggable method having to print such a warning, it'd be very noisy. You could try to maybe do it in LoggingResourceProcessor but this is just a warning that should be printed for native mode and I don't know how that could be done. Maybe the feature needs to be present for jvm mode too, but that's beyond the scope of this right now... any ideas @dmlloyd?

The warning should probably happen as a config validation when logging sets up each log category and handler at run time. That code already needs to clamp the log level to the min-level in order to be consistent between JVM and native mode, so adding a warning there should be trivial.

[galderz]

This is ready now.

I've ended up creating 2 integration test projects. One tests the logic when no min-level config is present (where we can fold isTraceEnabled/isDebugEnabled to false) and the other tests when a variety of min-level setups are tried and complicated gizmo generated code is exercised.

Also added some light touches to the logging documentation.

[galderz]

Once it's been approved I'll go ahead and squash the commits.

[galderz]

Looking into CI results, the failures seem to be caused by the PR itself.

[galderz]

@gsmet Addressed comments, squashed and pushed.

[gsmet]

Rebased to fix a conflict and get CI to run again.

[gsmet]

OK let's get this in then. Thanks.

[galderz]

Thx all!

[loicmathieu]

I just try Quarkus 1.11 and now my debug logs didn't show anymore due to this PR.
Normally, as console log is at level ALL by default, if I configure a category to log at DEBUG it will shows up.
Now, as I understand it, I also need to configure a new min-level build property.

Logging level is something that everybody set at runtime to have different log levels on different environements, so it feels wrong to me that this is a build time property.
Setting a log at DEBUG is really common (on dev env for example, or during a pilote phase of an application), so it may surpise a lot of people that after 1.11 all there DEBUG log disapear.

I understand that it causes an issue on native but maybe a native only solution could has been found (like a specific native build prop).

Sorry to give feedback late but I really think this change will surprised a lot of people and I wanted to give awardeness to it.

[galderz]

I just try Quarkus 1.11 and now my debug logs didn't show anymore due to this PR.
Normally, as console log is at level ALL by default, if I configure a category to log at DEBUG it will shows up.
Now, as I understand it, I also need to configure a new min-level build property.

Right, but you should have seen a warning message in the console saying that the DEBUG level was promoted to INFO because the min-level is INFO.

Logging level is something that everybody set at runtime to have different log levels on different environements, so it feels wrong to me that this is a build time property.

It's quite common to have debug builds of native executables. The idea is that you have a production one with no debug, and one that has been built with debug/trace min-level for when you want to debug things.

Setting a log at DEBUG is really common (on dev env for example, or during a pilote phase of an application), so it may surpise a lot of people that after 1.11 all there DEBUG log disapear.

Surprise that DEBUG is not there yeah, but the warning message should be there.

I understand that it causes an issue on native but maybe a native only solution could has been found (like a specific native build prop).

Doing this creates the opposite problem: for native I need to pass extra X property whereas for jvm mode I don't. With the information we have so far, we decided to keep things as consistent as possible between the two modes.

[maxandersen]

@galderz I assume this change has some memory/cpu impact - can we quantify it a bit as otherwise this does seem like a bit unfortunate UX wise.

[galderz]

@maxandersen You can find numbers in this Infinispan PR. The optimisations introduced by this PR increase throughput around 10-15%.

[maxandersen]

Excellent, thanks @galderz ! 10-15% is worth it and we seem to log/warn where ever detectable.

[loicmathieu]

@maxandersen

Excellent, thanks @galderz ! 10-15% is worth it and we seem to log/warn where ever detectable.

This is only when running with Infinispan or other extensions that uses TRACE level logs. Most applications should suffer no performance penaly.

Right, but you should have seen a warning message in the console saying that the DEBUG level was promoted to INFO because the min-level is INFO.

This log message should at least provides the right configuration option to use (in my case it was quarkus.log.console.min-level I think).

It's quite common to have debug builds of native executables.

True, but it's very un-common to have debug builds of JVM applications ...

Doing this creates the opposite problem: for native I need to pass extra X property whereas for jvm mode I don't.

I would prefere this one as most application / developer I've talk about Quarkus with still deploy Quarkus on JVM (80 to 90% of them I think) but maybe my experience is not significative.

[Sanne]

We use TRACE extensively in many libraries, including Hibernate ORM, transaction manager, drivers. Galder's patches are very welcome as they fix several long standing performance issues which we identified since during the early Protean prototypes.

…

On Tue, 19 Jan 2021, 12:54 Loïc Mathieu, ***@***.***> wrote: @maxandersen <https://github.com/maxandersen> Excellent, thanks @galderz <https://github.com/galderz> ! 10-15% is worth it and we seem to log/warn where ever detectable. This is only when running with Infinispan or other extensions that uses TRACE level logs. Most applications should suffer no performance penaly. Right, but you should have seen a warning message in the console saying that the DEBUG level was promoted to INFO because the min-level is INFO. This log message should at least provides the right configuration option to use (in my case it was quarkus.log.console.min-level I think). It's quite common to have debug builds of native executables. True, but it's very un-common to have debug builds of JVM applications ... Doing this creates the opposite problem: for native I need to pass extra X property whereas for jvm mode I don't. I would prefere this one as most application / developer I've talk about Quarkus with still deploy Quarkus on JVM (80 to 90% of them I think) but maybe my experience is not significative. — You are receiving this because you were mentioned. Reply to this email directly, view it on GitHub <#13376 (comment)>, or unsubscribe <https://github.com/notifications/unsubscribe-auth/AAAKMTNTTNMXJAUJCEFGYL3S2V6GTANCNFSM4T3IOJSA> .

[maxandersen]

I think the argument is not necessarily for including trace in min-level but make it DEBUG.

Would that be a compromise that removes trace from hotspots but still allow easy debugging while users who can benefit than set min-level to info ?

Or is the belief the majority of 10-15% gain was from stripping out debug ?

[loicmathieu]

I think the argument is not necessarily for including trace in min-level but make it DEBUG.

Each level would be arbitrary, I usually use INFO on production and turn on DEBUG only when needed (local for some part of the code, at the moment also on our integration env because we are in the rampdown phase of our apps).

But I now some people use DEBUG in production, and other uses WARNING !

And some people never use TRACE (like myself) and other logs everything at INFO ...

For me, DEBUG is better but it's only my usage of log level.

[danberindei]

From the perspective of Infinispan, changing the default min-level to DEBUG doesn't impact performance at all: we don't log a lot of DEBUG messages, and all per-request log messages are TRACE. However, I am aware of libraries we use/have used that use DEBUG/FINE as we use TRACE, e.g. okhttp.

@galderz since we no longer use a trace constant, I wonder if it's possible to keep the log.isTraceEnabled() check in the native code when min-level is set to TRACE (or maybe you're already doing it?). It would still add bloat to the native executable and it may even add measurable overhead when the runtime level is higher, but it might make a better default because any runtime level would work OOTB. I know this wasn't an option when you started working on this, and I'm not sure if all the other projects that were using a trace constant (e.g. Hibernate) have also made the change.

[galderz]

@galderz since we no longer use a trace constant, I wonder if it's possible to keep the log.isTraceEnabled() check in the native code when min-level is set to TRACE (or maybe you're already doing it?).

@danberindei When min-level is set to TRACE, the log.isTraceEnabled() remains because we don't know what the runtime log levels will be. This means that when min-level is TRACE, the code works as it'd normally: log.isTraceEnabled() is called, the runtime log levels are checked to see if the given category has trace enabled...etc.

It would still add bloat to the native executable and it may even add measurable overhead when the runtime level is higher, but it might make a better default because any runtime level would work OOTB. I know this wasn't an option when you started working on this, and I'm not sure if all the other projects that were using a trace constant (e.g. Hibernate) have also made the change.

That's an interesting angle. TBH, I don't really mind what the default value for min-level is. As I said @maxandersen a couple of days back, it's up to the Quarkus UX overlords to decide what the best default is.

When it comes to Infinispan Native Server POV perspective, you're free to set the default min-level to DEBUG or INFO when you build it to get extra speed. Then you can have a debug download with min-level set to TRACE.