From 1c96cc87fe8657652ec2a767a3c0057d706b1519 Mon Sep 17 00:00:00 2001 From: Attila Szegedi Date: Fri, 2 Oct 2026 12:04:20 +0200 Subject: [PATCH 1/3] Extract a format-neutral profile normalizer from the pprof serializer Move everything in profile-serializer.ts that is about profile semantics rather than pprof encoding into a new profile-normalizer.ts. That covers the tree walk, source mapping, synthetic runtime frames, per-context sample expansion, CPU time attribution, label generation and sample values. The normalizer streams resolved frames, stacks and samples to a ProfileVisitor, and reports the visit result to its end() method. The pprof serializer is now one such visitor and its output is byte-identical. Samples refer to a deduplicated stack by ID, which mirrors the OTel profiles stack_table and libdatadog's stacktrace interning. Stacks are interned by prefix, through a small map of child stacks per stack, so equal stacks get equal IDs without comparing arrays. A stack is only delivered when its first sample is emitted, so visitors never receive stacks that no sample uses. Frames are looked up by their raw position first, with a short key. The source mapper, and the longer key that includes the resolved file, are needed only for a position not seen before, so a repeated position no longer goes through the source mapper again, which the serializer on main did for every node. On profiles from a TypeScript-compiler workload (about 43,000 time and 12,000 to 20,000 heap nodes), pprof serialization is within about 3-7% of main. Expose the new layer publicly: normalizeTimeProfile/normalizeHeapProfile, visitTimeProfile/visitHeapProfile, time.stopRaw(), time.stopNormalized() and heap.normalizedProfile(). This lets other encoders, such as an OTel profiles exporter, reuse the same profile semantics. --- ts/src/heap-profiler.ts | 112 +++-- ts/src/index.ts | 20 + ts/src/profile-normalizer.ts | 719 +++++++++++++++++++++++++++++ ts/src/profile-serializer.ts | 659 +++++--------------------- ts/src/time-profiler.ts | 26 ++ ts/test/test-heap-profiler.ts | 26 ++ ts/test/test-profile-normalizer.ts | 423 +++++++++++++++++ ts/test/test-time-profiler.ts | 21 + 8 files changed, 1433 insertions(+), 573 deletions(-) create mode 100644 ts/src/profile-normalizer.ts create mode 100644 ts/test/test-profile-normalizer.ts diff --git a/ts/src/heap-profiler.ts b/ts/src/heap-profiler.ts index dfc15e27..17ed4187 100644 --- a/ts/src/heap-profiler.ts +++ b/ts/src/heap-profiler.ts @@ -28,6 +28,7 @@ import { DEFAULT_COLUMN_NUMBERS, serializeHeapProfile, } from './profile-serializer'; +import {NormalizedProfile, normalizeHeapProfile} from './profile-normalizer'; import {SourceMapper} from './sourcemapper/sourcemapper'; import { AllocationProfileNode, @@ -103,6 +104,31 @@ export function profile( ); } +/** + * Collects a profile and returns it normalized into a format-neutral + * representation. Throws if heap profiler is not enabled. + */ +export function normalizedProfile( + ignoreSamplePath?: string, + sourceMapper?: SourceMapper, + generateLabels?: GenerateAllocationLabelsFunction, +): NormalizedProfile { + return collectProfile(root => { + const startTimeNanos = Date.now() * 1000 * 1000; + return normalizeHeapProfile( + addExternalMemoryNode(root, startedWithAllocations), + { + startTimeNanos, + intervalBytes: heapIntervalBytes, + ignoreSamplesPath: ignoreSamplePath, + sourceMapper, + generateLabels, + allocations: startedWithAllocations, + }, + ); + }); +} + function collectProfile( processProfile: ( root: AllocationProfileNode | AllocationProfileNodeWithStats, @@ -135,47 +161,8 @@ export function convertProfile( ): Profile { const allocations = startedWithAllocations; const startTimeNanos = Date.now() * 1000 * 1000; - // Add node for external memory usage. - // Current type definitions do not have external. - // TODO: remove any once type definition is updated to include external. - // eslint-disable-next-line @typescript-eslint/no-explicit-any - const {external}: {external: number} = process.memoryUsage() as any; - let root: AllocationProfileNode | AllocationProfileNodeWithStats; - if (external > 0) { - if (allocations) { - const externalNode: AllocationProfileNodeWithStats = { - name: '(external)', - scriptName: '', - children: [], - allocations: [ - { - inuseObjects: 1, - inuseSpaceBytes: external, - allocObjects: 1, - allocSpaceBytes: external, - }, - ], - }; - const allocationRoot = rootNode as AllocationProfileNodeWithStats; - root = { - ...allocationRoot, - children: [...allocationRoot.children, externalNode], - }; - } else { - const externalNode: AllocationProfileNode = { - name: '(external)', - scriptName: '', - children: [], - allocations: [{sizeBytes: external, count: 1}], - }; - const heapRoot = rootNode as AllocationProfileNode; - root = {...heapRoot, children: [...heapRoot.children, externalNode]}; - } - } else { - root = rootNode; - } return serializeHeapProfile( - root, + addExternalMemoryNode(rootNode, allocations), startTimeNanos, heapIntervalBytes, ignoreSamplePath, @@ -186,6 +173,51 @@ export function convertProfile( ); } +/** + * Returns the profile with a node for external memory usage added under the + * root, if there is any external memory. Does not modify the input. + */ +function addExternalMemoryNode( + rootNode: AllocationProfileNode | AllocationProfileNodeWithStats, + allocations: boolean, +): AllocationProfileNode | AllocationProfileNodeWithStats { + // Current type definitions do not have external. + // TODO: remove any once type definition is updated to include external. + // eslint-disable-next-line @typescript-eslint/no-explicit-any + const {external}: {external: number} = process.memoryUsage() as any; + if (external <= 0) { + return rootNode; + } + if (allocations) { + const externalNode: AllocationProfileNodeWithStats = { + name: '(external)', + scriptName: '', + children: [], + allocations: [ + { + inuseObjects: 1, + inuseSpaceBytes: external, + allocObjects: 1, + allocSpaceBytes: external, + }, + ], + }; + const allocationRoot = rootNode as AllocationProfileNodeWithStats; + return { + ...allocationRoot, + children: [...allocationRoot.children, externalNode], + }; + } + const externalNode: AllocationProfileNode = { + name: '(external)', + scriptName: '', + children: [], + allocations: [{sizeBytes: external, count: 1}], + }; + const heapRoot = rootNode as AllocationProfileNode; + return {...heapRoot, children: [...heapRoot.children, externalNode]}; +} + /** * Collects a profile and returns it serialized in pprof format using lazy V2 API. * Throws if heap profiler is not enabled. diff --git a/ts/src/index.ts b/ts/src/index.ts index 10d2052b..b5ccbf8f 100644 --- a/ts/src/index.ts +++ b/ts/src/index.ts @@ -24,7 +24,24 @@ export { TimeProfileNode, ProfileNode, LabelSet, + TimeProfile, } from './v8-types'; +export { + Frame, + frameFunctionName, + NormalizedProfile, + NormalizedSample, + normalizeHeapProfile, + normalizeTimeProfile, + ProfileMetadata, + ProfileVisitor, + SampleLabel, + SampleLabelValue, + SampleType, + visitHeapProfile, + visitTimeProfile, + VisitResult, +} from './profile-normalizer'; export {HeapLimitExtensionSize} from './heap-profiler'; @@ -37,6 +54,8 @@ export const time = { profile: timeProfiler.profile, start: timeProfiler.start, stop: timeProfiler.stop, + stopNormalized: timeProfiler.stopNormalized, + stopRaw: timeProfiler.stopRaw, profileV2: timeProfiler.profileV2, getContext: timeProfiler.getContext, setContext: timeProfiler.setContext, @@ -54,6 +73,7 @@ export const heap = { stop: heapProfiler.stop, profile: heapProfiler.profile, profileV2: heapProfiler.profileV2, + normalizedProfile: heapProfiler.normalizedProfile, convertProfile: heapProfiler.convertProfile, v8Profile: heapProfiler.v8Profile, monitorOutOfMemory: heapProfiler.monitorOutOfMemory, diff --git a/ts/src/profile-normalizer.ts b/ts/src/profile-normalizer.ts new file mode 100644 index 00000000..5003b725 --- /dev/null +++ b/ts/src/profile-normalizer.ts @@ -0,0 +1,719 @@ +/** + * Copyright 2026 Datadog. 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. + */ + +/** + * Format-neutral normalization of V8 profiles. + * + * Turns the raw V8 time and heap profile trees into a stream of resolved + * frames and samples, applying everything that is a matter of profile + * semantics rather than of any particular output format: source mapping, + * synthetic runtime frames, per-context sample expansion, CPU time + * attribution, label generation and sample values. Output formats (pprof in + * profile-serializer.ts, and potentially others) are implemented as + * {@link ProfileVisitor}s on top of it. + */ + +import { + GeneratedLocation, + SourceLocation, + SourceMapper, +} from './sourcemapper/sourcemapper'; +import { + Allocation, + AllocationWithStats, + AllocationProfileNode, + AllocationProfileNodeWithStats, + GenerateAllocationLabelsFunction, + GenerateTimeLabelsFunction, + ProfileNode, + TimeProfile, + TimeProfileNode, +} from './v8-types'; + +export const NON_JS_THREADS_FUNCTION_NAME = 'Non JS threads activity'; +export const GARBAGE_COLLECTION_FUNCTION_NAME = 'Garbage Collection'; + +/** + * A resolved stack frame: `file://` prefix stripped and source map applied. + */ +export interface Frame { + /** + * Function name after source mapping. Empty or absent for anonymous + * functions; use {@link frameFunctionName} to get a display name. + */ + name?: string; + file: string; + line?: number; + column?: number; + scriptId?: number; + /** + * True when the frame's script declares a sourceMappingURL but the map + * could not be found locally, i.e. the frame is a candidate for server-side + * unminification. + */ + missingMapFile: boolean; +} + +export type SampleLabelValue = string | number | bigint; + +/** A label as a key/value pair. */ +export type SampleLabel = [key: string, value: SampleLabelValue]; + +export interface NormalizedSample { + /** The stack, as the ID returned by {@link ProfileVisitor.stack}. */ + stackId: number; + /** One value for each of {@link ProfileMetadata.sampleTypes}. */ + values: number[]; + labels: SampleLabel[]; +} + +export interface SampleType { + type: string; + unit: string; +} + +export interface ProfileMetadata { + sampleTypes: SampleType[]; + periodType: SampleType; + period: number; + /** Time of collection in nanoseconds since epoch. */ + timeNanos: number; + durationNanos?: number; +} + +/** + * Receives a normalized profile. Calls arrive in this order: metadata() once, + * then frame(), stack() and sample() interleaved, then end() once. Each distinct frame and + * stack is delivered exactly once, before the first stack or sample that + * references it. Only stacks that have samples are delivered. + * + * All samples of a profile tree node are delivered consecutively. A stack ID + * normally belongs to a single node, but can recur later if two nodes resolve + * to the same frames (e.g. when source maps map distinct generated locations + * to the same original location). + */ +export interface ProfileVisitor { + metadata(metadata: ProfileMetadata): void; + /** + * @returns the ID by which stacks will refer to this frame. + */ + frame(frame: Frame): number; + /** + * @param frameIds - the stack, leaf first, as IDs returned by frame(). The + * array is not reused by the caller, so the visitor may retain it. + * @returns the ID by which samples will refer to this stack. + */ + stack(frameIds: number[]): number; + sample(sample: NormalizedSample): void; + /** Called after the last sample, with what the visit found. */ + end?(result: VisitResult): void; +} + +export interface VisitResult { + /** True if at least one frame has {@link Frame.missingMapFile} set. */ + hasMissingMapFiles: boolean; +} + +/** A normalized profile collected into arrays. */ +export interface NormalizedProfile extends ProfileMetadata, VisitResult { + frames: Frame[]; + /** Stacks, leaf first, as indices into {@link frames}. */ + stacks: number[][]; + /** Samples' stack IDs are indices into {@link stacks}. */ + samples: NormalizedSample[]; +} + +export interface TimeProfileNormalizerOptions { + /** Average time in microseconds between samples, as requested. */ + intervalMicros: number; + sourceMapper?: SourceMapper; + /** + * Recompute the sampling interval from the profile duration and total hit + * count, bounded to [intervalMicros, 2 * intervalMicros]. + */ + recomputeSamplingInterval?: boolean; + generateLabels?: GenerateTimeLabelsFunction; +} + +export interface HeapProfileNormalizerOptions { + /** Start time of profile, in nanoseconds since epoch. */ + startTimeNanos: number; + /** Bytes allocated between samples. */ + intervalBytes: number; + ignoreSamplesPath?: string; + sourceMapper?: SourceMapper; + generateLabels?: GenerateAllocationLabelsFunction; + /** Root was collected in allocation mode (nodes carry allocation stats). */ + allocations?: boolean; +} + +/** + * Emits a sample for the node currently being visited. + */ +type EmitSample = (values: number[], labels: SampleLabel[]) => void; + +/** + * Converts a node into zero or more samples and passes them to emit. + */ +type EmitSamples = (node: T, emit: EmitSample) => void; + +/** + * Profile node and the interned stack of its parent (-1 for top level nodes). + */ +interface Entry { + node: T; + parentStack: number; +} + +function isGeneratedLocation( + location: SourceLocation, +): location is GeneratedLocation { + return ( + location.column !== undefined && + location.line !== undefined && + location.line > 0 + ); +} + +/** + * @returns the frame's function name, or a synthesized + * `(anonymous:L#line:C#column)` name for anonymous functions. + */ +export function frameFunctionName(frame: Frame): string { + if (frame.name) { + return frame.name; + } + if (frame.line) { + if (frame.column) { + return `(anonymous:L#${frame.line}:C#${frame.column})`; + } + return `(anonymous:L#${frame.line})`; + } + return '(anonymous)'; +} + +function toSampleLabels(labelSet: object): SampleLabel[] { + const labels: SampleLabel[] = []; + // A for...in loop doesn't allocate the entries array of Object.entries() + for (const key in labelSet) { + if (!Object.prototype.hasOwnProperty.call(labelSet, key)) continue; + const value = (labelSet as Record)[key]; + switch (typeof value) { + case 'string': + case 'number': + case 'bigint': + labels.push([key, value]); + break; + } + } + return labels; +} + +function requireAllocationStat( + value: number | undefined, + field: string, +): number { + if (value === undefined) { + throw new Error(`Allocation profile is missing ${field}.`); + } + return value; +} + +/** + * Walks the V8 profile tree depth first, delivering each distinct frame and + * stack, and the samples emitted for each node to the visitor. + * + * Stacks are interned by prefix: a node's stack is identified by its parent's + * stack and its own frame ID, so stacks with equal frames get the same ID + * without comparing whole arrays. A stack is only materialized and delivered + * to the visitor when its first sample is emitted. + */ +function visitTree( + root: T, + visitor: ProfileVisitor, + emitSamples: EmitSamples, + ignoreSamplesPath?: string, + sourceMapper?: SourceMapper, +): VisitResult { + // Frames, by internal frame index: the visitor's frame ID. Indexed by the + // raw position (before source mapping), so a repeated position skips + // source mapping, and by resolved identity, so different positions that + // resolve to the same frame share it. + const frameIndexByPosition = new Map(); + const frameIndexByIdentity = new Map(); + const frameIds: number[] = []; + let hasMissingMapFiles = false; + + // Interned stacks, by internal stack index: the parent stack index (-1 for + // none), the internal frame index, the visitor's stack ID (undefined until + // delivered), and the child stacks by frame index. Top-level stacks are + // the children of rootStacks. + const stackParents: number[] = []; + const stackFrames: number[] = []; + const stackIds: Array = []; + const stackChildren: Array | undefined> = []; + const rootStacks = new Map(); + + let currentStack = -1; + const emit: EmitSample = (values, labels) => { + visitor.sample({stackId: getStackId(currentStack), values, labels}); + }; + + const entries: Array> = (root.children as T[]).map((n: T) => ({ + node: n, + parentStack: -1, + })); + while (entries.length > 0) { + const entry = entries.pop()!; + const node = entry.node; + + // mjs files have a `file://` prefix in the scriptName -> remove it + const scriptName = node.scriptName.startsWith('file://') + ? node.scriptName.slice(7) + : node.scriptName; + + if (ignoreSamplesPath && scriptName.indexOf(ignoreSamplesPath) > -1) { + continue; + } + const stack = internStack( + entry.parentStack, + getFrameIndex(node, scriptName), + ); + currentStack = stack; + emitSamples(node, emit); + for (const child of node.children as T[]) { + entries.push({node: child, parentStack: stack}); + } + } + + const result = {hasMissingMapFiles}; + visitor.end?.(result); + return result; + + function internStack(parent: number, frame: number): number { + let children: Map | undefined; + if (parent < 0) { + children = rootStacks; + } else { + children = stackChildren[parent]; + if (children === undefined) { + children = new Map(); + stackChildren[parent] = children; + } + } + let stack = children.get(frame); + if (stack === undefined) { + stack = stackParents.length; + stackParents.push(parent); + stackFrames.push(frame); + stackIds.push(undefined); + stackChildren.push(undefined); + children.set(frame, stack); + } + return stack; + } + + function getStackId(stack: number): number { + let id = stackIds[stack]; + if (id === undefined) { + const stackFrameIds: number[] = []; + for (let s = stack; s !== -1; s = stackParents[s]) { + stackFrameIds.push(frameIds[stackFrames[s]]); + } + id = visitor.stack(stackFrameIds); + stackIds[stack] = id; + } + return id; + } + + function getFrameIndex(node: ProfileNode, scriptName: string): number { + // The script ID identifies a script in V8 profiles; without one, the + // script name has to. The name comes last, so the key is unambiguous. + const positionKey = + node.scriptId !== undefined + ? `${node.scriptId}:${node.lineNumber}:${node.columnNumber}:${node.name}` + : `:${scriptName.length}:${scriptName}:${node.lineNumber}:${node.columnNumber}:${node.name}`; + let index = frameIndexByPosition.get(positionKey); + if (index === undefined) { + index = resolveFrameIndex(node, scriptName); + frameIndexByPosition.set(positionKey, index); + } + return index; + } + + function resolveFrameIndex(node: ProfileNode, scriptName: string): number { + let loc: SourceLocation = { + file: scriptName || '', + line: node.lineNumber, + column: node.columnNumber, + name: node.name, + }; + + let mapped = false; + if (loc.line) { + if (sourceMapper && isGeneratedLocation(loc)) { + loc = sourceMapper.mappingInfo(loc); + mapped = true; + if (loc.missingMapFile) { + hasMissingMapFiles = true; + } + } + } + const file = loc.file || ''; + // An unmapped frame is identified by its position, which was just looked + // up. Source mapping can resolve different positions to the same frame, + // so a mapped frame needs to be looked up by its resolved identity. The + // resolved file is part of that: after source mapping, one script can map + // to several original files. The file's length makes the key unambiguous. + const keyStr = mapped + ? `${node.scriptId}:${loc.line}:${loc.column}:${loc.missingMapFile ? 1 : 0}:${file.length}:${file}:${loc.name}` + : undefined; + let index = + keyStr === undefined ? undefined : frameIndexByIdentity.get(keyStr); + if (index === undefined) { + index = frameIds.length; + frameIds.push( + visitor.frame({ + name: loc.name, + file, + line: loc.line, + column: loc.column, + scriptId: node.scriptId, + missingMapFile: loc.missingMapFile === true, + }), + ); + if (keyStr !== undefined) frameIndexByIdentity.set(keyStr, index); + } + return index; + } +} + +export function computeTotalHitCount(root: TimeProfileNode): number { + return ( + root.hitCount + + (root.children as TimeProfileNode[]).reduce( + (sum, node) => sum + computeTotalHitCount(node), + 0, + ) + ); +} + +/** Perform some modifications on time profile: + * - Add non-JS thread activity node if available + * - remove `(program)` nodes + * - remove `(idle)` nodes with no context + * - set `(idle)` nodes' wall time to zero when they have a context + * - Convert `(garbage collector)` node to `Garbage Collection` + * - Put `non-JS thread activity` node and `Garbage Collection` under a top level `Node.js` node + * This function does not change the input profile. + */ +function updateTimeProfile(prof: TimeProfile): TimeProfile { + const newTopLevelChildren: TimeProfileNode[] = []; + + let runtimeNode: TimeProfileNode | undefined; + + function getRuntimeNode(): TimeProfileNode { + if (!runtimeNode) { + runtimeNode = { + name: 'Node.js', + scriptName: '', + scriptId: 0, + lineNumber: 0, + columnNumber: 0, + children: [], + hitCount: 0, + }; + newTopLevelChildren.push(runtimeNode); + } + return runtimeNode; + } + + for (const child of prof.topDownRoot.children as TimeProfileNode[]) { + if (child.name === '(program)') { + continue; + } + if (child.name === '(idle)' && child.contexts?.length === 0) { + continue; + } + if (child.name === '(garbage collector)') { + // Create a new node to avoid modifying the input one + const newChild: TimeProfileNode = { + ...child, + name: GARBAGE_COLLECTION_FUNCTION_NAME, + }; + getRuntimeNode().children.push(newChild); + } else { + newTopLevelChildren.push(child); + } + } + + if (prof.hasCpuTime && prof.nonJSThreadsCpuTime) { + const node: TimeProfileNode = { + name: NON_JS_THREADS_FUNCTION_NAME, + scriptName: '', + scriptId: 0, + lineNumber: 0, + columnNumber: 0, + children: [], + hitCount: 0, // 0 because this should not be accounted for wall time + contexts: [ + { + context: {}, + timestamp: BigInt(0), + cpuTime: prof.nonJSThreadsCpuTime, + asyncId: -1, + }, + ], + }; + getRuntimeNode().children.push(node); + } + return { + ...prof, + topDownRoot: {...prof.topDownRoot, children: newTopLevelChildren}, + }; +} + +/** + * Normalizes a V8 time profile and passes it to the visitor. + * + * Sample values are [sample count, wall nanoseconds] plus CPU nanoseconds if + * the profile has CPU time. + */ +export function visitTimeProfile( + prof: TimeProfile, + visitor: ProfileVisitor, + options: TimeProfileNormalizerOptions, +): VisitResult { + const {sourceMapper, recomputeSamplingInterval, generateLabels} = options; + let intervalMicros = options.intervalMicros; + // If requested, recompute sampling interval from profile duration and total number of hits, + // since profile duration should be #hits x interval. + // Recomputing an average interval is more accurate, since in practice intervals between + // samples are larger than the requested sampling interval (eg. 12.5ms vs 10ms requested). + // For very short durations, computation becomes meaningless (eg. if there is only one hit), + // therefore keep intervalMicros as a lower bound and 2 * intervalMicros as upper bound. + if (recomputeSamplingInterval) { + const totalHitCount = + prof.totalHitCount ?? computeTotalHitCount(prof.topDownRoot); + if (totalHitCount > 0) { + intervalMicros = Math.min( + Math.max( + Math.floor((prof.endTime - prof.startTime) / totalHitCount), + intervalMicros, + ), + 2 * intervalMicros, + ); + } + } + const intervalNanos = intervalMicros * 1000; + + const timeType = {type: 'wall', unit: 'nanoseconds'}; + const sampleTypes = [{type: 'sample', unit: 'count'}, timeType]; + if (prof.hasCpuTime) { + sampleTypes.push({type: 'cpu', unit: 'nanoseconds'}); + } + visitor.metadata({ + sampleTypes, + timeNanos: Date.now() * 1000 * 1000, + durationNanos: (prof.endTime - prof.startTime) * 1000, + periodType: timeType, + period: intervalNanos, + }); + + const emitTimeSamples: EmitSamples = ( + node: TimeProfileNode, + emit: EmitSample, + ) => { + let unlabelledHits = node.hitCount; + let unlabelledCpuTime = 0; + const isIdle = node.name === '(idle)'; + for (const context of node.contexts || []) { + const labels = toSampleLabels( + generateLabels + ? generateLabels({node, context}) + : (context.context ?? {}), + ); + if (labels.length > 0) { + // Only assign wall time if there are hits, some special nodes such as `(Non-JS threads)` + // have zero hit count (since they do not count as wall time) and should not be assigned any + // wall time. Also, `(idle)` nodes should be assigned zero wall time. + const values = + unlabelledHits > 0 ? [1, isIdle ? 0 : intervalNanos] : [0, 0]; + if (prof.hasCpuTime) { + values.push(context.cpuTime ?? 0); + } + emit(values, labels); + unlabelledHits--; + } else if (prof.hasCpuTime) { + unlabelledCpuTime += context.cpuTime ?? 0; + } + } + if ((!isIdle && unlabelledHits > 0) || unlabelledCpuTime > 0) { + const labels = generateLabels ? generateLabels({node}) : {}; + const values = + unlabelledHits > 0 + ? [unlabelledHits, isIdle ? 0 : unlabelledHits * intervalNanos] + : [0, 0]; + if (prof.hasCpuTime) { + values.push(unlabelledCpuTime); + } + emit(values, toSampleLabels(labels)); + } + }; + + return visitTree( + updateTimeProfile(prof).topDownRoot, + visitor, + emitTimeSamples, + undefined, + sourceMapper, + ); +} + +/** + * Normalizes a V8 heap profile and passes it to the visitor. + * + * Sample values are [inuse objects, inuse bytes], or [inuse objects, alloc + * objects, inuse bytes, alloc bytes] in allocation mode. + */ +export function visitHeapProfile( + prof: AllocationProfileNode | AllocationProfileNodeWithStats, + visitor: ProfileVisitor, + options: HeapProfileNormalizerOptions, +): VisitResult { + const {ignoreSamplesPath, sourceMapper, generateLabels, allocations} = + options; + + const sampleTypes = allocations + ? [ + {type: 'inuse_objects', unit: 'count'}, + {type: 'alloc_objects', unit: 'count'}, + {type: 'inuse_space', unit: 'bytes'}, + {type: 'alloc_space', unit: 'bytes'}, + ] + : [ + {type: 'inuse_objects', unit: 'count'}, + {type: 'inuse_space', unit: 'bytes'}, + ]; + visitor.metadata({ + sampleTypes, + timeNanos: options.startTimeNanos, + periodType: sampleTypes[sampleTypes.length - 1], + period: options.intervalBytes, + }); + + const emitHeapSamples: EmitSamples< + AllocationProfileNode | AllocationProfileNodeWithStats + > = ( + node: AllocationProfileNode | AllocationProfileNodeWithStats, + emit: EmitSample, + ) => { + if (node.allocations.length === 0) { + return; + } + const labels = generateLabels + ? toSampleLabels(generateLabels({node: node as AllocationProfileNode})) + : []; + for (const alloc of node.allocations) { + // Live heap only + if (!allocations) { + const heapAllocation = alloc as Allocation; + emit( + [ + heapAllocation.count, + heapAllocation.sizeBytes * heapAllocation.count, + ], + labels, + // TODO: add tag for allocation size + ); + continue; + } + + const stats = alloc as AllocationWithStats; + const inuseObjects = requireAllocationStat( + stats.inuseObjects, + 'inuseObjects', + ); + const inuseSpaceBytes = requireAllocationStat( + stats.inuseSpaceBytes, + 'inuseSpaceBytes', + ); + const allocObjects = requireAllocationStat( + stats.allocObjects, + 'allocObjects', + ); + const allocSpaceBytes = requireAllocationStat( + stats.allocSpaceBytes, + 'allocSpaceBytes', + ); + emit( + [inuseObjects, allocObjects, inuseSpaceBytes, allocSpaceBytes], + labels, + // TODO: add tag for allocation size + ); + } + }; + + return visitTree( + prof, + visitor, + emitHeapSamples, + ignoreSamplesPath, + sourceMapper, + ); +} + +function collect( + visit: (visitor: ProfileVisitor) => VisitResult, +): NormalizedProfile { + let metadata: ProfileMetadata | undefined; + const frames: Frame[] = []; + const stacks: number[][] = []; + const samples: NormalizedSample[] = []; + const {hasMissingMapFiles} = visit({ + metadata: m => { + metadata = m; + }, + frame: f => frames.push(f) - 1, + stack: s => stacks.push(s) - 1, + sample: s => { + samples.push(s); + }, + }); + return {...metadata!, frames, stacks, samples, hasMissingMapFiles}; +} + +/** + * Normalizes a V8 time profile into a {@link NormalizedProfile}. + * See {@link visitTimeProfile}. + */ +export function normalizeTimeProfile( + prof: TimeProfile, + options: TimeProfileNormalizerOptions, +): NormalizedProfile { + return collect(visitor => visitTimeProfile(prof, visitor, options)); +} + +/** + * Normalizes a V8 heap profile into a {@link NormalizedProfile}. + * See {@link visitHeapProfile}. + */ +export function normalizeHeapProfile( + prof: AllocationProfileNode | AllocationProfileNodeWithStats, + options: HeapProfileNormalizerOptions, +): NormalizedProfile { + return collect(visitor => visitHeapProfile(prof, visitor, options)); +} diff --git a/ts/src/profile-serializer.ts b/ts/src/profile-serializer.ts index 0e5d349c..72bc0296 100644 --- a/ts/src/profile-serializer.ts +++ b/ts/src/profile-serializer.ts @@ -21,62 +21,37 @@ import { Line, Location, Profile, + ProfileInput, Sample, ValueType, StringTable, - ProfileInput, } from 'pprof-format'; import { - GeneratedLocation, - SourceLocation, - SourceMapper, -} from './sourcemapper/sourcemapper'; + Frame, + frameFunctionName, + HeapProfileNormalizerOptions, + ProfileVisitor, + SampleLabel, + SampleType, + TimeProfileNormalizerOptions, + visitHeapProfile, + visitTimeProfile, + VisitResult, +} from './profile-normalizer'; +import {SourceMapper} from './sourcemapper/sourcemapper'; import { - Allocation, - AllocationWithStats, AllocationProfileNode, AllocationProfileNodeWithStats, GenerateAllocationLabelsFunction, GenerateTimeLabelsFunction, - ProfileNode, TimeProfile, - TimeProfileNode, } from './v8-types'; -export const NON_JS_THREADS_FUNCTION_NAME = 'Non JS threads activity'; -export const GARBAGE_COLLECTION_FUNCTION_NAME = 'Garbage Collection'; - -/** - * A stack of function IDs. - */ -type Stack = number[]; - -/** - * A function which converts entry into one or more samples, then - * appends those sample(s) to samples. - */ -type AppendEntryToSamples = ( - entry: Entry, - samples: Sample[], -) => void; - -/** - * Profile node and stack trace to that node. - */ -interface Entry { - node: T; - stack: Stack; -} - -function isGeneratedLocation( - location: SourceLocation, -): location is GeneratedLocation { - return ( - location.column !== undefined && - location.line !== undefined && - location.line > 0 - ); -} +export { + computeTotalHitCount, + GARBAGE_COLLECTION_FUNCTION_NAME, + NON_JS_THREADS_FUNCTION_NAME, +} from './profile-normalizer'; /** * Controls how a frame's column number is represented in the emitted profile. @@ -127,71 +102,64 @@ function packLineAndColumn( return (BigInt(column) << 32n) | BigInt(line); } -function requireAllocationStat( - value: number | undefined, - field: string, -): number { - if (value === undefined) { - throw new Error(`Allocation profile is missing ${field}.`); - } - return value; -} - /** - * Takes v8 profile and populates sample, location, and function fields of - * profile.proto. + * Encodes a normalized profile as a profile proto. * - * @param profile - profile.proto with empty sample, location, and function - * fields. - * @param root - root of v8 profile tree describing samples to be appended - * to profile. - * @param appendToSamples - function which converts entry to sample(s) and - * appends these to end of an array of samples. - * @param stringTable - string table for the existing profile. + * @param visit - function that delivers the normalized profile to a visitor. + * @param lowCardinalityLabels - keys of labels with few distinct values, whose + * Label objects are shared between samples to save memory. */ -function serialize( - profile: ProfileInput, - root: T, - appendToSamples: AppendEntryToSamples, - stringTable: StringTable, - ignoreSamplesPath?: string, - sourceMapper?: SourceMapper, +function serialize( + visit: (visitor: ProfileVisitor) => VisitResult, + lowCardinalityLabels: string[] = [], columnNumbers: ColumnNumbers = DEFAULT_COLUMN_NUMBERS, -) { +): Profile { + const stringTable = new StringTable(); const samples: Sample[] = []; const locations: Location[] = []; + const stacks: number[][] = []; const functions: Function[] = []; const functionIdMap = new Map(); - const locationIdMap = new Map(); const packColumns = columnNumbers === 'pack'; const emitColumns = columnNumbers === 'emit'; - - let hasMissingMapFiles = false; - - const entries: Array> = (root.children as T[]).map((n: T) => ({ - node: n, - stack: [], - })); - while (entries.length > 0) { - const entry = entries.pop()!; - const node = entry.node; - - // mjs files have a `file://` prefix in the scriptName -> remove it - const scriptName = node.scriptName.startsWith('file://') - ? node.scriptName.slice(7) - : node.scriptName; - - if (ignoreSamplesPath && scriptName.indexOf(ignoreSamplesPath) > -1) { - continue; - } - const stack = entry.stack; - const location = getLocation(node, scriptName, sourceMapper); - stack.unshift(location.id as number); - appendToSamples(entry, samples); - for (const child of node.children as T[]) { - entries.push({node: child, stack: stack.slice()}); - } + const labelCaches: Map[] = []; + for (const l of lowCardinalityLabels) { + labelCaches[stringTable.dedup(l)] = new Map(); } + let profile: ProfileInput = {}; + + const {hasMissingMapFiles} = visit({ + metadata: metadata => { + const valueType = (t: SampleType) => + new ValueType({ + type: stringTable.dedup(t.type), + unit: stringTable.dedup(t.unit), + }); + profile = { + sampleType: metadata.sampleTypes.map(valueType), + timeNanos: metadata.timeNanos, + durationNanos: metadata.durationNanos, + periodType: valueType(metadata.periodType), + period: metadata.period, + }; + }, + frame: frame => { + // id is index+1, since 0 is not valid id. + const id = locations.length + 1; + locations.push(new Location({id, line: [getLine(frame)]})); + return id; + }, + stack: frameIds => stacks.push(frameIds) - 1, + sample: sample => { + samples.push( + new Sample({ + locationId: stacks[sample.stackId], + value: sample.values, + label: dedupLabels(buildLabels(sample.labels)), + }), + ); + }, + }); profile.sample = samples; profile.location = locations; @@ -202,75 +170,38 @@ function serialize( profile.comment = [stringTable.dedup('dd:has-missing-map-files')]; } - function getLocation( - node: ProfileNode, - scriptName: string, - sourceMapper?: SourceMapper, - ): Location { - let profLoc: SourceLocation = { - file: scriptName || '', - line: node.lineNumber, - column: node.columnNumber, - name: node.name, - }; - - if (profLoc.line) { - if (sourceMapper && isGeneratedLocation(profLoc)) { - profLoc = sourceMapper.mappingInfo(profLoc); - if (profLoc.missingMapFile) { - hasMissingMapFiles = true; - } - } - } - // The resolved file is part of a location's identity: after source - // mapping, one script can map to several original files. The file's - // length makes the key unambiguous. - const file = profLoc.file || ''; - const keyStr = `${node.scriptId}:${profLoc.line}:${profLoc.column}:${profLoc.missingMapFile ? 1 : 0}:${file.length}:${file}:${profLoc.name}`; - let id = locationIdMap.get(keyStr); - if (id !== undefined) { - // id is index+1, since 0 is not valid id. - return locations[id - 1]; - } - id = locations.length + 1; - locationIdMap.set(keyStr, id); - const line = getLine(profLoc, node.scriptId); - const location = new Location({id, line: [line]}); - locations.push(location); - return location; - } + return new Profile(profile); - function getLine(loc: SourceLocation, scriptId?: number): Line { + function getLine(frame: Frame): Line { // Both 'pack' and 'emit' carry the column only for frames whose source map // was declared but missing locally — i.e. exactly the frames bound for // server-side unminification (the same condition that sets // dd:has-missing-map-files). Locally-resolved frames keep a plain line and // no column, so column data never reaches profiles that skip server-side // unminification. - const carryColumn = loc.missingMapFile === true; + const carryColumn = frame.missingMapFile; return new Line({ - functionId: getFunction(loc, scriptId).id, + functionId: getFunction(frame).id, // 'pack' encodes the column into the high 32 bits of the line field. line: packColumns && carryColumn - ? packLineAndColumn(loc.line, loc.column) - : loc.line, + ? packLineAndColumn(frame.line, frame.column) + : frame.line, // 'emit' records the column in the dedicated pprof Line.column field // instead; the backend does the line/column packing itself. - column: emitColumns && carryColumn ? loc.column : undefined, + column: emitColumns && carryColumn ? frame.column : undefined, }); } - function getFunction(loc: SourceLocation, scriptId?: number): Function { - let name = loc.name; + function getFunction(frame: Frame): Function { // A function is identified by script, file and name, or by script, file // and position for anonymous functions; the prefixes keep the two kinds // apart. The file matters because after source mapping, one script can // map to several original files. - const file = loc.file || ''; - const keyStr = name - ? `n:${scriptId}:${file.length}:${file}:${name}` - : `a:${scriptId}:${loc.line}:${loc.column}:${file}`; + const file = frame.file; + const keyStr = frame.name + ? `n:${frame.scriptId}:${file.length}:${file}:${frame.name}` + : `a:${frame.scriptId}:${frame.line}:${frame.column}:${file}`; let id = functionIdMap.get(keyStr); if (id !== undefined) { // id is index+1, since 0 is not valid id. @@ -278,217 +209,33 @@ function serialize( } id = functions.length + 1; functionIdMap.set(keyStr, id); - if (!name) { - if (loc.line) { - if (loc.column) { - name = `(anonymous:L#${loc.line}:C#${loc.column})`; - } else { - name = `(anonymous:L#${loc.line})`; - } - } else { - name = '(anonymous)'; - } - } - const nameId = stringTable.dedup(name); + const nameId = stringTable.dedup(frameFunctionName(frame)); const f = new Function({ id, name: nameId, systemName: nameId, - filename: stringTable.dedup(loc.file || ''), + filename: stringTable.dedup(frame.file), }); functions.push(f); return f; } -} -/** - * @return value type for sample counts (type:sample, units:count), and - * adds strings used in this value type to the table. - */ -function createSampleCountValueType(table: StringTable): ValueType { - return new ValueType({ - type: table.dedup('sample'), - unit: table.dedup('count'), - }); -} - -/** - * @return value type for time samples (type:wall, units:nanoseconds), and - * adds strings used in this value type to the table. - */ -function createTimeValueType(table: StringTable): ValueType { - return new ValueType({ - type: table.dedup('wall'), - unit: table.dedup('nanoseconds'), - }); -} - -/** - * @return value type for cpu samples (type:cpu, units:nanoseconds), and - * adds strings used in this value type to the table. - */ -function createCpuValueType(table: StringTable): ValueType { - return new ValueType({ - type: table.dedup('cpu'), - unit: table.dedup('nanoseconds'), - }); -} - -function createInUseObjectCountValueType(table: StringTable): ValueType { - return new ValueType({ - type: table.dedup('inuse_objects'), - unit: table.dedup('count'), - }); -} - -function createAllocatedObjectCountValueType(table: StringTable): ValueType { - return new ValueType({ - type: table.dedup('alloc_objects'), - unit: table.dedup('count'), - }); -} - -function createInUseSpaceValueType(table: StringTable): ValueType { - return new ValueType({ - type: table.dedup('inuse_space'), - unit: table.dedup('bytes'), - }); -} - -function createAllocatedSpaceValueType(table: StringTable): ValueType { - return new ValueType({ - type: table.dedup('alloc_space'), - unit: table.dedup('bytes'), - }); -} - -export function computeTotalHitCount(root: TimeProfileNode): number { - return ( - root.hitCount + - (root.children as TimeProfileNode[]).reduce( - (sum, node) => sum + computeTotalHitCount(node), - 0, - ) - ); -} - -/** Perform some modifications on time profile: - * - Add non-JS thread activity node if available - * - remove `(program)` nodes - * - remove `(idle)` nodes with no context - * - set `(idle)` nodes' wall time to zero when they have a context - * - Convert `(garbage collector)` node to `Garbage Collection` - * - Put `non-JS thread activity` node and `Garbage Collection` under a top level `Node.js` node - * This function does not change the input profile. - */ -function updateTimeProfile(prof: TimeProfile): TimeProfile { - const newTopLevelChildren: TimeProfileNode[] = []; - - let runtimeNode: TimeProfileNode | undefined; - - function getRuntimeNode(): TimeProfileNode { - if (!runtimeNode) { - runtimeNode = { - name: 'Node.js', - scriptName: '', - scriptId: 0, - lineNumber: 0, - columnNumber: 0, - children: [], - hitCount: 0, - }; - newTopLevelChildren.push(runtimeNode); - } - return runtimeNode; - } - - for (const child of prof.topDownRoot.children as TimeProfileNode[]) { - if (child.name === '(program)') { - continue; - } - if (child.name === '(idle)' && child.contexts?.length === 0) { - continue; - } - if (child.name === '(garbage collector)') { - // Create a new node to avoid modifying the input one - const newChild: TimeProfileNode = { - ...child, - name: GARBAGE_COLLECTION_FUNCTION_NAME, - }; - getRuntimeNode().children.push(newChild); - } else { - newTopLevelChildren.push(child); + function buildLabels(sampleLabels: SampleLabel[]): Label[] { + const labels: Label[] = new Array(sampleLabels.length); + for (let i = 0; i < sampleLabels.length; i++) { + const [key, value] = sampleLabels[i]; + const labelInput: LabelInput = {key: stringTable.dedup(key)}; + if (typeof value === 'string') { + labelInput.str = stringTable.dedup(value); + } else { + labelInput.num = value; + } + labels[i] = new Label(labelInput); } + return labels; } - if (prof.hasCpuTime && prof.nonJSThreadsCpuTime) { - const node: TimeProfileNode = { - name: NON_JS_THREADS_FUNCTION_NAME, - scriptName: '', - scriptId: 0, - lineNumber: 0, - columnNumber: 0, - children: [], - hitCount: 0, // 0 because this should not be accounted for wall time - contexts: [ - { - context: {}, - timestamp: BigInt(0), - cpuTime: prof.nonJSThreadsCpuTime, - asyncId: -1, - }, - ], - }; - getRuntimeNode().children.push(node); - } - return { - ...prof, - topDownRoot: {...prof.topDownRoot, children: newTopLevelChildren}, - }; -} - -/** - * Converts v8 time profile into into a profile proto. - * (https://github.com/google/pprof/blob/master/proto/profile.proto) - * - * @param prof - profile to be converted. - * @param intervalMicros - average time (microseconds) between samples. - */ -export function serializeTimeProfile( - prof: TimeProfile, - intervalMicros: number, - sourceMapper?: SourceMapper, - recomputeSamplingInterval = false, - generateLabels?: GenerateTimeLabelsFunction, - lowCardinalityLabels: string[] = [], - columnNumbers: ColumnNumbers = DEFAULT_COLUMN_NUMBERS, -): Profile { - // If requested, recompute sampling interval from profile duration and total number of hits, - // since profile duration should be #hits x interval. - // Recomputing an average interval is more accurate, since in practice intervals between - // samples are larger than the requested sampling interval (eg. 12.5ms vs 10ms requested). - // For very short durations, computation becomes meaningless (eg. if there is only one hit), - // therefore keep intervalMicros as a lower bound and 2 * intervalMicros as upper bound. - if (recomputeSamplingInterval) { - const totalHitCount = - prof.totalHitCount ?? computeTotalHitCount(prof.topDownRoot); - if (totalHitCount > 0) { - intervalMicros = Math.min( - Math.max( - Math.floor((prof.endTime - prof.startTime) / totalHitCount), - intervalMicros, - ), - 2 * intervalMicros, - ); - } - } - const intervalNanos = intervalMicros * 1000; - const stringTable = new StringTable(); - const labelCaches: Map[] = []; - for (const l of lowCardinalityLabels) { - labelCaches[stringTable.dedup(l)] = new Map(); - } - const dedupLabels = (labels: Label[]) => { + function dedupLabels(labels: Label[]) { for (let i = 0; i < labels.length; i++) { const label = labels[i]; const cache = labelCaches[Number(label.key)]; @@ -507,112 +254,36 @@ export function serializeTimeProfile( } } return labels; - }; - - const appendTimeEntryToSamples: AppendEntryToSamples = ( - entry: Entry, - samples: Sample[], - ) => { - let unlabelledHits = entry.node.hitCount; - let unlabelledCpuTime = 0; - const isIdle = entry.node.name === '(idle)'; - for (const context of entry.node.contexts || []) { - const labels = generateLabels - ? generateLabels({node: entry.node, context}) - : (context.context ?? {}); - const labelsArr = buildLabels(labels, stringTable); - if (labelsArr.length > 0) { - // Only assign wall time if there are hits, some special nodes such as `(Non-JS threads)` - // have zero hit count (since they do not count as wall time) and should not be assigned any - // wall time. Also, `(idle)` nodes should be assigned zero wall time. - const values = - unlabelledHits > 0 ? [1, isIdle ? 0 : intervalNanos] : [0, 0]; - if (prof.hasCpuTime) { - values.push(context.cpuTime ?? 0); - } - const sample = new Sample({ - locationId: entry.stack, - value: values, - label: dedupLabels(labelsArr), - }); - samples.push(sample); - unlabelledHits--; - } else if (prof.hasCpuTime) { - unlabelledCpuTime += context.cpuTime ?? 0; - } - } - if ((!isIdle && unlabelledHits > 0) || unlabelledCpuTime > 0) { - const labels = generateLabels ? generateLabels({node: entry.node}) : {}; - const values = - unlabelledHits > 0 - ? [unlabelledHits, isIdle ? 0 : unlabelledHits * intervalNanos] - : [0, 0]; - if (prof.hasCpuTime) { - values.push(unlabelledCpuTime); - } - const sample = new Sample({ - locationId: entry.stack, - value: values, - label: buildLabels(labels, stringTable), - }); - samples.push(sample); - } - }; - - const sampleValueType = createSampleCountValueType(stringTable); - const timeValueType = createTimeValueType(stringTable); - - const sampleTypes = [sampleValueType, timeValueType]; - if (prof.hasCpuTime) { - const cpuValueType = createCpuValueType(stringTable); - sampleTypes.push(cpuValueType); } +} - const profile = { - sampleType: sampleTypes, - timeNanos: Date.now() * 1000 * 1000, - durationNanos: (prof.endTime - prof.startTime) * 1000, - periodType: timeValueType, - period: intervalNanos, - }; - - const updatedProf = updateTimeProfile(prof); - - serialize( - profile, - updatedProf.topDownRoot, - appendTimeEntryToSamples, - stringTable, - undefined, +/** + * Converts v8 time profile into into a profile proto. + * (https://github.com/google/pprof/blob/master/proto/profile.proto) + * + * @param prof - profile to be converted. + * @param intervalMicros - average time (microseconds) between samples. + */ +export function serializeTimeProfile( + prof: TimeProfile, + intervalMicros: number, + sourceMapper?: SourceMapper, + recomputeSamplingInterval = false, + generateLabels?: GenerateTimeLabelsFunction, + lowCardinalityLabels: string[] = [], + columnNumbers: ColumnNumbers = DEFAULT_COLUMN_NUMBERS, +): Profile { + const options: TimeProfileNormalizerOptions = { + intervalMicros, sourceMapper, + recomputeSamplingInterval, + generateLabels, + }; + return serialize( + visitor => visitTimeProfile(prof, visitor, options), + lowCardinalityLabels, columnNumbers, ); - - return new Profile(profile); -} - -function buildLabels(labelSet: object, stringTable: StringTable): Label[] { - const labels: Label[] = []; - - for (const [key, value] of Object.entries(labelSet)) { - const labelInput: LabelInput = { - key: stringTable.dedup(key), - }; - switch (typeof value) { - case 'string': - labelInput.str = stringTable.dedup(value); - break; - case 'number': - case 'bigint': - labelInput.num = value; - break; - default: - continue; - } - labels.push(new Label(labelInput)); - } - - return labels; } /** @@ -621,8 +292,6 @@ function buildLabels(labelSet: object, stringTable: StringTable): Label[] { * * @param prof - profile to be converted. * @param startTimeNanos - start time of profile, in nanoseconds (POSIX time). - * @param durationsNanos - duration of the profile (wall clock time) in - * nanoseconds. * @param intervalBytes - bytes allocated between samples. */ export function serializeHeapProfile( @@ -635,93 +304,17 @@ export function serializeHeapProfile( allocations = false, columnNumbers: ColumnNumbers = DEFAULT_COLUMN_NUMBERS, ): Profile { - const appendHeapEntryToSamples: AppendEntryToSamples< - AllocationProfileNode | AllocationProfileNodeWithStats - > = ( - entry: Entry, - samples: Sample[], - ) => { - if (entry.node.allocations.length > 0) { - const labels = generateLabels - ? buildLabels( - generateLabels({node: entry.node as AllocationProfileNode}), - stringTable, - ) - : []; - for (const alloc of entry.node.allocations) { - // Live heap only - if (!allocations) { - const heapAllocation = alloc as Allocation; - const sample = new Sample({ - locationId: entry.stack, - value: [ - heapAllocation.count, - heapAllocation.sizeBytes * heapAllocation.count, - ], - label: labels, - // TODO: add tag for allocation size - }); - samples.push(sample); - continue; - } - - const stats = alloc as AllocationWithStats; - const inuseObjects = requireAllocationStat( - stats.inuseObjects, - 'inuseObjects', - ); - const inuseSpaceBytes = requireAllocationStat( - stats.inuseSpaceBytes, - 'inuseSpaceBytes', - ); - const allocObjects = requireAllocationStat( - stats.allocObjects, - 'allocObjects', - ); - const allocSpaceBytes = requireAllocationStat( - stats.allocSpaceBytes, - 'allocSpaceBytes', - ); - const sample = new Sample({ - locationId: entry.stack, - value: [inuseObjects, allocObjects, inuseSpaceBytes, allocSpaceBytes], - label: labels, - // TODO: add tag for allocation size - }); - samples.push(sample); - } - } - }; - - const stringTable = new StringTable(); - const sampleTypes = allocations - ? [ - createInUseObjectCountValueType(stringTable), - createAllocatedObjectCountValueType(stringTable), - createInUseSpaceValueType(stringTable), - createAllocatedSpaceValueType(stringTable), - ] - : [ - createInUseObjectCountValueType(stringTable), - createInUseSpaceValueType(stringTable), - ]; - - const profile = { - sampleType: sampleTypes, - timeNanos: startTimeNanos, - periodType: sampleTypes[sampleTypes.length - 1], - period: intervalBytes, - }; - - serialize( - profile, - prof, - appendHeapEntryToSamples, - stringTable, + const options: HeapProfileNormalizerOptions = { + startTimeNanos, + intervalBytes, ignoreSamplesPath, sourceMapper, + generateLabels, + allocations, + }; + return serialize( + visitor => visitHeapProfile(prof, visitor, options), + [], columnNumbers, ); - - return new Profile(profile); } diff --git a/ts/src/time-profiler.ts b/ts/src/time-profiler.ts index 294b5835..f0be4876 100644 --- a/ts/src/time-profiler.ts +++ b/ts/src/time-profiler.ts @@ -24,6 +24,7 @@ import { GARBAGE_COLLECTION_FUNCTION_NAME, NON_JS_THREADS_FUNCTION_NAME, } from './profile-serializer'; +import {NormalizedProfile, normalizeTimeProfile} from './profile-normalizer'; import {SourceMapper} from './sourcemapper/sourcemapper'; import { TimeProfiler, @@ -191,6 +192,31 @@ export function stop( ); } +/** + * Same as stop(), but returns the profile normalized into a format-neutral + * representation instead of serialized as pprof. + */ +export function stopNormalized( + restart = false, + generateLabels?: GenerateTimeLabelsFunction, +): NormalizedProfile { + return stopAndProcess(restart, profile => + normalizeTimeProfile(profile, { + intervalMicros: gIntervalMicros, + sourceMapper: gSourceMapper, + recomputeSamplingInterval: true, + generateLabels, + }), + ); +} + +/** + * Same as stop(), but returns the raw V8 time profile without any processing. + */ +export function stopRaw(restart = false): TimeProfile { + return stopAndProcess(restart, profile => profile); +} + function stopAndProcess( restart: boolean, processProfile: (profile: TimeProfile) => T, diff --git a/ts/test/test-heap-profiler.ts b/ts/test/test-heap-profiler.ts index 3cbc3d19..728a99c9 100644 --- a/ts/test/test-heap-profiler.ts +++ b/ts/test/test-heap-profiler.ts @@ -123,6 +123,32 @@ describe('HeapProfiler', () => { assert.deepEqual(heapProfileWithExternal, profile); }); + it('should return a normalized profile matching the serialized one', async () => { + profileStub = sinon + .stub(v8HeapProfiler, 'getAllocationProfile') + .returns(copy(v8HeapProfile)); + memoryUsageStub = sinon.stub(process, 'memoryUsage').returns({ + external: 1024, + rss: 2048, + heapTotal: 4096, + heapUsed: 2048, + arrayBuffers: 512, + }); + const intervalBytes = 1024 * 512; + heapProfiler.start(intervalBytes, 32); + const normalized = heapProfiler.normalizedProfile(); + assert.strictEqual(normalized.period, intervalBytes); + assert.strictEqual( + normalized.samples.length, + heapProfileWithExternal.sample.length, + ); + assert.deepStrictEqual( + normalized.samples.map(s => s.values), + heapProfileWithExternal.sample.map(s => s.value), + ); + assert.ok(normalized.frames.some(f => f.name === '(external)')); + }); + it('should return a profile equal to the expected profile when including all samples', async () => { profileStub = sinon .stub(v8HeapProfiler, 'getAllocationProfile') diff --git a/ts/test/test-profile-normalizer.ts b/ts/test/test-profile-normalizer.ts new file mode 100644 index 00000000..319c699f --- /dev/null +++ b/ts/test/test-profile-normalizer.ts @@ -0,0 +1,423 @@ +/* + * Copyright 2026 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. + */ + +import * as sinon from 'sinon'; +import {Profile} from 'pprof-format'; + +import { + Frame, + frameFunctionName, + GARBAGE_COLLECTION_FUNCTION_NAME, + NON_JS_THREADS_FUNCTION_NAME, + NormalizedProfile, + normalizeHeapProfile, + normalizeTimeProfile, + ProfileVisitor, + visitTimeProfile, +} from '../src/profile-normalizer'; +import { + serializeHeapProfile, + serializeTimeProfile, +} from '../src/profile-serializer'; +import {SourceMapper} from '../src/sourcemapper/sourcemapper'; +import {TimeProfile, TimeProfileNode} from '../src/v8-types'; +import { + labelEncodingProfile, + v8AnonymousFunctionHeapProfile, + v8HeapProfile, + v8HeapWithPathProfile, + v8TimeProfile, +} from './profiles-for-tests'; + +const assert = require('assert'); + +/** + * Renders each sample of a normalized profile as a comparable string of its + * function names (leaf first), values and labels. + */ +function describeNormalizedSamples(prof: NormalizedProfile): string[] { + return prof.samples.map(s => + JSON.stringify({ + stack: prof.stacks[s.stackId].map(i => frameFunctionName(prof.frames[i])), + values: s.values, + labels: s.labels.map(([k, v]) => [k, String(v)]), + }), + ); +} + +/** + * Same as describeNormalizedSamples, for a pprof profile. + */ +function describePprofSamples(prof: Profile): string[] { + const strings = prof.stringTable.strings; + return prof.sample.map(s => + JSON.stringify({ + stack: s.locationId.map(id => { + const location = prof.location[Number(id) - 1]; + const fn = prof.function[Number(location.line[0].functionId) - 1]; + return strings[Number(fn.name)]; + }), + values: s.value.map(Number), + labels: s.label.map(l => [ + strings[Number(l.key)], + l.str ? strings[Number(l.str)] : String(l.num), + ]), + }), + ); +} + +function makeTimeProfile(children: TimeProfileNode[]): TimeProfile { + return { + startTime: 0, + endTime: 10 * 1000 * 1000, + hasCpuTime: true, + topDownRoot: { + name: '(root)', + scriptName: 'root', + scriptId: 0, + lineNumber: 0, + columnNumber: 0, + hitCount: 0, + children, + }, + }; +} + +function makeLeaf( + name: string, + props: Partial = {}, +): TimeProfileNode { + return { + name, + scriptName: 'script', + scriptId: 1, + lineNumber: 1, + columnNumber: 1, + hitCount: 1, + children: [], + ...props, + }; +} + +describe('profile-normalizer', () => { + let dateStub: sinon.SinonStub<[], number>; + + before(() => { + dateStub = sinon.stub(Date, 'now').returns(0); + }); + after(() => { + dateStub.restore(); + }); + + describe('normalizeTimeProfile', () => { + it('should have the same samples as the serialized pprof profile', () => { + const normalized = normalizeTimeProfile(v8TimeProfile, { + intervalMicros: 1000, + }); + const pprof = serializeTimeProfile(v8TimeProfile, 1000); + assert.deepStrictEqual( + describeNormalizedSamples(normalized), + describePprofSamples(pprof), + ); + assert.strictEqual(normalized.frames.length, pprof.location.length); + assert.strictEqual(normalized.period, pprof.period); + assert.strictEqual(normalized.durationNanos, pprof.durationNanos); + }); + + it('should describe wall and sample count types, and CPU when present', () => { + const withCpu = normalizeTimeProfile(makeTimeProfile([]), { + intervalMicros: 1000, + }); + assert.deepStrictEqual(withCpu.sampleTypes, [ + {type: 'sample', unit: 'count'}, + {type: 'wall', unit: 'nanoseconds'}, + {type: 'cpu', unit: 'nanoseconds'}, + ]); + assert.deepStrictEqual(withCpu.periodType, { + type: 'wall', + unit: 'nanoseconds', + }); + const withoutCpu = normalizeTimeProfile( + {...makeTimeProfile([]), hasCpuTime: false}, + {intervalMicros: 1000}, + ); + assert.strictEqual(withoutCpu.sampleTypes.length, 2); + }); + + it('should keep only string, number and bigint labels', () => { + const normalized = normalizeTimeProfile( + labelEncodingProfile as unknown as TimeProfile, + {intervalMicros: 1000}, + ); + assert.deepStrictEqual(normalized.samples[0].labels, [ + ['someStr', 'foo'], + ['someNum', 42], + ['someBigint', 18446744073709551557n], + ]); + }); + + it('should put synthetic runtime frames under a Node.js frame', () => { + const prof = makeTimeProfile([ + makeLeaf('(program)'), + makeLeaf('(garbage collector)'), + makeLeaf('foo'), + ]); + prof.nonJSThreadsCpuTime = 500; + const normalized = normalizeTimeProfile(prof, {intervalMicros: 1000}); + const stacks = normalized.samples.map(s => + normalized.stacks[s.stackId].map(i => + frameFunctionName(normalized.frames[i]), + ), + ); + assert.deepStrictEqual(stacks.sort(), [ + [GARBAGE_COLLECTION_FUNCTION_NAME, 'Node.js'], + [NON_JS_THREADS_FUNCTION_NAME, 'Node.js'], + ['foo'], + ]); + const nonJS = normalized.samples.find( + s => + normalized.frames[normalized.stacks[s.stackId][0]].name === + NON_JS_THREADS_FUNCTION_NAME, + )!; + assert.deepStrictEqual(nonJS.values, [0, 0, 500]); + }); + + it('should emit a sample per labelled context and give idle zero wall time', () => { + const prof = makeTimeProfile([ + makeLeaf('(idle)', { + hitCount: 2, + contexts: [ + {context: {a: 'x'}, timestamp: 1n, cpuTime: 10}, + {context: {}, timestamp: 2n, cpuTime: 20}, + ], + }), + ]); + const normalized = normalizeTimeProfile(prof, {intervalMicros: 1000}); + assert.deepStrictEqual( + normalized.samples.map(s => [s.values, s.labels]), + [ + [[1, 0, 10], [['a', 'x']]], + // The unlabelled context's hit and CPU time go into one sample. + [[1, 0, 20], []], + ], + ); + }); + + it('should pass the context to generateLabels', () => { + const context = {context: {}, timestamp: 42n}; + const prof = makeTimeProfile([makeLeaf('foo', {contexts: [context]})]); + const generateLabels = sinon.stub().returns({ts: 42n}); + const normalized = normalizeTimeProfile(prof, { + intervalMicros: 1000, + generateLabels, + }); + sinon.assert.calledOnce(generateLabels); + assert.strictEqual(generateLabels.getCall(0).args[0].context, context); + assert.deepStrictEqual(normalized.samples[0].labels, [['ts', 42n]]); + }); + + it('should keep frames from different original files apart', () => { + // One generated script whose two positions map to different original + // files, with the same function name and position + const sourceMapper = { + mappingInfo: (loc: {line: number}) => ({ + file: loc.line === 1 ? '/app/a.ts' : '/app/b.ts', + line: 1, + column: 1, + name: 'render', + }), + } as unknown as SourceMapper; + const prof = makeTimeProfile([ + makeLeaf('x', {scriptId: 42, lineNumber: 1, columnNumber: 5}), + makeLeaf('y', {scriptId: 42, lineNumber: 2, columnNumber: 5}), + ]); + const normalized = normalizeTimeProfile(prof, { + intervalMicros: 1000, + sourceMapper, + }); + assert.deepStrictEqual(normalized.frames.map(f => f.file).sort(), [ + '/app/a.ts', + '/app/b.ts', + ]); + assert.strictEqual(normalized.stacks.length, 2); + + const pprof = serializeTimeProfile(prof, 1000, sourceMapper); + const strings = pprof.stringTable.strings; + assert.deepStrictEqual( + pprof.function.map(f => strings[Number(f.filename)]).sort(), + ['/app/a.ts', '/app/b.ts'], + ); + }); + + it('should keep named and anonymous functions apart', () => { + // A function named like an anonymous function's position + const prof = makeTimeProfile([ + makeLeaf('1:1', {lineNumber: 5, columnNumber: 5}), + makeLeaf('', {lineNumber: 1, columnNumber: 1}), + ]); + const pprof = serializeTimeProfile(prof, 1000); + const strings = pprof.stringTable.strings; + assert.deepStrictEqual( + pprof.function.map(f => strings[Number(f.name)]).sort(), + ['(anonymous:L#1:C#1)', '1:1'], + ); + }); + + it('should strip file:// prefixes from script names', () => { + const prof = makeTimeProfile([ + makeLeaf('foo', {scriptName: 'file:///app/index.mjs'}), + ]); + const normalized = normalizeTimeProfile(prof, {intervalMicros: 1000}); + assert.strictEqual(normalized.frames[0].file, '/app/index.mjs'); + }); + }); + + describe('visitTimeProfile', () => { + it('should deliver metadata first, frames and stacks once before use, and end last', () => { + const events: string[] = []; + const frameIds = new Set(); + const stackIds = new Set(); + let nextId = 100; + const visitor: ProfileVisitor = { + metadata: () => { + events.push('metadata'); + }, + frame: () => { + events.push('frame'); + const id = nextId++; + frameIds.add(id); + return id; + }, + stack: ids => { + events.push('stack'); + for (const id of ids) { + assert.ok(frameIds.has(id), `frame ${id} delivered before stack`); + } + const id = nextId++; + stackIds.add(id); + return id; + }, + sample: s => { + events.push('sample'); + assert.ok( + stackIds.has(s.stackId), + `stack ${s.stackId} delivered before sample`, + ); + }, + }; + visitor.end = result => { + events.push('end'); + assert.deepStrictEqual(result, {hasMissingMapFiles: false}); + }; + const result = visitTimeProfile(v8TimeProfile, visitor, { + intervalMicros: 1000, + }); + assert.strictEqual(events[0], 'metadata'); + assert.strictEqual(events.lastIndexOf('metadata'), 0); + assert.ok(events.includes('sample')); + assert.strictEqual(events.indexOf('end'), events.length - 1); + assert.strictEqual(result.hasMissingMapFiles, false); + }); + + it('should deliver a stack per distinct frame sequence that has samples', () => { + // Two sibling nodes resolving to the same frame share a stack, and the + // sample-less "parent" node's stack is never delivered. + const prof = makeTimeProfile([ + makeLeaf('parent', { + hitCount: 0, + children: [makeLeaf('foo', {scriptId: 2}), makeLeaf('bar')], + }), + makeLeaf('parent', { + hitCount: 0, + children: [makeLeaf('foo', {scriptId: 2})], + }), + ]); + const normalized = normalizeTimeProfile(prof, {intervalMicros: 1000}); + const stacks = normalized.stacks.map(s => + s.map(i => frameFunctionName(normalized.frames[i])), + ); + assert.deepStrictEqual(stacks.sort(), [ + ['bar', 'parent'], + ['foo', 'parent'], + ]); + assert.strictEqual(normalized.samples.length, 3); + const fooStack = normalized.stacks.findIndex( + s => normalized.frames[s[0]].name === 'foo', + ); + assert.strictEqual( + normalized.samples.filter(s => s.stackId === fooStack).length, + 2, + ); + }); + }); + + describe('normalizeHeapProfile', () => { + it('should have the same samples as the serialized pprof profile', () => { + for (const prof of [v8HeapProfile, v8AnonymousFunctionHeapProfile]) { + const normalized = normalizeHeapProfile(prof, { + startTimeNanos: 0, + intervalBytes: 64, + }); + const pprof = serializeHeapProfile(prof, 0, 64); + assert.deepStrictEqual( + describeNormalizedSamples(normalized), + describePprofSamples(pprof), + ); + assert.deepStrictEqual(normalized.sampleTypes, [ + {type: 'inuse_objects', unit: 'count'}, + {type: 'inuse_space', unit: 'bytes'}, + ]); + } + }); + + it('should omit samples under ignoreSamplesPath', () => { + const ignored = '@google-cloud/profiler'; + const normalized = normalizeHeapProfile(v8HeapWithPathProfile, { + startTimeNanos: 0, + intervalBytes: 64, + ignoreSamplesPath: ignored, + }); + assert.ok(normalized.frames.length > 0); + for (const frame of normalized.frames) { + assert.ok(!frame.file.includes(ignored)); + } + }); + }); + + describe('frameFunctionName', () => { + const frame = (props: Partial): Frame => ({ + file: 'f.js', + missingMapFile: false, + ...props, + }); + + it('should return the name when there is one', () => { + assert.strictEqual(frameFunctionName(frame({name: 'foo'})), 'foo'); + }); + + it('should synthesize names for anonymous functions', () => { + assert.strictEqual( + frameFunctionName(frame({name: '', line: 3, column: 5})), + '(anonymous:L#3:C#5)', + ); + assert.strictEqual( + frameFunctionName(frame({line: 3})), + '(anonymous:L#3)', + ); + assert.strictEqual(frameFunctionName(frame({})), '(anonymous)'); + }); + }); +}); diff --git a/ts/test/test-time-profiler.ts b/ts/test/test-time-profiler.ts index 112a584e..86cd8e23 100644 --- a/ts/test/test-time-profiler.ts +++ b/ts/test/test-time-profiler.ts @@ -536,6 +536,27 @@ describe('Time Profiler', () => { sinon.assert.calledOnce(timeProfilerStub.stop); }); + it('should return the raw profile from stopRaw', () => { + time.start({intervalMicros: PROFILE_OPTIONS.intervalMicros}); + assert.strictEqual(time.stopRaw(true), v8TimeProfile); + assert.ok(time.isStarted()); + assert.strictEqual(time.stopRaw(), v8TimeProfile); + assert.ok(!time.isStarted()); + }); + + it('should return a normalized profile matching the serialized one from stopNormalized', () => { + time.start({intervalMicros: PROFILE_OPTIONS.intervalMicros}); + const normalized = time.stopNormalized(); + assert.ok(!time.isStarted()); + assert.strictEqual(normalized.samples.length, timeProfile.sample.length); + assert.strictEqual(normalized.frames.length, timeProfile.location.length); + assert.strictEqual(normalized.period, timeProfile.period); + assert.deepStrictEqual( + normalized.samples.map(s => s.values), + timeProfile.sample.map(s => s.value), + ); + }); + it('should serialize with the source mapper still set when stopping', () => { // Regression test: stop() used to tear down the profiler state (via // handleStopNoRestart, which clears gSourceMapper) *before* serializing, From 9f2ab19a12a0ab049f6aa0a13ca7fa699e407e9a Mon Sep 17 00:00:00 2001 From: Attila Szegedi Date: Fri, 2 Oct 2026 12:12:57 +0200 Subject: [PATCH 2/3] Add per-sample timing to time profile normalization Samples emitted for a labelled context now carry the context's timestamp as NormalizedSample.timestamp, in nanoseconds since epoch. Aggregated samples and synthetic contexts (timestamp 0) have none. Until now the only way to see a timestamp was through generateLabels, which dd-trace uses to add an end_timestamp_ns label. OTel profiles carry timestamps in Sample.timestamps_unix_nano instead, and labels there should have bounded cardinality. By default, the hits and CPU time of contexts without labels are folded into one sample per node, without a timestamp, so a profile can mix timestamped and aggregated samples. OTel profiles recommend that all samples in a profile have the same shape. With the new samplePerContext option, every context becomes its own timestamped sample. Hits without any context are still aggregated, so the totals match the default mode. time.stopNormalized() now takes an options object (generateLabels, samplePerContext). The option types are exported. --- ts/src/index.ts | 2 ++ ts/src/profile-normalizer.ts | 47 ++++++++++++++++++++---- ts/src/time-profiler.ts | 13 +++++-- ts/test/test-profile-normalizer.ts | 57 +++++++++++++++++++++++++++--- 4 files changed, 106 insertions(+), 13 deletions(-) diff --git a/ts/src/index.ts b/ts/src/index.ts index b5ccbf8f..cf1ca01e 100644 --- a/ts/src/index.ts +++ b/ts/src/index.ts @@ -29,6 +29,7 @@ export { export { Frame, frameFunctionName, + HeapProfileNormalizerOptions, NormalizedProfile, NormalizedSample, normalizeHeapProfile, @@ -38,6 +39,7 @@ export { SampleLabel, SampleLabelValue, SampleType, + TimeProfileNormalizerOptions, visitHeapProfile, visitTimeProfile, VisitResult, diff --git a/ts/src/profile-normalizer.ts b/ts/src/profile-normalizer.ts index 5003b725..8d4ce96c 100644 --- a/ts/src/profile-normalizer.ts +++ b/ts/src/profile-normalizer.ts @@ -78,6 +78,13 @@ export interface NormalizedSample { /** One value for each of {@link ProfileMetadata.sampleTypes}. */ values: number[]; labels: SampleLabel[]; + /** + * Time at which the sample was taken, in nanoseconds since epoch (with + * microsecond precision). Only set on samples that represent a single + * observation with a known time, i.e. time profile samples for a context. + * Undefined for aggregated samples. + */ + timestamp?: bigint; } export interface SampleType { @@ -146,6 +153,15 @@ export interface TimeProfileNormalizerOptions { */ recomputeSamplingInterval?: boolean; generateLabels?: GenerateTimeLabelsFunction; + /** + * Emit a separate, timestamped sample for every context, even when it has + * no labels. By default, the hits and CPU time of contexts without labels + * are aggregated into a single sample per node, without a timestamp. Set + * this when every sample should have a timestamp, e.g. for OTel profiles, + * whose samples should all have the same shape. Hits without a context + * (e.g. when contexts are not collected) are still aggregated. + */ + samplePerContext?: boolean; } export interface HeapProfileNormalizerOptions { @@ -163,7 +179,11 @@ export interface HeapProfileNormalizerOptions { /** * Emits a sample for the node currently being visited. */ -type EmitSample = (values: number[], labels: SampleLabel[]) => void; +type EmitSample = ( + values: number[], + labels: SampleLabel[], + timestamp?: bigint, +) => void; /** * Converts a node into zero or more samples and passes them to emit. @@ -268,8 +288,13 @@ function visitTree( const rootStacks = new Map(); let currentStack = -1; - const emit: EmitSample = (values, labels) => { - visitor.sample({stackId: getStackId(currentStack), values, labels}); + const emit: EmitSample = (values, labels, timestamp) => { + visitor.sample({ + stackId: getStackId(currentStack), + values, + labels, + timestamp, + }); }; const entries: Array> = (root.children as T[]).map((n: T) => ({ @@ -497,7 +522,12 @@ export function visitTimeProfile( visitor: ProfileVisitor, options: TimeProfileNormalizerOptions, ): VisitResult { - const {sourceMapper, recomputeSamplingInterval, generateLabels} = options; + const { + sourceMapper, + recomputeSamplingInterval, + generateLabels, + samplePerContext, + } = options; let intervalMicros = options.intervalMicros; // If requested, recompute sampling interval from profile duration and total number of hits, // since profile duration should be #hits x interval. @@ -546,7 +576,7 @@ export function visitTimeProfile( ? generateLabels({node, context}) : (context.context ?? {}), ); - if (labels.length > 0) { + if (labels.length > 0 || samplePerContext) { // Only assign wall time if there are hits, some special nodes such as `(Non-JS threads)` // have zero hit count (since they do not count as wall time) and should not be assigned any // wall time. Also, `(idle)` nodes should be assigned zero wall time. @@ -555,7 +585,12 @@ export function visitTimeProfile( if (prof.hasCpuTime) { values.push(context.cpuTime ?? 0); } - emit(values, labels); + // Context timestamps are in microseconds; 0 marks a synthetic context. + emit( + values, + labels, + context.timestamp ? BigInt(context.timestamp) * 1000n : undefined, + ); unlabelledHits--; } else if (prof.hasCpuTime) { unlabelledCpuTime += context.cpuTime ?? 0; diff --git a/ts/src/time-profiler.ts b/ts/src/time-profiler.ts index f0be4876..af73b11c 100644 --- a/ts/src/time-profiler.ts +++ b/ts/src/time-profiler.ts @@ -24,7 +24,11 @@ import { GARBAGE_COLLECTION_FUNCTION_NAME, NON_JS_THREADS_FUNCTION_NAME, } from './profile-serializer'; -import {NormalizedProfile, normalizeTimeProfile} from './profile-normalizer'; +import { + NormalizedProfile, + normalizeTimeProfile, + TimeProfileNormalizerOptions, +} from './profile-normalizer'; import {SourceMapper} from './sourcemapper/sourcemapper'; import { TimeProfiler, @@ -198,14 +202,17 @@ export function stop( */ export function stopNormalized( restart = false, - generateLabels?: GenerateTimeLabelsFunction, + options: Pick< + TimeProfileNormalizerOptions, + 'generateLabels' | 'samplePerContext' + > = {}, ): NormalizedProfile { return stopAndProcess(restart, profile => normalizeTimeProfile(profile, { + ...options, intervalMicros: gIntervalMicros, sourceMapper: gSourceMapper, recomputeSamplingInterval: true, - generateLabels, }), ); } diff --git a/ts/test/test-profile-normalizer.ts b/ts/test/test-profile-normalizer.ts index 319c699f..83fc73e9 100644 --- a/ts/test/test-profile-normalizer.ts +++ b/ts/test/test-profile-normalizer.ts @@ -193,6 +193,7 @@ describe('profile-normalizer', () => { NON_JS_THREADS_FUNCTION_NAME, )!; assert.deepStrictEqual(nonJS.values, [0, 0, 500]); + assert.strictEqual(nonJS.timestamp, undefined); }); it('should emit a sample per labelled context and give idle zero wall time', () => { @@ -207,15 +208,63 @@ describe('profile-normalizer', () => { ]); const normalized = normalizeTimeProfile(prof, {intervalMicros: 1000}); assert.deepStrictEqual( - normalized.samples.map(s => [s.values, s.labels]), + normalized.samples.map(s => [s.values, s.labels, s.timestamp]), [ - [[1, 0, 10], [['a', 'x']]], - // The unlabelled context's hit and CPU time go into one sample. - [[1, 0, 20], []], + // Labelled samples carry the context timestamp in nanoseconds. + [[1, 0, 10], [['a', 'x']], 1000n], + // The unlabelled context's hit and CPU time go into one aggregated + // sample, without a timestamp. + [[1, 0, 20], [], undefined], ], ); }); + it('should emit a timestamped sample per context with samplePerContext', () => { + const prof = makeTimeProfile([ + makeLeaf('(idle)', { + hitCount: 2, + contexts: [ + {context: {a: 'x'}, timestamp: 1n, cpuTime: 10}, + {context: {}, timestamp: 2n, cpuTime: 20}, + ], + }), + makeLeaf('foo', { + scriptId: 2, + // One more hit than contexts: that one stays aggregated. + hitCount: 3, + contexts: [ + {context: {}, timestamp: 3n, cpuTime: 30}, + {context: {}, timestamp: 4n, cpuTime: 40}, + ], + }), + ]); + const describe = (p: NormalizedProfile) => + p.samples.map(s => [ + frameFunctionName(p.frames[p.stacks[s.stackId][0]]), + s.values, + s.labels, + s.timestamp, + ]); + const perContext = normalizeTimeProfile(prof, { + intervalMicros: 1000, + samplePerContext: true, + }); + assert.deepStrictEqual(describe(perContext), [ + ['foo', [1, 1000000, 30], [], 3000n], + ['foo', [1, 1000000, 40], [], 4000n], + ['foo', [1, 1000000, 0], [], undefined], + ['(idle)', [1, 0, 10], [['a', 'x']], 1000n], + ['(idle)', [1, 0, 20], [], 2000n], + ]); + // Totals match the default, aggregating mode. + const aggregated = normalizeTimeProfile(prof, {intervalMicros: 1000}); + assert.deepStrictEqual(describe(aggregated), [ + ['foo', [3, 3000000, 70], [], undefined], + ['(idle)', [1, 0, 10], [['a', 'x']], 1000n], + ['(idle)', [1, 0, 20], [], undefined], + ]); + }); + it('should pass the context to generateLabels', () => { const context = {context: {}, timestamp: 42n}; const prof = makeTimeProfile([makeLeaf('foo', {contexts: [context]})]); From 212f1222eaa088d84767b4b28f73f0f02c5f53ec Mon Sep 17 00:00:00 2001 From: Attila Szegedi Date: Mon, 26 Oct 2026 19:49:55 +0100 Subject: [PATCH 3/3] Report exact collection times in profile metadata The collection time in nanoseconds since epoch is around 1.7e18, beyond Number.MAX_SAFE_INTEGER, so Date.now() * 1000 * 1000 rounded it to a double. ProfileMetadata.timeNanos is now a bigint computed exactly, and so is the heap normalizer's startTimeNanos option that feeds it. The pprof serializer still gives Profile.timeNanos a number equal to Date.now() * 1000 * 1000, so pprof output and the Profile objects returned to callers are unchanged. serializeHeapProfile() accepts either a number or a bigint start time. Context timestamps are V8 timer values converted to microseconds since the UNIX epoch with an offset the native profiler computes at stop. The profile's startTime and endTime remained raw V8 timer values, so the collection period couldn't be placed on the epoch timeline that sample timestamps use, and timeNanos, the time of normalization, lies after every sample. A format that bounds sample timestamps by the profile's time range (OTel: [time_unix_nano, time_unix_nano + duration_nano)) therefore got timestamps before the range. The native profiler now computes the offset once per stop, uses it for the sample timestamps, and returns it as the profile's epochOffset. The normalizer reports the start of the collection period as the new ProfileMetadata.startTimeNanos: exactly with the offset, or estimated as the collection time minus the duration without one. timeNanos keeps its meaning, so pprof output is unchanged. --- bindings/profilers/wall.cc | 34 +++++++++++++++++----- bindings/profilers/wall.hh | 3 +- ts/src/heap-profiler.ts | 4 +-- ts/src/profile-normalizer.ts | 27 ++++++++++++++---- ts/src/profile-serializer.ts | 8 ++++-- ts/src/v8-types.ts | 6 ++++ ts/test/test-profile-normalizer.ts | 46 ++++++++++++++++++++++++++++-- ts/test/test-time-profiler.ts | 30 +++++++++++++++++++ 8 files changed, 138 insertions(+), 20 deletions(-) diff --git a/bindings/profilers/wall.cc b/bindings/profilers/wall.cc index 32e8ef7a..c08ab094 100644 --- a/bindings/profilers/wall.cc +++ b/bindings/profilers/wall.cc @@ -511,7 +511,8 @@ void WallProfiler::Cleanup(Isolate* isolate) { ContextsByNode WallProfiler::GetContextsByNode(CpuProfile* profile, ContextBuffer& contexts, - int64_t startCpuTime) { + int64_t startCpuTime, + int64_t V8toEpochOffset) { ContextsByNode contextsByNode; auto sampleCount = profile->GetSamplesCount(); @@ -551,7 +552,6 @@ ContextsByNode WallProfiler::GetContextsByNode(CpuProfile* profile, return object; }; #endif - auto V8toEpochOffset = GetV8ToEpochOffset(); auto lastCpuTime = startCpuTime; // skip first sample because it's the one taken on profiler start, outside of @@ -1160,6 +1160,9 @@ Result WallProfiler::StopCore(bool restart, ProfileBuilder&& buildProfile) { ContextsByNode* contextsByNodePtr = nullptr; int64_t nonJSThreadsCpuTime = 0; bool hasCpuTime = false; + // One offset for both the sample timestamps and the profile's epochOffset, + // so that they agree. + auto v8ToEpochOffset = GetV8ToEpochOffset(); if (withContexts_) { if (isMainThread_ && collectCpuTime_) { @@ -1173,13 +1176,17 @@ Result WallProfiler::StopCore(bool restart, ProfileBuilder&& buildProfile) { std::max(processCpu - totalWorkerCpu, ProcessCpuClock::duration{}) .count(); } - contextsByNode = - GetContextsByNode(v8_profile, contexts, startThreadCpuTime); + contextsByNode = GetContextsByNode( + v8_profile, contexts, startThreadCpuTime, v8ToEpochOffset); contextsByNodePtr = &contextsByNode; hasCpuTime = collectCpuTime_; } - buildProfile(v8_profile, hasCpuTime, nonJSThreadsCpuTime, contextsByNodePtr); + buildProfile(v8_profile, + hasCpuTime, + nonJSThreadsCpuTime, + contextsByNodePtr, + v8ToEpochOffset); v8_profile->Delete(); @@ -1197,17 +1204,28 @@ Result WallProfiler::StopCore(bool restart, ProfileBuilder&& buildProfile) { return {}; } +// Sets the offset that converts the profile's V8 timer values (startTime, +// endTime) to microseconds since the UNIX epoch, like sample timestamps. +static void SetEpochOffset(v8::Local profile, + int64_t v8ToEpochOffset) { + Nan::Set(profile.As(), + Nan::New("epochOffset").ToLocalChecked(), + Nan::New(static_cast(v8ToEpochOffset))); +} + Result WallProfiler::StopImpl(bool restart, v8::Local& profile) { return StopCore(restart, [&](const v8::CpuProfile* v8_profile, bool hasCpuTime, int64_t nonJSThreadsCpuTime, - ContextsByNode* contextsByNodePtr) { + ContextsByNode* contextsByNodePtr, + int64_t v8ToEpochOffset) { profile = TranslateTimeProfile(v8_profile, includeLines_, contextsByNodePtr, hasCpuTime, nonJSThreadsCpuTime); + SetEpochOffset(profile, v8ToEpochOffset); }); } @@ -1219,11 +1237,13 @@ Result WallProfiler::StopAndCollectImpl(bool restart, [&](const v8::CpuProfile* v8_profile, bool hasCpuTime, int64_t nonJSThreadsCpuTime, - ContextsByNode* contextsByNodePtr) { + ContextsByNode* contextsByNodePtr, + int64_t v8ToEpochOffset) { auto* isolate = Isolate::GetCurrent(); TimeProfileViewState state{includeLines_, contextsByNodePtr, {}}; auto profile_view = BuildTimeProfileView( v8_profile, hasCpuTime, nonJSThreadsCpuTime, state); + SetEpochOffset(profile_view, v8ToEpochOffset); v8::Local argv[] = {profile_view}; auto cb_result = Nan::Call( callback, isolate->GetCurrentContext()->Global(), 1, argv); diff --git a/bindings/profilers/wall.hh b/bindings/profilers/wall.hh index 5fdf0d22..d44f87a1 100644 --- a/bindings/profilers/wall.hh +++ b/bindings/profilers/wall.hh @@ -128,7 +128,8 @@ class WallProfiler : public Nan::ObjectWrap { ContextsByNode GetContextsByNode(v8::CpuProfile* profile, ContextBuffer& contexts, - int64_t startCpuTime); + int64_t startCpuTime, + int64_t v8ToEpochOffset); bool waitForSignal(uint64_t targetCallCount = 0); static void CleanupHook(void* data); diff --git a/ts/src/heap-profiler.ts b/ts/src/heap-profiler.ts index 17ed4187..447b88d8 100644 --- a/ts/src/heap-profiler.ts +++ b/ts/src/heap-profiler.ts @@ -114,7 +114,7 @@ export function normalizedProfile( generateLabels?: GenerateAllocationLabelsFunction, ): NormalizedProfile { return collectProfile(root => { - const startTimeNanos = Date.now() * 1000 * 1000; + const startTimeNanos = BigInt(Date.now()) * 1_000_000n; return normalizeHeapProfile( addExternalMemoryNode(root, startedWithAllocations), { @@ -160,7 +160,7 @@ export function convertProfile( columnNumbers: ColumnNumbers = DEFAULT_COLUMN_NUMBERS, ): Profile { const allocations = startedWithAllocations; - const startTimeNanos = Date.now() * 1000 * 1000; + const startTimeNanos = BigInt(Date.now()) * 1_000_000n; return serializeHeapProfile( addExternalMemoryNode(rootNode, allocations), startTimeNanos, diff --git a/ts/src/profile-normalizer.ts b/ts/src/profile-normalizer.ts index 8d4ce96c..2f023940 100644 --- a/ts/src/profile-normalizer.ts +++ b/ts/src/profile-normalizer.ts @@ -96,8 +96,17 @@ export interface ProfileMetadata { sampleTypes: SampleType[]; periodType: SampleType; period: number; - /** Time of collection in nanoseconds since epoch. */ - timeNanos: number; + /** + * Time of collection in nanoseconds since epoch: when the profile was + * normalized. A bigint, because the value exceeds Number.MAX_SAFE_INTEGER. + */ + timeNanos: bigint; + /** + * Start of the profile's collection period, in nanoseconds since epoch, + * for profiles collected over a period (time profiles). Sample timestamps + * fall within [startTimeNanos, startTimeNanos + durationNanos]. + */ + startTimeNanos?: bigint; durationNanos?: number; } @@ -166,7 +175,7 @@ export interface TimeProfileNormalizerOptions { export interface HeapProfileNormalizerOptions { /** Start time of profile, in nanoseconds since epoch. */ - startTimeNanos: number; + startTimeNanos: bigint; /** Bytes allocated between samples. */ intervalBytes: number; ignoreSamplesPath?: string; @@ -555,10 +564,18 @@ export function visitTimeProfile( if (prof.hasCpuTime) { sampleTypes.push({type: 'cpu', unit: 'nanoseconds'}); } + const timeNanos = BigInt(Date.now()) * 1_000_000n; + const durationNanos = (prof.endTime - prof.startTime) * 1000; visitor.metadata({ sampleTypes, - timeNanos: Date.now() * 1000 * 1000, - durationNanos: (prof.endTime - prof.startTime) * 1000, + timeNanos, + // Exact with the native profiler's epoch offset. Without one, estimate it + // on the assumption that the profile was just stopped. + startTimeNanos: + prof.epochOffset !== undefined + ? BigInt(Math.round(prof.startTime + prof.epochOffset)) * 1000n + : timeNanos - BigInt(Math.round(durationNanos)), + durationNanos, periodType: timeType, period: intervalNanos, }); diff --git a/ts/src/profile-serializer.ts b/ts/src/profile-serializer.ts index 72bc0296..aecac7a2 100644 --- a/ts/src/profile-serializer.ts +++ b/ts/src/profile-serializer.ts @@ -137,7 +137,9 @@ function serialize( }); profile = { sampleType: metadata.sampleTypes.map(valueType), - timeNanos: metadata.timeNanos, + // pprof Profile objects have always had a number here; keep it one. + // It rounds the time to a double, like Date.now() * 1000 * 1000 did. + timeNanos: Number(metadata.timeNanos), durationNanos: metadata.durationNanos, periodType: valueType(metadata.periodType), period: metadata.period, @@ -296,7 +298,7 @@ export function serializeTimeProfile( */ export function serializeHeapProfile( prof: AllocationProfileNode | AllocationProfileNodeWithStats, - startTimeNanos: number, + startTimeNanos: number | bigint, intervalBytes: number, ignoreSamplesPath?: string, sourceMapper?: SourceMapper, @@ -305,7 +307,7 @@ export function serializeHeapProfile( columnNumbers: ColumnNumbers = DEFAULT_COLUMN_NUMBERS, ): Profile { const options: HeapProfileNormalizerOptions = { - startTimeNanos, + startTimeNanos: BigInt(startTimeNanos), intervalBytes, ignoreSamplesPath, sourceMapper, diff --git a/ts/src/v8-types.ts b/ts/src/v8-types.ts index 6221326f..579f3eff 100644 --- a/ts/src/v8-types.ts +++ b/ts/src/v8-types.ts @@ -22,6 +22,12 @@ export interface TimeProfile { topDownRoot: TimeProfileNode; /** V8 timer value, in microseconds, at which profile was started. */ startTime: number; + /** + * Microseconds to add to a V8 timer value (startTime, endTime) to get + * microseconds since the UNIX epoch. The same offset converts sample + * timestamps, so the converted startTime and endTime bracket them. + */ + epochOffset?: number; hasCpuTime?: boolean; /** CPU time of non-JS threads, only reported for the main worker thread */ nonJSThreadsCpuTime?: number; diff --git a/ts/test/test-profile-normalizer.ts b/ts/test/test-profile-normalizer.ts index 83fc73e9..69b03ff1 100644 --- a/ts/test/test-profile-normalizer.ts +++ b/ts/test/test-profile-normalizer.ts @@ -137,6 +137,48 @@ describe('profile-normalizer', () => { assert.strictEqual(normalized.durationNanos, pprof.durationNanos); }); + it('should give the collection time exactly, as a bigint', () => { + // 1.7e18 nanoseconds is beyond the precision of a double + dateStub.returns(1700000000123); + try { + const normalized = normalizeTimeProfile(makeTimeProfile([]), { + intervalMicros: 1000, + }); + assert.strictEqual(normalized.timeNanos, 1700000000123000000n); + // The pprof profile keeps the number it has always had + const pprof = serializeTimeProfile(makeTimeProfile([]), 1000); + assert.strictEqual(pprof.timeNanos, 1700000000123 * 1000 * 1000); + } finally { + dateStub.returns(0); + } + }); + + it('should give the start of the collection period', () => { + dateStub.returns(1700000000123); + try { + // With the native profiler's epoch offset, exactly + const prof = { + ...makeTimeProfile([]), + startTime: 5_000_000, + endTime: 15_000_000, + epochOffset: 1700000000000_000 - 5_000_000, + }; + const exact = normalizeTimeProfile(prof, {intervalMicros: 1000}); + assert.strictEqual(exact.startTimeNanos, 1700000000000_000_000n); + assert.strictEqual(exact.durationNanos, 10_000_000_000); + // Without one, estimated as the collection time minus the duration + const estimated = normalizeTimeProfile(makeTimeProfile([]), { + intervalMicros: 1000, + }); + assert.strictEqual( + estimated.startTimeNanos, + 1700000000123_000_000n - 10_000_000_000n, + ); + } finally { + dateStub.returns(0); + } + }); + it('should describe wall and sample count types, and CPU when present', () => { const withCpu = normalizeTimeProfile(makeTimeProfile([]), { intervalMicros: 1000, @@ -417,7 +459,7 @@ describe('profile-normalizer', () => { it('should have the same samples as the serialized pprof profile', () => { for (const prof of [v8HeapProfile, v8AnonymousFunctionHeapProfile]) { const normalized = normalizeHeapProfile(prof, { - startTimeNanos: 0, + startTimeNanos: 0n, intervalBytes: 64, }); const pprof = serializeHeapProfile(prof, 0, 64); @@ -435,7 +477,7 @@ describe('profile-normalizer', () => { it('should omit samples under ignoreSamplesPath', () => { const ignored = '@google-cloud/profiler'; const normalized = normalizeHeapProfile(v8HeapWithPathProfile, { - startTimeNanos: 0, + startTimeNanos: 0n, intervalBytes: 64, ignoreSamplesPath: ignored, }); diff --git a/ts/test/test-time-profiler.ts b/ts/test/test-time-profiler.ts index 86cd8e23..bcd56649 100644 --- a/ts/test/test-time-profiler.ts +++ b/ts/test/test-time-profiler.ts @@ -416,6 +416,36 @@ describe('Time Profiler', () => { }); }); + it('should put sample timestamps within the collection period', async function shouldBracketTimestamps() { + if (unsupportedPlatform) { + this.skip(); + } + this.timeout(3000); + + time.start({ + intervalMicros: PROFILE_OPTIONS.intervalMicros, + withContexts: true, + }); + const testStart = hrtime.bigint(); + while (hrtime.bigint() - testStart < 200_000_000n) { + time.setContext({}); + await setTimeoutPromise(1); + } + const profile = time.stopNormalized(false, {samplePerContext: true}); + const timestamps = profile.samples + .map(sample => sample.timestamp) + .filter(timestamp => timestamp !== undefined) as bigint[]; + assert.ok(timestamps.length > 0, 'has timestamped samples'); + const start = profile.startTimeNanos!; + const end = start + BigInt(Math.round(profile.durationNanos!)); + for (const timestamp of timestamps) { + assert.ok( + timestamp >= start && timestamp <= end, + `${timestamp} outside [${start}, ${end}]`, + ); + } + }); + it('should have async IDs when enabled', async function shouldCollectAsyncIDs() { if (!(collectAsyncId && ['darwin', 'linux'].includes(process.platform))) { this.skip();