refactor: Apply SLF4J best practices

[timtebeek]

Hi all, continuation here of earlier work on

• refactor: SLF4J best practices micronaut-starter#2002

I've run these three recipes together, to hopefully improve the logging output, with some small fixes thrown in too:

• Parameterize SLF4J's logging statements
• SLF4J logging statements should begin with constants
• Enhances logging of exceptions by including the full stack trace in addition to the exception message

When looking at other projects these fixes could be applied a few more times:

Use this link to re-run the recipe: https://app.moderne.io/recipes/builder/NBXKac4Ye?organizationId=TWljcm9uYXV0

[altro3]

It is interesting that this change is not entirely correct: it makes sense to use placeholders only if you do not have a preliminary check for isDebugEnabled / isInfoEnabled / ... . In general, they were invented precisely for this purpose, to simplify the code, but at the same time not to carry out unnecessary calculations. That is, when you call a logger with some calculations, and then it turns out that logging is not happening due to another level of logging, but you have already spent time calculating the parameters.

In general, what I want to say is that the current changes will result in logging execution being slower than before, even if only slightly.

But since the slowdown is really insignificant, they can be done.

An example of such changes:

[timtebeek]

It is interesting that this change is not entirely correct: it makes sense to use placeholders only if you do not have a preliminary check for isDebugEnabled / isInfoEnabled / ... . In general, they were invented precisely for this purpose, to simplify the code, but at the same time not to carry out unnecessary calculations. That is, when you call a logger with some calculations, and then it turns out that logging is not happening due to another level of logging, but you have already spent time calculating the parameters.

In general, what I want to say is that the current changes will result in logging execution being slower than before, even if only slightly.

Interesting perspective, thanks! So if I understand you correctly you're saying not to use parameterized logging when contained within a logging guard block? As then the arguments are guaranteed to be used if executed, and String concatenation is faster than the log string formatting.

Scrolling through the pull request changes again it seems the project is pretty consistent in using guard blocks. An alternative point can also be made that those guard blocks are perhaps not as needed when using parameterized logging, and could clean up the code a bit. Not saying we should do this, but it's an interesting thought.

Looking at for instance the following snippet, in the before situation the guard block prevented unnecessary string concatenation, whereas when using parameterized logging the if could also be removed, such that you only interact with LOG once. I have no measurements on performance there, but the code reads cleaner without the guarding conditional.

         if (LOG.isDebugEnabled()) {
-            LOG.debug("Swallowed an IOException caused by client connectivity: " + cause.getMessage(), cause);
+            LOG.debug("Swallowed an IOException caused by client connectivity: {}", cause.getMessage(), cause);
         }

Curious to hear your thoughts; I'd now be inclined to write a recipe to clear out unnecessary guard blocks, even if it's not applied here. :)

[altro3]

Yes, that's right, your example is correct. Of course, string concatenation is faster than string parsing and replacing placeholders.

Yes, if you switched to placeholders, then there is no need to check the logging level before doing so. The check will still occur in the Slf4J implementation. for example, in the ch.qos.logback.classic.Logger class. But even here everything is not entirely clear: in the logger, the level is checked not immediately, but after several quick operations.

Therefore, the following conclusions can be drawn:

1. The most effective method of logging in terms of speed (But at the same time, the most inconvenient method, which existed BEFORE the creation of Slf4J and was proposed in Log4J):

if (LOG.isDebugEnabled()) {
    LOG.debug("Swallowed an IOException caused by client connectivity: " + cause.getMessage(), cause);
}

2. The most convenient way, but with several additional internal operations:

LOG.debug("Swallowed an IOException caused by client connectivity: {}", cause.getMessage(), cause);

As always, we have a standard conflict in programming: convenience or performance :-)

[timtebeek]

Agreed! And then this PR somewhat counter-intuitively uses both guards and parameterized logging, with the performance penalty you've indicated. So then I'll leave up to all of you if you still want to merge this for the readability improvements and minor fixes, or revisit at a later point in time.

As perhaps known these code changes were mostly automated (apart from the fixes and reverts), so no harm in rejecting a PR if you're not happy with it. Merely trying to help, and learn & improve in the process. :)

[altro3]

The guys will decide that :). There is nothing wrong with these changes. There is little performance loss. I would just then remove the checks at the logging level, because... they will happen inside the method anyway. Those. in the case of logging, it seems to me that it is quite possible to sacrifice performance for the sake of convenience. But it's not up to me to decide ;-)

In any case, I think it’s worth adding to these changes and removing checks at the logging level in cases where there are no calculations

[sdelamo]

what do you think? @dstepanov I was about to merge this.