trace_events: add node.promises category, rejection counter

jasnell · targos · commit fd318e70b550 · 2018-08-11T17:33:53.000+02:00
Allow the trace event log to include a count of unhandled rejections and handled after rejections. This is useful primarily as a quick check to see if rejections may be going unhandled (and unnoticed in a process). PR-URL: #22124 Reviewed-By: Benjamin Gruenbaum <benjamingr@gmail.com> Reviewed-By: Colin Ihrig <cjihrig@gmail.com> Reviewed-By: Matteo Collina <matteo.collina@gmail.com>
diff --git a/doc/api/tracing.md b/doc/api/tracing.md
@@ -18,12 +18,14 @@ The available categories are:
   The [`async_hooks`] events have a unique `asyncId` and a special `triggerId`
   `triggerAsyncId` property.
 * `node.bootstrap` - Enables capture of Node.js bootstrap milestones.
+* `node.fs.sync` - Enables capture of trace data for file system sync methods.
 * `node.perf` - Enables capture of [Performance API] measurements.
   * `node.perf.usertiming` - Enables capture of only Performance API User Timing
     measures and marks.
   * `node.perf.timerify` - Enables capture of only Performance API timerify
     measurements.
-* `node.fs.sync` - Enables capture of trace data for file system sync methods.
+* `node.promises.rejections` - Enables capture of trace data tracking the number
+  of unhandled Promise rejections and handled-after-rejections.
 * `node.vm.script` - Enables capture of trace data for the `vm` module's
   `runInNewContext()`, `runInContext()`, and `runInThisContext()` methods.
 * `v8` - The [V8] events are GC, compiling, and execution related.
diff --git a/src/bootstrapper.cc b/src/bootstrapper.cc
@@ -3,6 +3,8 @@
 #include "node_internals.h"
 #include "v8.h"
 
+#include <atomic>
+
 namespace node {
 
 using v8::Array;
@@ -51,6 +53,9 @@ void SetupNextTick(const FunctionCallbackInfo<Value>& args) {
 }
 
 void PromiseRejectCallback(PromiseRejectMessage message) {
+  static std::atomic<uint64_t> unhandledRejections{0};
+  static std::atomic<uint64_t> rejectionsHandledAfter{0};
+
   Local<Promise> promise = message.GetPromise();
   Isolate* isolate = promise->GetIsolate();
   PromiseRejectEvent event = message.GetEvent();
@@ -65,13 +70,23 @@ void PromiseRejectCallback(PromiseRejectMessage message) {
 
     if (value.IsEmpty())
       value = Undefined(isolate);
+
+    unhandledRejections++;
   } else if (event == v8::kPromiseHandlerAddedAfterReject) {
     callback = env->promise_reject_handled_function();
     value = Undefined(isolate);
+
+    rejectionsHandledAfter++;
   } else {
     return;
   }
 
+  TRACE_COUNTER2(TRACING_CATEGORY_NODE2(promises, rejections),
+                 "rejections",
+                 "unhandled", unhandledRejections,
+                 "handledAfter", rejectionsHandledAfter);
+
+
   Local<Value> args[] = { promise, value };
   MaybeLocal<Value> ret = callback->Call(env->context(),
                                          Undefined(isolate),
diff --git a/test/parallel/test-trace-event-promises.js b/test/parallel/test-trace-event-promises.js
@@ -0,0 +1,48 @@
+'use strict';
+const common = require('../common');
+const assert = require('assert');
+const cp = require('child_process');
+const path = require('path');
+const fs = require('fs');
+const tmpdir = require('../common/tmpdir');
+
+common.disableCrashOnUnhandledRejection();
+
+if (!common.isMainThread)
+  common.skip('process.chdir is not available in Workers');
+
+if (process.argv[2] === 'child') {
+  const p = Promise.reject(1);  // Handled later
+  Promise.reject(2);  // Unhandled
+  setImmediate(() => {
+    p.catch(() => { /* intentional noop */ });
+  });
+} else {
+  tmpdir.refresh();
+  process.chdir(tmpdir.path);
+
+  const proc = cp.fork(__filename,
+                       [ 'child' ], {
+                         execArgv: [
+                           '--no-warnings',
+                           '--trace-event-categories',
+                           'node.promises.rejections'
+                         ]
+                       });
+
+  proc.once('exit', common.mustCall(() => {
+    const file = path.join(tmpdir.path, 'node_trace.1.log');
+
+    assert(common.fileExists(file));
+    fs.readFile(file, common.mustCall((err, data) => {
+      const traces = JSON.parse(data.toString()).traceEvents
+        .filter((trace) => trace.cat !== '__metadata');
+      traces.forEach((trace) => {
+        assert.strictEqual(trace.pid, proc.pid);
+        assert.strictEqual(trace.name, 'rejections');
+        assert(trace.args.unhandled <= 2);
+        assert(trace.args.handledAfter <= 1);
+      });
+    }));
+  }));
+}
