src: trace threadpool event

Author: theanarkh

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.threadpoolwork`: Enables capture of trace data for threadpool
+  asynchronous operations, such as `blob`, `zlib`, `crypto` and `node_api`.
 * `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

@@ -333,14 +333,13 @@ class CryptoJob : public AsyncWrap, public ThreadPoolWork {
  public:
   using AdditionalParams = typename CryptoJobTraits::AdditionalParameters;
 
-  explicit CryptoJob(
-      Environment* env,
-      v8::Local<v8::Object> object,
-      AsyncWrap::ProviderType type,
-      CryptoJobMode mode,
-      AdditionalParams&& params)
+  explicit CryptoJob(Environment* env,
+                     v8::Local<v8::Object> object,
+                     AsyncWrap::ProviderType type,
+                     CryptoJobMode mode,
+                     AdditionalParams&& params)
       : AsyncWrap(env, object, type),
-        ThreadPoolWork(env),
+        ThreadPoolWork(env, "crypto"),
         mode_(mode),
         params_(std::move(params)) {
     // If the CryptoJob is async, then the instance will be

src/node_api.cc

@@ -1069,7 +1069,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(), "node_api"),
         _env(env),
         _data(data),
         _execute(execute),

src/node_blob.cc

@@ -306,13 +306,12 @@ void Blob::GetDataObject(const v8::FunctionCallbackInfo<v8::Value>& args) {
   }
 }
 
-FixedSizeBlobCopyJob::FixedSizeBlobCopyJob(
-    Environment* env,
-    Local<Object> object,
-    Blob* blob,
-    FixedSizeBlobCopyJob::Mode mode)
+FixedSizeBlobCopyJob::FixedSizeBlobCopyJob(Environment* env,
+                                           Local<Object> object,
+                                           Blob* blob,
+                                           FixedSizeBlobCopyJob::Mode mode)
     : AsyncWrap(env, object, AsyncWrap::PROVIDER_FIXEDSIZEBLOBCOPY),
-      ThreadPoolWork(env),
+      ThreadPoolWork(env, "blob"),
       mode_(mode) {
   if (mode == FixedSizeBlobCopyJob::Mode::SYNC) MakeWeak();
   source_ = blob->entries();

src/node_internals.h

@@ -258,7 +258,8 @@ class DebugSealHandleScope {
 
 class ThreadPoolWork {
  public:
-  explicit inline ThreadPoolWork(Environment* env) : env_(env) {
+  explicit inline ThreadPoolWork(Environment* env, const char* type)
+      : env_(env), type_(type) {
     CHECK_NOT_NULL(env);
   }
   inline virtual ~ThreadPoolWork() = default;
@@ -274,6 +275,8 @@ class ThreadPoolWork {
  private:
   Environment* env_;
   uv_work_t work_req_;
+  const char* type_;
+  uint64_t time_ = 0;
 };
 
 #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, "zlib"),
         write_result_(nullptr) {
     MakeWeak();
   }

src/threadpoolwork-inl.h

@@ -24,23 +24,46 @@
 
 #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(threadpoolwork), type_, this);
+  bool enabled = false;
+  uv_work_cb fn = [](uv_work_t* req) {
+    ThreadPoolWork* self = ContainerOf(&ThreadPoolWork::work_req_, req);
+    self->DoThreadPoolWork();
+  };
+  if (*TRACE_EVENT_API_GET_CATEGORY_GROUP_ENABLED(
+          TRACING_CATEGORY_NODE1(threadpoolwork))) {
+    enabled = true;
+    fn = [](uv_work_t* req) {
+      ThreadPoolWork* self = ContainerOf(&ThreadPoolWork::work_req_, req);
+      uint64_t start = uv_hrtime();
+      self->DoThreadPoolWork();
+      self->time_ = uv_hrtime() - start;
+    };
+  }
   int status = uv_queue_work(
       env_->event_loop(),
       &work_req_,
-      [](uv_work_t* req) {
-        ThreadPoolWork* self = ContainerOf(&ThreadPoolWork::work_req_, req);
-        self->DoThreadPoolWork();
-      },
+      fn,
       [](uv_work_t* req, int status) {
         ThreadPoolWork* self = ContainerOf(&ThreadPoolWork::work_req_, req);
         self->env_->DecreaseWaitingRequestCounter();
+        TRACE_EVENT_NESTABLE_ASYNC_END2(
+            TRACING_CATEGORY_NODE1(threadpoolwork),
+            self->type_,
+            self,
+            "result",
+            status,
+            "syncTime",
+            self->time_);
         self->AfterThreadPoolWork(status);
       });
   CHECK_EQ(status, 0);

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

@@ -0,0 +1,72 @@
+'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.threadpoolwork',
+               __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.threadpoolwork') {
+    if (item.ph === 'e') {
+      assert.ok(item.args.result === 0);
+      assert.ok(item.args.syncTime >= 0);
+    }
+    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 async events at least
+assert.ok(blobCount >= 2);
+assert.ok(zlibCount >= 2);
+assert.ok(cryptoCount >= 2);