Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

feat: memory profiling #524

Merged
merged 24 commits into from
Sep 16, 2022
Merged
Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
24 commits
Select commit Hold shift + click to select a range
4107568
feat: export pprof (#517)
rauno56 Aug 1, 2022
2c12b57
fix: add source.event.period to samples
seemk Aug 2, 2022
12f3ba1
fix: handle unknown line numbers
seemk Aug 2, 2022
fdc0976
initial memory samples serialization
seemk Aug 4, 2022
95fa794
fix: don't overwrite stacktrace lines array
seemk Aug 4, 2022
f03d78d
Merge branch 'pprof-export' into memory-profiling
seemk Aug 5, 2022
eb96e3f
feat: simplify sample collection
seemk Aug 5, 2022
dadab9e
feat: bfs traversal of allocations
seemk Aug 6, 2022
80e2e09
fix: keep track of new samples
seemk Aug 6, 2022
bd432c8
feat: add stop for memory profiling, clean out printouts
seemk Aug 7, 2022
67b4f1d
refactor: remove duplicate code
seemk Aug 7, 2022
9b7c3ce
refactor: remove duplicate code, fix cpu serialization test
seemk Aug 7, 2022
00028b2
fix: add timestamps to heap profile, add a test
seemk Aug 7, 2022
417558a
test: add test for heap profile collection
seemk Aug 7, 2022
2e5f1d7
test: add test for memory profiling export
seemk Aug 7, 2022
0759bff
chore: remove unsupported versions from prebuilds
seemk Aug 7, 2022
b28140f
doc: update profiling docs
seemk Aug 7, 2022
ea1d844
test: reduce allocation test flakiness
seemk Aug 7, 2022
e95beae
Merge branch 'main' into memory-profiling
seemk Aug 7, 2022
0bf4bf9
doc: add a doc about memory profiling
seemk Aug 7, 2022
ba710a9
doc: improve wording
seemk Aug 9, 2022
6b6d482
refactor: remove unused function
seemk Sep 13, 2022
d9a517a
Merge branch 'main' into memory-profiling
seemk Sep 13, 2022
284799e
refactor: use range based for
seemk Sep 13, 2022
File filter

Filter by extension

Filter by extension

Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
1 change: 1 addition & 0 deletions binding.gyp
Original file line number Diff line number Diff line change
Expand Up @@ -6,6 +6,7 @@
"src/native_ext/util/hex.cpp",
"src/native_ext/module.cpp",
"src/native_ext/metrics.cpp",
"src/native_ext/memory_profiling.cpp",
"src/native_ext/profiling.cpp",
"src/native_ext/util/modp_numtoa.cpp",
"src/native_ext/util/platform.cpp"
Expand Down
1 change: 1 addition & 0 deletions docs/advanced-config.md
Original file line number Diff line number Diff line change
Expand Up @@ -82,6 +82,7 @@ The following config options can be set by passing them as arguments to `startTr
| Environment variable<br>``startProfiling()`` argument | Default value | Support | Notes
| --------------------------------------------------------------- | ----------------------- | ------- | ---
| `SPLUNK_PROFILER_ENABLED` | `false` | Experimental | Enable continuous profiling. See [profiling documentation](profiling.md) for more information.
| `SPLUNK_PROFILER_MEMORY_ENABLED`<br>`memoryProfilingEnabled` | `false` | Experimental | Enable continuous memory profiling.
| `SPLUNK_PROFILER_LOGS_ENDPOINT`<br>`endpoint` | `http://localhost:4317` | Experimental | The OTLP logs receiver endpoint used for profiling data.
| `OTEL_SERVICE_NAME`<br>`serviceName` | `unnamed-node-service` | Stable | Service name of the application.
| `OTEL_RESOURCE_ATTRIBUTES` | | Stable | Comma-separated list of resource attributes. <details><summary>Example</summary>`deployment.environment=demo,key2=val2`</details>
Expand Down
23 changes: 23 additions & 0 deletions docs/profiling.md
Original file line number Diff line number Diff line change
Expand Up @@ -10,6 +10,7 @@ When loading the instrumentation via CLI:

```
export SPLUNK_PROFILER_ENABLED=true
export SPLUNK_PROFILER_MEMORY_ENABLED=true
node -r @splunk/otel/instrument app.js
```

Expand All @@ -21,7 +22,29 @@ const { startProfiling } = require('@splunk/otel');
// NOTE: profiling needs to be started before tracing. This will be fixed in future versions.
startProfiling({
serviceName: 'my-service',
// Optional, disabled by default
memoryProfilingEnabled: true,
});

startTracing({ ... });
```


### Memory profiling

Memory profiling is disabled by default. You can enable it via the `memoryProfilingEnabled` flag.

Internally the profiler uses V8's sampling heap profiler, where it periodically queries for new allocation samples from the allocation profile.

You can tune [V8 heap profiler's parameters](https://v8.github.io/api/head/classv8_1_1HeapProfiler.html#a6b9450bbf1f4e1a4909df92d4df4a174) using the `memoryProfilingOptions` configuration field:

```javascript
startProfiling({
serviceName: 'my-service',
memoryProfilingEnabled: true,
memoryProfilingOptions: {
maxStackDepth: 128, // default: 256
sampleIntervalBytes: 1024 * 64, // default: 1024 * 128
},
});
```
219 changes: 219 additions & 0 deletions src/native_ext/memory_profiling.cpp
Original file line number Diff line number Diff line change
@@ -0,0 +1,219 @@
#include "memory_profiling.h"
#include "khash.h"
#include "util/platform.h"
#include <v8-profiler.h>
#include <vector>

namespace Splunk {
namespace Profiling {

namespace {
enum MemoryProfilingStringIndex {
V8String_Name,
V8String_ScriptName,
V8String_LineNumber,
V8String_ParentId,
V8String_MAX
};

struct BFSNode {
BFSNode(v8::AllocationProfile::Node* node, uint32_t parentId) : node(node), parentId(parentId) {}
v8::AllocationProfile::Node* node;
uint32_t parentId;
};

using AllocationSample = v8::AllocationProfile::Sample;
KHASH_MAP_INIT_INT64(SampleId, uint64_t);

struct MemoryProfiling {
MemoryProfiling() : tracking(kh_init(SampleId)) { stack.reserve(128); }
~MemoryProfiling() { kh_destroy(SampleId, tracking); }
uint64_t generation = 0;
// Used to keep track which were the new samples added to the allocation profile.
khash_t(SampleId) * tracking;
std::vector<BFSNode> stack;
bool isRunning = false;
};

MemoryProfiling* profiling = nullptr;

struct StringStash {
v8::Local<v8::String> strings[V8String_MAX];
};

v8::Local<v8::Object>
ToJsHeapNode(v8::AllocationProfile::Node* node, uint32_t parentId, StringStash* stash) {
auto jsNode = Nan::New<v8::Object>();
Nan::Set(jsNode, stash->strings[V8String_Name], node->name);
Nan::Set(jsNode, stash->strings[V8String_ScriptName], node->script_name);
Nan::Set(jsNode, stash->strings[V8String_LineNumber], Nan::New<v8::Integer>(node->line_number));
Nan::Set(jsNode, stash->strings[V8String_ParentId], Nan::New<v8::Uint32>(parentId));
return jsNode;
}

} // namespace

NAN_METHOD(StartMemoryProfiling) {
if (!profiling) {
profiling = new MemoryProfiling();
}

if (profiling->isRunning) {
return;
}

v8::HeapProfiler* profiler = info.GetIsolate()->GetHeapProfiler();

if (!profiler) {
Nan::ThrowError("unable to get heap profiler - isolate not initialized");
return;
}

int64_t sampleIntervalBytes = 1024 * 128;
int32_t maxStackDepth = 256;

if (info.Length() >= 1 && info[0]->IsObject()) {
auto options = Nan::To<v8::Object>(info[0]).ToLocalChecked();
auto maybeSampleIntervalBytes =
Nan::Get(options, Nan::New("sampleIntervalBytes").ToLocalChecked());
if (
!maybeSampleIntervalBytes.IsEmpty() &&
maybeSampleIntervalBytes.ToLocalChecked()->IsNumber()) {
sampleIntervalBytes = Nan::To<int64_t>(maybeSampleIntervalBytes.ToLocalChecked()).FromJust();
}

auto maybeMaxStackDepth = Nan::Get(options, Nan::New("maxStackDepth").ToLocalChecked());
if (!maybeMaxStackDepth.IsEmpty() && maybeMaxStackDepth.ToLocalChecked()->IsNumber()) {
maxStackDepth = Nan::To<int32_t>(maybeMaxStackDepth.ToLocalChecked()).FromJust();
}
}

profiling->isRunning = profiler->StartSamplingHeapProfiler(sampleIntervalBytes, maxStackDepth);
}

NAN_METHOD(CollectHeapProfile) {
info.GetReturnValue().SetNull();

if (!profiling) {
return;
}

if (!profiling->isRunning) {
return;
}

v8::HeapProfiler* profiler = info.GetIsolate()->GetHeapProfiler();

if (!profiler) {
return;
}

v8::AllocationProfile* profile = profiler->GetAllocationProfile();

if (!profile) {
return;
}

auto jsResult = Nan::New<v8::Object>();
auto jsSamples = Nan::New<v8::Array>();
auto jsNodeTree = Nan::New<v8::Object>();
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Are the node id's unique across the lifetime of the program? I ask to suss out why use object instead of an array where the keys are integers already - saves a conversion and perhaps some (type) errors(even though arr[2] === arr['2']).

Copy link
Collaborator Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Node ID is an incrementing counter. No idea how large it gets and how many gaps will exist. Just used a denser form 🤷‍♂️

Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

const arr = [];
array[5] = "hello";
array[10] = "world";

Makes a "holey" array, which is equivalent in terms of the density. I assume calling the same API from the native side behaves the same.

Copy link
Collaborator Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Tested it and it actually turns to DICTIONARY_ELEMENTS type even with a small app as the node IDs get large, thus it's basically the same as using an object 🤔 And for some reason the average read speed was actually faster when using an object (no idea why) while the write speeds stayed the same.

int32_t jsSamplesLength = 0;

v8::AllocationProfile::Node* root = profile->GetRootNode();

const std::vector<v8::AllocationProfile::Sample>& samples = profile->GetSamples();

profiling->generation++;
uint64_t generation = profiling->generation;

khash_t(SampleId)* tracking = profiling->tracking;

for (const auto& sample : samples) {
if (kh_get(SampleId, tracking, sample.sample_id) == kh_end(tracking)) {
auto jsSample = Nan::New<v8::Object>();
Nan::Set(
jsSample, Nan::New<v8::String>("nodeId").ToLocalChecked(),
Nan::New<v8::Uint32>(sample.node_id));
Nan::Set(
jsSample, Nan::New<v8::String>("size").ToLocalChecked(),
Nan::New<v8::Uint32>(uint32_t(sample.size * sample.count)));
Nan::Set(jsSamples, jsSamplesLength++, jsSample);
}

int ret;
khiter_t it = kh_put(SampleId, tracking, sample.sample_id, &ret);
if (ret != -1) {
kh_value(tracking, it) = generation;
}
}

for (khiter_t it = kh_begin(tracking); it != kh_end(tracking); ++it) {
if (!kh_exist(tracking, it)) {
continue;
}

if (kh_val(tracking, it) != generation) {
kh_del(SampleId, tracking, it);
}
}

StringStash stash;
rauno56 marked this conversation as resolved.
Show resolved Hide resolved
stash.strings[V8String_Name] = Nan::New<v8::String>("name").ToLocalChecked();
stash.strings[V8String_ScriptName] = Nan::New<v8::String>("scriptName").ToLocalChecked();
stash.strings[V8String_LineNumber] = Nan::New<v8::String>("lineNumber").ToLocalChecked();
stash.strings[V8String_ParentId] = Nan::New<v8::String>("parentId").ToLocalChecked();

std::vector<BFSNode>& stack = profiling->stack;
stack.clear();

// Cut off the root node
for (v8::AllocationProfile::Node* child : root->children) {
stack.emplace_back(child, root->node_id);
}

while (!stack.empty()) {
rauno56 marked this conversation as resolved.
Show resolved Hide resolved
BFSNode graphNode = stack.back();
stack.pop_back();

v8::AllocationProfile::Node* node = graphNode.node;

auto jsNode = ToJsHeapNode(node, graphNode.parentId, &stash);
Nan::Set(jsNodeTree, Nan::New<v8::Uint32>(node->node_id), jsNode);

for (v8::AllocationProfile::Node* child : node->children) {
stack.emplace_back(child, node->node_id);
}
}

Nan::Set(jsResult, Nan::New<v8::String>("treeMap").ToLocalChecked(), jsNodeTree);
Nan::Set(jsResult, Nan::New<v8::String>("samples").ToLocalChecked(), jsSamples);
Nan::Set(
jsResult, Nan::New<v8::String>("timestamp").ToLocalChecked(),
Nan::New<v8::Number>(MilliSecondsSinceEpoch()));

info.GetReturnValue().Set(jsResult);

delete profile;
}

NAN_METHOD(StopMemoryProfiling) {
if (!profiling) {
return;
}

if (profiling->isRunning) {
v8::HeapProfiler* profiler = info.GetIsolate()->GetHeapProfiler();

if (!profiler) {
return;
}

profiler->StopSamplingHeapProfiler();
}

delete profiling;
profiling = nullptr;
}

} // namespace Profiling
} // namespace Splunk
13 changes: 13 additions & 0 deletions src/native_ext/memory_profiling.h
Original file line number Diff line number Diff line change
@@ -0,0 +1,13 @@
#pragma once

#include <nan.h>

namespace Splunk {
namespace Profiling {

NAN_METHOD(StartMemoryProfiling);
NAN_METHOD(CollectHeapProfile);
NAN_METHOD(StopMemoryProfiling);

} // namespace Profiling
} // namespace Splunk
37 changes: 23 additions & 14 deletions src/native_ext/profiling.cpp
Original file line number Diff line number Diff line change
@@ -1,10 +1,10 @@
#include "profiling.h"
#include "khash.h"
#include "memory_profiling.h"
#include "util/arena.h"
#include "util/hex.h"
#include "util/modp_numtoa.h"
#include "util/platform.h"
#include <chrono>
#include <inttypes.h>
#include <nan.h>
#include <v8-profiler.h>
Expand Down Expand Up @@ -182,9 +182,11 @@ struct Profiling {
v8::CpuProfiler* profiler;
int64_t wallStartTime = 0;
int64_t startTime = 0;
// Maximum offset in nanoseconds from profiling start from which a sample is considered always valid.
// Maximum offset in nanoseconds from profiling start from which a sample is considered always
rauno56 marked this conversation as resolved.
Show resolved Hide resolved
// valid.
int64_t maxSampleCutoffDelayNanos = 500LL * 1000LL * 1000LL;
// Point in time before which a sample is considered invalid, necessary to avoid biases with self-sampling.
// Point in time before which a sample is considered invalid, necessary to avoid biases with
// self-sampling.
int64_t sampleCutoffPoint = 0;
int32_t activationDepth = 0;
int32_t flags = ProfilingFlags_None;
Expand Down Expand Up @@ -310,12 +312,6 @@ void InsertActivation(Profiling* profiling, SpanActivation* activation) {

Profiling* profiling = nullptr;

int64_t MicroSecondsSinceEpoch() {
return std::chrono::duration_cast<std::chrono::microseconds>(
std::chrono::system_clock::now().time_since_epoch())
.count();
}

void V8StartProfiling(v8::CpuProfiler* profiler, const char* title) {
v8::Local<v8::String> v8Title = Nan::New(title).ToLocalChecked();
const bool recordSamples = true;
Expand Down Expand Up @@ -368,8 +364,11 @@ NAN_METHOD(StartProfiling) {

auto maybeMaxSampleCutoffDelay =
Nan::Get(options, Nan::New("maxSampleCutoffDelayMicroseconds").ToLocalChecked());
if (!maybeMaxSampleCutoffDelay.IsEmpty() && maybeMaxSampleCutoffDelay.ToLocalChecked()->IsNumber()) {
int64_t maxSampleCutoffDelayMicros = Nan::To<int64_t>(maybeMaxSampleCutoffDelay.ToLocalChecked()).FromJust();
if (
rauno56 marked this conversation as resolved.
Show resolved Hide resolved
!maybeMaxSampleCutoffDelay.IsEmpty() &&
maybeMaxSampleCutoffDelay.ToLocalChecked()->IsNumber()) {
int64_t maxSampleCutoffDelayMicros =
Nan::To<int64_t>(maybeMaxSampleCutoffDelay.ToLocalChecked()).FromJust();
profiling->maxSampleCutoffDelayNanos = maxSampleCutoffDelayMicros * 1000LL;
}
}
Expand Down Expand Up @@ -828,9 +827,7 @@ void ProfilingBuildRawStacktraces(
Nan::Set(
jsTrace, Nan::New<v8::String>("timestamp").ToLocalChecked(),
Nan::New<v8::String>(tsBuf, tsLen).ToLocalChecked());
Nan::Set(
jsTrace, Nan::New<v8::String>("stacktrace").ToLocalChecked(),
stackTraceLines);
Nan::Set(jsTrace, Nan::New<v8::String>("stacktrace").ToLocalChecked(), stackTraceLines);

#if PROFILER_DEBUG_EXPORT
char tpBuf[32];
Expand Down Expand Up @@ -1111,6 +1108,18 @@ void Initialize(v8::Local<v8::Object> target) {
profilingModule, Nan::New("exitContext").ToLocalChecked(),
Nan::GetFunction(Nan::New<v8::FunctionTemplate>(ExitContext)).ToLocalChecked());

Nan::Set(
profilingModule, Nan::New("startMemoryProfiling").ToLocalChecked(),
Nan::GetFunction(Nan::New<v8::FunctionTemplate>(StartMemoryProfiling)).ToLocalChecked());

Nan::Set(
profilingModule, Nan::New("collectHeapProfile").ToLocalChecked(),
Nan::GetFunction(Nan::New<v8::FunctionTemplate>(CollectHeapProfile)).ToLocalChecked());

Nan::Set(
profilingModule, Nan::New("stopMemoryProfiling").ToLocalChecked(),
Nan::GetFunction(Nan::New<v8::FunctionTemplate>(StopMemoryProfiling)).ToLocalChecked());

Nan::Set(target, Nan::New("profiling").ToLocalChecked(), profilingModule);
}

Expand Down
Loading