Logging in Project-X
Version: 17.07
Overview
Log statements in code is essential for many reasons. Sometimes in multithreaded applications and distributed applications logging becomes the only way of debugging. Logging is also useful for the fact that it provides precise context about a run of the application. Log output can also be saved in persistent medium to be analysed at a later time. Therefore logging is an important component of the development cycle.
Project-X has it’s own logging API namely X-Logging. One of the main reasons behind the design decision to develop our own logging API in Project-X is that it allows us to code without being bound to one specific logging implementation. Hence migrating from one logging implementation to another will not be an issue for Project-X. Not just that but there are also other logging API level improvements that are made in X-Logging API to make logging easier as well as to make more use of logging. One such improvement is the Concept of Log Codes and Log Code Governance which will be discussed in details shortly.
In the current implementation, Project-X uses Log4j 2.x as the logging implementation. One of the main advantages provides by log4j2 is Async Logging. In multi-threaded scenarios Asynchronous Loggers have 10 times higher throughput and orders of magnitude lower latency than Log4j 1.x and Logback.
-
Concept of Log Codes and Log Code Governance
-
Independent & Easy to use Logging API
-
Async Logging
Concept of Log Codes and Log Code Governance
In addition to the usual logging semantics X-Logging provides a concept of log codes which will be used in logging as a thread context extension. Further more, it provides governance over the log codes used across the system using an annotation called LogInfo. While the log code being capable of pointing to the absolute positions in the code it could also be used for log monitoring solutions. The log code emitted by the logger has 12 characters, of the following form. Note that the code is always padded with preceding '0' and the padding process is transparent from the user API.
Log Code Format
Let the code be of the form TTTMMMLLSCCC the following table describes the full code.
|
Component Type |
3 character String representing the Component Type of the logger |
||||||||||
|
Module Id |
Three digit module id specified in the annotation LogInfo. |
||||||||||
|
Logger Id |
Two digit logger id specified in the annotation LogInfo. |
||||||||||
|
Severity/Log Level |
Log level of the log statement, one of [T, D, I, W, E] characters to denote log level.
|
||||||||||
|
Code |
Three digit code used to identify individual log lines. |
Independent & Easy to use Logging API
As mentioned previously Project-X logging API does not bind to any logging implementation hence migrating Projet-X to another logging framework is only a matter of changing the API implementation to use the new logging framework and no any other code level change is required.
X-Logging API includes methods mainly of two types. One type the typical logging API method which basically accepts a format and a set of object arguments as shown below.
void info(int status, String format, Object... arguments)
The other is the Java-8 style method which accepts a Supplier as shown below. This is very useful in scenarios where obtaining the arguments for the log is an expensive operation. In such cases we can provide that operation as a supplier and it will only be evaluated if the given log level is allowed to be logged.
void info(int status, String format, Supplier<?>... argumentSuppliers)
Apart from methods of these two types, there is new method introduced namely errorOnDebugOrWarn which implements the following pattern where we want to see the stack trace with the error if debug is enabled and if not we only want to see a warn with the error message.
if (logger.isDebugEnabled()) {
logger.debug("Error doing operation", e);
} else {
logger.warn("Error doing operation", e.getMessage());
}
The errorOnDebugOrWarn method is as follows.
void errorOnDebugOrWarn(int status, String format, Throwable t, Object... arguments)
|
You might have noticed that there is an integer parameter called status in all the above methods. This is a parameter required for the log code generation and it represents each individual log line. |
Async Logging
As mentioned previously Project-X logging uses log4j2 as the logging implementation. Therefore Project-X has the advantage of Async Logging. Asynchronous logging improves application’s performance by executing the I/O operations in a separate thread. Here are a few benefits of Async Logging, directly taken from log4j2 documentation titled Asynchronous Loggers for Low-Latency Logging.
-
Higher peak throughput. With an asynchronous logger your application can log messages at 6 - 68 times the rate of a synchronous logger.
-
Lower logging response time latency. Response time latency is the time it takes for a call to Logger.log to return under a given workload. Asynchronous Loggers have consistently lower latency than synchronous loggers or even queue-based asynchronous appenders.
Logging Peak Throughput
The graph below in Figure 1 compares the throughput of synchronous loggers, asynchronous appenders and asynchronous loggers. This is the total throughput of all threads together. In the test with 64 threads, asynchronous loggers are 12 times faster than asynchronous appenders, and 68 times faster than synchronous loggers.
Asynchronous loggers' throughput increases with the number of threads, whereas both synchronous loggers and asynchronous appenders have more or less constant throughput regardless of the number of threads that are doing the logging.
Figure 1. Async vs Sync Throughput (source - log4j2 documentation)
Response Time Latency
The graph below in Figure 2 compares response time latency of the ArrayBlockingQueue-based asynchronous appenders in Logback 1.1.7, Log4j 1.2.17 to the various options for asynchronous logging that Log4j 2.6 offers. Under a workload of 128,000 messages per second, using 16 threads (each logging at a rate of 8,000 messages per second), we see that Logback 1.1.7, Log4j 1.2.17 experience latency spikes that are orders of magnitude larger than Log4j 2.
Figure 2. Response Time Async Logging (source - log4j2 documentation)
Even though there is a huge performance improvement when using async logging sometimes one might want to use sync logging as well. In that case a mixture of synchronous and asynchronous Loggers can be configured through log4j2 configuration.
In this topic
In this topic