Hi, Habr!

I think almost every program has logging. Moreover, in a number of already new applications (which means with a sea of ​​non-trivial conditions), logs often become vital on a combat server.

However, despite the importance and prevalence of this technology, I noticed that people often make standard mistakes when working with them. This article largely describes the behavior of .Net, but I made small inserts from the Java world, just to make a comparison.

Allocation (memory allocation)

The most common mistake (according to my observations) is negligence in relation to small memory allocations near the place where the log.Debug(...) function is log.Debug(...) .

So, our standard code in .Net:

 private static readonly ILog Log4NetLog = LogManager.GetLogger(typeof(Program)); private static readonly Logger NLogLog = NLog.LogManager.GetCurrentClassLogger(); private static void PublishData(int id, string name, EMail email, decimal amount) { Log4NetLog.Debug($"Id={id}"); // 1 Log4NetLog.DebugFormat("Id={0}", id); // 2 Log4NetLog.Debug($"Id={id}; name={name}; email={email.Normalize()}; amount={amount}"); // 3 Log4NetLog.DebugFormat("Id={0}; name={1}; email={2}; amount={3}", id, name, email.Normalize(), amount); // 4 NLogLog.Debug($"Id={id}"); // 5 NLogLog.Debug("Id={0}", id); // 6 NLogLog.Debug($"Id={id}; name={name}; email={email.Normalize()}; amount={amount}"); // 7 NLogLog.Debug("Id={0}; name={1}; email={2}; amount={3}", id, name, email.Normalize(), amount); // 8 } 

In many respects, I only met the log4net and NLog libraries, and therefore I will use them in the examples.

So the questions are:

• In which lines will memory be allocated even if Debug is turned off?
• If memory is allocated, then how easy is it to detect in the same dotTrace, what specific loggers are to blame for this very memory allocation?

The correct answer to the first question: memory is not allocated only in paragraph "6". And the answer to the second question: to catch this is incredibly difficult, since such code is often spread over the project. You may recall a typical .Net application. It will often have similar code that makes GC work.

However, let's go through the technical details to see exactly where we will have an impact on performance.

So, the first point:

 Log4NetLog.Debug($"Id={id}"); // 1 

In fact, the compiler converts it to:

 var temp = string.Format("Id={0}", id); // <--       Log4NetLog.Debug(temp); 

That is, the first expression will essentially force the processor to create a string, passing it to the logger. He will quickly verify that logging is not necessary, and therefore the string is simply created in memory. And, what is important, if you dig out more such code, the lines will be created in heaps of program locations, that is, the program will work just a little slower. Everywhere.

The second example is slightly more efficient, since the string is not created in it:

 Log4NetLog.DebugFormat("Id={0}", id); 

However, the memory is still allocated here, since boxing will occur. Let me remind the signature of the DebugFormat method:

 void DebugFormat(string format, object arg0) 

As you can see, an entry type is required at the input. However, we are trying to pass a meaningful type int . As a result, each call will result in the removal of the id parameter in the heap, in order to pass it to the method. And let me remind you that in the method itself the parameter is not needed, since the Debug is turned off by the condition of the problem.

The following example is loaded and simple:

 Log4NetLog.Debug($"Id={id}; name={name}; email={email.Normalize()}; amount={amount}"); // 3 

I am sure that you already understood that again the line will stand out in a heap, and so on. Therefore at once we will pass this example. The following call method looks more efficient:

 Log4NetLog.DebugFormat("Id={0}; name={1}; email={2}; amount={3}", id, name, email.Normalize(), amount); // 4 

And so, but let's calculate how many times it is necessary to allocate a piece of memory:

• email.Normalize() results in the creation of an object. That is why this object will stand out in the heap (or on the stack - it doesn’t matter, since boxing will make everything stand out in the heap)
• id will go to the heap, as we’ve previously reviewed.
• Log4net has the following interface for similar long formatted calls: void DebugFormat(string format, params object[] args) . As you can see, .Net will create an array in the heap to pass it to the DebugFormat method.

As a result, a rather typical call to a logging operation will result in a heap of objects in memory. Which is pretty disappointing, since logging itself is often turned off. However, move on to NLog.

This line will trigger the selection of an object on the heap:

 NLogLog.Debug($"Id={id}"); 

Everything is obvious here, but the line below does not have the following disadvantage:

 NLogLog.Debug("Id={0}", id); 

And the reason is that NLog has a special signature for ints: void Debug(string message, int argument) . Moreover, even if you pass a different structure, the void Debug<TArgument>([Localizable(false)] string message, TArgument argument) method void Debug<TArgument>([Localizable(false)] string message, TArgument argument) called. And this method does not require boxing, since after JIT a separate function will be created for each type (of course, this is not quite so, but the essence is important: there will be no boxing).

I’ll skip the easy-to-understand script with a large input line and go straight to:

 NLogLog.Debug("Id={0}; name={1}; email={2}; amount={3}", id, name, email.Normalize(), amount); 

Strangely enough, NLog did not increase the number of Generic parameters for the methods, and therefore the signature would be used: void Debug([Localizable(false)] string message, params object[] args) . And it will again lead to the creation of objects in the heap and so on.

Conclusions and improvements

The main conclusion is that if you have many calls of logging methods in the program that do not lead to a physical record in the file, then you can out of the blue start allocating a lot of unnecessary objects on the heap. And thereby slowing down the work of the program.

Conclusion 2: If you transfer not many objects to the method, then use NLog. Due to the fact that it took care of the Generic parameters, you can be more relaxed about performance.

However, in order to be completely safe, it is more logical to do this:

 if (NLogLog.IsDebugEnabled) { NLogLog.Debug($"Id={id}; name={name}; email={email.Normalize()}; amount={amount}"); } 

Here the logging method will not be called if it is not necessary. However, if you still have to reset the data to the log, then the convenient String Interpolation will be used. Inside, loggers (at least the same NLog) are optimized to write a line to logs directly (i.e., formatting will take place immediately in the Stream , instead of creating a line in memory). However, this optimization of NLog fades away from the fact that it is necessary to reset the data to a file.

Kotlin example

To dilute the description of the work of popular loggers in .Net, I will give an interesting way to wrap calls in kotlin. The idea is built literally on one interesting possibility of the language: inline methods . So, a simple code for outputting something in debug:

 class SomeService{ private companion object : KLogging() fun publishData(id: Int){ logger.debug { "Identity: $id" } } } 

And it will be converted by the compiler into something like this:

 class SomeService{ private companion object : KLogging() fun publishData(id: Int){ if(logger.isDebugEnabled){ try{ val message = "Identity: $id" logger.debug(message) }catch (e: Exception){ /*handle*/ } } } } 

Here it is important: everything inside the curly braces near the debug is lyambda. However, it will be built into your method, that is, a function object will not be created in the heaps. Thus, you can hide large operations inside, which will be called only if you want to output the result in debug . For example:

 class SomeService{ private companion object : KLogging() fun publishData(id: Int){ logger.debug { val idList = getIdList() "Identity: $idList" } } } 

Here, getIdList will be called only if you need to send something to the file. And all because the code is converted to:

 class SomeService{ private companion object : KLogging() fun publishData(id: Int){ if(logger.isDebugEnabled){ try{ val idList = getIdList() val message = "Identity: $idList" logger.debug(message) }catch (){ /*handle*/ } } logger.debug { "Identity: $id" } } } 

Large Object ==> Large Object Heap

In addition to the previous example. I am sure that many people know that in .Net / JVM there is the concept of "Large Object Heap". More precisely, in Java there is no special definition, however allocators will often create large objects immediately in the last generation (to minimize the movement of objects and level the problem of fast memory penetration for a streaming allocator).

Let's go back to the example:

 NLogLog.Debug($"Id={id}"); 

As you understand, if the id object has a ToString implementation that creates a string of size in megabytes, then the face has the following hits in LOH:

• ToString call itself
• Formatting $"Id={id}"
• And if the developers of the logger did not catch all such things (and it is extremely difficult to write a test for the absence of objects in LOH), then the logger will add more problems.

And here you can use three ways to log such things:

• Use special layout and do not require calling ToString . For example, NLog has JsonLayout . Thus, you can simply transfer an object to the logger, which will be serialized immediately into the resulting stream (for example, to a file).
• Write to the file yourself. Or in other words - do not use the logger. From myself I can only advise how to find out which file NLog will write to: var filePath = NLog.LogManager.Configuration.AllTargets.OfType<FileTarget>().First().FileName.Render(LogEventInfo.CreateNullEvent()) . Obviously, this function will return the first FileTarget , but if everyone writes to one folder, then in a similar way you can find out the folder for writing, and then directly send a dump of your object to a file.
• If you have log4j2 (exactly the second, this is important), then you can use StringBuilderFormattable . It is just created in order to output the data to the logger in chunks (moreover, in order not to allocate part of the chunks in the heap yet, since they have already been allocated).

 public interface StringBuilderFormattable { /** * Writes a text representation of this object into the specified {@code StringBuilder}, ideally without allocating * temporary objects. * * @param buffer the StringBuilder to write into */ void formatTo(StringBuilder buffer); } 

Synchronicity (and asynchronous problems)

Once, in one program, I noticed that during load operations, about half the waiting time for the UI was for logging operations. Once again: half of the time the program took to call logger.Debug or something like that. And the reason is simple: we used log4net, which can only write files synchronously.

From here I derived rule 1 : the logger should always work in a different thread. You should not block the application code for the sake of traces, because it is incredibly strange. In other words - using NLog - it is always necessary to put down async=true in the nlog tag (it is the main one). Or, as stated in the example :

 <targets async="true"> ... your targets go here ... </targets> 

If you use log4net, either redirect it to NLog, or make AsyncFileAppender.

For the Java world: both Logback and Log4J2 have the ability to do asynchronous logging. Here is a comparison from the official site :

However, when everything is written asynchronously, another problem arises - what to do in case of critical errors? After all, it happens that the program shuts down not because it left the Main stream (for example, the program can end by calling Application.Exit or Environment.FailFast , which is not very nice, but it occurs). In this case, you should always call Flush before killing your process. Otherwise, if you fall on the battle server, the most valuable information will be missed.

Conclusion

I hope this article will help write fast programs with convenient logging. I highlighted only a part of the problems that I see in the code. All of them are not the most obvious, however, and not the most complex.

In any case, as I said at the beginning, work with loggers is practically every application. Moreover, according to my notes, about half of the classes themselves display something in the log. Thus, the correct operation with these functions affects almost the entire application as a whole.