From c705b73a740ec7eb75469a2011aa7e41e006f362 Mon Sep 17 00:00:00 2001 From: Joyee Cheung Date: Tue, 5 Dec 2023 12:26:44 +0100 Subject: [PATCH] src: implement --trace-promises MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit This patch implements a debugging flag that dumps the current stack trace when a promise is created or resolved. To reduce noise we ignore before and after events (as the execution is less interesting) and use the per-isolate hook to avoid extra JS frames. This flag can assist work in reducing unnecessary promise overhead. PR-URL: https://github.com/nodejs/node/pull/50899 Reviewed-By: Yagiz Nizipli Reviewed-By: Geoffrey Booth Reviewed-By: Vinícius Lourenço Claro Cardoso Reviewed-By: Chengzhong Wu Reviewed-By: Benjamin Gruenbaum --- src/env.cc | 58 +++++++++++++++++++ src/env.h | 4 ++ src/env_properties.h | 1 + src/node.cc | 3 + src/node_errors.cc | 7 +++ src/node_internals.h | 2 + src/node_options.cc | 4 ++ src/node_options.h | 1 + ...rocess-env-allowed-flags-are-documented.js | 2 + 9 files changed, 82 insertions(+) diff --git a/src/env.cc b/src/env.cc index a429d5526d0af6..f921a545f1be3e 100644 --- a/src/env.cc +++ b/src/env.cc @@ -30,6 +30,7 @@ #include #include #include +#include #include namespace node { @@ -55,6 +56,8 @@ using v8::Number; using v8::Object; using v8::ObjectTemplate; using v8::Private; +using v8::Promise; +using v8::PromiseHookType; using v8::Script; using v8::SnapshotCreator; using v8::StackTrace; @@ -62,6 +65,7 @@ using v8::String; using v8::Symbol; using v8::TracingController; using v8::TryCatch; +using v8::Uint32; using v8::Undefined; using v8::Value; using v8::WrapperDescriptor; @@ -1839,6 +1843,60 @@ void Environment::BuildEmbedderGraph(Isolate* isolate, tracker.Track(env); } +std::optional GetPromiseId(Environment* env, Local promise) { + Local id_val; + if (!promise->GetPrivate(env->context(), env->promise_trace_id()) + .ToLocal(&id_val) || + !id_val->IsUint32()) { + return std::nullopt; + } + return id_val.As()->Value(); +} + +void Environment::TracePromises(PromiseHookType type, + Local promise, + Local parent) { + // We don't care about the execution of promises, just the + // creation/resolution. + if (type == PromiseHookType::kBefore || type == PromiseHookType::kAfter) { + return; + } + Isolate* isolate = Isolate::GetCurrent(); + Local context = isolate->GetCurrentContext(); + Environment* env = Environment::GetCurrent(context); + if (env == nullptr) return; + + std::optional parent_id; + if (!parent.IsEmpty() && parent->IsPromise()) { + parent_id = GetPromiseId(env, parent.As()); + } + + uint32_t id = 0; + std::string action; + if (type == PromiseHookType::kInit) { + id = env->trace_promise_id_counter_++; + promise->SetPrivate( + context, env->promise_trace_id(), Uint32::New(isolate, id)); + action = "created"; + } else if (type == PromiseHookType::kResolve) { + auto opt = GetPromiseId(env, promise); + if (!opt.has_value()) return; + id = opt.value(); + action = "resolved"; + } else { + UNREACHABLE(); + } + + FPrintF(stderr, "[--trace-promises] "); + if (parent_id.has_value()) { + FPrintF(stderr, "promise #%d ", parent_id.value()); + } + FPrintF(stderr, "%s promise #%d\n", action, id); + // TODO(joyeecheung): we can dump the native stack trace too if the + // JS stack trace is empty i.e. it may be resolved on the native side. + PrintCurrentStackTrace(isolate); +} + size_t Environment::NearHeapLimitCallback(void* data, size_t current_heap_limit, size_t initial_heap_limit) { diff --git a/src/env.h b/src/env.h index 1047f1d794da2a..244b8828c73a18 100644 --- a/src/env.h +++ b/src/env.h @@ -934,6 +934,9 @@ class Environment : public MemoryRetainer { inline void RemoveCleanupHook(CleanupQueue::Callback cb, void* arg); void RunCleanup(); + static void TracePromises(v8::PromiseHookType type, + v8::Local promise, + v8::Local parent); static size_t NearHeapLimitCallback(void* data, size_t current_heap_limit, size_t initial_heap_limit); @@ -1094,6 +1097,7 @@ class Environment : public MemoryRetainer { uint32_t module_id_counter_ = 0; uint32_t script_id_counter_ = 0; uint32_t function_id_counter_ = 0; + uint32_t trace_promise_id_counter_ = 0; AliasedInt32Array exit_info_; diff --git a/src/env_properties.h b/src/env_properties.h index 8c5b80fe5635ec..9e769efc8636e3 100644 --- a/src/env_properties.h +++ b/src/env_properties.h @@ -26,6 +26,7 @@ V(napi_wrapper, "node:napi:wrapper") \ V(untransferable_object_private_symbol, "node:untransferableObject") \ V(exit_info_private_symbol, "node:exit_info_private_symbol") \ + V(promise_trace_id, "node:promise_trace_id") \ V(require_private_symbol, "node:require_private_symbol") // Symbols are per-isolate primitives but Environment proxies them diff --git a/src/node.cc b/src/node.cc index 524f80ee69ee52..0d601ae21b8314 100644 --- a/src/node.cc +++ b/src/node.cc @@ -264,6 +264,9 @@ void Environment::InitializeDiagnostics() { env->isolate()->SetAtomicsWaitCallback(nullptr, nullptr); }, this); } + if (options_->trace_promises) { + isolate_->SetPromiseHook(TracePromises); + } } static diff --git a/src/node_errors.cc b/src/node_errors.cc index 50618e6c716f0b..7ef6ea7f07998f 100644 --- a/src/node_errors.cc +++ b/src/node_errors.cc @@ -291,6 +291,13 @@ void PrintStackTrace(Isolate* isolate, PrintToStderrAndFlush(FormatStackTrace(isolate, stack, prefix)); } +void PrintCurrentStackTrace(Isolate* isolate, StackTracePrefix prefix) { + Local stack; + if (GetCurrentStackTrace(isolate).ToLocal(&stack)) { + PrintStackTrace(isolate, stack, prefix); + } +} + std::string FormatCaughtException(Isolate* isolate, Local context, Local err, diff --git a/src/node_internals.h b/src/node_internals.h index 9a96e042fc5cda..5604f35aeff6b4 100644 --- a/src/node_internals.h +++ b/src/node_internals.h @@ -87,6 +87,8 @@ enum class StackTracePrefix { kAt, // " at " kNumber }; +void PrintCurrentStackTrace(v8::Isolate* isolate, + StackTracePrefix prefix = StackTracePrefix::kAt); void PrintStackTrace(v8::Isolate* isolate, v8::Local stack, StackTracePrefix prefix = StackTracePrefix::kAt); diff --git a/src/node_options.cc b/src/node_options.cc index 5da6918af8c125..43422b536ba285 100644 --- a/src/node_options.cc +++ b/src/node_options.cc @@ -667,6 +667,10 @@ EnvironmentOptionsParser::EnvironmentOptionsParser() { "show stack traces on process warnings", &EnvironmentOptions::trace_warnings, kAllowedInEnvvar); + AddOption("--trace-promises", + "show stack traces on promise initialization and resolution", + &EnvironmentOptions::trace_promises, + kAllowedInEnvvar); AddOption("--experimental-default-type", "set module system to use by default", &EnvironmentOptions::type, diff --git a/src/node_options.h b/src/node_options.h index 312fae8f759c58..1cba9350980fac 100644 --- a/src/node_options.h +++ b/src/node_options.h @@ -178,6 +178,7 @@ class EnvironmentOptions : public Options { bool trace_tls = false; bool trace_uncaught = false; bool trace_warnings = false; + bool trace_promises = false; bool extra_info_on_fatal_exception = true; std::string unhandled_rejections; std::vector userland_loaders; diff --git a/test/parallel/test-process-env-allowed-flags-are-documented.js b/test/parallel/test-process-env-allowed-flags-are-documented.js index dc4c704b6f0b88..2746fdfc086f99 100644 --- a/test/parallel/test-process-env-allowed-flags-are-documented.js +++ b/test/parallel/test-process-env-allowed-flags-are-documented.js @@ -106,6 +106,8 @@ assert(undocumented.delete('--no-node-snapshot')); assert(undocumented.delete('--loader')); assert(undocumented.delete('--verify-base-objects')); assert(undocumented.delete('--no-verify-base-objects')); +assert(undocumented.delete('--trace-promises')); +assert(undocumented.delete('--no-trace-promises')); // Remove negated versions of the flags. for (const flag of undocumented) {