From 9ca94526c02e1ed0960a517d60062f86f943accb Mon Sep 17 00:00:00 2001 From: James M Snell Date: Wed, 1 Aug 2018 19:01:14 -0700 Subject: [PATCH 1/4] trace_events: add node.promises category, rejection counter 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). --- doc/api/tracing.md | 4 +- src/bootstrapper.cc | 13 ++++++ test/parallel/test-trace-event-promises.js | 48 ++++++++++++++++++++++ 3 files changed, 64 insertions(+), 1 deletion(-) create mode 100644 test/parallel/test-trace-event-promises.js diff --git a/doc/api/tracing.md b/doc/api/tracing.md index ca91b8aac78cc3..e067760643a1ea 100644 --- 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 index 5f40d62a82fdef..feafa284a5074f 100644 --- a/src/bootstrapper.cc +++ b/src/bootstrapper.cc @@ -51,6 +51,9 @@ void SetupNextTick(const FunctionCallbackInfo& args) { } void PromiseRejectCallback(PromiseRejectMessage message) { + static uint64_t unhandledRejections = 0; + static uint64_t rejectionsHandledAfter = 0; + Local promise = message.GetPromise(); Isolate* isolate = promise->GetIsolate(); PromiseRejectEvent event = message.GetEvent(); @@ -65,13 +68,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 args[] = { promise, value }; MaybeLocal 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 new file mode 100644 index 00000000000000..9c0608b1d0de5d --- /dev/null +++ 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(trace.name === 'rejections'); + assert(trace.args.unhandled <= 2); + assert(trace.args.handledAfter <= 1); + }); + })); + })); +} From 825e0d2c65ebff782bd130f8a5007185c957bbfb Mon Sep 17 00:00:00 2001 From: James M Snell Date: Sat, 4 Aug 2018 10:18:47 -0700 Subject: [PATCH 2/4] [Squash] use atomic_uint64_t --- src/bootstrapper.cc | 6 ++++-- 1 file changed, 4 insertions(+), 2 deletions(-) diff --git a/src/bootstrapper.cc b/src/bootstrapper.cc index feafa284a5074f..521e17e2178a28 100644 --- a/src/bootstrapper.cc +++ b/src/bootstrapper.cc @@ -3,6 +3,8 @@ #include "node_internals.h" #include "v8.h" +#include + namespace node { using v8::Array; @@ -51,8 +53,8 @@ void SetupNextTick(const FunctionCallbackInfo& args) { } void PromiseRejectCallback(PromiseRejectMessage message) { - static uint64_t unhandledRejections = 0; - static uint64_t rejectionsHandledAfter = 0; + static std::atomic_uint64_t unhandledRejections{0}; + static std::atomic_uint64_t rejectionsHandledAfter{0}; Local promise = message.GetPromise(); Isolate* isolate = promise->GetIsolate(); From 1684f431a917cd2e3638a610ff506fc730a86613 Mon Sep 17 00:00:00 2001 From: James M Snell Date: Mon, 6 Aug 2018 16:28:13 -0700 Subject: [PATCH 3/4] [Squash] fixup --- src/bootstrapper.cc | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/src/bootstrapper.cc b/src/bootstrapper.cc index 521e17e2178a28..94bb9413772dd0 100644 --- a/src/bootstrapper.cc +++ b/src/bootstrapper.cc @@ -53,8 +53,8 @@ void SetupNextTick(const FunctionCallbackInfo& args) { } void PromiseRejectCallback(PromiseRejectMessage message) { - static std::atomic_uint64_t unhandledRejections{0}; - static std::atomic_uint64_t rejectionsHandledAfter{0}; + static std::atomic unhandledRejections{0}; + static std::atomic rejectionsHandledAfter{0}; Local promise = message.GetPromise(); Isolate* isolate = promise->GetIsolate(); From e4e5fdd79f5e893e1a162cac96d2c5b1428a712c Mon Sep 17 00:00:00 2001 From: James M Snell Date: Mon, 6 Aug 2018 16:40:32 -0700 Subject: [PATCH 4/4] [Squash] fixup --- test/parallel/test-trace-event-promises.js | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/test/parallel/test-trace-event-promises.js b/test/parallel/test-trace-event-promises.js index 9c0608b1d0de5d..69d35f25ecb3bb 100644 --- a/test/parallel/test-trace-event-promises.js +++ b/test/parallel/test-trace-event-promises.js @@ -39,7 +39,7 @@ if (process.argv[2] === 'child') { .filter((trace) => trace.cat !== '__metadata'); traces.forEach((trace) => { assert.strictEqual(trace.pid, proc.pid); - assert(trace.name === 'rejections'); + assert.strictEqual(trace.name, 'rejections'); assert(trace.args.unhandled <= 2); assert(trace.args.handledAfter <= 1); });