Logger trace logging impact

Ignition
1

I've always wondered, what's the performance impact of adding TRACE logging (e.g. system.util.getLogger('bob').trace('Hello!')) methods to function calls if the logger's min logging level itself is set above this (e.g. to INFO)? I'm particularly interested in the case the trace text is quite long. Does the trace method simply drop out if it sees that the logging level excludes it?

Edit:
Upon reading on the underlying logger class, perhaps I should be checking if the level is enabled before calling the log functions, to avoid the overhead of running any operations that create the log message itself.

LOGGER = system.util.getLogger('Test')
if: LOGGER.isTraceEnabled():
   LOGGER.trace('We did the thing')

https://files.inductiveautomation.com/sdk/javadoc/ignition79/795/com/inductiveautomation/ignition/common/util/LoggerEx.html

Although this states the check isn't required using lazy eval:
https://logging.apache.org/log4j/2.x/javadoc/log4j-api/org/apache/logging/log4j/Logger.html

How would I lazily eval the arg passed into the trace method?

2

Hmmm. Good question. I'm not sure jython can do that.

3

Ok, so the next best thing is checking if the level is enabled I guess

4

Our logging facade doesn't support lazy evaluation of logging properties, so you're always paying the allocation overhead of a string.
You won't pay the disk IO cost if the logger isn't enabled, and you also won't pay the CPU cost of concatenating a string together if you use the 'format' style methods; that is:
logger.tracef("some message {}", someObject)
Will (likely) be faster than doing the equivalent formatting in Python:
logger.trace("some message {}".format(someObject)
Because the string formatting/concatenation operation will only happen if the appropriate log level is set when the evaluation happens.

If you have some "expensive" object to create that's only relevant to logging, then sure, put it behind an isTraceEnabled check. In practice logging is almost guaranteed to not be the slowest thing in your application, but it's not a bad idea to stick to best practices.

1 Like
5

This. I use the .debugf(), and .tracef() methods specifically to take advantage of this. The only catch is that you need to supply arguments that format nicely. Objects without .toString() implementations will be ugly.

6

In regards to this... do to f string methods allow for formatting in the braces? IE can we use something like:

logger.tracef('Execution took {:5f} seconds',executionTime)
7

Huh. I thought the f methods only took printf()-style placeholders. The underlying SLF4J loggers do take braced placeholders (and only braced placeholders).

8

The manual: system.util.getLogger - Ignition User Manual 8.1 - Ignition Documentation references % style formatting, but @PGriffith mentions {} style. It is a bit confusing for new guys.

Edit. I just tested with the curly braces and it doesn't want to work.

logger = system.util.getLogger('testing')
logger.tracef('tracef %s','test message')
logger.tracef('tracef {}','test message')

Produces

09:05:13.614 [SwingWorker-pool-1-thread-10] TRACE testing - tracef test message
09:05:13.615 [SwingWorker-pool-1-thread-10] TRACE testing - tracef {}

In the logger. So it appears that even though log4j accepts it, the IA implementation doesn't?

9

The LoggerEx facade uses Formatter internally, so yes printf style. We currently back it with a particular logging library, but as far as I know the justification for the LoggerEx class is to be an abstraction to allow us to swap out the logging "backend" if we ever have to in the future.

10

On the second or third backend now?

1 Like
11

OK thanks. I appreciate the info clearing it up.