diff --git a/doc/api/tracing.md b/doc/api/tracing.md index ab3603475df7ad..8225468ca648d4 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 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. diff --git a/src/crypto/crypto_util.h b/src/crypto/crypto_util.h index 7f83d6d1919df5..716b40be50cdc2 100644 --- a/src/crypto/crypto_util.h +++ b/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 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, "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 48b94a7c12873c..a37d354eaf0ed1 100644 --- a/src/node_api.cc +++ b/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), diff --git a/src/node_blob.cc b/src/node_blob.cc index b290273466c686..61960fee14b6c6 100644 --- a/src/node_blob.cc +++ b/src/node_blob.cc @@ -306,13 +306,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, "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 9f15a807d02e09..5e40fae214f9fe 100644 --- a/src/node_internals.h +++ b/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" diff --git a/src/node_zlib.cc b/src/node_zlib.cc index 367979f01203a2..303a0efba3261f 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, "zlib"), write_result_(nullptr) { MakeWeak(); } diff --git a/src/threadpoolwork-inl.h b/src/threadpoolwork-inl.h index 8bba988b18db0f..8fd95d42edd8fb 100644 --- a/src/threadpoolwork-inl.h +++ b/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); diff --git a/test/parallel/test-trace-events-threadpool.js b/test/parallel/test-trace-events-threadpool.js new file mode 100644 index 00000000000000..2a201d89274425 --- /dev/null +++ b/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);