A summary diagnostic report for Node.js was introduced in NodeReport – first failure data capture for Node.js. The report can be triggered on unhandled exceptions, fatal errors, signals and by calling JavaScript APIs. It contains key information about the JavaScript application and the Node.js run-time, including JavaScript and C++ stacks, V8 heap statistics, per-process and per-thread CPU usage, environment variables and resource limits.

The project has been moved under the Node Foundation and renamed from nodereport to node-report for consistency with other project names. Version 2.1.0 is now available as an npm module here: https://www.npmjs.com/package/node-report. This article describes the enhancements in version 2.1.0, and provides an example of how the node-report module can be triggered by an external signal to obtain a diagnostic report from a running Node.js application.

Enhancements in node-report version 2.1.0

1. The hooks to produce a report on fatal error, uncaught exceptions or signal are now enabled by default. This means that reports can be enabled without any code changes, simply using the -r node-report command-line option when starting your Node.js application.

node -r node-report application.js

If required, the node-report API can be enabled without adding the automatic exception and fatal error hooks and the signal handler, as follows:

var nodereport = require('node-report/api');
nodereport.triggerReport();

2. The report now includes a list of native libraries loaded by the process. This can be very useful when tracking down problems related to system library levels or native npm modules. The list is provided at the end of the System Information section in the report, for example:

==== System Information ====================================================
....
Loaded libraries
  /lib/x86_64-linux-gnu/librt.so.1
  /usr/lib/x86_64-linux-gnu/libstdc++.so.6
  /lib/x86_64-linux-gnu/libgcc_s.so.1
  /lib/x86_64-linux-gnu/libpthread.so.0
  /lib/x86_64-linux-gnu/libc.so.6
  /lib64/ld-linux-x86-64.so.2
  /home/rchamberlain/test/node_modules/node-report/api.node

3. The hook used to generate a report on uncaught exceptions has been modified to match default Node.js behavior. This means that Node.js will exit as normal when node-report is used to produce a report on an uncaught exception. If node-report is enabled and you specify the –abort-on-uncaught-exception option, a report will be produced then Node.js will terminate with an abort condition so that the operating system produces a core dump.

4. The command line used to start the node process is now shown in the header section of the report:

==== Node Report ===============================================================

Event: SIGUSR2, location: "SignalDumpAsyncCallback"
Filename: node-report.20170213.115012.3362.001.txt
Dump event time:  2017/02/13 11:50:12
Module load time: 2017/02/13 11:45:32
Process ID: 3362
Command line: node -r node-report example.js

5. The content of a report can also be returned as a JavaScript string via an API call from a JavaScript application.

var nodereport = require('node-report');
var report_str = nodereport.getReport();
console.log(report_str);

Example – what is my Node.js app doing? Sending a signal to a Node.js application to obtain a diagnostic report

This example shows how to use the node-report module to investigate a running Node.js application. By sending a signal to the application, a report is generated showing exactly what is happening in the application. In the first case, the application is idle, with no request processing taking place at the time the signal was received. In the second case, a request is being processed and the report shows that the application is under a heavy load.

The first step is to install the node-report module and enable it in your application using the -r node-report option or a require(‘node-report’) statement in your code:

npm install node-report

then

node -r node-report application.js

or

var nodereport = require('node-report');

Then when the application is running, use the ps command to find its process ID, and send a USR2 signal to it. Note that the operating system ‘kill’ command sends the signal to trigger a report. The application will continue running after the report is produced.

$ ps -ef | grep node
user1  3509  3074  2 14:44 pts/8    00:00:00 node -r node-report example.js
$ kill -USR2 3509

Messages will be written to the Node.js application stdout stream indicating that a report has been produced:

Writing Node.js report to file: node-report.20170213.115012.3362.001.txt
Node.js report completed

In the first example report below, the Node.js application is idle, waiting for work, when the signal was received. From the difference between the current time and the module load time in the report header section, you can see that the application has been running for approximately 5 minutes. The JavaScript stack trace is empty, and the resource usage section shows that the application has used just 0.08 seconds of CPU time.

================================================================================
==== Node Report ===============================================================

Event: SIGUSR2, location: "SignalDumpAsyncCallback"
Filename: node-report.20170213.115012.3362.001.txt
Dump event time:  2017/02/13 11:50:12
Module load time: 2017/02/13 11:45:32
Process ID: 3362
Command line: node -r node-report example.js 

....
================================================================================
==== JavaScript Stack Trace ====================================================

Signal received when event loop idle, no stack trace available

================================================================================
==== Native Stack Trace ========================================================

 0: [pc=0x131474b]  [node]
 1: [pc=0x1314823]  [node]
 2: [pc=0x1324df0]  [node]
 3: [pc=0x1315306] uv_run [node]
 4: [pc=0x10a09e0] node::Start(int, char**) [node]
 5: [pc=0x7fe959bddf45] __libc_start_main [/lib/x86_64-linux-gnu/libc.so.6]
 6: [pc=0x7b517d]  [node]

....
================================================================================
==== Resource Usage ============================================================

Process total resource usage:
  User mode CPU: 0.080000 secs
  Kernel mode CPU: 0.008000 secs
  Maximum resident set size: 26,746,880 bytes
  Page faults: 0 (I/O required) 2567 (no I/O required)
  Filesystem activity: 0 reads 8 writes

Event loop thread resource usage:
  User mode CPU: 0.080000 secs
  Kernel mode CPU: 0.008000 secs
  Filesystem activity: 0 reads 8 writes

....

In the second example report, the Node.js application is busy processing a request in JavaScript code when the signal was received. From the difference between the current time and the module load time in the report header section, you can see that the application has been running for approximately 5 minutes (i.e. 300 seconds) as in the first case. However, in this case there is a JavaScript stack trace that shows the currently running code. The resource usage section shows that the application has used 280 seconds of CPU time, so it is using approximately 90% of the CPU. Further examination of the code shown in the stack trace is recommended in this case, along with investigation of the request load on the application.

================================================================================
==== Node Report ===============================================================

Event: SIGUSR2, location: "SignalDumpInterruptCallback"
Filename: node-report.20170213.114413.3334.002.txt
Dump event time:  2017/02/13 11:44:13
Module load time: 2017/02/13 11:39:20
Process ID: 3334
Command line: node -r node-report loop.js 

....
================================================================================
==== JavaScript Stack Trace ====================================================

 0: [pc=0x38db5bfb3b5a] my_listener (/home/rchamberlain/test/loop.js:18:16)
 1: [pc=0x38db5bf22db3] emitTwo (events.js:106:13)
 2: [pc=0x38db5bf228db] emit (events.js:191:7)
 3: [pc=0x38db5bf96cbf] parserOnIncoming (_http_server.js:546:12)
 4: [pc=0x38db5bf947bf] parserOnHeadersComplete (_http_common.js:99:23)

================================================================================
==== Native Stack Trace ========================================================

 0: [pc=0xd4ad51] v8::internal::Isolate::InvokeApiInterruptCallbacks() [node]
 1: [pc=0xc51908] v8::internal::StackGuard::HandleInterrupts() [node]
 2: [pc=0xeb1aec] v8::internal::Runtime_StackGuard(int, v8::internal::Object**, v8::internal::Isolate*) [node]
 3: [pc=0x38db5be079a7] 

....
================================================================================
==== Resource Usage ============================================================

Process total resource usage:
  User mode CPU: 281.972000 secs
  Kernel mode CPU: 0.024000 secs
  Maximum resident set size: 28,938,240 bytes
  Page faults: 5 (I/O required) 2838 (no I/O required)
  Filesystem activity: 864 reads 32 writes

Event loop thread resource usage:
  User mode CPU: 281.972000 secs
  Kernel mode CPU: 0.024000 secs
  Filesystem activity: 864 reads 32 writes

....

1 comment on"Announcing node-report version 2.1.0 – the essential diagnostic for Node.js applications"

Join The Discussion

Your email address will not be published. Required fields are marked *