src: trace threadpool event

doc/api/tracing.md

@@ -22,6 +22,8 @@ The available categories are:
 * `node.bootstrap`: Enables capture of Node.js bootstrap milestones.
 * `node.console`: Enables capture of `console.time()` and `console.count()`
   output.
+* `node.threadpool`: Enables capture of Node.js threadpool,
+  except asynchronous file IO and DNS.
 * `node.dns.native`: Enables capture of trace data for DNS queries.
 * `node.net.native`: Enables capture of trace data for network.
 * `node.environment`: Enables capture of Node.js Environment milestones.

src/crypto/crypto_util.h

@@ -353,7 +353,7 @@ class CryptoJob : public AsyncWrap, public ThreadPoolWork {
       CryptoJobMode mode,
       AdditionalParams&& params)
       : AsyncWrap(env, object, type),
-        ThreadPoolWork(env),
+        ThreadPoolWork(env, ThreadPoolWorkType::CRYPTO),
         mode_(mode),
         params_(std::move(params)) {
     // If the CryptoJob is async, then the instance will be

src/node_api.cc

@@ -1068,7 +1068,7 @@ class Work : public node::AsyncResource, public node::ThreadPoolWork {
             env->isolate,
             async_resource,
             *v8::String::Utf8Value(env->isolate, async_resource_name)),
-        ThreadPoolWork(env->node_env()),
+        ThreadPoolWork(env->node_env(), ThreadPoolWorkType::NAPI),
         _env(env),
         _data(data),
         _execute(execute),

src/node_blob.cc

@@ -314,7 +314,7 @@ FixedSizeBlobCopyJob::FixedSizeBlobCopyJob(
     Blob* blob,
     FixedSizeBlobCopyJob::Mode mode)
     : AsyncWrap(env, object, AsyncWrap::PROVIDER_FIXEDSIZEBLOBCOPY),
-      ThreadPoolWork(env),
+      ThreadPoolWork(env, ThreadPoolWorkType::BLOB),
       mode_(mode) {
   if (mode == FixedSizeBlobCopyJob::Mode::SYNC) MakeWeak();
   source_ = blob->entries();

src/node_internals.h

@@ -258,7 +258,14 @@ class DebugSealHandleScope {
 
 class ThreadPoolWork {
  public:
-  explicit inline ThreadPoolWork(Environment* env) : env_(env) {
+  enum class ThreadPoolWorkType {
+    BLOB,
+    CRYPTO,
+    ZLIB,
+    NAPI,
+  };
+  explicit inline ThreadPoolWork(Environment* env, ThreadPoolWorkType type)
+      : env_(env), type_(type) {
     CHECK_NOT_NULL(env);
   }
   inline virtual ~ThreadPoolWork() = default;
@@ -271,9 +278,25 @@ class ThreadPoolWork {
 
   Environment* env() const { return env_; }
 
+  const char * typeName() {
+    switch (type_) {
+      case ThreadPoolWorkType::BLOB:
+        return "blob";
+      case ThreadPoolWorkType::CRYPTO:
+        return "crypto";
+      case ThreadPoolWorkType::ZLIB:
+        return "zlib";
+      case ThreadPoolWorkType::NAPI:
+        return "napi";
+      default:
+        return "unknown";
+    }
+  }
+
  private:
   Environment* env_;
   uv_work_t work_req_;
+  ThreadPoolWorkType type_;
 };
 
 #define TRACING_CATEGORY_NODE "node"

src/node_zlib.cc

@@ -259,7 +259,7 @@ class CompressionStream : public AsyncWrap, public ThreadPoolWork {
 
   CompressionStream(Environment* env, Local<Object> wrap)
       : AsyncWrap(env, wrap, AsyncWrap::PROVIDER_ZLIB),
-        ThreadPoolWork(env),
+        ThreadPoolWork(env, ThreadPoolWorkType::ZLIB),
         write_result_(nullptr) {
     MakeWeak();
   }

src/threadpoolwork-inl.h

@@ -24,13 +24,16 @@
 
 #if defined(NODE_WANT_INTERNALS) && NODE_WANT_INTERNALS
 
-#include "util-inl.h"
 #include "node_internals.h"
+#include "tracing/trace_event.h"
+#include "util-inl.h"
 
 namespace node {
 
 void ThreadPoolWork::ScheduleWork() {
   env_->IncreaseWaitingRequestCounter();
+  TRACE_EVENT_NESTABLE_ASYNC_BEGIN0(
+      TRACING_CATEGORY_NODE1(threadpool), typeName(), this);
   int status = uv_queue_work(
       env_->event_loop(),
       &work_req_,
@@ -41,6 +44,12 @@ void ThreadPoolWork::ScheduleWork() {
       [](uv_work_t* req, int status) {
         ThreadPoolWork* self = ContainerOf(&ThreadPoolWork::work_req_, req);
         self->env_->DecreaseWaitingRequestCounter();
+        TRACE_EVENT_NESTABLE_ASYNC_END1(
+            TRACING_CATEGORY_NODE1(threadpool),
+            self->typeName(),
+            self,
+            "result",
+            status);
         self->AfterThreadPoolWork(status);
       });
   CHECK_EQ(status, 0);

test/parallel/test-trace-events-threadpool.js

@@ -0,0 +1,64 @@
+'use strict';
+const common = require('../common');
+const assert = require('assert');
+const cp = require('child_process');
+const fs = require('fs');
+const path = require('path');
+const tmpdir = require('../common/tmpdir');
+
+if (!common.hasCrypto)
+  common.skip('missing crypto');
+
+const { hkdf } = require('crypto');
+const { deflate } = require('zlib');
+const { Blob } = require('buffer');
+
+
+if (process.env.isChild === '1') {
+  hkdf('sha512', 'key', 'salt', 'info', 64, () => {});
+  deflate('hello', () => {});
+  // Make async call
+  const blob = new Blob(['h'.repeat(4096 * 2)]);
+  blob.arrayBuffer();
+  return;
+}
+
+tmpdir.refresh();
+const FILE_NAME = path.join(tmpdir.path, 'node_trace.1.log');
+
+cp.spawnSync(process.execPath,
+             [
+               '--trace-events-enabled',
+               '--trace-event-categories', 'node.threadpool',
+               __filename,
+             ],
+             {
+               cwd: tmpdir.path,
+               env: {
+                 ...process.env,
+                 isChild: '1',
+               },
+             });
+
+assert(fs.existsSync(FILE_NAME));
+const data = fs.readFileSync(FILE_NAME);
+const traces = JSON.parse(data.toString()).traceEvents;
+assert(traces.length > 0);
+let blobCount = 0;
+let zlibCount = 0;
+let cryptoCount = 0;
+traces.forEach((item) => {
+  if (item.cat === 'node,node.threadpool') {
+    if (item.name === 'blob') {
+      blobCount++;
+    } else if (item.name === 'zlib') {
+      zlibCount++;
+    } else if (item.name === 'crypto') {
+      cryptoCount++;
+    }
+  }
+});
+// There are three types, each type has two events at least
+assert.strictEqual(blobCount >= 2, true);
+assert.strictEqual(zlibCount >= 2, true);
+assert.strictEqual(cryptoCount >= 2, true);