From 8ea92ad1e48bfa8212d543831581ccb5e6be9f6e Mon Sep 17 00:00:00 2001 From: Nicolas Savoire Date: Fri, 14 Apr 2023 10:49:04 +0200 Subject: [PATCH 01/27] Use timestamps to implement code hotspots --- bindings/profilers/wall.cc | 62 ++++++++++++++++++++++++++++++++++- bindings/profilers/wall.hh | 17 ++++++++++ ts/src/index.ts | 2 +- ts/src/time-profiler.ts | 8 +++-- ts/test/test-time-profiler.ts | 2 +- 5 files changed, 86 insertions(+), 5 deletions(-) diff --git a/bindings/profilers/wall.cc b/bindings/profilers/wall.cc index 5a8f03a0..5f085036 100644 --- a/bindings/profilers/wall.cc +++ b/bindings/profilers/wall.cc @@ -29,6 +29,21 @@ using namespace v8; namespace dd { +// Should not be static but per isolate ? +static WallProfiler* s_profiler; + +static void (*old_handler)(int, siginfo_t *, void *) = nullptr; + +static void sighandler(int sig, siginfo_t *info, void * context) { + if (s_profiler) { + s_profiler->PushContext(); + } + if (old_handler) { + old_handler(sig, info, context); + } +} + + Local CreateTimeNode(Local name, Local scriptName, Local scriptId, @@ -263,7 +278,7 @@ NAN_METHOD(WallProfiler::Start) { // Sample counts and timestamps are not used, so we do not need to record // samples. - const bool recordSamples = false; + const bool recordSamples = true; if (includeLines) { profiler->StartProfiling( @@ -271,6 +286,19 @@ NAN_METHOD(WallProfiler::Start) { } else { profiler->StartProfiling(name, recordSamples); } + + struct sigaction sa, old_sa; + sa.sa_flags = SA_SIGINFO | SA_RESTART; + sa.sa_sigaction = &sighandler; + sigemptyset(&sa.sa_mask); + sigaction(SIGPROF, &sa, &old_sa); + + // At the end of a cycle start is called before stop, + // at this point old_sa.sa_sigaction is sighandler ! + if (!old_handler) { + old_handler = old_sa.sa_sigaction; + } + s_profiler = wallProfiler; } NAN_METHOD(WallProfiler::Stop) { @@ -307,6 +335,10 @@ NAN_MODULE_INIT(WallProfiler::Init) { tpl->SetClassName(className); tpl->InstanceTemplate()->SetInternalFieldCount(1); + Nan::SetAccessor(tpl->InstanceTemplate(), + Nan::New("labels").ToLocalChecked(), + GetLabels, SetLabels); + Nan::SetPrototypeMethod(tpl, "start", Start); Nan::SetPrototypeMethod(tpl, "dispose", Dispose); Nan::SetPrototypeMethod(tpl, "stop", Stop); @@ -329,4 +361,32 @@ v8::CpuProfiler* WallProfiler::GetProfiler() { return cpuProfiler; } +v8::Local WallProfiler::GetLabels() { + return Nan::Undefined(); +} + +void WallProfiler::SetLabels(v8::Local value) { + labels_ = std::make_shared(value); +} + +NAN_GETTER(WallProfiler::GetLabels) { + auto profiler = Nan::ObjectWrap::Unwrap(info.Holder()); + info.GetReturnValue().Set(profiler->GetLabels()); +} + +NAN_SETTER(WallProfiler::SetLabels) { + auto profiler = Nan::ObjectWrap::Unwrap(info.Holder()); + profiler->SetLabels(value); +} + +void WallProfiler::PushContext() { + // Be carefull this is called in a signal handler context + // therefore all operations must be async signal safe + // (in particular no allocations) + if (contexts_.size() < contexts_.capacity()) { + int64_t timestamp = 0; // need to figure out the timestamp + contexts_.push_back({labels_, timestamp}); + } +} + } // namespace dd diff --git a/bindings/profilers/wall.hh b/bindings/profilers/wall.hh index b79249f6..1444dbb5 100644 --- a/bindings/profilers/wall.hh +++ b/bindings/profilers/wall.hh @@ -2,6 +2,7 @@ #include #include +#include "../wrap.hh" namespace dd { @@ -9,6 +10,15 @@ class WallProfiler : public Nan::ObjectWrap { private: int samplingInterval = 0; v8::CpuProfiler* cpuProfiler = nullptr; + std::shared_ptr labels_; + + struct SampleContext { + std::shared_ptr labels; + int64_t timestamp; + }; + + std::vector contexts_; + ~WallProfiler(); void Dispose(); @@ -19,11 +29,18 @@ class WallProfiler : public Nan::ObjectWrap { public: explicit WallProfiler(int interval); + v8::Local GetLabels(); + void SetLabels(v8::Local); + + void PushContext(); + static NAN_METHOD(New); static NAN_METHOD(Dispose); static NAN_METHOD(Start); static NAN_METHOD(Stop); static NAN_MODULE_INIT(Init); + static NAN_GETTER(GetLabels); + static NAN_SETTER(SetLabels); }; } // namespace dd diff --git a/ts/src/index.ts b/ts/src/index.ts index 0e50f994..76a3370f 100644 --- a/ts/src/index.ts +++ b/ts/src/index.ts @@ -44,7 +44,7 @@ export const heap = { // If loaded with --require, start profiling. if (module.parent && module.parent.id === 'internal/preload') { - const stop = time.start(); + const {stop} = time.start(); process.on('exit', () => { // The process is going to terminate imminently. All work here needs to // be synchronous. diff --git a/ts/src/time-profiler.ts b/ts/src/time-profiler.ts index b129f9aa..271f09f5 100644 --- a/ts/src/time-profiler.ts +++ b/ts/src/time-profiler.ts @@ -45,7 +45,7 @@ export interface TimeProfilerOptions { } export async function profile(options: TimeProfilerOptions) { - const stop = start( + const {stop} = start( options.intervalMicros || DEFAULT_INTERVAL_MICROS, options.name, options.sourceMapper, @@ -68,7 +68,7 @@ export function start( ) { const profiler = new TimeProfiler(intervalMicros); let runName = start(); - return majorVersion < 16 ? stopOld : stop; + return { stop: majorVersion < 16 ? stopOld : stop, setLabels }; function start() { const runName = ensureRunName(name); @@ -103,4 +103,8 @@ export function start( if (!restart) profiler.dispose(); return serializeTimeProfile(result, intervalMicros, sourceMapper, true); } + + function setLabels(labels: any) { + profiler.labels = labels + } } diff --git a/ts/test/test-time-profiler.ts b/ts/test/test-time-profiler.ts index 0319c559..c58aa9a8 100644 --- a/ts/test/test-time-profiler.ts +++ b/ts/test/test-time-profiler.ts @@ -81,7 +81,7 @@ describe('Time Profiler', () => { }); it('should be able to restart when stopping', async () => { - const stop = time.start(PROFILE_OPTIONS.intervalMicros); + const {stop} = time.start(PROFILE_OPTIONS.intervalMicros); timeProfilerStub.start.resetHistory(); timeProfilerStub.stop.resetHistory(); timeProfilerStub.dispose.resetHistory(); From 03758737584adfe6f7fef2a90374f2a85c27a0cd Mon Sep 17 00:00:00 2001 From: Nicolas Savoire Date: Fri, 14 Apr 2023 11:56:57 +0200 Subject: [PATCH 02/27] typo --- bindings/profilers/wall.cc | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/bindings/profilers/wall.cc b/bindings/profilers/wall.cc index 5f085036..68a49192 100644 --- a/bindings/profilers/wall.cc +++ b/bindings/profilers/wall.cc @@ -380,7 +380,7 @@ NAN_SETTER(WallProfiler::SetLabels) { } void WallProfiler::PushContext() { - // Be carefull this is called in a signal handler context + // Be careful this is called in a signal handler context // therefore all operations must be async signal safe // (in particular no allocations) if (contexts_.size() < contexts_.capacity()) { From bd31776f64f583e868f9c2407a0f3c1bf605b89c Mon Sep 17 00:00:00 2001 From: Attila Szegedi Date: Wed, 19 Apr 2023 18:28:34 +0200 Subject: [PATCH 03/27] Initial code for code hotspots in wall profiler --- bindings/buffer.hh | 76 +++++++++++++ bindings/profilers/cpu.hh | 56 +--------- bindings/profilers/wall.cc | 202 ++++++++++++++++++++++++++++------- bindings/profilers/wall.hh | 37 ++++++- ts/src/profile-serializer.ts | 16 ++- ts/src/time-profiler.ts | 11 +- ts/src/v8-types.ts | 1 + 7 files changed, 298 insertions(+), 101 deletions(-) create mode 100644 bindings/buffer.hh diff --git a/bindings/buffer.hh b/bindings/buffer.hh new file mode 100644 index 00000000..a8c2887e --- /dev/null +++ b/bindings/buffer.hh @@ -0,0 +1,76 @@ +#pragma once + +namespace dd { +template +class RingBuffer { + public: + explicit RingBuffer(size_t size) + : buffer(std::make_unique(size)), + capacity_(size), + size_(0), + back_index_(0), + front_index_(0) {} + + bool full() const { return size_ == capacity_; } + bool empty() const { return size_ == 0; } + + T& front() { return buffer[front_index_]; } + + const T& front() const { return buffer[front_index_]; } + + void push_back(T t) { + if (full()) { + if (empty()) { + return; + } + // overwrite buffer head + buffer[back_index_] = std::move(t); + increment(back_index_); + // move buffer head + front_index_ = back_index_; + } else { + buffer[back_index_] = std::move(t); + increment(back_index_); + ++size_; + } + } + + void push_front(T t) { + if (full()) { + if (empty()) { + return; + } + // overwrite buffer head + decrement(front_index_); + buffer[front_index_] = std::move(t); + // move buffer head + back_index_ = front_index_; + } else { + decrement(front_index_); + buffer[front_index_] = std::move(t); + ++size_; + } + } + + T pop_front() { + auto idx = front_index_; + increment(front_index_); + --size_; + return std::move(buffer[idx]); + } + + private: + void increment(size_t& idx) const { + idx = idx + 1 == capacity_ ? 0 : idx + 1; + } + void decrement(size_t& idx) const { + idx = idx == 0 ? capacity_ - 1 : idx - 1; + } + + std::unique_ptr buffer; + size_t capacity_; + size_t size_; + size_t back_index_; + size_t front_index_; +}; +} // namespace dd diff --git a/bindings/profilers/cpu.hh b/bindings/profilers/cpu.hh index b915a432..9601fa49 100644 --- a/bindings/profilers/cpu.hh +++ b/bindings/profilers/cpu.hh @@ -7,6 +7,7 @@ #include #include +#include "../buffer.hh" #include "../code-map.hh" #include "../cpu-time.hh" #include "../sample.hh" @@ -14,59 +15,6 @@ namespace dd { -class SampleBuffer { - public: - using SamplePtr = std::unique_ptr; - - explicit SampleBuffer(size_t size) - : samples_(std::make_unique(size)), - capacity_(size), - size_(0), - back_index_(0), - front_index_(0) {} - - bool full() const { return size_ == capacity_; } - bool empty() const { return size_ == 0; } - - SamplePtr& front() { return samples_[front_index_]; } - - const SamplePtr& front() const { return samples_[front_index_]; } - - void push_back(SamplePtr ptr) { - if (full()) { - if (empty()) { - return; - } - // overwrite buffer head - samples_[back_index_] = std::move(ptr); - increment(back_index_); - // move buffer head - front_index_ = back_index_; - } else { - samples_[back_index_] = std::move(ptr); - increment(back_index_); - ++size_; - } - } - - SamplePtr pop_front() { - auto idx = front_index_; - increment(front_index_); - --size_; - return std::move(samples_[idx]); - } - - private: - void increment(size_t& idx) const { - idx = idx + 1 == capacity_ ? 0 : idx + 1; - } - std::unique_ptr samples_; - size_t capacity_; - size_t size_; - size_t back_index_; - size_t front_index_; -}; - class CpuProfiler : public Nan::ObjectWrap { friend class CodeMap; @@ -75,7 +23,7 @@ class CpuProfiler : public Nan::ObjectWrap { uv_async_t* async; std::shared_ptr code_map; CpuTime cpu_time; - SampleBuffer last_samples; + RingBuffer> last_samples; std::shared_ptr labels_; double frequency = 0; Nan::Global samples; diff --git a/bindings/profilers/wall.cc b/bindings/profilers/wall.cc index 68a49192..758eecde 100644 --- a/bindings/profilers/wall.cc +++ b/bindings/profilers/wall.cc @@ -31,10 +31,11 @@ namespace dd { // Should not be static but per isolate ? static WallProfiler* s_profiler; +static std::unordered_map> labelSetsByNode; -static void (*old_handler)(int, siginfo_t *, void *) = nullptr; +static void (*old_handler)(int, siginfo_t*, void*) = nullptr; -static void sighandler(int sig, siginfo_t *info, void * context) { +static void sighandler(int sig, siginfo_t* info, void* context) { if (s_profiler) { s_profiler->PushContext(); } @@ -43,6 +44,16 @@ static void sighandler(int sig, siginfo_t *info, void * context) { } } +Local getLabelSetsForNode(const CpuProfileNode* node) { + auto it = labelSetsByNode.find(node); + if (it != labelSetsByNode.end()) { + auto retval = it->second; + labelSetsByNode.erase(it); + return retval; + } else { + return Nan::New(0); + } +} Local CreateTimeNode(Local name, Local scriptName, @@ -50,7 +61,8 @@ Local CreateTimeNode(Local name, Local lineNumber, Local columnNumber, Local hitCount, - Local children) { + Local children, + Local labelSets) { Local js_node = Nan::New(); Nan::Set(js_node, Nan::New("name").ToLocalChecked(), name); Nan::Set( @@ -62,6 +74,7 @@ Local CreateTimeNode(Local name, js_node, Nan::New("columnNumber").ToLocalChecked(), columnNumber); Nan::Set(js_node, Nan::New("hitCount").ToLocalChecked(), hitCount); Nan::Set(js_node, Nan::New("children").ToLocalChecked(), children); + Nan::Set(js_node, Nan::New("labelSets").ToLocalChecked(), labelSets); return js_node; } @@ -69,14 +82,14 @@ Local CreateTimeNode(Local name, Local TranslateLineNumbersTimeProfileNode(const CpuProfileNode* parent, const CpuProfileNode* node); -Local GetLineNumberTimeProfileChildren(const CpuProfileNode* parent, - const CpuProfileNode* node) { +Local GetLineNumberTimeProfileChildren(const CpuProfileNode* node) { unsigned int index = 0; Local children; int32_t count = node->GetChildrenCount(); unsigned int hitLineCount = node->GetHitLineCount(); unsigned int hitCount = node->GetHitCount(); + auto labelSets = getLabelSetsForNode(node); if (hitLineCount > 0) { std::vector entries(hitLineCount); node->GetLineTicks(&entries[0], hitLineCount); @@ -90,7 +103,8 @@ Local GetLineNumberTimeProfileChildren(const CpuProfileNode* parent, Nan::New(entry.line), Nan::New(0), Nan::New(entry.hit_count), - Nan::New(0))); + Nan::New(0), + labelSets)); } } else if (hitCount > 0) { // Handle nodes for pseudo-functions like "process" and "garbage collection" @@ -104,7 +118,8 @@ Local GetLineNumberTimeProfileChildren(const CpuProfileNode* parent, Nan::New(node->GetLineNumber()), Nan::New(node->GetColumnNumber()), Nan::New(hitCount), - Nan::New(0))); + Nan::New(0), + labelSets)); } else { children = Nan::New(count); } @@ -126,7 +141,8 @@ Local TranslateLineNumbersTimeProfileNode(const CpuProfileNode* parent, Nan::New(node->GetLineNumber()), Nan::New(node->GetColumnNumber()), Nan::New(0), - GetLineNumberTimeProfileChildren(parent, node)); + GetLineNumberTimeProfileChildren(node), + getLabelSetsForNode(node)); } // In profiles with line level accurate line numbers, a node's line number @@ -137,7 +153,7 @@ Local TranslateLineNumbersTimeProfileRoot(const CpuProfileNode* node) { std::vector> childrenArrs(count); int32_t childCount = 0; for (int32_t i = 0; i < count; i++) { - Local c = GetLineNumberTimeProfileChildren(node, node->GetChild(i)); + Local c = GetLineNumberTimeProfileChildren(node->GetChild(i)); childCount = childCount + c->Length(); childrenArrs[i] = c; } @@ -158,7 +174,8 @@ Local TranslateLineNumbersTimeProfileRoot(const CpuProfileNode* node) { Nan::New(node->GetLineNumber()), Nan::New(node->GetColumnNumber()), Nan::New(0), - children); + children, + getLabelSetsForNode(node)); } Local TranslateTimeProfileNode(const CpuProfileNode* node) { @@ -174,7 +191,8 @@ Local TranslateTimeProfileNode(const CpuProfileNode* node) { Nan::New(node->GetLineNumber()), Nan::New(node->GetColumnNumber()), Nan::New(node->GetHitCount()), - children); + children, + getLabelSetsForNode(node)); } Local TranslateTimeProfile(const CpuProfile* profile, @@ -205,10 +223,84 @@ Local TranslateTimeProfile(const CpuProfile* profile, Nan::Set(js_profile, Nan::New("endTime").ToLocalChecked(), Nan::New(profile->GetEndTime())); + return js_profile; } -WallProfiler::WallProfiler(int interval) : samplingInterval(interval) {} +bool isIdleSample(const CpuProfileNode* sample) { + return +#if NODE_MODULE_VERSION > NODE_12_0_MODULE_VERSION + sample->GetParent() == nullptr && +#endif + sample->GetChildrenCount() == 0 && + strncmp("(idle)", sample->GetFunctionNameStr(), 7) == 0; +} + +void WallProfiler::AddLabelSetsByNode(CpuProfile* profile) { + auto halfInterval = samplingInterval * 1000 / 2; + + if (contexts.empty()) { + return; + } + SampleContext sampleContext = contexts.pop_front(); + + uint64_t time_diff = last_start - profile->GetStartTime() * 1000; + + for (int i = 0; i < profile->GetSamplesCount(); i++) { + auto sample = profile->GetSample(i); + if (isIdleSample(sample)) { + continue; + } + + // Translate from profiler micros to uv_hrtime nanos + auto sampleTimestamp = profile->GetSampleTimestamp(i) * 1000 + time_diff; + + // This loop will drop all contexts that are too old to be associated with + // the current sample; associate those (normally one) that are close enough + // to it in time, and stop as soon as it sees a context that's too recent + // for this sample. + for (;;) { + auto contextTimestamp = sampleContext.timestamp; + if (contextTimestamp < sampleTimestamp - halfInterval) { + // Current sample context is too old, discard it and fetch the next one + if (contexts.empty()) { + return; + } + sampleContext = contexts.pop_front(); + } else if (contextTimestamp >= sampleTimestamp + halfInterval) { + // Current sample context is too recent, we'll try to match it to the + // next sample + break; + } else { + // This context timestamp is in the goldilocks zone around the sample + // timestamp, so associate its labels with the sample. + auto it = labelSetsByNode.find(sample); + Local array; + if (it == labelSetsByNode.end()) { + array = Nan::New(); + labelSetsByNode.emplace(sample, array); + } else { + array = it->second; + } + Nan::Set(array, array->Length(), sampleContext.labels.get()->handle()); + // Sample context was consumed, fetch the next one + if (contexts.empty()) { + return; + } + sampleContext = contexts.pop_front(); + } + } + } + // Push the last popped sample context back into the ring to be used by the + // next profile + contexts.push_front(std::move(sampleContext)); +} + +static Nan::Persistent constructor; + +WallProfiler::WallProfiler(int intervalMicros, int durationMicros) + : samplingInterval(intervalMicros), + contexts(durationMicros * 2 / intervalMicros) {} WallProfiler::~WallProfiler() { Dispose(); @@ -229,19 +321,36 @@ NAN_METHOD(WallProfiler::Dispose) { } NAN_METHOD(WallProfiler::New) { - if (info.Length() != 1) { - return Nan::ThrowTypeError("WallProfiler must have one argument."); + if (info.Length() != 2) { + return Nan::ThrowTypeError("WallProfiler must have two arguments."); } if (!info[0]->IsNumber()) { return Nan::ThrowTypeError("Sample rate must be a number."); } + if (!info[0]->IsNumber()) { + return Nan::ThrowTypeError("Duration must be a number."); + } + if (info.IsConstructCall()) { int interval = Nan::MaybeLocal(info[0].As()) .ToLocalChecked() ->Value(); + int duration = Nan::MaybeLocal(info[1].As()) + .ToLocalChecked() + ->Value(); - WallProfiler* obj = new WallProfiler(interval); + if (interval <= 0) { + return Nan::ThrowTypeError("Sample rate must be positive."); + } + if (duration <= 0) { + return Nan::ThrowTypeError("Duration must be positive."); + } + if (duration < interval) { + return Nan::ThrowTypeError("Duration must not be less than sample rate."); + } + + WallProfiler* obj = new WallProfiler(interval, duration); obj->Wrap(info.This()); info.GetReturnValue().Set(info.This()); } else { @@ -274,18 +383,7 @@ NAN_METHOD(WallProfiler::Start) { bool includeLines = Nan::MaybeLocal(info[1].As()).ToLocalChecked()->Value(); - auto profiler = wallProfiler->GetProfiler(); - - // Sample counts and timestamps are not used, so we do not need to record - // samples. - const bool recordSamples = true; - - if (includeLines) { - profiler->StartProfiling( - name, CpuProfilingMode::kCallerLineNumbers, recordSamples); - } else { - profiler->StartProfiling(name, recordSamples); - } + wallProfiler->StartImpl(name, includeLines); struct sigaction sa, old_sa; sa.sa_flags = SA_SIGINFO | SA_RESTART; @@ -301,10 +399,19 @@ NAN_METHOD(WallProfiler::Start) { s_profiler = wallProfiler; } -NAN_METHOD(WallProfiler::Stop) { - WallProfiler* wallProfiler = - Nan::ObjectWrap::Unwrap(info.Holder()); +void WallProfiler::StartImpl(Local name, bool includeLines) { + if (includeLines) { + GetProfiler()->StartProfiling( + name, CpuProfilingMode::kCallerLineNumbers, true); + } else { + GetProfiler()->StartProfiling(name, true); + } + + last_start = current_start; + current_start = uv_hrtime(); +} +NAN_METHOD(WallProfiler::Stop) { if (info.Length() != 2) { return Nan::ThrowTypeError("Start must have two arguments."); } @@ -321,8 +428,12 @@ NAN_METHOD(WallProfiler::Stop) { bool includeLines = Nan::MaybeLocal(info[1].As()).ToLocalChecked()->Value(); + WallProfiler* wallProfiler = + Nan::ObjectWrap::Unwrap(info.Holder()); + auto profiler = wallProfiler->GetProfiler(); auto v8_profile = profiler->StopProfiling(name); + wallProfiler->AddLabelSetsByNode(v8_profile); Local profile = TranslateTimeProfile(v8_profile, includeLines); v8_profile->Delete(); @@ -335,13 +446,15 @@ NAN_MODULE_INIT(WallProfiler::Init) { tpl->SetClassName(className); tpl->InstanceTemplate()->SetInternalFieldCount(1); - Nan::SetAccessor(tpl->InstanceTemplate(), - Nan::New("labels").ToLocalChecked(), - GetLabels, SetLabels); + Nan::SetAccessor(tpl->InstanceTemplate(), + Nan::New("labels").ToLocalChecked(), + GetLabels, + SetLabels); Nan::SetPrototypeMethod(tpl, "start", Start); Nan::SetPrototypeMethod(tpl, "dispose", Dispose); Nan::SetPrototypeMethod(tpl, "stop", Stop); + Nan::SetPrototypeMethod(tpl, "unsetLabels", UnsetLabels); PerIsolateData::For(Isolate::GetCurrent()) ->WallProfilerConstructor() @@ -362,13 +475,18 @@ v8::CpuProfiler* WallProfiler::GetProfiler() { } v8::Local WallProfiler::GetLabels() { - return Nan::Undefined(); + if (!labels_) return Nan::Undefined(); + return labels_->handle(); } void WallProfiler::SetLabels(v8::Local value) { labels_ = std::make_shared(value); } +void WallProfiler::UnsetLabels() { + labels_.reset(); +} + NAN_GETTER(WallProfiler::GetLabels) { auto profiler = Nan::ObjectWrap::Unwrap(info.Holder()); info.GetReturnValue().Set(profiler->GetLabels()); @@ -379,13 +497,17 @@ NAN_SETTER(WallProfiler::SetLabels) { profiler->SetLabels(value); } +NAN_METHOD(WallProfiler::UnsetLabels) { + auto profiler = Nan::ObjectWrap::Unwrap(info.Holder()); + profiler->UnsetLabels(); +} + void WallProfiler::PushContext() { - // Be careful this is called in a signal handler context - // therefore all operations must be async signal safe - // (in particular no allocations) - if (contexts_.size() < contexts_.capacity()) { - int64_t timestamp = 0; // need to figure out the timestamp - contexts_.push_back({labels_, timestamp}); + // Be careful this is called in a signal handler context therefore all + // operations must be async signal safe (in particular no allocations). Our + // ring buffer avoids allocations. + if (labels_) { + contexts.push_back(SampleContext(labels_, uv_hrtime())); } } diff --git a/bindings/profilers/wall.hh b/bindings/profilers/wall.hh index 1444dbb5..77c43675 100644 --- a/bindings/profilers/wall.hh +++ b/bindings/profilers/wall.hh @@ -2,6 +2,7 @@ #include #include +#include "../buffer.hh" #include "../wrap.hh" namespace dd { @@ -14,10 +15,29 @@ class WallProfiler : public Nan::ObjectWrap { struct SampleContext { std::shared_ptr labels; - int64_t timestamp; + uint64_t timestamp; + + // Needed to initialize ring buffer elements + SampleContext() {} + + SampleContext(std::shared_ptr l, uint64_t t) + : labels(l), timestamp(t) {} + + SampleContext(SampleContext&& rval) { + labels = std::move(rval.labels); + timestamp = rval.timestamp; + } + + SampleContext& operator=(SampleContext&& rval) { + labels = std::move(rval.labels); + timestamp = rval.timestamp; + return *this; + } }; - std::vector contexts_; + RingBuffer contexts; + uint64_t current_start; // start of current profiling run + uint64_t last_start; // start of last profiling run ~WallProfiler(); void Dispose(); @@ -27,17 +47,28 @@ class WallProfiler : public Nan::ObjectWrap { v8::CpuProfiler* GetProfiler(); public: - explicit WallProfiler(int interval); + /** + * @param intervalMicros sampling interval, in microseconds + * @param durationMicros the duration of sampling, in microseconds. This + * parameter is informative; it is up to the caller to call the Stop method + * every period. The parameter is used to preallocate data structures that + * should not be reallocated in async signal safe code. + */ + explicit WallProfiler(int intervalMicros, int durationMicros); v8::Local GetLabels(); void SetLabels(v8::Local); + void UnsetLabels(); void PushContext(); + void StartImpl(v8::Local name, bool includeLines); + void AddLabelSetsByNode(v8::CpuProfile* profile); static NAN_METHOD(New); static NAN_METHOD(Dispose); static NAN_METHOD(Start); static NAN_METHOD(Stop); + static NAN_METHOD(UnsetLabels); static NAN_MODULE_INIT(Init); static NAN_GETTER(GetLabels); static NAN_SETTER(SetLabels); diff --git a/ts/src/profile-serializer.ts b/ts/src/profile-serializer.ts index 749897b4..d177be88 100644 --- a/ts/src/profile-serializer.ts +++ b/ts/src/profile-serializer.ts @@ -299,10 +299,22 @@ export function serializeTimeProfile( entry: Entry, samples: Sample[] ) => { - if (entry.node.hitCount > 0) { + let unlabelledHits = entry.node.hitCount; + for (const labelSet of entry.node.labelSets || []) { + if (Object.keys(labelSet).length > 0) { + const sample = new Sample({ + locationId: entry.stack, + value: [1, intervalNanos], + label: buildLabels(labelSet, stringTable), + }); + samples.push(sample); + unlabelledHits--; + } + } + if (unlabelledHits > 0) { const sample = new Sample({ locationId: entry.stack, - value: [entry.node.hitCount, entry.node.hitCount * intervalNanos], + value: [unlabelledHits, unlabelledHits * intervalNanos], }); samples.push(sample); } diff --git a/ts/src/time-profiler.ts b/ts/src/time-profiler.ts index 271f09f5..25146c21 100644 --- a/ts/src/time-profiler.ts +++ b/ts/src/time-profiler.ts @@ -21,6 +21,7 @@ import {SourceMapper} from './sourcemapper/sourcemapper'; import {TimeProfiler} from './time-profiler-bindings'; const DEFAULT_INTERVAL_MICROS: Microseconds = 1000; +const DEFAULT_DURATION_MILLIS: Milliseconds = 60000; const majorVersion = process.version.slice(1).split('.').map(Number)[0]; @@ -47,6 +48,7 @@ export interface TimeProfilerOptions { export async function profile(options: TimeProfilerOptions) { const {stop} = start( options.intervalMicros || DEFAULT_INTERVAL_MICROS, + options.durationMillis, options.name, options.sourceMapper, options.lineNumbers @@ -62,13 +64,14 @@ function ensureRunName(name?: string) { // NOTE: refreshing doesn't work if giving a profile name. export function start( intervalMicros: Microseconds = DEFAULT_INTERVAL_MICROS, + durationMillis: Milliseconds = DEFAULT_DURATION_MILLIS, name?: string, sourceMapper?: SourceMapper, lineNumbers = true ) { - const profiler = new TimeProfiler(intervalMicros); + const profiler = new TimeProfiler(intervalMicros, durationMillis * 1000); let runName = start(); - return { stop: majorVersion < 16 ? stopOld : stop, setLabels }; + return { stop: majorVersion < 16 ? stopOld : stop, setLabels, unsetLabels } function start() { const runName = ensureRunName(name); @@ -107,4 +110,8 @@ export function start( function setLabels(labels: any) { profiler.labels = labels } + + function unsetLabels() { + profiler.unsetLabels(); + } } diff --git a/ts/src/v8-types.ts b/ts/src/v8-types.ts index 4eef4885..2763ca13 100644 --- a/ts/src/v8-types.ts +++ b/ts/src/v8-types.ts @@ -36,6 +36,7 @@ export interface ProfileNode { export interface TimeProfileNode extends ProfileNode { hitCount: number; + labelSets?: LabelSet[]; // TODO: use LabelsCpu later } export interface AllocationProfileNode extends ProfileNode { From f02e78167d086829c79055cbe37eae5d74842c5d Mon Sep 17 00:00:00 2001 From: Attila Szegedi Date: Mon, 8 May 2023 17:26:33 +0200 Subject: [PATCH 04/27] Maintain profilers per isolate, in a copy-on-write style map --- bindings/profilers/wall.cc | 57 ++++++++++++++++++++++++++++++++------ bindings/profilers/wall.hh | 2 +- 2 files changed, 50 insertions(+), 9 deletions(-) diff --git a/bindings/profilers/wall.cc b/bindings/profilers/wall.cc index 758eecde..f093f24a 100644 --- a/bindings/profilers/wall.cc +++ b/bindings/profilers/wall.cc @@ -14,6 +14,7 @@ * limitations under the License. */ +#include #include #include #include @@ -29,16 +30,21 @@ using namespace v8; namespace dd { -// Should not be static but per isolate ? -static WallProfiler* s_profiler; +using ProfilerMap = std::unordered_map; + +static std::atomic profilers(new ProfilerMap()); + static std::unordered_map> labelSetsByNode; static void (*old_handler)(int, siginfo_t*, void*) = nullptr; static void sighandler(int sig, siginfo_t* info, void* context) { - if (s_profiler) { - s_profiler->PushContext(); + auto prof_map = profilers.load(); + auto prof_it = prof_map->find(Isolate::GetCurrent()); + if (prof_it != prof_map->end()) { + prof_it->second->PushContext(); } + if (old_handler) { old_handler(sig, info, context); } @@ -303,13 +309,46 @@ WallProfiler::WallProfiler(int intervalMicros, int durationMicros) contexts(durationMicros * 2 / intervalMicros) {} WallProfiler::~WallProfiler() { - Dispose(); + Dispose(nullptr); +} + +template +void updateProfilers(F updateFn) { + auto currProfilers = profilers.load(); + for (;;) { + auto newProfilers = new ProfilerMap(*currProfilers); + updateFn(newProfilers); + if (profilers.compare_exchange_weak(currProfilers, newProfilers)) { + delete currProfilers; + break; + } else { + delete newProfilers; + } + } } -void WallProfiler::Dispose() { +void WallProfiler::Dispose(Isolate* isolate) { if (cpuProfiler != nullptr) { cpuProfiler->Dispose(); cpuProfiler = nullptr; + + updateProfilers([isolate, this](auto map) { + if (isolate != nullptr) { + auto it = map->find(isolate); + if (it != map->end() && it->second == this) { + map->erase(it); + } + } else { + // TODO: use map->erase_if once we can use C++20. + for (auto it = map->begin(), last = map->end(); it != last;) { + if (it->second == this) { + it = map->erase(it); + } else { + ++it; + } + } + } + }); } } @@ -317,7 +356,7 @@ NAN_METHOD(WallProfiler::Dispose) { WallProfiler* wallProfiler = Nan::ObjectWrap::Unwrap(info.Holder()); - wallProfiler->Dispose(); + wallProfiler->Dispose(info.GetIsolate()); } NAN_METHOD(WallProfiler::New) { @@ -396,7 +435,6 @@ NAN_METHOD(WallProfiler::Start) { if (!old_handler) { old_handler = old_sa.sa_sigaction; } - s_profiler = wallProfiler; } void WallProfiler::StartImpl(Local name, bool includeLines) { @@ -468,6 +506,9 @@ NAN_MODULE_INIT(WallProfiler::Init) { v8::CpuProfiler* WallProfiler::GetProfiler() { if (cpuProfiler == nullptr) { v8::Isolate* isolate = v8::Isolate::GetCurrent(); + + updateProfilers([isolate, this](auto map) { map->emplace(isolate, this); }); + cpuProfiler = v8::CpuProfiler::New(isolate); cpuProfiler->SetSamplingInterval(samplingInterval); } diff --git a/bindings/profilers/wall.hh b/bindings/profilers/wall.hh index 77c43675..1bc0cb63 100644 --- a/bindings/profilers/wall.hh +++ b/bindings/profilers/wall.hh @@ -40,7 +40,7 @@ class WallProfiler : public Nan::ObjectWrap { uint64_t last_start; // start of last profiling run ~WallProfiler(); - void Dispose(); + void Dispose(v8::Isolate* isolate); // A new CPU profiler object will be created each time profiling is started // to work around https://bugs.chromium.org/p/v8/issues/detail?id=11051. From f508a2d301dfb31cdbb3cebb6ebe205bfb551144 Mon Sep 17 00:00:00 2001 From: Attila Szegedi Date: Thu, 11 May 2023 15:33:30 +0200 Subject: [PATCH 05/27] Make labelSetsByNode per-profiler --- bindings/profilers/wall.cc | 34 ++++++++++++++++++++-------------- bindings/profilers/wall.hh | 19 ++++++++++++++++++- 2 files changed, 38 insertions(+), 15 deletions(-) diff --git a/bindings/profilers/wall.cc b/bindings/profilers/wall.cc index f093f24a..9a95cdb2 100644 --- a/bindings/profilers/wall.cc +++ b/bindings/profilers/wall.cc @@ -34,8 +34,6 @@ using ProfilerMap = std::unordered_map; static std::atomic profilers(new ProfilerMap()); -static std::unordered_map> labelSetsByNode; - static void (*old_handler)(int, siginfo_t*, void*) = nullptr; static void sighandler(int sig, siginfo_t* info, void* context) { @@ -50,7 +48,7 @@ static void sighandler(int sig, siginfo_t* info, void* context) { } } -Local getLabelSetsForNode(const CpuProfileNode* node) { +Local WallProfiler::getLabelSetsForNode(const CpuProfileNode* node) { auto it = labelSetsByNode.find(node); if (it != labelSetsByNode.end()) { auto retval = it->second; @@ -88,7 +86,8 @@ Local CreateTimeNode(Local name, Local TranslateLineNumbersTimeProfileNode(const CpuProfileNode* parent, const CpuProfileNode* node); -Local GetLineNumberTimeProfileChildren(const CpuProfileNode* node) { +Local WallProfiler::GetLineNumberTimeProfileChildren( + const CpuProfileNode* node) { unsigned int index = 0; Local children; int32_t count = node->GetChildrenCount(); @@ -139,8 +138,8 @@ Local GetLineNumberTimeProfileChildren(const CpuProfileNode* node) { return children; } -Local TranslateLineNumbersTimeProfileNode(const CpuProfileNode* parent, - const CpuProfileNode* node) { +Local WallProfiler::TranslateLineNumbersTimeProfileNode( + const CpuProfileNode* parent, const CpuProfileNode* node) { return CreateTimeNode(parent->GetFunctionName(), parent->GetScriptResourceName(), Nan::New(parent->GetScriptId()), @@ -154,7 +153,8 @@ Local TranslateLineNumbersTimeProfileNode(const CpuProfileNode* parent, // In profiles with line level accurate line numbers, a node's line number // and column number refer to the line/column from which the function was // called. -Local TranslateLineNumbersTimeProfileRoot(const CpuProfileNode* node) { +Local WallProfiler::TranslateLineNumbersTimeProfileRoot( + const CpuProfileNode* node) { int32_t count = node->GetChildrenCount(); std::vector> childrenArrs(count); int32_t childCount = 0; @@ -184,7 +184,8 @@ Local TranslateLineNumbersTimeProfileRoot(const CpuProfileNode* node) { getLabelSetsForNode(node)); } -Local TranslateTimeProfileNode(const CpuProfileNode* node) { +Local WallProfiler::TranslateTimeProfileNode( + const CpuProfileNode* node) { int32_t count = node->GetChildrenCount(); Local children = Nan::New(count); for (int32_t i = 0; i < count; i++) { @@ -201,8 +202,8 @@ Local TranslateTimeProfileNode(const CpuProfileNode* node) { getLabelSetsForNode(node)); } -Local TranslateTimeProfile(const CpuProfile* profile, - bool includeLineInfo) { +Local WallProfiler::TranslateTimeProfile(const CpuProfile* profile, + bool includeLineInfo) { Local js_profile = Nan::New(); Nan::Set(js_profile, Nan::New("title").ToLocalChecked(), @@ -469,13 +470,18 @@ NAN_METHOD(WallProfiler::Stop) { WallProfiler* wallProfiler = Nan::ObjectWrap::Unwrap(info.Holder()); - auto profiler = wallProfiler->GetProfiler(); + auto profile = wallProfiler->StopImpl(name, includeLines); + + info.GetReturnValue().Set(profile); +} + +Local WallProfiler::StopImpl(Local name, bool includeLines) { + auto profiler = GetProfiler(); auto v8_profile = profiler->StopProfiling(name); - wallProfiler->AddLabelSetsByNode(v8_profile); + AddLabelSetsByNode(v8_profile); Local profile = TranslateTimeProfile(v8_profile, includeLines); v8_profile->Delete(); - - info.GetReturnValue().Set(profile); + return profile; } NAN_MODULE_INIT(WallProfiler::Init) { diff --git a/bindings/profilers/wall.hh b/bindings/profilers/wall.hh index 1bc0cb63..a6a8617d 100644 --- a/bindings/profilers/wall.hh +++ b/bindings/profilers/wall.hh @@ -2,6 +2,8 @@ #include #include +#include + #include "../buffer.hh" #include "../wrap.hh" @@ -12,6 +14,8 @@ class WallProfiler : public Nan::ObjectWrap { int samplingInterval = 0; v8::CpuProfiler* cpuProfiler = nullptr; std::shared_ptr labels_; + std::unordered_map> + labelSetsByNode; struct SampleContext { std::shared_ptr labels; @@ -46,6 +50,19 @@ class WallProfiler : public Nan::ObjectWrap { // to work around https://bugs.chromium.org/p/v8/issues/detail?id=11051. v8::CpuProfiler* GetProfiler(); + void AddLabelSetsByNode(v8::CpuProfile* profile); + v8::Local getLabelSetsForNode(const v8::CpuProfileNode* node); + v8::Local GetLineNumberTimeProfileChildren( + const v8::CpuProfileNode* node); + v8::Local TranslateLineNumbersTimeProfileNode( + const v8::CpuProfileNode* parent, const v8::CpuProfileNode* node); + v8::Local TranslateLineNumbersTimeProfileRoot( + const v8::CpuProfileNode* node); + v8::Local TranslateTimeProfileNode(const v8::CpuProfileNode* node); + // TODO: get rid of includeLineInfo + v8::Local TranslateTimeProfile(const v8::CpuProfile* profile, + bool includeLineInfo); + public: /** * @param intervalMicros sampling interval, in microseconds @@ -62,7 +79,7 @@ class WallProfiler : public Nan::ObjectWrap { void PushContext(); void StartImpl(v8::Local name, bool includeLines); - void AddLabelSetsByNode(v8::CpuProfile* profile); + v8::Local StopImpl(v8::Local name, bool includeLines); static NAN_METHOD(New); static NAN_METHOD(Dispose); From 221eecbdffef1ac77c4ba1316abe148d9224b0e8 Mon Sep 17 00:00:00 2001 From: Attila Szegedi Date: Mon, 15 May 2023 11:03:35 +0200 Subject: [PATCH 06/27] add labelsCaptured property that can be used to detect profiling sample with labels was taken --- bindings/profilers/wall.cc | 10 ++++++++++ bindings/profilers/wall.hh | 7 +++++++ ts/src/time-profiler.ts | 7 ++++++- 3 files changed, 23 insertions(+), 1 deletion(-) diff --git a/bindings/profilers/wall.cc b/bindings/profilers/wall.cc index 9a95cdb2..0d66bb3f 100644 --- a/bindings/profilers/wall.cc +++ b/bindings/profilers/wall.cc @@ -495,6 +495,10 @@ NAN_MODULE_INIT(WallProfiler::Init) { GetLabels, SetLabels); + Nan::SetAccessor(tpl->InstanceTemplate(), + Nan::New("labelsCaptured").ToLocalChecked(), + GetLabelsCaptured); + Nan::SetPrototypeMethod(tpl, "start", Start); Nan::SetPrototypeMethod(tpl, "dispose", Dispose); Nan::SetPrototypeMethod(tpl, "stop", Stop); @@ -549,12 +553,18 @@ NAN_METHOD(WallProfiler::UnsetLabels) { profiler->UnsetLabels(); } +NAN_GETTER(WallProfiler::GetLabelsCaptured) { + auto profiler = Nan::ObjectWrap::Unwrap(info.Holder()); + info.GetReturnValue().Set(profiler->GetLabelsCaptured()); +} + void WallProfiler::PushContext() { // Be careful this is called in a signal handler context therefore all // operations must be async signal safe (in particular no allocations). Our // ring buffer avoids allocations. if (labels_) { contexts.push_back(SampleContext(labels_, uv_hrtime())); + labelsCaptured = true; } } diff --git a/bindings/profilers/wall.hh b/bindings/profilers/wall.hh index a6a8617d..7c4d87b4 100644 --- a/bindings/profilers/wall.hh +++ b/bindings/profilers/wall.hh @@ -16,6 +16,7 @@ class WallProfiler : public Nan::ObjectWrap { std::shared_ptr labels_; std::unordered_map> labelSetsByNode; + bool labelsCaptured = false; struct SampleContext { std::shared_ptr labels; @@ -74,6 +75,11 @@ class WallProfiler : public Nan::ObjectWrap { explicit WallProfiler(int intervalMicros, int durationMicros); v8::Local GetLabels(); + bool GetLabelsCaptured() { + bool captured = labelsCaptured; + labelsCaptured = false; + return captured; + } void SetLabels(v8::Local); void UnsetLabels(); @@ -89,6 +95,7 @@ class WallProfiler : public Nan::ObjectWrap { static NAN_MODULE_INIT(Init); static NAN_GETTER(GetLabels); static NAN_SETTER(SetLabels); + static NAN_GETTER(GetLabelsCaptured); }; } // namespace dd diff --git a/ts/src/time-profiler.ts b/ts/src/time-profiler.ts index 25146c21..2b106cf6 100644 --- a/ts/src/time-profiler.ts +++ b/ts/src/time-profiler.ts @@ -71,7 +71,7 @@ export function start( ) { const profiler = new TimeProfiler(intervalMicros, durationMillis * 1000); let runName = start(); - return { stop: majorVersion < 16 ? stopOld : stop, setLabels, unsetLabels } + return { stop: majorVersion < 16 ? stopOld : stop, setLabels, unsetLabels, labelsCaptured } function start() { const runName = ensureRunName(name); @@ -113,5 +113,10 @@ export function start( function unsetLabels() { profiler.unsetLabels(); + + } + + function labelsCaptured() { + return profiler.labelsCaptured; } } From 71f4c4ffc726a876c323946e48a5d717842f9718 Mon Sep 17 00:00:00 2001 From: Attila Szegedi Date: Mon, 15 May 2023 15:45:26 +0200 Subject: [PATCH 07/27] Linting --- ts/src/time-profiler.ts | 13 +++++++++---- 1 file changed, 9 insertions(+), 4 deletions(-) diff --git a/ts/src/time-profiler.ts b/ts/src/time-profiler.ts index 2b106cf6..023df39e 100644 --- a/ts/src/time-profiler.ts +++ b/ts/src/time-profiler.ts @@ -19,6 +19,7 @@ import delay from 'delay'; import {serializeTimeProfile} from './profile-serializer'; import {SourceMapper} from './sourcemapper/sourcemapper'; import {TimeProfiler} from './time-profiler-bindings'; +import {LabelSet} from './v8-types'; const DEFAULT_INTERVAL_MICROS: Microseconds = 1000; const DEFAULT_DURATION_MILLIS: Milliseconds = 60000; @@ -71,7 +72,12 @@ export function start( ) { const profiler = new TimeProfiler(intervalMicros, durationMillis * 1000); let runName = start(); - return { stop: majorVersion < 16 ? stopOld : stop, setLabels, unsetLabels, labelsCaptured } + return { + stop: majorVersion < 16 ? stopOld : stop, + setLabels, + unsetLabels, + labelsCaptured, + }; function start() { const runName = ensureRunName(name); @@ -107,13 +113,12 @@ export function start( return serializeTimeProfile(result, intervalMicros, sourceMapper, true); } - function setLabels(labels: any) { - profiler.labels = labels + function setLabels(labels: LabelSet) { + profiler.labels = labels; } function unsetLabels() { profiler.unsetLabels(); - } function labelsCaptured() { From e28aaa2d4a656661363b529b681a9499fd6dc5f4 Mon Sep 17 00:00:00 2001 From: Attila Szegedi Date: Tue, 16 May 2023 14:26:02 +0200 Subject: [PATCH 08/27] Disable signal code on Windows --- bindings/profilers/wall.cc | 10 ++++++++++ 1 file changed, 10 insertions(+) diff --git a/bindings/profilers/wall.cc b/bindings/profilers/wall.cc index 0d66bb3f..e22a6574 100644 --- a/bindings/profilers/wall.cc +++ b/bindings/profilers/wall.cc @@ -26,6 +26,12 @@ #include "../per-isolate-data.hh" #include "wall.hh" +#ifndef _WIN32 +#define DD_WALL_USE_SIGPROF +#else +#undef DD_WALL_USE_SIGPROF +#endif + using namespace v8; namespace dd { @@ -34,6 +40,7 @@ using ProfilerMap = std::unordered_map; static std::atomic profilers(new ProfilerMap()); +#ifdef DD_WALL_USE_SIGPROF static void (*old_handler)(int, siginfo_t*, void*) = nullptr; static void sighandler(int sig, siginfo_t* info, void* context) { @@ -47,6 +54,7 @@ static void sighandler(int sig, siginfo_t* info, void* context) { old_handler(sig, info, context); } } +#endif Local WallProfiler::getLabelSetsForNode(const CpuProfileNode* node) { auto it = labelSetsByNode.find(node); @@ -425,6 +433,7 @@ NAN_METHOD(WallProfiler::Start) { wallProfiler->StartImpl(name, includeLines); +#ifdef DD_WALL_USE_SIGPROF struct sigaction sa, old_sa; sa.sa_flags = SA_SIGINFO | SA_RESTART; sa.sa_sigaction = &sighandler; @@ -436,6 +445,7 @@ NAN_METHOD(WallProfiler::Start) { if (!old_handler) { old_handler = old_sa.sa_sigaction; } +#endif } void WallProfiler::StartImpl(Local name, bool includeLines) { From 0a10aa933ff7a5afa4ad2c5bd6a6514da4f93da6 Mon Sep 17 00:00:00 2001 From: Attila Szegedi Date: Fri, 19 May 2023 12:25:40 +0200 Subject: [PATCH 09/27] Don't use LabelWrap --- bindings/profilers/wall.cc | 19 +++++++++++-------- bindings/profilers/wall.hh | 13 ++++++------- 2 files changed, 17 insertions(+), 15 deletions(-) diff --git a/bindings/profilers/wall.cc b/bindings/profilers/wall.cc index e22a6574..43a1c23f 100644 --- a/bindings/profilers/wall.cc +++ b/bindings/profilers/wall.cc @@ -257,6 +257,8 @@ void WallProfiler::AddLabelSetsByNode(CpuProfile* profile) { if (contexts.empty()) { return; } + auto isolate = Isolate::GetCurrent(); + SampleContext sampleContext = contexts.pop_front(); uint64_t time_diff = last_start - profile->GetStartTime() * 1000; @@ -297,7 +299,8 @@ void WallProfiler::AddLabelSetsByNode(CpuProfile* profile) { } else { array = it->second; } - Nan::Set(array, array->Length(), sampleContext.labels.get()->handle()); + Nan::Set( + array, array->Length(), sampleContext.labels.get()->Get(isolate)); // Sample context was consumed, fetch the next one if (contexts.empty()) { return; @@ -535,13 +538,13 @@ v8::CpuProfiler* WallProfiler::GetProfiler() { return cpuProfiler; } -v8::Local WallProfiler::GetLabels() { - if (!labels_) return Nan::Undefined(); - return labels_->handle(); +v8::Local WallProfiler::GetLabels(Isolate* isolate) { + if (!labels_) return v8::Undefined(isolate); + return labels_->Get(isolate); } -void WallProfiler::SetLabels(v8::Local value) { - labels_ = std::make_shared(value); +void WallProfiler::SetLabels(Isolate* isolate, Local value) { + labels_ = std::make_shared>(isolate, value); } void WallProfiler::UnsetLabels() { @@ -550,12 +553,12 @@ void WallProfiler::UnsetLabels() { NAN_GETTER(WallProfiler::GetLabels) { auto profiler = Nan::ObjectWrap::Unwrap(info.Holder()); - info.GetReturnValue().Set(profiler->GetLabels()); + info.GetReturnValue().Set(profiler->GetLabels(info.GetIsolate())); } NAN_SETTER(WallProfiler::SetLabels) { auto profiler = Nan::ObjectWrap::Unwrap(info.Holder()); - profiler->SetLabels(value); + profiler->SetLabels(info.GetIsolate(), value); } NAN_METHOD(WallProfiler::UnsetLabels) { diff --git a/bindings/profilers/wall.hh b/bindings/profilers/wall.hh index 7c4d87b4..70ce390e 100644 --- a/bindings/profilers/wall.hh +++ b/bindings/profilers/wall.hh @@ -5,7 +5,6 @@ #include #include "../buffer.hh" -#include "../wrap.hh" namespace dd { @@ -13,19 +12,19 @@ class WallProfiler : public Nan::ObjectWrap { private: int samplingInterval = 0; v8::CpuProfiler* cpuProfiler = nullptr; - std::shared_ptr labels_; + std::shared_ptr> labels_; std::unordered_map> labelSetsByNode; bool labelsCaptured = false; struct SampleContext { - std::shared_ptr labels; + std::shared_ptr> labels; uint64_t timestamp; // Needed to initialize ring buffer elements SampleContext() {} - SampleContext(std::shared_ptr l, uint64_t t) + SampleContext(std::shared_ptr> l, uint64_t t) : labels(l), timestamp(t) {} SampleContext(SampleContext&& rval) { @@ -74,14 +73,14 @@ class WallProfiler : public Nan::ObjectWrap { */ explicit WallProfiler(int intervalMicros, int durationMicros); - v8::Local GetLabels(); + v8::Local GetLabels(v8::Isolate*); + void SetLabels(v8::Isolate*, v8::Local); + void UnsetLabels(); bool GetLabelsCaptured() { bool captured = labelsCaptured; labelsCaptured = false; return captured; } - void SetLabels(v8::Local); - void UnsetLabels(); void PushContext(); void StartImpl(v8::Local name, bool includeLines); From d25e466ccf8b7206aca706d1e42372edb19c1d70 Mon Sep 17 00:00:00 2001 From: Attila Szegedi Date: Fri, 19 May 2023 13:33:15 +0200 Subject: [PATCH 10/27] Leave comments for performance improvements --- bindings/profilers/wall.cc | 1 + bindings/profilers/wall.hh | 3 +++ 2 files changed, 4 insertions(+) diff --git a/bindings/profilers/wall.cc b/bindings/profilers/wall.cc index 43a1c23f..ad7e5e93 100644 --- a/bindings/profilers/wall.cc +++ b/bindings/profilers/wall.cc @@ -76,6 +76,7 @@ Local CreateTimeNode(Local name, Local children, Local labelSets) { Local js_node = Nan::New(); + // TODO: create these strings once per isolate, store them in a global. Nan::Set(js_node, Nan::New("name").ToLocalChecked(), name); Nan::Set( js_node, Nan::New("scriptName").ToLocalChecked(), scriptName); diff --git a/bindings/profilers/wall.hh b/bindings/profilers/wall.hh index 70ce390e..d0939d49 100644 --- a/bindings/profilers/wall.hh +++ b/bindings/profilers/wall.hh @@ -12,6 +12,9 @@ class WallProfiler : public Nan::ObjectWrap { private: int samplingInterval = 0; v8::CpuProfiler* cpuProfiler = nullptr; + // TODO: Investigate use of v8::Persistent instead of shared_ptr to + // avoid heap allocation. Need to figure out the right move/copy semantics in + // and out of the ring buffer. std::shared_ptr> labels_; std::unordered_map> labelSetsByNode; From c09cccee023edcb898dc562daf4ccc9d12e9b1b5 Mon Sep 17 00:00:00 2001 From: Attila Szegedi Date: Fri, 19 May 2023 14:49:21 +0200 Subject: [PATCH 11/27] Encapsulate profile translation, this fixes scoping of labelSetsByNode as well --- bindings/profilers/wall.cc | 291 +++++++++++++++++++------------------ bindings/profilers/wall.hh | 17 +-- 2 files changed, 152 insertions(+), 156 deletions(-) diff --git a/bindings/profilers/wall.cc b/bindings/profilers/wall.cc index ad7e5e93..671d10a5 100644 --- a/bindings/profilers/wall.cc +++ b/bindings/profilers/wall.cc @@ -56,17 +56,6 @@ static void sighandler(int sig, siginfo_t* info, void* context) { } #endif -Local WallProfiler::getLabelSetsForNode(const CpuProfileNode* node) { - auto it = labelSetsByNode.find(node); - if (it != labelSetsByNode.end()) { - auto retval = it->second; - labelSetsByNode.erase(it); - return retval; - } else { - return Nan::New(0); - } -} - Local CreateTimeNode(Local name, Local scriptName, Local scriptId, @@ -92,156 +81,171 @@ Local CreateTimeNode(Local name, return js_node; } -Local TranslateLineNumbersTimeProfileNode(const CpuProfileNode* parent, - const CpuProfileNode* node); - -Local WallProfiler::GetLineNumberTimeProfileChildren( - const CpuProfileNode* node) { - unsigned int index = 0; - Local children; - int32_t count = node->GetChildrenCount(); - - unsigned int hitLineCount = node->GetHitLineCount(); - unsigned int hitCount = node->GetHitCount(); - auto labelSets = getLabelSetsForNode(node); - if (hitLineCount > 0) { - std::vector entries(hitLineCount); - node->GetLineTicks(&entries[0], hitLineCount); - children = Nan::New(count + hitLineCount); - for (const CpuProfileNode::LineTick entry : entries) { +class ProfileTranslator { + friend class WallProfiler; + + LabelSetsByNode labelSetsByNode; + ProfileTranslator( + std::unordered_map>&& nls) + : labelSetsByNode(std::move(nls)) {} + + Local getLabelSetsForNode(const CpuProfileNode* node) { + auto it = labelSetsByNode.find(node); + if (it != labelSetsByNode.end()) { + auto retval = it->second; + labelSetsByNode.erase(it); + return retval; + } else { + return Nan::New(0); + } + } + + Local GetLineNumberTimeProfileChildren( + const CpuProfileNode* node) { + unsigned int index = 0; + Local children; + int32_t count = node->GetChildrenCount(); + + unsigned int hitLineCount = node->GetHitLineCount(); + unsigned int hitCount = node->GetHitCount(); + auto labelSets = getLabelSetsForNode(node); + if (hitLineCount > 0) { + std::vector entries(hitLineCount); + node->GetLineTicks(&entries[0], hitLineCount); + children = Nan::New(count + hitLineCount); + for (const CpuProfileNode::LineTick entry : entries) { + Nan::Set(children, + index++, + CreateTimeNode(node->GetFunctionName(), + node->GetScriptResourceName(), + Nan::New(node->GetScriptId()), + Nan::New(entry.line), + Nan::New(0), + Nan::New(entry.hit_count), + Nan::New(0), + labelSets)); + } + } else if (hitCount > 0) { + // Handle nodes for pseudo-functions like "process" and "garbage + // collection" which do not have hit line counts. + children = Nan::New(count + 1); Nan::Set(children, index++, CreateTimeNode(node->GetFunctionName(), node->GetScriptResourceName(), Nan::New(node->GetScriptId()), - Nan::New(entry.line), - Nan::New(0), - Nan::New(entry.hit_count), + Nan::New(node->GetLineNumber()), + Nan::New(node->GetColumnNumber()), + Nan::New(hitCount), Nan::New(0), labelSets)); + } else { + children = Nan::New(count); } - } else if (hitCount > 0) { - // Handle nodes for pseudo-functions like "process" and "garbage collection" - // which do not have hit line counts. - children = Nan::New(count + 1); - Nan::Set(children, - index++, - CreateTimeNode(node->GetFunctionName(), - node->GetScriptResourceName(), - Nan::New(node->GetScriptId()), - Nan::New(node->GetLineNumber()), - Nan::New(node->GetColumnNumber()), - Nan::New(hitCount), - Nan::New(0), - labelSets)); - } else { - children = Nan::New(count); - } - for (int32_t i = 0; i < count; i++) { - Nan::Set(children, - index++, - TranslateLineNumbersTimeProfileNode(node, node->GetChild(i))); - }; - - return children; -} + for (int32_t i = 0; i < count; i++) { + Nan::Set(children, + index++, + TranslateLineNumbersTimeProfileNode(node, node->GetChild(i))); + }; -Local WallProfiler::TranslateLineNumbersTimeProfileNode( - const CpuProfileNode* parent, const CpuProfileNode* node) { - return CreateTimeNode(parent->GetFunctionName(), - parent->GetScriptResourceName(), - Nan::New(parent->GetScriptId()), - Nan::New(node->GetLineNumber()), - Nan::New(node->GetColumnNumber()), - Nan::New(0), - GetLineNumberTimeProfileChildren(node), - getLabelSetsForNode(node)); -} + return children; + } -// In profiles with line level accurate line numbers, a node's line number -// and column number refer to the line/column from which the function was -// called. -Local WallProfiler::TranslateLineNumbersTimeProfileRoot( - const CpuProfileNode* node) { - int32_t count = node->GetChildrenCount(); - std::vector> childrenArrs(count); - int32_t childCount = 0; - for (int32_t i = 0; i < count; i++) { - Local c = GetLineNumberTimeProfileChildren(node->GetChild(i)); - childCount = childCount + c->Length(); - childrenArrs[i] = c; + Local TranslateLineNumbersTimeProfileNode( + const CpuProfileNode* parent, const CpuProfileNode* node) { + return CreateTimeNode(parent->GetFunctionName(), + parent->GetScriptResourceName(), + Nan::New(parent->GetScriptId()), + Nan::New(node->GetLineNumber()), + Nan::New(node->GetColumnNumber()), + Nan::New(0), + GetLineNumberTimeProfileChildren(node), + getLabelSetsForNode(node)); } - Local children = Nan::New(childCount); - int32_t idx = 0; - for (int32_t i = 0; i < count; i++) { - Local arr = childrenArrs[i]; - for (uint32_t j = 0; j < arr->Length(); j++) { - Nan::Set(children, idx, Nan::Get(arr, j).ToLocalChecked()); - idx++; + // In profiles with line level accurate line numbers, a node's line number + // and column number refer to the line/column from which the function was + // called. + Local TranslateLineNumbersTimeProfileRoot(const CpuProfileNode* node) { + int32_t count = node->GetChildrenCount(); + std::vector> childrenArrs(count); + int32_t childCount = 0; + for (int32_t i = 0; i < count; i++) { + Local c = GetLineNumberTimeProfileChildren(node->GetChild(i)); + childCount = childCount + c->Length(); + childrenArrs[i] = c; } - } - return CreateTimeNode(node->GetFunctionName(), - node->GetScriptResourceName(), - Nan::New(node->GetScriptId()), - Nan::New(node->GetLineNumber()), - Nan::New(node->GetColumnNumber()), - Nan::New(0), - children, - getLabelSetsForNode(node)); -} + Local children = Nan::New(childCount); + int32_t idx = 0; + for (int32_t i = 0; i < count; i++) { + Local arr = childrenArrs[i]; + for (uint32_t j = 0; j < arr->Length(); j++) { + Nan::Set(children, idx, Nan::Get(arr, j).ToLocalChecked()); + idx++; + } + } -Local WallProfiler::TranslateTimeProfileNode( - const CpuProfileNode* node) { - int32_t count = node->GetChildrenCount(); - Local children = Nan::New(count); - for (int32_t i = 0; i < count; i++) { - Nan::Set(children, i, TranslateTimeProfileNode(node->GetChild(i))); + return CreateTimeNode(node->GetFunctionName(), + node->GetScriptResourceName(), + Nan::New(node->GetScriptId()), + Nan::New(node->GetLineNumber()), + Nan::New(node->GetColumnNumber()), + Nan::New(0), + children, + getLabelSetsForNode(node)); } - return CreateTimeNode(node->GetFunctionName(), - node->GetScriptResourceName(), - Nan::New(node->GetScriptId()), - Nan::New(node->GetLineNumber()), - Nan::New(node->GetColumnNumber()), - Nan::New(node->GetHitCount()), - children, - getLabelSetsForNode(node)); -} + Local TranslateTimeProfileNode(const CpuProfileNode* node) { + int32_t count = node->GetChildrenCount(); + Local children = Nan::New(count); + for (int32_t i = 0; i < count; i++) { + Nan::Set(children, i, TranslateTimeProfileNode(node->GetChild(i))); + } -Local WallProfiler::TranslateTimeProfile(const CpuProfile* profile, - bool includeLineInfo) { - Local js_profile = Nan::New(); - Nan::Set(js_profile, - Nan::New("title").ToLocalChecked(), - profile->GetTitle()); + return CreateTimeNode(node->GetFunctionName(), + node->GetScriptResourceName(), + Nan::New(node->GetScriptId()), + Nan::New(node->GetLineNumber()), + Nan::New(node->GetColumnNumber()), + Nan::New(node->GetHitCount()), + children, + getLabelSetsForNode(node)); + } -#if NODE_MODULE_VERSION > NODE_11_0_MODULE_VERSION - if (includeLineInfo) { + Local TranslateTimeProfile(const CpuProfile* profile, + bool includeLineInfo) { + Local js_profile = Nan::New(); Nan::Set(js_profile, - Nan::New("topDownRoot").ToLocalChecked(), - TranslateLineNumbersTimeProfileRoot(profile->GetTopDownRoot())); - } else { + Nan::New("title").ToLocalChecked(), + profile->GetTitle()); + +#if NODE_MODULE_VERSION > NODE_11_0_MODULE_VERSION + if (includeLineInfo) { + Nan::Set(js_profile, + Nan::New("topDownRoot").ToLocalChecked(), + TranslateLineNumbersTimeProfileRoot(profile->GetTopDownRoot())); + } else { + Nan::Set(js_profile, + Nan::New("topDownRoot").ToLocalChecked(), + TranslateTimeProfileNode(profile->GetTopDownRoot())); + } +#else Nan::Set(js_profile, Nan::New("topDownRoot").ToLocalChecked(), TranslateTimeProfileNode(profile->GetTopDownRoot())); - } -#else - Nan::Set(js_profile, - Nan::New("topDownRoot").ToLocalChecked(), - TranslateTimeProfileNode(profile->GetTopDownRoot())); #endif - Nan::Set(js_profile, - Nan::New("startTime").ToLocalChecked(), - Nan::New(profile->GetStartTime())); - Nan::Set(js_profile, - Nan::New("endTime").ToLocalChecked(), - Nan::New(profile->GetEndTime())); - - return js_profile; -} + Nan::Set(js_profile, + Nan::New("startTime").ToLocalChecked(), + Nan::New(profile->GetStartTime())); + Nan::Set(js_profile, + Nan::New("endTime").ToLocalChecked(), + Nan::New(profile->GetEndTime())); + + return js_profile; + } +}; bool isIdleSample(const CpuProfileNode* sample) { return @@ -252,11 +256,13 @@ bool isIdleSample(const CpuProfileNode* sample) { strncmp("(idle)", sample->GetFunctionNameStr(), 7) == 0; } -void WallProfiler::AddLabelSetsByNode(CpuProfile* profile) { +LabelSetsByNode WallProfiler::GetLabelSetsByNode(CpuProfile* profile) { auto halfInterval = samplingInterval * 1000 / 2; + LabelSetsByNode labelSetsByNode; + if (contexts.empty()) { - return; + return labelSetsByNode; } auto isolate = Isolate::GetCurrent(); @@ -282,7 +288,7 @@ void WallProfiler::AddLabelSetsByNode(CpuProfile* profile) { if (contextTimestamp < sampleTimestamp - halfInterval) { // Current sample context is too old, discard it and fetch the next one if (contexts.empty()) { - return; + return labelSetsByNode; } sampleContext = contexts.pop_front(); } else if (contextTimestamp >= sampleTimestamp + halfInterval) { @@ -304,7 +310,7 @@ void WallProfiler::AddLabelSetsByNode(CpuProfile* profile) { array, array->Length(), sampleContext.labels.get()->Get(isolate)); // Sample context was consumed, fetch the next one if (contexts.empty()) { - return; + return labelSetsByNode; } sampleContext = contexts.pop_front(); } @@ -313,6 +319,7 @@ void WallProfiler::AddLabelSetsByNode(CpuProfile* profile) { // Push the last popped sample context back into the ring to be used by the // next profile contexts.push_front(std::move(sampleContext)); + return labelSetsByNode; } static Nan::Persistent constructor; @@ -492,8 +499,8 @@ NAN_METHOD(WallProfiler::Stop) { Local WallProfiler::StopImpl(Local name, bool includeLines) { auto profiler = GetProfiler(); auto v8_profile = profiler->StopProfiling(name); - AddLabelSetsByNode(v8_profile); - Local profile = TranslateTimeProfile(v8_profile, includeLines); + Local profile = ProfileTranslator(GetLabelSetsByNode(v8_profile)) + .TranslateTimeProfile(v8_profile, includeLines); v8_profile->Delete(); return profile; } diff --git a/bindings/profilers/wall.hh b/bindings/profilers/wall.hh index d0939d49..aa2af898 100644 --- a/bindings/profilers/wall.hh +++ b/bindings/profilers/wall.hh @@ -8,6 +8,8 @@ namespace dd { +using LabelSetsByNode = std::unordered_map>; + class WallProfiler : public Nan::ObjectWrap { private: int samplingInterval = 0; @@ -16,8 +18,6 @@ class WallProfiler : public Nan::ObjectWrap { // avoid heap allocation. Need to figure out the right move/copy semantics in // and out of the ring buffer. std::shared_ptr> labels_; - std::unordered_map> - labelSetsByNode; bool labelsCaptured = false; struct SampleContext { @@ -53,18 +53,7 @@ class WallProfiler : public Nan::ObjectWrap { // to work around https://bugs.chromium.org/p/v8/issues/detail?id=11051. v8::CpuProfiler* GetProfiler(); - void AddLabelSetsByNode(v8::CpuProfile* profile); - v8::Local getLabelSetsForNode(const v8::CpuProfileNode* node); - v8::Local GetLineNumberTimeProfileChildren( - const v8::CpuProfileNode* node); - v8::Local TranslateLineNumbersTimeProfileNode( - const v8::CpuProfileNode* parent, const v8::CpuProfileNode* node); - v8::Local TranslateLineNumbersTimeProfileRoot( - const v8::CpuProfileNode* node); - v8::Local TranslateTimeProfileNode(const v8::CpuProfileNode* node); - // TODO: get rid of includeLineInfo - v8::Local TranslateTimeProfile(const v8::CpuProfile* profile, - bool includeLineInfo); + LabelSetsByNode GetLabelSetsByNode(v8::CpuProfile* profile); public: /** From 2b9988beb438500ca47c43e58a30c74376f713d3 Mon Sep 17 00:00:00 2001 From: Attila Szegedi Date: Mon, 22 May 2023 10:30:35 +0200 Subject: [PATCH 12/27] Optimize creation of reused strings etc. --- bindings/profilers/wall.cc | 147 +++++++++++++++++++++---------------- 1 file changed, 85 insertions(+), 62 deletions(-) diff --git a/bindings/profilers/wall.cc b/bindings/profilers/wall.cc index 671d10a5..c837caa3 100644 --- a/bindings/profilers/wall.cc +++ b/bindings/profilers/wall.cc @@ -56,35 +56,28 @@ static void sighandler(int sig, siginfo_t* info, void* context) { } #endif -Local CreateTimeNode(Local name, - Local scriptName, - Local scriptId, - Local lineNumber, - Local columnNumber, - Local hitCount, - Local children, - Local labelSets) { - Local js_node = Nan::New(); - // TODO: create these strings once per isolate, store them in a global. - Nan::Set(js_node, Nan::New("name").ToLocalChecked(), name); - Nan::Set( - js_node, Nan::New("scriptName").ToLocalChecked(), scriptName); - Nan::Set(js_node, Nan::New("scriptId").ToLocalChecked(), scriptId); - Nan::Set( - js_node, Nan::New("lineNumber").ToLocalChecked(), lineNumber); - Nan::Set( - js_node, Nan::New("columnNumber").ToLocalChecked(), columnNumber); - Nan::Set(js_node, Nan::New("hitCount").ToLocalChecked(), hitCount); - Nan::Set(js_node, Nan::New("children").ToLocalChecked(), children); - Nan::Set(js_node, Nan::New("labelSets").ToLocalChecked(), labelSets); - - return js_node; -} - class ProfileTranslator { friend class WallProfiler; LabelSetsByNode labelSetsByNode; + Isolate* isolate = Isolate::GetCurrent(); + Local emptyArray = NewArray(0); + Local zero = NewInteger(0); + +#define FIELDS \ + X(name) \ + X(scriptName) \ + X(scriptId) \ + X(lineNumber) \ + X(columnNumber) \ + X(hitCount) \ + X(children) \ + X(labelSets) + +#define X(name) Local str_##name = NewString(#name); + FIELDS +#undef X + ProfileTranslator( std::unordered_map>&& nls) : labelSetsByNode(std::move(nls)) {} @@ -96,12 +89,42 @@ class ProfileTranslator { labelSetsByNode.erase(it); return retval; } else { - return Nan::New(0); + return emptyArray; } } - Local GetLineNumberTimeProfileChildren( - const CpuProfileNode* node) { + Local CreateTimeNode(Local name, + Local scriptName, + Local scriptId, + Local lineNumber, + Local columnNumber, + Local hitCount, + Local children, + Local labelSets) { + Local js_node = Nan::New(); +#define X(name) Nan::Set(js_node, str_##name, name); + FIELDS +#undef X + return js_node; + } + + Local NewInteger(int32_t x) { + return Integer::New(isolate, x); + } + + Local NewArray(int length) { + return Array::New(isolate, length); + } + + Local NewString(const char* str) { +#if NODE_MODULE_VERSION > NODE_12_0_MODULE_VERSION + return String::NewFromUtf8(isolate, str).ToLocalChecked(); +#else + return Nan::New(str).ToLocalChecked(); +#endif + } + + Local GetLineNumberTimeProfileChildren(const CpuProfileNode* node) { unsigned int index = 0; Local children; int32_t count = node->GetChildrenCount(); @@ -109,38 +132,39 @@ class ProfileTranslator { unsigned int hitLineCount = node->GetHitLineCount(); unsigned int hitCount = node->GetHitCount(); auto labelSets = getLabelSetsForNode(node); + auto scriptId = NewInteger(node->GetScriptId()); if (hitLineCount > 0) { std::vector entries(hitLineCount); node->GetLineTicks(&entries[0], hitLineCount); - children = Nan::New(count + hitLineCount); + children = NewArray(count + hitLineCount); for (const CpuProfileNode::LineTick entry : entries) { Nan::Set(children, index++, CreateTimeNode(node->GetFunctionName(), node->GetScriptResourceName(), - Nan::New(node->GetScriptId()), - Nan::New(entry.line), - Nan::New(0), - Nan::New(entry.hit_count), - Nan::New(0), + scriptId, + NewInteger(entry.line), + zero, + NewInteger(entry.hit_count), + emptyArray, labelSets)); } } else if (hitCount > 0) { // Handle nodes for pseudo-functions like "process" and "garbage // collection" which do not have hit line counts. - children = Nan::New(count + 1); + children = NewArray(count + 1); Nan::Set(children, index++, CreateTimeNode(node->GetFunctionName(), node->GetScriptResourceName(), - Nan::New(node->GetScriptId()), - Nan::New(node->GetLineNumber()), - Nan::New(node->GetColumnNumber()), - Nan::New(hitCount), - Nan::New(0), + scriptId, + NewInteger(node->GetLineNumber()), + NewInteger(node->GetColumnNumber()), + NewInteger(hitCount), + emptyArray, labelSets)); } else { - children = Nan::New(count); + children = NewArray(count); } for (int32_t i = 0; i < count; i++) { @@ -156,10 +180,10 @@ class ProfileTranslator { const CpuProfileNode* parent, const CpuProfileNode* node) { return CreateTimeNode(parent->GetFunctionName(), parent->GetScriptResourceName(), - Nan::New(parent->GetScriptId()), - Nan::New(node->GetLineNumber()), - Nan::New(node->GetColumnNumber()), - Nan::New(0), + NewInteger(parent->GetScriptId()), + NewInteger(node->GetLineNumber()), + NewInteger(node->GetColumnNumber()), + zero, GetLineNumberTimeProfileChildren(node), getLabelSetsForNode(node)); } @@ -177,7 +201,7 @@ class ProfileTranslator { childrenArrs[i] = c; } - Local children = Nan::New(childCount); + Local children = NewArray(childCount); int32_t idx = 0; for (int32_t i = 0; i < count; i++) { Local arr = childrenArrs[i]; @@ -189,10 +213,10 @@ class ProfileTranslator { return CreateTimeNode(node->GetFunctionName(), node->GetScriptResourceName(), - Nan::New(node->GetScriptId()), - Nan::New(node->GetLineNumber()), - Nan::New(node->GetColumnNumber()), - Nan::New(0), + NewInteger(node->GetScriptId()), + NewInteger(node->GetLineNumber()), + NewInteger(node->GetColumnNumber()), + zero, children, getLabelSetsForNode(node)); } @@ -206,10 +230,10 @@ class ProfileTranslator { return CreateTimeNode(node->GetFunctionName(), node->GetScriptResourceName(), - Nan::New(node->GetScriptId()), - Nan::New(node->GetLineNumber()), - Nan::New(node->GetColumnNumber()), - Nan::New(node->GetHitCount()), + NewInteger(node->GetScriptId()), + NewInteger(node->GetLineNumber()), + NewInteger(node->GetColumnNumber()), + NewInteger(node->GetHitCount()), children, getLabelSetsForNode(node)); } @@ -217,34 +241,33 @@ class ProfileTranslator { Local TranslateTimeProfile(const CpuProfile* profile, bool includeLineInfo) { Local js_profile = Nan::New(); - Nan::Set(js_profile, - Nan::New("title").ToLocalChecked(), - profile->GetTitle()); + Nan::Set(js_profile, NewString("title"), profile->GetTitle()); #if NODE_MODULE_VERSION > NODE_11_0_MODULE_VERSION if (includeLineInfo) { Nan::Set(js_profile, - Nan::New("topDownRoot").ToLocalChecked(), + NewString("topDownRoot"), TranslateLineNumbersTimeProfileRoot(profile->GetTopDownRoot())); } else { Nan::Set(js_profile, - Nan::New("topDownRoot").ToLocalChecked(), + NewString("topDownRoot"), TranslateTimeProfileNode(profile->GetTopDownRoot())); } #else Nan::Set(js_profile, - Nan::New("topDownRoot").ToLocalChecked(), + NewString("topDownRoot"), TranslateTimeProfileNode(profile->GetTopDownRoot())); #endif Nan::Set(js_profile, - Nan::New("startTime").ToLocalChecked(), + NewString("startTime"), Nan::New(profile->GetStartTime())); Nan::Set(js_profile, - Nan::New("endTime").ToLocalChecked(), + NewString("endTime"), Nan::New(profile->GetEndTime())); return js_profile; } +#undef FIELDS }; bool isIdleSample(const CpuProfileNode* sample) { From 8658adf30ca0f80688915e5a6bf1eef352e3d5ab Mon Sep 17 00:00:00 2001 From: Attila Szegedi Date: Mon, 22 May 2023 14:49:32 +0200 Subject: [PATCH 13/27] No need for unsetLabels --- bindings/profilers/wall.cc | 16 +++++----------- bindings/profilers/wall.hh | 2 -- ts/src/time-profiler.ts | 5 ----- 3 files changed, 5 insertions(+), 18 deletions(-) diff --git a/bindings/profilers/wall.cc b/bindings/profilers/wall.cc index c837caa3..9ed215d3 100644 --- a/bindings/profilers/wall.cc +++ b/bindings/profilers/wall.cc @@ -546,7 +546,6 @@ NAN_MODULE_INIT(WallProfiler::Init) { Nan::SetPrototypeMethod(tpl, "start", Start); Nan::SetPrototypeMethod(tpl, "dispose", Dispose); Nan::SetPrototypeMethod(tpl, "stop", Stop); - Nan::SetPrototypeMethod(tpl, "unsetLabels", UnsetLabels); PerIsolateData::For(Isolate::GetCurrent()) ->WallProfilerConstructor() @@ -575,11 +574,11 @@ v8::Local WallProfiler::GetLabels(Isolate* isolate) { } void WallProfiler::SetLabels(Isolate* isolate, Local value) { - labels_ = std::make_shared>(isolate, value); -} - -void WallProfiler::UnsetLabels() { - labels_.reset(); + if (value->BooleanValue(isolate)) { + labels_ = std::make_shared>(isolate, value); + } else { + labels_.reset(); + } } NAN_GETTER(WallProfiler::GetLabels) { @@ -592,11 +591,6 @@ NAN_SETTER(WallProfiler::SetLabels) { profiler->SetLabels(info.GetIsolate(), value); } -NAN_METHOD(WallProfiler::UnsetLabels) { - auto profiler = Nan::ObjectWrap::Unwrap(info.Holder()); - profiler->UnsetLabels(); -} - NAN_GETTER(WallProfiler::GetLabelsCaptured) { auto profiler = Nan::ObjectWrap::Unwrap(info.Holder()); info.GetReturnValue().Set(profiler->GetLabelsCaptured()); diff --git a/bindings/profilers/wall.hh b/bindings/profilers/wall.hh index aa2af898..e929f7f7 100644 --- a/bindings/profilers/wall.hh +++ b/bindings/profilers/wall.hh @@ -67,7 +67,6 @@ class WallProfiler : public Nan::ObjectWrap { v8::Local GetLabels(v8::Isolate*); void SetLabels(v8::Isolate*, v8::Local); - void UnsetLabels(); bool GetLabelsCaptured() { bool captured = labelsCaptured; labelsCaptured = false; @@ -82,7 +81,6 @@ class WallProfiler : public Nan::ObjectWrap { static NAN_METHOD(Dispose); static NAN_METHOD(Start); static NAN_METHOD(Stop); - static NAN_METHOD(UnsetLabels); static NAN_MODULE_INIT(Init); static NAN_GETTER(GetLabels); static NAN_SETTER(SetLabels); diff --git a/ts/src/time-profiler.ts b/ts/src/time-profiler.ts index 023df39e..6a914619 100644 --- a/ts/src/time-profiler.ts +++ b/ts/src/time-profiler.ts @@ -75,7 +75,6 @@ export function start( return { stop: majorVersion < 16 ? stopOld : stop, setLabels, - unsetLabels, labelsCaptured, }; @@ -117,10 +116,6 @@ export function start( profiler.labels = labels; } - function unsetLabels() { - profiler.unsetLabels(); - } - function labelsCaptured() { return profiler.labelsCaptured; } From 08be6f831a7c7b6fc2a22cf3cb22247a5df19c9a Mon Sep 17 00:00:00 2001 From: Attila Szegedi Date: Fri, 26 May 2023 15:21:22 +0200 Subject: [PATCH 14/27] Improve RingBuffer and SampleContext move semantics --- bindings/buffer.hh | 14 ++++++++------ bindings/profilers/wall.hh | 11 ----------- 2 files changed, 8 insertions(+), 17 deletions(-) diff --git a/bindings/buffer.hh b/bindings/buffer.hh index a8c2887e..7813c53c 100644 --- a/bindings/buffer.hh +++ b/bindings/buffer.hh @@ -18,36 +18,38 @@ class RingBuffer { const T& front() const { return buffer[front_index_]; } - void push_back(T t) { + template + void push_back(T2&& t) { if (full()) { if (empty()) { return; } // overwrite buffer head - buffer[back_index_] = std::move(t); + buffer[back_index_] = std::forward(t); increment(back_index_); // move buffer head front_index_ = back_index_; } else { - buffer[back_index_] = std::move(t); + buffer[back_index_] = std::forward(t); increment(back_index_); ++size_; } } - void push_front(T t) { + template + void push_front(T2&& t) { if (full()) { if (empty()) { return; } // overwrite buffer head decrement(front_index_); - buffer[front_index_] = std::move(t); + buffer[front_index_] = std::forward(t); // move buffer head back_index_ = front_index_; } else { decrement(front_index_); - buffer[front_index_] = std::move(t); + buffer[front_index_] = std::forward(t); ++size_; } } diff --git a/bindings/profilers/wall.hh b/bindings/profilers/wall.hh index e929f7f7..fc60ad68 100644 --- a/bindings/profilers/wall.hh +++ b/bindings/profilers/wall.hh @@ -29,17 +29,6 @@ class WallProfiler : public Nan::ObjectWrap { SampleContext(std::shared_ptr> l, uint64_t t) : labels(l), timestamp(t) {} - - SampleContext(SampleContext&& rval) { - labels = std::move(rval.labels); - timestamp = rval.timestamp; - } - - SampleContext& operator=(SampleContext&& rval) { - labels = std::move(rval.labels); - timestamp = rval.timestamp; - return *this; - } }; RingBuffer contexts; From 2b642a7eca4be2c9f55f36a88a47150b935a7078 Mon Sep 17 00:00:00 2001 From: Attila Szegedi Date: Tue, 30 May 2023 11:22:24 +0200 Subject: [PATCH 15/27] Restore backwards compatibility of the start method --- ts/src/index.ts | 3 ++- ts/src/time-profiler.ts | 23 ++++++++++++++++++++--- ts/test/test-time-profiler.ts | 2 +- 3 files changed, 23 insertions(+), 5 deletions(-) diff --git a/ts/src/index.ts b/ts/src/index.ts index 76a3370f..6bf7e7c1 100644 --- a/ts/src/index.ts +++ b/ts/src/index.ts @@ -30,6 +30,7 @@ export const CpuProfiler = cpuProfiler; export const time = { profile: timeProfiler.profile, start: timeProfiler.start, + startWithLabels: timeProfiler.startWithLabels, }; export const heap = { @@ -44,7 +45,7 @@ export const heap = { // If loaded with --require, start profiling. if (module.parent && module.parent.id === 'internal/preload') { - const {stop} = time.start(); + const stop = time.start(); process.on('exit', () => { // The process is going to terminate imminently. All work here needs to // be synchronous. diff --git a/ts/src/time-profiler.ts b/ts/src/time-profiler.ts index 6a914619..cff40b95 100644 --- a/ts/src/time-profiler.ts +++ b/ts/src/time-profiler.ts @@ -47,9 +47,9 @@ export interface TimeProfilerOptions { } export async function profile(options: TimeProfilerOptions) { - const {stop} = start( + const {stop} = startWithLabels( options.intervalMicros || DEFAULT_INTERVAL_MICROS, - options.durationMillis, + options.durationMillis || DEFAULT_DURATION_MILLIS, options.name, options.sourceMapper, options.lineNumbers @@ -62,8 +62,25 @@ function ensureRunName(name?: string) { return name || `pprof-${Date.now()}-${Math.random()}`; } -// NOTE: refreshing doesn't work if giving a profile name. +// Retained for backwards compatibility with older tracer export function start( + intervalMicros: Microseconds = DEFAULT_INTERVAL_MICROS, + name?: string, + sourceMapper?: SourceMapper, + lineNumbers = true +) { + const {stop} = startWithLabels( + intervalMicros, + DEFAULT_DURATION_MILLIS, + name, + sourceMapper, + lineNumbers + ); + return stop; +} + +// NOTE: refreshing doesn't work if giving a profile name. +export function startWithLabels( intervalMicros: Microseconds = DEFAULT_INTERVAL_MICROS, durationMillis: Milliseconds = DEFAULT_DURATION_MILLIS, name?: string, diff --git a/ts/test/test-time-profiler.ts b/ts/test/test-time-profiler.ts index c58aa9a8..0319c559 100644 --- a/ts/test/test-time-profiler.ts +++ b/ts/test/test-time-profiler.ts @@ -81,7 +81,7 @@ describe('Time Profiler', () => { }); it('should be able to restart when stopping', async () => { - const {stop} = time.start(PROFILE_OPTIONS.intervalMicros); + const stop = time.start(PROFILE_OPTIONS.intervalMicros); timeProfilerStub.start.resetHistory(); timeProfilerStub.stop.resetHistory(); timeProfilerStub.dispose.resetHistory(); From b1a517ee886013adb9bdaa5c5d9907790dd91a6c Mon Sep 17 00:00:00 2001 From: Attila Szegedi Date: Tue, 30 May 2023 15:55:54 +0200 Subject: [PATCH 16/27] Hide new functionality behind a flag --- bindings/profilers/wall.cc | 42 +++++++++++++++++++++++--------------- bindings/profilers/wall.hh | 2 +- ts/src/time-profiler.ts | 38 ++++++++++++++++++++++++++-------- 3 files changed, 55 insertions(+), 27 deletions(-) diff --git a/bindings/profilers/wall.cc b/bindings/profilers/wall.cc index 9ed215d3..900de36a 100644 --- a/bindings/profilers/wall.cc +++ b/bindings/profilers/wall.cc @@ -449,14 +449,17 @@ NAN_METHOD(WallProfiler::Start) { WallProfiler* wallProfiler = Nan::ObjectWrap::Unwrap(info.Holder()); - if (info.Length() != 2) { - return Nan::ThrowTypeError("Start must have two arguments."); + if (info.Length() != 3) { + return Nan::ThrowTypeError("Start must have three arguments."); } if (!info[0]->IsString()) { return Nan::ThrowTypeError("Profile name must be a string."); } if (!info[1]->IsBoolean()) { - return Nan::ThrowTypeError("Include lines must be a boolean."); + return Nan::ThrowTypeError("Include lines flag must be a boolean."); + } + if (!info[2]->IsBoolean()) { + return Nan::ThrowTypeError("With labels flag must be a boolean."); } Local name = @@ -465,29 +468,34 @@ NAN_METHOD(WallProfiler::Start) { bool includeLines = Nan::MaybeLocal(info[1].As()).ToLocalChecked()->Value(); - wallProfiler->StartImpl(name, includeLines); + bool withLabels = + Nan::MaybeLocal(info[2].As()).ToLocalChecked()->Value(); -#ifdef DD_WALL_USE_SIGPROF - struct sigaction sa, old_sa; - sa.sa_flags = SA_SIGINFO | SA_RESTART; - sa.sa_sigaction = &sighandler; - sigemptyset(&sa.sa_mask); - sigaction(SIGPROF, &sa, &old_sa); + wallProfiler->StartImpl(name, includeLines, withLabels); - // At the end of a cycle start is called before stop, - // at this point old_sa.sa_sigaction is sighandler ! - if (!old_handler) { - old_handler = old_sa.sa_sigaction; +#ifdef DD_WALL_USE_SIGPROF + if (withLabels) { + struct sigaction sa, old_sa; + sa.sa_flags = SA_SIGINFO | SA_RESTART; + sa.sa_sigaction = &sighandler; + sigemptyset(&sa.sa_mask); + sigaction(SIGPROF, &sa, &old_sa); + + // At the end of a cycle start is called before stop, + // at this point old_sa.sa_sigaction is sighandler ! + if (!old_handler) { + old_handler = old_sa.sa_sigaction; + } } #endif } -void WallProfiler::StartImpl(Local name, bool includeLines) { +void WallProfiler::StartImpl(Local name, bool includeLines, bool withLabels) { if (includeLines) { GetProfiler()->StartProfiling( - name, CpuProfilingMode::kCallerLineNumbers, true); + name, CpuProfilingMode::kCallerLineNumbers, withLabels); } else { - GetProfiler()->StartProfiling(name, true); + GetProfiler()->StartProfiling(name, withLabels); } last_start = current_start; diff --git a/bindings/profilers/wall.hh b/bindings/profilers/wall.hh index fc60ad68..56ef1ee7 100644 --- a/bindings/profilers/wall.hh +++ b/bindings/profilers/wall.hh @@ -63,7 +63,7 @@ class WallProfiler : public Nan::ObjectWrap { } void PushContext(); - void StartImpl(v8::Local name, bool includeLines); + void StartImpl(v8::Local name, bool includeLines, bool withLabels); v8::Local StopImpl(v8::Local name, bool includeLines); static NAN_METHOD(New); diff --git a/ts/src/time-profiler.ts b/ts/src/time-profiler.ts index cff40b95..1359b9af 100644 --- a/ts/src/time-profiler.ts +++ b/ts/src/time-profiler.ts @@ -47,9 +47,8 @@ export interface TimeProfilerOptions { } export async function profile(options: TimeProfilerOptions) { - const {stop} = startWithLabels( + const stop = start( options.intervalMicros || DEFAULT_INTERVAL_MICROS, - options.durationMillis || DEFAULT_DURATION_MILLIS, options.name, options.sourceMapper, options.lineNumbers @@ -62,24 +61,26 @@ function ensureRunName(name?: string) { return name || `pprof-${Date.now()}-${Math.random()}`; } -// Retained for backwards compatibility with older tracer +// Temporarily retained for backwards compatibility with older tracer export function start( intervalMicros: Microseconds = DEFAULT_INTERVAL_MICROS, name?: string, sourceMapper?: SourceMapper, lineNumbers = true ) { - const {stop} = startWithLabels( + const {stop} = startInternal( + intervalMicros, + // Duration must be at least intervalMicros; not used anyway when + // not collecting extra info (CPU time, labels) with samples. intervalMicros, - DEFAULT_DURATION_MILLIS, name, sourceMapper, - lineNumbers + lineNumbers, + false ); return stop; } -// NOTE: refreshing doesn't work if giving a profile name. export function startWithLabels( intervalMicros: Microseconds = DEFAULT_INTERVAL_MICROS, durationMillis: Milliseconds = DEFAULT_DURATION_MILLIS, @@ -87,7 +88,26 @@ export function startWithLabels( sourceMapper?: SourceMapper, lineNumbers = true ) { - const profiler = new TimeProfiler(intervalMicros, durationMillis * 1000); + return startInternal( + intervalMicros, + durationMillis * 1000, + name, + sourceMapper, + lineNumbers, + true + ); +} + +// NOTE: refreshing doesn't work if giving a profile name. +function startInternal( + intervalMicros: Microseconds, + durationMicros: Microseconds, + name?: string, + sourceMapper?: SourceMapper, + lineNumbers?: boolean, + withLabels?: boolean +) { + const profiler = new TimeProfiler(intervalMicros, durationMicros); let runName = start(); return { stop: majorVersion < 16 ? stopOld : stop, @@ -97,7 +117,7 @@ export function startWithLabels( function start() { const runName = ensureRunName(name); - profiler.start(runName, lineNumbers); + profiler.start(runName, lineNumbers, withLabels); return runName; } From db1aa3947b1e0812c06913f696d43c303713caaf Mon Sep 17 00:00:00 2001 From: Attila Szegedi Date: Wed, 31 May 2023 18:59:55 +0200 Subject: [PATCH 17/27] Add a test + fixes for the test --- bindings/buffer.hh | 1 + bindings/profilers/wall.cc | 131 ++++++++++++++++++---------- bindings/profilers/wall.hh | 24 ++++-- package.json | 1 + ts/src/time-profiler.ts | 22 ++--- ts/test/test-time-profiler.ts | 156 +++++++++++++++++++++++++++++++++- 6 files changed, 270 insertions(+), 65 deletions(-) diff --git a/bindings/buffer.hh b/bindings/buffer.hh index 7813c53c..f4100e37 100644 --- a/bindings/buffer.hh +++ b/bindings/buffer.hh @@ -13,6 +13,7 @@ class RingBuffer { bool full() const { return size_ == capacity_; } bool empty() const { return size_ == 0; } + size_t size() const { return size_; } T& front() { return buffer[front_index_]; } diff --git a/bindings/profilers/wall.cc b/bindings/profilers/wall.cc index 900de36a..c6a693e2 100644 --- a/bindings/profilers/wall.cc +++ b/bindings/profilers/wall.cc @@ -46,13 +46,12 @@ static void (*old_handler)(int, siginfo_t*, void*) = nullptr; static void sighandler(int sig, siginfo_t* info, void* context) { auto prof_map = profilers.load(); auto prof_it = prof_map->find(Isolate::GetCurrent()); - if (prof_it != prof_map->end()) { - prof_it->second->PushContext(); - } - if (old_handler) { old_handler(sig, info, context); } + if (prof_it != prof_map->end()) { + prof_it->second->PushContext(); + } } #endif @@ -279,63 +278,92 @@ bool isIdleSample(const CpuProfileNode* sample) { strncmp("(idle)", sample->GetFunctionNameStr(), 7) == 0; } -LabelSetsByNode WallProfiler::GetLabelSetsByNode(CpuProfile* profile) { - auto halfInterval = samplingInterval * 1000 / 2; - +LabelSetsByNode WallProfiler::GetLabelSetsByNode(CpuProfile* profile, + uint64_t startTime) { LabelSetsByNode labelSetsByNode; - if (contexts.empty()) { + if (contexts.empty() || profile->GetSamplesCount() == 0) { return labelSetsByNode; } auto isolate = Isolate::GetCurrent(); - SampleContext sampleContext = contexts.pop_front(); - uint64_t time_diff = last_start - profile->GetStartTime() * 1000; - - for (int i = 0; i < profile->GetSamplesCount(); i++) { + auto sampleCount = profile->GetSamplesCount(); + uint64_t halfInterval = + (sampleCount > 1 ? (profile->GetSampleTimestamp(sampleCount - 1) - + profile->GetSampleTimestamp(0)) / + (sampleCount - 1) + : samplingInterval) / + 2; + + // Assumption is that startTime and profile->GetSampleTimestamp(0) were both + // taken very closely to each other in real time so they can be used as a + // common point of time origin, since startTime is taken in + // WallProfiler::Start just after calling WallProfiler::StartImpl. + // Sample times are in micros, context times are + // in nanos. We are using these values - adjusted for half interval in the + // past so we don't suffer any overflows anywhere in the arithmetic below. + int64_t zeroSampleTime = profile->GetSampleTimestamp(0) - halfInterval; + uint64_t zeroContextTime = startTime - halfInterval * 1000; + + for (int i = 0; i < sampleCount; i++) { auto sample = profile->GetSample(i); if (isIdleSample(sample)) { continue; } - - // Translate from profiler micros to uv_hrtime nanos - auto sampleTimestamp = profile->GetSampleTimestamp(i) * 1000 + time_diff; + int64_t sampleTimestamp = profile->GetSampleTimestamp(i) - zeroSampleTime; + // Compute earliest (inclusive) and latest (exclusive) context timestamps + // that can belong to this sample. Use half the distance to neighboring + // samples, or barring that half the sampling interval + uint64_t earliest = + 1000 * (i > 0 ? (sampleTimestamp + (profile->GetSampleTimestamp(i - 1) - + zeroSampleTime)) / + 2 + : (sampleTimestamp - halfInterval)); + uint64_t latest = + 1000 * (i < sampleCount - 1 + ? (sampleTimestamp + + (profile->GetSampleTimestamp(i + 1) - zeroSampleTime)) / + 2 + : (sampleTimestamp + halfInterval)); // This loop will drop all contexts that are too old to be associated with // the current sample; associate those (normally one) that are close enough // to it in time, and stop as soon as it sees a context that's too recent // for this sample. for (;;) { - auto contextTimestamp = sampleContext.timestamp; - if (contextTimestamp < sampleTimestamp - halfInterval) { - // Current sample context is too old, discard it and fetch the next one + auto contextTimestamp = sampleContext.timestamp - zeroContextTime; + if (contextTimestamp < earliest) { + // Current sample context is too old (closer to the previous sample than + // to this one), discard it and fetch the next one. if (contexts.empty()) { return labelSetsByNode; } sampleContext = contexts.pop_front(); - } else if (contextTimestamp >= sampleTimestamp + halfInterval) { - // Current sample context is too recent, we'll try to match it to the - // next sample + } else if (contextTimestamp >= latest) { + // Current sample context is too recent (closer to the next sample than + // to this one), we'll try to match it to the next sample. break; } else { - // This context timestamp is in the goldilocks zone around the sample - // timestamp, so associate its labels with the sample. - auto it = labelSetsByNode.find(sample); - Local array; - if (it == labelSetsByNode.end()) { - array = Nan::New(); - labelSetsByNode.emplace(sample, array); - } else { - array = it->second; + // This sample context is the closest to this sample. + if (sampleContext.labels) { + auto it = labelSetsByNode.find(sample); + Local array; + if (it == labelSetsByNode.end()) { + array = Nan::New(); + labelSetsByNode.emplace(sample, array); + } else { + array = it->second; + } + Nan::Set( + array, array->Length(), sampleContext.labels.get()->Get(isolate)); } - Nan::Set( - array, array->Length(), sampleContext.labels.get()->Get(isolate)); // Sample context was consumed, fetch the next one if (contexts.empty()) { return labelSetsByNode; } sampleContext = contexts.pop_front(); + break; // don't match more than one context to one sample } } } @@ -472,6 +500,7 @@ NAN_METHOD(WallProfiler::Start) { Nan::MaybeLocal(info[2].As()).ToLocalChecked()->Value(); wallProfiler->StartImpl(name, includeLines, withLabels); + auto now = withLabels ? wallProfiler->PushContext() : uv_hrtime(); #ifdef DD_WALL_USE_SIGPROF if (withLabels) { @@ -488,23 +517,24 @@ NAN_METHOD(WallProfiler::Start) { } } #endif + auto bi_now = BigInt::NewFromUnsigned(info.GetIsolate(), now); + info.GetReturnValue().Set(bi_now); } -void WallProfiler::StartImpl(Local name, bool includeLines, bool withLabels) { +void WallProfiler::StartImpl(Local name, + bool includeLines, + bool withLabels) { if (includeLines) { GetProfiler()->StartProfiling( name, CpuProfilingMode::kCallerLineNumbers, withLabels); } else { GetProfiler()->StartProfiling(name, withLabels); } - - last_start = current_start; - current_start = uv_hrtime(); } NAN_METHOD(WallProfiler::Stop) { - if (info.Length() != 2) { - return Nan::ThrowTypeError("Start must have two arguments."); + if (info.Length() != 3) { + return Nan::ThrowTypeError("Stop must have three arguments."); } if (!info[0]->IsString()) { return Nan::ThrowTypeError("Profile name must be a string."); @@ -513,25 +543,36 @@ NAN_METHOD(WallProfiler::Stop) { return Nan::ThrowTypeError("Include lines must be a boolean."); } + if (!info[2]->IsBigInt()) { + return Nan::ThrowTypeError("Start time must be a bigint."); + } + Local name = Nan::MaybeLocal(info[0].As()).ToLocalChecked(); bool includeLines = Nan::MaybeLocal(info[1].As()).ToLocalChecked()->Value(); + uint64_t startTime = Nan::MaybeLocal(info[2].As()) + .ToLocalChecked() + ->Uint64Value(); + WallProfiler* wallProfiler = Nan::ObjectWrap::Unwrap(info.Holder()); - auto profile = wallProfiler->StopImpl(name, includeLines); + auto profile = wallProfiler->StopImpl(name, includeLines, startTime); info.GetReturnValue().Set(profile); } -Local WallProfiler::StopImpl(Local name, bool includeLines) { +Local WallProfiler::StopImpl(Local name, + bool includeLines, + uint64_t startTime) { auto profiler = GetProfiler(); auto v8_profile = profiler->StopProfiling(name); - Local profile = ProfileTranslator(GetLabelSetsByNode(v8_profile)) - .TranslateTimeProfile(v8_profile, includeLines); + Local profile = + ProfileTranslator(GetLabelSetsByNode(v8_profile, startTime)) + .TranslateTimeProfile(v8_profile, includeLines); v8_profile->Delete(); return profile; } @@ -604,14 +645,16 @@ NAN_GETTER(WallProfiler::GetLabelsCaptured) { info.GetReturnValue().Set(profiler->GetLabelsCaptured()); } -void WallProfiler::PushContext() { +uint64_t WallProfiler::PushContext() { // Be careful this is called in a signal handler context therefore all // operations must be async signal safe (in particular no allocations). Our // ring buffer avoids allocations. + auto now = uv_hrtime(); + contexts.push_back(SampleContext(labels_, now)); if (labels_) { - contexts.push_back(SampleContext(labels_, uv_hrtime())); labelsCaptured = true; } + return now; } } // namespace dd diff --git a/bindings/profilers/wall.hh b/bindings/profilers/wall.hh index 56ef1ee7..e0e5f38e 100644 --- a/bindings/profilers/wall.hh +++ b/bindings/profilers/wall.hh @@ -8,7 +8,10 @@ namespace dd { -using LabelSetsByNode = std::unordered_map>; +using LabelSetsByNode = + std::unordered_map>; + +using ValuePtr = std::shared_ptr>; class WallProfiler : public Nan::ObjectWrap { private: @@ -17,11 +20,11 @@ class WallProfiler : public Nan::ObjectWrap { // TODO: Investigate use of v8::Persistent instead of shared_ptr to // avoid heap allocation. Need to figure out the right move/copy semantics in // and out of the ring buffer. - std::shared_ptr> labels_; + ValuePtr labels_; bool labelsCaptured = false; struct SampleContext { - std::shared_ptr> labels; + ValuePtr labels; uint64_t timestamp; // Needed to initialize ring buffer elements @@ -32,8 +35,6 @@ class WallProfiler : public Nan::ObjectWrap { }; RingBuffer contexts; - uint64_t current_start; // start of current profiling run - uint64_t last_start; // start of last profiling run ~WallProfiler(); void Dispose(v8::Isolate* isolate); @@ -42,7 +43,8 @@ class WallProfiler : public Nan::ObjectWrap { // to work around https://bugs.chromium.org/p/v8/issues/detail?id=11051. v8::CpuProfiler* GetProfiler(); - LabelSetsByNode GetLabelSetsByNode(v8::CpuProfile* profile); + LabelSetsByNode GetLabelSetsByNode(v8::CpuProfile* profile, + uint64_t startTime); public: /** @@ -62,9 +64,13 @@ class WallProfiler : public Nan::ObjectWrap { return captured; } - void PushContext(); - void StartImpl(v8::Local name, bool includeLines, bool withLabels); - v8::Local StopImpl(v8::Local name, bool includeLines); + uint64_t PushContext(); + void StartImpl(v8::Local name, + bool includeLines, + bool withLabels); + v8::Local StopImpl(v8::Local name, + bool includeLines, + uint64_t startTime); static NAN_METHOD(New); static NAN_METHOD(Dispose); diff --git a/package.json b/package.json index 6856b442..2c3f40e9 100644 --- a/package.json +++ b/package.json @@ -10,6 +10,7 @@ "rebuild": "node-gyp rebuild --jobs=max", "test:js": "nyc mocha out/test/test-*.js", "test:cpp": "node scripts/cctest.js", + "test:wall": "nyc mocha out/test/test-time-profiler.js", "test": "npm run test:js && npm run test:cpp", "codecov": "nyc report --reporter=json && codecov -f coverage/*.json", "compile": "tsc -p .", diff --git a/ts/src/time-profiler.ts b/ts/src/time-profiler.ts index 1359b9af..62d62875 100644 --- a/ts/src/time-profiler.ts +++ b/ts/src/time-profiler.ts @@ -108,7 +108,7 @@ function startInternal( withLabels?: boolean ) { const profiler = new TimeProfiler(intervalMicros, durationMicros); - let runName = start(); + let runInfo = start(); return { stop: majorVersion < 16 ? stopOld : stop, setLabels, @@ -117,18 +117,18 @@ function startInternal( function start() { const runName = ensureRunName(name); - profiler.start(runName, lineNumbers, withLabels); - return runName; + const startTime = profiler.start(runName, lineNumbers, withLabels); + return {name: runName, startTime}; } // Node.js versions prior to v16 leak memory if not disposed and recreated // between each profile. As disposing deletes current profile data too, // we must stop then dispose then start. function stopOld(restart = false) { - const result = profiler.stop(runName, lineNumbers); + const result = profiler.stop(runInfo.name, lineNumbers, runInfo.startTime); profiler.dispose(); if (restart) { - runName = start(); + runInfo = start(); } return serializeTimeProfile(result, intervalMicros, sourceMapper, true); } @@ -137,19 +137,19 @@ function startInternal( // current one as otherwise the active profile count could reach zero which // means V8 might tear down the symbolizer thread and need to start it again. function stop(restart = false) { - let nextRunName; + let nextRunInfo; if (restart) { - nextRunName = start(); + nextRunInfo = start(); } - const result = profiler.stop(runName, lineNumbers); - if (nextRunName) { - runName = nextRunName; + const result = profiler.stop(runInfo.name, lineNumbers, runInfo.startTime); + if (nextRunInfo) { + runInfo = nextRunInfo; } if (!restart) profiler.dispose(); return serializeTimeProfile(result, intervalMicros, sourceMapper, true); } - function setLabels(labels: LabelSet) { + function setLabels(labels?: LabelSet) { profiler.labels = labels; } diff --git a/ts/test/test-time-profiler.ts b/ts/test/test-time-profiler.ts index 0319c559..49dbb76c 100644 --- a/ts/test/test-time-profiler.ts +++ b/ts/test/test-time-profiler.ts @@ -19,6 +19,9 @@ import * as sinon from 'sinon'; import * as time from '../src/time-profiler'; import * as v8TimeProfiler from '../src/time-profiler-bindings'; import {timeProfile, v8TimeProfile} from './profiles-for-tests'; +import {hrtime} from 'process'; +import {Label, Profile} from 'pprof-format'; +import {AssertionError} from 'assert'; const assert = require('assert'); @@ -42,13 +45,164 @@ describe('Time Profiler', () => { [-1, -1] ); }); + + it('should assign labels', () => { + const intervalNanos = PROFILE_OPTIONS.intervalMicros * 1_000; + const {stop, setLabels} = time.startWithLabels( + PROFILE_OPTIONS.intervalMicros, + PROFILE_OPTIONS.durationMillis + ); + // By repeating the test few times, we also exercise the profiler + // start-stop overlap behavior. + const repeats = 3; + for (let i = 0; i < repeats; ++i) { + loop(); + validateProfile(stop(i < repeats - 1)); + } + + // Each of fn0, fn1, fn2 loops busily for one or two profiling intervals. + // fn0 resets the label; fn1 and fn2 don't. Label for fn1 + // is reset in the loop. This ensures the following invariants that we + // test for: + // label0 can be observed in loop or fn0 + // label1 can be observed in loop or fn1 + // fn0 might be observed with no label + // fn1 must always be observed with label1 + // fn2 must never be observed with a label + function fn0() { + const start = hrtime.bigint(); + while (hrtime.bigint() - start < intervalNanos); + setLabels(undefined); + } + + function fn1() { + const start = hrtime.bigint(); + while (hrtime.bigint() - start < intervalNanos); + } + + function fn2() { + const start = hrtime.bigint(); + while (hrtime.bigint() - start < intervalNanos); + } + + function loop() { + const label0 = {label: 'value0'}; + const label1 = {label: 'value1'}; + const durationNanos = PROFILE_OPTIONS.durationMillis * 1_000_000; + const start = hrtime.bigint(); + while (hrtime.bigint() - start < durationNanos) { + setLabels(label0); + fn0(); + setLabels(label1); + fn1(); + setLabels(undefined); + fn2(); + } + } + + function validateProfile(profile: Profile) { + // Get string table indices for strings we're interested in + const stringTable = profile.stringTable; + const [ + loopIdx, + fn0Idx, + fn1Idx, + fn2Idx, + labelIdx, + value0Idx, + value1Idx, + ] = ['loop', 'fn0', 'fn1', 'fn2', 'label', 'value0', 'value1'].map(x => + stringTable.dedup(x) + ); + + function labelIs(l: Label, str: number) { + return l.key === labelIdx && l.str === str; + } + + function idx(n: number | bigint): number { + if (typeof n === 'number') { + // We want a 0-based array index, but IDs start from 1. + return n - 1; + } + throw new AssertionError({message: 'Expected a number'}); + } + + function labelStr(label: Label) { + return label ? stringTable.strings[idx(label.str) + 1] : "undefined"; + } + + let fn0ObservedWithLabel0 = false; + let fn1ObservedWithLabel1 = false; + let fn2ObservedWithoutLabels = false; + profile.sample.forEach(sample => { + const locIdx = idx(sample.locationId[0]); + const loc = profile.location[locIdx]; + const fnIdx = idx(loc.line[0].functionId); + const fn = profile.function[fnIdx]; + const fnName = fn.name; + const labels = sample.label; + switch (fnName) { + case loopIdx: + assert(labels.length < 2, 'loop can have at most one label'); + labels.forEach(label => { + assert( + labelIs(label, value0Idx) || labelIs(label, value1Idx), + 'loop can be observed with value0 or value1' + ); + }); + break; + case fn0Idx: + assert(labels.length < 2, 'fn0 can have at most one label'); + labels.forEach(label => { + if (labelIs(label, value0Idx)) { + fn0ObservedWithLabel0 = true; + } else { + throw new AssertionError({ + message: + 'Only value0 can be observed with fn0. Observed instead ' + + labelStr(label), + }); + } + }); + break; + case fn1Idx: + assert(labels.length === 1, 'fn1 must be observed with a label'); + labels.forEach(label => { + assert( + labelIs(label, value1Idx), + 'Only value1 can be observed with fn1' + ); + }); + fn1ObservedWithLabel1 = true; + break; + case fn2Idx: + assert( + labels.length === 0, + 'fn2 must be observed with no labels. Observed instead with ' + + labelStr(labels[0]) + ); + fn2ObservedWithoutLabels = true; + break; + default: + // Make no assumptions about other functions; we can just as well + // capture internals of time-profiler.ts, GC, etc. + } + }); + assert(fn0ObservedWithLabel0, 'fn0 was not observed with value0'); + assert(fn1ObservedWithLabel1, 'fn1 was not observed with value1'); + assert( + fn2ObservedWithoutLabels, + 'fn2 was not observed without a label' + ); + } + }); }); describe('profile (w/ stubs)', () => { // eslint-disable-next-line @typescript-eslint/no-explicit-any const sinonStubs: Array> = []; const timeProfilerStub = { - start: sinon.stub(), + start: sinon.stub().returns(BigInt(0)), stop: sinon.stub().returns(v8TimeProfile), dispose: sinon.stub(), }; From cdf42b1310b3c0747237c19695c178ba31ce59ff Mon Sep 17 00:00:00 2001 From: Attila Szegedi Date: Fri, 2 Jun 2023 13:06:16 +0200 Subject: [PATCH 18/27] Suggestions from Nicolas' review, minus the atomic update of profilers map --- bindings/profilers/wall.cc | 10 ++++------ bindings/profilers/wall.hh | 13 +++++-------- ts/src/time-profiler.ts | 6 +++--- ts/test/test-time-profiler.ts | 2 +- 4 files changed, 13 insertions(+), 18 deletions(-) diff --git a/bindings/profilers/wall.cc b/bindings/profilers/wall.cc index c6a693e2..5d79f28c 100644 --- a/bindings/profilers/wall.cc +++ b/bindings/profilers/wall.cc @@ -363,7 +363,7 @@ LabelSetsByNode WallProfiler::GetLabelSetsByNode(CpuProfile* profile, return labelSetsByNode; } sampleContext = contexts.pop_front(); - break; // don't match more than one context to one sample + break; // don't match more than one context to one sample } } } @@ -373,8 +373,6 @@ LabelSetsByNode WallProfiler::GetLabelSetsByNode(CpuProfile* profile, return labelSetsByNode; } -static Nan::Persistent constructor; - WallProfiler::WallProfiler(int intervalMicros, int durationMicros) : samplingInterval(intervalMicros), contexts(durationMicros * 2 / intervalMicros) {} @@ -438,7 +436,7 @@ NAN_METHOD(WallProfiler::New) { return Nan::ThrowTypeError("Sample rate must be a number."); } - if (!info[0]->IsNumber()) { + if (!info[1]->IsNumber()) { return Nan::ThrowTypeError("Duration must be a number."); } @@ -464,8 +462,8 @@ NAN_METHOD(WallProfiler::New) { obj->Wrap(info.This()); info.GetReturnValue().Set(info.This()); } else { - const int argc = 1; - v8::Local argv[argc] = {info[0]}; + const int argc = 2; + v8::Local argv[argc] = {info[0], info[1]}; v8::Local cons = Nan::New( PerIsolateData::For(info.GetIsolate())->WallProfilerConstructor()); info.GetReturnValue().Set( diff --git a/bindings/profilers/wall.hh b/bindings/profilers/wall.hh index e0e5f38e..59e36907 100644 --- a/bindings/profilers/wall.hh +++ b/bindings/profilers/wall.hh @@ -2,7 +2,9 @@ #include #include +#include #include +#include #include "../buffer.hh" @@ -28,10 +30,9 @@ class WallProfiler : public Nan::ObjectWrap { uint64_t timestamp; // Needed to initialize ring buffer elements - SampleContext() {} + SampleContext() = default; - SampleContext(std::shared_ptr> l, uint64_t t) - : labels(l), timestamp(t) {} + SampleContext(const ValuePtr& l, uint64_t t) : labels(l), timestamp(t) {} }; RingBuffer contexts; @@ -58,11 +59,7 @@ class WallProfiler : public Nan::ObjectWrap { v8::Local GetLabels(v8::Isolate*); void SetLabels(v8::Isolate*, v8::Local); - bool GetLabelsCaptured() { - bool captured = labelsCaptured; - labelsCaptured = false; - return captured; - } + bool GetLabelsCaptured() { return std::exchange(labelsCaptured, false); } uint64_t PushContext(); void StartImpl(v8::Local name, diff --git a/ts/src/time-profiler.ts b/ts/src/time-profiler.ts index 62d62875..ea7c691c 100644 --- a/ts/src/time-profiler.ts +++ b/ts/src/time-profiler.ts @@ -22,7 +22,7 @@ import {TimeProfiler} from './time-profiler-bindings'; import {LabelSet} from './v8-types'; const DEFAULT_INTERVAL_MICROS: Microseconds = 1000; -const DEFAULT_DURATION_MILLIS: Milliseconds = 60000; +const DEFAULT_DURATION_MICROS: Microseconds = 60000000; const majorVersion = process.version.slice(1).split('.').map(Number)[0]; @@ -83,14 +83,14 @@ export function start( export function startWithLabels( intervalMicros: Microseconds = DEFAULT_INTERVAL_MICROS, - durationMillis: Milliseconds = DEFAULT_DURATION_MILLIS, + durationMicros: Microseconds = DEFAULT_DURATION_MICROS, name?: string, sourceMapper?: SourceMapper, lineNumbers = true ) { return startInternal( intervalMicros, - durationMillis * 1000, + durationMicros, name, sourceMapper, lineNumbers, diff --git a/ts/test/test-time-profiler.ts b/ts/test/test-time-profiler.ts index 49dbb76c..82a6f2ac 100644 --- a/ts/test/test-time-profiler.ts +++ b/ts/test/test-time-profiler.ts @@ -50,7 +50,7 @@ describe('Time Profiler', () => { const intervalNanos = PROFILE_OPTIONS.intervalMicros * 1_000; const {stop, setLabels} = time.startWithLabels( PROFILE_OPTIONS.intervalMicros, - PROFILE_OPTIONS.durationMillis + PROFILE_OPTIONS.durationMillis * 1000 ); // By repeating the test few times, we also exercise the profiler // start-stop overlap behavior. From a30739b468357eabf8cb5485303805c7ba70cbd7 Mon Sep 17 00:00:00 2001 From: Attila Szegedi Date: Mon, 5 Jun 2023 09:35:38 +0200 Subject: [PATCH 19/27] Safe atomics for profiler map --- bindings/profilers/wall.cc | 39 +++++++++++++++++++++++++++----------- 1 file changed, 28 insertions(+), 11 deletions(-) diff --git a/bindings/profilers/wall.cc b/bindings/profilers/wall.cc index 5d79f28c..85507d3c 100644 --- a/bindings/profilers/wall.cc +++ b/bindings/profilers/wall.cc @@ -17,6 +17,7 @@ #include #include #include +#include #include #include @@ -39,18 +40,27 @@ namespace dd { using ProfilerMap = std::unordered_map; static std::atomic profilers(new ProfilerMap()); +static std::mutex update_profilers; #ifdef DD_WALL_USE_SIGPROF static void (*old_handler)(int, siginfo_t*, void*) = nullptr; static void sighandler(int sig, siginfo_t* info, void* context) { - auto prof_map = profilers.load(); - auto prof_it = prof_map->find(Isolate::GetCurrent()); + auto isolate = Isolate::GetCurrent(); + WallProfiler* prof = nullptr; + auto prof_map = profilers.exchange(nullptr, std::memory_order_acq_rel); + if (prof_map) { + auto prof_it = prof_map->find(isolate); + if (prof_it != prof_map->end()) { + prof = prof_it->second; + } + profilers.store(prof_map, std::memory_order_release); + } if (old_handler) { old_handler(sig, info, context); } - if (prof_it != prof_map->end()) { - prof_it->second->PushContext(); + if (prof) { + prof->PushContext(); } } #endif @@ -383,17 +393,24 @@ WallProfiler::~WallProfiler() { template void updateProfilers(F updateFn) { - auto currProfilers = profilers.load(); + std::lock_guard lock(update_profilers); + auto currProfilers = profilers.load(std::memory_order_acquire); + // Wait until sighandler is done using the map + while (!currProfilers) { + currProfilers = profilers.load(std::memory_order_relaxed); + } + auto newProfilers = new ProfilerMap(*currProfilers); + updateFn(newProfilers); + // Wait until sighandler is done using the map before installing a new map. + // The value in profilers is either nullptr or currProfilers. for (;;) { - auto newProfilers = new ProfilerMap(*currProfilers); - updateFn(newProfilers); - if (profilers.compare_exchange_weak(currProfilers, newProfilers)) { - delete currProfilers; + ProfilerMap* currProfilers2 = currProfilers; + if (profilers.compare_exchange_weak( + currProfilers2, newProfilers, std::memory_order_acq_rel)) { break; - } else { - delete newProfilers; } } + delete currProfilers; } void WallProfiler::Dispose(Isolate* isolate) { From 89dc34d51e5349b0dbf16d79ce7553e8ec1b48d5 Mon Sep 17 00:00:00 2001 From: Attila Szegedi Date: Mon, 5 Jun 2023 15:05:59 +0200 Subject: [PATCH 20/27] unsigneds are evil --- bindings/profilers/wall.cc | 28 ++++++++++++++-------------- bindings/profilers/wall.hh | 10 +++++----- 2 files changed, 19 insertions(+), 19 deletions(-) diff --git a/bindings/profilers/wall.cc b/bindings/profilers/wall.cc index 85507d3c..6373c454 100644 --- a/bindings/profilers/wall.cc +++ b/bindings/profilers/wall.cc @@ -289,7 +289,7 @@ bool isIdleSample(const CpuProfileNode* sample) { } LabelSetsByNode WallProfiler::GetLabelSetsByNode(CpuProfile* profile, - uint64_t startTime) { + int64_t startTime) { LabelSetsByNode labelSetsByNode; if (contexts.empty() || profile->GetSamplesCount() == 0) { @@ -299,7 +299,7 @@ LabelSetsByNode WallProfiler::GetLabelSetsByNode(CpuProfile* profile, SampleContext sampleContext = contexts.pop_front(); auto sampleCount = profile->GetSamplesCount(); - uint64_t halfInterval = + auto halfInterval = (sampleCount > 1 ? (profile->GetSampleTimestamp(sampleCount - 1) - profile->GetSampleTimestamp(0)) / (sampleCount - 1) @@ -313,24 +313,24 @@ LabelSetsByNode WallProfiler::GetLabelSetsByNode(CpuProfile* profile, // Sample times are in micros, context times are // in nanos. We are using these values - adjusted for half interval in the // past so we don't suffer any overflows anywhere in the arithmetic below. - int64_t zeroSampleTime = profile->GetSampleTimestamp(0) - halfInterval; - uint64_t zeroContextTime = startTime - halfInterval * 1000; + auto zeroSampleTime = profile->GetSampleTimestamp(0) - halfInterval; + auto zeroContextTime = startTime - halfInterval * 1000; for (int i = 0; i < sampleCount; i++) { auto sample = profile->GetSample(i); if (isIdleSample(sample)) { continue; } - int64_t sampleTimestamp = profile->GetSampleTimestamp(i) - zeroSampleTime; + auto sampleTimestamp = profile->GetSampleTimestamp(i) - zeroSampleTime; // Compute earliest (inclusive) and latest (exclusive) context timestamps // that can belong to this sample. Use half the distance to neighboring // samples, or barring that half the sampling interval - uint64_t earliest = + auto earliest = 1000 * (i > 0 ? (sampleTimestamp + (profile->GetSampleTimestamp(i - 1) - zeroSampleTime)) / 2 : (sampleTimestamp - halfInterval)); - uint64_t latest = + auto latest = 1000 * (i < sampleCount - 1 ? (sampleTimestamp + (profile->GetSampleTimestamp(i + 1) - zeroSampleTime)) / @@ -532,7 +532,7 @@ NAN_METHOD(WallProfiler::Start) { } } #endif - auto bi_now = BigInt::NewFromUnsigned(info.GetIsolate(), now); + auto bi_now = BigInt::New(info.GetIsolate(), now); info.GetReturnValue().Set(bi_now); } @@ -568,9 +568,9 @@ NAN_METHOD(WallProfiler::Stop) { bool includeLines = Nan::MaybeLocal(info[1].As()).ToLocalChecked()->Value(); - uint64_t startTime = Nan::MaybeLocal(info[2].As()) - .ToLocalChecked() - ->Uint64Value(); + auto startTime = Nan::MaybeLocal(info[2].As()) + .ToLocalChecked() + ->Int64Value(); WallProfiler* wallProfiler = Nan::ObjectWrap::Unwrap(info.Holder()); @@ -582,7 +582,7 @@ NAN_METHOD(WallProfiler::Stop) { Local WallProfiler::StopImpl(Local name, bool includeLines, - uint64_t startTime) { + int64_t startTime) { auto profiler = GetProfiler(); auto v8_profile = profiler->StopProfiling(name); Local profile = @@ -660,11 +660,11 @@ NAN_GETTER(WallProfiler::GetLabelsCaptured) { info.GetReturnValue().Set(profiler->GetLabelsCaptured()); } -uint64_t WallProfiler::PushContext() { +int64_t WallProfiler::PushContext() { // Be careful this is called in a signal handler context therefore all // operations must be async signal safe (in particular no allocations). Our // ring buffer avoids allocations. - auto now = uv_hrtime(); + int64_t now = uv_hrtime(); contexts.push_back(SampleContext(labels_, now)); if (labels_) { labelsCaptured = true; diff --git a/bindings/profilers/wall.hh b/bindings/profilers/wall.hh index 59e36907..9c9789e8 100644 --- a/bindings/profilers/wall.hh +++ b/bindings/profilers/wall.hh @@ -27,12 +27,12 @@ class WallProfiler : public Nan::ObjectWrap { struct SampleContext { ValuePtr labels; - uint64_t timestamp; + int64_t timestamp; // Needed to initialize ring buffer elements SampleContext() = default; - SampleContext(const ValuePtr& l, uint64_t t) : labels(l), timestamp(t) {} + SampleContext(const ValuePtr& l, int64_t t) : labels(l), timestamp(t) {} }; RingBuffer contexts; @@ -45,7 +45,7 @@ class WallProfiler : public Nan::ObjectWrap { v8::CpuProfiler* GetProfiler(); LabelSetsByNode GetLabelSetsByNode(v8::CpuProfile* profile, - uint64_t startTime); + int64_t startTime); public: /** @@ -61,13 +61,13 @@ class WallProfiler : public Nan::ObjectWrap { void SetLabels(v8::Isolate*, v8::Local); bool GetLabelsCaptured() { return std::exchange(labelsCaptured, false); } - uint64_t PushContext(); + int64_t PushContext(); void StartImpl(v8::Local name, bool includeLines, bool withLabels); v8::Local StopImpl(v8::Local name, bool includeLines, - uint64_t startTime); + int64_t startTime); static NAN_METHOD(New); static NAN_METHOD(Dispose); From 7898fe8d38d425c4d1ca518475424e82bd5dc8b7 Mon Sep 17 00:00:00 2001 From: Attila Szegedi Date: Tue, 6 Jun 2023 14:13:52 +0200 Subject: [PATCH 21/27] Avoid the need for clock sync by ensuring we use the same clock as V8 does --- bindings/profilers/wall.cc | 68 +++++++++++++------------------------- bindings/profilers/wall.hh | 6 ++-- ts/src/time-profiler.ts | 20 +++++------ 3 files changed, 35 insertions(+), 59 deletions(-) diff --git a/bindings/profilers/wall.cc b/bindings/profilers/wall.cc index 6373c454..3fed6017 100644 --- a/bindings/profilers/wall.cc +++ b/bindings/profilers/wall.cc @@ -33,6 +33,16 @@ #undef DD_WALL_USE_SIGPROF #endif +// Declare v8::base::TimeTicks::Now. It is exported from the node executable so +// our addon will be able to dynamically link to the symbol when loaded. +namespace v8 { + namespace base { + struct TimeTicks { + static int64_t Now(); + }; + } +} + using namespace v8; namespace dd { @@ -288,8 +298,7 @@ bool isIdleSample(const CpuProfileNode* sample) { strncmp("(idle)", sample->GetFunctionNameStr(), 7) == 0; } -LabelSetsByNode WallProfiler::GetLabelSetsByNode(CpuProfile* profile, - int64_t startTime) { +LabelSetsByNode WallProfiler::GetLabelSetsByNode(CpuProfile* profile) { LabelSetsByNode labelSetsByNode; if (contexts.empty() || profile->GetSamplesCount() == 0) { @@ -306,35 +315,16 @@ LabelSetsByNode WallProfiler::GetLabelSetsByNode(CpuProfile* profile, : samplingInterval) / 2; - // Assumption is that startTime and profile->GetSampleTimestamp(0) were both - // taken very closely to each other in real time so they can be used as a - // common point of time origin, since startTime is taken in - // WallProfiler::Start just after calling WallProfiler::StartImpl. - // Sample times are in micros, context times are - // in nanos. We are using these values - adjusted for half interval in the - // past so we don't suffer any overflows anywhere in the arithmetic below. - auto zeroSampleTime = profile->GetSampleTimestamp(0) - halfInterval; - auto zeroContextTime = startTime - halfInterval * 1000; for (int i = 0; i < sampleCount; i++) { auto sample = profile->GetSample(i); if (isIdleSample(sample)) { continue; } - auto sampleTimestamp = profile->GetSampleTimestamp(i) - zeroSampleTime; - // Compute earliest (inclusive) and latest (exclusive) context timestamps - // that can belong to this sample. Use half the distance to neighboring - // samples, or barring that half the sampling interval - auto earliest = - 1000 * (i > 0 ? (sampleTimestamp + (profile->GetSampleTimestamp(i - 1) - - zeroSampleTime)) / - 2 - : (sampleTimestamp - halfInterval)); + auto sampleTimestamp = profile->GetSampleTimestamp(i); auto latest = - 1000 * (i < sampleCount - 1 - ? (sampleTimestamp + - (profile->GetSampleTimestamp(i + 1) - zeroSampleTime)) / - 2 + (i < sampleCount - 1 + ? (sampleTimestamp + profile->GetSampleTimestamp(i + 1)) / 2 : (sampleTimestamp + halfInterval)); // This loop will drop all contexts that are too old to be associated with @@ -342,8 +332,8 @@ LabelSetsByNode WallProfiler::GetLabelSetsByNode(CpuProfile* profile, // to it in time, and stop as soon as it sees a context that's too recent // for this sample. for (;;) { - auto contextTimestamp = sampleContext.timestamp - zeroContextTime; - if (contextTimestamp < earliest) { + auto contextTimestamp = sampleContext.timestamp; + if (contextTimestamp < sampleTimestamp) { // Current sample context is too old (closer to the previous sample than // to this one), discard it and fetch the next one. if (contexts.empty()) { @@ -515,10 +505,9 @@ NAN_METHOD(WallProfiler::Start) { Nan::MaybeLocal(info[2].As()).ToLocalChecked()->Value(); wallProfiler->StartImpl(name, includeLines, withLabels); - auto now = withLabels ? wallProfiler->PushContext() : uv_hrtime(); - #ifdef DD_WALL_USE_SIGPROF if (withLabels) { + wallProfiler->PushContext(); struct sigaction sa, old_sa; sa.sa_flags = SA_SIGINFO | SA_RESTART; sa.sa_sigaction = &sighandler; @@ -532,8 +521,6 @@ NAN_METHOD(WallProfiler::Start) { } } #endif - auto bi_now = BigInt::New(info.GetIsolate(), now); - info.GetReturnValue().Set(bi_now); } void WallProfiler::StartImpl(Local name, @@ -548,8 +535,8 @@ void WallProfiler::StartImpl(Local name, } NAN_METHOD(WallProfiler::Stop) { - if (info.Length() != 3) { - return Nan::ThrowTypeError("Stop must have three arguments."); + if (info.Length() != 2) { + return Nan::ThrowTypeError("Stop must have two arguments."); } if (!info[0]->IsString()) { return Nan::ThrowTypeError("Profile name must be a string."); @@ -558,35 +545,26 @@ NAN_METHOD(WallProfiler::Stop) { return Nan::ThrowTypeError("Include lines must be a boolean."); } - if (!info[2]->IsBigInt()) { - return Nan::ThrowTypeError("Start time must be a bigint."); - } - Local name = Nan::MaybeLocal(info[0].As()).ToLocalChecked(); bool includeLines = Nan::MaybeLocal(info[1].As()).ToLocalChecked()->Value(); - auto startTime = Nan::MaybeLocal(info[2].As()) - .ToLocalChecked() - ->Int64Value(); - WallProfiler* wallProfiler = Nan::ObjectWrap::Unwrap(info.Holder()); - auto profile = wallProfiler->StopImpl(name, includeLines, startTime); + auto profile = wallProfiler->StopImpl(name, includeLines); info.GetReturnValue().Set(profile); } Local WallProfiler::StopImpl(Local name, - bool includeLines, - int64_t startTime) { + bool includeLines) { auto profiler = GetProfiler(); auto v8_profile = profiler->StopProfiling(name); Local profile = - ProfileTranslator(GetLabelSetsByNode(v8_profile, startTime)) + ProfileTranslator(GetLabelSetsByNode(v8_profile)) .TranslateTimeProfile(v8_profile, includeLines); v8_profile->Delete(); return profile; @@ -664,7 +642,7 @@ int64_t WallProfiler::PushContext() { // Be careful this is called in a signal handler context therefore all // operations must be async signal safe (in particular no allocations). Our // ring buffer avoids allocations. - int64_t now = uv_hrtime(); + int64_t now = v8::base::TimeTicks::Now(); contexts.push_back(SampleContext(labels_, now)); if (labels_) { labelsCaptured = true; diff --git a/bindings/profilers/wall.hh b/bindings/profilers/wall.hh index 9c9789e8..53eb1c83 100644 --- a/bindings/profilers/wall.hh +++ b/bindings/profilers/wall.hh @@ -44,8 +44,7 @@ class WallProfiler : public Nan::ObjectWrap { // to work around https://bugs.chromium.org/p/v8/issues/detail?id=11051. v8::CpuProfiler* GetProfiler(); - LabelSetsByNode GetLabelSetsByNode(v8::CpuProfile* profile, - int64_t startTime); + LabelSetsByNode GetLabelSetsByNode(v8::CpuProfile* profile); public: /** @@ -66,8 +65,7 @@ class WallProfiler : public Nan::ObjectWrap { bool includeLines, bool withLabels); v8::Local StopImpl(v8::Local name, - bool includeLines, - int64_t startTime); + bool includeLines); static NAN_METHOD(New); static NAN_METHOD(Dispose); diff --git a/ts/src/time-profiler.ts b/ts/src/time-profiler.ts index ea7c691c..3ea36224 100644 --- a/ts/src/time-profiler.ts +++ b/ts/src/time-profiler.ts @@ -108,7 +108,7 @@ function startInternal( withLabels?: boolean ) { const profiler = new TimeProfiler(intervalMicros, durationMicros); - let runInfo = start(); + let runName = start(); return { stop: majorVersion < 16 ? stopOld : stop, setLabels, @@ -117,18 +117,18 @@ function startInternal( function start() { const runName = ensureRunName(name); - const startTime = profiler.start(runName, lineNumbers, withLabels); - return {name: runName, startTime}; + profiler.start(runName, lineNumbers, withLabels); + return runName; } // Node.js versions prior to v16 leak memory if not disposed and recreated // between each profile. As disposing deletes current profile data too, // we must stop then dispose then start. function stopOld(restart = false) { - const result = profiler.stop(runInfo.name, lineNumbers, runInfo.startTime); + const result = profiler.stop(runName, lineNumbers); profiler.dispose(); if (restart) { - runInfo = start(); + runName = start(); } return serializeTimeProfile(result, intervalMicros, sourceMapper, true); } @@ -137,13 +137,13 @@ function startInternal( // current one as otherwise the active profile count could reach zero which // means V8 might tear down the symbolizer thread and need to start it again. function stop(restart = false) { - let nextRunInfo; + let nextRunName; if (restart) { - nextRunInfo = start(); + nextRunName = start(); } - const result = profiler.stop(runInfo.name, lineNumbers, runInfo.startTime); - if (nextRunInfo) { - runInfo = nextRunInfo; + const result = profiler.stop(runName, lineNumbers); + if (nextRunName) { + runName = nextRunName; } if (!restart) profiler.dispose(); return serializeTimeProfile(result, intervalMicros, sourceMapper, true); From 2fb0442a03129eb686fb0a1ec5c3c2de8a07ae5b Mon Sep 17 00:00:00 2001 From: Attila Szegedi Date: Fri, 9 Jun 2023 15:13:45 +0200 Subject: [PATCH 22/27] Use time intervals for matching sample contexts --- bindings/profilers/wall.cc | 43 ++++++++++++++------------------------ bindings/profilers/wall.hh | 7 ++++--- 2 files changed, 20 insertions(+), 30 deletions(-) diff --git a/bindings/profilers/wall.cc b/bindings/profilers/wall.cc index 3fed6017..40a2006c 100644 --- a/bindings/profilers/wall.cc +++ b/bindings/profilers/wall.cc @@ -56,6 +56,10 @@ static std::mutex update_profilers; static void (*old_handler)(int, siginfo_t*, void*) = nullptr; static void sighandler(int sig, siginfo_t* info, void* context) { + if (!old_handler) { + return; + } + auto isolate = Isolate::GetCurrent(); WallProfiler* prof = nullptr; auto prof_map = profilers.exchange(nullptr, std::memory_order_acq_rel); @@ -66,11 +70,10 @@ static void sighandler(int sig, siginfo_t* info, void* context) { } profilers.store(prof_map, std::memory_order_release); } - if (old_handler) { - old_handler(sig, info, context); - } + auto now = v8::base::TimeTicks::Now(); + old_handler(sig, info, context); if (prof) { - prof->PushContext(); + prof->PushContext(now); } } #endif @@ -308,13 +311,6 @@ LabelSetsByNode WallProfiler::GetLabelSetsByNode(CpuProfile* profile) { SampleContext sampleContext = contexts.pop_front(); auto sampleCount = profile->GetSamplesCount(); - auto halfInterval = - (sampleCount > 1 ? (profile->GetSampleTimestamp(sampleCount - 1) - - profile->GetSampleTimestamp(0)) / - (sampleCount - 1) - : samplingInterval) / - 2; - for (int i = 0; i < sampleCount; i++) { auto sample = profile->GetSample(i); @@ -322,27 +318,21 @@ LabelSetsByNode WallProfiler::GetLabelSetsByNode(CpuProfile* profile) { continue; } auto sampleTimestamp = profile->GetSampleTimestamp(i); - auto latest = - (i < sampleCount - 1 - ? (sampleTimestamp + profile->GetSampleTimestamp(i + 1)) / 2 - : (sampleTimestamp + halfInterval)); // This loop will drop all contexts that are too old to be associated with // the current sample; associate those (normally one) that are close enough // to it in time, and stop as soon as it sees a context that's too recent // for this sample. for (;;) { - auto contextTimestamp = sampleContext.timestamp; - if (contextTimestamp < sampleTimestamp) { - // Current sample context is too old (closer to the previous sample than - // to this one), discard it and fetch the next one. + if (sampleContext.time_to < sampleTimestamp) { + // Current sample context is too old, discard it and fetch the next one. if (contexts.empty()) { return labelSetsByNode; } sampleContext = contexts.pop_front(); - } else if (contextTimestamp >= latest) { - // Current sample context is too recent (closer to the next sample than - // to this one), we'll try to match it to the next sample. + } else if (sampleContext.time_from > sampleTimestamp) { + // Current sample context is too recent, we'll try to match it to the + // next sample. break; } else { // This sample context is the closest to this sample. @@ -504,10 +494,11 @@ NAN_METHOD(WallProfiler::Start) { bool withLabels = Nan::MaybeLocal(info[2].As()).ToLocalChecked()->Value(); + auto now = v8::base::TimeTicks::Now(); wallProfiler->StartImpl(name, includeLines, withLabels); #ifdef DD_WALL_USE_SIGPROF if (withLabels) { - wallProfiler->PushContext(); + wallProfiler->PushContext(now); struct sigaction sa, old_sa; sa.sa_flags = SA_SIGINFO | SA_RESTART; sa.sa_sigaction = &sighandler; @@ -638,16 +629,14 @@ NAN_GETTER(WallProfiler::GetLabelsCaptured) { info.GetReturnValue().Set(profiler->GetLabelsCaptured()); } -int64_t WallProfiler::PushContext() { +void WallProfiler::PushContext(int64_t time_from) { // Be careful this is called in a signal handler context therefore all // operations must be async signal safe (in particular no allocations). Our // ring buffer avoids allocations. - int64_t now = v8::base::TimeTicks::Now(); - contexts.push_back(SampleContext(labels_, now)); + contexts.push_back(SampleContext(labels_, time_from, v8::base::TimeTicks::Now())); if (labels_) { labelsCaptured = true; } - return now; } } // namespace dd diff --git a/bindings/profilers/wall.hh b/bindings/profilers/wall.hh index 53eb1c83..57bd62f5 100644 --- a/bindings/profilers/wall.hh +++ b/bindings/profilers/wall.hh @@ -27,12 +27,13 @@ class WallProfiler : public Nan::ObjectWrap { struct SampleContext { ValuePtr labels; - int64_t timestamp; + int64_t time_from; + int64_t time_to; // Needed to initialize ring buffer elements SampleContext() = default; - SampleContext(const ValuePtr& l, int64_t t) : labels(l), timestamp(t) {} + SampleContext(const ValuePtr& l, int64_t from, int64_t to) : labels(l), time_from(from), time_to(to) {} }; RingBuffer contexts; @@ -60,7 +61,7 @@ class WallProfiler : public Nan::ObjectWrap { void SetLabels(v8::Isolate*, v8::Local); bool GetLabelsCaptured() { return std::exchange(labelsCaptured, false); } - int64_t PushContext(); + void PushContext(int64_t time_from); void StartImpl(v8::Local name, bool includeLines, bool withLabels); From e7ce771df6138c429f5e47ef76f0862dffa7a992 Mon Sep 17 00:00:00 2001 From: Attila Szegedi Date: Fri, 9 Jun 2023 15:14:25 +0200 Subject: [PATCH 23/27] Remove CPU profiler tests. CpuProfiler causes crashes in tests, WONTFIX. --- ts/test/test-cpu-profiler.ts | 167 ----------------------------------- 1 file changed, 167 deletions(-) delete mode 100644 ts/test/test-cpu-profiler.ts diff --git a/ts/test/test-cpu-profiler.ts b/ts/test/test-cpu-profiler.ts deleted file mode 100644 index 043ad872..00000000 --- a/ts/test/test-cpu-profiler.ts +++ /dev/null @@ -1,167 +0,0 @@ -/** - * Copyright 2017 Google Inc. All Rights Reserved. - * - * Licensed under the Apache License, Version 2.0 (the "License"); - * you may not use this file except in compliance with the License. - * You may obtain a copy of the License at - * - * http://www.apache.org/licenses/LICENSE-2.0 - * - * Unless required by applicable law or agreed to in writing, software - * distributed under the License is distributed on an "AS IS" BASIS, - * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. - * See the License for the specific language governing permissions and - * limitations under the License. - */ - -import CpuProfiler from '../src/cpu-profiler'; -import {Profile, ValueType} from 'pprof-format'; - -const assert = require('assert'); - -// eslint-disable-next-line @typescript-eslint/no-explicit-any -function str(profile: Profile, index: any) { - return profile.stringTable.strings![index as number]; -} - -function verifyValueType(profile: Profile, valueType: ValueType, name: string) { - const type = str(profile, valueType.type!); - const unit = str(profile, valueType.unit!); - - assert.strictEqual( - `${type}/${unit}`, - name, - 'has expected type and unit for value type' - ); -} - -function verifySampleType(profile: Profile, index: number, name: string) { - const sampleType = profile.sampleType![index]; - verifyValueType(profile, sampleType, name); -} - -function verifyPeriodType(profile: Profile, name: string) { - verifyValueType(profile, profile.periodType!, name); -} - -function verifyFunction(profile: Profile, index: number) { - const fn = profile.function![index]; - assert.ok(fn, 'has function matching function id'); - assert.ok(fn.id! >= 0, 'has id for function'); - - assert.strictEqual( - typeof str(profile, fn.name), - 'string', - 'has name in string table for function' - ); - assert.strictEqual( - typeof str(profile, fn.systemName), - 'string', - 'has systemName in string table for function' - ); - assert.strictEqual( - typeof str(profile, fn.filename), - 'string', - 'has filename in string table for function' - ); -} - -function verifyLocation(profile: Profile, index: number) { - const location = profile.location![index]; - assert.ok(location, 'has location matching location id'); - assert.ok(location.id! > 0, 'has id for location'); - - for (const line of location.line!) { - assert.ok(line.line! >= 0, 'has line number for line record'); - verifyFunction(profile, (line.functionId! as number) - 1); - } -} - -function verifySample(profile: Profile, index: number) { - const sample = profile.sample![index]; - for (const locationId of sample.locationId!) { - verifyLocation(profile, (locationId as number) - 1); - } - assert.strictEqual( - sample.value!.length, - 2, - 'has expected number of values in sample' - ); -} - -function busyWait(ms: number) { - return new Promise(resolve => { - let done = false; - function work() { - if (done) return; - let sum = 0; - for (let i = 0; i < 1e6; i++) { - sum += sum; - } - setImmediate(work, sum); - } - setImmediate(work); - setTimeout(() => { - done = true; - resolve(undefined); - }, ms); - }); -} - -describe('CPU Profiler', () => { - describe('profile', () => { - it('should have valid basic structure', async () => { - const data = {str: 'foo', num: 123}; - const cpu = new CpuProfiler(); - cpu.labels = data; - cpu.start(99); - await busyWait(100); - const profile = cpu.profile()!; - cpu.stop(); - - verifySampleType(profile, 0, 'sample/count'); - verifySampleType(profile, 1, 'cpu/nanoseconds'); - // verifySampleType(profile, 2, 'wall/nanoseconds'); - verifyPeriodType(profile, 'cpu/nanoseconds'); - - assert.strictEqual(profile.period, 1e9 / 99); - assert.ok(profile.durationNanos! > 0); - assert.ok(profile.timeNanos! > 0); - - assert.ok(profile.sample!.length > 0); - assert.ok(profile.location!.length > 0); - assert.ok(profile.function!.length > 0); - - verifySample(profile, 0); - - const {label = []} = profile.sample![0]; - assert.notEqual(label, null); - if (label === null) return; // Appease TypeScript. - assert.strictEqual(label.length, 2); - assert.strictEqual(str(profile, label[0].key! as number), 'str'); - assert.strictEqual(str(profile, label[0].str! as number), 'foo'); - assert.strictEqual(str(profile, label[1].key! as number), 'num'); - assert.strictEqual(label[1].num!, 123); - }); - - it('should have timeNanos gap that roughly matches durationNanos', async () => { - const wait = 100; - // Need 10% wiggle room due to precision loss in timeNanos - const minimumDuration = wait * 1e6 * 0.9; - const cpu = new CpuProfiler(); - cpu.start(99); - - await busyWait(wait); - const first = cpu.profile()!; - assert.ok(first.durationNanos! >= minimumDuration); - - await busyWait(wait); - const second = cpu.profile()!; - assert.ok( - second.timeNanos! >= (first.timeNanos! as number) + minimumDuration - ); - assert.ok(second.durationNanos! >= minimumDuration); - cpu.stop(); - }); - }); -}); From a0e18d5dc9d52d4b2dc6e8ce9e46ba53ed8eb3b9 Mon Sep 17 00:00:00 2001 From: Attila Szegedi Date: Fri, 9 Jun 2023 15:17:27 +0200 Subject: [PATCH 24/27] Remove labelsCaptured logic --- bindings/profilers/wall.cc | 12 ------------ bindings/profilers/wall.hh | 3 --- ts/src/time-profiler.ts | 7 +------ 3 files changed, 1 insertion(+), 21 deletions(-) diff --git a/bindings/profilers/wall.cc b/bindings/profilers/wall.cc index 40a2006c..caa306ff 100644 --- a/bindings/profilers/wall.cc +++ b/bindings/profilers/wall.cc @@ -572,10 +572,6 @@ NAN_MODULE_INIT(WallProfiler::Init) { GetLabels, SetLabels); - Nan::SetAccessor(tpl->InstanceTemplate(), - Nan::New("labelsCaptured").ToLocalChecked(), - GetLabelsCaptured); - Nan::SetPrototypeMethod(tpl, "start", Start); Nan::SetPrototypeMethod(tpl, "dispose", Dispose); Nan::SetPrototypeMethod(tpl, "stop", Stop); @@ -624,19 +620,11 @@ NAN_SETTER(WallProfiler::SetLabels) { profiler->SetLabels(info.GetIsolate(), value); } -NAN_GETTER(WallProfiler::GetLabelsCaptured) { - auto profiler = Nan::ObjectWrap::Unwrap(info.Holder()); - info.GetReturnValue().Set(profiler->GetLabelsCaptured()); -} - void WallProfiler::PushContext(int64_t time_from) { // Be careful this is called in a signal handler context therefore all // operations must be async signal safe (in particular no allocations). Our // ring buffer avoids allocations. contexts.push_back(SampleContext(labels_, time_from, v8::base::TimeTicks::Now())); - if (labels_) { - labelsCaptured = true; - } } } // namespace dd diff --git a/bindings/profilers/wall.hh b/bindings/profilers/wall.hh index 57bd62f5..ff02a3c3 100644 --- a/bindings/profilers/wall.hh +++ b/bindings/profilers/wall.hh @@ -23,7 +23,6 @@ class WallProfiler : public Nan::ObjectWrap { // avoid heap allocation. Need to figure out the right move/copy semantics in // and out of the ring buffer. ValuePtr labels_; - bool labelsCaptured = false; struct SampleContext { ValuePtr labels; @@ -59,7 +58,6 @@ class WallProfiler : public Nan::ObjectWrap { v8::Local GetLabels(v8::Isolate*); void SetLabels(v8::Isolate*, v8::Local); - bool GetLabelsCaptured() { return std::exchange(labelsCaptured, false); } void PushContext(int64_t time_from); void StartImpl(v8::Local name, @@ -75,7 +73,6 @@ class WallProfiler : public Nan::ObjectWrap { static NAN_MODULE_INIT(Init); static NAN_GETTER(GetLabels); static NAN_SETTER(SetLabels); - static NAN_GETTER(GetLabelsCaptured); }; } // namespace dd diff --git a/ts/src/time-profiler.ts b/ts/src/time-profiler.ts index 3ea36224..492c1132 100644 --- a/ts/src/time-profiler.ts +++ b/ts/src/time-profiler.ts @@ -111,8 +111,7 @@ function startInternal( let runName = start(); return { stop: majorVersion < 16 ? stopOld : stop, - setLabels, - labelsCaptured, + setLabels }; function start() { @@ -152,8 +151,4 @@ function startInternal( function setLabels(labels?: LabelSet) { profiler.labels = labels; } - - function labelsCaptured() { - return profiler.labelsCaptured; - } } From cda5e4f66b79aa9195febde3e25e534fb84292ef Mon Sep 17 00:00:00 2001 From: Attila Szegedi Date: Fri, 9 Jun 2023 16:33:29 +0200 Subject: [PATCH 25/27] Ensure atomic updates to labels for signal safety --- bindings/profilers/wall.cc | 16 +++++++++++----- bindings/profilers/wall.hh | 7 ++++++- 2 files changed, 17 insertions(+), 6 deletions(-) diff --git a/bindings/profilers/wall.cc b/bindings/profilers/wall.cc index caa306ff..c39184ca 100644 --- a/bindings/profilers/wall.cc +++ b/bindings/profilers/wall.cc @@ -598,16 +598,20 @@ v8::CpuProfiler* WallProfiler::GetProfiler() { } v8::Local WallProfiler::GetLabels(Isolate* isolate) { - if (!labels_) return v8::Undefined(isolate); - return labels_->Get(isolate); + auto labels = *curLabels.load(std::memory_order_relaxed); + if (!labels) return v8::Undefined(isolate); + return labels->Get(isolate); } void WallProfiler::SetLabels(Isolate* isolate, Local value) { + auto newCurLabels = curLabels.load(std::memory_order_relaxed) == &labels1 ? &labels2 : &labels1; if (value->BooleanValue(isolate)) { - labels_ = std::make_shared>(isolate, value); + *newCurLabels = std::make_shared>(isolate, value); } else { - labels_.reset(); + newCurLabels->reset(); } + std::atomic_signal_fence(std::memory_order_release); + curLabels.store(newCurLabels, std::memory_order_relaxed); } NAN_GETTER(WallProfiler::GetLabels) { @@ -624,7 +628,9 @@ void WallProfiler::PushContext(int64_t time_from) { // Be careful this is called in a signal handler context therefore all // operations must be async signal safe (in particular no allocations). Our // ring buffer avoids allocations. - contexts.push_back(SampleContext(labels_, time_from, v8::base::TimeTicks::Now())); + auto labels = curLabels.load(std::memory_order_relaxed); + std::atomic_signal_fence(std::memory_order_acquire); + contexts.push_back(SampleContext(*labels, time_from, v8::base::TimeTicks::Now())); } } // namespace dd diff --git a/bindings/profilers/wall.hh b/bindings/profilers/wall.hh index ff02a3c3..5f5027f2 100644 --- a/bindings/profilers/wall.hh +++ b/bindings/profilers/wall.hh @@ -22,7 +22,12 @@ class WallProfiler : public Nan::ObjectWrap { // TODO: Investigate use of v8::Persistent instead of shared_ptr to // avoid heap allocation. Need to figure out the right move/copy semantics in // and out of the ring buffer. - ValuePtr labels_; + + // We're using a pair of shared pointers and an atomic pointer-to-current as + // a way to ensure signal safety on update. + ValuePtr labels1; + ValuePtr labels2; + std::atomic curLabels = &labels1; struct SampleContext { ValuePtr labels; From 85de5337eb6ce7918ed60710ffea9df4172d1b7f Mon Sep 17 00:00:00 2001 From: Attila Szegedi Date: Fri, 9 Jun 2023 17:19:28 +0200 Subject: [PATCH 26/27] Don't use RingBuffer.push_front --- bindings/buffer.hh | 24 +++--------------------- bindings/profilers/wall.cc | 14 +++++--------- 2 files changed, 8 insertions(+), 30 deletions(-) diff --git a/bindings/buffer.hh b/bindings/buffer.hh index f4100e37..d8308907 100644 --- a/bindings/buffer.hh +++ b/bindings/buffer.hh @@ -4,9 +4,9 @@ namespace dd { template class RingBuffer { public: - explicit RingBuffer(size_t size) - : buffer(std::make_unique(size)), - capacity_(size), + explicit RingBuffer(size_t capacity) + : buffer(std::make_unique(capacity)), + capacity_(capacity), size_(0), back_index_(0), front_index_(0) {} @@ -37,24 +37,6 @@ class RingBuffer { } } - template - void push_front(T2&& t) { - if (full()) { - if (empty()) { - return; - } - // overwrite buffer head - decrement(front_index_); - buffer[front_index_] = std::forward(t); - // move buffer head - back_index_ = front_index_; - } else { - decrement(front_index_); - buffer[front_index_] = std::forward(t); - ++size_; - } - } - T pop_front() { auto idx = front_index_; increment(front_index_); diff --git a/bindings/profilers/wall.cc b/bindings/profilers/wall.cc index c39184ca..e9bed277 100644 --- a/bindings/profilers/wall.cc +++ b/bindings/profilers/wall.cc @@ -304,13 +304,11 @@ bool isIdleSample(const CpuProfileNode* sample) { LabelSetsByNode WallProfiler::GetLabelSetsByNode(CpuProfile* profile) { LabelSetsByNode labelSetsByNode; - if (contexts.empty() || profile->GetSamplesCount() == 0) { + auto sampleCount = profile->GetSamplesCount(); + if (contexts.empty() || sampleCount == 0) { return labelSetsByNode; } auto isolate = Isolate::GetCurrent(); - SampleContext sampleContext = contexts.pop_front(); - - auto sampleCount = profile->GetSamplesCount(); for (int i = 0; i < sampleCount; i++) { auto sample = profile->GetSample(i); @@ -324,12 +322,13 @@ LabelSetsByNode WallProfiler::GetLabelSetsByNode(CpuProfile* profile) { // to it in time, and stop as soon as it sees a context that's too recent // for this sample. for (;;) { + auto& sampleContext = contexts.front(); if (sampleContext.time_to < sampleTimestamp) { // Current sample context is too old, discard it and fetch the next one. + contexts.pop_front(); if (contexts.empty()) { return labelSetsByNode; } - sampleContext = contexts.pop_front(); } else if (sampleContext.time_from > sampleTimestamp) { // Current sample context is too recent, we'll try to match it to the // next sample. @@ -349,17 +348,14 @@ LabelSetsByNode WallProfiler::GetLabelSetsByNode(CpuProfile* profile) { array, array->Length(), sampleContext.labels.get()->Get(isolate)); } // Sample context was consumed, fetch the next one + contexts.pop_front(); if (contexts.empty()) { return labelSetsByNode; } - sampleContext = contexts.pop_front(); break; // don't match more than one context to one sample } } } - // Push the last popped sample context back into the ring to be used by the - // next profile - contexts.push_front(std::move(sampleContext)); return labelSetsByNode; } From 516a9d6b2dce96e9256b4551a821c06f2e4db413 Mon Sep 17 00:00:00 2001 From: Nicolas Savoire Date: Tue, 13 Jun 2023 13:34:27 +0200 Subject: [PATCH 27/27] Make code signal safe, fix some minor issues Make line number incompatible with custom labels --- binding.gyp | 4 + bindings/binding.cc | 16 + bindings/buffer.hh | 57 +- bindings/code-event-record.cc | 16 + bindings/code-event-record.hh | 16 + bindings/code-map.cc | 16 + bindings/code-map.hh | 16 + bindings/cpu-time.cc | 16 + bindings/cpu-time.hh | 16 + bindings/labelsets.hh | 31 + bindings/location.cc | 16 + bindings/location.hh | 16 + bindings/per-isolate-data.cc | 16 + bindings/per-isolate-data.hh | 16 + bindings/profilers/defer.hh | 16 + bindings/profilers/heap.cc | 2 +- bindings/profilers/wall.cc | 863 +++++++++++++----------- bindings/profilers/wall.hh | 85 ++- bindings/sample.cc | 16 + bindings/sample.hh | 16 + bindings/test/binding.cc | 16 + bindings/test/code-event-record.test.cc | 16 + bindings/test/code-event-record.test.hh | 16 + bindings/test/code-map.test.cc | 16 + bindings/test/code-map.test.hh | 16 + bindings/test/cpu-time.test.cc | 16 + bindings/test/cpu-time.test.hh | 16 + bindings/test/location.test.cc | 16 + bindings/test/location.test.hh | 16 + bindings/test/profilers/cpu.test.cc | 16 + bindings/test/profilers/cpu.test.hh | 16 + bindings/test/sample.test.cc | 16 + bindings/test/sample.test.hh | 16 + bindings/test/tap.h | 20 +- bindings/translate-time-profile.cc | 252 +++++++ bindings/translate-time-profile.hh | 31 + bindings/wrap.hh | 16 + package.json | 4 +- ts/src/index.ts | 8 +- ts/src/time-profiler.ts | 160 ++--- ts/test/test-time-profiler.ts | 51 +- 41 files changed, 1430 insertions(+), 586 deletions(-) create mode 100644 bindings/labelsets.hh create mode 100644 bindings/translate-time-profile.cc create mode 100644 bindings/translate-time-profile.hh diff --git a/binding.gyp b/binding.gyp index df68afe6..0018fc0d 100644 --- a/binding.gyp +++ b/binding.gyp @@ -22,9 +22,11 @@ "bindings/location.cc", "bindings/per-isolate-data.cc", "bindings/sample.cc", + "bindings/translate-time-profile.cc", "bindings/binding.cc" ], "include_dirs": [ + "bindings", " #include #include diff --git a/bindings/buffer.hh b/bindings/buffer.hh index d8308907..f3cae172 100644 --- a/bindings/buffer.hh +++ b/bindings/buffer.hh @@ -1,3 +1,19 @@ +/* + * Copyright 2023 Datadog, Inc + * + * Licensed under the Apache License, Version 2.0 (the "License"); + * you may not use this file except in compliance with the License. + * You may obtain a copy of the License at + * + * http://www.apache.org/licenses/LICENSE-2.0 + * + * Unless required by applicable law or agreed to in writing, software + * distributed under the License is distributed on an "AS IS" BASIS, + * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. + * See the License for the specific language governing permissions and + * limitations under the License. + */ + #pragma once namespace dd { @@ -11,29 +27,20 @@ class RingBuffer { back_index_(0), front_index_(0) {} + size_t capacity() const { return capacity_; } bool full() const { return size_ == capacity_; } bool empty() const { return size_ == 0; } size_t size() const { return size_; } T& front() { return buffer[front_index_]; } - const T& front() const { return buffer[front_index_]; } - template - void push_back(T2&& t) { - if (full()) { - if (empty()) { - return; - } - // overwrite buffer head - buffer[back_index_] = std::forward(t); - increment(back_index_); - // move buffer head - front_index_ = back_index_; - } else { - buffer[back_index_] = std::forward(t); - increment(back_index_); - ++size_; + void push_back(const T& t) { push_back_(t); } + void push_back(T&& t) { push_back_(std::move(t)); } + + void clear() { + while (!empty()) { + pop_front(); } } @@ -45,6 +52,24 @@ class RingBuffer { } private: + template + void push_back_(U&& t) { + const bool is_full = full(); + + if (is_full && empty()) { + return; + } + buffer[back_index_] = std::forward(t); + increment(back_index_); + + if (is_full) { + // move buffer head + front_index_ = back_index_; + } else { + ++size_; + } + } + void increment(size_t& idx) const { idx = idx + 1 == capacity_ ? 0 : idx + 1; } diff --git a/bindings/code-event-record.cc b/bindings/code-event-record.cc index 78b7f436..08c00834 100644 --- a/bindings/code-event-record.cc +++ b/bindings/code-event-record.cc @@ -1,3 +1,19 @@ +/* + * Copyright 2023 Datadog, Inc + * + * Licensed under the Apache License, Version 2.0 (the "License"); + * you may not use this file except in compliance with the License. + * You may obtain a copy of the License at + * + * http://www.apache.org/licenses/LICENSE-2.0 + * + * Unless required by applicable law or agreed to in writing, software + * distributed under the License is distributed on an "AS IS" BASIS, + * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. + * See the License for the specific language governing permissions and + * limitations under the License. + */ + #include #include "code-event-record.hh" diff --git a/bindings/code-event-record.hh b/bindings/code-event-record.hh index 06076d8f..c417a0ef 100644 --- a/bindings/code-event-record.hh +++ b/bindings/code-event-record.hh @@ -1,3 +1,19 @@ +/* + * Copyright 2023 Datadog, Inc + * + * Licensed under the Apache License, Version 2.0 (the "License"); + * you may not use this file except in compliance with the License. + * You may obtain a copy of the License at + * + * http://www.apache.org/licenses/LICENSE-2.0 + * + * Unless required by applicable law or agreed to in writing, software + * distributed under the License is distributed on an "AS IS" BASIS, + * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. + * See the License for the specific language governing permissions and + * limitations under the License. + */ + #pragma once #include diff --git a/bindings/code-map.cc b/bindings/code-map.cc index 822a32ea..3d1e9683 100644 --- a/bindings/code-map.cc +++ b/bindings/code-map.cc @@ -1,3 +1,19 @@ +/* + * Copyright 2023 Datadog, Inc + * + * Licensed under the Apache License, Version 2.0 (the "License"); + * you may not use this file except in compliance with the License. + * You may obtain a copy of the License at + * + * http://www.apache.org/licenses/LICENSE-2.0 + * + * Unless required by applicable law or agreed to in writing, software + * distributed under the License is distributed on an "AS IS" BASIS, + * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. + * See the License for the specific language governing permissions and + * limitations under the License. + */ + #include #include diff --git a/bindings/code-map.hh b/bindings/code-map.hh index 2f6f6d8a..25ca0a83 100644 --- a/bindings/code-map.hh +++ b/bindings/code-map.hh @@ -1,3 +1,19 @@ +/* + * Copyright 2023 Datadog, Inc + * + * Licensed under the Apache License, Version 2.0 (the "License"); + * you may not use this file except in compliance with the License. + * You may obtain a copy of the License at + * + * http://www.apache.org/licenses/LICENSE-2.0 + * + * Unless required by applicable law or agreed to in writing, software + * distributed under the License is distributed on an "AS IS" BASIS, + * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. + * See the License for the specific language governing permissions and + * limitations under the License. + */ + #pragma once #include diff --git a/bindings/cpu-time.cc b/bindings/cpu-time.cc index 60acad53..e37932bc 100644 --- a/bindings/cpu-time.cc +++ b/bindings/cpu-time.cc @@ -1,3 +1,19 @@ +/* + * Copyright 2023 Datadog, Inc + * + * Licensed under the Apache License, Version 2.0 (the "License"); + * you may not use this file except in compliance with the License. + * You may obtain a copy of the License at + * + * http://www.apache.org/licenses/LICENSE-2.0 + * + * Unless required by applicable law or agreed to in writing, software + * distributed under the License is distributed on an "AS IS" BASIS, + * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. + * See the License for the specific language governing permissions and + * limitations under the License. + */ + #include "cpu-time.hh" #ifdef __linux__ diff --git a/bindings/cpu-time.hh b/bindings/cpu-time.hh index cdfade90..6aad0dbf 100644 --- a/bindings/cpu-time.hh +++ b/bindings/cpu-time.hh @@ -1,3 +1,19 @@ +/* + * Copyright 2023 Datadog, Inc + * + * Licensed under the Apache License, Version 2.0 (the "License"); + * you may not use this file except in compliance with the License. + * You may obtain a copy of the License at + * + * http://www.apache.org/licenses/LICENSE-2.0 + * + * Unless required by applicable law or agreed to in writing, software + * distributed under the License is distributed on an "AS IS" BASIS, + * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. + * See the License for the specific language governing permissions and + * limitations under the License. + */ + #pragma once #include diff --git a/bindings/labelsets.hh b/bindings/labelsets.hh new file mode 100644 index 00000000..13ef4780 --- /dev/null +++ b/bindings/labelsets.hh @@ -0,0 +1,31 @@ +/* + * Copyright 2023 Datadog, Inc + * + * Licensed under the Apache License, Version 2.0 (the "License"); + * you may not use this file except in compliance with the License. + * You may obtain a copy of the License at + * + * http://www.apache.org/licenses/LICENSE-2.0 + * + * Unless required by applicable law or agreed to in writing, software + * distributed under the License is distributed on an "AS IS" BASIS, + * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. + * See the License for the specific language governing permissions and + * limitations under the License. + */ + +#pragma once + +#include +#include +#include + +namespace dd { + +struct NodeInfo { + v8::Local labelSets; + uint32_t hitcount; +}; + +using LabelSetsByNode = std::unordered_map; +} // namespace dd diff --git a/bindings/location.cc b/bindings/location.cc index ae5effb9..2c4ad5e9 100644 --- a/bindings/location.cc +++ b/bindings/location.cc @@ -1,3 +1,19 @@ +/* + * Copyright 2023 Datadog, Inc + * + * Licensed under the Apache License, Version 2.0 (the "License"); + * you may not use this file except in compliance with the License. + * You may obtain a copy of the License at + * + * http://www.apache.org/licenses/LICENSE-2.0 + * + * Unless required by applicable law or agreed to in writing, software + * distributed under the License is distributed on an "AS IS" BASIS, + * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. + * See the License for the specific language governing permissions and + * limitations under the License. + */ + #include #include diff --git a/bindings/location.hh b/bindings/location.hh index 07e4596b..c3849dde 100644 --- a/bindings/location.hh +++ b/bindings/location.hh @@ -1,3 +1,19 @@ +/* + * Copyright 2023 Datadog, Inc + * + * Licensed under the Apache License, Version 2.0 (the "License"); + * you may not use this file except in compliance with the License. + * You may obtain a copy of the License at + * + * http://www.apache.org/licenses/LICENSE-2.0 + * + * Unless required by applicable law or agreed to in writing, software + * distributed under the License is distributed on an "AS IS" BASIS, + * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. + * See the License for the specific language governing permissions and + * limitations under the License. + */ + #pragma once #include diff --git a/bindings/per-isolate-data.cc b/bindings/per-isolate-data.cc index 04c94959..ea78dc65 100644 --- a/bindings/per-isolate-data.cc +++ b/bindings/per-isolate-data.cc @@ -1,3 +1,19 @@ +/* + * Copyright 2023 Datadog, Inc + * + * Licensed under the Apache License, Version 2.0 (the "License"); + * you may not use this file except in compliance with the License. + * You may obtain a copy of the License at + * + * http://www.apache.org/licenses/LICENSE-2.0 + * + * Unless required by applicable law or agreed to in writing, software + * distributed under the License is distributed on an "AS IS" BASIS, + * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. + * See the License for the specific language governing permissions and + * limitations under the License. + */ + #include #include #include diff --git a/bindings/per-isolate-data.hh b/bindings/per-isolate-data.hh index 2718c5b4..1f516912 100644 --- a/bindings/per-isolate-data.hh +++ b/bindings/per-isolate-data.hh @@ -1,3 +1,19 @@ +/* + * Copyright 2023 Datadog, Inc + * + * Licensed under the Apache License, Version 2.0 (the "License"); + * you may not use this file except in compliance with the License. + * You may obtain a copy of the License at + * + * http://www.apache.org/licenses/LICENSE-2.0 + * + * Unless required by applicable law or agreed to in writing, software + * distributed under the License is distributed on an "AS IS" BASIS, + * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. + * See the License for the specific language governing permissions and + * limitations under the License. + */ + #pragma once #include diff --git a/bindings/profilers/defer.hh b/bindings/profilers/defer.hh index 1ba3750d..a07dd613 100644 --- a/bindings/profilers/defer.hh +++ b/bindings/profilers/defer.hh @@ -1,3 +1,19 @@ +/* + * Copyright 2023 Datadog, Inc + * + * Licensed under the Apache License, Version 2.0 (the "License"); + * you may not use this file except in compliance with the License. + * You may obtain a copy of the License at + * + * http://www.apache.org/licenses/LICENSE-2.0 + * + * Unless required by applicable law or agreed to in writing, software + * distributed under the License is distributed on an "AS IS" BASIS, + * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. + * See the License for the specific language governing permissions and + * limitations under the License. + */ + #pragma once #include diff --git a/bindings/profilers/heap.cc b/bindings/profilers/heap.cc index c2ce16ec..c534d914 100644 --- a/bindings/profilers/heap.cc +++ b/bindings/profilers/heap.cc @@ -16,8 +16,8 @@ #include "heap.hh" -#include "../per-isolate-data.hh" #include "defer.hh" +#include "per-isolate-data.hh" #include #include diff --git a/bindings/profilers/wall.cc b/bindings/profilers/wall.cc index e9bed277..7c510bdb 100644 --- a/bindings/profilers/wall.cc +++ b/bindings/profilers/wall.cc @@ -1,11 +1,11 @@ -/** - * Copyright 2018 Google Inc. All Rights Reserved. +/* + * Copyright 2023 Datadog, Inc * * Licensed under the Apache License, Version 2.0 (the "License"); * you may not use this file except in compliance with the License. * You may obtain a copy of the License at * - * http://www.apache.org/licenses/LICENSE-2.0 + * http://www.apache.org/licenses/LICENSE-2.0 * * Unless required by applicable law or agreed to in writing, software * distributed under the License is distributed on an "AS IS" BASIS, @@ -15,6 +15,7 @@ */ #include +#include #include #include #include @@ -24,422 +25,352 @@ #include #include -#include "../per-isolate-data.hh" +#include "per-isolate-data.hh" +#include "translate-time-profile.hh" #include "wall.hh" #ifndef _WIN32 #define DD_WALL_USE_SIGPROF -#else -#undef DD_WALL_USE_SIGPROF -#endif // Declare v8::base::TimeTicks::Now. It is exported from the node executable so // our addon will be able to dynamically link to the symbol when loaded. namespace v8 { - namespace base { - struct TimeTicks { - static int64_t Now(); - }; - } -} +namespace base { +struct TimeTicks { + static int64_t Now(); +}; +} // namespace base +} // namespace v8 + +static int64_t Now() { + return v8::base::TimeTicks::Now(); +}; +#else +static int64_t Now() { + return 0; +}; +#endif using namespace v8; namespace dd { -using ProfilerMap = std::unordered_map; - -static std::atomic profilers(new ProfilerMap()); -static std::mutex update_profilers; - -#ifdef DD_WALL_USE_SIGPROF -static void (*old_handler)(int, siginfo_t*, void*) = nullptr; - -static void sighandler(int sig, siginfo_t* info, void* context) { - if (!old_handler) { - return; - } - - auto isolate = Isolate::GetCurrent(); - WallProfiler* prof = nullptr; - auto prof_map = profilers.exchange(nullptr, std::memory_order_acq_rel); - if (prof_map) { +class ProtectedProfilerMap { + public: + WallProfiler* GetProfiler(const Isolate* isolate) const { + // Prevent updates to profiler map by atomically setting g_profilers to null + auto prof_map = profilers_.exchange(nullptr, std::memory_order_acq_rel); + if (!prof_map) { + return nullptr; + } auto prof_it = prof_map->find(isolate); + WallProfiler* profiler = nullptr; if (prof_it != prof_map->end()) { - prof = prof_it->second; + profiler = prof_it->second; } - profilers.store(prof_map, std::memory_order_release); + // Allow updates + profilers_.store(prof_map, std::memory_order_release); + return profiler; } - auto now = v8::base::TimeTicks::Now(); - old_handler(sig, info, context); - if (prof) { - prof->PushContext(now); + + bool RemoveProfiler(const v8::Isolate* isolate, WallProfiler* profiler) { + return UpdateProfilers([isolate, profiler](auto map) { + if (isolate != nullptr) { + auto it = map->find(isolate); + if (it != map->end() && it->second == profiler) { + map->erase(it); + return true; + } + } else { + auto it = std::find_if(map->begin(), map->end(), [profiler](auto& x) { + return x.second == profiler; + }); + if (it != map->end()) { + map->erase(it); + return true; + } + } + return false; + }); } -} -#endif -class ProfileTranslator { - friend class WallProfiler; + bool AddProfiler(const v8::Isolate* isolate, WallProfiler* profiler) { + return UpdateProfilers([isolate, profiler](auto map) { + return map->emplace(isolate, profiler).second; + }); + } - LabelSetsByNode labelSetsByNode; - Isolate* isolate = Isolate::GetCurrent(); - Local emptyArray = NewArray(0); - Local zero = NewInteger(0); - -#define FIELDS \ - X(name) \ - X(scriptName) \ - X(scriptId) \ - X(lineNumber) \ - X(columnNumber) \ - X(hitCount) \ - X(children) \ - X(labelSets) - -#define X(name) Local str_##name = NewString(#name); - FIELDS -#undef X - - ProfileTranslator( - std::unordered_map>&& nls) - : labelSetsByNode(std::move(nls)) {} - - Local getLabelSetsForNode(const CpuProfileNode* node) { - auto it = labelSetsByNode.find(node); - if (it != labelSetsByNode.end()) { - auto retval = it->second; - labelSetsByNode.erase(it); - return retval; - } else { - return emptyArray; + private: + template + bool UpdateProfilers(F updateFn) { + // use mutex to prevent two isolates of updating profilers concurrently + std::lock_guard lock(update_mutex_); + + if (!init_) { + profilers_.store(new ProfilerMap(), std::memory_order_release); } - } - Local CreateTimeNode(Local name, - Local scriptName, - Local scriptId, - Local lineNumber, - Local columnNumber, - Local hitCount, - Local children, - Local labelSets) { - Local js_node = Nan::New(); -#define X(name) Nan::Set(js_node, str_##name, name); - FIELDS -#undef X - return js_node; + auto currProfilers = profilers_.load(std::memory_order_acquire); + // Wait until sighandler is done using the map + while (!currProfilers) { + currProfilers = profilers_.load(std::memory_order_relaxed); + } + auto newProfilers = new ProfilerMap(*currProfilers); + auto res = updateFn(newProfilers); + // Wait until sighandler is done using the map before installing a new map. + // The value in profilers is either nullptr or currProfilers. + for (;;) { + ProfilerMap* currProfilers2 = currProfilers; + if (profilers_.compare_exchange_weak( + currProfilers2, newProfilers, std::memory_order_acq_rel)) { + break; + } + } + delete currProfilers; + return res; } - Local NewInteger(int32_t x) { - return Integer::New(isolate, x); - } + using ProfilerMap = std::unordered_map; + mutable std::atomic profilers_; + std::mutex update_mutex_; + bool init_ = false; + ; +}; + +using ProfilerMap = std::unordered_map; + +static ProtectedProfilerMap g_profilers; +static std::mutex g_profilers_update_mtx; + +namespace { - Local NewArray(int length) { - return Array::New(isolate, length); +#ifdef DD_WALL_USE_SIGPROF +class SignalHandler { + public: + static void IncreaseUseCount() { + std::lock_guard lock(mutex_); + ++use_count_; + // Always reinstall the signal handler + Install(); + } + + static void DecreaseUseCount() { + std::lock_guard lock(mutex_); + if (--use_count_ == 0) { + Restore(); + } } - Local NewString(const char* str) { -#if NODE_MODULE_VERSION > NODE_12_0_MODULE_VERSION - return String::NewFromUtf8(isolate, str).ToLocalChecked(); -#else - return Nan::New(str).ToLocalChecked(); -#endif + static bool Installed() { + std::lock_guard lock(mutex_); + return installed_; } - Local GetLineNumberTimeProfileChildren(const CpuProfileNode* node) { - unsigned int index = 0; - Local children; - int32_t count = node->GetChildrenCount(); - - unsigned int hitLineCount = node->GetHitLineCount(); - unsigned int hitCount = node->GetHitCount(); - auto labelSets = getLabelSetsForNode(node); - auto scriptId = NewInteger(node->GetScriptId()); - if (hitLineCount > 0) { - std::vector entries(hitLineCount); - node->GetLineTicks(&entries[0], hitLineCount); - children = NewArray(count + hitLineCount); - for (const CpuProfileNode::LineTick entry : entries) { - Nan::Set(children, - index++, - CreateTimeNode(node->GetFunctionName(), - node->GetScriptResourceName(), - scriptId, - NewInteger(entry.line), - zero, - NewInteger(entry.hit_count), - emptyArray, - labelSets)); - } - } else if (hitCount > 0) { - // Handle nodes for pseudo-functions like "process" and "garbage - // collection" which do not have hit line counts. - children = NewArray(count + 1); - Nan::Set(children, - index++, - CreateTimeNode(node->GetFunctionName(), - node->GetScriptResourceName(), - scriptId, - NewInteger(node->GetLineNumber()), - NewInteger(node->GetColumnNumber()), - NewInteger(hitCount), - emptyArray, - labelSets)); + private: + static void Install() { + struct sigaction sa; + sa.sa_sigaction = &HandleProfilerSignal; + sigemptyset(&sa.sa_mask); + sa.sa_flags = SA_RESTART | SA_SIGINFO | SA_ONSTACK; + if (installed_) { + sigaction(SIGPROF, &sa, nullptr); } else { - children = NewArray(count); + installed_ = (sigaction(SIGPROF, &sa, &old_handler_) == 0); + old_handler_func_.store(old_handler_.sa_sigaction, + std::memory_order_relaxed); } + } - for (int32_t i = 0; i < count; i++) { - Nan::Set(children, - index++, - TranslateLineNumbersTimeProfileNode(node, node->GetChild(i))); - }; - - return children; - } - - Local TranslateLineNumbersTimeProfileNode( - const CpuProfileNode* parent, const CpuProfileNode* node) { - return CreateTimeNode(parent->GetFunctionName(), - parent->GetScriptResourceName(), - NewInteger(parent->GetScriptId()), - NewInteger(node->GetLineNumber()), - NewInteger(node->GetColumnNumber()), - zero, - GetLineNumberTimeProfileChildren(node), - getLabelSetsForNode(node)); - } - - // In profiles with line level accurate line numbers, a node's line number - // and column number refer to the line/column from which the function was - // called. - Local TranslateLineNumbersTimeProfileRoot(const CpuProfileNode* node) { - int32_t count = node->GetChildrenCount(); - std::vector> childrenArrs(count); - int32_t childCount = 0; - for (int32_t i = 0; i < count; i++) { - Local c = GetLineNumberTimeProfileChildren(node->GetChild(i)); - childCount = childCount + c->Length(); - childrenArrs[i] = c; + static void Restore() { + if (installed_) { + sigaction(SIGPROF, &old_handler_, nullptr); + installed_ = false; + old_handler_func_.store(nullptr, std::memory_order_relaxed); } + } - Local children = NewArray(childCount); - int32_t idx = 0; - for (int32_t i = 0; i < count; i++) { - Local arr = childrenArrs[i]; - for (uint32_t j = 0; j < arr->Length(); j++) { - Nan::Set(children, idx, Nan::Get(arr, j).ToLocalChecked()); - idx++; - } - } + static void HandleProfilerSignal(int signal, siginfo_t* info, void* context); - return CreateTimeNode(node->GetFunctionName(), - node->GetScriptResourceName(), - NewInteger(node->GetScriptId()), - NewInteger(node->GetLineNumber()), - NewInteger(node->GetColumnNumber()), - zero, - children, - getLabelSetsForNode(node)); - } - - Local TranslateTimeProfileNode(const CpuProfileNode* node) { - int32_t count = node->GetChildrenCount(); - Local children = Nan::New(count); - for (int32_t i = 0; i < count; i++) { - Nan::Set(children, i, TranslateTimeProfileNode(node->GetChild(i))); - } + // Protects the process wide state below. + static std::mutex mutex_; + static int use_count_; + static bool installed_; + static struct sigaction old_handler_; + using HandlerFunc = void (*)(int, siginfo_t*, void*); + static std::atomic old_handler_func_; +}; - return CreateTimeNode(node->GetFunctionName(), - node->GetScriptResourceName(), - NewInteger(node->GetScriptId()), - NewInteger(node->GetLineNumber()), - NewInteger(node->GetColumnNumber()), - NewInteger(node->GetHitCount()), - children, - getLabelSetsForNode(node)); - } - - Local TranslateTimeProfile(const CpuProfile* profile, - bool includeLineInfo) { - Local js_profile = Nan::New(); - Nan::Set(js_profile, NewString("title"), profile->GetTitle()); - -#if NODE_MODULE_VERSION > NODE_11_0_MODULE_VERSION - if (includeLineInfo) { - Nan::Set(js_profile, - NewString("topDownRoot"), - TranslateLineNumbersTimeProfileRoot(profile->GetTopDownRoot())); - } else { - Nan::Set(js_profile, - NewString("topDownRoot"), - TranslateTimeProfileNode(profile->GetTopDownRoot())); - } -#else - Nan::Set(js_profile, - NewString("topDownRoot"), - TranslateTimeProfileNode(profile->GetTopDownRoot())); -#endif - Nan::Set(js_profile, - NewString("startTime"), - Nan::New(profile->GetStartTime())); - Nan::Set(js_profile, - NewString("endTime"), - Nan::New(profile->GetEndTime())); +std::mutex SignalHandler::mutex_; +int SignalHandler::use_count_ = 0; +struct sigaction SignalHandler::old_handler_; +bool SignalHandler::installed_ = false; +std::atomic SignalHandler::old_handler_func_; - return js_profile; +void SignalHandler::HandleProfilerSignal(int sig, + siginfo_t* info, + void* context) { + auto old_handler = old_handler_func_.load(std::memory_order_relaxed); + + if (!old_handler) { + return; } -#undef FIELDS -}; -bool isIdleSample(const CpuProfileNode* sample) { - return -#if NODE_MODULE_VERSION > NODE_12_0_MODULE_VERSION - sample->GetParent() == nullptr && -#endif - sample->GetChildrenCount() == 0 && - strncmp("(idle)", sample->GetFunctionNameStr(), 7) == 0; + auto isolate = Isolate::GetCurrent(); + WallProfiler* prof = g_profilers.GetProfiler(isolate); + + if (!prof) { + // no profiler found for current isolate, just pass the signal to old + // handler + old_handler(sig, info, context); + return; + } + + // Check if sampling is allowed + if (!prof->collectSampleAllowed()) { + return; + } + + auto time_from = Now(); + old_handler(sig, info, context); + auto time_to = Now(); + prof->PushContext(time_from, time_to); } +#else +class SignalHandler { + public: + static void IncreaseUseCount() {} + static void DecreaseUseCount() {} +}; +#endif +} // namespace -LabelSetsByNode WallProfiler::GetLabelSetsByNode(CpuProfile* profile) { +LabelSetsByNode WallProfiler::GetLabelSetsByNode(CpuProfile* profile, + ContextBuffer& contexts) { LabelSetsByNode labelSetsByNode; auto sampleCount = profile->GetSamplesCount(); if (contexts.empty() || sampleCount == 0) { return labelSetsByNode; } - auto isolate = Isolate::GetCurrent(); - for (int i = 0; i < sampleCount; i++) { - auto sample = profile->GetSample(i); - if (isIdleSample(sample)) { - continue; + auto isolate = Isolate::GetCurrent(); + // auto labelKey = Nan::New("label").ToLocalChecked(); + + auto contextIt = contexts.begin(); + + // deltaIdx is the offset of the sample to process compared to current + // iteration index + int deltaIdx = 0; + + // skip first sample because it's the one taken on profiler start, outside of + // signal handler + for (int i = 1; i < sampleCount; i++) { + // Handle out-of-order samples, hypothesis is that at most 2 consecutive + // samples can be out-of-order + if (deltaIdx == 1) { + // previous iteration was processing next sample, so this one should + // process previous sample + deltaIdx = -1; + } else if (deltaIdx == -1) { + // previous iteration was processing previous sample, returns to normal + // index + deltaIdx = 0; + } else if (i < sampleCount - 1 && profile->GetSampleTimestamp(i + 1) < + profile->GetSampleTimestamp(i)) { + // detected out-of-order sample, process next sample + deltaIdx = 1; } - auto sampleTimestamp = profile->GetSampleTimestamp(i); + + auto sampleIdx = i + deltaIdx; + auto sample = profile->GetSample(sampleIdx); + + auto sampleTimestamp = profile->GetSampleTimestamp(sampleIdx); // This loop will drop all contexts that are too old to be associated with - // the current sample; associate those (normally one) that are close enough - // to it in time, and stop as soon as it sees a context that's too recent - // for this sample. - for (;;) { - auto& sampleContext = contexts.front(); + // the current sample; association is done by matching each sample with + // context whose [time_from,time_to] interval encompasses sample timestamp. + while (contextIt != contexts.end()) { + auto& sampleContext = *contextIt; if (sampleContext.time_to < sampleTimestamp) { // Current sample context is too old, discard it and fetch the next one. - contexts.pop_front(); - if (contexts.empty()) { - return labelSetsByNode; - } + ++contextIt; } else if (sampleContext.time_from > sampleTimestamp) { // Current sample context is too recent, we'll try to match it to the // next sample. break; } else { // This sample context is the closest to this sample. + auto it = labelSetsByNode.find(sample); + Local array; + if (it == labelSetsByNode.end()) { + array = Nan::New(); + assert(labelSetsByNode.find(sample) == labelSetsByNode.end()); + labelSetsByNode[sample] = {array, 1}; + } else { + array = it->second.labelSets; + ++it->second.hitcount; + } if (sampleContext.labels) { - auto it = labelSetsByNode.find(sample); - Local array; - if (it == labelSetsByNode.end()) { - array = Nan::New(); - labelSetsByNode.emplace(sample, array); - } else { - array = it->second; - } Nan::Set( array, array->Length(), sampleContext.labels.get()->Get(isolate)); } + // Sample context was consumed, fetch the next one - contexts.pop_front(); - if (contexts.empty()) { - return labelSetsByNode; - } + ++contextIt; break; // don't match more than one context to one sample } } } + return labelSetsByNode; } -WallProfiler::WallProfiler(int intervalMicros, int durationMicros) - : samplingInterval(intervalMicros), - contexts(durationMicros * 2 / intervalMicros) {} +WallProfiler::WallProfiler(int samplingPeriodMicros, + int durationMicros, + bool includeLines, + bool withLabels) + : samplingPeriodMicros_(samplingPeriodMicros), + includeLines_(includeLines), + withLabels_(withLabels) { + contexts_.reserve(durationMicros * 2 / samplingPeriodMicros); + curLabels_.store(&labels1_, std::memory_order_relaxed); + collectSamples_.store(false, std::memory_order_relaxed); +} WallProfiler::~WallProfiler() { Dispose(nullptr); } -template -void updateProfilers(F updateFn) { - std::lock_guard lock(update_profilers); - auto currProfilers = profilers.load(std::memory_order_acquire); - // Wait until sighandler is done using the map - while (!currProfilers) { - currProfilers = profilers.load(std::memory_order_relaxed); - } - auto newProfilers = new ProfilerMap(*currProfilers); - updateFn(newProfilers); - // Wait until sighandler is done using the map before installing a new map. - // The value in profilers is either nullptr or currProfilers. - for (;;) { - ProfilerMap* currProfilers2 = currProfilers; - if (profilers.compare_exchange_weak( - currProfilers2, newProfilers, std::memory_order_acq_rel)) { - break; - } - } - delete currProfilers; -} - void WallProfiler::Dispose(Isolate* isolate) { - if (cpuProfiler != nullptr) { - cpuProfiler->Dispose(); - cpuProfiler = nullptr; + if (cpuProfiler_ != nullptr) { + cpuProfiler_->Dispose(); + cpuProfiler_ = nullptr; - updateProfilers([isolate, this](auto map) { - if (isolate != nullptr) { - auto it = map->find(isolate); - if (it != map->end() && it->second == this) { - map->erase(it); - } - } else { - // TODO: use map->erase_if once we can use C++20. - for (auto it = map->begin(), last = map->end(); it != last;) { - if (it->second == this) { - it = map->erase(it); - } else { - ++it; - } - } - } - }); + g_profilers.RemoveProfiler(isolate, this); } } -NAN_METHOD(WallProfiler::Dispose) { - WallProfiler* wallProfiler = - Nan::ObjectWrap::Unwrap(info.Holder()); - - wallProfiler->Dispose(info.GetIsolate()); -} - NAN_METHOD(WallProfiler::New) { - if (info.Length() != 2) { - return Nan::ThrowTypeError("WallProfiler must have two arguments."); + if (info.Length() != 4) { + return Nan::ThrowTypeError("WallProfiler must have four arguments."); } + if (!info[0]->IsNumber()) { - return Nan::ThrowTypeError("Sample rate must be a number."); + return Nan::ThrowTypeError("Sample period must be a number."); } - if (!info[1]->IsNumber()) { return Nan::ThrowTypeError("Duration must be a number."); } + if (!info[2]->IsBoolean()) { + return Nan::ThrowTypeError("includeLines must be a boolean."); + } + if (!info[3]->IsBoolean()) { + return Nan::ThrowTypeError("withLabels must be a boolean."); + } if (info.IsConstructCall()) { - int interval = Nan::MaybeLocal(info[0].As()) - .ToLocalChecked() - ->Value(); - int duration = Nan::MaybeLocal(info[1].As()) - .ToLocalChecked() - ->Value(); + int interval = info[0].As()->Value(); + int duration = info[1].As()->Value(); if (interval <= 0) { return Nan::ThrowTypeError("Sample rate must be positive."); @@ -451,12 +382,41 @@ NAN_METHOD(WallProfiler::New) { return Nan::ThrowTypeError("Duration must not be less than sample rate."); } - WallProfiler* obj = new WallProfiler(interval, duration); + bool includeLines = info[2].As()->Value(); + bool withLabels = info[3].As()->Value(); + +#ifndef DD_WALL_USE_SIGPROF + if (withLabels) { + return Nan::ThrowTypeError("Labels are not supported."); + } +#endif + + if (includeLines && withLabels) { + // Currently custom labels are not compatible with caller line + // information, because it's not possible to associate labels with line + // ticks: + // labels are associated to sample which itself is associated with + // a CpuProfileNode, but this node has several line ticks, and we cannot + // determine labels <-> line ticks association. Note that line number is + // present in v8 internal sample struct and would allow mapping sample to + // line tick, and thus labels to line tick, but this information is not + // available in v8 public API. + // More over in caller line number mode, line number of a CpuProfileNode + // is not the line of the current function, but the line number where this + // function is called, therefore we don't access either to the line of the + // function (otherwise we could ignoree line ticks and replace them with + // single hitcount for the function). + return Nan::ThrowTypeError( + "Include line option is not compatible with labels."); + } + + WallProfiler* obj = + new WallProfiler(interval, duration, includeLines, withLabels); obj->Wrap(info.This()); info.GetReturnValue().Set(info.This()); } else { - const int argc = 2; - v8::Local argv[argc] = {info[0], info[1]}; + const int argc = 4; + v8::Local argv[argc] = {info[0], info[1], info[2], info[3]}; v8::Local cons = Nan::New( PerIsolateData::For(info.GetIsolate())->WallProfilerConstructor()); info.GetReturnValue().Set( @@ -468,93 +428,167 @@ NAN_METHOD(WallProfiler::Start) { WallProfiler* wallProfiler = Nan::ObjectWrap::Unwrap(info.Holder()); - if (info.Length() != 3) { - return Nan::ThrowTypeError("Start must have three arguments."); + if (info.Length() != 0) { + return Nan::ThrowTypeError("Start must not have any arguments."); } - if (!info[0]->IsString()) { - return Nan::ThrowTypeError("Profile name must be a string."); + + auto res = wallProfiler->StartImpl(); + if (!res.success) { + return Nan::ThrowTypeError(res.msg.c_str()); } - if (!info[1]->IsBoolean()) { - return Nan::ThrowTypeError("Include lines flag must be a boolean."); +} + +Result WallProfiler::StartImpl() { + if (started_) { + return Result{"Start called on already started profiler, stop it first."}; } - if (!info[2]->IsBoolean()) { - return Nan::ThrowTypeError("With labels flag must be a boolean."); + + profileIdx_ = 0; + + if (!CreateV8CpuProfiler()) { + return Result{"Cannot start profiler: another profiler is already active."}; } - Local name = - Nan::MaybeLocal(info[0].As()).ToLocalChecked(); + profileId_ = StartInternal(); - bool includeLines = - Nan::MaybeLocal(info[1].As()).ToLocalChecked()->Value(); + collectSamples_.store(true, std::memory_order_relaxed); + started_ = true; + return {}; +} - bool withLabels = - Nan::MaybeLocal(info[2].As()).ToLocalChecked()->Value(); +std::string WallProfiler::StartInternal() { + char buf[128]; + snprintf(buf, sizeof(buf), "pprof-%" PRId64, profileIdx_++); + v8::Local title = Nan::New(buf).ToLocalChecked(); + cpuProfiler_->StartProfiling(title, + includeLines_ + ? CpuProfilingMode::kCallerLineNumbers + : CpuProfilingMode::kLeafNodeLineNumbers, + withLabels_); - auto now = v8::base::TimeTicks::Now(); - wallProfiler->StartImpl(name, includeLines, withLabels); -#ifdef DD_WALL_USE_SIGPROF - if (withLabels) { - wallProfiler->PushContext(now); - struct sigaction sa, old_sa; - sa.sa_flags = SA_SIGINFO | SA_RESTART; - sa.sa_sigaction = &sighandler; - sigemptyset(&sa.sa_mask); - sigaction(SIGPROF, &sa, &old_sa); + // reinstall sighandler on each new upload period + if (withLabels_) { + SignalHandler::IncreaseUseCount(); + } - // At the end of a cycle start is called before stop, - // at this point old_sa.sa_sigaction is sighandler ! - if (!old_handler) { - old_handler = old_sa.sa_sigaction; - } + return buf; +} + +NAN_METHOD(WallProfiler::Stop) { + if (info.Length() != 1) { + return Nan::ThrowTypeError("Stop must have one argument."); } + if (!info[0]->IsBoolean()) { + return Nan::ThrowTypeError("Restart must be a boolean."); + } + + bool restart = info[0].As()->Value(); + + WallProfiler* wallProfiler = + Nan::ObjectWrap::Unwrap(info.Holder()); + + v8::Local profile; +#if NODE_MODULE_VERSION < NODE_16_0_MODULE_VERSION + auto err = wallProfiler->StopImplOld(restart, profile); +#else + auto err = wallProfiler->StopImpl(restart, profile); #endif -} -void WallProfiler::StartImpl(Local name, - bool includeLines, - bool withLabels) { - if (includeLines) { - GetProfiler()->StartProfiling( - name, CpuProfilingMode::kCallerLineNumbers, withLabels); - } else { - GetProfiler()->StartProfiling(name, withLabels); + if (!err.success) { + return Nan::ThrowTypeError(err.msg.c_str()); } + info.GetReturnValue().Set(profile); } -NAN_METHOD(WallProfiler::Stop) { - if (info.Length() != 2) { - return Nan::ThrowTypeError("Stop must have two arguments."); +Result WallProfiler::StopImpl(bool restart, v8::Local& profile) { + if (!started_) { + return Result{"Stop called on not started profiler."}; } - if (!info[0]->IsString()) { - return Nan::ThrowTypeError("Profile name must be a string."); + + auto oldProfileId = profileId_; + if (withLabels_) { + collectSamples_.store(false, std::memory_order_relaxed); + std::atomic_signal_fence(std::memory_order_release); + + // make sure timestamp changes to avoid having samples from previous profile + auto now = Now(); + while (Now() == now) { + } } - if (!info[1]->IsBoolean()) { - return Nan::ThrowTypeError("Include lines must be a boolean."); + + if (restart) { + profileId_ = StartInternal(); } - Local name = - Nan::MaybeLocal(info[0].As()).ToLocalChecked(); + if (withLabels_) { + SignalHandler::DecreaseUseCount(); + } + auto v8_profile = cpuProfiler_->StopProfiling( + Nan::New(oldProfileId).ToLocalChecked()); - bool includeLines = - Nan::MaybeLocal(info[1].As()).ToLocalChecked()->Value(); + ContextBuffer contexts; + if (withLabels_) { + contexts.reserve(contexts_.capacity()); + std::swap(contexts, contexts_); + } - WallProfiler* wallProfiler = - Nan::ObjectWrap::Unwrap(info.Holder()); + if (restart && withLabels_) { + // make sure timestamp changes to avoid mixing sample taken upon start and a + // sample from signal handler + auto now = Now(); + while (Now() == now) { + } + collectSamples_.store(true, std::memory_order_relaxed); + std::atomic_signal_fence(std::memory_order_release); + } - auto profile = wallProfiler->StopImpl(name, includeLines); + if (withLabels_) { + auto labelSetsByNode = GetLabelSetsByNode(v8_profile, contexts); + profile = TranslateTimeProfile(v8_profile, includeLines_, &labelSetsByNode); - info.GetReturnValue().Set(profile); + } else { + profile = TranslateTimeProfile(v8_profile, includeLines_); + } + v8_profile->Delete(); + + if (!restart) { + Dispose(v8::Isolate::GetCurrent()); + } + started_ = restart; + + return {}; } -Local WallProfiler::StopImpl(Local name, - bool includeLines) { - auto profiler = GetProfiler(); - auto v8_profile = profiler->StopProfiling(name); - Local profile = - ProfileTranslator(GetLabelSetsByNode(v8_profile)) - .TranslateTimeProfile(v8_profile, includeLines); +Result WallProfiler::StopImplOld(bool restart, v8::Local& profile) { + if (!started_) { + return Result{"Stop called on not started profiler."}; + } + + if (withLabels_) { + SignalHandler::DecreaseUseCount(); + } + auto v8_profile = cpuProfiler_->StopProfiling( + Nan::New(profileId_).ToLocalChecked()); + + if (withLabels_) { + auto labelSetsByNode = GetLabelSetsByNode(v8_profile, contexts_); + profile = TranslateTimeProfile(v8_profile, includeLines_, &labelSetsByNode); + + } else { + profile = TranslateTimeProfile(v8_profile, includeLines_); + } + contexts_.clear(); v8_profile->Delete(); - return profile; + Dispose(v8::Isolate::GetCurrent()); + + if (restart) { + CreateV8CpuProfiler(); + profileId_ = StartInternal(); + } else { + started_ = false; + } + + return {}; } NAN_MODULE_INIT(WallProfiler::Init) { @@ -569,7 +603,6 @@ NAN_MODULE_INIT(WallProfiler::Init) { SetLabels); Nan::SetPrototypeMethod(tpl, "start", Start); - Nan::SetPrototypeMethod(tpl, "dispose", Dispose); Nan::SetPrototypeMethod(tpl, "stop", Stop); PerIsolateData::For(Isolate::GetCurrent()) @@ -581,33 +614,45 @@ NAN_MODULE_INIT(WallProfiler::Init) { // A new CPU profiler object will be created each time profiling is started // to work around https://bugs.chromium.org/p/v8/issues/detail?id=11051. // TODO: Fixed in v16. Delete this hack when deprecating v14. -v8::CpuProfiler* WallProfiler::GetProfiler() { - if (cpuProfiler == nullptr) { +v8::CpuProfiler* WallProfiler::CreateV8CpuProfiler() { + if (cpuProfiler_ == nullptr) { v8::Isolate* isolate = v8::Isolate::GetCurrent(); - updateProfilers([isolate, this](auto map) { map->emplace(isolate, this); }); + bool inserted = g_profilers.AddProfiler(isolate, this); - cpuProfiler = v8::CpuProfiler::New(isolate); - cpuProfiler->SetSamplingInterval(samplingInterval); + if (!inserted) { + // refuse to create a new profiler if one is already active + return nullptr; + } + cpuProfiler_ = v8::CpuProfiler::New(isolate); + cpuProfiler_->SetSamplingInterval(samplingPeriodMicros_); } - return cpuProfiler; + return cpuProfiler_; } v8::Local WallProfiler::GetLabels(Isolate* isolate) { - auto labels = *curLabels.load(std::memory_order_relaxed); + auto labels = *curLabels_.load(std::memory_order_relaxed); if (!labels) return v8::Undefined(isolate); return labels->Get(isolate); } void WallProfiler::SetLabels(Isolate* isolate, Local value) { - auto newCurLabels = curLabels.load(std::memory_order_relaxed) == &labels1 ? &labels2 : &labels1; + // Need to be careful here, because we might be interrupted by a + // signal handler that will make use of curLabels_. + // Update of shared_ptr is not atomic, so instead we use a pointer + // (curLabels_) that points on two shared_ptr (labels1_ and labels2_), update + // the shared_ptr that is not currently in use and then atomically update + // curLabels_. + auto newCurLabels = curLabels_.load(std::memory_order_relaxed) == &labels1_ + ? &labels2_ + : &labels1_; if (value->BooleanValue(isolate)) { *newCurLabels = std::make_shared>(isolate, value); } else { newCurLabels->reset(); } std::atomic_signal_fence(std::memory_order_release); - curLabels.store(newCurLabels, std::memory_order_relaxed); + curLabels_.store(newCurLabels, std::memory_order_relaxed); } NAN_GETTER(WallProfiler::GetLabels) { @@ -620,13 +665,15 @@ NAN_SETTER(WallProfiler::SetLabels) { profiler->SetLabels(info.GetIsolate(), value); } -void WallProfiler::PushContext(int64_t time_from) { +void WallProfiler::PushContext(int64_t time_from, int64_t time_to) { // Be careful this is called in a signal handler context therefore all - // operations must be async signal safe (in particular no allocations). Our - // ring buffer avoids allocations. - auto labels = curLabels.load(std::memory_order_relaxed); + // operations must be async signal safe (in particular no allocations). + // Our ring buffer avoids allocations. + auto labels = curLabels_.load(std::memory_order_relaxed); std::atomic_signal_fence(std::memory_order_acquire); - contexts.push_back(SampleContext(*labels, time_from, v8::base::TimeTicks::Now())); + if (contexts_.size() < contexts_.capacity()) { + contexts_.push_back({*labels, time_from, time_to}); + } } } // namespace dd diff --git a/bindings/profilers/wall.hh b/bindings/profilers/wall.hh index 5f5027f2..1ff9f807 100644 --- a/bindings/profilers/wall.hh +++ b/bindings/profilers/wall.hh @@ -1,78 +1,109 @@ +/* + * Copyright 2023 Datadog, Inc + * + * Licensed under the Apache License, Version 2.0 (the "License"); + * you may not use this file except in compliance with the License. + * You may obtain a copy of the License at + * + * http://www.apache.org/licenses/LICENSE-2.0 + * + * Unless required by applicable law or agreed to in writing, software + * distributed under the License is distributed on an "AS IS" BASIS, + * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. + * See the License for the specific language governing permissions and + * limitations under the License. + */ + #pragma once +#include "labelsets.hh" + #include #include #include #include #include -#include "../buffer.hh" - namespace dd { -using LabelSetsByNode = - std::unordered_map>; +struct Result { + Result() = default; + explicit Result(const char* msg) : success{false}, msg{msg} {}; -using ValuePtr = std::shared_ptr>; + bool success = true; + std::string msg; +}; class WallProfiler : public Nan::ObjectWrap { private: - int samplingInterval = 0; - v8::CpuProfiler* cpuProfiler = nullptr; + using ValuePtr = std::shared_ptr>; + + int samplingPeriodMicros_ = 0; + v8::CpuProfiler* cpuProfiler_ = nullptr; // TODO: Investigate use of v8::Persistent instead of shared_ptr to // avoid heap allocation. Need to figure out the right move/copy semantics in // and out of the ring buffer. // We're using a pair of shared pointers and an atomic pointer-to-current as // a way to ensure signal safety on update. - ValuePtr labels1; - ValuePtr labels2; - std::atomic curLabels = &labels1; + ValuePtr labels1_; + ValuePtr labels2_; + std::atomic curLabels_; + std::atomic collectSamples_; + std::string profileId_; + int64_t profileIdx_ = 0; + bool includeLines_ = false; + bool withLabels_ = false; + bool started_ = false; struct SampleContext { ValuePtr labels; int64_t time_from; int64_t time_to; - - // Needed to initialize ring buffer elements - SampleContext() = default; - - SampleContext(const ValuePtr& l, int64_t from, int64_t to) : labels(l), time_from(from), time_to(to) {} }; - RingBuffer contexts; + using ContextBuffer = std::vector; + ContextBuffer contexts_; ~WallProfiler(); void Dispose(v8::Isolate* isolate); // A new CPU profiler object will be created each time profiling is started // to work around https://bugs.chromium.org/p/v8/issues/detail?id=11051. - v8::CpuProfiler* GetProfiler(); + v8::CpuProfiler* CreateV8CpuProfiler(); - LabelSetsByNode GetLabelSetsByNode(v8::CpuProfile* profile); + LabelSetsByNode GetLabelSetsByNode(v8::CpuProfile* profile, + ContextBuffer& contexts); public: /** - * @param intervalMicros sampling interval, in microseconds + * @param samplingPeriodMicros sampling interval, in microseconds * @param durationMicros the duration of sampling, in microseconds. This * parameter is informative; it is up to the caller to call the Stop method * every period. The parameter is used to preallocate data structures that * should not be reallocated in async signal safe code. */ - explicit WallProfiler(int intervalMicros, int durationMicros); + explicit WallProfiler(int samplingPeriodMicros, + int durationMicros, + bool includeLines, + bool withLabels); v8::Local GetLabels(v8::Isolate*); void SetLabels(v8::Isolate*, v8::Local); - void PushContext(int64_t time_from); - void StartImpl(v8::Local name, - bool includeLines, - bool withLabels); - v8::Local StopImpl(v8::Local name, - bool includeLines); + void PushContext(int64_t time_from, int64_t time_to); + Result StartImpl(); + std::string StartInternal(); + Result StopImpl(bool restart, v8::Local& profile); + Result StopImplOld(bool restart, v8::Local& profile); + + bool collectSampleAllowed() const { + bool res = collectSamples_.load(std::memory_order_relaxed); + std::atomic_signal_fence(std::memory_order_acquire); + return res; + } static NAN_METHOD(New); - static NAN_METHOD(Dispose); static NAN_METHOD(Start); static NAN_METHOD(Stop); static NAN_MODULE_INIT(Init); diff --git a/bindings/sample.cc b/bindings/sample.cc index 3d10ad04..57fb313b 100644 --- a/bindings/sample.cc +++ b/bindings/sample.cc @@ -1,3 +1,19 @@ +/* + * Copyright 2023 Datadog, Inc + * + * Licensed under the Apache License, Version 2.0 (the "License"); + * you may not use this file except in compliance with the License. + * You may obtain a copy of the License at + * + * http://www.apache.org/licenses/LICENSE-2.0 + * + * Unless required by applicable law or agreed to in writing, software + * distributed under the License is distributed on an "AS IS" BASIS, + * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. + * See the License for the specific language governing permissions and + * limitations under the License. + */ + #include #include #include diff --git a/bindings/sample.hh b/bindings/sample.hh index 47b15964..5ea84b70 100644 --- a/bindings/sample.hh +++ b/bindings/sample.hh @@ -1,3 +1,19 @@ +/* + * Copyright 2023 Datadog, Inc + * + * Licensed under the Apache License, Version 2.0 (the "License"); + * you may not use this file except in compliance with the License. + * You may obtain a copy of the License at + * + * http://www.apache.org/licenses/LICENSE-2.0 + * + * Unless required by applicable law or agreed to in writing, software + * distributed under the License is distributed on an "AS IS" BASIS, + * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. + * See the License for the specific language governing permissions and + * limitations under the License. + */ + #pragma once #include diff --git a/bindings/test/binding.cc b/bindings/test/binding.cc index 1ed3854a..fa819de2 100644 --- a/bindings/test/binding.cc +++ b/bindings/test/binding.cc @@ -1,3 +1,19 @@ +/* + * Copyright 2023 Datadog, Inc + * + * Licensed under the Apache License, Version 2.0 (the "License"); + * you may not use this file except in compliance with the License. + * You may obtain a copy of the License at + * + * http://www.apache.org/licenses/LICENSE-2.0 + * + * Unless required by applicable law or agreed to in writing, software + * distributed under the License is distributed on an "AS IS" BASIS, + * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. + * See the License for the specific language governing permissions and + * limitations under the License. + */ + #include #include #include diff --git a/bindings/test/code-event-record.test.cc b/bindings/test/code-event-record.test.cc index b317425f..5776fe09 100644 --- a/bindings/test/code-event-record.test.cc +++ b/bindings/test/code-event-record.test.cc @@ -1,3 +1,19 @@ +/* + * Copyright 2023 Datadog, Inc + * + * Licensed under the Apache License, Version 2.0 (the "License"); + * you may not use this file except in compliance with the License. + * You may obtain a copy of the License at + * + * http://www.apache.org/licenses/LICENSE-2.0 + * + * Unless required by applicable law or agreed to in writing, software + * distributed under the License is distributed on an "AS IS" BASIS, + * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. + * See the License for the specific language governing permissions and + * limitations under the License. + */ + #include #include diff --git a/bindings/test/code-event-record.test.hh b/bindings/test/code-event-record.test.hh index 9cb3e7d9..12b6c0f7 100644 --- a/bindings/test/code-event-record.test.hh +++ b/bindings/test/code-event-record.test.hh @@ -1,3 +1,19 @@ +/* + * Copyright 2023 Datadog, Inc + * + * Licensed under the Apache License, Version 2.0 (the "License"); + * you may not use this file except in compliance with the License. + * You may obtain a copy of the License at + * + * http://www.apache.org/licenses/LICENSE-2.0 + * + * Unless required by applicable law or agreed to in writing, software + * distributed under the License is distributed on an "AS IS" BASIS, + * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. + * See the License for the specific language governing permissions and + * limitations under the License. + */ + #pragma once #include "tap.h" diff --git a/bindings/test/code-map.test.cc b/bindings/test/code-map.test.cc index 0cadcefa..bf9959ad 100644 --- a/bindings/test/code-map.test.cc +++ b/bindings/test/code-map.test.cc @@ -1,3 +1,19 @@ +/* + * Copyright 2023 Datadog, Inc + * + * Licensed under the Apache License, Version 2.0 (the "License"); + * you may not use this file except in compliance with the License. + * You may obtain a copy of the License at + * + * http://www.apache.org/licenses/LICENSE-2.0 + * + * Unless required by applicable law or agreed to in writing, software + * distributed under the License is distributed on an "AS IS" BASIS, + * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. + * See the License for the specific language governing permissions and + * limitations under the License. + */ + #include "code-map.test.hh" #include "../code-map.hh" diff --git a/bindings/test/code-map.test.hh b/bindings/test/code-map.test.hh index 9ed7d5ee..eaa2592e 100644 --- a/bindings/test/code-map.test.hh +++ b/bindings/test/code-map.test.hh @@ -1,3 +1,19 @@ +/* + * Copyright 2023 Datadog, Inc + * + * Licensed under the Apache License, Version 2.0 (the "License"); + * you may not use this file except in compliance with the License. + * You may obtain a copy of the License at + * + * http://www.apache.org/licenses/LICENSE-2.0 + * + * Unless required by applicable law or agreed to in writing, software + * distributed under the License is distributed on an "AS IS" BASIS, + * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. + * See the License for the specific language governing permissions and + * limitations under the License. + */ + #pragma once #include "tap.h" diff --git a/bindings/test/cpu-time.test.cc b/bindings/test/cpu-time.test.cc index 0867c0e5..769e3813 100644 --- a/bindings/test/cpu-time.test.cc +++ b/bindings/test/cpu-time.test.cc @@ -1,3 +1,19 @@ +/* + * Copyright 2023 Datadog, Inc + * + * Licensed under the Apache License, Version 2.0 (the "License"); + * you may not use this file except in compliance with the License. + * You may obtain a copy of the License at + * + * http://www.apache.org/licenses/LICENSE-2.0 + * + * Unless required by applicable law or agreed to in writing, software + * distributed under the License is distributed on an "AS IS" BASIS, + * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. + * See the License for the specific language governing permissions and + * limitations under the License. + */ + #include "cpu-time.test.hh" #include "../cpu-time.hh" diff --git a/bindings/test/cpu-time.test.hh b/bindings/test/cpu-time.test.hh index eb9403c9..df1ae55c 100644 --- a/bindings/test/cpu-time.test.hh +++ b/bindings/test/cpu-time.test.hh @@ -1,3 +1,19 @@ +/* + * Copyright 2023 Datadog, Inc + * + * Licensed under the Apache License, Version 2.0 (the "License"); + * you may not use this file except in compliance with the License. + * You may obtain a copy of the License at + * + * http://www.apache.org/licenses/LICENSE-2.0 + * + * Unless required by applicable law or agreed to in writing, software + * distributed under the License is distributed on an "AS IS" BASIS, + * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. + * See the License for the specific language governing permissions and + * limitations under the License. + */ + #pragma once #include "tap.h" diff --git a/bindings/test/location.test.cc b/bindings/test/location.test.cc index 7c4ad5bd..ae407d8b 100644 --- a/bindings/test/location.test.cc +++ b/bindings/test/location.test.cc @@ -1,3 +1,19 @@ +/* + * Copyright 2023 Datadog, Inc + * + * Licensed under the Apache License, Version 2.0 (the "License"); + * you may not use this file except in compliance with the License. + * You may obtain a copy of the License at + * + * http://www.apache.org/licenses/LICENSE-2.0 + * + * Unless required by applicable law or agreed to in writing, software + * distributed under the License is distributed on an "AS IS" BASIS, + * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. + * See the License for the specific language governing permissions and + * limitations under the License. + */ + #include "location.test.hh" #include "../location.hh" diff --git a/bindings/test/location.test.hh b/bindings/test/location.test.hh index 0a591885..a38b4b53 100644 --- a/bindings/test/location.test.hh +++ b/bindings/test/location.test.hh @@ -1,3 +1,19 @@ +/* + * Copyright 2023 Datadog, Inc + * + * Licensed under the Apache License, Version 2.0 (the "License"); + * you may not use this file except in compliance with the License. + * You may obtain a copy of the License at + * + * http://www.apache.org/licenses/LICENSE-2.0 + * + * Unless required by applicable law or agreed to in writing, software + * distributed under the License is distributed on an "AS IS" BASIS, + * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. + * See the License for the specific language governing permissions and + * limitations under the License. + */ + #pragma once #include "tap.h" diff --git a/bindings/test/profilers/cpu.test.cc b/bindings/test/profilers/cpu.test.cc index 24cf68da..f4156358 100644 --- a/bindings/test/profilers/cpu.test.cc +++ b/bindings/test/profilers/cpu.test.cc @@ -1,3 +1,19 @@ +/* + * Copyright 2023 Datadog, Inc + * + * Licensed under the Apache License, Version 2.0 (the "License"); + * you may not use this file except in compliance with the License. + * You may obtain a copy of the License at + * + * http://www.apache.org/licenses/LICENSE-2.0 + * + * Unless required by applicable law or agreed to in writing, software + * distributed under the License is distributed on an "AS IS" BASIS, + * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. + * See the License for the specific language governing permissions and + * limitations under the License. + */ + #include "cpu.test.hh" #include "../../location.hh" #include "../../profilers/cpu.hh" diff --git a/bindings/test/profilers/cpu.test.hh b/bindings/test/profilers/cpu.test.hh index 125ccab2..2a7e67ee 100644 --- a/bindings/test/profilers/cpu.test.hh +++ b/bindings/test/profilers/cpu.test.hh @@ -1,3 +1,19 @@ +/* + * Copyright 2023 Datadog, Inc + * + * Licensed under the Apache License, Version 2.0 (the "License"); + * you may not use this file except in compliance with the License. + * You may obtain a copy of the License at + * + * http://www.apache.org/licenses/LICENSE-2.0 + * + * Unless required by applicable law or agreed to in writing, software + * distributed under the License is distributed on an "AS IS" BASIS, + * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. + * See the License for the specific language governing permissions and + * limitations under the License. + */ + #pragma once #include "../tap.h" diff --git a/bindings/test/sample.test.cc b/bindings/test/sample.test.cc index 06e57f50..bceefe87 100644 --- a/bindings/test/sample.test.cc +++ b/bindings/test/sample.test.cc @@ -1,3 +1,19 @@ +/* + * Copyright 2023 Datadog, Inc + * + * Licensed under the Apache License, Version 2.0 (the "License"); + * you may not use this file except in compliance with the License. + * You may obtain a copy of the License at + * + * http://www.apache.org/licenses/LICENSE-2.0 + * + * Unless required by applicable law or agreed to in writing, software + * distributed under the License is distributed on an "AS IS" BASIS, + * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. + * See the License for the specific language governing permissions and + * limitations under the License. + */ + #include #include "../sample.hh" diff --git a/bindings/test/sample.test.hh b/bindings/test/sample.test.hh index de1cfccb..b7d4267e 100644 --- a/bindings/test/sample.test.hh +++ b/bindings/test/sample.test.hh @@ -1,3 +1,19 @@ +/* + * Copyright 2023 Datadog, Inc + * + * Licensed under the Apache License, Version 2.0 (the "License"); + * you may not use this file except in compliance with the License. + * You may obtain a copy of the License at + * + * http://www.apache.org/licenses/LICENSE-2.0 + * + * Unless required by applicable law or agreed to in writing, software + * distributed under the License is distributed on an "AS IS" BASIS, + * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. + * See the License for the specific language governing permissions and + * limitations under the License. + */ + #pragma once #include "tap.h" diff --git a/bindings/test/tap.h b/bindings/test/tap.h index 25d19e63..a6b20377 100644 --- a/bindings/test/tap.h +++ b/bindings/test/tap.h @@ -1,11 +1,17 @@ -/** - * @file tap.h - * @author Stephen Belanger - * @date Apr 13, 2022 - * @brief C and C++ API for TAP testing +/* + * Copyright 2023 Datadog, Inc + * + * Licensed under the Apache License, Version 2.0 (the "License"); + * you may not use this file except in compliance with the License. + * You may obtain a copy of the License at + * + * http://www.apache.org/licenses/LICENSE-2.0 * - * @todo TODO directives - * @todo YAML blocks? + * Unless required by applicable law or agreed to in writing, software + * distributed under the License is distributed on an "AS IS" BASIS, + * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. + * See the License for the specific language governing permissions and + * limitations under the License. */ #ifndef _INCLUDE_TAP_H_ diff --git a/bindings/translate-time-profile.cc b/bindings/translate-time-profile.cc new file mode 100644 index 00000000..c3ec3a7e --- /dev/null +++ b/bindings/translate-time-profile.cc @@ -0,0 +1,252 @@ +/** + * Copyright 2018 Google Inc. All Rights Reserved. + * + * Licensed under the Apache License, Version 2.0 (the "License"); + * you may not use this file except in compliance with the License. + * You may obtain a copy of the License at + * + * http://www.apache.org/licenses/LICENSE-2.0 + * + * Unless required by applicable law or agreed to in writing, software + * distributed under the License is distributed on an "AS IS" BASIS, + * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. + * See the License for the specific language governing permissions and + * limitations under the License. + */ + +#include "translate-time-profile.hh" + +#include + +namespace dd { + +namespace { +class ProfileTranslator { + private: + LabelSetsByNode* labelSetsByNode; + v8::Isolate* isolate = v8::Isolate::GetCurrent(); + v8::Local emptyArray = NewArray(0); + v8::Local zero = NewInteger(0); + +#define FIELDS \ + X(name) \ + X(scriptName) \ + X(scriptId) \ + X(lineNumber) \ + X(columnNumber) \ + X(hitCount) \ + X(children) \ + X(labelSets) + +#define X(name) v8::Local str_##name = NewString(#name); + FIELDS +#undef X + + v8::Local getLabelSetsForNode(const v8::CpuProfileNode* node, + uint32_t& hitcount) { + hitcount = node->GetHitCount(); + if (!labelSetsByNode) { + // custom labels are not enabled, keep the node hitcount and return empty + // array + return emptyArray; + } + + auto it = labelSetsByNode->find(node); + auto labelSets = emptyArray; + if (it != labelSetsByNode->end()) { + hitcount = it->second.hitcount; + labelSets = it->second.labelSets; + } else { + // no context found for node, discard it since every sample taken from + // signal handler should have a matching context if it does not, it means + // sample was captured by a deopt event + hitcount = 0; + } + return labelSets; + } + + v8::Local CreateTimeNode(v8::Local name, + v8::Local scriptName, + v8::Local scriptId, + v8::Local lineNumber, + v8::Local columnNumber, + v8::Local hitCount, + v8::Local children, + v8::Local labelSets) { + v8::Local js_node = Nan::New(); +#define X(name) Nan::Set(js_node, str_##name, name); + FIELDS +#undef X +#undef FIELDS + return js_node; + } + + v8::Local NewInteger(int32_t x) { + return v8::Integer::New(isolate, x); + } + + v8::Local NewArray(int length) { + return v8::Array::New(isolate, length); + } + + v8::Local NewString(const char* str) { + return Nan::New(str).ToLocalChecked(); + } + + v8::Local GetLineNumberTimeProfileChildren( + const v8::CpuProfileNode* node) { + unsigned int index = 0; + v8::Local children; + int32_t count = node->GetChildrenCount(); + + unsigned int hitLineCount = node->GetHitLineCount(); + unsigned int hitCount = node->GetHitCount(); + auto scriptId = NewInteger(node->GetScriptId()); + if (hitLineCount > 0) { + std::vector entries(hitLineCount); + node->GetLineTicks(&entries[0], hitLineCount); + children = NewArray(count + hitLineCount); + for (const v8::CpuProfileNode::LineTick entry : entries) { + Nan::Set(children, + index++, + CreateTimeNode(node->GetFunctionName(), + node->GetScriptResourceName(), + scriptId, + NewInteger(entry.line), + zero, + NewInteger(entry.hit_count), + emptyArray, + emptyArray)); + } + } else if (hitCount > 0) { + // Handle nodes for pseudo-functions like "process" and "garbage + // collection" which do not have hit line counts. + children = NewArray(count + 1); + Nan::Set(children, + index++, + CreateTimeNode(node->GetFunctionName(), + node->GetScriptResourceName(), + scriptId, + NewInteger(node->GetLineNumber()), + NewInteger(node->GetColumnNumber()), + NewInteger(hitCount), + emptyArray, + emptyArray)); + } else { + children = NewArray(count); + } + + for (int32_t i = 0; i < count; i++) { + Nan::Set(children, + index++, + TranslateLineNumbersTimeProfileNode(node, node->GetChild(i))); + }; + + return children; + } + + v8::Local TranslateLineNumbersTimeProfileNode( + const v8::CpuProfileNode* parent, const v8::CpuProfileNode* node) { + return CreateTimeNode(parent->GetFunctionName(), + parent->GetScriptResourceName(), + NewInteger(parent->GetScriptId()), + NewInteger(node->GetLineNumber()), + NewInteger(node->GetColumnNumber()), + zero, + GetLineNumberTimeProfileChildren(node), + emptyArray); + } + + // In profiles with line level accurate line numbers, a node's line number + // and column number refer to the line/column from which the function was + // called. + v8::Local TranslateLineNumbersTimeProfileRoot( + const v8::CpuProfileNode* node) { + int32_t count = node->GetChildrenCount(); + std::vector> childrenArrs(count); + int32_t childCount = 0; + for (int32_t i = 0; i < count; i++) { + v8::Local c = + GetLineNumberTimeProfileChildren(node->GetChild(i)); + childCount = childCount + c->Length(); + childrenArrs[i] = c; + } + + v8::Local children = NewArray(childCount); + int32_t idx = 0; + for (int32_t i = 0; i < count; i++) { + v8::Local arr = childrenArrs[i]; + for (uint32_t j = 0; j < arr->Length(); j++) { + Nan::Set(children, idx, Nan::Get(arr, j).ToLocalChecked()); + idx++; + } + } + + return CreateTimeNode(node->GetFunctionName(), + node->GetScriptResourceName(), + NewInteger(node->GetScriptId()), + NewInteger(node->GetLineNumber()), + NewInteger(node->GetColumnNumber()), + zero, + children, + emptyArray); + } + + v8::Local TranslateTimeProfileNode( + const v8::CpuProfileNode* node) { + int32_t count = node->GetChildrenCount(); + v8::Local children = Nan::New(count); + for (int32_t i = 0; i < count; i++) { + Nan::Set(children, i, TranslateTimeProfileNode(node->GetChild(i))); + } + + uint32_t hitcount = 0; + auto labels = getLabelSetsForNode(node, hitcount); + + return CreateTimeNode(node->GetFunctionName(), + node->GetScriptResourceName(), + NewInteger(node->GetScriptId()), + NewInteger(node->GetLineNumber()), + NewInteger(node->GetColumnNumber()), + NewInteger(hitcount), + children, + labels); + } + + public: + explicit ProfileTranslator(LabelSetsByNode* nls = nullptr) + : labelSetsByNode(nls) {} + + v8::Local TranslateTimeProfile(const v8::CpuProfile* profile, + bool includeLineInfo) { + v8::Local js_profile = Nan::New(); + + if (includeLineInfo) { + Nan::Set(js_profile, + NewString("topDownRoot"), + TranslateLineNumbersTimeProfileRoot(profile->GetTopDownRoot())); + } else { + Nan::Set(js_profile, + NewString("topDownRoot"), + TranslateTimeProfileNode(profile->GetTopDownRoot())); + } + Nan::Set(js_profile, + NewString("startTime"), + Nan::New(profile->GetStartTime())); + Nan::Set(js_profile, + NewString("endTime"), + Nan::New(profile->GetEndTime())); + + return js_profile; + } +}; +} // namespace + +v8::Local TranslateTimeProfile(const v8::CpuProfile* profile, + bool includeLineInfo, + LabelSetsByNode* labelSetsByNode) { + return ProfileTranslator(labelSetsByNode) + .TranslateTimeProfile(profile, includeLineInfo); +} + +} // namespace dd \ No newline at end of file diff --git a/bindings/translate-time-profile.hh b/bindings/translate-time-profile.hh new file mode 100644 index 00000000..ed96e41a --- /dev/null +++ b/bindings/translate-time-profile.hh @@ -0,0 +1,31 @@ +/** + * Copyright 2018 Google Inc. All Rights Reserved. + * + * Licensed under the Apache License, Version 2.0 (the "License"); + * you may not use this file except in compliance with the License. + * You may obtain a copy of the License at + * + * http://www.apache.org/licenses/LICENSE-2.0 + * + * Unless required by applicable law or agreed to in writing, software + * distributed under the License is distributed on an "AS IS" BASIS, + * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. + * See the License for the specific language governing permissions and + * limitations under the License. + */ + +#pragma once + +#include "labelsets.hh" + +#include +#include + +namespace dd { + +v8::Local TranslateTimeProfile( + const v8::CpuProfile* profile, + bool includeLineInfo, + LabelSetsByNode* labelSetsByNode = nullptr); + +} // namespace dd diff --git a/bindings/wrap.hh b/bindings/wrap.hh index cbd65c32..0da587ac 100644 --- a/bindings/wrap.hh +++ b/bindings/wrap.hh @@ -1,3 +1,19 @@ +/* + * Copyright 2023 Datadog, Inc + * + * Licensed under the Apache License, Version 2.0 (the "License"); + * you may not use this file except in compliance with the License. + * You may obtain a copy of the License at + * + * http://www.apache.org/licenses/LICENSE-2.0 + * + * Unless required by applicable law or agreed to in writing, software + * distributed under the License is distributed on an "AS IS" BASIS, + * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. + * See the License for the specific language governing permissions and + * limitations under the License. + */ + #pragma once #include // cppcheck-suppress missingIncludeSystem diff --git a/package.json b/package.json index 2c3f40e9..f43f1540 100644 --- a/package.json +++ b/package.json @@ -8,9 +8,9 @@ "scripts": { "install": "exit 0", "rebuild": "node-gyp rebuild --jobs=max", - "test:js": "nyc mocha out/test/test-*.js", + "test:js": "nyc mocha -r source-map-support/register out/test/test-*.js", "test:cpp": "node scripts/cctest.js", - "test:wall": "nyc mocha out/test/test-time-profiler.js", + "test:wall": "nyc mocha -r source-map-support/register out/test/test-time-profiler.js", "test": "npm run test:js && npm run test:cpp", "codecov": "nyc report --reporter=json && codecov -f coverage/*.json", "compile": "tsc -p .", diff --git a/ts/src/index.ts b/ts/src/index.ts index 6bf7e7c1..89cdfb04 100644 --- a/ts/src/index.ts +++ b/ts/src/index.ts @@ -30,7 +30,9 @@ export const CpuProfiler = cpuProfiler; export const time = { profile: timeProfiler.profile, start: timeProfiler.start, - startWithLabels: timeProfiler.startWithLabels, + stop: timeProfiler.stop, + setLabels: timeProfiler.setLabels, + isStarted: timeProfiler.isStarted, }; export const heap = { @@ -45,11 +47,11 @@ export const heap = { // If loaded with --require, start profiling. if (module.parent && module.parent.id === 'internal/preload') { - const stop = time.start(); + time.start({}); process.on('exit', () => { // The process is going to terminate imminently. All work here needs to // be synchronous. - const profile = stop(); + const profile = time.stop(); const buffer = encodeSync(profile); writeFileSync(`pprof-profile-${process.pid}.pb.gz`, buffer); }); diff --git a/ts/src/time-profiler.ts b/ts/src/time-profiler.ts index 492c1132..84356c35 100644 --- a/ts/src/time-profiler.ts +++ b/ts/src/time-profiler.ts @@ -22,20 +22,27 @@ import {TimeProfiler} from './time-profiler-bindings'; import {LabelSet} from './v8-types'; const DEFAULT_INTERVAL_MICROS: Microseconds = 1000; -const DEFAULT_DURATION_MICROS: Microseconds = 60000000; - -const majorVersion = process.version.slice(1).split('.').map(Number)[0]; +const DEFAULT_DURATION_MILLIS: Milliseconds = 60000; type Microseconds = number; type Milliseconds = number; +let gProfiler: InstanceType | undefined; +let gSourceMapper: SourceMapper | undefined; +let gIntervalMicros: Microseconds; + +/** Make sure to stop profiler before node shuts down, otherwise profiling + * signal might cause a crash if it occurs during shutdown */ +process.once('exit', () => { + if (isStarted()) stop(); +}); + export interface TimeProfilerOptions { /** time in milliseconds for which to collect profile. */ - durationMillis: Milliseconds; + durationMillis?: Milliseconds; /** average time in microseconds between samples */ intervalMicros?: Microseconds; sourceMapper?: SourceMapper; - name?: string; /** * This configuration option is experimental. @@ -44,111 +51,76 @@ export interface TimeProfilerOptions { * This defaults to false. */ lineNumbers?: boolean; + customLabels?: boolean; } -export async function profile(options: TimeProfilerOptions) { - const stop = start( - options.intervalMicros || DEFAULT_INTERVAL_MICROS, - options.name, - options.sourceMapper, - options.lineNumbers - ); - await delay(options.durationMillis); - return stop(); -} - -function ensureRunName(name?: string) { - return name || `pprof-${Date.now()}-${Math.random()}`; -} - -// Temporarily retained for backwards compatibility with older tracer -export function start( - intervalMicros: Microseconds = DEFAULT_INTERVAL_MICROS, - name?: string, - sourceMapper?: SourceMapper, - lineNumbers = true -) { - const {stop} = startInternal( - intervalMicros, - // Duration must be at least intervalMicros; not used anyway when - // not collecting extra info (CPU time, labels) with samples. +export async function profile({ + intervalMicros = DEFAULT_INTERVAL_MICROS, + durationMillis = DEFAULT_DURATION_MILLIS, + sourceMapper, + lineNumbers = false, + customLabels = false, +}: TimeProfilerOptions) { + start({ intervalMicros, - name, + durationMillis, sourceMapper, lineNumbers, - false - ); - return stop; + customLabels, + }); + await delay(durationMillis); + return stop(); } -export function startWithLabels( - intervalMicros: Microseconds = DEFAULT_INTERVAL_MICROS, - durationMicros: Microseconds = DEFAULT_DURATION_MICROS, - name?: string, - sourceMapper?: SourceMapper, - lineNumbers = true -) { - return startInternal( +// Temporarily retained for backwards compatibility with older tracer +export function start({ + intervalMicros = DEFAULT_INTERVAL_MICROS, + durationMillis = DEFAULT_DURATION_MILLIS, + sourceMapper, + lineNumbers = false, + customLabels = false, +}: TimeProfilerOptions) { + if (gProfiler) { + throw new Error('Wall profiler is already started'); + } + + gProfiler = new TimeProfiler( intervalMicros, - durationMicros, - name, - sourceMapper, + durationMillis * 1000, lineNumbers, - true + customLabels ); + gProfiler.start(); + gSourceMapper = sourceMapper; + gIntervalMicros = intervalMicros; } -// NOTE: refreshing doesn't work if giving a profile name. -function startInternal( - intervalMicros: Microseconds, - durationMicros: Microseconds, - name?: string, - sourceMapper?: SourceMapper, - lineNumbers?: boolean, - withLabels?: boolean -) { - const profiler = new TimeProfiler(intervalMicros, durationMicros); - let runName = start(); - return { - stop: majorVersion < 16 ? stopOld : stop, - setLabels - }; - - function start() { - const runName = ensureRunName(name); - profiler.start(runName, lineNumbers, withLabels); - return runName; +export function stop(restart = false) { + if (!gProfiler) { + throw new Error('Wall profiler is not started'); } - // Node.js versions prior to v16 leak memory if not disposed and recreated - // between each profile. As disposing deletes current profile data too, - // we must stop then dispose then start. - function stopOld(restart = false) { - const result = profiler.stop(runName, lineNumbers); - profiler.dispose(); - if (restart) { - runName = start(); - } - return serializeTimeProfile(result, intervalMicros, sourceMapper, true); + const profile = gProfiler.stop(restart); + const serialized_profile = serializeTimeProfile( + profile, + gIntervalMicros, + gSourceMapper, + true + ); + if (!restart) { + gProfiler = undefined; + gSourceMapper = undefined; } + return serialized_profile; +} - // For Node.js v16+, we want to start the next profile before we stop the - // current one as otherwise the active profile count could reach zero which - // means V8 might tear down the symbolizer thread and need to start it again. - function stop(restart = false) { - let nextRunName; - if (restart) { - nextRunName = start(); - } - const result = profiler.stop(runName, lineNumbers); - if (nextRunName) { - runName = nextRunName; - } - if (!restart) profiler.dispose(); - return serializeTimeProfile(result, intervalMicros, sourceMapper, true); +export function setLabels(labels?: LabelSet) { + if (!gProfiler) { + throw new Error('Wall profiler is not started'); } + gProfiler.labels = labels; +} - function setLabels(labels?: LabelSet) { - profiler.labels = labels; - } +export function isStarted() { + return !!gProfiler; } diff --git a/ts/test/test-time-profiler.ts b/ts/test/test-time-profiler.ts index 82a6f2ac..84d25b76 100644 --- a/ts/test/test-time-profiler.ts +++ b/ts/test/test-time-profiler.ts @@ -25,8 +25,6 @@ import {AssertionError} from 'assert'; const assert = require('assert'); -const majorVersion = process.version.slice(1).split('.').map(Number)[0]; - const PROFILE_OPTIONS = { durationMillis: 500, intervalMicros: 1000, @@ -46,18 +44,25 @@ describe('Time Profiler', () => { ); }); - it('should assign labels', () => { + it('should assign labels', function () { + if (process.platform !== 'darwin' && process.platform !== 'linux') { + this.skip(); + } + this.timeout(3000); + const intervalNanos = PROFILE_OPTIONS.intervalMicros * 1_000; - const {stop, setLabels} = time.startWithLabels( - PROFILE_OPTIONS.intervalMicros, - PROFILE_OPTIONS.durationMillis * 1000 - ); + time.start({ + intervalMicros: PROFILE_OPTIONS.intervalMicros, + durationMillis: PROFILE_OPTIONS.durationMillis, + customLabels: true, + lineNumbers: false, + }); // By repeating the test few times, we also exercise the profiler // start-stop overlap behavior. const repeats = 3; for (let i = 0; i < repeats; ++i) { loop(); - validateProfile(stop(i < repeats - 1)); + validateProfile(time.stop(i < repeats - 1)); } // Each of fn0, fn1, fn2 loops busily for one or two profiling intervals. @@ -72,7 +77,7 @@ describe('Time Profiler', () => { function fn0() { const start = hrtime.bigint(); while (hrtime.bigint() - start < intervalNanos); - setLabels(undefined); + time.setLabels(undefined); } function fn1() { @@ -91,11 +96,11 @@ describe('Time Profiler', () => { const durationNanos = PROFILE_OPTIONS.durationMillis * 1_000_000; const start = hrtime.bigint(); while (hrtime.bigint() - start < durationNanos) { - setLabels(label0); + time.setLabels(label0); fn0(); - setLabels(label1); + time.setLabels(label1); fn1(); - setLabels(undefined); + time.setLabels(undefined); fn2(); } } @@ -114,7 +119,6 @@ describe('Time Profiler', () => { ] = ['loop', 'fn0', 'fn1', 'fn2', 'label', 'value0', 'value1'].map(x => stringTable.dedup(x) ); - function labelIs(l: Label, str: number) { return l.key === labelIdx && l.str === str; } @@ -128,7 +132,7 @@ describe('Time Profiler', () => { } function labelStr(label: Label) { - return label ? stringTable.strings[idx(label.str) + 1] : "undefined"; + return label ? stringTable.strings[idx(label.str) + 1] : 'undefined'; } let fn0ObservedWithLabel0 = false; @@ -202,9 +206,8 @@ describe('Time Profiler', () => { // eslint-disable-next-line @typescript-eslint/no-explicit-any const sinonStubs: Array> = []; const timeProfilerStub = { - start: sinon.stub().returns(BigInt(0)), + start: sinon.stub(), stop: sinon.stub().returns(v8TimeProfile), - dispose: sinon.stub(), }; before(() => { @@ -235,30 +238,22 @@ describe('Time Profiler', () => { }); it('should be able to restart when stopping', async () => { - const stop = time.start(PROFILE_OPTIONS.intervalMicros); + time.start({intervalMicros: PROFILE_OPTIONS.intervalMicros}); timeProfilerStub.start.resetHistory(); timeProfilerStub.stop.resetHistory(); - timeProfilerStub.dispose.resetHistory(); - assert.deepEqual(timeProfile, stop(true)); + assert.deepEqual(timeProfile, time.stop(true)); - sinon.assert.calledOnce(timeProfilerStub.start); + sinon.assert.notCalled(timeProfilerStub.start); sinon.assert.calledOnce(timeProfilerStub.stop); - if (majorVersion >= 16) { - sinon.assert.notCalled(timeProfilerStub.dispose); - } else { - sinon.assert.calledOnce(timeProfilerStub.dispose); - } timeProfilerStub.start.resetHistory(); timeProfilerStub.stop.resetHistory(); - timeProfilerStub.dispose.resetHistory(); - assert.deepEqual(timeProfile, stop()); + assert.deepEqual(timeProfile, time.stop()); sinon.assert.notCalled(timeProfilerStub.start); sinon.assert.calledOnce(timeProfilerStub.stop); - sinon.assert.calledOnce(timeProfilerStub.dispose); }); }); });