Akka anti-patterns: logging (the wrong way)

Update: removed rogue toString call in the second code example, since it was unnecessary (and harmful).

Proper logging

Proper logging

Debugging actor systems is no small feat, even when there is IDE support for it. In fact, debugging any asynchronous system for that matter is a rather complicated task. Which is why, especially during development, it is not entirely uncommon to rely on DEBUG level logging to get a sense of how messages flow between actors. Whilst doing so is fine, there are a few precautions that need to be taken when logging at DEBUG level (or any other level). Remember, logging ranks very high on the list of top 10 performance mistakes.

Here are a few offenders that are good to watch out for when logging things in your actor system.

String concatenation

String concatentation is expensive. Granted, it is not that expensive — but in a system processing millions of messages per second it can become very expensive.

Consider the following example:

Even if your logging configuration specifies a level above DEBUG, this type of call will still result in string concatenation and in the evaluation of the toString() method (which may be more or less expensive, depending on the message and on how it is implemented).

The recommended way, therefore, is to favour string interpolation which allows lazy evaluation, thus ensuring that log statements do not create any costs when they are not needed.

With Akka’s built-in logging, our previous example becomes:

Non-asynchronous logging

Don’t lock, log.

This one should be obvious, but it is worth stressing it nonetheless. By all means, make sure that you use Akka’s built-in logging adapter which takes care of this. There would be nothing worse for the performance of your application than having each log statement block while the log entry is written to disk or to the network.

Even better, make sure to configure an asynchronous logging backend.

Not turning debug logging off in production settings

Again, this one should go without saying. You should not want (nor need) to capture DEBUG log statements in your production environment. Asynchronous or not, there is an associated cost with logging and if you can avoid that, do it by all means. You can turn off DEBUG level logging entirely in your production version of the configuration like so:

This way, anything below the INFO level will not even reach the logging backend.

Not using built-in logging features

Especially when getting started with building actor systems there are a few things you may want to see in the logs:

  • unhandled messages, which is to say messages that an actor does not know what to do with (this happens for example when you send a message to a wrong actor)
  • lifecycle changes such as restarts, deaths, etc.
  • the configuration in use

For this purpose, don’t roll your own solution. Instead make sure to check out the auxiliary logging options in the Akka documentation.

Forgetting to clear the MDC context

A very useful feature you may want to leverage is the so-called Mapped Diagnostic Context (or MDC in short) which allows you to add supplementary context information to the log entries. Akka has built-in support for the MDC.

If you use the MDC, do not forget to clear it after the logging is done. Failing this, you will end up with rather incoherent log entries.

Happy logging!


Liked this post? Subscribe to the mailing list to get regular updates on similar topics.

5 Comments on “Akka anti-patterns: logging (the wrong way)”

  1. about :
    log().debug(“Received message: {}”, msg.toString());

    you also need to be careful of the cost of evaluating “msg.toString()” which can far outstrip the cost of concatenation.

  2. Laziness of log-statements is arguable. Just try something with side effect, e.g.:
    log().debug(“Received message: {}”, { print(“Not evaluated”); msg });
    Even with INFO log level configured you’ll see all these “Not evaluated” printed though msg itself not logged (as expected).

    1. That’s not quite how it is intended to be though. Can’t check right now but could this be something related to the Java API & the way an inline block gets passed to it? I.e. what happens if you pass in an object, and move the print statement to that object’s toString() method?

Leave a Reply

Your email address will not be published. Required fields are marked *