Wednesday 18 April 2018

Performance Conscious Logging

There are few things to consider when you decide your logging philosophy to make it performance conscious. First let us breakdown the resources spent on logging.

  • CPU time spent on writing to the destination (I/O), can be file, console, network etc.
  • CPU time spent on appending or assembling a particular log line & garbage collection
  • Working memory spent on appending or assembling a particular log line
  • Wall time spent on waiting or fighting on a shared resource or shared destination. This may be a file on disk or a synchronous method inside the logging framework.
  • Disk space or any other storage occupied to persist the log file
Following are the things that you can do to minimize the above.
  • Have controls over logging. Have proper log levels so can only INFO,WARN,ERROR will be used in production, and DEBUG, TRACE will be used in development. Most importantly levels should not control writing the logs to the destination, but it should also control assembling log lines as well. To achieve this, use parameterized logging ( https://www.slf4j.org/faq.html#logging_performance ) or simply check the log level is enabled before assembling the log line. Using a lambda is an alternative as well.
  • Avoid costly formatting. If pretty printing is needed write a log extraction tool convert raw log lines to pretty log lines, which will happen offline, and on demand. There are lot of useful things that can be easily done if the logs are forwarded a tool like Splunk or ElasticSearch.
  • Minimize log size. Use shorthand codes to minimize the size of a log lines while preserving the readability.
  • Minimize log frequency. When deciding to log something, roughly estimate on how much log size/transaction or how many log lines/ transaction. If it is more than 1:100, then that is too much logging, well it depends.
  • Try asynchronous logging. In other words do not write to the destination (I/O) in the transaction thread, rather add it to a buffer and tackle it in the background. RandomAccessFileAppender is such facility provided by Log4J
  • Divide and conquer. Have the logs segmented. Later in production, this can be used to spread the load on destinations (I/O) by having different destinations (files) for different logs