Node.js 14 has been available since April 21, 2020.
This version embeds a new version of v8 but also a lot of new features like the AsyncLocalStorage class of the async_hooks module.
This class allows to store and access data throughout a series of asynchronous calls.
We will look together at how this can make our lives easier.
TL;DR
Let's imagine a web application that receives a request.
The entry point of my application is the function receiving a request and calling a service
const app = express();
const log = message => console.log(message);
const emailService = new EmailService(logger);
app.get('/', (request, response) => {
const requestId = uuid();
log(`[${requestId}] Start processing`);
await emailService.notify(request.body.emails, requestId);
response.writeHead(200);
});
In my application, I want to be able to add the unique identifier of the request to each log line so that I can correctly trace all related actions.
So if I want to log something in the EmailService, I'll have to give it at least the request ID.
class EmailService {
constructor (log) {
this.log = log;
}
async notify (emails, requestId) {
for (const email of emails) {
this.log(`[${requestId}] Send email: ${email}`);
sendGrid.send(email);
}
}
}
The problem is that my EmailService is only responsible for sending emails.
So it should not receive a requestId, because it shouldn’t care about a request!
Also, if you develop and distribute a backend or framework to other users, you can't force them to add a parameter to all their methods to pass the unique identifier of the request in case they want to log something.
So we'll have to find a way to retrieve the right requestId each time we want to log something.
AsyncLocalStorage provides a simple API to share a context in a succession of asynchronous calls.
Regardless of the number of services and methods used, we will always be able to retrieve our context and use it to store data.
First of all, we will wrap all our treatments in the callback of the AsyncLocalStorage.run method.
The first argument of this method will be attached to the asynchronous context started with the callback passed as the second argument.
const { AsyncLocalStorage } = require('async_hooks');
const asyncLocalStorage = new AsyncLocalStorage();
app.get('/', (request, response) => {
const requestId = uuid();
asyncLocalStorage.run(requestId, async () => {
// entering asynchronous context
log('Start processing')
await emailService.notify(request.body.emails);
response.writeHead(200);
});
});
Next, we will modify the log method in order to retrieve the requestId from the current asynchronous execution context.
For this, we will use the AsyncLocalStorage.getStore method.
const log = message => {
const requestId = asyncLocalStorage.getStore();
if (requestId) {
console.log(`[${requestId}] ${message}`);
}
else {
console.log(message);
}
};
So finally in our EmailService we don't need to pass the requestId anymore, we just use the log method which will retrieve the requestId from the current asynchronous context.
Of course there is an overhead to using AsyncLocalStorage and async_hooks in general.
At Kuzzle we always pay attention to the performance of our backend, that's why we wanted to know what the cost of this new feature was.
A micro benchmark was also carried out but as always this kind of results is to be taken with caution and a test in real condition should always be carried out before a decision is taken.
So we added AsyncLocalStorage to the execution of a request in order to keep the request ID so that we can add it to each log line. (Code available on Github)
Then we tested the performance with WRK, a tool to make HTTP benchmarks. These performance tests were done with NODE_ENV=production.
Log w/ AsyncLocalStorage | Log classic | Difference | |
Requests/sec | 2613 | 2842 | ~ 8% |
There is a drop in performance of less than 10%, which is still acceptable given the possibilities offered by this new API.
AsyncLocalStorage opens many perspectives in terms of operational analysis of your application, indeed it is possible to link all the events triggered by the same request.
In our example, our shared context is simply a String but it is quite possible to share more complex objects such as a Map for example.
const contextStore = new Map();
contextStore.set('requestId', uuid());
asyncLocalStorage.run(contextStore, async () => {
// entering asynchronous context
});
This opens many possibilities and use cases.
We could know the exact number of queries to Elasticsearch triggered by a request with other information such as the amount of data transferred and the execution time.
This would provide a very good tool for analyzing the performance of an application.
In Kuzzle, a request to the API can potentially trigger other actions with hooks/pipes or in a method of a plugin controller.
It would therefore also be possible to list all the methods used during request execution. (Eg: 3 document:create, 4 document:get, 2 collection:exists)
For example, we could create reports to analyze the underlying complexity of an API method.
Most of the time when working with callbacks, the first argument is an error.
If the execution has a problem somewhere, you have to go up the whole callback chain by passing this error.
One could imagine a system where the callback of the query response is stored in AsyncLocalStorage and all other callbacks would take only one argument.
An exception would be used to raise an error and a global error handler would retrieve the response callback associated with the execution context to call it with the caught error.
We plan to wait for the next release of Node.js 12 (12.17.0) before starting to use AsyncLocalStorage because this feature should be backported in this version of Node.js.
In the meantime do not hesitate to test it on your own applications!
I would like to thank my colleagues from Kuzzle for proofreading this article as well as Vladimir de Turckheim, the author of AsyncLocalStorage API.
If you have any questions or remarks, don't hesitate to come and talk to us on Kuzzle Discord ;-)