From de2340dccd4c483c1b6fdae4e7426915c86938d5 Mon Sep 17 00:00:00 2001 From: Ali Ijaz Sheikh Date: Thu, 11 Oct 2018 06:33:25 -0700 Subject: [PATCH] src: trace_event: secondary storage for metadata Metadata trace-events should be held in secondary storage so that they can be periodically reemitted. This change establishes the secondary storage and ensures that events are reemitted on each flush. Backport-PR-URL: https://github.com/nodejs/node/pull/23700 PR-URL: https://github.com/nodejs/node/pull/20900 Reviewed-By: James M Snell Reviewed-By: Anna Henningsen Backport-PR-URL: https://github.com/nodejs/node/pull/23700 --- src/node.cc | 4 +- src/node_platform.cc | 2 +- src/node_platform.h | 9 +++-- src/tracing/agent.cc | 27 +++++++++++++ src/tracing/agent.h | 15 +++++++ src/tracing/trace_event.cc | 14 ++++--- src/tracing/trace_event.h | 40 +++++++++++++------ test/cctest/node_test_fixture.cc | 2 +- test/cctest/node_test_fixture.h | 12 +++--- .../test-trace-events-dynamic-enable.js | 10 ++--- 10 files changed, 98 insertions(+), 37 deletions(-) diff --git a/src/node.cc b/src/node.cc index d9f297cc29a92b..a6728b7fb0fd5a 100644 --- a/src/node.cc +++ b/src/node.cc @@ -279,9 +279,9 @@ static struct { #if NODE_USE_V8_PLATFORM void Initialize(int thread_pool_size) { tracing_agent_.reset(new tracing::Agent()); + node::tracing::TraceEventHelper::SetAgent(tracing_agent_.get()); auto controller = tracing_agent_->GetTracingController(); controller->AddTraceStateObserver(new NodeTraceStateObserver(controller)); - tracing::TraceEventHelper::SetTracingController(controller); StartTracingAgent(); // Tracing must be initialized before platform threads are created. platform_ = new NodePlatform(thread_pool_size, controller); @@ -2805,7 +2805,7 @@ MultiIsolatePlatform* GetMainThreadMultiIsolatePlatform() { MultiIsolatePlatform* CreatePlatform( int thread_pool_size, - TracingController* tracing_controller) { + node::tracing::TracingController* tracing_controller) { return new NodePlatform(thread_pool_size, tracing_controller); } diff --git a/src/node_platform.cc b/src/node_platform.cc index ad0cd0db3ec684..fd8d045404ecc7 100644 --- a/src/node_platform.cc +++ b/src/node_platform.cc @@ -14,7 +14,7 @@ using v8::Local; using v8::Object; using v8::Platform; using v8::Task; -using v8::TracingController; +using node::tracing::TracingController; struct PlatformWorkerData { TaskQueue* task_queue; diff --git a/src/node_platform.h b/src/node_platform.h index c89c6a5ff6708e..91c3cad81ad754 100644 --- a/src/node_platform.h +++ b/src/node_platform.h @@ -11,6 +11,7 @@ #include "libplatform/libplatform.h" #include "node.h" #include "node_mutex.h" +#include "tracing/agent.h" #include "uv.h" namespace node { @@ -126,7 +127,8 @@ class BackgroundTaskRunner : public v8::TaskRunner { class NodePlatform : public MultiIsolatePlatform { public: - NodePlatform(int thread_pool_size, v8::TracingController* tracing_controller); + NodePlatform(int thread_pool_size, + node::tracing::TracingController* tracing_controller); virtual ~NodePlatform() {} void DrainBackgroundTasks(v8::Isolate* isolate) override; @@ -143,7 +145,7 @@ class NodePlatform : public MultiIsolatePlatform { bool IdleTasksEnabled(v8::Isolate* isolate) override; double MonotonicallyIncreasingTime() override; double CurrentClockTimeMillis() override; - v8::TracingController* GetTracingController() override; + node::tracing::TracingController* GetTracingController() override; bool FlushForegroundTasks(v8::Isolate* isolate) override; void RegisterIsolate(IsolateData* isolate_data, uv_loop_t* loop) override; @@ -161,8 +163,7 @@ class NodePlatform : public MultiIsolatePlatform { std::unordered_map> per_isolate_; - - v8::TracingController* tracing_controller_; + node::tracing::TracingController* tracing_controller_; std::shared_ptr background_task_runner_; }; diff --git a/src/tracing/agent.cc b/src/tracing/agent.cc index fd5cb3387b14ae..103df55da5236e 100644 --- a/src/tracing/agent.cc +++ b/src/tracing/agent.cc @@ -1,6 +1,7 @@ #include "tracing/agent.h" #include +#include "trace_event.h" #include "tracing/node_trace_buffer.h" #include "debug_utils.h" #include "env-inl.h" @@ -207,9 +208,35 @@ void Agent::AppendTraceEvent(TraceObject* trace_event) { } void Agent::Flush(bool blocking) { + for (const auto& event : metadata_events_) + AppendTraceEvent(event.get()); + for (const auto& id_writer : writers_) id_writer.second->Flush(blocking); } +void TracingController::AddMetadataEvent( + const unsigned char* category_group_enabled, + const char* name, + int num_args, + const char** arg_names, + const unsigned char* arg_types, + const uint64_t* arg_values, + std::unique_ptr* convertable_values, + unsigned int flags) { + std::unique_ptr trace_event(new TraceObject); + trace_event->Initialize( + TRACE_EVENT_PHASE_METADATA, category_group_enabled, name, + node::tracing::kGlobalScope, // scope + node::tracing::kNoId, // id + node::tracing::kNoId, // bind_id + num_args, arg_names, arg_types, arg_values, convertable_values, + TRACE_EVENT_FLAG_NONE, + CurrentTimestampMicroseconds(), + CurrentCpuTimestampMicroseconds()); + node::tracing::TraceEventHelper::GetAgent()->AddMetadataEvent( + std::move(trace_event)); +} + } // namespace tracing } // namespace node diff --git a/src/tracing/agent.h b/src/tracing/agent.h index bb2e514aee2914..e1a4ffbe893249 100644 --- a/src/tracing/agent.h +++ b/src/tracing/agent.h @@ -7,6 +7,7 @@ #include "util.h" #include "node_mutex.h" +#include #include #include #include @@ -34,6 +35,15 @@ class TracingController : public v8::platform::tracing::TracingController { int64_t CurrentTimestampMicroseconds() override { return uv_hrtime() / 1000; } + void AddMetadataEvent( + const unsigned char* category_group_enabled, + const char* name, + int num_args, + const char** arg_names, + const unsigned char* arg_types, + const uint64_t* arg_values, + std::unique_ptr* convertable_values, + unsigned int flags); }; class AgentWriterHandle { @@ -91,6 +101,10 @@ class Agent { // Writes to all writers registered through AddClient(). void AppendTraceEvent(TraceObject* trace_event); + + void AddMetadataEvent(std::unique_ptr event) { + metadata_events_.push_back(std::move(event)); + } // Flushes all writers registered through AddClient(). void Flush(bool blocking); @@ -129,6 +143,7 @@ class Agent { ConditionVariable initialize_writer_condvar_; uv_async_t initialize_writer_async_; std::set to_be_initialized_; + std::list> metadata_events_; }; void AgentWriterHandle::reset() { diff --git a/src/tracing/trace_event.cc b/src/tracing/trace_event.cc index f661dd5c69a07a..9232c34c4ca322 100644 --- a/src/tracing/trace_event.cc +++ b/src/tracing/trace_event.cc @@ -3,14 +3,18 @@ namespace node { namespace tracing { -v8::TracingController* g_controller = nullptr; +Agent* g_agent = nullptr; -void TraceEventHelper::SetTracingController(v8::TracingController* controller) { - g_controller = controller; +void TraceEventHelper::SetAgent(Agent* agent) { + g_agent = agent; } -v8::TracingController* TraceEventHelper::GetTracingController() { - return g_controller; +Agent* TraceEventHelper::GetAgent() { + return g_agent; +} + +TracingController* TraceEventHelper::GetTracingController() { + return g_agent->GetTracingController(); } } // namespace tracing diff --git a/src/tracing/trace_event.h b/src/tracing/trace_event.h index 1165fca59a99ea..d5d4befb14600a 100644 --- a/src/tracing/trace_event.h +++ b/src/tracing/trace_event.h @@ -310,8 +310,9 @@ const uint64_t kNoId = 0; class TraceEventHelper { public: - static v8::TracingController* GetTracingController(); - static void SetTracingController(v8::TracingController* controller); + static TracingController* GetTracingController(); + static Agent* GetAgent(); + static void SetAgent(Agent* agent); }; // TraceID encapsulates an ID that can either be an integer or pointer. Pointers @@ -487,6 +488,26 @@ static V8_INLINE uint64_t AddTraceEventWithTimestampImpl( arg_names, arg_types, arg_values, arg_convertables, flags, timestamp); } +static V8_INLINE void AddMetadataEventImpl( + const uint8_t* category_group_enabled, const char* name, int32_t num_args, + const char** arg_names, const uint8_t* arg_types, + const uint64_t* arg_values, unsigned int flags) { + std::unique_ptr arg_convertibles[2]; + if (num_args > 0 && arg_types[0] == TRACE_VALUE_TYPE_CONVERTABLE) { + arg_convertibles[0].reset(reinterpret_cast( + static_cast(arg_values[0]))); + } + if (num_args > 1 && arg_types[1] == TRACE_VALUE_TYPE_CONVERTABLE) { + arg_convertibles[1].reset(reinterpret_cast( + static_cast(arg_values[1]))); + } + node::tracing::TracingController* controller = + node::tracing::TraceEventHelper::GetTracingController(); + return controller->AddMetadataEvent( + category_group_enabled, name, num_args, arg_names, arg_types, arg_values, + arg_convertibles, flags); +} + // Define SetTraceValue for each allowed type. It stores the type and // value in the return arguments. This allows this API to avoid declaring any // structures so that it is portable to third_party libraries. @@ -632,23 +653,16 @@ static V8_INLINE uint64_t AddTraceEventWithTimestamp( } template -static V8_INLINE uint64_t AddMetadataEvent( +static V8_INLINE void AddMetadataEvent( const uint8_t* category_group_enabled, const char* name, const char* arg1_name, ARG1_TYPE&& arg1_val) { const int num_args = 1; uint8_t arg_type; uint64_t arg_value; SetTraceValue(std::forward(arg1_val), &arg_type, &arg_value); - // TODO(ofrobots): It would be good to add metadata events to a separate - // buffer so that they can be periodically reemitted. For now, we have a - // single buffer, so we just add them to the main buffer. - return TRACE_EVENT_API_ADD_TRACE_EVENT( - TRACE_EVENT_PHASE_METADATA, - category_group_enabled, name, - node::tracing::kGlobalScope, // scope - node::tracing::kNoId, // id - node::tracing::kNoId, // bind_id - num_args, &arg1_name, &arg_type, &arg_value, TRACE_EVENT_FLAG_NONE); + AddMetadataEventImpl( + category_group_enabled, name, num_args, &arg1_name, &arg_type, &arg_value, + TRACE_EVENT_FLAG_NONE); } // Used by TRACE_EVENTx macros. Do not use directly. diff --git a/test/cctest/node_test_fixture.cc b/test/cctest/node_test_fixture.cc index acc975a4cb3c6e..f13481824734fb 100644 --- a/test/cctest/node_test_fixture.cc +++ b/test/cctest/node_test_fixture.cc @@ -3,4 +3,4 @@ ArrayBufferUniquePtr NodeTestFixture::allocator{nullptr, nullptr}; uv_loop_t NodeTestFixture::current_loop; NodePlatformUniquePtr NodeTestFixture::platform; -TracingControllerUniquePtr NodeTestFixture::tracing_controller; +TracingAgentUniquePtr NodeTestFixture::tracing_agent; diff --git a/test/cctest/node_test_fixture.h b/test/cctest/node_test_fixture.h index 8cba5d99ba3c64..be3d82db643dd7 100644 --- a/test/cctest/node_test_fixture.h +++ b/test/cctest/node_test_fixture.h @@ -55,22 +55,22 @@ struct Argv { using ArrayBufferUniquePtr = std::unique_ptr; -using TracingControllerUniquePtr = std::unique_ptr; +using TracingAgentUniquePtr = std::unique_ptr; using NodePlatformUniquePtr = std::unique_ptr; class NodeTestFixture : public ::testing::Test { protected: static ArrayBufferUniquePtr allocator; - static TracingControllerUniquePtr tracing_controller; + static TracingAgentUniquePtr tracing_agent; static NodePlatformUniquePtr platform; static uv_loop_t current_loop; v8::Isolate* isolate_; static void SetUpTestCase() { - tracing_controller.reset(new v8::TracingController()); - node::tracing::TraceEventHelper::SetTracingController( - tracing_controller.get()); - platform.reset(new node::NodePlatform(4, nullptr)); + tracing_agent.reset(new node::tracing::Agent()); + node::tracing::TraceEventHelper::SetAgent(tracing_agent.get()); + platform.reset( + new node::NodePlatform(4, tracing_agent->GetTracingController())); CHECK_EQ(0, uv_loop_init(¤t_loop)); v8::V8::InitializePlatform(platform.get()); v8::V8::Initialize(); diff --git a/test/parallel/test-trace-events-dynamic-enable.js b/test/parallel/test-trace-events-dynamic-enable.js index 24a186c15a85c7..645dcb2764a1be 100644 --- a/test/parallel/test-trace-events-dynamic-enable.js +++ b/test/parallel/test-trace-events-dynamic-enable.js @@ -25,9 +25,12 @@ function post(message, data) { async function test() { session.connect(); - let traceNotification = null; + const events = []; let tracingComplete = false; - session.on('NodeTracing.dataCollected', (n) => traceNotification = n); + session.on('NodeTracing.dataCollected', (n) => { + assert.ok(n && n.data && n.data.value); + events.push(...n.data.value); // append the events. + }); session.on('NodeTracing.tracingComplete', () => tracingComplete = true); // Generate a node.perf event before tracing is enabled. @@ -47,10 +50,7 @@ async function test() { session.disconnect(); assert.ok(tracingComplete); - assert.ok(traceNotification); - assert.ok(traceNotification.data && traceNotification.data.value); - const events = traceNotification.data.value; const marks = events.filter((t) => null !== /node\.perf\.usertim/.exec(t.cat)); assert.strictEqual(marks.length, 1); assert.strictEqual(marks[0].name, 'mark2');