From 40c49ab2f5064e09f5650a3a602007023289f423 Mon Sep 17 00:00:00 2001 From: theanarkh Date: Wed, 31 Aug 2022 00:26:26 +0800 Subject: [PATCH] src: trace threadpool event --- doc/api/tracing.md | 2 + src/crypto/crypto_util.h | 13 ++-- src/node_api.cc | 2 +- src/node_blob.cc | 11 ++-- src/node_internals.h | 25 +++++++- src/node_zlib.cc | 2 +- src/threadpoolwork-inl.h | 10 ++- test/parallel/test-trace-events-threadpool.js | 64 +++++++++++++++++++ 8 files changed, 112 insertions(+), 17 deletions(-) create mode 100644 test/parallel/test-trace-events-threadpool.js diff --git a/doc/api/tracing.md b/doc/api/tracing.md index a0bd4060ca4d51..9f83c8234fe946 100644 --- a/doc/api/tracing.md +++ b/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 Node.js threadpool work, + 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. diff --git a/src/crypto/crypto_util.h b/src/crypto/crypto_util.h index 4afae1884fe40e..6254eaf7cdba48 100644 --- a/src/crypto/crypto_util.h +++ b/src/crypto/crypto_util.h @@ -346,14 +346,13 @@ class CryptoJob : public AsyncWrap, public ThreadPoolWork { public: using AdditionalParams = typename CryptoJobTraits::AdditionalParameters; - explicit CryptoJob( - Environment* env, - v8::Local object, - AsyncWrap::ProviderType type, - CryptoJobMode mode, - AdditionalParams&& params) + explicit CryptoJob(Environment* env, + v8::Local object, + AsyncWrap::ProviderType type, + 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 diff --git a/src/node_api.cc b/src/node_api.cc index 08352b0a584b54..9f7e9693fd57cf 100644 --- a/src/node_api.cc +++ b/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::NODE_API), _env(env), _data(data), _execute(execute), diff --git a/src/node_blob.cc b/src/node_blob.cc index d785aa60332d61..20974fd3b44648 100644 --- a/src/node_blob.cc +++ b/src/node_blob.cc @@ -308,13 +308,12 @@ void Blob::GetDataObject(const v8::FunctionCallbackInfo& args) { } } -FixedSizeBlobCopyJob::FixedSizeBlobCopyJob( - Environment* env, - Local object, - Blob* blob, - FixedSizeBlobCopyJob::Mode mode) +FixedSizeBlobCopyJob::FixedSizeBlobCopyJob(Environment* env, + Local object, + 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(); diff --git a/src/node_internals.h b/src/node_internals.h index de81fbee07c30f..65170c9aec1e51 100644 --- a/src/node_internals.h +++ b/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, + NODE_API, + }; + 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* type_name() { + switch (type_) { + case ThreadPoolWorkType::BLOB: + return "blob"; + case ThreadPoolWorkType::CRYPTO: + return "crypto"; + case ThreadPoolWorkType::ZLIB: + return "zlib"; + case ThreadPoolWorkType::NODE_API: + return "node_api"; + default: + return "unknown"; + } + } + private: Environment* env_; uv_work_t work_req_; + ThreadPoolWorkType type_; }; #define TRACING_CATEGORY_NODE "node" diff --git a/src/node_zlib.cc b/src/node_zlib.cc index c217861e82ae1d..4be50b2b67092f 100644 --- a/src/node_zlib.cc +++ b/src/node_zlib.cc @@ -259,7 +259,7 @@ class CompressionStream : public AsyncWrap, public ThreadPoolWork { CompressionStream(Environment* env, Local wrap) : AsyncWrap(env, wrap, AsyncWrap::PROVIDER_ZLIB), - ThreadPoolWork(env), + ThreadPoolWork(env, ThreadPoolWorkType::ZLIB), write_result_(nullptr) { MakeWeak(); } diff --git a/src/threadpoolwork-inl.h b/src/threadpoolwork-inl.h index 8bba988b18db0f..7269099622749a 100644 --- a/src/threadpoolwork-inl.h +++ b/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), type_name(), this); int status = uv_queue_work( env_->event_loop(), &work_req_, @@ -41,6 +44,11 @@ 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->type_name(), + self, + "result", + status); self->AfterThreadPoolWork(status); }); CHECK_EQ(status, 0); diff --git a/test/parallel/test-trace-events-threadpool.js b/test/parallel/test-trace-events-threadpool.js new file mode 100644 index 00000000000000..d20e8c93409672 --- /dev/null +++ b/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);