diff --git a/.env.example b/.env.example index 5e7045785c..fa575663b9 100644 --- a/.env.example +++ b/.env.example @@ -294,6 +294,11 @@ S3_ADMIN_SECRET_KEY= # enable distributed tracing; leave empty to disable. e.g. http://localhost:4318 OTEL_EXPORTER_OTLP_ENDPOINT= +# Continuous CPU profiling. Point this at a Pyroscope instance to push profiles +# every 60s; leave empty to disable. Independent of tracing above. +# e.g. http://localhost:4040 +PYROSCOPE_SERVER_ADDRESS= + FIXER_BASE_URL= FIXER_API_KEY= diff --git a/package-lock.json b/package-lock.json index b293fef6e1..7903f02646 100644 --- a/package-lock.json +++ b/package-lock.json @@ -47,6 +47,7 @@ "@opentelemetry/exporter-trace-otlp-http": "^0.218.0", "@opentelemetry/sdk-node": "^0.218.0", "@opentelemetry/sdk-trace-base": "^2.7.1", + "@pyroscope/nodejs": "^0.6.2", "@railgun-community/engine": "^9.4.0", "@scure/bip32": "^1.6.2", "@scure/bip39": "^1.5.4", @@ -2943,6 +2944,21 @@ "node": ">= 10" } }, + "node_modules/@datadog/pprof": { + "version": "5.14.4", + "resolved": "https://registry.npmjs.org/@datadog/pprof/-/pprof-5.14.4.tgz", + "integrity": "sha512-egEZDD9v98RBI8ijbHyaWQeY8rW0WEu004As5D7SUkdqSMORhrnh7ZdsM46PUzQgAc85IaEZoukWS9UhMvWn9w==", + "hasInstallScript": true, + "license": "Apache-2.0", + "dependencies": { + "node-gyp-build": "^4.8.4", + "pprof-format": "^2.2.1", + "source-map": "^0.7.4" + }, + "engines": { + "node": ">=16" + } + }, "node_modules/@deuro/eurocoin": { "version": "1.0.17", "resolved": "https://registry.npmjs.org/@deuro/eurocoin/-/eurocoin-1.0.17.tgz", @@ -12387,6 +12403,71 @@ "node": ">=12" } }, + "node_modules/@pyroscope/nodejs": { + "version": "0.6.2", + "resolved": "https://registry.npmjs.org/@pyroscope/nodejs/-/nodejs-0.6.2.tgz", + "integrity": "sha512-o1tmdpDiWnY8G1RYid1isLvFPTU5MW0f1B99WjrL9TubsfjSvK+q/I90s5YmooyRRG+3MgcL0RbPQIvEt0oGOA==", + "license": "Apache-2.0", + "dependencies": { + "@datadog/pprof": "5.14.4", + "debug": "^4.4.3", + "p-limit": "^7.3.0", + "pprof-format": "^2.2.1", + "regenerator-runtime": "^0.14.1", + "source-map": "^0.7.6" + }, + "engines": { + "node": ">=20.20.2" + }, + "peerDependencies": { + "express": "^4.0.0 || ^5.0.0", + "fastify": "^5.8.5" + }, + "peerDependenciesMeta": { + "express": { + "optional": true + }, + "fastify": { + "optional": true + } + } + }, + "node_modules/@pyroscope/nodejs/node_modules/p-limit": { + "version": "7.3.1", + "resolved": "https://registry.npmjs.org/p-limit/-/p-limit-7.3.1.tgz", + "integrity": "sha512-0trZaiG7Y7kN/Egy9a8j47t9osC0Tch4PaIWd9yGF6bvmlk7muExRvGNYb8sXBwEKMoNKsbNN9P8EefuQekE4Q==", + "license": "MIT", + "dependencies": { + "yocto-queue": "^1.2.1" + }, + "engines": { + "node": ">=20" + }, + "funding": { + "url": "https://github.com/sponsors/sindresorhus" + } + }, + "node_modules/@pyroscope/nodejs/node_modules/source-map": { + "version": "0.7.6", + "resolved": "https://registry.npmjs.org/source-map/-/source-map-0.7.6.tgz", + "integrity": "sha512-i5uvt8C3ikiWeNZSVZNWcfZPItFQOsYTUAOkcUPGd8DqDy1uOUikjt5dG+uRlwyvR108Fb9DOd4GvXfT0N2/uQ==", + "license": "BSD-3-Clause", + "engines": { + "node": ">= 12" + } + }, + "node_modules/@pyroscope/nodejs/node_modules/yocto-queue": { + "version": "1.2.2", + "resolved": "https://registry.npmjs.org/yocto-queue/-/yocto-queue-1.2.2.tgz", + "integrity": "sha512-4LCcse/U2MHZ63HAJVE+v71o7yOdIe4cZ70Wpf8D/IyjDKYQLV5GD46B+hSTjJsvV5PztjvHoU580EftxjDZFQ==", + "license": "MIT", + "engines": { + "node": ">=12.20" + }, + "funding": { + "url": "https://github.com/sponsors/sindresorhus" + } + }, "node_modules/@railgun-community/circomlibjs": { "version": "0.0.8", "resolved": "https://registry.npmjs.org/@railgun-community/circomlibjs/-/circomlibjs-0.0.8.tgz", @@ -29510,6 +29591,12 @@ "node": ">=0.10.0" } }, + "node_modules/pprof-format": { + "version": "2.3.0", + "resolved": "https://registry.npmjs.org/pprof-format/-/pprof-format-2.3.0.tgz", + "integrity": "sha512-ovChRLoV4H3k0zKWq0AXewtnuPGskzBLjBPmF2N0DZu+H65PYuo51+6e/1GTb8Olm7oC0xvhhLdqPL4/XhCl4A==", + "license": "MIT" + }, "node_modules/prelude-ls": { "version": "1.2.1", "resolved": "https://registry.npmjs.org/prelude-ls/-/prelude-ls-1.2.1.tgz", @@ -32320,7 +32407,6 @@ "version": "0.7.4", "resolved": "https://registry.npmjs.org/source-map/-/source-map-0.7.4.tgz", "integrity": "sha512-l3BikUxvPOcn5E74dZiq5BGsTb5yEwhaTSzccU6t4sDOH8NWJCstKO5QT2CvtFoK6F0saL7p9xHAqHOlCPJygA==", - "dev": true, "license": "BSD-3-Clause", "engines": { "node": ">= 8" diff --git a/package.json b/package.json index 74a9f61938..7b531286fc 100644 --- a/package.json +++ b/package.json @@ -66,6 +66,7 @@ "@opentelemetry/exporter-trace-otlp-http": "^0.218.0", "@opentelemetry/sdk-node": "^0.218.0", "@opentelemetry/sdk-trace-base": "^2.7.1", + "@pyroscope/nodejs": "^0.6.2", "@railgun-community/engine": "^9.4.0", "@scure/bip32": "^1.6.2", "@scure/bip39": "^1.5.4", diff --git a/src/__tests__/tracing.spec.ts b/src/__tests__/tracing.spec.ts index 424a36e058..b8290185c5 100644 --- a/src/__tests__/tracing.spec.ts +++ b/src/__tests__/tracing.spec.ts @@ -1,4 +1,6 @@ const mockStart = jest.fn(); +const mockPyroscopeInit = jest.fn(); +const mockStartWallProfiling = jest.fn(); jest.mock('@opentelemetry/sdk-node', () => ({ NodeSDK: jest.fn().mockImplementation(() => ({ start: mockStart })), @@ -9,10 +11,14 @@ jest.mock('@opentelemetry/auto-instrumentations-node', () => ({ jest.mock('@opentelemetry/exporter-trace-otlp-http', () => ({ OTLPTraceExporter: jest.fn(), })); +jest.mock('@pyroscope/nodejs', () => ({ + __esModule: true, + default: { init: mockPyroscopeInit, startWallProfiling: mockStartWallProfiling }, +})); import { SpanKind, SpanStatusCode } from '@opentelemetry/api'; import { ReadableSpan } from '@opentelemetry/sdk-trace-base'; -import { ClientErrorSpanProcessor, isClientError, startTracing } from '../tracing'; +import { ClientErrorSpanProcessor, isClientError, startProfiling, startTracing } from '../tracing'; function fakeSpan(kind: SpanKind, statusCode: SpanStatusCode, httpStatus?: number): ReadableSpan { return { @@ -89,3 +95,92 @@ describe('startTracing', () => { expect(mockStart).toHaveBeenCalledTimes(1); }); }); + +// Every case loads its own copy of the module: importing tracing.ts calls +// startProfiling() as a side effect, and the module latches `profiling` after +// the first successful start. A fresh registry per case keeps that latch — the +// thing being tested — from leaking between them. +describe('startProfiling', () => { + const originalAddress = process.env.PYROSCOPE_SERVER_ADDRESS; + const originalEnvironment = process.env.ENVIRONMENT; + + function loadTracing(): { startProfiling: () => boolean } { + let loaded: { startProfiling: () => boolean }; + jest.isolateModules(() => { + // require, not import: isolateModules is synchronous and the point is to + // re-execute the module body (and with it its start-up side effects). + // eslint-disable-next-line @typescript-eslint/no-require-imports + loaded = require('../tracing'); + }); + + return loaded; + } + + beforeEach(() => { + mockPyroscopeInit.mockReset(); + mockStartWallProfiling.mockReset(); + jest.spyOn(console, 'error').mockImplementation(() => undefined); + }); + + afterEach(() => { + jest.restoreAllMocks(); + + if (originalAddress === undefined) delete process.env.PYROSCOPE_SERVER_ADDRESS; + else process.env.PYROSCOPE_SERVER_ADDRESS = originalAddress; + + if (originalEnvironment === undefined) delete process.env.ENVIRONMENT; + else process.env.ENVIRONMENT = originalEnvironment; + }); + + it('is disabled (returns false) without PYROSCOPE_SERVER_ADDRESS', () => { + delete process.env.PYROSCOPE_SERVER_ADDRESS; + process.env.ENVIRONMENT = 'prd'; + + expect(startProfiling()).toBe(false); + expect(mockPyroscopeInit).not.toHaveBeenCalled(); + expect(mockStartWallProfiling).not.toHaveBeenCalled(); + }); + + it('starts the wall profiler with the environment tag and CPU time enabled', () => { + process.env.PYROSCOPE_SERVER_ADDRESS = 'http://localhost:4040'; + process.env.ENVIRONMENT = 'prd'; + + const tracing = loadTracing(); + + expect(mockPyroscopeInit).toHaveBeenCalledWith({ + appName: 'dfx-api', + serverAddress: 'http://localhost:4040', + tags: { env: 'prd' }, + wall: { collectCpuTime: true }, + }); + // Once for the module-level call, and not again on the explicit one: + // starting a second sampler would double the profiling cost. + expect(tracing.startProfiling()).toBe(true); + expect(mockStartWallProfiling).toHaveBeenCalledTimes(1); + }); + + it('reports the failure and keeps running when ENVIRONMENT is missing', () => { + process.env.PYROSCOPE_SERVER_ADDRESS = 'http://localhost:4040'; + delete process.env.ENVIRONMENT; + + const tracing = loadTracing(); + + expect(tracing.startProfiling()).toBe(false); + expect(mockStartWallProfiling).not.toHaveBeenCalled(); + expect(console.error).toHaveBeenCalled(); + }); + + it('reports the failure and keeps running when the SDK throws', () => { + process.env.PYROSCOPE_SERVER_ADDRESS = 'http://localhost:4040'; + process.env.ENVIRONMENT = 'prd'; + mockPyroscopeInit.mockImplementation(() => { + throw new Error('boom'); + }); + + const tracing = loadTracing(); + + expect(tracing.startProfiling()).toBe(false); + expect(mockStartWallProfiling).not.toHaveBeenCalled(); + expect(console.error).toHaveBeenCalled(); + }); +}); diff --git a/src/tracing.ts b/src/tracing.ts index 937f4f5fb1..9a03b46161 100644 --- a/src/tracing.ts +++ b/src/tracing.ts @@ -3,8 +3,9 @@ import { getNodeAutoInstrumentations } from '@opentelemetry/auto-instrumentation import { OTLPTraceExporter } from '@opentelemetry/exporter-trace-otlp-http'; import { NodeSDK } from '@opentelemetry/sdk-node'; import { BatchSpanProcessor, ReadableSpan, SpanProcessor } from '@opentelemetry/sdk-trace-base'; +import Pyroscope from '@pyroscope/nodejs'; -// OpenTelemetry tracing for dfx-api. +// OpenTelemetry tracing and continuous CPU profiling for dfx-api. // // This module is imported first in main.ts so the SDK starts before any // instrumented library (http, pg/TypeORM, …) is loaded — otherwise the @@ -13,8 +14,13 @@ import { BatchSpanProcessor, ReadableSpan, SpanProcessor } from '@opentelemetry/ // OTEL_EXPORTER_OTLP_ENDPOINT (no hardcoded collector address). When the // variable is unset, tracing is disabled and the app boots unchanged. // -// The exported helpers are pure and unit-tested; startTracing() has the side -// effect of registering the global SDK. +// Profiling follows the same rule with its own variable +// (PYROSCOPE_SERVER_ADDRESS) and answers a different question: tracing measures +// how long a request waited, profiling measures what burned the CPU while it +// ran. The two are independent — either can be enabled without the other. +// +// The exported helpers are pure and unit-tested; startTracing() and +// startProfiling() have the side effect of registering a global SDK. /** * HTTP 4xx (client error) check. @@ -87,4 +93,70 @@ export function startTracing(): NodeSDK | undefined { return sdk; } +let profiling = false; + +/** + * Starts continuous CPU profiling and returns whether the profiler is running. + * + * Disabled unless PYROSCOPE_SERVER_ADDRESS points at a Pyroscope instance, so + * LOC, tests and any environment without one boot untouched. + */ +export function startProfiling(): boolean { + if (!process.env.PYROSCOPE_SERVER_ADDRESS) return false; + if (profiling) return true; + + try { + // dev and prd push to the same Pyroscope, exactly as they push to the same + // Tempo, so the profiles need a label that tells them apart. ENVIRONMENT is + // the variable the rest of the app already keys off (see config.ts), which + // keeps this from becoming a second source of truth. Checked explicitly + // because the SDK would otherwise reject the undefined tag value with a + // message that says nothing about where it came from. + const environment = process.env.ENVIRONMENT; + if (!environment) throw new Error('ENVIRONMENT is not set — profiles could not be told apart per environment'); + + Pyroscope.init({ + // Becomes the service_name label Pyroscope indexes by; matches the OTel + // serviceName above so both signals name the same service. + appName: 'dfx-api', + serverAddress: process.env.PYROSCOPE_SERVER_ADDRESS, + tags: { env: environment }, + // Without collectCpuTime the wall profiler reports elapsed time, which + // for an event loop that is mostly waiting says little. With it, the + // `wall:cpu:nanoseconds:wall:nanoseconds` series carries actual CPU time + // — the series to chart. + // + // Sampling stays at the 100 Hz default on purpose. Measured on a + // CPU-saturated Node process, halving it to 50 Hz changed throughput by + // less than the run-to-run spread (-4.3 % vs -4.6 % against no profiler): + // the cost is in the sampler being installed at all, not in the sample + // rate, so turning it down buys resolution loss and nothing else. + wall: { collectCpuTime: true }, + }); + + // Wall/CPU only. Heap profiling is a second sampler with its own cost and + // is deliberately left off: this exists to attribute CPU time. Enable it + // via Pyroscope.startHeapProfiling() if allocation sites become the + // question. + Pyroscope.startWallProfiling(); + profiling = true; + + return true; + } catch (e) { + // The profiler is an observability extra; it must never be the reason the + // API fails to boot. Loud rather than silent: the line lands in Loki, and + // the absence of profiles in Grafana is the second signal. + // + // console is the only channel that exists here: this module runs before + // Nest is bootstrapped, so DfxLogger is not available, and OTel's diag + // logger is a no-op unless a sink is registered — which would turn a + // failure into silence. + // eslint-disable-next-line no-console + console.error('Continuous profiling disabled — Pyroscope failed to start:', e); + + return false; + } +} + startTracing(); +startProfiling();