inefficient use of loggers

[stephengold]

Issue #1672 drew my attention to inefficient use of loggers in JMonkeyEngine. A quick scan found dozens of instances that can probably be improved. A common anti-pattern is code that constructs a log message using string concatenation, as in GltfUtilities:

                logger.log(Level.WARNING, "Unsupported Vertex Buffer type " + attribute);

Most of these should be refactored.

[pspeed42]

WARNING is a bad example because it is almost always enabled and so the check is redundant.

Whatever crappy-JUL's version of INFO is... that's sort of on the fence. Finer than that should either be gated or use the pattern version. (I prefer gating in general if a conversion is being done because that pattern idiom has an argument limit before it's no better than concatenating a string.)

[vxel]

Indeed, I've spotted the same issue in a couple of classes in jme3-core. I did not check in other libs.
Not all FINE loggers are problematic though, e.g. those used only during initialization.

Additionnally, I wonder if it is worth the effort to gate logger statements that use multiple parameters, such as :
logger.log(Level.FINE, "{0} {1}", new Object[]{myobject1, myobject2})
Since this statement implies the creation of an object array, I also added a gate, but not systematically.

I'm preparing a PR fot this. Before submit it, you may take a look and tell me what you think.

[tonihele]

Isnt there the method that takes in the supplier? That is executed only when the line is actually logged. Could be used for complex cases that have a performance impact on creating the message. Im not sure how heavy this method is though...

…

On Wed, 24 Nov 2021, 17:47 vxel, ***@***.***> wrote: Indeed, I spotted the same issue in a couple of classes in jme3-core. I did not check in other libs. Not all FINE loggers are problematic though, e.g. those used only during initialization. Additionnally, I wonder if it is worth the effort to gate logger statements that use multiple parameters, such as : logger.log(Level.FINE, "{0} {1}", new Object[]{myobject1, myobject2}) Since this statement implies the creation of an object array, I also added a gate, but not systematically. — You are receiving this because you are subscribed to this thread. Reply to this email directly, view it on GitHub <#1680 (comment)>, or unsubscribe <https://github.com/notifications/unsubscribe-auth/AB7VJPTNNR2XQMW2MLQP3QLUNUCH3ANCNFSM5IU3JDXA> . Triage notifications on the go with GitHub Mobile for iOS <https://apps.apple.com/app/apple-store/id1477376905?ct=notification-email&mt=8&pt=524675> or Android <https://play.google.com/store/apps/details?id=com.github.android&referrer=utm_campaign%3Dnotification-email%26utm_medium%3Demail%26utm_source%3Dgithub>.

[vxel]

No, this statement does not use the supplier. I'm pretty sure the performance penalty of the array creation is present, even if the logger is not enabled, because the parameter is evaluated before calling the log method.

It is true that we can use a supplier instead of a gate for log statements like this :
logger.log(Level.FINE, "My log : {0}", () -> myMethod())
This does not seem to be a common practice in jme3, so I use a gate for now.

[stephengold]

I'm preparing a PR fot this. Before submit it, you may take a look and tell me what you think.

I'm glad to know you're working on this, and I look forward to seeing your changes.

However, I'll do that after you submit the PR, not before.

[pspeed42]

re: logger.log(Level.FINE, "{0} {1}", new Object[]{myobject1, myobject2})

Yeah, that should be gated also. (Some logging APIs supply several multi-arg methods to avoid a var-args but JUL, even in its labyrinth of poopy and confusing APIs, chose not to do this.)

I still fail to understand why a line like that is better than logger.log(Level.FIND, myobject1 + " " + myobject2) but that may be personal style.

[pspeed42]

Also, strictly speaking, if object creation is what we try to avoid then:
logger.log(Level.FINE, "My log : {0}", () -> myMethod())

...is no better because it will instantiate a lambda object every time, even if logging will be suppressed for FINE.

[vxel]

re: logger.log(Level.FINE, "{0} {1}", new Object[]{myobject1, myobject2})
I still fail to understand why a line like that is better than logger.log(Level.FINE, myobject1 + " " + myobject2) but that may be personal style.

The 1st statement requires the cost of an array creation. The 2nd statement requires two invocations of myobject1.toString(), myobject2.toString, plus the overall string concatenation, even if the level is suppressed. This certainly more expensive, even if the toString() implementations of the objects are trivial.

Also, strictly speaking, if object creation is what we try to avoid then:
logger.log(Level.FINE, "My log : {0}", () -> myMethod())
...is no better because it will instantiate a lambda object every time, even if logging will be suppressed for FINE.

Regarding the use of lambdas, my understanding is that lambdas without parameters are compiled once (at runtime) and reused (according to the talk of Brian Goetz about this : http://youtu.be/C_QbkGU_lqY?t=36m25s).

The example is then equivalent to :

private static final Supplier<String> MY_LAMBDA = () -> myMethod();
...
logger.log(Level.FINE, "My log : {0}", MY_LAMBDA);

which costs less than using a gate (not counting the unique compilation overhead).

Anyway, I wouldn't use lambda to preserve coherence among the code base, and because the logging API limits to 1 the number of supplier parameters we can pass.

[tonihele]

Anyway, I wouldn't use lambda to preserve coherence among the code base, and because the logging API limits to 1 the number of supplier parameters we can pass.

One is enough right?

logger.log(Level.FINE, () -> myobject1 + " " + myobject2)

[vxel]

Oh yes it is.

Btw, I now understand the point of @pspeed42 regarding the personal style. If the statement is already gated, then the difference between

logger.log(Level.FINE, "{0} {1}", new Object[]{myobject1, myobject2})
and
logger.log(Level.FINE, myobject1 + " " + myobject2)

is mostly aesthetic.