Conditional logging performance improvements

[ghost]

In org.freedesktop.dbus.messages.Message::populate, there's a call to Hexdump.toAscii that's always invoked:

https://github.com/hypfvieh/dbus-java/blob/cef605503d009a8d5c470a2f8b3a482fda38a2c4/dbus-java-core/src/main/java/org/freedesktop/dbus/messages/Message.java#L168

Using logIf may be beneficial:

LoggingHelper.logIf(logger.isTraceEnabled(),
  () -> logger.trace("Message header: {}", Hexdump.toAscii(_headers))
);

It offers a small performance gain (0.35%):

--- 24797584 ns (0.35%), 17 samples
  [ 0] java.lang.AbstractStringBuilder.append
  [ 1] java.lang.StringBuilder.append
  [ 2] org.freedesktop.dbus.utils.Hexdump.toAscii
  [ 3] org.freedesktop.dbus.utils.Hexdump.toAscii
  [ 4] org.freedesktop.dbus.messages.Message.populate
  [ 5] org.freedesktop.dbus.messages.MessageFactory.createMessage
  [ 6] org.freedesktop.dbus.spi.message.InputStreamMessageReader.readMessage
  [ 7] org.freedesktop.dbus.connections.transports.AbstractTransport.readMessage
  [ 8] org.freedesktop.dbus.connections.AbstractConnection.readIncoming
  [ 9] org.freedesktop.dbus.connections.IncomingMessageThread.run

We're trying to find ways to reduce GC pressure, and string creation tends to be one of the stressors.

Similarly, could the following call be checked before invoked?

https://github.com/hypfvieh/dbus-java/blob/cef605503d009a8d5c470a2f8b3a482fda38a2c4/dbus-java-core/src/main/java/org/freedesktop/dbus/messages/Message.java#L171

Full asyc-profile logging profile attached.

dbus-2.log

[ghost]

Aside, do you see a way to simplify the following code?

LoggingHelper.logIf(logger.isTraceEnabled(),
  () -> logger.trace("Message header: {}", Hexdump.toAscii(_headers))
);

It seems to be a common pattern in the code base. I'm not sure how much simpler it can get, possibly:

LoggingHelper.logIfTracing(logger,
  () -> log(logger, "Message header: {}", Hexdump.toAscii(_headers))
);

That could help prevent logging level mismatches:

LoggingHelper.logIf(logger.isTraceEnabled(),
  () -> logger.debug("Message header: {}", Hexdump.toAscii(_headers))
);

[hypfvieh]

I checked the calls to Hexdump.toAscii and Arrays.deepToString and replaced them with the LoggingHelper if required.

The call in Message.java at Line 171 is useless. First, the Arrays.deepToString will only be called if trace is enabled and then the created deep-String is not used (not event logged). I replaced that line with LoggingHelper.logIf so the created String will be printed at trace level.

Because of the 'simplified' LoggingHelper: I already thought about that, but I don't see any way of doing this nicely.

When using slf4j, you have to call .trace()/.debug()/.error()etc. directly, so you have to create something which may work using some sort of LogLevel enum. This would allow you to provide alog()` method to the Lambda like you suggested.

Doing this would require to wrap the slf4j logger creating temporary objects for doing your checks and maybe log. If you want to avoid creating temporary objects one may have to create a custom logger/logger API which I definitely don't want to do.

Creating objects just for checking if logging is required is a bit too much overhead in my eyes. Logging should be done fast without doing more than required to log or to ignore the log message. In that case I would stick with the 'uncomfortable' LoggingHelper way of doing this.

[ghost]

Fixed on branch, closing.