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

@@ -61,6 +61,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);
 
@@ -82,6 +84,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

@@ -495,6 +495,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_,
@@ -505,6 +512,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_));
 
 {
@@ -521,6 +530,8 @@ void Environment::InitializeLibuv(){
 // the one environment per process setup, but will be called in
 // FreeEnvironment.
 RegisterHandleCleanups();
+
+StartProfilerIdleNotifier();
 }
 
 voidEnvironment::ExitEnv(){
@@ -548,6 +559,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_));
 }
 
@@ -579,6 +592,17 @@ void Environment::CleanupHandles(){
  }
 }
 
+voidEnvironment::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);
+ });
+}
+
 voidEnvironment::PrintSyncTrace() const{
 if (!trace_sync_io_) return;
 

src/env.h

@@ -919,6 +919,8 @@ class Environment : public MemoryRetainer{
 inlinevoidAssignToContext(v8::Local<v8::Context> context,
 const ContextInfo& info);
 
+voidStartProfilerIdleNotifier();
+
 inline v8::Isolate* isolate() const;
 inlineuv_loop_t* event_loop() const;
 inlinevoidTryLoadAddon(
@@ -1252,6 +1254,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';
+constcommon=require('../common');
+
+common.skipIfInspectorDisabled();
+
+constassert=require('assert');
+const{ Session }=require('inspector');
+const{ promisify }=require('util');
+
+constsleep=promisify(setTimeout);
+
+asyncfunctiontest(){
+constinspector=newSession();
+inspector.connect();
+
+inspector.post('Profiler.enable');
+inspector.post('Profiler.start');
+
+awaitsleep(1000);
+
+const{ profile }=awaitnewPromise((resolve,reject)=>{
+inspector.post('Profiler.stop',(err,params)=>{
+if(err)returnreject(err);
+resolve(params);
+});
+});
+
+lethasIdle=false;
+for(constnodeofprofile.nodes){
+if(node.callFrame.functionName==='(idle)'){
+hasIdle=true;
+break;
+}
+}
+assert(hasIdle);
+
+inspector.post('Profiler.disable');
+inspector.disconnect();
+}
+
+test().then(common.mustCall(()=>{
+console.log('Done!');
+}));