inspector: implement --cpu-prof[-path]

This patch introduces a CLI flag --cpu-prof that starts the V8
CPU profiler on start up, and ends the profiler then writes the
CPU profile before the Node.js instance (on the main thread or
the worker thread) exits. By default the profile is written to
`${cwd}/CPU.${yyyymmdd}.${hhmmss}.${pid}.${tid}.${seq}.cpuprofile`.
The patch also introduces a --cpu-prof-path flag for the user
to specify the path the profile will be written to.

Refs: #26878
PR-URL: #27147
Reviewed-By: Anna Henningsen <[email protected]>

doc/api/cli.md

@@ -75,6 +75,37 @@ $ node --completion-bash > node_bash_completion
 $ source node_bash_completion
 ```
 
+### `--cpu-prof`
+<!-- YAML
+added: REPLACEME
+-->
+
+> Stability: 1 - Experimental
+
+Starts the V8 CPU profiler on start up, and writes the CPU profile to disk
+before exit. If `--cpu-prof-path` is not specified, the profile will be
+written to `${cwd}/CPU.${yyyymmdd}.${hhmmss}.${pid}.${tid}.${seq}.cpuprofile`.
+
+```console
+$ node --cpu-prof index.js
+$ ls *.cpuprofile
+CPU.20190409.202950.15293.0.0.cpuprofile
+```
+
+### `--cpu-prof-path`
+<!-- YAML
+added: REPLACEME
+-->
+
+> Stability: 1 - Experimental
+
+Location where the CPU profile generated by `--cpu-prof`
+should be written to. When used alone, it implies `--cpu-prof`.
+
+```console
+$ node --cpu-prof-path /tmp/test.cpuprofile index.js
+```
+
 ### `--diagnostic-report-directory=directory`
 <!-- YAML
 added: v11.8.0

doc/node.1

@@ -78,6 +78,18 @@ Aborting instead of exiting causes a core file to be generated for analysis.
 .It Fl -completion-bash
 Print source-able bash completion script for Node.js.
 .
+.It Fl -cpu-prof
+Start the V8 CPU profiler on start up, and write the CPU profile to disk
+before exit. If
+.Fl -cpu-prof-path
+is not specified, the profile will be written to the current working directory.
+.
+.It Fl -cpu-prof-path
+Path the V8 CPU profile generated with
+.Fl -cpu-prof
+will be written to. When used alone, it implies
+.Fl -cpu-prof
+.
 .It Fl -diagnostic-report-directory
 Location at which the
 .Sy diagnostic report

src/env-inl.h

@@ -659,6 +659,25 @@ inline profiler::V8CoverageConnection* Environment::coverage_connection() {
 inline const std::string& Environment::coverage_directory() const {
   return coverage_directory_;
 }
+
+inline void Environment::set_cpu_profiler_connection(
+    std::unique_ptr<profiler::V8CpuProfilerConnection> connection) {
+  CHECK_NULL(cpu_profiler_connection_);
+  std::swap(cpu_profiler_connection_, connection);
+}
+
+inline profiler::V8CpuProfilerConnection*
+Environment::cpu_profiler_connection() {
+  return cpu_profiler_connection_.get();
+}
+
+inline void Environment::set_cpu_profile_path(const std::string& path) {
+  cpu_profile_path_ = path;
+}
+
+inline const std::string& Environment::cpu_profile_path() const {
+  return cpu_profile_path_;
+}
 #endif  // HAVE_INSPECTOR
 
 inline std::shared_ptr<HostPort> Environment::inspector_host_port() {

src/env.h

@@ -71,6 +71,7 @@ class AgentWriterHandle;
 #if HAVE_INSPECTOR
 namespace profiler {
 class V8CoverageConnection;
+class V8CpuProfilerConnection;
 }  // namespace profiler
 #endif  // HAVE_INSPECTOR
 
@@ -1129,6 +1130,13 @@ class Environment : public MemoryRetainer {
 
   inline void set_coverage_directory(const char* directory);
   inline const std::string& coverage_directory() const;
+
+  void set_cpu_profiler_connection(
+      std::unique_ptr<profiler::V8CpuProfilerConnection> connection);
+  profiler::V8CpuProfilerConnection* cpu_profiler_connection();
+
+  inline void set_cpu_profile_path(const std::string& path);
+  inline const std::string& cpu_profile_path() const;
 #endif  // HAVE_INSPECTOR
 
  private:
@@ -1163,7 +1171,9 @@ class Environment : public MemoryRetainer {
 
 #if HAVE_INSPECTOR
   std::unique_ptr<profiler::V8CoverageConnection> coverage_connection_;
+  std::unique_ptr<profiler::V8CpuProfilerConnection> cpu_profiler_connection_;
   std::string coverage_directory_;
+  std::string cpu_profile_path_;
 #endif  // HAVE_INSPECTOR
 
   std::shared_ptr<EnvironmentOptions> options_;

src/inspector_profiler.cc

@@ -23,10 +23,14 @@ using v8::Value;
 using v8_inspector::StringBuffer;
 using v8_inspector::StringView;
 
-#ifdef __POSIX__
-const char* const kPathSeparator = "/";
-#else
+#ifdef _WIN32
 const char* const kPathSeparator = "\\/";
+/* MAX_PATH is in characters, not bytes. Make sure we have enough headroom. */
+#define CWD_BUFSIZE (MAX_PATH * 4)
+#else
+#include <climits>  // PATH_MAX on Solaris.
+const char* const kPathSeparator = "/";
+#define CWD_BUFSIZE (PATH_MAX)
 #endif
 
 std::unique_ptr<StringBuffer> ToProtocolString(Isolate* isolate,
@@ -180,6 +184,116 @@ void V8CoverageConnection::End() {
   DispatchMessage(end);
 }
 
+void V8CpuProfilerConnection::OnMessage(
+    const v8_inspector::StringView& message) {
+  Debug(env(),
+        DebugCategory::INSPECTOR_PROFILER,
+        "Receive cpu profiling message, ending = %s\n",
+        ending_ ? "true" : "false");
+  if (!ending_) {
+    return;
+  }
+  Isolate* isolate = env()->isolate();
+  HandleScope handle_scope(isolate);
+  Local<Context> context = env()->context();
+  Context::Scope context_scope(context);
+  Local<String> result;
+  if (!String::NewFromTwoByte(isolate,
+                              message.characters16(),
+                              NewStringType::kNormal,
+                              message.length())
+           .ToLocal(&result)) {
+    fprintf(stderr, "Failed to convert profiling message\n");
+  }
+  WriteCpuProfile(result);
+}
+
+void V8CpuProfilerConnection::WriteCpuProfile(Local<String> message) {
+  const std::string& path = env()->cpu_profile_path();
+  CHECK(!path.empty());
+  std::string directory = path.substr(0, path.find_last_of(kPathSeparator));
+  if (directory != path) {
+    uv_fs_t req;
+    int ret = fs::MKDirpSync(nullptr, &req, directory, 0777, nullptr);
+    uv_fs_req_cleanup(&req);
+    if (ret < 0 && ret != UV_EEXIST) {
+      char err_buf[128];
+      uv_err_name_r(ret, err_buf, sizeof(err_buf));
+      fprintf(stderr,
+              "%s: Failed to create cpu profile directory %s\n",
+              err_buf,
+              directory.c_str());
+      return;
+    }
+  }
+  MaybeLocal<String> result = GetResult(message);
+  if (!result.IsEmpty()) {
+    WriteResult(path.c_str(), result.ToLocalChecked());
+  }
+}
+
+MaybeLocal<String> V8CpuProfilerConnection::GetResult(Local<String> message) {
+  Local<Context> context = env()->context();
+  Isolate* isolate = env()->isolate();
+  Local<Value> parsed;
+  if (!v8::JSON::Parse(context, message).ToLocal(&parsed) ||
+      !parsed->IsObject()) {
+    fprintf(stderr, "Failed to parse CPU profile result as JSON object\n");
+    return MaybeLocal<String>();
+  }
+
+  Local<Value> result_v;
+  if (!parsed.As<Object>()
+           ->Get(context, FIXED_ONE_BYTE_STRING(isolate, "result"))
+           .ToLocal(&result_v)) {
+    fprintf(stderr, "Failed to get result from CPU profile message\n");
+    return MaybeLocal<String>();
+  }
+
+  if (!result_v->IsObject()) {
+    fprintf(stderr, "'result' from CPU profile message is not an object\n");
+    return MaybeLocal<String>();
+  }
+
+  Local<Value> profile_v;
+  if (!result_v.As<Object>()
+           ->Get(context, FIXED_ONE_BYTE_STRING(isolate, "profile"))
+           .ToLocal(&profile_v)) {
+    fprintf(stderr, "'profile' from CPU profile result is undefined\n");
+    return MaybeLocal<String>();
+  }
+
+  Local<String> result_s;
+  if (!v8::JSON::Stringify(context, profile_v).ToLocal(&result_s)) {
+    fprintf(stderr, "Failed to stringify CPU profile result\n");
+    return MaybeLocal<String>();
+  }
+
+  return result_s;
+}
+
+void V8CpuProfilerConnection::Start() {
+  Debug(env(), DebugCategory::INSPECTOR_PROFILER, "Sending Profiler.start\n");
+  Isolate* isolate = env()->isolate();
+  Local<String> enable = FIXED_ONE_BYTE_STRING(
+      isolate, R"({"id": 1, "method": "Profiler.enable"})");
+  Local<String> start = FIXED_ONE_BYTE_STRING(
+      isolate, R"({"id": 2, "method": "Profiler.start"})");
+  DispatchMessage(enable);
+  DispatchMessage(start);
+}
+
+void V8CpuProfilerConnection::End() {
+  CHECK_EQ(ending_, false);
+  ending_ = true;
+  Debug(env(), DebugCategory::INSPECTOR_PROFILER, "Sending Profiler.stop\n");
+  Isolate* isolate = env()->isolate();
+  HandleScope scope(isolate);
+  Local<String> end =
+      FIXED_ONE_BYTE_STRING(isolate, R"({"id": 3, "method": "Profiler.stop"})");
+  DispatchMessage(end);
+}
+
 // For now, we only support coverage profiling, but we may add more
 // in the future.
 void EndStartedProfilers(Environment* env) {
@@ -190,6 +304,12 @@ void EndStartedProfilers(Environment* env) {
         env, DebugCategory::INSPECTOR_PROFILER, "Ending coverage collection\n");
     connection->End();
   }
+
+  connection = env->cpu_profiler_connection();
+  if (connection != nullptr && !connection->ending()) {
+    Debug(env, DebugCategory::INSPECTOR_PROFILER, "Ending cpu profiling\n");
+    connection->End();
+  }
 }
 
 void StartCoverageCollection(Environment* env) {
@@ -198,6 +318,26 @@ void StartCoverageCollection(Environment* env) {
   env->coverage_connection()->Start();
 }
 
+void StartCpuProfiling(Environment* env, const std::string& profile_path) {
+  std::string path;
+  if (profile_path.empty()) {
+    char cwd[CWD_BUFSIZE];
+    size_t size = CWD_BUFSIZE;
+    int err = uv_cwd(cwd, &size);
+    // TODO(joyeecheung): fallback to exec path / argv[0]
+    CHECK_EQ(err, 0);
+    CHECK_GT(size, 0);
+    DiagnosticFilename filename(env, "CPU", "cpuprofile");
+    path = cwd + std::string(kPathSeparator) + (*filename);
+  } else {
+    path = profile_path;
+  }
+  env->set_cpu_profile_path(std::move(path));
+  env->set_cpu_profiler_connection(
+      std::make_unique<V8CpuProfilerConnection>(env));
+  env->cpu_profiler_connection()->Start();
+}
+
 static void SetCoverageDirectory(const FunctionCallbackInfo<Value>& args) {
   CHECK(args[0]->IsString());
   Environment* env = Environment::GetCurrent(args);

src/inspector_profiler.h

@@ -68,6 +68,24 @@ class V8CoverageConnection : public V8ProfilerConnection {
   bool ending_ = false;
 };
 
+class V8CpuProfilerConnection : public V8ProfilerConnection {
+ public:
+  explicit V8CpuProfilerConnection(Environment* env)
+      : V8ProfilerConnection(env) {}
+
+  void Start() override;
+  void End() override;
+  void OnMessage(const v8_inspector::StringView& message) override;
+  bool ending() const override { return ending_; }
+
+ private:
+  void WriteCpuProfile(v8::Local<v8::String> message);
+  v8::MaybeLocal<v8::String> GetResult(v8::Local<v8::String> message);
+
+  std::unique_ptr<inspector::InspectorSession> session_;
+  bool ending_ = false;
+};
+
 }  // namespace profiler
 }  // namespace node
 

src/node.cc

@@ -237,6 +237,12 @@ MaybeLocal<Value> RunBootstrapping(Environment* env) {
 #endif  // HAVE_INSPECTOR
   }
 
+#if HAVE_INSPECTOR
+  if (env->options()->cpu_prof) {
+    profiler::StartCpuProfiling(env, env->options()->cpu_prof_path);
+  }
+#endif  // HAVE_INSPECTOR
+
   // Add a reference to the global object
   Local<Object> global = context->Global();
 

src/node_internals.h

@@ -314,6 +314,7 @@ void MarkBootstrapComplete(const v8::FunctionCallbackInfo<v8::Value>& args);
 #if HAVE_INSPECTOR
 namespace profiler {
 void StartCoverageCollection(Environment* env);
+void StartCpuProfiling(Environment* env, const std::string& profile_name);
 void EndStartedProfilers(Environment* env);
 }
 #endif  // HAVE_INSPECTOR

src/node_options.cc

@@ -332,6 +332,18 @@ EnvironmentOptionsParser::EnvironmentOptionsParser() {
             &EnvironmentOptions::prof_process);
   // Options after --prof-process are passed through to the prof processor.
   AddAlias("--prof-process", { "--prof-process", "--" });
+#if HAVE_INSPECTOR
+  AddOption("--cpu-prof",
+            "Start the V8 CPU profiler on start up, and write the CPU profile "
+            "to disk before exit. If --cpu-prof-path is not specified, write "
+            "the profile to the current working directory.",
+            &EnvironmentOptions::cpu_prof);
+  AddOption("--cpu-prof-path",
+            "Path the V8 CPU profile generated with --cpu-prof will be "
+            "written to.",
+            &EnvironmentOptions::cpu_prof_path);
+  Implies("--cpu-prof-path", "--cpu-prof");
+#endif  // HAVE_INSPECTOR
   AddOption("--redirect-warnings",
             "write warnings to file instead of stderr",
             &EnvironmentOptions::redirect_warnings,

src/node_options.h

@@ -109,6 +109,10 @@ class EnvironmentOptions : public Options {
   bool preserve_symlinks = false;
   bool preserve_symlinks_main = false;
   bool prof_process = false;
+#if HAVE_INSPECTOR
+  std::string cpu_prof_path;
+  bool cpu_prof = false;
+#endif  // HAVE_INSPECTOR
   std::string redirect_warnings;
   bool throw_deprecation = false;
   bool trace_deprecation = false;

test/fixtures/workload/fibonacci-exit.js

@@ -0,0 +1,7 @@
+'use strict';
+function fib(n) {
+  if (n === 0 || n === 1) return n;
+  return fib(n - 1) + fib(n - 2);
+}
+fib(parseInt(process.argv[2]) || 35);
+process.exit(55);

test/fixtures/workload/fibonacci-sigint.js

@@ -0,0 +1,7 @@
+'use strict';
+function fib(n) {
+  if (n === 0 || n === 1) return n;
+  return fib(n - 1) + fib(n - 2);
+}
+fib(parseInt(process.argv[2]) || 35);
+process.kill(process.pid, "SIGINT");

test/fixtures/workload/fibonacci-worker.js

@@ -0,0 +1,7 @@
+'use strict';
+
+const { Worker } = require('worker_threads');
+const path = require('path');
+new Worker(path.join(__dirname, 'fibonacci.js'), {
+  execArgv: ['--cpu-prof']
+});

test/fixtures/workload/fibonacci.js

@@ -0,0 +1,8 @@
+'use strict';
+function fib(n) {
+  if (n === 0 || n === 1) return n;
+  return fib(n - 1) + fib(n - 2);
+}
+
+const n = parseInt(process.env.FIB) || 35;
+process.stdout.write(`${fib(n)}\n`);

test/sequential/test-cpu-prof.js

@@ -0,0 +1,195 @@
+'use strict';
+
+// This tests that --cpu-prof and --cpu-prof-path works.
+
+const common = require('../common');
+const fixtures = require('../common/fixtures');
+common.skipIfInspectorDisabled();
+
+const assert = require('assert');
+const fs = require('fs');
+const path = require('path');
+const { spawnSync } = require('child_process');
+
+const tmpdir = require('../common/tmpdir');
+
+function getCpuProfiles(dir) {
+  const list = fs.readdirSync(dir);
+  return list
+    .filter((file) => file.endsWith('.cpuprofile'))
+    .map((file) => path.join(dir, file));
+}
+
+function verifyFrames(output, file, suffix) {
+  const data = fs.readFileSync(file, 'utf8');
+  const profile = JSON.parse(data);
+  const frames = profile.nodes.filter((i) => {
+    const frame = i.callFrame;
+    return frame.url.endsWith(suffix);
+  });
+  if (frames.length === 0) {
+    // Show native debug output and the profile for debugging.
+    console.log(output.stderr.toString());
+    console.log(profile.nodes);
+  }
+  assert.notDeepStrictEqual(frames, []);
+}
+
+let FIB = 30;
+// This is based on emperial values - in the CI, on Windows the program
+// tend to finish too fast then we won't be able to see the profiled script
+// in the samples, so we need to bump the values a bit. On slower platforms
+// like the Pis it could take more time to complete, we need to use a
+// smaller value so the test would not time out.
+if (common.isWindows) {
+  FIB = 40;
+}
+
+const env = {
+  ...process.env,
+  FIB,
+  NODE_DEBUG_NATIVE: 'INSPECTOR_PROFILER'
+};
+
+// Outputs CPU profile when event loop is drained.
+// TODO(joyeecheung): share the fixutres with v8 coverage tests
+{
+  tmpdir.refresh();
+  const output = spawnSync(process.execPath, [
+    '--cpu-prof',
+    fixtures.path('workload', 'fibonacci.js'),
+  ], {
+    cwd: tmpdir.path,
+    env
+  });
+  if (output.status !== 0) {
+    console.log(output.stderr.toString());
+  }
+  assert.strictEqual(output.status, 0);
+  const profiles = getCpuProfiles(tmpdir.path);
+  assert.strictEqual(profiles.length, 1);
+  verifyFrames(output, profiles[0], 'fibonacci.js');
+}
+
+// Outputs CPU profile when process.exit(55) exits process.
+{
+  tmpdir.refresh();
+  const output = spawnSync(process.execPath, [
+    '--cpu-prof',
+    fixtures.path('workload', 'fibonacci-exit.js'),
+  ], {
+    cwd: tmpdir.path,
+    env
+  });
+  if (output.status !== 55) {
+    console.log(output.stderr.toString());
+  }
+  assert.strictEqual(output.status, 55);
+  const profiles = getCpuProfiles(tmpdir.path);
+  assert.strictEqual(profiles.length, 1);
+  verifyFrames(output, profiles[0], 'fibonacci-exit.js');
+}
+
+// Outputs CPU profile when process.kill(process.pid, "SIGINT"); exits process.
+{
+  tmpdir.refresh();
+  const output = spawnSync(process.execPath, [
+    '--cpu-prof',
+    fixtures.path('workload', 'fibonacci-sigint.js'),
+  ], {
+    cwd: tmpdir.path,
+    env
+  });
+  if (!common.isWindows) {
+    if (output.signal !== 'SIGINT') {
+      console.log(output.stderr.toString());
+    }
+    assert.strictEqual(output.signal, 'SIGINT');
+  }
+  const profiles = getCpuProfiles(tmpdir.path);
+  assert.strictEqual(profiles.length, 1);
+  verifyFrames(output, profiles[0], 'fibonacci-sigint.js');
+}
+
+// Outputs CPU profile from worker.
+{
+  tmpdir.refresh();
+  const output = spawnSync(process.execPath, [
+    fixtures.path('workload', 'fibonacci-worker.js'),
+  ], {
+    cwd: tmpdir.path,
+    env
+  });
+  if (output.status !== 0) {
+    console.log(output.stderr.toString());
+  }
+  assert.strictEqual(output.status, 0);
+  const profiles = getCpuProfiles(tmpdir.path);
+  assert.strictEqual(profiles.length, 1);
+  verifyFrames(output, profiles[0], 'fibonacci.js');
+}
+
+// Output to specified --cpu-prof-path without --cpu-prof
+{
+  tmpdir.refresh();
+  const file = path.join(tmpdir.path, 'test.cpuprofile');
+  const output = spawnSync(process.execPath, [
+    '--cpu-prof-path',
+    file,
+    fixtures.path('workload', 'fibonacci.js'),
+  ], {
+    cwd: tmpdir.path,
+    env
+  });
+  if (output.status !== 0) {
+    console.log(output.stderr.toString());
+  }
+  assert.strictEqual(output.status, 0);
+  const profiles = getCpuProfiles(tmpdir.path);
+  assert.deepStrictEqual(profiles, [file]);
+  verifyFrames(output, file, 'fibonacci.js');
+}
+
+// Output to specified --cpu-prof-path with --cpu-prof
+{
+  tmpdir.refresh();
+  const file = path.join(tmpdir.path, 'test.cpuprofile');
+  const output = spawnSync(process.execPath, [
+    '--cpu-prof',
+    '--cpu-prof-path',
+    file,
+    fixtures.path('workload', 'fibonacci.js'),
+  ], {
+    cwd: tmpdir.path,
+    env
+  });
+  if (output.status !== 0) {
+    console.log(output.stderr.toString());
+  }
+  assert.strictEqual(output.status, 0);
+  const profiles = getCpuProfiles(tmpdir.path);
+  assert.deepStrictEqual(profiles, [file]);
+  verifyFrames(output, file, 'fibonacci.js');
+}
+
+// Output to specified --cpu-prof-path when it's not absolute
+{
+  tmpdir.refresh();
+  const file = path.join(tmpdir.path, 'test.cpuprofile');
+  const output = spawnSync(process.execPath, [
+    '--cpu-prof',
+    '--cpu-prof-path',
+    'test.cpuprofile',
+    fixtures.path('workload', 'fibonacci.js'),
+  ], {
+    cwd: tmpdir.path,
+    env
+  });
+  if (output.status !== 0) {
+    console.log(output.stderr.toString());
+  }
+  assert.strictEqual(output.status, 0);
+  const profiles = getCpuProfiles(tmpdir.path);
+  assert.deepStrictEqual(profiles, [file]);
+  verifyFrames(output, file, 'fibonacci.js');
+}