Browse Source

src: add tracing controller

This commit adds support for trace-event tracing to Node.js. It provides
a mechanism to centralize tracing information generated by V8, Node
core, and userspace code. It includes:

 - A trace writer responsible for serializing traces and cycling the
   output files so that no individual file becomes to large.
 - A buffer for aggregating traces to allow for batched flushes.
 - An agent which initializes the tracing controller and ensures that
   trace serialization is done on a separate thread.
 - A set of macros for generating trace events.
 - Tests and documentation.

Author: Raymond Kang <raymondksi@gmail.com>
Author: Kelvin Jin <kelvinjin@google.com>
Author: Matthew Loring <mattloring@google.com>
Author: Jason Ginchereau <jasongin@microsoft.com>

PR-URL: https://github.com/nodejs/node/pull/11106
Reviewed-By: Josh Gavant <josh.gavant@outlook.com>
v7.x
misterpoe 9 years ago
committed by Italo A. Casas
parent
commit
bd4ccc892c
No known key found for this signature in database GPG Key ID: 23EFEFE93C4CFFFE
  1. 14
      doc/api/cli.md
  2. 2
      doc/api/debugger.md
  3. 19
      doc/api/tracing.md
  4. 5
      node.gyp
  5. 28
      src/node.cc
  6. 1
      src/node.h
  7. 72
      src/tracing/agent.cc
  8. 31
      src/tracing/agent.h
  9. 177
      src/tracing/node_trace_buffer.cc
  10. 89
      src/tracing/node_trace_buffer.h
  11. 185
      src/tracing/node_trace_writer.cc
  12. 74
      src/tracing/node_trace_writer.h
  13. 17
      src/tracing/trace_event.cc
  14. 1710
      src/tracing/trace_event.h
  15. 35
      test/parallel/test-trace-event.js

14
doc/api/cli.md

@ -139,6 +139,20 @@ added: v2.1.0
Prints a stack trace whenever synchronous I/O is detected after the first turn
of the event loop.
### `--trace-events-enabled`
<!-- YAML
added: REPLACEME
-->
Enables the collection of trace event tracing information.
### `--trace-event-categories`
<!-- YAML
added: REPLACEME
-->
A comma separated list of categories that should be traced when trace event
tracing is enabled using `--trace-events-enabled`.
### `--zero-fill-buffers`
<!-- YAML

2
doc/api/debugger.md

@ -201,4 +201,4 @@ To start debugging, open the following URL in Chrome:
chrome-devtools://devtools/remote/serve_file/@60cd6e859b9f557d2312f5bf532f6aec5f284980/inspector.html?experiments=true&v8only=true&ws=localhost:9229/node
```
[TCP-based protocol]: https://github.com/v8/v8/wiki/Debugging-Protocol
[TCP-based protocol]: https://github.com/v8/v8/wiki/Debugging-Protocol

19
doc/api/tracing.md

@ -0,0 +1,19 @@
# Tracing
Trace Event provides a mechanism to centralize tracing information generated by
V8, Node core, and userspace code.
Tracing can be enabled by passing the `--trace-events-enabled` flag when starting a
Node.js application.
The set of categories for which traces are recorded can be specified using the
`--trace-event-categories` flag followed by a list of comma separated category names.
By default the `node` and `v8` categories are enabled.
```txt
node --trace-events-enabled --trace-event-categories v8,node server.js
```
Running Node.js with tracing enabled will produce log files that can be opened
in the [`chrome://tracing`](https://www.chromium.org/developers/how-tos/trace-event-profiling-tool)
tab of Chrome.

5
node.gyp

@ -152,6 +152,10 @@
],
'sources': [
'src/tracing/agent.cc',
'src/tracing/node_trace_buffer.cc',
'src/tracing/node_trace_writer.cc',
'src/tracing/trace_event.cc',
'src/async-wrap.cc',
'src/cares_wrap.cc',
'src/connection_wrap.cc',
@ -230,6 +234,7 @@
'src/stream_base.h',
'src/stream_base-inl.h',
'src/stream_wrap.h',
'src/tracing/trace_event.h'
'src/tree.h',
'src/util.h',
'src/util-inl.h',

28
src/node.cc

@ -38,6 +38,7 @@
#include "req-wrap.h"
#include "req-wrap-inl.h"
#include "string_bytes.h"
#include "tracing/agent.h"
#include "util.h"
#include "uv.h"
#if NODE_USE_V8_PLATFORM
@ -151,6 +152,8 @@ static node_module* modpending;
static node_module* modlist_builtin;
static node_module* modlist_linked;
static node_module* modlist_addon;
static bool trace_enabled = false;
static const char* trace_enabled_categories = nullptr;
#if defined(NODE_HAVE_I18N_SUPPORT)
// Path to ICU data (for i18n / Intl)
@ -195,6 +198,7 @@ static uv_async_t dispatch_debug_messages_async;
static Mutex node_isolate_mutex;
static v8::Isolate* node_isolate;
static tracing::Agent* tracing_agent;
static node::DebugOptions debug_options;
@ -203,6 +207,7 @@ static struct {
void Initialize(int thread_pool_size) {
platform_ = v8::platform::CreateDefaultPlatform(thread_pool_size);
V8::InitializePlatform(platform_);
tracing::TraceEventHelper::SetCurrentPlatform(platform_);
}
void PumpMessageLoop(Isolate* isolate) {
@ -3369,6 +3374,9 @@ void SetupProcessObject(Environment* env,
void SignalExit(int signo) {
uv_tty_reset_mode();
if (trace_enabled) {
tracing_agent->Stop();
}
#ifdef __FreeBSD__
// FreeBSD has a nasty bug, see RegisterSignalHandler for details
struct sigaction sa;
@ -3655,6 +3663,16 @@ static void ParseArgs(int* argc,
trace_deprecation = true;
} else if (strcmp(arg, "--trace-sync-io") == 0) {
trace_sync_io = true;
} else if (strcmp(arg, "--trace-events-enabled") == 0) {
trace_enabled = true;
} else if (strcmp(arg, "--trace-event-categories") == 0) {
const char* categories = argv[index + 1];
if (categories == nullptr) {
fprintf(stderr, "%s: %s requires an argument\n", argv[0], arg);
exit(9);
}
args_consumed += 1;
trace_enabled_categories = categories;
} else if (strcmp(arg, "--track-heap-objects") == 0) {
track_heap_objects = true;
} else if (strcmp(arg, "--throw-deprecation") == 0) {
@ -4499,10 +4517,20 @@ int Start(int argc, char** argv) {
#endif // HAVE_OPENSSL
v8_platform.Initialize(v8_thread_pool_size);
// Enable tracing when argv has --trace-events-enabled.
if (trace_enabled) {
fprintf(stderr, "Warning: Trace event is an experimental feature "
"and could change at any time.\n");
tracing_agent = new tracing::Agent();
tracing_agent->Start(v8_platform.platform_, trace_enabled_categories);
}
V8::Initialize();
v8_initialized = true;
const int exit_code =
Start(uv_default_loop(), argc, argv, exec_argc, exec_argv);
if (trace_enabled) {
tracing_agent->Stop();
}
v8_initialized = false;
V8::Dispose();

1
src/node.h

@ -41,6 +41,7 @@
#include "v8.h" // NOLINT(build/include_order)
#include "node_version.h" // NODE_MODULE_VERSION
#include "tracing/trace_event.h"
#define NODE_MAKE_VERSION(major, minor, patch) \
((major) * 0x1000 + (minor) * 0x100 + (patch))

72
src/tracing/agent.cc

@ -0,0 +1,72 @@
#include "tracing/agent.h"
#include <sstream>
#include <string>
#include "env-inl.h"
#include "libplatform/libplatform.h"
namespace node {
namespace tracing {
using v8::platform::tracing::TraceConfig;
Agent::Agent() {}
void Agent::Start(v8::Platform* platform, const char* enabled_categories) {
platform_ = platform;
int err = uv_loop_init(&tracing_loop_);
CHECK_EQ(err, 0);
NodeTraceWriter* trace_writer = new NodeTraceWriter(&tracing_loop_);
TraceBuffer* trace_buffer = new NodeTraceBuffer(
NodeTraceBuffer::kBufferChunks, trace_writer, &tracing_loop_);
tracing_controller_ = new TracingController();
TraceConfig* trace_config = new TraceConfig();
if (enabled_categories) {
std::stringstream category_list(enabled_categories);
while (category_list.good()) {
std::string category;
getline(category_list, category, ',');
trace_config->AddIncludedCategory(category.c_str());
}
} else {
trace_config->AddIncludedCategory("v8");
trace_config->AddIncludedCategory("node");
}
// This thread should be created *after* async handles are created
// (within NodeTraceWriter and NodeTraceBuffer constructors).
// Otherwise the thread could shut down prematurely.
err = uv_thread_create(&thread_, ThreadCb, this);
CHECK_EQ(err, 0);
tracing_controller_->Initialize(trace_buffer);
tracing_controller_->StartTracing(trace_config);
v8::platform::SetTracingController(platform, tracing_controller_);
}
void Agent::Stop() {
if (!IsStarted()) {
return;
}
// Perform final Flush on TraceBuffer. We don't want the tracing controller
// to flush the buffer again on destruction of the V8::Platform.
tracing_controller_->StopTracing();
delete tracing_controller_;
// Thread should finish when the tracing loop is stopped.
uv_thread_join(&thread_);
v8::platform::SetTracingController(platform_, nullptr);
}
// static
void Agent::ThreadCb(void* arg) {
Agent* agent = static_cast<Agent*>(arg);
uv_run(&agent->tracing_loop_, UV_RUN_DEFAULT);
}
} // namespace tracing
} // namespace node

31
src/tracing/agent.h

@ -0,0 +1,31 @@
#ifndef SRC_TRACING_AGENT_H_
#define SRC_TRACING_AGENT_H_
#include "tracing/node_trace_buffer.h"
#include "tracing/node_trace_writer.h"
#include "uv.h"
#include "v8.h"
namespace node {
namespace tracing {
class Agent {
public:
explicit Agent();
void Start(v8::Platform* platform, const char* enabled_categories);
void Stop();
private:
bool IsStarted() { return platform_ != nullptr; }
static void ThreadCb(void* arg);
uv_thread_t thread_;
uv_loop_t tracing_loop_;
v8::Platform* platform_ = nullptr;
TracingController* tracing_controller_;
};
} // namespace tracing
} // namespace node
#endif // SRC_TRACING_AGENT_H_

177
src/tracing/node_trace_buffer.cc

@ -0,0 +1,177 @@
#include "tracing/node_trace_buffer.h"
namespace node {
namespace tracing {
InternalTraceBuffer::InternalTraceBuffer(size_t max_chunks, uint32_t id,
NodeTraceWriter* trace_writer, NodeTraceBuffer* external_buffer)
: id_(id), flushing_(false), max_chunks_(max_chunks),
trace_writer_(trace_writer), external_buffer_(external_buffer) {
chunks_.resize(max_chunks);
}
TraceObject* InternalTraceBuffer::AddTraceEvent(uint64_t* handle) {
Mutex::ScopedLock scoped_lock(mutex_);
// Create new chunk if last chunk is full or there is no chunk.
if (total_chunks_ == 0 || chunks_[total_chunks_ - 1]->IsFull()) {
auto& chunk = chunks_[total_chunks_++];
if (chunk) {
chunk->Reset(current_chunk_seq_++);
} else {
chunk.reset(new TraceBufferChunk(current_chunk_seq_++));
}
}
auto& chunk = chunks_[total_chunks_ - 1];
size_t event_index;
TraceObject* trace_object = chunk->AddTraceEvent(&event_index);
*handle = MakeHandle(total_chunks_ - 1, chunk->seq(), event_index);
return trace_object;
}
TraceObject* InternalTraceBuffer::GetEventByHandle(uint64_t handle) {
Mutex::ScopedLock scoped_lock(mutex_);
if (handle == 0) {
// A handle value of zero never has a trace event associated with it.
return NULL;
}
size_t chunk_index, event_index;
uint32_t buffer_id, chunk_seq;
ExtractHandle(handle, &buffer_id, &chunk_index, &chunk_seq, &event_index);
if (buffer_id != id_ || chunk_index >= total_chunks_) {
// Either the chunk belongs to the other buffer, or is outside the current
// range of chunks loaded in memory (the latter being true suggests that
// the chunk has already been flushed and is no longer in memory.)
return NULL;
}
auto& chunk = chunks_[chunk_index];
if (chunk->seq() != chunk_seq) {
// Chunk is no longer in memory.
return NULL;
}
return chunk->GetEventAt(event_index);
}
void InternalTraceBuffer::Flush(bool blocking) {
{
Mutex::ScopedLock scoped_lock(mutex_);
if (total_chunks_ > 0) {
flushing_ = true;
for (size_t i = 0; i < total_chunks_; ++i) {
auto& chunk = chunks_[i];
for (size_t j = 0; j < chunk->size(); ++j) {
trace_writer_->AppendTraceEvent(chunk->GetEventAt(j));
}
}
total_chunks_ = 0;
flushing_ = false;
}
}
trace_writer_->Flush(blocking);
}
uint64_t InternalTraceBuffer::MakeHandle(
size_t chunk_index, uint32_t chunk_seq, size_t event_index) const {
return ((static_cast<uint64_t>(chunk_seq) * Capacity() +
chunk_index * TraceBufferChunk::kChunkSize + event_index) << 1) + id_;
}
void InternalTraceBuffer::ExtractHandle(
uint64_t handle, uint32_t* buffer_id, size_t* chunk_index,
uint32_t* chunk_seq, size_t* event_index) const {
*buffer_id = static_cast<uint32_t>(handle & 0x1);
handle >>= 1;
*chunk_seq = static_cast<uint32_t>(handle / Capacity());
size_t indices = handle % Capacity();
*chunk_index = indices / TraceBufferChunk::kChunkSize;
*event_index = indices % TraceBufferChunk::kChunkSize;
}
NodeTraceBuffer::NodeTraceBuffer(size_t max_chunks,
NodeTraceWriter* trace_writer, uv_loop_t* tracing_loop)
: tracing_loop_(tracing_loop), trace_writer_(trace_writer),
buffer1_(max_chunks, 0, trace_writer, this),
buffer2_(max_chunks, 1, trace_writer, this) {
current_buf_.store(&buffer1_);
flush_signal_.data = this;
int err = uv_async_init(tracing_loop_, &flush_signal_, NonBlockingFlushSignalCb);
CHECK_EQ(err, 0);
exit_signal_.data = this;
err = uv_async_init(tracing_loop_, &exit_signal_, ExitSignalCb);
CHECK_EQ(err, 0);
}
NodeTraceBuffer::~NodeTraceBuffer() {
uv_async_send(&exit_signal_);
Mutex::ScopedLock scoped_lock(exit_mutex_);
while(!exited_) {
exit_cond_.Wait(scoped_lock);
}
}
TraceObject* NodeTraceBuffer::AddTraceEvent(uint64_t* handle) {
// If the buffer is full, attempt to perform a flush.
if (!TryLoadAvailableBuffer()) {
// Assign a value of zero as the trace event handle.
// This is equivalent to calling InternalTraceBuffer::MakeHandle(0, 0, 0),
// and will cause GetEventByHandle to return NULL if passed as an argument.
*handle = 0;
return nullptr;
}
return current_buf_.load()->AddTraceEvent(handle);
}
TraceObject* NodeTraceBuffer::GetEventByHandle(uint64_t handle) {
return current_buf_.load()->GetEventByHandle(handle);
}
bool NodeTraceBuffer::Flush() {
buffer1_.Flush(true);
buffer2_.Flush(true);
return true;
}
// Attempts to set current_buf_ such that it references a buffer that can
// can write at least one trace event. If both buffers are unavailable this
// method returns false; otherwise it returns true.
bool NodeTraceBuffer::TryLoadAvailableBuffer() {
InternalTraceBuffer* prev_buf = current_buf_.load();
if (prev_buf->IsFull()) {
uv_async_send(&flush_signal_); // trigger flush on a separate thread
InternalTraceBuffer* other_buf = prev_buf == &buffer1_ ?
&buffer2_ : &buffer1_;
if (!other_buf->IsFull()) {
current_buf_.store(other_buf);
} else {
return false;
}
}
return true;
}
// static
void NodeTraceBuffer::NonBlockingFlushSignalCb(uv_async_t* signal) {
NodeTraceBuffer* buffer = reinterpret_cast<NodeTraceBuffer*>(signal->data);
if (buffer->buffer1_.IsFull() && !buffer->buffer1_.IsFlushing()) {
buffer->buffer1_.Flush(false);
}
if (buffer->buffer2_.IsFull() && !buffer->buffer2_.IsFlushing()) {
buffer->buffer2_.Flush(false);
}
}
// static
void NodeTraceBuffer::ExitSignalCb(uv_async_t* signal) {
NodeTraceBuffer* buffer = reinterpret_cast<NodeTraceBuffer*>(signal->data);
uv_close(reinterpret_cast<uv_handle_t*>(&buffer->flush_signal_), nullptr);
uv_close(reinterpret_cast<uv_handle_t*>(&buffer->exit_signal_), [](uv_handle_t* signal) {
NodeTraceBuffer* buffer = reinterpret_cast<NodeTraceBuffer*>(signal->data);
Mutex::ScopedLock scoped_lock(buffer->exit_mutex_);
buffer->exited_ = true;
buffer->exit_cond_.Signal(scoped_lock);
});
}
} // namespace tracing
} // namespace node

89
src/tracing/node_trace_buffer.h

@ -0,0 +1,89 @@
#ifndef SRC_NODE_TRACE_BUFFER_H_
#define SRC_NODE_TRACE_BUFFER_H_
#include "node_mutex.h"
#include "tracing/node_trace_writer.h"
#include "libplatform/v8-tracing.h"
#include <atomic>
namespace node {
namespace tracing {
using v8::platform::tracing::TraceBuffer;
using v8::platform::tracing::TraceBufferChunk;
using v8::platform::tracing::TraceObject;
// forward declaration
class NodeTraceBuffer;
class InternalTraceBuffer {
public:
InternalTraceBuffer(size_t max_chunks, uint32_t id,
NodeTraceWriter* trace_writer,
NodeTraceBuffer* external_buffer);
TraceObject* AddTraceEvent(uint64_t* handle);
TraceObject* GetEventByHandle(uint64_t handle);
void Flush(bool blocking);
bool IsFull() const {
return total_chunks_ == max_chunks_ && chunks_[total_chunks_ - 1]->IsFull();
}
bool IsFlushing() const {
return flushing_;
}
private:
uint64_t MakeHandle(size_t chunk_index, uint32_t chunk_seq,
size_t event_index) const;
void ExtractHandle(uint64_t handle, uint32_t* buffer_id, size_t* chunk_index,
uint32_t* chunk_seq, size_t* event_index) const;
size_t Capacity() const { return max_chunks_ * TraceBufferChunk::kChunkSize; }
Mutex mutex_;
bool flushing_;
size_t max_chunks_;
NodeTraceWriter* trace_writer_;
NodeTraceBuffer* external_buffer_;
std::vector<std::unique_ptr<TraceBufferChunk>> chunks_;
size_t total_chunks_ = 0;
uint32_t current_chunk_seq_ = 1;
uint32_t id_;
};
class NodeTraceBuffer : public TraceBuffer {
public:
NodeTraceBuffer(size_t max_chunks, NodeTraceWriter* trace_writer,
uv_loop_t* tracing_loop);
~NodeTraceBuffer();
TraceObject* AddTraceEvent(uint64_t* handle) override;
TraceObject* GetEventByHandle(uint64_t handle) override;
bool Flush() override;
static const size_t kBufferChunks = 1024;
private:
bool TryLoadAvailableBuffer();
static void NonBlockingFlushSignalCb(uv_async_t* signal);
static void ExitSignalCb(uv_async_t* signal);
uv_loop_t* tracing_loop_;
uv_async_t flush_signal_;
uv_async_t exit_signal_;
bool exited_ = false;
// Used exclusively for exit logic.
Mutex exit_mutex_;
// Used to wait until async handles have been closed.
ConditionVariable exit_cond_;
std::unique_ptr<NodeTraceWriter> trace_writer_;
// TODO: Change std::atomic to something less contentious.
std::atomic<InternalTraceBuffer*> current_buf_;
InternalTraceBuffer buffer1_;
InternalTraceBuffer buffer2_;
};
} // namespace tracing
} // namespace node
#endif // SRC_NODE_TRACING_CONTROLLER_H_

185
src/tracing/node_trace_writer.cc

@ -0,0 +1,185 @@
#include "tracing/node_trace_writer.h"
#include <string.h>
#include <fcntl.h>
#include "util.h"
namespace node {
namespace tracing {
NodeTraceWriter::NodeTraceWriter(uv_loop_t* tracing_loop)
: tracing_loop_(tracing_loop) {
flush_signal_.data = this;
int err = uv_async_init(tracing_loop_, &flush_signal_, FlushSignalCb);
CHECK_EQ(err, 0);
exit_signal_.data = this;
err = uv_async_init(tracing_loop_, &exit_signal_, ExitSignalCb);
CHECK_EQ(err, 0);
}
void NodeTraceWriter::WriteSuffix() {
// If our final log file has traces, then end the file appropriately.
// This means that if no trace events are recorded, then no trace file is
// produced.
bool should_flush = false;
{
Mutex::ScopedLock scoped_lock(stream_mutex_);
if (total_traces_ > 0) {
total_traces_ = 0; // so we don't write it again in FlushPrivate
// Appends "]}" to stream_.
delete json_trace_writer_;
should_flush = true;
}
}
if (should_flush) {
Flush(true);
}
}
NodeTraceWriter::~NodeTraceWriter() {
WriteSuffix();
uv_fs_t req;
int err;
if (fd_ != -1) {
err = uv_fs_close(tracing_loop_, &req, fd_, nullptr);
CHECK_EQ(err, 0);
uv_fs_req_cleanup(&req);
}
uv_async_send(&exit_signal_);
Mutex::ScopedLock scoped_lock(request_mutex_);
while(!exited_) {
exit_cond_.Wait(scoped_lock);
}
}
void NodeTraceWriter::OpenNewFileForStreaming() {
++file_num_;
uv_fs_t req;
std::ostringstream log_file;
log_file << "node_trace." << file_num_ << ".log";
fd_ = uv_fs_open(tracing_loop_, &req, log_file.str().c_str(),
O_CREAT | O_WRONLY | O_TRUNC, 0644, NULL);
CHECK_NE(fd_, -1);
uv_fs_req_cleanup(&req);
}
void NodeTraceWriter::AppendTraceEvent(TraceObject* trace_event) {
Mutex::ScopedLock scoped_lock(stream_mutex_);
// If this is the first trace event, open a new file for streaming.
if (total_traces_ == 0) {
OpenNewFileForStreaming();
// Constructing a new JSONTraceWriter object appends "{\"traceEvents\":["
// to stream_.
// In other words, the constructor initializes the serialization stream
// to a state where we can start writing trace events to it.
// Repeatedly constructing and destroying json_trace_writer_ allows
// us to use V8's JSON writer instead of implementing our own.
json_trace_writer_ = TraceWriter::CreateJSONTraceWriter(stream_);
}
++total_traces_;
json_trace_writer_->AppendTraceEvent(trace_event);
}
void NodeTraceWriter::FlushPrivate() {
std::string str;
int highest_request_id;
{
Mutex::ScopedLock stream_scoped_lock(stream_mutex_);
if (total_traces_ >= kTracesPerFile) {
total_traces_ = 0;
// Destroying the member JSONTraceWriter object appends "]}" to
// stream_ - in other words, ending a JSON file.
delete json_trace_writer_;
}
// str() makes a copy of the contents of the stream.
str = stream_.str();
stream_.str("");
stream_.clear();
}
{
Mutex::ScopedLock request_scoped_lock(request_mutex_);
highest_request_id = num_write_requests_;
}
WriteToFile(std::move(str), highest_request_id);
}
void NodeTraceWriter::FlushSignalCb(uv_async_t* signal) {
NodeTraceWriter* trace_writer = static_cast<NodeTraceWriter*>(signal->data);
trace_writer->FlushPrivate();
}
// TODO: Remove (is it necessary to change the API? Since because of WriteSuffix
// it no longer matters whether it's true or false)
void NodeTraceWriter::Flush() {
Flush(true);
}
void NodeTraceWriter::Flush(bool blocking) {
Mutex::ScopedLock scoped_lock(request_mutex_);
if (!json_trace_writer_) {
return;
}
int request_id = ++num_write_requests_;
int err = uv_async_send(&flush_signal_);
CHECK_EQ(err, 0);
if (blocking) {
// Wait until data associated with this request id has been written to disk.
// This guarantees that data from all earlier requests have also been
// written.
while (request_id > highest_request_id_completed_) {
request_cond_.Wait(scoped_lock);
}
}
}
void NodeTraceWriter::WriteToFile(std::string&& str, int highest_request_id) {
WriteRequest* write_req = new WriteRequest();
write_req->str = std::move(str);
write_req->writer = this;
write_req->highest_request_id = highest_request_id;
uv_buf_t uv_buf = uv_buf_init(const_cast<char*>(write_req->str.c_str()),
write_req->str.length());
request_mutex_.Lock();
// Manage a queue of WriteRequest objects because the behavior of uv_write is
// is undefined if the same WriteRequest object is used more than once
// between WriteCb calls. In addition, this allows us to keep track of the id
// of the latest write request that actually been completed.
write_req_queue_.push(write_req);
request_mutex_.Unlock();
int err = uv_fs_write(tracing_loop_, reinterpret_cast<uv_fs_t*>(write_req),
fd_, &uv_buf, 1, -1, WriteCb);
CHECK_EQ(err, 0);
}
void NodeTraceWriter::WriteCb(uv_fs_t* req) {
WriteRequest* write_req = reinterpret_cast<WriteRequest*>(req);
CHECK_GE(write_req->req.result, 0);
NodeTraceWriter* writer = write_req->writer;
int highest_request_id = write_req->highest_request_id;
{
Mutex::ScopedLock scoped_lock(writer->request_mutex_);
CHECK_EQ(write_req, writer->write_req_queue_.front());
writer->write_req_queue_.pop();
writer->highest_request_id_completed_ = highest_request_id;
writer->request_cond_.Broadcast(scoped_lock);
}
delete write_req;
}
// static
void NodeTraceWriter::ExitSignalCb(uv_async_t* signal) {
NodeTraceWriter* trace_writer = static_cast<NodeTraceWriter*>(signal->data);
uv_close(reinterpret_cast<uv_handle_t*>(&trace_writer->flush_signal_), nullptr);
uv_close(reinterpret_cast<uv_handle_t*>(&trace_writer->exit_signal_), [](uv_handle_t* signal) {
NodeTraceWriter* trace_writer = static_cast<NodeTraceWriter*>(signal->data);
Mutex::ScopedLock scoped_lock(trace_writer->request_mutex_);
trace_writer->exited_ = true;
trace_writer->exit_cond_.Signal(scoped_lock);
});
}
} // namespace tracing
} // namespace node

74
src/tracing/node_trace_writer.h

@ -0,0 +1,74 @@
#ifndef SRC_NODE_TRACE_WRITER_H_
#define SRC_NODE_TRACE_WRITER_H_
#include <sstream>
#include <queue>
#include "node_mutex.h"
#include "libplatform/v8-tracing.h"
#include "uv.h"
namespace node {
namespace tracing {
using v8::platform::tracing::TraceObject;
using v8::platform::tracing::TraceWriter;
using v8::platform::tracing::TracingController;
class NodeTraceWriter : public TraceWriter {
public:
NodeTraceWriter(uv_loop_t* tracing_loop);
~NodeTraceWriter();
void AppendTraceEvent(TraceObject* trace_event) override;
void Flush() override;
void Flush(bool blocking);
static const int kTracesPerFile = 1 << 19;
private:
struct WriteRequest {
uv_fs_t req;
NodeTraceWriter* writer;
std::string str;
int highest_request_id;
};
static void WriteCb(uv_fs_t* req);
void OpenNewFileForStreaming();
void WriteToFile(std::string&& str, int highest_request_id);
void WriteSuffix();
static void FlushSignalCb(uv_async_t* signal);
void FlushPrivate();
static void ExitSignalCb(uv_async_t* signal);
uv_loop_t* tracing_loop_;
// Triggers callback to initiate writing the contents of stream_ to disk.
uv_async_t flush_signal_;
// Triggers callback to close async objects, ending the tracing thread.
uv_async_t exit_signal_;
// Prevents concurrent R/W on state related to serialized trace data
// before it's written to disk, namely stream_ and total_traces_.
Mutex stream_mutex_;
// Prevents concurrent R/W on state related to write requests.
Mutex request_mutex_;
// Allows blocking calls to Flush() to wait on a condition for
// trace events to be written to disk.
ConditionVariable request_cond_;
// Used to wait until async handles have been closed.
ConditionVariable exit_cond_;
int fd_ = -1;
std::queue<WriteRequest*> write_req_queue_;
int num_write_requests_ = 0;
int highest_request_id_completed_ = 0;
int total_traces_ = 0;
int file_num_ = 0;
std::ostringstream stream_;
TraceWriter* json_trace_writer_ = nullptr;
bool exited_ = false;
};
} // namespace tracing
} // namespace node
#endif // SRC_NODE_TRACE_WRITER_H_

17
src/tracing/trace_event.cc

@ -0,0 +1,17 @@
#include "tracing/trace_event.h"
namespace node {
namespace tracing {
v8::Platform* platform_ = nullptr;
void TraceEventHelper::SetCurrentPlatform(v8::Platform* platform) {
platform_ = platform;
}
v8::Platform* TraceEventHelper::GetCurrentPlatform() {
return platform_;
}
} // namespace tracing
} // namespace node

1710
src/tracing/trace_event.h

File diff suppressed because it is too large

35
test/parallel/test-trace-event.js

@ -0,0 +1,35 @@
'use strict';
const common = require('../common');
const assert = require('assert');
const cp = require('child_process');
const fs = require('fs');
const CODE = 'for (var i = 0; i < 100000; i++) { "test" + i }';
const FILE_NAME = 'node_trace.1.log';
common.refreshTmpDir();
process.chdir(common.tmpDir);
const proc_no_categories = cp.spawn(process.execPath,
[ '--trace-events-enabled', '--trace-event-categories', '""', '-e', CODE ]);
proc_no_categories.once('exit', common.mustCall(() => {
assert(!common.fileExists(FILE_NAME));
const proc = cp.spawn(process.execPath,
[ '--trace-events-enabled', '-e', CODE ]);
proc.once('exit', common.mustCall(() => {
assert(common.fileExists(FILE_NAME));
fs.readFile(FILE_NAME, (err, data) => {
const traces = JSON.parse(data.toString()).traceEvents;
assert(traces.length > 0);
// Values that should be present on all runs to approximate correctness.
assert(traces.some((trace) => { return trace.pid === proc.pid; }));
assert(traces.some((trace) => { return trace.cat === 'v8'; }));
assert(traces.some((trace) => {
return trace.name === 'V8.ScriptCompiler';
}));
});
}));
}));
Loading…
Cancel
Save