Roger Ngo's Website

Personal thoughts about life and tech written down.

High Performance Logging

Introduction

Logging is essential to any application. You never know when you might need that extra tracing information to diagnose a production incident, or debug through that one gnarly bug which you can't seem to reproduce!

While working on a side project of mine, I decided to implement logging into the service to be able to gather some data for future debugging and validation.

The technology I chose to implement this service was Node.js, and the logging framework I had chosen was log4js, a port of log4j in JavaScript.

Little did I know, not only choosing where and what to log is important, but also the fact that patterns and practices in using the logging framework is critical to performance of the overall application.

First Attempt - Weak Performance

When I first installed log4js, I had naively chose to do file-append logging with each log entry being assigned and associated with a correlation ID. The thought of using a correlation ID for every log entry was to be able to perform a back-trace on every request and response which would be linked to a single operational context. In this case, for my application, it was an HTTP request. This is fairly standard practice when implementing some sort of logging into an application.

Though the approach was correct, the implementation was flawed from a performance perspective.

To generate the correlation ID, I decided to use UUID strings generated by the uuid Node package. A quick snippet on how this is done is shown:

const uuidv4 = require('uuid/v4');

global.contextId = uuidv4();

This assigns a generated UUID to the Node.js contextId property within the global object. From here, we would be able to reference this property and retrieve the value throughout all other modules within the lifecycle of our application.

Now, in order to initially configure the log4js framework to make use of this ID as a logging correlation ID,I had configured the logging framework to make use of 2 different types of appenders: the file-appender and the console appender. Documentation relating to this can be found in the log4js documentation here.

I decided to abstract the configuration and initialization of the logging framework here by wrapping it within a function called initialize within its own module.

const log4js = require('log4js');

const initialize = (logFileName) => {
const _logFileName = logFileName || 'debug';
log4js.configure({
    appenders: {
        main: {
            type: 'file',
            filename: `log/${_getLogFilename()}.${_logFileName}.${os.hostname()}.log`,
            maxLogSize: 16384000,
            backup: 10,
            compress: false,
            layout: {
                type: 'pattern',
                pattern: '[%x{contextId}] [%d] [%p] %c - %m',
                tokens: {
                    contextId: global.contextId
                }
            }
        },
        console: {
            type: 'console',
            layout: {
                type: 'pattern',
                pattern: '%[[%x{contextId}] [%d] [%p] %c%] - %m',
                tokens: {
                    contextId: global.contextId
                }
            }
        }
    },
    categories: {
        default: {
            appenders: ['main', 'console'],
            level: config.LogLevel
        }
    }
});

return log4js;
};
    

The implementation calls the configure function within the log4js object with the object containing all the information needed to create the appenders. Specifically, we provide standard things such as:

  • Filename
  • Max size of the log
  • How many log files to keep in rotation
  • Whether to compress the old log files

And most importantly, the logging layout for each entry as defined in the layout property.

Defining the custom logging layout allows us to make use of token values, which would be the replacement values for the the token defined within the pattern. Here, our UUID correlation ID makes an appearance as a replacement for the contextId token.

As you can see, I have made a direct reference to the global.contextId variable with the intention that each new request updates the global.contextId variable and have the logging framework reinitialze the appenders with the new ID value.

Each request would update the global.contextId and reinitialize the global logging variable like so:

const server = http.createServer((req, res) => {
global.contextId = uuidv4();
global.LogManager = LogManager.initialize('application');

// make use of the logger in the context of this category
const currentLogger = global.LogManager.getLogger('main-server');

... do stuff here ...
});
    

Not so Fast!

Here is where things go wrong. The first point is that it is completely wasteful to reinitialize the file appender each and every time a request is made to the server. The immediate initial thought for a solution was to initialize and configure log4js just once:

global.LogManager = LogManager.initialize('application');

const server = http.createServer((req, res) => {
global.contextId = uuidv4();

// make use of the logger in the context of this category
const currentLogger = global.LogManager.getLogger('main-server');

... do stuff here ...
});
    

This would assume that then, on every request we will assign a newly generated UUID to the global.contextId variable and the log4js object will pick it up.

Apparently, this was not the case. The reason being is that the variable is pointed to a value and not an object. Therefore on each request, the new log entries would retain the initial UUID that was generated upon server initialization. Thus, each subsequent log entry will have the same UUID attached to the request regardless of whether or not it was a new client who initiated the request.

Reading the documentation provided by log4js actually allowed me to solve this issue easily! Simply wrap the assignment of the token value within a function upon configuring the log4js object to return the current value held in global.contextId:

log4js.configure({
appenders: {
    main: {
        type: 'file',
        filename: `log/${_getLogFilename()}.${_logFileName}.${os.hostname()}.log`,
        maxLogSize: 16384000,
        backup: 10,
        compress: false,
        layout: {
            type: 'pattern',
            pattern: '[%x{contextId}] [%d] [%p] %c - %m',
            tokens: {
                contextId: () => { return global.contextId; }
            }
        }
    },
...
}
});
    

With that single initialization, we will then assign the the contextId within the tokens property to refere to a function which would then return the current UUID assigned to the global.contextId variable.

This allows us to then initialize the logging framework just once, and only focus on making sure that a new correlation ID is generated for each request.

Appender Type Matters

There might be questions as to why I chose to log into a file. Why not directly to some sort of database? The answer is that file I/O is much faster than network I/O. With file operations, we are limited by just the speed of the reads/writes of the disk minus the compute time it takes to initialize the file calls. With network operations, we must make a remote call over the wire which can travel certain amount of distance which adds an additional network latency on top of the destination file I/O operation.

On applications which experience lower levels of load, this sort of difference between file I/O and network I/O is not immediately apparent. However, as you increase the load of the application by attempting to serve more requests, it will be apparent that network transfers simply cannot keep up with the other operations involved in ultimately generating a response.

For my purposes, simply writing to a file was enough given the expected load of my application. Perhaps if one needs to scale further in performance, buffering the log entries and flushing periodically to file would be a simple optimization.

Log Level and Choosing What to Log

I have lumped these two to its own section simply because they go hand in hand. Choosing what to output into your appender through the use of log levels will alleviate a lot of noise. Making sure that you are only outputting WARNs, ERRORs, and CRITs on a production environment is smart.

We tend to like to sprinkle lots of DEBUGs and INFO-level statements throughout our application because we are tempted to think that they will serve a purpose during debugging. This is true in a development environment, but not practical in production.

The above statement can be a touchy religous view -- it really depends on your development team and yourself. I strongly believe that a lot of issues should be caught during testing before code is made out to production. This assumption leads me to believe that DEBUGs and INFOs which logs things such as entering functions, verification of function returns, assignments, and other "printf" type of statements should not be visible in production-level logs.

Each log entry results in a penalty in performance. So be mindful.

A solid middle ground is to make your log level configurable. Therefore, check to see if the log level is enabled then log the entry into your appender. This can be made through some sort of application-level configuration variable. From here, it can be dynamically set to any level should more verbose tracing be needed in a production-type of environment.

Key Logging Tips

And now, in summary, I present to you my suggestions on how to make sure your logging will not take down your application with 4 simple tips:

Lesson 1 - Learn to Use Your Logging Framework

I had made the mistake in not properly configuring my logging framework. I did not configure the log4js logging appenders appropriately and was reinitializing the object and reconfiguring the logging object after each request!

Lesson 2 - The Appender Matters

Do not append to a remote destination if you do not have to. Using a remote location as a logging destination can cause a serious bottleneck by increasing latency and decreasing reliability. Remote calls are slow due to having to create a connection and sending that data through the wire. The process requires time. Not only that, the connection to the remote destination can unexpectedly drop during the process -- thus decreasing reliability in your log entry potentially never reaching the destination.

Keep logging local to the file system and move them to a remote location for storage as needed.

Lesson 3 - Log Level

If you are on a production-like environment, for various security reasons along with the high-frequency of logging activity which would cause noise, avoid logging at the DEBUG level, and if possible avoid the INFO level as much as possible. WARNs, ERRORs, and CRITs are more important for production.

If a number of ERRORs are encountered, make your application flexible enough to switch logging level on the fly. This can typically be achieved through an application configuration setting.

Lesson 4 - Choose What to Log

The main question to ask if you are in need to log absolutely everything. Do you really need to log everything? Keep in mind, each logging statement is another append to a destination -- whether it be file (I/O operation), or remote (network operation). All the additions to the log requires CPU cycles, latency, etc. Unnecessary logging will consume time and resources. Think about whether or not something is worth logging.

Does your logging statement provide valuable information if incident management is to occur? Is your log statement just outputting something along the lines of "Entering [x] function."? If so, then it is a useless logging statement. Testing should have made sure that certain parameters trigger code paths that enter and exit functions as expected.

Logging statements such as confirmation that a remote call to a database for instance, is also very useless. Almost always, the operation to a database should succeed in production. Otherwise, such an operation and situation should have been caught during testing. Failures to a remote call due to network connection, bad credentials or INSERT statements to a database should be logged and should be expected to happen in low-frequency if proper QA is done.

Conclusion

It could be said that no logging is the best thing for performance, but that is unrealistic in the real-world where we actually need application traces in order to sanely diagnose problems.

The best we can do is to make sure we know what our logging framework can do, and leverage it for our intentions. Choosing how to log, what to log and where to log are the important questions to ask when creating a highly performant logging practice.