src: report idle time correctly

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: #37868
Reviewed-By: Gerhard Stöbich <[email protected]>
Reviewed-By: Anna Henningsen <[email protected]>
Reviewed-By: Michael Dawson <[email protected]>
Reviewed-By: Gireesh Punathil <[email protected]>

Author: Stephen Belanger

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()) {

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<uv_handle_t*>(&idle_prepare_handle_));
+  uv_unref(reinterpret_cast<uv_handle_t*>(&idle_check_handle_));
   uv_unref(reinterpret_cast<uv_handle_t*>(&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<uv_handle_t*>(timer_handle()));
   register_handle(reinterpret_cast<uv_handle_t*>(immediate_check_handle()));
   register_handle(reinterpret_cast<uv_handle_t*>(immediate_idle_handle()));
+  register_handle(reinterpret_cast<uv_handle_t*>(&idle_prepare_handle_));
+  register_handle(reinterpret_cast<uv_handle_t*>(&idle_check_handle_));
   register_handle(reinterpret_cast<uv_handle_t*>(&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;
 

src/env.h

@@ -1057,6 +1057,8 @@ class Environment : public MemoryRetainer {
   inline void AssignToContext(v8::Local<v8::Context> 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;
 

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!');
+}));