diff --git a/binding.gyp b/binding.gyp index 3dae8cc1..172ff3ef 100644 --- a/binding.gyp +++ b/binding.gyp @@ -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" diff --git a/docs/advanced-config.md b/docs/advanced-config.md index 65d46e29..2238634d 100644 --- a/docs/advanced-config.md +++ b/docs/advanced-config.md @@ -82,6 +82,7 @@ The following config options can be set by passing them as arguments to `startTr | Environment variable
``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`
`memoryProfilingEnabled` | `false` | Experimental | Enable continuous memory profiling. | `SPLUNK_PROFILER_LOGS_ENDPOINT`
`endpoint` | `http://localhost:4317` | Experimental | The OTLP logs receiver endpoint used for profiling data. | `OTEL_SERVICE_NAME`
`serviceName` | `unnamed-node-service` | Stable | Service name of the application. | `OTEL_RESOURCE_ATTRIBUTES` | | Stable | Comma-separated list of resource attributes.
Example`deployment.environment=demo,key2=val2`
diff --git a/docs/profiling.md b/docs/profiling.md index fb11289a..28f7d633 100644 --- a/docs/profiling.md +++ b/docs/profiling.md @@ -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 ``` @@ -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 + }, +}); +``` diff --git a/src/native_ext/memory_profiling.cpp b/src/native_ext/memory_profiling.cpp new file mode 100644 index 00000000..bef1aefe --- /dev/null +++ b/src/native_ext/memory_profiling.cpp @@ -0,0 +1,219 @@ +#include "memory_profiling.h" +#include "khash.h" +#include "util/platform.h" +#include +#include + +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 stack; + bool isRunning = false; +}; + +MemoryProfiling* profiling = nullptr; + +struct StringStash { + v8::Local strings[V8String_MAX]; +}; + +v8::Local +ToJsHeapNode(v8::AllocationProfile::Node* node, uint32_t parentId, StringStash* stash) { + auto jsNode = Nan::New(); + 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(node->line_number)); + Nan::Set(jsNode, stash->strings[V8String_ParentId], Nan::New(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(info[0]).ToLocalChecked(); + auto maybeSampleIntervalBytes = + Nan::Get(options, Nan::New("sampleIntervalBytes").ToLocalChecked()); + if ( + !maybeSampleIntervalBytes.IsEmpty() && + maybeSampleIntervalBytes.ToLocalChecked()->IsNumber()) { + sampleIntervalBytes = Nan::To(maybeSampleIntervalBytes.ToLocalChecked()).FromJust(); + } + + auto maybeMaxStackDepth = Nan::Get(options, Nan::New("maxStackDepth").ToLocalChecked()); + if (!maybeMaxStackDepth.IsEmpty() && maybeMaxStackDepth.ToLocalChecked()->IsNumber()) { + maxStackDepth = Nan::To(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(); + auto jsSamples = Nan::New(); + auto jsNodeTree = Nan::New(); + int32_t jsSamplesLength = 0; + + v8::AllocationProfile::Node* root = profile->GetRootNode(); + + const std::vector& 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(); + Nan::Set( + jsSample, Nan::New("nodeId").ToLocalChecked(), + Nan::New(sample.node_id)); + Nan::Set( + jsSample, Nan::New("size").ToLocalChecked(), + Nan::New(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; + stash.strings[V8String_Name] = Nan::New("name").ToLocalChecked(); + stash.strings[V8String_ScriptName] = Nan::New("scriptName").ToLocalChecked(); + stash.strings[V8String_LineNumber] = Nan::New("lineNumber").ToLocalChecked(); + stash.strings[V8String_ParentId] = Nan::New("parentId").ToLocalChecked(); + + std::vector& 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()) { + 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(node->node_id), jsNode); + + for (v8::AllocationProfile::Node* child : node->children) { + stack.emplace_back(child, node->node_id); + } + } + + Nan::Set(jsResult, Nan::New("treeMap").ToLocalChecked(), jsNodeTree); + Nan::Set(jsResult, Nan::New("samples").ToLocalChecked(), jsSamples); + Nan::Set( + jsResult, Nan::New("timestamp").ToLocalChecked(), + Nan::New(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 diff --git a/src/native_ext/memory_profiling.h b/src/native_ext/memory_profiling.h new file mode 100644 index 00000000..33573167 --- /dev/null +++ b/src/native_ext/memory_profiling.h @@ -0,0 +1,13 @@ +#pragma once + +#include + +namespace Splunk { +namespace Profiling { + +NAN_METHOD(StartMemoryProfiling); +NAN_METHOD(CollectHeapProfile); +NAN_METHOD(StopMemoryProfiling); + +} // namespace Profiling +} // namespace Splunk diff --git a/src/native_ext/profiling.cpp b/src/native_ext/profiling.cpp index 38ad6798..8afba075 100644 --- a/src/native_ext/profiling.cpp +++ b/src/native_ext/profiling.cpp @@ -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 #include #include #include @@ -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 + // 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; @@ -310,12 +312,6 @@ void InsertActivation(Profiling* profiling, SpanActivation* activation) { Profiling* profiling = nullptr; -int64_t MicroSecondsSinceEpoch() { - return std::chrono::duration_cast( - std::chrono::system_clock::now().time_since_epoch()) - .count(); -} - void V8StartProfiling(v8::CpuProfiler* profiler, const char* title) { v8::Local v8Title = Nan::New(title).ToLocalChecked(); const bool recordSamples = true; @@ -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(maybeMaxSampleCutoffDelay.ToLocalChecked()).FromJust(); + if ( + !maybeMaxSampleCutoffDelay.IsEmpty() && + maybeMaxSampleCutoffDelay.ToLocalChecked()->IsNumber()) { + int64_t maxSampleCutoffDelayMicros = + Nan::To(maybeMaxSampleCutoffDelay.ToLocalChecked()).FromJust(); profiling->maxSampleCutoffDelayNanos = maxSampleCutoffDelayMicros * 1000LL; } } @@ -828,9 +827,7 @@ void ProfilingBuildRawStacktraces( Nan::Set( jsTrace, Nan::New("timestamp").ToLocalChecked(), Nan::New(tsBuf, tsLen).ToLocalChecked()); - Nan::Set( - jsTrace, Nan::New("stacktrace").ToLocalChecked(), - stackTraceLines); + Nan::Set(jsTrace, Nan::New("stacktrace").ToLocalChecked(), stackTraceLines); #if PROFILER_DEBUG_EXPORT char tpBuf[32]; @@ -1111,6 +1108,18 @@ void Initialize(v8::Local target) { profilingModule, Nan::New("exitContext").ToLocalChecked(), Nan::GetFunction(Nan::New(ExitContext)).ToLocalChecked()); + Nan::Set( + profilingModule, Nan::New("startMemoryProfiling").ToLocalChecked(), + Nan::GetFunction(Nan::New(StartMemoryProfiling)).ToLocalChecked()); + + Nan::Set( + profilingModule, Nan::New("collectHeapProfile").ToLocalChecked(), + Nan::GetFunction(Nan::New(CollectHeapProfile)).ToLocalChecked()); + + Nan::Set( + profilingModule, Nan::New("stopMemoryProfiling").ToLocalChecked(), + Nan::GetFunction(Nan::New(StopMemoryProfiling)).ToLocalChecked()); + Nan::Set(target, Nan::New("profiling").ToLocalChecked(), profilingModule); } diff --git a/src/native_ext/util/platform.cpp b/src/native_ext/util/platform.cpp index 60b5d88e..c5c90874 100644 --- a/src/native_ext/util/platform.cpp +++ b/src/native_ext/util/platform.cpp @@ -1,4 +1,5 @@ #include "platform.h" +#include #include #ifdef __APPLE__ @@ -7,6 +8,14 @@ namespace Splunk { +namespace { +template +int64_t SinceEpoch() { + return std::chrono::duration_cast(std::chrono::system_clock::now().time_since_epoch()) + .count(); +} +} // namespace + #ifdef __APPLE__ int64_t HrTime() { static mach_timebase_info_data_t timebase; @@ -19,4 +28,9 @@ int64_t HrTime() { #else int64_t HrTime() { return uv_hrtime(); } #endif + +int64_t MicroSecondsSinceEpoch() { return SinceEpoch(); } + +int64_t MilliSecondsSinceEpoch() { return SinceEpoch(); } + } // namespace Splunk diff --git a/src/native_ext/util/platform.h b/src/native_ext/util/platform.h index c64de53c..a540524f 100644 --- a/src/native_ext/util/platform.h +++ b/src/native_ext/util/platform.h @@ -4,4 +4,6 @@ namespace Splunk { int64_t HrTime(); +int64_t MicroSecondsSinceEpoch(); +int64_t MilliSecondsSinceEpoch(); } diff --git a/src/profiling/DebugExporter.ts b/src/profiling/DebugExporter.ts index 699c7b81..9d4f86bd 100644 --- a/src/profiling/DebugExporter.ts +++ b/src/profiling/DebugExporter.ts @@ -15,11 +15,17 @@ */ import * as fs from 'fs'; import { diag } from '@opentelemetry/api'; -import { RawProfilingData, ProfilingData, ProfilingExporter } from './types'; +import { + HeapProfile, + ProfilingData, + ProfilingExporter, + RawProfilingData, +} from './types'; export class DebugExporter implements ProfilingExporter { runTimestamp = Date.now(); profileIndex = 0; + heapProfileIndex = 0; send(data: ProfilingData | RawProfilingData) { const baseName = `profile-${this.runTimestamp}-${this.profileIndex++}.json`; @@ -29,4 +35,14 @@ export class DebugExporter implements ProfilingExporter { } }); } + + sendHeapProfile(profile: HeapProfile) { + const name = `heap-profile-${this.runTimestamp}-${this + .heapProfileIndex++}.json`; + fs.writeFile(name, JSON.stringify(profile), err => { + if (err) { + diag.error(`error writing to ${name}`, err); + } + }); + } } diff --git a/src/profiling/OTLPProfilingExporter.ts b/src/profiling/OTLPProfilingExporter.ts index c6bde273..9f693e63 100644 --- a/src/profiling/OTLPProfilingExporter.ts +++ b/src/profiling/OTLPProfilingExporter.ts @@ -16,11 +16,16 @@ import * as protoLoader from '@grpc/proto-loader'; import * as grpc from '@grpc/grpc-js'; import * as path from 'path'; -import { RawProfilingData, ProfilingExporter } from './types'; +import { HeapProfile, RawProfilingData, ProfilingExporter } from './types'; import { diag } from '@opentelemetry/api'; import { Resource } from '@opentelemetry/resources'; import { SemanticResourceAttributes } from '@opentelemetry/semantic-conventions'; -import { parseEndpoint, serialize, encode } from './utils'; +import { + parseEndpoint, + serialize, + serializeHeapProfile, + encode, +} from './utils'; export interface OTLPExporterOptions { callstackInterval: number; @@ -32,6 +37,25 @@ interface LogsClient extends grpc.Client { export: (request: unknown, metadata: grpc.Metadata, callback: Function) => {}; } +const OTEL_PROFILING_VERSION = '0.1.0'; + +function commonAttributes(profilingType: 'cpu' | 'allocation') { + return [ + { + key: 'profiling.data.format', + value: { stringValue: 'pprof-gzip-base64' }, + }, + { + key: 'profiling.data.type', + value: { stringValue: profilingType }, + }, + { + key: 'com.splunk.sourcetype', + value: { stringValue: 'otel.profiling' }, + }, + ]; +} + export class OTLPProfilingExporter implements ProfilingExporter { protected _client: LogsClient; protected _options: OTLPExporterOptions; @@ -103,20 +127,7 @@ export class OTLPProfilingExporter implements ProfilingExporter { const { stacktraces } = profile; diag.debug(`profiling: Exporting ${stacktraces?.length} samples`); const { callstackInterval } = this._options; - const attributes = [ - { - key: 'profiling.data.format', - value: { stringValue: 'pprof-gzip-base64' }, - }, - { - key: 'profiling.data.type', - value: { stringValue: 'cpu' }, - }, - { - key: 'com.splunk.sourcetype', - value: { stringValue: 'otel.profiling' }, - }, - ]; + const attributes = commonAttributes('cpu'); encode(serialize(profile, { samplingPeriodMillis: callstackInterval })) .then(serializedProfile => { const logs = [serializedProfile].map(st => { @@ -129,7 +140,48 @@ export class OTLPProfilingExporter implements ProfilingExporter { const ilLogs = { instrumentationLibrary: { name: 'otel.profiling', - version: '0.1.0', + version: OTEL_PROFILING_VERSION, + }, + logs, + }; + const resourceLogs = [ + { + resource: { + attributes: this._resourceAttributes, + }, + instrumentationLibraryLogs: [ilLogs], + }, + ]; + const payload = { + resourceLogs, + }; + this._client.export(payload, new grpc.Metadata(), (err: unknown) => { + if (err) { + diag.error('Error exporting profiling data', err); + } + }); + }) + .catch((err: unknown) => { + diag.error('Error exporting profiling data', err); + }); + } + + sendHeapProfile(profile: HeapProfile) { + const serialized = serializeHeapProfile(profile); + const attributes = commonAttributes('allocation'); + encode(serialized) + .then(serializedProfile => { + const logs = [serializedProfile].map(st => { + return { + name: 'otel.profiling', + body: { stringValue: st.toString('base64') }, + attributes, + }; + }); + const ilLogs = { + instrumentationLibrary: { + name: 'otel.profiling', + version: OTEL_PROFILING_VERSION, }, logs, }; diff --git a/src/profiling/index.ts b/src/profiling/index.ts index 4757d2c4..4b61aa82 100644 --- a/src/profiling/index.ts +++ b/src/profiling/index.ts @@ -19,11 +19,14 @@ import { Resource } from '@opentelemetry/resources'; import { assertNoExtraneousProperties, defaultServiceName, + getEnvBoolean, getEnvNumber, } from '../utils'; import { detect as detectResource } from '../resource'; import { SemanticResourceAttributes } from '@opentelemetry/semantic-conventions'; import { + HeapProfile, + MemoryProfilingOptions, ProfilingExporter, ProfilingExtension, ProfilingOptions, @@ -42,6 +45,10 @@ function extStopProfiling(extension: ProfilingExtension) { return extension.stop(); } +function extStopMemoryProfiling(extension: ProfilingExtension) { + return extension.stopMemoryProfiling(); +} + function extStartProfiling( extension: ProfilingExtension, opts: ProfilingStartOptions @@ -50,6 +57,19 @@ function extStartProfiling( extension.start(opts); } +function extStartMemoryProfiling( + extension: ProfilingExtension, + options?: MemoryProfilingOptions +) { + return extension.startMemoryProfiling(options); +} + +function extCollectHeapProfile( + extension: ProfilingExtension +): HeapProfile | null { + return extension.collectHeapProfile(); +} + function extCollectSamples(extension: ProfilingExtension) { diag.debug('profiling: Collecting samples'); return extension.collectRaw(); @@ -101,7 +121,7 @@ export function startProfiling(opts: Partial = {}) { extStartProfiling(extension, startOptions); - const interval = setInterval(() => { + const cpuSamplesCollectInterval = setInterval(() => { const profilingData = extCollectSamples(extension); if (profilingData) { @@ -111,16 +131,36 @@ export function startProfiling(opts: Partial = {}) { } }, options.collectionDuration); - interval.unref(); + cpuSamplesCollectInterval.unref(); + + let memSamplesCollectInterval: NodeJS.Timer | undefined; + if (options.memoryProfilingEnabled) { + extStartMemoryProfiling(extension, options.memoryProfilingOptions); + memSamplesCollectInterval = setInterval(() => { + const heapProfile = extCollectHeapProfile(extension); + if (heapProfile) { + for (const exporter of exporters) { + exporter.sendHeapProfile(heapProfile); + } + } + }, options.collectionDuration); + + memSamplesCollectInterval.unref(); + } return { stop: () => { - clearInterval(interval); - const profilingData = extStopProfiling(extension); + if (options.memoryProfilingEnabled) { + clearInterval(memSamplesCollectInterval); + extStopMemoryProfiling(extension); + } - if (profilingData) { + clearInterval(cpuSamplesCollectInterval); + const cpuProfile = extStopProfiling(extension); + + if (cpuProfile) { for (const exporter of exporters) { - exporter.send(profilingData); + exporter.send(cpuProfile); } } }, @@ -171,6 +211,10 @@ export function _setDefaultOptions( }) ); + const memoryProfilingEnabled = + options.memoryProfilingEnabled ?? + getEnvBoolean('SPLUNK_PROFILER_MEMORY_ENABLED', false); + return { serviceName: serviceName, endpoint, @@ -181,5 +225,7 @@ export function _setDefaultOptions( resource, debugExport: options.debugExport ?? false, exporterFactory: options.exporterFactory ?? defaultExporterFactory, + memoryProfilingEnabled, + memoryProfilingOptions: options.memoryProfilingOptions, }; } diff --git a/src/profiling/types.ts b/src/profiling/types.ts index 35fb95ef..6cd938ed 100644 --- a/src/profiling/types.ts +++ b/src/profiling/types.ts @@ -49,6 +49,24 @@ export interface RawProfilingStackFrame extends Array { export type RawProfilingData = GenericProfilingData; export type ProfilingData = GenericProfilingData; +export interface HeapProfileNode { + name: string; + scriptName: string; + lineNumber: number; + parentId: number; +} + +export interface AllocationSample { + nodeId: number; + size: number; +} + +export interface HeapProfile { + samples: AllocationSample[]; + treeMap: { [nodeId: string]: HeapProfileNode }; + timestamp: number; +} + export interface ProfilingExtension { start(options?: ProfilingStartOptions): void; stop(): RawProfilingData; @@ -56,12 +74,20 @@ export interface ProfilingExtension { collectRaw(): RawProfilingData; enterContext(context: unknown, traceId: string, spanId: string): void; exitContext(context: unknown): void; + startMemoryProfiling(options?: MemoryProfilingOptions): void; + stopMemoryProfiling(): void; + collectHeapProfile(): HeapProfile | null; } export type ProfilingExporterFactory = ( options: ProfilingOptions ) => ProfilingExporter[]; +export interface MemoryProfilingOptions { + maxStackDepth?: number; + sampleIntervalBytes?: number; +} + export interface ProfilingOptions { endpoint: string; serviceName: string; @@ -71,10 +97,13 @@ export interface ProfilingOptions { debugExport: boolean; resource: Resource; exporterFactory: ProfilingExporterFactory; + memoryProfilingEnabled: boolean; + memoryProfilingOptions?: MemoryProfilingOptions; } export interface ProfilingExporter { send(profile: RawProfilingData): void; + sendHeapProfile(profile: HeapProfile): void; } export const allowedProfilingOptions = [ @@ -85,4 +114,6 @@ export const allowedProfilingOptions = [ 'resource', 'serviceName', 'exporterFactory', + 'memoryProfilingEnabled', + 'memoryProfilingOptions', ]; diff --git a/src/profiling/utils.ts b/src/profiling/utils.ts index 0e950eb5..229b1017 100644 --- a/src/profiling/utils.ts +++ b/src/profiling/utils.ts @@ -20,7 +20,7 @@ import * as grpc from '@grpc/grpc-js'; import { diag } from '@opentelemetry/api'; import { perftools } from './proto/profile'; -import type { RawProfilingData } from './types'; +import type { HeapProfile, RawProfilingData } from './types'; const gzipPromise = promisify(gzip); @@ -50,119 +50,172 @@ export interface PProfSerializationOptions { samplingPeriodMillis: number; } -export const serialize = ( - profile: RawProfilingData, - options: PProfSerializationOptions -) => { - const { stacktraces } = profile; - - const stringTable = new StringTable(); - const locationsMap = new Map(); - const functionsMap = new Map(); - - // Precreating those because they are really likely to be used - const STR = { - TIMESTAMP: stringTable.getIndex('source.event.time'), - TRACE_ID: stringTable.getIndex('trace_id'), - SPAN_ID: stringTable.getIndex('span_id'), - SOURCE_EVENT_PERIOD: stringTable.getIndex('source.event.period'), - }; +class Serializer { + stringTable = new StringTable(); + locationsMap = new Map(); + functionsMap = new Map(); - const getLocation = ( + getLocation( fileName: string, functionName: string, lineNumber: number - ): perftools.profiles.Location => { - const key = [fileName, functionName, lineNumber].join(':'); - let location = locationsMap.get(key); + ): perftools.profiles.Location { + const key = `${fileName}:${functionName}:${lineNumber}`; + let location = this.locationsMap.get(key); if (!location) { location = new perftools.profiles.Location({ - id: locationsMap.size + 1, - line: [getLine(fileName, functionName, lineNumber)], + id: this.locationsMap.size + 1, + line: [this.getLine(fileName, functionName, lineNumber)], }); - locationsMap.set(key, location); + this.locationsMap.set(key, location); } return location; - }; + } - const getFunction = ( + getFunction( fileName: string, functionName: string - ): perftools.profiles.Function => { - const key = [fileName, functionName].join(':'); - let fun = functionsMap.get(key); + ): perftools.profiles.Function { + const key = `${fileName}:${functionName}`; + let fun = this.functionsMap.get(key); if (!fun) { - const functionNameId = stringTable.getIndex(functionName); + const functionNameId = this.stringTable.getIndex(functionName); fun = new perftools.profiles.Function({ - id: functionsMap.size + 1, + id: this.functionsMap.size + 1, name: functionNameId, systemName: functionNameId, - filename: stringTable.getIndex(fileName || ''), + filename: this.stringTable.getIndex(fileName), }); - functionsMap.set(key, fun); + this.functionsMap.set(key, fun); } return fun; - }; + } - const getLine = ( + getLine( fileName: string, functionName: string, lineNumber: number - ): perftools.profiles.Line => { + ): perftools.profiles.Line { return new perftools.profiles.Line({ - functionId: getFunction(fileName, functionName).id, + functionId: this.getFunction(fileName, functionName).id, line: lineNumber !== 0 ? lineNumber : -1, }); - }; + } - const eventPeriodLabel = new perftools.profiles.Label({ - key: STR.SOURCE_EVENT_PERIOD, - num: options.samplingPeriodMillis, - }); - const samples = stacktraces.map( - ({ stacktrace, timestamp, spanId, traceId }) => { - const labels = [ - new perftools.profiles.Label({ - key: STR.TIMESTAMP, - num: Number(BigInt(timestamp) / BigInt(1_000_000)), - }), - eventPeriodLabel, - ]; - if (traceId) { - labels.push( - new perftools.profiles.Label({ - key: STR.TRACE_ID, - str: stringTable.getIndex(traceId.toString('hex')), - }) - ); - } - if (spanId) { - labels.push( - new perftools.profiles.Label({ - key: STR.SPAN_ID, - str: stringTable.getIndex(spanId.toString('hex')), - }) + serializeHeapProfile(profile: HeapProfile) { + const SOURCE_EVENT_TIME = this.stringTable.getIndex('source.event.time'); + + const label = [{ key: SOURCE_EVENT_TIME, num: profile.timestamp }]; + + const sample: perftools.profiles.ISample[] = []; + + const { samples, treeMap } = profile; + + for (const s of samples) { + let node = treeMap[s.nodeId]; + const path: number[] = []; + + while (node !== undefined) { + const location = this.getLocation( + node.scriptName, + node.name, + node.lineNumber ); + + path.push(location.id as number); + + node = treeMap[node.parentId]; } - return new perftools.profiles.Sample({ - locationId: stacktrace.map(([fileName, functionName, lineNumber]) => { - return getLocation(fileName, functionName, lineNumber).id; - }), - value: [], - label: labels, + sample.push({ + locationId: path, + value: [s.size], + label, }); } - ); - - return perftools.profiles.Profile.create({ - sample: samples, - location: [...locationsMap.values()], - function: [...functionsMap.values()], - stringTable: stringTable.serialize(), - }); + + return perftools.profiles.Profile.create({ + sample, + location: [...this.locationsMap.values()], + function: [...this.functionsMap.values()], + stringTable: this.stringTable.serialize(), + }); + } + + serializeCpuProfile( + profile: RawProfilingData, + options: PProfSerializationOptions + ) { + const { stacktraces } = profile; + + const STR = { + TIMESTAMP: this.stringTable.getIndex('source.event.time'), + TRACE_ID: this.stringTable.getIndex('trace_id'), + SPAN_ID: this.stringTable.getIndex('span_id'), + SOURCE_EVENT_PERIOD: this.stringTable.getIndex('source.event.period'), + }; + + const eventPeriodLabel = new perftools.profiles.Label({ + key: STR.SOURCE_EVENT_PERIOD, + num: options.samplingPeriodMillis, + }); + + const samples = stacktraces.map( + ({ stacktrace, timestamp, spanId, traceId }) => { + const labels = [ + new perftools.profiles.Label({ + key: STR.TIMESTAMP, + num: Number(BigInt(timestamp) / BigInt(1_000_000)), + }), + eventPeriodLabel, + ]; + if (traceId) { + labels.push( + new perftools.profiles.Label({ + key: STR.TRACE_ID, + str: this.stringTable.getIndex(traceId.toString('hex')), + }) + ); + } + if (spanId) { + labels.push( + new perftools.profiles.Label({ + key: STR.SPAN_ID, + str: this.stringTable.getIndex(spanId.toString('hex')), + }) + ); + } + + return new perftools.profiles.Sample({ + locationId: stacktrace.map(([fileName, functionName, lineNumber]) => { + return this.getLocation(fileName, functionName, lineNumber).id; + }), + value: [], + label: labels, + }); + } + ); + + return perftools.profiles.Profile.create({ + sample: samples, + location: [...this.locationsMap.values()], + function: [...this.functionsMap.values()], + stringTable: this.stringTable.serialize(), + }); + } +} + +export const serialize = ( + profile: RawProfilingData, + options: PProfSerializationOptions +) => { + return new Serializer().serializeCpuProfile(profile, options); }; +export function serializeHeapProfile(profile: HeapProfile) { + return new Serializer().serializeHeapProfile(profile); +} + export const encode = async function encode( profile: perftools.profiles.IProfile ): Promise { diff --git a/test/profiling/extension.test.ts b/test/profiling/extension.test.ts index cf4202fd..de83e9b0 100644 --- a/test/profiling/extension.test.ts +++ b/test/profiling/extension.test.ts @@ -15,8 +15,11 @@ */ import { strict as assert } from 'assert'; -import { hrtime } from 'process'; -import { ProfilingExtension } from '../../src/profiling/types'; +import { + AllocationSample, + HeapProfileNode, + ProfilingExtension, +} from '../../src/profiling/types'; import * as utils from '../utils'; const extension: ProfilingExtension = require('../../src/native_ext').profiling; @@ -121,4 +124,78 @@ describe('profiling native extension', () => { } } }); + + it('is possible to collect a heap profile', () => { + assert.equal(extension.collectHeapProfile(), null); + + extension.startMemoryProfiling(); + + function doAllocations() { + const dump = []; + + for (let i = 0; i < 4096; i++) { + dump.push(`abcd-${i}`.repeat(2048)); + } + + return dump; + } + + doAllocations(); + + const profile = extension.collectHeapProfile(); + + assert.notEqual(profile, null); + assert.equal(typeof profile.timestamp, 'number'); + assert( + Date.now() - profile.timestamp <= 60_000, + 'not a feasible heap profile timestamp' + ); + + const { treeMap, samples } = profile; + + assert(samples.length > 0, 'no allocation samples'); + + let maybeLeaf: HeapProfileNode | undefined; + let leafNodeId; + for (const nodeId in treeMap) { + const node = treeMap[nodeId]; + if (node.name === 'repeat') { + maybeLeaf = node; + leafNodeId = Number(nodeId); + break; + } + } + + assert.notEqual(maybeLeaf, undefined); + assert.notEqual(leafNodeId, undefined); + const leaf = maybeLeaf!; + assert.deepEqual(leaf.lineNumber, 0); + assert.deepEqual(leaf.scriptName, ''); + assert.deepEqual(typeof leaf.parentId, 'number'); + + const parentNode = treeMap[leaf.parentId]; + assert(parentNode.lineNumber > 0, 'parent line number can not be empty'); + assert( + parentNode.scriptName.endsWith('extension.test.ts'), + 'invalid parent node file name' + ); + assert.deepEqual(parentNode.name, 'doAllocations'); + assert.deepEqual(typeof parentNode.parentId, 'number'); + + // No point going up the tree any more + + let maybeSample: AllocationSample | undefined; + + for (const s of samples) { + if (s.nodeId === leafNodeId) { + maybeSample = s; + break; + } + } + + assert.notEqual(maybeSample, undefined); + const sample = maybeSample!; + assert.deepEqual(typeof sample.size, 'number'); + assert(sample.size > 0, 'sample with zero size'); + }); }); diff --git a/test/profiling/profiling.test.ts b/test/profiling/profiling.test.ts index 6f91076f..347d06a2 100644 --- a/test/profiling/profiling.test.ts +++ b/test/profiling/profiling.test.ts @@ -29,7 +29,11 @@ import { _setDefaultOptions, } from '../../src/profiling'; import { start, stop } from '../../src'; -import { ProfilingExporter, ProfilingData } from '../../src/profiling/types'; +import { + HeapProfile, + ProfilingExporter, + RawProfilingData, +} from '../../src/profiling/types'; import { ProfilingContextManager } from '../../src/profiling/ProfilingContextManager'; import { detect as detectResource } from '../../src/resource'; @@ -57,6 +61,8 @@ describe('profiling', () => { [SemanticResourceAttributes.SERVICE_NAME]: 'unnamed-node-service', }).merge(detectResource()), exporterFactory: defaultExporterFactory, + memoryProfilingEnabled: false, + memoryProfilingOptions: undefined, }); }); @@ -92,11 +98,12 @@ describe('profiling', () => { let sendCallCount = 0; const stacktracesReceived = []; const exporter: ProfilingExporter = { - send(profilingData: ProfilingData) { + send(profilingData: RawProfilingData) { const { stacktraces } = profilingData; sendCallCount += 1; stacktracesReceived.push(...stacktraces); }, + sendHeapProfile(_profile: HeapProfile) {}, }; // enabling tracing is required for span information to be caught @@ -150,5 +157,31 @@ describe('profiling', () => { // Stop flushes the exporters, hence the extra call count assert.deepStrictEqual(sendCallCount, 2); }).timeout(10_000); + + it('exports heap profiles', async () => { + let sendCallCount = 0; + const exporter: ProfilingExporter = { + send(_profilingData: RawProfilingData) {}, + sendHeapProfile(profile: HeapProfile) { + sendCallCount += 1; + }, + }; + + // enabling tracing is required for span information to be caught + start({ + profiling: { + serviceName: 'my-service', + collectionDuration: 100, + exporterFactory: () => [exporter], + memoryProfilingEnabled: true, + }, + }); + + // let runtime empty the task-queue and enable profiling + await sleep(200); + + stop(); + assert(sendCallCount > 0, 'no profiles were sent'); + }); }); }); diff --git a/test/profiling/serialization.test.ts b/test/profiling/serialization.test.ts index 032f0f30..45450e86 100644 --- a/test/profiling/serialization.test.ts +++ b/test/profiling/serialization.test.ts @@ -14,7 +14,11 @@ * limitations under the License. */ import { strict as assert } from 'assert'; -import { serialize, StringTable } from '../../src/profiling/utils'; +import { + serialize, + serializeHeapProfile, + StringTable, +} from '../../src/profiling/utils'; import { perftools } from '../../src/profiling/proto/profile.js'; const proto = perftools.profiles; @@ -118,5 +122,89 @@ describe('profiling:serialization', () => { clone(serializedProfile).toJSON() ); }); + + it('correctly serializes a heap profile', () => { + const heapProfile = { + samples: [ + { nodeId: 1, size: 128 }, + { nodeId: 1, size: 256 }, + { nodeId: 3, size: 512 }, + ], + treeMap: { + 1: { + name: 'work', + scriptName: '/app/foo.js', + lineNumber: 42, + parentId: 2, + }, + 2: { + name: 'schedule', + scriptName: '/app/foo.js', + lineNumber: 241, + parentId: 3, + }, + 3: { + name: 'runTimers', + scriptName: 'node:internal/timers', + lineNumber: -1, + parentId: 0, + }, + 4: { + name: 'other', + scriptName: '', + lineNumber: 10, + parentId: 0, + }, + }, + timestamp: Date.now(), + }; + + const ts = String(heapProfile.timestamp); + const serializedProfile = serializeHeapProfile(heapProfile); + + assert.deepEqual(serializedProfile.toJSON(), { + sample: [ + { + locationId: ['1', '2', '3'], + value: ['128'], + label: [{ key: '1', num: ts }], + }, + { + locationId: ['1', '2', '3'], + value: ['256'], + label: [{ key: '1', num: ts }], + }, + { + locationId: ['3'], + value: ['512'], + label: [{ key: '1', num: ts }], + }, + ], + location: [ + { id: '1', line: [{ functionId: '1', line: '42' }] }, + { id: '2', line: [{ functionId: '2', line: '241' }] }, + { id: '3', line: [{ functionId: '3', line: '-1' }] }, + ], + function: [ + { id: '1', name: '2', systemName: '2', filename: '3' }, + { id: '2', name: '4', systemName: '4', filename: '3' }, + { id: '3', name: '5', systemName: '5', filename: '6' }, + ], + stringTable: [ + '', + 'source.event.time', + 'work', + '/app/foo.js', + 'schedule', + 'runTimers', + 'node:internal/timers', + ], + }); + + assert.deepEqual( + serializedProfile.toJSON(), + clone(serializedProfile).toJSON() + ); + }); }); });