Performance Considerations for Akka Debug Logging

The Akka actor-model framework provides convenient libraries for application logging. As one would expect, there is support for configurable logging levels—error, warning, informational, and debug— and log messages are written asynchronously for good performance.

There is a subtle performance consideration, however, that I've encountered a few times in code reviews, that I would like to highlight. Consider the following contrived example, using the Scala programming language, with an actor that maintains a repository of the usage count for various resources. Assume that the usage count changes frequently. Each time the usage count changes, a message is sent to the actor. The actor implements a cache and persists the cache in an external store every 10 seconds, so that it is available to other services.

case class Resource(name: String, count: Long)

object UsageRepositoryMessage {
  sealed trait RepositoryMessage
  case class Update(value: Resource) extends RepositoryMessage
  case object Persist extends RepositoryMessage
}

class UsageRepository extends Actor with ActorLogging {

  val resources = scala.collection.mutable.HashSet.empty[Resource]

  override def preStart() = {
    log.info("Starting")
    scheduleUpdate()
  }

  def receive() = {
    case Update(resource)  =>
      resources += resource
      log.debug(s"Cache state after adding element : $resources")
    case Persist =>
      persist()
      scheduleUpdate()
  }

  private def scheduleUpdate() = {
    context.system.scheduler.scheduleOnce(10 seconds, self, Persist)
  }

  private def persist() = {
    log.info(s"Persisting ${resources.size} elements")
    // Left to the imagination of the reader
  }
}

The actor uses the ActorLogging mixin for convenient logging. Informational log messages are printed when the actor is started and each time the cache is persisted. When the application is running with debug logging, a message is printed each time the cache is updated, to assist in troubleshooting or debugging. This could result in a large number of log messages and negatively impact performance, so these log messages are not printed under normal operation at an informational logging level. If the following application is executed with informational logging, we see the expected log messages.

object Application extends App {
  val system = ActorSystem("app")
  val repository = system.actorOf(UsageRepository.props(), "usage-repository")

  repository ! Update(Resource("One", 1))
  repository ! Update(Resource("Two", 2))
  repository ! Update(Resource("Three", 3))
  
  sys.addShutdownHook {
    Await.result(system.terminate(), Duration.Inf)
  }
}

2016-10-02 17:17:48 INFO  Slf4jLogger - Slf4jLogger started
2016-10-02 17:17:48 INFO  UsageRepository - Starting
2016-10-02 17:17:58 INFO  UsageRepository - Persisting 3 elements

At first glace, this code looks fine. There are no obvious problems. But let's experiment by overriding the toString method of the Resource class, to print a message to the console each time this method is called.

case class Resource(name: String, count: Long) {
  override def toString = {
    val msg = s"name: $name, count: $count"
    println(msg)
    msg
  }
}

If we run the program again, we see output that we might not expect.

2016-10-02 17:17:48 INFO  Slf4jLogger - Slf4jLogger started
2016-10-02 17:17:48 INFO  UsageRepository - Starting
name: One, count: 1
name: Two, count: 2
name: One, count: 1
name: Two, count: 2
name: Three, count: 3
name: One, count: 1
2016-10-02 17:17:58 INFO  UsageRepository - Persisting 3 elements

The debug message is always constructed, even when, as in this case, the application is not run with debug logging, as evidenced by multiple invocations of the Resource class toString method. This is quite subtle and easy to miss in a code review. It is something that I would like a static analysis tool to highlight, but, at the time of writing, I don't know of one that does. I think it is particularly easy to overlook this subtle performance issue if you are coming from a language like C#, where Debug.WriteLine statements are not even executed unless debug mode is enabled, because they are decorated with the ConditionalAttribute and eliminated at compile time.

If the debug log statement uses the {} syntax for substitution parameters, as specified in the documentation, rather than string interpolation, the output is as expected.

log.debug("Cache state after adding element : {}", resources)

2016-10-02 17:18:00 INFO  Slf4jLogger - Slf4jLogger started
2016-10-02 17:18:00 INFO  UsageRepository - Starting
2016-10-02 17:18:10 INFO  UsageRepository - Persisting 3 elements

I'm not the first person to point out latent performance issues with actor logging. This certainly isn't something that I want to keep in mind for every code review. I would rather focus on the functionality and maintainability of the application in terms of the business requirements. For this reason, I prefer using the Scala Logging library, since it is less error prone. It is equally convenient to mixin to a class, but it has the advantage of only executing if debug logging is enabled. It is the equivalent of executing the following:

if (logger.isDebugEnabled) logger.debug(s"Some $expensive message!")

Using this mixin, we see the messages we expect, when informational logging is enabled.

class UsageRepository extends Actor with StrictLogging {

  val resources = scala.collection.mutable.HashSet.empty[Resource]

  override def preStart() = {
    logger.info("Starting")
    scheduleUpdate()
  }

  def receive() = {
    case Update(resource)  =>
      resources += resource
      log.debug(s"Cache state after adding element : $resources")
    case Persist =>
      persist()
      scheduleUpdate()
  }

  private def scheduleUpdate() = {
    context.system.scheduler.scheduleOnce(10 seconds, self, Persist)
  }

  private def persist() = {
    logger.info(s"Persisting ${resources.size} elements")
    // Left to the imagination of the reader
  }
}

2016-10-02 17:22:49 INFO  Slf4jLogger - Slf4jLogger started
2016-10-02 17:22:49 INFO  UsageRepository - Starting
2016-10-02 17:22:59 INFO  UsageRepository - Persisting 3 elements

Be aware of this subtle performance consideration when logging debug messages in your application. Favour using the Scala Logging library to avoid introducing unintended string allocations that may negatively impact performance.