From 2da532cef8b2159290c2bcc4f6fb61c9697ed738 Mon Sep 17 00:00:00 2001 From: Stephen Belanger Date: Mon, 22 Mar 2021 16:27:31 -0700 Subject: [PATCH] src: report idle time correctly MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit With this change, the V8 profiler will attribute any time between prepare and check cycles, except any entrances to InternalCallbackScope, to be "idle" time. All callbacks, microtasks, and timers will be marked as not idle. The one exception is native modules which don't use the MakeCallback helper, but those are already broken anyway for async context tracking so we should just encourage broken modules to be fixed. PR-URL: https://github.com/nodejs/node/pull/37868 Reviewed-By: Gerhard Stöbich Reviewed-By: Anna Henningsen Reviewed-By: Michael Dawson Reviewed-By: Gireesh Punathil --- src/api/callback.cc | 4 +++ src/env.cc | 24 +++++++++++++ src/env.h | 4 +++ test/parallel/test-inspector-has-idle.js | 43 ++++++++++++++++++++++++ 4 files changed, 75 insertions(+) create mode 100644 test/parallel/test-inspector-has-idle.js diff --git a/src/api/callback.cc b/src/api/callback.cc index a7b23dd4924baf..8aed3fb8d31425 100644 --- a/src/api/callback.cc +++ b/src/api/callback.cc @@ -60,6 +60,8 @@ InternalCallbackScope::InternalCallbackScope(Environment* env, // If you hit this assertion, you forgot to enter the v8::Context first. CHECK_EQ(Environment::GetCurrent(env->isolate()), env); + env->isolate()->SetIdle(false); + env->async_hooks()->push_async_context( async_context_.async_id, async_context_.trigger_async_id, object); @@ -81,6 +83,8 @@ void InternalCallbackScope::Close() { if (closed_) return; closed_ = true; + auto idle = OnScopeLeave([&]() { env_->isolate()->SetIdle(true); }); + if (!env_->can_call_into_js()) return; auto perform_stopping_check = [&]() { if (env_->is_stopping()) { diff --git a/src/env.cc b/src/env.cc index 119706129713bd..abe9bc029d133a 100644 --- a/src/env.cc +++ b/src/env.cc @@ -555,6 +555,13 @@ void Environment::InitializeLibuv() { uv_check_start(immediate_check_handle(), CheckImmediate); + // Inform V8's CPU profiler when we're idle. The profiler is sampling-based + // but not all samples are created equal; mark the wall clock time spent in + // epoll_wait() and friends so profiling tools can filter it out. The samples + // still end up in v8.log but with state=IDLE rather than state=EXTERNAL. + uv_prepare_init(event_loop(), &idle_prepare_handle_); + uv_check_init(event_loop(), &idle_check_handle_); + uv_async_init( event_loop(), &task_queues_async_, @@ -565,6 +572,8 @@ void Environment::InitializeLibuv() { Context::Scope context_scope(env->context()); env->RunAndClearNativeImmediates(); }); + uv_unref(reinterpret_cast(&idle_prepare_handle_)); + uv_unref(reinterpret_cast(&idle_check_handle_)); uv_unref(reinterpret_cast(&task_queues_async_)); { @@ -581,6 +590,8 @@ void Environment::InitializeLibuv() { // the one environment per process setup, but will be called in // FreeEnvironment. RegisterHandleCleanups(); + + StartProfilerIdleNotifier(); } void Environment::ExitEnv() { @@ -608,6 +619,8 @@ void Environment::RegisterHandleCleanups() { register_handle(reinterpret_cast(timer_handle())); register_handle(reinterpret_cast(immediate_check_handle())); register_handle(reinterpret_cast(immediate_idle_handle())); + register_handle(reinterpret_cast(&idle_prepare_handle_)); + register_handle(reinterpret_cast(&idle_check_handle_)); register_handle(reinterpret_cast(&task_queues_async_)); } @@ -639,6 +652,17 @@ void Environment::CleanupHandles() { } } +void Environment::StartProfilerIdleNotifier() { + uv_prepare_start(&idle_prepare_handle_, [](uv_prepare_t* handle) { + Environment* env = ContainerOf(&Environment::idle_prepare_handle_, handle); + env->isolate()->SetIdle(true); + }); + uv_check_start(&idle_check_handle_, [](uv_check_t* handle) { + Environment* env = ContainerOf(&Environment::idle_check_handle_, handle); + env->isolate()->SetIdle(false); + }); +} + void Environment::PrintSyncTrace() const { if (!trace_sync_io_) return; diff --git a/src/env.h b/src/env.h index fa61450d0945d5..2dabdbb296ace8 100644 --- a/src/env.h +++ b/src/env.h @@ -1057,6 +1057,8 @@ class Environment : public MemoryRetainer { inline void AssignToContext(v8::Local context, const ContextInfo& info); + void StartProfilerIdleNotifier(); + inline v8::Isolate* isolate() const; inline uv_loop_t* event_loop() const; inline void TryLoadAddon( @@ -1408,6 +1410,8 @@ class Environment : public MemoryRetainer { uv_timer_t timer_handle_; uv_check_t immediate_check_handle_; uv_idle_t immediate_idle_handle_; + uv_prepare_t idle_prepare_handle_; + uv_check_t idle_check_handle_; uv_async_t task_queues_async_; int64_t task_queues_async_refs_ = 0; diff --git a/test/parallel/test-inspector-has-idle.js b/test/parallel/test-inspector-has-idle.js new file mode 100644 index 00000000000000..c14590353e6780 --- /dev/null +++ b/test/parallel/test-inspector-has-idle.js @@ -0,0 +1,43 @@ +'use strict'; +const common = require('../common'); + +common.skipIfInspectorDisabled(); + +const assert = require('assert'); +const { Session } = require('inspector'); +const { promisify } = require('util'); + +const sleep = promisify(setTimeout); + +async function test() { + const inspector = new Session(); + inspector.connect(); + + inspector.post('Profiler.enable'); + inspector.post('Profiler.start'); + + await sleep(1000); + + const { profile } = await new Promise((resolve, reject) => { + inspector.post('Profiler.stop', (err, params) => { + if (err) return reject(err); + resolve(params); + }); + }); + + let hasIdle = false; + for (const node of profile.nodes) { + if (node.callFrame.functionName === '(idle)') { + hasIdle = true; + break; + } + } + assert(hasIdle); + + inspector.post('Profiler.disable'); + inspector.disconnect(); +} + +test().then(common.mustCall(() => { + console.log('Done!'); +}));