# Logger trace logging impact

**URL:** <https://forum.inductiveautomation.com/t/logger-trace-logging-impact/81749>\
**Category:** Ignition\
**Tags:** scripting\
**Created:** [November 10, 2023, 1:38am UTC](https://forum.inductiveautomation.com/t/logger-trace-logging-impact/81749 "2023-11-10T01:38:28Z")\
**Posts on this page:** 11\
**Page:** 1

<div class="post-metadata">

**Author:** ![nminchin](https://sea1.discourse-cdn.com/inductiveautomation/user_avatar/forum.inductiveautomation.com/nminchin/32/6911_2.png) [@nminchin](https://forum.inductiveautomation.com/u/nminchin)\
**Post date:** [November 10, 2023, 1:38am UTC](https://forum.inductiveautomation.com/t/logger-trace-logging-impact/81749/1 "2023-11-10T01:38:28Z")

</div>

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.

```auto
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](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](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?

---

<div class="post-metadata">

**Author:** ![pturmel](https://sea1.discourse-cdn.com/inductiveautomation/user_avatar/forum.inductiveautomation.com/pturmel/32/3295_2.png) [@pturmel](https://forum.inductiveautomation.com/u/pturmel)\
**Post date:** [November 10, 2023, 2:36am UTC](https://forum.inductiveautomation.com/t/logger-trace-logging-impact/81749/2 "2023-11-10T02:36:49Z")

</div>

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

---

<div class="post-metadata">

**Author:** ![nminchin](https://sea1.discourse-cdn.com/inductiveautomation/user_avatar/forum.inductiveautomation.com/nminchin/32/6911_2.png) [@nminchin](https://forum.inductiveautomation.com/u/nminchin)\
**Post date:** [November 10, 2023, 2:43am UTC](https://forum.inductiveautomation.com/t/logger-trace-logging-impact/81749/3 "2023-11-10T02:43:17Z")

</div>

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

---

<div class="post-metadata">

**Author:** ![paul-griffith](https://sea1.discourse-cdn.com/inductiveautomation/user_avatar/forum.inductiveautomation.com/paul-griffith/32/37249_2.png) [@paul-griffith](https://forum.inductiveautomation.com/u/paul-griffith)\
**Post date:** [November 10, 2023, 3:22am UTC](https://forum.inductiveautomation.com/t/logger-trace-logging-impact/81749/4 "2023-11-10T03:22:26Z")

</div>

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.

---

<div class="post-metadata">

**Author:** ![pturmel](https://sea1.discourse-cdn.com/inductiveautomation/user_avatar/forum.inductiveautomation.com/pturmel/32/3295_2.png) [@pturmel](https://forum.inductiveautomation.com/u/pturmel)\
**Post date:** [November 10, 2023, 12:06pm UTC](https://forum.inductiveautomation.com/t/logger-trace-logging-impact/81749/5 "2023-11-10T12:06:05Z")

</div>

> [@paul-griffith](#):
>
> Because the string formatting/concatenation operation will only happen if the appropriate log level is set when the evaluation happens.

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.

---

<div class="post-metadata">

**Author:** ![bschroeder](https://sea1.discourse-cdn.com/inductiveautomation/user_avatar/forum.inductiveautomation.com/bschroeder/32/13260_2.png) [@bschroeder](https://forum.inductiveautomation.com/u/bschroeder)\
**Post date:** [November 10, 2023, 1:22pm UTC](https://forum.inductiveautomation.com/t/logger-trace-logging-impact/81749/6 "2023-11-10T13:22:28Z")

</div>

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

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

```

---

<div class="post-metadata">

**Author:** ![pturmel](https://sea1.discourse-cdn.com/inductiveautomation/user_avatar/forum.inductiveautomation.com/pturmel/32/3295_2.png) [@pturmel](https://forum.inductiveautomation.com/u/pturmel)\
**Post date:** [November 10, 2023, 1:35pm UTC](https://forum.inductiveautomation.com/t/logger-trace-logging-impact/81749/7 "2023-11-10T13:35:21Z")

</div>

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

---

<div class="post-metadata">

**Author:** ![bschroeder](https://sea1.discourse-cdn.com/inductiveautomation/user_avatar/forum.inductiveautomation.com/bschroeder/32/13260_2.png) [@bschroeder](https://forum.inductiveautomation.com/u/bschroeder)\
**Post date:** [November 10, 2023, 1:37pm UTC](https://forum.inductiveautomation.com/t/logger-trace-logging-impact/81749/8 "2023-11-10T13:37:47Z")

</div>

The manual: [system.util.getLogger - Ignition User Manual 8.1 - Ignition Documentation](https://docs.inductiveautomation.com/display/DOC81/system.util.getLogger) references % style formatting, but @paul-griffith 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.

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

```

Produces

```auto
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?

---

<div class="post-metadata">

**Author:** ![paul-griffith](https://sea1.discourse-cdn.com/inductiveautomation/user_avatar/forum.inductiveautomation.com/paul-griffith/32/37249_2.png) [@paul-griffith](https://forum.inductiveautomation.com/u/paul-griffith)\
**Post date:** [November 10, 2023, 4:49pm UTC](https://forum.inductiveautomation.com/t/logger-trace-logging-impact/81749/9 "2023-11-10T16:49:52Z")

</div>

The LoggerEx facade uses [`Formatter`](https://docs.oracle.com/en/java/javase/17/docs/api/java.base/java/util/Formatter.html) 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.

---

<div class="post-metadata">

**Author:** ![pturmel](https://sea1.discourse-cdn.com/inductiveautomation/user_avatar/forum.inductiveautomation.com/pturmel/32/3295_2.png) [@pturmel](https://forum.inductiveautomation.com/u/pturmel)\
**Post date:** [November 10, 2023, 5:02pm UTC](https://forum.inductiveautomation.com/t/logger-trace-logging-impact/81749/10 "2023-11-10T17:02:43Z")

</div>

> [@paul-griffith](#):
>
> swap out the logging "backend" if we ever have to _ **again** _ ~~in the future~~.

On the second or third backend now?

---

<div class="post-metadata">

**Author:** ![bschroeder](https://sea1.discourse-cdn.com/inductiveautomation/user_avatar/forum.inductiveautomation.com/bschroeder/32/13260_2.png) [@bschroeder](https://forum.inductiveautomation.com/u/bschroeder)\
**Post date:** [November 10, 2023, 5:53pm UTC](https://forum.inductiveautomation.com/t/logger-trace-logging-impact/81749/11 "2023-11-10T17:53:00Z")

</div>

OK thanks. I appreciate the info clearing it up.