diff --git a/doc/api/tracing.md b/doc/api/tracing.md index ab3603475df7ad..0adeed4713a7d8 100644 --- a/doc/api/tracing.md +++ b/doc/api/tracing.md @@ -22,6 +22,10 @@ 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.sync`: Enables capture of trace data for threadpool + synchronous operations, such as `blob`, `zlib`, `crypto` and `node_api`. +* `node.threadpoolwork.async`: 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 9cd89faca13159..efbdbeabf5a6af 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,7 @@ class ThreadPoolWork { private: Environment* env_; uv_work_t work_req_; + const char* type_; }; #define TRACING_CATEGORY_NODE "node" diff --git a/src/node_v8_platform-inl.h b/src/node_v8_platform-inl.h index 2504ff30b77e20..9f428d53315713 100644 --- a/src/node_v8_platform-inl.h +++ b/src/node_v8_platform-inl.h @@ -109,7 +109,7 @@ struct V8Platform { if (!initialized_) return; initialized_ = false; - + node::tracing::TraceEventHelper::SetAgent(nullptr); StopTracingAgent(); platform_->Shutdown(); delete platform_; @@ -117,6 +117,7 @@ struct V8Platform { // Destroy tracing after the platform (and platform threads) have been // stopped. tracing_agent_.reset(nullptr); + // The observer remove itself in OnTraceEnabled trace_state_observer_.reset(nullptr); } 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..729e3de8eeaa4c 100644 --- a/src/threadpoolwork-inl.h +++ b/src/threadpoolwork-inl.h @@ -24,23 +24,36 @@ #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_NODE2(threadpoolwork, async), type_, this); int status = uv_queue_work( env_->event_loop(), &work_req_, [](uv_work_t* req) { ThreadPoolWork* self = ContainerOf(&ThreadPoolWork::work_req_, req); + TRACE_EVENT_BEGIN0(TRACING_CATEGORY_NODE2(threadpoolwork, sync), + self->type_); self->DoThreadPoolWork(); + TRACE_EVENT_END0(TRACING_CATEGORY_NODE2(threadpoolwork, sync), + self->type_); }, [](uv_work_t* req, int status) { ThreadPoolWork* self = ContainerOf(&ThreadPoolWork::work_req_, req); self->env_->DecreaseWaitingRequestCounter(); + TRACE_EVENT_NESTABLE_ASYNC_END1( + TRACING_CATEGORY_NODE2(threadpoolwork, async), + self->type_, + self, + "result", + status); self->AfterThreadPoolWork(status); }); CHECK_EQ(status, 0); diff --git a/src/tracing/trace_event.cc b/src/tracing/trace_event.cc index 3ffe6f8867cae0..35acb8a9a8fd10 100644 --- a/src/tracing/trace_event.cc +++ b/src/tracing/trace_event.cc @@ -8,8 +8,13 @@ Agent* g_agent = nullptr; v8::TracingController* g_controller = nullptr; void TraceEventHelper::SetAgent(Agent* agent) { - g_agent = agent; - g_controller = agent->GetTracingController(); + if (agent) { + g_agent = agent; + g_controller = agent->GetTracingController(); + } else { + g_agent = nullptr; + g_controller = nullptr; + } } Agent* TraceEventHelper::GetAgent() { diff --git a/test/parallel/test-trace-events-threadpool.js b/test/parallel/test-trace-events-threadpool.js new file mode 100644 index 00000000000000..dd1cc02e53d793 --- /dev/null +++ b/test/parallel/test-trace-events-threadpool.js @@ -0,0 +1,71 @@ +'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.sync,node.threadpoolwork.async', + __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 ([ + 'node,node.threadpoolwork,node.threadpoolwork.sync', + 'node,node.threadpoolwork,node.threadpoolwork.async', + ].includes(item.cat)) { + 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 and sync events at least +assert.ok(blobCount >= 4); +assert.ok(zlibCount >= 4); +assert.ok(cryptoCount >= 4);