For a typical system, performance problems are mainly affected by:

• Code implementation issues
• Architecture issues: for example, can we add a caching system (e.g. Redis) to improve query efficiency?
• There are system problems with the systems we rely on: for example, MySQL, which we rely on heavily, is overloaded

This time we will focus on the details from the first point of view: code implementation, code by code

This is actually a skill problem, can continue to sum up

Using V8 profiling results in the following:

Profiling results in ordering functions in code from highest to lowest in terms of the number of times a function is called, and as you can see from this graph, the one that consumes us the most is fs.readsync;

This was a surprise to me because I didn’t feel like there was any file reading in the code, especially synchronous file reading, but why?

Moving on to bottom-up, this shows the entire function call stack from the outside in:

Fs.readsync == == == == == == == == == == == == == == == == == == == == == == == == == == == == == == == == == == == == == == == == == = This is mainly due to my understanding of the loading mechanism of Node modules. I thought Node would compile with all require statements in advance, but it doesn’t.

In addition, write a demo to prove the logic again:

// require in the header require(' HTTP '); require('https'); require('child_process'); require('cluster'); require('fs'); require('crypto'); require('net'); require('events'); require('zlib'); require('util'); function f() {} var startTime = new Date().getTime(); f(); var endTime = new Date().getTime(); Console. log(endtime-starttime) // The result is 0Copy the code

Function f() {require(' HTTP '); require('https'); require('child_process'); require('cluster'); require('fs'); require('crypto'); require('net'); require('events'); require('zlib'); require('util'); } var startTime = new Date().getTime(); f(); var endTime = new Date().getTime(); console.log(endTime - startTime); / / get 39Copy the code

That says it all.

However, Node will cache the require itself, so it should not be a performance bottleneck even though the require is called many times and the IO is synchronized.

So let’s move on

The above two analyses and changes are minor tweaks that do not involve the bones of the system itself. We continue parsing: we can see that the top file is error-stack-parser.js, which comes from the error-stack-parser I introduced.

Why did I introduce this dependency?

I have written a log output module, but the output format I want in the log output module is:

Date (YYYYMMDD) LEVEL APP_NAME message (in fileName:lineNumber)

Where date (YYYYMMDD), fileName and lineNumber are variables, where fileName and lineNumber are obtained?

Use (new Error()).stack to parse as baryon/tracer did. In addition, I introduced error-stack-parser for easy parsing, and error-stack-parser uses regular expressions to parse, which is very slow!!

The cause of the problem is found, but how to solve it?

The easiest way, of course, is not to print fileName and lineNumber, but that’s not what I want.

The alternative, of course, is to pass fileName and lineNumber wherever you type log. Node has a preset variable __filename, but not __line, and, Logger.debug (” MSG “) from logger.debug(” MSG “) to logger.debug(__filename, __line, “MSG “) is not a good idea. No logger module requires this.

I remember when I wrote C++, the output of logging was wrapped in a macro, such as:

#define LOG_INFO(format, args...) { \ logger->log(alog::LOG_LEVEL_INFO, __FILE__, __LINE__, __FUNCTION__, format, ##args); }Copy the code

So can I do the same?

Babel is a nice thing that allows us to create our own syntax, so we can use Babel and change our code from Logger.debug (” MSG “) to: Logger.debug ({fileName: “fileName “, lineNumber: 12},” MSG “)

Let’s implement the Babel plugin:

const path = require('path'); const LOG_PATTERN = /__LOG_(\w+)__/; module.exports = ({types}) => { const void0Expression = types.unaryExpression('void', types.numericLiteral(0), true); let transformLog = (nodePath, state) => { let calleeName = nodePath.node.callee.name; let matched = LOG_PATTERN.exec(calleeName); let methodName = matched[1].toLowerCase(); let filePath = path.resolve(state.file.opts.filename); let startLineNumber = nodePath.node.loc.start.line; let calleeInstance = ""; if (nodePath.node.arguments[0].type === "MemberExpression") { calleeInstance = nodePath.node.arguments[0].object.name + "." + nodePath.node.arguments[0].property.name } else { calleeInstance = nodePath.node.arguments[0].name; } let calleeExpression = types.identifier(calleeInstance + "." + methodName); let logBasic = types.identifier(JSON.stringify({ lineNumber: startLineNumber, fileName: filePath })); let calleeArguments = [ logBasic ]; for (const arg of nodePath.node.arguments.slice(1)) { calleeArguments.push(arg); } let joinedCallExpression = types.callExpression(calleeExpression, calleeArguments); nodePath.replaceWith(joinedCallExpression); }; return { visitor: { CallExpression: function(nodePath, state) { let calleeName = nodePath.node.callee.name; if (LOG_PATTERN.test(calleeName)) { transformLog(nodePath, state); }}}}; };Copy the code

After this plug-in conversion:

__LOG_DEBUG__(self.logger, 'got instance: %s', name);Copy the code

To become

self.logger.debug({"lineNumber":224,"fileName":"/Users/wuliang/zone/node-guice/src/v2/Guice2.js"}, 'got instance: %s', name);Copy the code

Ok, let’s test the performance again:

QPS is almost 300+, a ten-fold increase.

After the above results, I found a certain bottleneck in the overall performance. I feel that the big head has been optimized, so we will look at the details of which can be optimized

There are two points that can be optimized:

• new Date().getTime() vs Date.now()
• Date formatting library selection

There are a lot of Date formatting options, like moment, fecha, which is much smaller than moment,

I used to use fecha, but after performance testing, I finally chose speed-date with cache.

Why is that?

Because my Date formatting is mainly on the originalUrl of the output request, and our system has very heavy traffic, so the benefits of caching the formatting stage at the same time are obvious.

For example, in my log library, we do the log date, level and other information are color output (write JS can do these, ha ha); However, color output is useless in production because production logs are written to a file, and normal modules do istTY judgment to decide whether they want color output or not. This judgment is therefore a liability in the production environment.

Solution: Add a startup environment variable, such as NODE_ENV=production, to mask the color output.

There is an implicit optimization point that I suddenly noticed because we added CORS to all request headers. The previous code was:

app.use(function (request, response, next) {
    response.header(
        'Access-Control-Allow-Origin',
        request.headers.origin
    );
    response.header(
        'Access-Control-Allow-Headers',
        'Content-Type, Access-Control-Allow-Headers, Authorization, X-Requested-With'
    );
    response.header(
        'Access-Control-Allow-Methods',
        'GET,HEAD,POST,PUT,DELETE,OPTIONS'
    );
    response.header('Access-Control-Allow-Credentials', 'true');
    next();
});Copy the code

When I changed to:

response.header({
    'Access-Control-Allow-Origin': request.headers.origin,
    'Access-Control-Allow-Headers':
        'Content-Type, Access-Control-Allow-Headers, Authorization, X-Requested-With',
    'Access-Control-Allow-Methods':
        'GET,HEAD,POST,PUT,DELETE,OPTIONS',
    'Access-Control-Allow-Credentials': 'true'
});
next();Copy the code

After the optimization of the above analysis five and six, the final test results are as follows:

The graph above is just the QPS of some points. I analyzed the jmeter log and found that ==QPS reached: 680, which is 32 times higher than before.

The points involved in performance are:

• The 1.x release made heavy use of Kriskowal/Q as the Promise library, but after profiling, the performance of this library was not very good
• Don’t Blindly use Promises: A number of methods have used promises in the past for general purpose purposes, but the reality is that this approach is too blind and affects performance, and should be used appropriately
• Don’t use it blindlyprocess.nextTickThe same goes for this one, because it pushes tasks to the next poll. Using it blindly causes things to be done later when they could be done now, and because you can’t predict the time consumption of tasks in the queue.