Typical logging mistakes

The most of our .Net/Java applications have logging functions. Moreover, for old semi-legacy applications (with a lot of non-trivial conditions inside) production logs are extremely important for effective support.

In spite of fast tracing importance I found, that a lot of programs have the same obvious mistakes. This article is about .Net world, however I added java code too.

Memory allocations

The most common mistake (from my observations) is neglect avoidance of unnecessary object creation. For instance, let’s see deeply on the frequent method log.Debug(…).

The common .Net code:

I worked with log4net and NLog in the most of time, so I use them for examples.

And questions:

• What lines allocates new objects even if Debug mode is disabled?
• If memory is allocated, how you can find this by using memory analyser (for example — dotTrace)?

Right answer on the first question: memory is not allocated at the six line only. And answer on the next question: it is too difficult to find this (in generic way), because such code is spread across the whole project. So you could not find line with a lot of allocations, because you have a lot of the same code, which does the same operations (e.g. create new objects). Just remember your old typical .Net projects — with big probability you have the same code, which loads GC below normal.

However let’s analyse our example deeply to understand, where we impact the performance.

First line:

After F9 key press (or Ctrl-B) compiler generates something like this:

So our first line asks processor to create new line and put it into the logger. Then tracing library checks, that Debug is disabled, therefore it does zero IO operations. However new object is in memory until the next GC. After copy-pasting (the most productive application development, from the some opinions) this behavior is applied to the many classes, so application just works slower. Everywhere.

The second example is a bit more efficient, because you don’t allocate memory for new string:

However you still create object in heap. The reason is boxing. Just to reming DebugFormat signature:

As you can see, only reference type can be used here. However we try to use value type int (or System.Int32). Therefore each call leads to creating new object in heap id. And it is needed just to call method which does nothing.

The next example is simpler for potential allocation detection:

I think you understand, that line above will allocate new string, because of string.Format implicit call. However next example is looks like more efficient:

And that is true, however let’s compute, how many objects we need to allocate:

• Statement email.Normalize() looks like is followed to new object allocation. So new string (or object) is allocated in the heap or on stack (last one is possible, because of JIT optimizations). However it does not matter, because object is allocated (the same with previous examples).
• id goes to heap, because of boxing. We observed this above.
• Log4net has the following interface for the such methods: void DebugFormat(string format, params object[] args). As you can see, .Net creates new array in the heap (implicit of course) to call method DebugFormat. And the same with above, array is created in your method, not inside the log4net library. And again these allocations are spread across the application. And that is offensively, because usually you turn off logging on production (and don’t turn allocations).

However, let’s check another logging library — NLog.

The same with log4net, line below requires new object in the heap:

However line below does not have this disadvantage:

The reason is in special method for the first int parameter in NLog: void Debug(string message, int argument). Moreover if you use struct, NLog uses generic method void Debug<TArgument>([Localizable(false)] string message, TArgument argument). And it does not require boxing, because JIT creates separate function for every type (formally it is not completely true, however the main cause — boxing does not required).

Let’s skip simple example with a huge input line and let’s check the following:

NLog does not have special generic method event for four parameters, so this signature is used void Debug([Localizable(false)] string message, params object[] args). And this requires object allocation in heap, etc.

Summary

Important point: if your application has a lot of logging methods, which don’t lead to physical IO operation, you may allocate a lot of unnecessary objects in the heap. And your application works slow, because of this.

Another point: if you throw logging methods with less than four parameters then just use NLog. It has special Generic parameters, which prevent for unnecessary allocations.

However to be on completely safe side (for really huge methods) it is better to use something like this:

As you can see, log methods are not called here, if it is not needed. However if you want to drop data into the logs then the convenient string interpolation is used. Inside loggers there is optimization to put this line directly into the Stream, which helps to avoid allocations. However IO operation eats resources (but in the separate thread for NLog).

Kotlin language example

Just to show example from the another stack, I’d like to demonstrate interesting technique from the Kotlin language. The idea is based on the small language ability: inline methods. So the simple code to drop something into debug log:

debug method is marked as inline, therefore our code is converted to the something like this:

All inside curly braces is lambda. It is embedded into the outer method, therefore it is not allocated in the heap. Moreover you can hide resource-expensive operations inside the logging block. And they are called only if IO operation is really needed. For example:

Here getIdList is called only if logger is enabled. And this is because of method is converted to:

Large Object ==> Large Object Heap

As you know, .Net/JVM has term “Large Object Heap”. Java does not have constant for them, however the most of allocators creates such objects at the last generation (to avoid frequent GC, because of such objects). This works slow for allocation, however helps for Garbage Collector.

Let’s return to our example:

Let’s imaging that id object has implementation ToString, which creates string with million symbols (e.g. size of String is about 1 Mb). Then the following LOH allocations are appeared:

• ToString call
• $”Id={id}” formatting
• If logging library developers don’t catch all same items (which are very hard to detect of course) then logger adds new problems too.

And here you can use one of following techniques to avoid such allocations:

• Use special layout, which does not require ToString call. For instance NLog has JsonLayout. And usage is the same: you can just push new object into the logger, e.g.: logger.Debug(id).
• You can write to file manually. In in the other words — avoid using loggers for such operations. You can get the loggers file name by using something like this: var filePath = NLog.LogManager.Configuration.AllTargets.OfType<FileTarget>().First().FileName.Render(LogEventInfo.CreateNullEvent()). Obviosly this function returns the first FileTarget, however if all your loggers writes into the same folder then you can get it by analysing any FileTarget.
• Some logging libraries have special construct to avoid ToString calls. For example, log4j2 from java world has interface StringBuilderFormattable. It has special method (please see signature below), which is called to avoid solid block allocations.

Blocked and non-blocked logging

Once I found, that application spends at about 50% of the time at the logging operations (during the intensive work only). So program worked twice slower than possible, because of methods logger.Debug and something like this. And the reason was in synchronous nature of log4net library, which we used.

After this case I found the most important rule of logging: IO operations should work in the different thread. You should not block your application for tracing operations. For instance: always set async=true inside nlog root tag. Just by example:

If you use log4net — just add log objects forwarding to NLog (or write custom manual AsyncFileAppender).

Logback and log4j2 from java world can do asynchronous logging. Here is performance comparison from their official web site:

However asynchronous logging has one difficult: what shall we do for critical failures? Sometimes application finishes work not because of Main thread finish. For example, program can exit because of calling Application.Exit or Environment.FailFast, which looks like smell, however can be happened. In this case it is better to call Flush before target process killing. Otherwise you may loose important error data, which is related to application failure.

Summary

I hope this article helps you to write fast applications with convenient logging. I highlighted only part of problems, which I saw in various code. All of them are not so obvious (however they are not so complicated too).

Anyway, the most of applications have traces. Moreover, by my observations, at about half of classes do logging. So effective logging functions usage affects whole application, which is important (from my point of view of course).