In Unit 4 of the Node.js Learning Path, I do a deep dive into asynchronous and synchronous programming. To fully understand this concept, I will walk you through three different scenarios that compare the two programming models and demonstrate why Node’s asynchronous programming model makes it so powerful.

Node.js Learning Path

We also cover some key concepts along the way, including Node.js’s module system, performance profiling, and Node’s http

Node programming style

If you search the web for Node.js, you won’t have to scroll through many results before a theme becomes apparent: Node.js uses a non-blocking – asynchronous – coding style. You may be wondering, “Why would Node force developers to do this?” I’ll explain the answer to that question in this unit and give you a few more Node tools.

But first, I want to tell you a story that illustrates the difference between blocking (synchronous) and non-blocking (asynchronous) coding.

The bank and the coffee shop

This story is about two familiar types of business: the bank and the coffee shop. While they serve very different purposes, fundamentally they exist to serve us. How they do that is very different.

The bank (Blocking)

You walk into your local bank branch, and in front of you is a queue of customers. In front of the queue are several teller windows, and behind each open window sits a teller assisting a single customer.

The banking model of transaction processing is blocking:

• A single teller may only help one customer at a time.
• The teller handles all steps in your transaction in order.
• If the teller cannot handle a step in your transaction – let’s say it requires a supervisor approval – the teller is blocked waiting for the approval before he or she may proceed.
• When the entire transaction is complete, you leave the teller window.

To serve more customers or serve customers more quickly, this model can scale in two ways:

• Vertically – add more tellers
• Horizontally – add more bank branches

The nature of a banking transaction is synchronous. The teller alone must complete all steps in the transaction before the teller can assist another customer.

The coffee chop (Non-blocking)

You walk into your local coffee shop, and in front of you is a queue of customers. In front of the queue is one counter employee who takes orders and processes payment, and one or more baristas behind the counter preparing orders.

The coffee shop model of transaction processing is non-blocking:

• A single counter employee may only help one customer at a time.
• A barista prepares one order at a time.
• The counter employee and barista share all the steps to complete your order.
• While the barista prepares your order, the counter employee is not blocked and may take other customer’s order.
• Later, when your order is ready, your name is called, and you step forward to collect it.

To serve more customers or serve customers faster, this model can scale in two ways:

• Vertically – add more baristas
• Horizontally – add more coffee shops

The nature of a coffee shop transaction is asynchronous. The counter employee simply takes orders, processes payment, and collects enough information so that the customer can be notified when his or her order is ready. The counter employee then helps the next customer, while the barista, in parallel, works on fulfilling orders.

Blocking versus non-blocking

Blocking: At the bank, the teller helps you from start to finish. Customers in the queue behind you must wait until your entire transaction is complete. If there is a step in the transaction that cannot be completed by the teller, the teller is blocked while that step is completed.

Non-blocking: At the coffee shop, the counter employee and the barista work together to complete your order. The counter employee takes your order and is not blocked while the barista completes your order.

I realize this isn’t a perfect analogy (some banks use multiple tellers to complete transactions, and some coffee shops have multiple people taking orders), but hopefully you understand the difference between the two programming models.

Node uses the coffee shop model. A single thread of execution runs all of your JavaScript code, and you provide callbacks to wait for results.

Other software stacks use the bank model. To scale, more threads (or processes) are created. Apache web server is one example that uses the bank scalability model.

Both models, of course, can achieve horizontal scalability by adding more servers.

The “dark side” of asynchronous programming: The chatty coffee shop counter employee

Now, there is a “dark side” to the non-blocking model: the chatty coffee shop counter employee. What if the employee at the counter is more interested in chatting with each customer than in diligently taking orders and payments? The line backs up, the baristas idle, and the whole process grinds to a halt.

This can happen with Node programming, too, where one application isn’t behaving properly, so it stalls or slows the process. In this tutorial, I show you how to profile your JavaScript code to look for those poor-performing “hot spots”.

Synchronous versus asynchronous – Act 1

“Blocking is when the execution of additional JavaScript in the Node.js process must wait until a non-JavaScript operation completes. This happens because the event loop is unable to continue running JavaScript while a blocking operation is occurring.

In Node.js, JavaScript that exhibits poor performance due to being CPU intensive rather than waiting on a non-JavaScript operation, such as I/O, isn’t typically referred to as blocking.”

In the first example (Act One), I take liberties with this definition just as a way of introducing the topic. Thank you in advance for this leeway while I move the discussion towards true blocking vs non-blocking examples. We will get there.

Get the code

All of the source code examples below are available in the GitHub repo for the Learning Path. To save space in the listings, I removed the comments, and added line numbers where it helps me explain specific lines of code. I encourage you to clone the code from GitHub and run the examples with me as you move through each unit in the course.

Synchronous programming style

Example 1 is a run-of-the-mill synchronous style program. It runs from top to bottom on the V8 thread, and just chews up some CPU (again, this is not technically blocking, but please bear with me).

Example 1. Normal synchronous programming style

'use strict'
console.log(Date.now().toString() + ': mainline: BEGIN');
const startTime = Date.now();
let endTime = startTime;
while (endTime < startTime + 20) {
    endTime = Date.now();
}
console.log(Date.now().toString() + ': mainline: END');

If you run example1.js (go ahead, try it!), its output looks like this:

$ node example1
1529596824055: mainline: BEGIN
1529596824077: mainline: END

After chewing up 20 seconds of CPU time (by constantly checking the system time), the loop terminates. Since there are no callbacks in the event loop, the program ends.

Asynchronous programming style

Example 2 is similar to the one above, but it uses asynchronous programming.

Example 2. Asynchronous programming style

'use strict'
console.log(Date.now().toString() + ': mainline: BEGIN');
setTimeout(() => {
    console.log(Date.now().toString() + ':event loop (callback): Asynchronous processing complete.');
}, 20);
console.log(Date.now().toString() + ':mainline: END');

If you run example2.js, its output looks like this:

$ node example2
1529597656500: mainline: BEGIN
1529597656502:mainline: END
1529597656525:event loop (callback): Asynchronous processing complete.

This output shows the tell-tale footprint of asynchronous code: Output is not in top-to-bottom order (as it appears in the source file, I mean). The program:

1. Outputs the BEGIN message.
2. Invokes setTimeout(), telling it to timeout in 20 milliseconds.
3. Outputs the END message.
4. After no less than 20 milliseconds, the event loop invokes the anonymous callback funciton provided to setTimeout() and it runs, outputting the Asynchronous processing complete message.

Conclusion to Act 1

So what’s the difference? If you look at the output from Example 1, you can see that the synchronous code ran in about 22 milliseconds, but the asynchronous code (Example 2) ran in about 25. Each message contains a timestamp in milliseconds.

Asynchronous is slower! Should you be worried? Not at all!

As you move through this unit, keep this in mind: the asynchronous programming style isn’t about pure speed; it’s about scalability (think coffee shop, not bank).

Node’s module system

Before we move on to our next comparison of the two programming models, we need to talk about Node’s module system. In previous units, I mentioned modules without really defining them, so let’s do that now.

Defining a Node module

In simple terms, a Node module is any JavaScript file that executes on the Node runtime. You saw two examples of this already: example1.js and example2.js.

There are two ways to make Node aware of a module:

1. Pass the name of that module to Node to execute the JavaScript code inside it:

   
    $ node example1
   

   Show more

   This is how you ran Examples 1 and 2.

2. Pull in JavaScript from some other module through the require() function.

    const fs = require('fs');
   

   Show more

   This method tells Node that you wish to use the fs module, through the require() function, which we’ll talk about shortly.

Why the Node module system exists

Modularization is a key concept in modern software development. It allows us to build more robust code and reuse code in multiple places, instead of having to write the same code again and again.

Node modularization gives us all the benefits listed above, plus it provides:

• Automatic encapsulation. By default, all code in a module is wrapped in a function wrapper so it’s hidden from other JavaScript code outside of the module.
• A way to expose a module’s interface. Functions, variables, and other constructs within a module must be explicitly exposed through module.exports (or its shortcut: exports) to JavaScript modules outside of the module.

Types of Node modules

There are different categories of Node modules, even though they all contain JavaScript code:

• Community contrib modules. Examples include:
• Custom modules such as those used in this unit:

We will look at each type of module above in detail as you move through the Learning Path.

How to use Node modules

To use a module, you need a reference to it, which you obtain through the require() function.

Consider this example from Unit 3:

var fs = require('fs');
var fileContents = fs.readFileSync('../data/50Words.txt', 'utf8');
var numberOfWords = fileContents.split(/[ ,.\n]+/).length;

To access the File System API, you get a reference to the fs module by calling require() on it. At that point, you can use its interface, such as calling readFileSync().

How to create a Node module

1. First, create a JavaScript file. We’ll call it foo.js:

   
    'use strict'
    function hello() {
        console.log('Hello from ' + __filename + '!');
    }
   

   Show more

2. Then, create a second JavaScript file, for example bar.js. To reference the foo module from the bar module use require():

   bar.js:

    'use strict'
    const foo = require('./foo');
    foo.hello();
   

   Show more

Go ahead and create these files and paste the JavaScript code above into the respective files, then run node bar (they are also in this Learning Path’s GitHub repo). You’ll see something like this:

$ node bar
/Users/sperry/home/development/projects/IBM-Code/Node.js/Course/Unit-4/bar.js:5
foo.hello();
    ^

TypeError: foo.hello is not a function
    at Object.<anonymous> (/Users/sperry/home/development/projects/IBM-Code/Node.js/Course/Unit-4/bar.js:5:5)
    at Module._compile (internal/modules/cjs/loader.js:702:30)
    at Object.Module._extensions..js (internal/modules/cjs/loader.js:713:10)
    at Module.load (internal/modules/cjs/loader.js:612:32)
    at tryModuleLoad (internal/modules/cjs/loader.js:551:12)
    at Function.Module._load (internal/modules/cjs/loader.js:543:3)
    at Function.Module.runMain (internal/modules/cjs/loader.js:744:10)
    at startup (internal/bootstrap/node.js:238:19)
    at bootstrapNodeJSCore (internal/bootstrap/node.js:572:3)

How do we fix this TypeError? By using module.exports and require('./foo').

Use module.exports

Remember when I said that, by default, all of the code in a module is hidden from the outside? You are seeing this in action: The foo hello() function cannot be seen by the bar code.

To expose the hello() function to the outside world, you must export it. Add this line to the bottom of foo.js:

modules.export.hello = hello;

Now run bar again:

$ node bar
Hello from /Users/sperry/home/development/projects/IBM-Code/Node.js/Course/Unit-4/foo.js!

Require the relative path of the referenced module

You may have noticed that when we reference a Node built-in module such as fs, we require() it like this:

const fs = require('fs');

But in the previous example you had to require() the foo module from bar like this:

bar.js:

.
.
const foo = require('./foo');

Why do we have to specify the relative path to the foo module?

require() has a very lengthy search algorithm it uses to resolve a module’s location when it needs to load that module. For custom modules, if you want to reference a module you’ve written (foo) from another module you’ve written (bar), the referencing modules must use the referenced module’s relative path as the argument to require().

One more thing: __filename

As I mentioned earlier, every Node module is wrapped in a function wrapper that looks like this:

(function(exports, require, module, __filename, __dirname) {
// Module code actually lives in here
});

foo.js, when modularized by Node, effectively looks like this:

(function(exports, require, module, __filename, __dirname) {
    // Module code actually lives in here
    'use strict'
    function hello() {
        console.log('Hello from ' + __filename + '!');
    }
    module.exports.hello = hello;
});

__filename, which is the fully qualified name of the module’s JavaScript source file, is passed to the function wrapper by Node, along with several other parameters:

• exports – short for module.exports
• require – our old friend that lets us include other modules
• module – reference to the current module
• __dirname – the full path to the directory of the module’s JavaScript source file

I recommend you check out the Modules API docs if you want to learn more about Node’s module system.

Modules used in this unit

Going forward, the examples I show use modules to encapsulate common code, in particular:

• File processing logic: all of the code that reads and processes files is located in the file-processor module.

• Message logging: all of the code that outputs messages to the console is located in the simple-logger module.

Before we dive into another head-to-head performance comparison of the programming models (Act 2), let’s look a little closer at these two modules, as they give you a pattern to follow when you want to write your own Node modules.

The file processing module: file-processor

The file-processor module contains most of the business logic for the examples in this tutorial. I named the functions in file-processor to match the naming style of the Node API: a function that behaves synchronously has the word Sync appended to the function name, an asynchronous function does not.

Listing 1 shows the function whose business logic is used to “process” a file synchronously. The function is called processFileSync():

Listing 1. The processFileSync() function of the process-file module, which behaves synchronously

01 function processFileSync(fileName) {
02    let startTime = process.hrtime();
03    logger.trace('processFileSync(): START', startTime);
04    let fileContents = fs.readFileSync(fileName, 'utf8');
05    let derivedKey = crypto.pbkdf2Sync(fileContents.toString(), SALT, NUMBER_OF_ITERATIONS, KEY_LENGTH, DIGEST);
06    let derivedKeyAsString = derivedKey.toString('hex');
07    logger.debug('processFileSync(): Computed hash: \'' + derivedKeyAsString + '\'', startTime);
08    logger.trace('processFileSync(): END', startTime);
09    return derivedKeyAsString;
10 };

Note: the constants SALT, NUMBER_OF_ITERATIONS, etc., are at the top of file-processor.js. Their values are not really relevant for these examples, but I wanted to point out where the source can be found in case you’re interested.

Like I said, functions in the Node API that are asynchronous have no name qualifier because asynchronous is Node’s default.

The asynchronous counterpart to processFileSync() (shown in Listing 1) is called processFile(). Listing 2 shows this:

Listing 2. The processFile() function, which behaves asynchronously

01 function processFile(fileName, resultsCallback) {
02    const startTime = process.hrtime();
03    logger.trace('fs.readFile(): START', startTime);
04    fs.readFile(fileName, 'utf8', function(err, fileContents) {
05        if (err) throw err;
06        crypto.pbkdf2(fileContents, SALT, NUMBER_OF_ITERATIONS, KEY_LENGTH, DIGEST, (err, derivedKey) => {
07            var derivedKeyAsString;
08            if (err) {
09                logger.error('Something went horribly wrong: ' + err.message);
10            } else {
11                derivedKeyAsString = derivedKey.toString('hex');
12                logger.debug('crypto.pbkdf2(): derivedKey: \'' + derivedKeyAsString + '\'', startTime);
13            }
14            resultsCallback(err, derivedKeyAsString);
15        });
16        logger.trace('fs.readFile(): END', startTime);
17    });
18 };

The message logging module – simple-logger

The simple-logger module contains all of the code that handles message logging for the examples in this unit. Messages are only logged to the console, though that detail is hidden behind the implementation, which is another reason to modularize your JavaScript code wherever possible.

The simple-logger consists of four internal components:

• Log Level, implemented by the Level object, which is associated with every message and allows any callers that are dependent on this module to throttle the message logging.
• The current Log Level, set to INFO by default, but can be changed by callers.
• The log() function, which is the internal implementation that selectively logs to the console.
• Helper functions, such as info(), which logs informational messages, debug() for more fine-grained debug messages, warn() for warnings, and so on.

To use simple-logger, modules call require(./simple-logger) to obtain a reference to the module. Optionally, call setLogLevel() (if the default of Level.INFO is not acceptable) to set the current log level. Finally, call various helper functions to perform the actual logging.

Listing 3 shows how the Log Levels are defined:

Listing 3. the various Levels supported by simple-logger

const Level = {
    TRACE : { priority : 0, outputString : 'TRACE' },
    DEBUG : { priority : 100, outputString : 'DEBUG' },
    INFO :  { priority : 200, outputString : 'INFO' },
    WARN :  { priority : 300, outputString : 'WARN' },
    ERROR :  { priority : 400, outputString : 'ERROR' },
    FATAL :  { priority : 500, outputString : 'FATAL' },
    OFF : { priority : 1000, outputString : 'OFF'}
};

Every message that is a candidate for logging has an associated Level. If a message’s Level.priority is at or above the current Log Level‘s priority it is logged. Otherwise, it is ignored.

Any module that wishes to require() the simple-logger can set the current Log Level through the setLogLevel() function, as Listing 4 shows:

Listing 4. The setLogLevel() function

.
.
// The current Log level
var logLevel = Level.INFO;
.
.
function setLogLevel(newLevel) {
    logLevel = newLevel;
}

The setLogLevel() function is used to set the current log threshold, which is stored in a module-scoped variable called logLevel.

Listing 5 shows the private log() function. It is not exported, so it is visible only within the simple-logger module:

Listing 5. The log() function

function log(messageLogLevel, message, startTime) {
    if (messageLogLevel.priority >= logLevel.priority) {
        let now = Date.now();
        let outputString = now.toString() + ':' + messageLogLevel.outputString;
        let computedMessage;
        if (startTime) {
            let stopTime = process.hrtime(startTime);
             computedMessage = outputString + ':' + message + ': (elapsed time: ' + `${1000 * (stopTime[0] + stopTime[1] / 1e9)}` + 'ms)';
        } else {
            computedMessage = outputString + ':' + message;
        }
        console.log(computedMessage);
    }
}

For each Level there is one helper function, each of which delegates to the log() method, passing its corresponding Level. Listing 6 shows the helper functions.

Listing 6. helper methods from simple-logger.js

function trace(message, startTime) {
    log(Level.TRACE, message, startTime);
}
function debug(message, startTime) {
    log(Level.DEBUG, message, startTime);
}
function info(message, startTime) {
    log(Level.INFO, message, startTime);
}
function warn(message, startTime) {
    log(Level.WARN, message, startTime);
}
function error(message, startTime) {
    log(Level.ERROR, message, startTime);
}
function fatal(message, startTime) {
    log(Level.FATAL, message, startTime);
}

That covers the custom modules you use in this unit (though, simple-logger will appear regularly throughout the Learning Path).

Now it’s time for another head-to-head comparison between synchronous and asynchronous coding styles, which I’ll call Act Two.

Synchronous vs asynchronous – Act 2

The examples we looked at earlier are too simple to be real-world examples. Real-world code uses modules and does interesting things like read files and encrypt things.

Synchronous

In Listing 1 we saw two synchronous Node API calls made by processFileSync() on lines 4 and 5:

01 function processFileSync(fileName) {
. . .
04    let fileContents = fs.readFileSync(fileName, 'utf8');
05    let derivedKey = crypto.pbkdf2Sync(fileContents.toString(), SALT, NUMBER_OF_ITERATIONS, KEY_LENGTH, DIGEST);
. . .
10 };

When the code on line 4 executes, V8 is blocked waiting for the I/O to finish before executing line 5.

Let’s run it now, using an example wrapper I’ve provided called example3.js.

You should see output like this:

$ node example3
1529618304278:INFO:mainLine(): Start processFile() calls... ***
1529618304280:DEBUG:mainline(): Processing file: ../data/1mWords.txt...
1529618304442:DEBUG:processFileSync(): Computed hash: '77da510b16c1503d47b6afadda86a039499547485ee4c10c5a3b3a3ce4f2c64e': (elapsed time: 161.794277ms)
1529618304442:DEBUG:mainline(): Derived key as string: '77da510b16c1503d47b6afadda86a039499547485ee4c10c5a3b3a3ce4f2c64e'
1529618304442:INFO:mainline(): End ***: (elapsed time: 164.579688ms)

Note: You might notice I’ve beefed up the logging output a bit, including computing an elapsed time so we can compare elapsed times between synchronous and asynchronous. That’s the simple-logger module at work.

Let’s compare the performance of example3 with its asynchronous counterpart.

Asynchronous

Listing 2 has several lines of code that illustrate the asynchronous coding style, which I show below:

01 function processFile(fileName, resultsCallback) {
. . .
04    fs.readFile(fileName, 'utf8', function(err, fileContents) {
05        if (err) throw err;
06        crypto.pbkdf2(fileContents, SALT, NUMBER_OF_ITERATIONS, KEY_LENGTH, DIGEST, (err, derivedKey) => {
07            var derivedKeyAsString;
. . .
14            resultsCallback(err, derivedKeyAsString);
15        });
16        logger.trace('fs.readFile(): END', startTime);
17    });
18 };

When V8 executes this function on the mainline of example4.js, Line 4 executes and passes an anonymous callback function (to be invoked when the I/O finishes), and then the method returns.

When the I/O is complete (at some later time), execution begins on line 5, and on line 6 another asynchronous Node API call is made to the crypto API (again, passing an anonymous callback function), which uses the file’s contents as the “password” to create a derived key. Then line 16 executes, and the function returns.

When the crypto function completes (at some still later time), execution begins on line 7, where eventually on line 14 the resultsCallback is invoked, passing the results (along with an err object) to the caller.

Whoa! So in actuality there is not one trip through the code in processFile() but three trips (executing different lines of code each trip through, of course)! Welcome to Node and asynchronous programming!

So, now let’s run it. I’ve provided another wrapper called example4.js that runs the processFile() function (see Listing 2).

You should see output like this:

$ node example4
1529618298372:INFO:mainline(): Start... ***: (elapsed time: 0.146585ms)
1529618298374:DEBUG:mainline(): Processing file: ../data/1mWords.txt...
1529618298375:INFO:mainline(): End. ***: (elapsed time: 2.887165ms)
1529618298551:DEBUG:crypto.pbkdf2(): Derived key: '77da510b16c1503d47b6afadda86a039499547485ee4c10c5a3b3a3ce4f2c64e': (elapsed time: 176.644805ms)
1529618298552:INFO:(callback)(): Derived key as string: '77da510b16c1503d47b6afadda86a039499547485ee4c10c5a3b3a3ce4f2c64e': (elapsed time: 179.45526ms)

Conclusion – Act 2

On my Macbook Pro, example3.js (synchronous) ran in about 165ms, compared to example4.js (asynchronous), which ran in about 180ms. Seems like the synchronous code is faster again.

If you’re getting worried that asynchronous code just doesn’t perform, I totally get it. But I encourage you to reserve judgment until Act Three.

Using the built-in V8 profiler

Before we go further, we need to talk about performance profiling.

As a professional Node developer, you should know how to run a performance analysis (called a profile) on your code. This profile tells you where in the code V8 is spending the most time executing. These locations are sometimes called “hot spots”.

An entire tutorial series could be dedicated to V8 profiling, so I’m only going to cover the basics here:

• How to run the profiler
• How to read profiler output

The V8 Engine has a built-in profiler that Node.js hooks into. To run the profiler, pass the --prof argument to the node program when you run it. The profiler also takes several other arguments, which I suggest you use to tailor the output:

• --no-logfile-per-isolate – Each time you run node, the instance of V8, called an isolate because the state of each V8 instance is isolated from all others, is assigned an ID. By default, this ID is part of the log file name. This argument tells the profiler to produce a single log file (called v8.log) each time it runs, overwriting the previous log file.
• --log – creates minimal logging (for example, no garbage collection samples)
• --logfile=exampleX.log – creates a log file called exampleX.log in the current directory. Combined with the --no-logfile-per-isolate flag, it overrides the default filename (that is, v8.log) and uses the value of the --logfile argument.

Now, run the profiler for example3.js by executing this command:

node --prof --no-logfile-per-isolate --log --logfile=example3.log example3

This produces a file called example3.log in the current directory. Take a look at it just for fun. It contains lines like this:

v8-version,6,7,288,45,-node.7,0
shared-library,/Users/sperry/.nvm/versions/node/v10.4.1/bin/node,0x100001000,0x100c59dba,0
shared-library,/System/Library/Frameworks/CoreFoundation.framework/Versions/A/CoreFoundation,0x7fff54ef8860,0x7fff550eb9ac,759017472
shared-library,/usr/lib/libSystem.B.dylib,0x7fff7aaa194a,0x7fff7aaa1b2e,759017472
shared-library,/usr/lib/libc++.1.dylib,0x7fff7acd5f40,0x7fff7ad1d2b0,759017472
shared-library,/usr/lib/libDiagnosticMessagesClient.dylib,0x7fff7a72af08,0x7fff7a72b90c,759017472
shared-library,/usr/lib/libicucore.A.dylib,0x7fff7b800fd4,0x7fff7b9b82e6,759017472
shared-library,/usr/lib/libobjc.A.dylib,0x7fff7c159000,0x7fff7c17a65a,759017472
.
.
code-creation,Builtin,3,6831,0xfc7d5d21840,2456,HasProperty
code-creation,Builtin,3,6842,0xfc7d5d22220,1036,DeleteProperty
code-creation,Builtin,3,6852,0xfc7d5d22680,25,Abort
code-creation,Builtin,3,6862,0xfc7d5d226e0,40,AbortJS
code-creation,Builtin,3,6872,0xfc7d5d22760,15,EmptyFunction
code-creation,Builtin,3,6882,0xfc7d5d227c0,15,Illegal
code-creation,Builtin,3,6896,0xfc7d5d22820,15,StrictPoisonPillThrower
code-creation,Builtin,3,6907,0xfc7d5d22880,15,UnsupportedThrower
code-creation,Builtin,3,6918,0xfc7d5d228e0,21,ArrayConstructor
code-creation,Builtin,3,6928,0xfc7d5d22940,9,InternalArrayConstructor
code-creation,Builtin,3,6939,0xfc7d5d229a0,15,ArrayConcat
.
.
code-creation,LazyCompile,10,272952,0x1cdb2ff4e60a,57,finishMaybe _stream_writable.js:635:21,0x1cdb269306c0,~
code-creation,LazyCompile,10,272998,0x1cdb2ff4e82a,55,emitAfterScript internal/async_hooks.js:354:25,0x1cdb00e391c8,~
code-creation,LazyCompile,10,273064,0x1cdb2ff4eaa2,198,popAsyncIds internal/async_hooks.js:402:21,0x1cdb00e393d0,~
code-creation,LazyCompile,10,273210,0x1cdb2ff4efaa,287,emitPromiseRejectionWarnings internal/process/promises.js:88:38,0x1cdb2694aec8,~
tick,0x7fff7ced6a1e,273422,0,0x0,6
delete,MemoryChunk,0x1cdb6be80000
delete,MemoryChunk,0x1cdbc2a00000
delete,MemoryChunk,0x1cdb2b600000
delete,MemoryChunk,0x1cdb0a780000
delete,MemoryChunk,0x1cdba3200000
delete,MemoryChunk,0x1cdb51c00000
delete,MemoryChunk,0x1cdb40f00000
delete,MemoryChunk,0x1cdbfff80000
delete,MemoryChunk,0x1cdbb7880000
delete,MemoryChunk,0x1cdb00e00000
delete,MemoryChunk,0x1cdb9dc00000
delete,MemoryChunk,0x1cdb32b00000
delete,MemoryChunk,0x1cdb26900000
delete,MemoryChunk,0x1cdb86b00000
delete,MemoryChunk,0x1cdb2ff00000
delete,MemoryChunk,0xfc7d5d00000
delete,MemoryChunk,0xfc7d5d80000
delete,MemoryChunk,0x1cdb9fe00000
delete,MemoryChunk,0x1cdbc8300000
delete,LargeObjectChunk,0x1cdb16400000
delete,MemoryChunk,0x1cdb16400000
profiler,end

Yikes! That’s not very helpful. Fortunately, passing the --prof-process argument to Node creates analyzed output:

node --prof-process example3.log > example3.log.txt

The above command invokes the profile analyzer, passes the example3.log profiler info, and then formats it for us. The output looks like this:

Statistical profiling result from v8.log, (215 ticks, 1 unaccounted, 0 excluded).

 [Shared libraries]:
   ticks  total  nonlib   name
      4    1.9%          /usr/lib/system/libsystem_pthread.dylib
      2    0.9%          /usr/lib/system/libsystem_malloc.dylib

 [JavaScript]:
   ticks  total  nonlib   name
      1    0.5%    0.5%  Script: ~<anonymous> console.js:1:11

 [C++]:
   ticks  total  nonlib   name
    118   54.9%   56.5%  T node::crypto::PBKDF2(v8::FunctionCallbackInfo<v8::Value> const&)
     24   11.2%   11.5%  T node::contextify::ContextifyScript::New(v8::FunctionCallbackInfo<v8::Value> const&)
     16    7.4%    7.7%  T ___guarded_open_dprotected_np
      5    2.3%    2.4%  t node::Buffer::(anonymous namespace)::CreateFromString(v8::FunctionCallbackInfo<v8::Value> const&)
.
.

A tick is a single sampling interval, which by default is 1000 microseconds (1 millisecond). Notice that V8 took 215 samples, which would indicate that V8 ran JavaScript code for at least 215ticks (ms).

There are sections showing us the amount of time (expressed in ticks) spent in Shared Libraries, JavaScript code, and C++ code. The number of ticks in each table tells us how many sampling intervals were spent in the code listed under name. The results are sorted in order of where the profile spent the most time to where they spent the least amount of time.

Right away, you can see that 118 ticks (or 54.9% of total) were spent in a Node core library called crypto::PBKDF2, which is the library that handles password-based key derivation (remember that from Listing 1, line 5?).

Next, just over 1/10th of the total time was spent turning our JavaScript into runnable code (called “contexifying” in V8 terms).

If you scroll down in the v8.log.txt file, you see another section with a summary, followed by a “Bottom-up” profile:

 [Summary]:
   ticks  total  nonlib   name
      1    0.5%    0.5%  JavaScript
    207   96.3%   99.0%  C++
      3    1.4%    1.4%  GC
      6    2.8%          Shared libraries
      1    0.5%          Unaccounted

 [C++ entry points]:
   ticks    cpp   total   name
    164   86.8%   76.3%  T v8::internal::Builtin_HandleApiCall(int, v8::internal::Object**, v8::internal::Isolate*)
     13    6.9%    6.0%  T v8::internal::Runtime_CompileLazy(int, v8::internal::Object**, v8::internal::Isolate*)
.
.
      1    0.5%    0.5%  T v8::internal::Runtime_KeyedLoadIC_Miss(int, v8::internal::Object**, v8::internal::Isolate*)

 [Bottom up (heavy) profile]:
  Note: percentage shows a share of a particular caller in the total
  amount of its parent calls.
  Callers occupying less than 1.0% are not shown.

   ticks parent  name
    118   54.9%  T node::crypto::PBKDF2(v8::FunctionCallbackInfo<v8::Value> const&)
    118  100.0%    T v8::internal::Builtin_HandleApiCall(int, v8::internal::Object**, v8::internal::Isolate*)
    118  100.0%      LazyCompile: ~_pbkdf2 internal/crypto/pbkdf2.js:37:17
    118  100.0%        LazyCompile: ~pbkdf2Sync internal/crypto/pbkdf2.js:33:20
    118  100.0%          LazyCompile: ~processFileSync /Users/sperry/home/development/projects/IBM-Code/Node.js/Course/Unit-4/file-processor.js:89:25
    118  100.0%            Script: ~mainline /Users/sperry/home/development/projects/IBM-Code/Node.js/Course/Unit-4/example3.js:31:19

     24   11.2%  T node::contextify::ContextifyScript::New(v8::FunctionCallbackInfo<v8::Value> const&)
     24  100.0%    T v8::internal::Builtin_HandleApiCall(int, v8::internal::Object**, v8::internal::Isolate*)
     22   91.7%      LazyCompile: ~NativeModule.compile internal/bootstrap/loaders.js:220:44
.
.

The information is pretty intuitive, though you may have to stare at it for a while before it makes sense. One thing I want to mention, the Bottom-up profile is formatted to be indented like a call stack, so you can see the order the functions were called (each nested call results in further indention under the name column).

Put it into practice

Exercise: Run the profiler on the example4.js code. Hint: make sure to redirect the output of node --prof-process to a different logfile than you did for example3. I suggest example4.log.txt.

Once you’ve completed the exercise, let’s compare the results of exercise3 and exercise4 and see if anything jumps out at us to explain why synchronous is still faster than asynchronous.