From cb9dd3f1cbde6ce2fcb5b1c8b3f342032ff965f7 Mon Sep 17 00:00:00 2001 From: Francesco Novy Date: Tue, 28 May 2024 08:51:29 +0200 Subject: [PATCH 1/6] feat(metrics): Add `timing` method to metrics --- .../suites/metrics/metricsEvent/init.js | 17 ++ .../suites/metrics/metricsEvent/test.ts | 17 +- .../suites/metrics/timing/init.js | 39 +++++ .../suites/metrics/timing/test.ts | 161 ++++++++++++++++++ packages/browser/src/metrics.ts | 23 ++- packages/core/src/metrics/exports-default.ts | 24 ++- packages/core/src/metrics/exports.ts | 51 +++++- packages/core/test/lib/metrics/timing.test.ts | 110 ++++++++++++ packages/integration-shims/src/metrics.ts | 6 + packages/types/src/metrics.ts | 14 +- 10 files changed, 452 insertions(+), 10 deletions(-) create mode 100644 dev-packages/browser-integration-tests/suites/metrics/timing/init.js create mode 100644 dev-packages/browser-integration-tests/suites/metrics/timing/test.ts create mode 100644 packages/core/test/lib/metrics/timing.test.ts diff --git a/dev-packages/browser-integration-tests/suites/metrics/metricsEvent/init.js b/dev-packages/browser-integration-tests/suites/metrics/metricsEvent/init.js index 97182a9af6e7..878444f52a0a 100644 --- a/dev-packages/browser-integration-tests/suites/metrics/metricsEvent/init.js +++ b/dev-packages/browser-integration-tests/suites/metrics/metricsEvent/init.js @@ -15,3 +15,20 @@ Sentry.metrics.gauge('gauge', 5); Sentry.metrics.gauge('gauge', '15'); Sentry.metrics.set('set', 'nope'); Sentry.metrics.set('set', 'another'); + +Sentry.metrics.timing('timing', 99, 'hour'); +Sentry.metrics.timing('timingSync', () => { + sleepSync(200); +}); +Sentry.metrics.timing('timingAsync', async () => { + await new Promise(resolve => setTimeout(resolve, 200)); +}); + +function sleepSync(milliseconds) { + var start = new Date().getTime(); + for (var i = 0; i < 1e7; i++) { + if (new Date().getTime() - start > milliseconds) { + break; + } + } +} diff --git a/dev-packages/browser-integration-tests/suites/metrics/metricsEvent/test.ts b/dev-packages/browser-integration-tests/suites/metrics/metricsEvent/test.ts index 05a6d238be93..38b0139edad3 100644 --- a/dev-packages/browser-integration-tests/suites/metrics/metricsEvent/test.ts +++ b/dev-packages/browser-integration-tests/suites/metrics/metricsEvent/test.ts @@ -17,9 +17,18 @@ sentryTest('collects metrics', async ({ getLocalTestUrl, page }) => { const statsdBuffer = await getFirstSentryEnvelopeRequest(page, url, properEnvelopeRequestParser); const statsdString = new TextDecoder().decode(statsdBuffer); // Replace all the Txxxxxx to remove the timestamps - const normalisedStatsdString = statsdString.replace(/T\d+\n?/g, 'T000000'); + const normalisedStatsdString = statsdString.replace(/T\d+\n?/g, 'T000000').trim(); - expect(normalisedStatsdString).toEqual( - 'increment@none:6|c|T000000distribution@none:42:45|d|T000000gauge@none:15:5:15:20:2|g|T000000set@none:3387254:3443787523|s|T000000', - ); + const parts = normalisedStatsdString.split('T000000'); + + expect(parts).toEqual([ + 'increment@none:6|c|', + 'distribution@none:42:45|d|', + 'gauge@none:15:5:15:20:2|g|', + 'set@none:3387254:3443787523|s|', + 'timing@hour:99|d|', + expect.stringMatching(/timingSync@second:0.(\d+)\|d\|/), + expect.stringMatching(/timingAsync@second:0.(\d+)\|d\|/), + '', // trailing element + ]); }); diff --git a/dev-packages/browser-integration-tests/suites/metrics/timing/init.js b/dev-packages/browser-integration-tests/suites/metrics/timing/init.js new file mode 100644 index 000000000000..87f087b04ecf --- /dev/null +++ b/dev-packages/browser-integration-tests/suites/metrics/timing/init.js @@ -0,0 +1,39 @@ +import * as Sentry from '@sentry/browser'; + +window.Sentry = Sentry; + +Sentry.init({ + dsn: 'https://public@dsn.ingest.sentry.io/1337', + tracesSampleRate: 1.0, + release: '1.0.0', + autoSessionTracking: false, +}); + +window.timingSync = () => { + // Ensure we always have a wrapping span + return Sentry.startSpan({ name: 'manual span' }, () => { + return Sentry.metrics.timing('timingSync', () => { + sleepSync(200); + return 'sync done'; + }); + }); +}; + +window.timingAsync = () => { + // Ensure we always have a wrapping span + return Sentry.startSpan({ name: 'manual span' }, () => { + return Sentry.metrics.timing('timingAsync', async () => { + await new Promise(resolve => setTimeout(resolve, 200)); + return 'async done'; + }); + }); +}; + +function sleepSync(milliseconds) { + var start = new Date().getTime(); + for (var i = 0; i < 1e7; i++) { + if (new Date().getTime() - start > milliseconds) { + break; + } + } +} diff --git a/dev-packages/browser-integration-tests/suites/metrics/timing/test.ts b/dev-packages/browser-integration-tests/suites/metrics/timing/test.ts new file mode 100644 index 000000000000..822d9bcf07bd --- /dev/null +++ b/dev-packages/browser-integration-tests/suites/metrics/timing/test.ts @@ -0,0 +1,161 @@ +import { expect } from '@playwright/test'; + +import { sentryTest } from '../../../utils/fixtures'; +import { + envelopeRequestParser, + properEnvelopeRequestParser, + shouldSkipTracingTest, + waitForTransactionRequest, +} from '../../../utils/helpers'; + +sentryTest('allows to wrap sync methods with a timing metric', async ({ getLocalTestUrl, page }) => { + if (shouldSkipTracingTest()) { + sentryTest.skip(); + } + + await page.route('https://dsn.ingest.sentry.io/**/*', route => { + return route.fulfill({ + status: 200, + contentType: 'application/json', + body: JSON.stringify({ id: 'test-id' }), + }); + }); + + const url = await getLocalTestUrl({ testDir: __dirname }); + + const beforeTime = Math.floor(Date.now() / 1000); + + const metricsPromiseReq = page.waitForRequest(req => { + const postData = req.postData(); + if (!postData) { + return false; + } + + try { + // this implies this is a metrics envelope + return typeof envelopeRequestParser(req) === 'string'; + } catch { + return false; + } + }); + + const transactionPromise = waitForTransactionRequest(page); + + await page.goto(url); + await page.waitForFunction('typeof window.timingSync === "function"'); + const response = await page.evaluate('window.timingSync()'); + + expect(response).toBe('sync done'); + + const statsdString = envelopeRequestParser(await metricsPromiseReq); + const transactionEvent = properEnvelopeRequestParser(await transactionPromise); + + expect(typeof statsdString).toEqual('string'); + + const parsedStatsd = /timingSync@second:(0\.\d+)\|d\|#(.+)\|T(\d+)/.exec(statsdString); + + expect(parsedStatsd).toBeTruthy(); + + const duration = parseFloat(parsedStatsd![1]); + const tags = parsedStatsd![2]; + const timestamp = parseInt(parsedStatsd![3], 10); + + expect(timestamp).toBeGreaterThanOrEqual(beforeTime); + expect(tags).toEqual('release:1.0.0,transaction:manual span'); + expect(duration).toBeGreaterThan(0.2); + expect(duration).toBeLessThan(1); + + expect(transactionEvent).toBeDefined(); + expect(transactionEvent.transaction).toEqual('manual span'); + // @ts-expect-error this is fine... + expect(transactionEvent._metrics_summary).toEqual({ + 'd:timingSync@second': [ + { + count: 1, + max: duration, + min: duration, + sum: duration, + tags: { + release: '1.0.0', + transaction: 'manual span', + }, + }, + ], + }); +}); + +sentryTest('allows to wrap async methods with a timing metric', async ({ getLocalTestUrl, page }) => { + if (shouldSkipTracingTest()) { + sentryTest.skip(); + } + + await page.route('https://dsn.ingest.sentry.io/**/*', route => { + return route.fulfill({ + status: 200, + contentType: 'application/json', + body: JSON.stringify({ id: 'test-id' }), + }); + }); + + const url = await getLocalTestUrl({ testDir: __dirname }); + + const beforeTime = Math.floor(Date.now() / 1000); + + const metricsPromiseReq = page.waitForRequest(req => { + const postData = req.postData(); + if (!postData) { + return false; + } + + try { + // this implies this is a metrics envelope + return typeof envelopeRequestParser(req) === 'string'; + } catch { + return false; + } + }); + + const transactionPromise = waitForTransactionRequest(page); + + await page.goto(url); + await page.waitForFunction('typeof window.timingAsync === "function"'); + const response = await page.evaluate('window.timingAsync()'); + + expect(response).toBe('async done'); + + const statsdString = envelopeRequestParser(await metricsPromiseReq); + const transactionEvent = properEnvelopeRequestParser(await transactionPromise); + + expect(typeof statsdString).toEqual('string'); + + const parsedStatsd = /timingAsync@second:(0\.\d+)\|d\|#(.+)\|T(\d+)/.exec(statsdString); + + expect(parsedStatsd).toBeTruthy(); + + const duration = parseFloat(parsedStatsd![1]); + const tags = parsedStatsd![2]; + const timestamp = parseInt(parsedStatsd![3], 10); + + expect(timestamp).toBeGreaterThanOrEqual(beforeTime); + expect(tags).toEqual('release:1.0.0,transaction:manual span'); + expect(duration).toBeGreaterThan(0.2); + expect(duration).toBeLessThan(1); + + expect(transactionEvent).toBeDefined(); + expect(transactionEvent.transaction).toEqual('manual span'); + // @ts-expect-error this is fine... + expect(transactionEvent._metrics_summary).toEqual({ + 'd:timingAsync@second': [ + { + count: 1, + max: duration, + min: duration, + sum: duration, + tags: { + release: '1.0.0', + transaction: 'manual span', + }, + }, + ], + }); +}); diff --git a/packages/browser/src/metrics.ts b/packages/browser/src/metrics.ts index 267fe90d03c9..3e2825e3e45c 100644 --- a/packages/browser/src/metrics.ts +++ b/packages/browser/src/metrics.ts @@ -1,5 +1,5 @@ import { BrowserMetricsAggregator, metrics as metricsCore } from '@sentry/core'; -import type { MetricData, Metrics } from '@sentry/types'; +import type { MetricData, Metrics, DurationUnit } from '@sentry/types'; /** * Adds a value to a counter metric @@ -37,9 +37,30 @@ function gauge(name: string, value: number, data?: MetricData): void { metricsCore.gauge(BrowserMetricsAggregator, name, value, data); } +/** + * Adds a timing metric. + * The metric is added as a distribution metric. + * + * You can either directly capture a numeric `value`, or wrap a callback function in `timing`. + * In the latter case, the duration of the callback execution will be captured as a span & a metric. + * + * @experimental This API is experimental and might have breaking changes in the future. + */ +function timing(name: string, value: number, unit?: DurationUnit, data?: Omit): void; +function timing(name: string, callback: () => T, unit?: DurationUnit, data?: Omit): T; +function timing( + name: string, + value: number | (() => T), + unit: DurationUnit = 'second', + data?: Omit, +): T | void { + return metricsCore.timing(BrowserMetricsAggregator, name, value, unit, data); +} + export const metrics: Metrics = { increment, distribution, set, gauge, + timing, }; diff --git a/packages/core/src/metrics/exports-default.ts b/packages/core/src/metrics/exports-default.ts index 86d294d059d8..e118d8bb3985 100644 --- a/packages/core/src/metrics/exports-default.ts +++ b/packages/core/src/metrics/exports-default.ts @@ -1,4 +1,4 @@ -import type { Client, MetricData, Metrics, MetricsAggregator as MetricsAggregatorInterface } from '@sentry/types'; +import type { Client, MetricData, Metrics, DurationUnit, MetricsAggregator as MetricsAggregatorInterface } from '@sentry/types'; import { MetricsAggregator } from './aggregator'; import { metrics as metricsCore } from './exports'; @@ -38,6 +38,26 @@ function gauge(name: string, value: number, data?: MetricData): void { metricsCore.gauge(MetricsAggregator, name, value, data); } +/** + * Adds a timing metric. + * The metric is added as a distribution metric. + * + * You can either directly capture a numeric `value`, or wrap a callback function in `timing`. + * In the latter case, the duration of the callback execution will be captured as a span & a metric. + * + * @experimental This API is experimental and might have breaking changes in the future. + */ +function timing(name: string, value: number, unit?: DurationUnit, data?: Omit): void; +function timing(name: string, callback: () => T, unit?: DurationUnit, data?: Omit): T; +function timing( + name: string, + value: number | (() => T), + unit: DurationUnit = 'second', + data?: Omit, +): T | void { + return metricsCore.timing(MetricsAggregator, name, value, unit, data); +} + /** * Returns the metrics aggregator for a given client. */ @@ -52,7 +72,7 @@ export const metricsDefault: Metrics & { distribution, set, gauge, - + timing, /** * @ignore This is for internal use only. */ diff --git a/packages/core/src/metrics/exports.ts b/packages/core/src/metrics/exports.ts index 665ac9c12816..8e698210af15 100644 --- a/packages/core/src/metrics/exports.ts +++ b/packages/core/src/metrics/exports.ts @@ -1,7 +1,9 @@ -import type { Client, MetricData, MetricsAggregator as MetricsAggregatorInterface } from '@sentry/types'; -import { getGlobalSingleton, logger } from '@sentry/utils'; +import type { Client, DurationUnit, MetricData, MetricsAggregator as MetricsAggregatorInterface } from '@sentry/types'; +import { getGlobalSingleton, logger, timestampInSeconds } from '@sentry/utils'; import { getClient } from '../currentScopes'; import { DEBUG_BUILD } from '../debug-build'; +import { startInactiveSpan } from '../tracing'; +import { handleCallbackErrors } from '../utils/handleCallbackErrors'; import { getActiveSpan, getRootSpan, spanToJSON } from '../utils/spanUtils'; import { COUNTER_METRIC_TYPE, DISTRIBUTION_METRIC_TYPE, GAUGE_METRIC_TYPE, SET_METRIC_TYPE } from './constants'; import type { MetricType } from './types'; @@ -90,6 +92,50 @@ function distribution(aggregator: MetricsAggregatorConstructor, name: string, va addToMetricsAggregator(aggregator, DISTRIBUTION_METRIC_TYPE, name, ensureNumber(value), data); } +/** + * Adds a timing metric. + * The metric is added as a distribution metric. + * + * You can either directly capture a numeric `value`, or wrap a callback function in `timing`. + * In the latter case, the duration of the callback execution will be captured as a span & a metric. + * + * @experimental This API is experimental and might have breaking changes in the future. + */ +function timing( + aggregator: MetricsAggregatorConstructor, + name: string, + value: number | (() => T), + unit: DurationUnit = 'second', + data?: Omit, +): T | void { + // callback form + if (typeof value === 'function') { + const startTime = timestampInSeconds(); + const span = startInactiveSpan({ + op: 'metrics.timing', + name, + startTime, + onlyIfParent: true, + }); + + return handleCallbackErrors( + () => value(), + () => { + // no special error handling necessary + }, + () => { + const endTime = timestampInSeconds(); + const timeDiff = endTime - startTime; + distribution(aggregator, name, timeDiff, { ...data, unit: 'second' }); + span.end(endTime); + }, + ); + } + + // value form + distribution(aggregator, name, value, { ...data, unit }); +} + /** * Adds a value to a set metric. Value must be a string or integer. * @@ -113,6 +159,7 @@ export const metrics = { distribution, set, gauge, + timing, /** * @ignore This is for internal use only. */ diff --git a/packages/core/test/lib/metrics/timing.test.ts b/packages/core/test/lib/metrics/timing.test.ts new file mode 100644 index 000000000000..4e796ecaeb27 --- /dev/null +++ b/packages/core/test/lib/metrics/timing.test.ts @@ -0,0 +1,110 @@ +import { getCurrentScope, getIsolationScope, setCurrentClient } from '../../../src'; +import { MetricsAggregator } from '../../../src/metrics/aggregator'; +import { metrics as metricsCore } from '../../../src/metrics/exports'; +import { metricsDefault } from '../../../src/metrics/exports-default'; +import { TestClient, getDefaultTestClientOptions } from '../../mocks/client'; + +const PUBLIC_DSN = 'https://username@domain/123'; + +describe('metrics.timing', () => { + let testClient: TestClient; + const options = getDefaultTestClientOptions({ + dsn: PUBLIC_DSN, + tracesSampleRate: 0.0, + }); + + beforeEach(() => { + jest.useFakeTimers('legacy'); + testClient = new TestClient(options); + setCurrentClient(testClient); + }); + + afterEach(() => { + getCurrentScope().setClient(undefined); + getCurrentScope().clear(); + getIsolationScope().clear(); + }); + + it('works with minimal data', async () => { + const res = metricsDefault.timing('t1', 10); + expect(res).toStrictEqual(undefined); + + const sendSpy = jest.spyOn(testClient.getTransport()!, 'send'); + + metricsCore.getMetricsAggregatorForClient(testClient, MetricsAggregator)!.flush(); + + expect(sendSpy).toHaveBeenCalledTimes(1); + expect(sendSpy).toHaveBeenCalledWith([ + { sent_at: expect.any(String) }, + [[{ length: expect.any(Number), type: 'statsd' }, expect.stringMatching(/t1@second:10\|d\|T(\d+)/)]], + ]); + }); + + it('allows to define a unit', async () => { + const res = metricsDefault.timing('t1', 10, 'hour'); + expect(res).toStrictEqual(undefined); + + const sendSpy = jest.spyOn(testClient.getTransport()!, 'send'); + + metricsCore.getMetricsAggregatorForClient(testClient, MetricsAggregator)!.flush(); + + expect(sendSpy).toHaveBeenCalledTimes(1); + expect(sendSpy).toHaveBeenCalledWith([ + { sent_at: expect.any(String) }, + [[{ length: expect.any(Number), type: 'statsd' }, expect.stringMatching(/t1@hour:10\|d\|T(\d+)/)]], + ]); + }); + + it('allows to define data', async () => { + const res = metricsDefault.timing('t1', 10, 'hour', { + tags: { tag1: 'value1', tag2: 'value2' }, + }); + expect(res).toStrictEqual(undefined); + + const sendSpy = jest.spyOn(testClient.getTransport()!, 'send'); + + metricsCore.getMetricsAggregatorForClient(testClient, MetricsAggregator)!.flush(); + + expect(sendSpy).toHaveBeenCalledTimes(1); + expect(sendSpy).toHaveBeenCalledWith([ + { sent_at: expect.any(String) }, + [ + [ + { length: expect.any(Number), type: 'statsd' }, + expect.stringMatching(/t1@hour:10\|d|#tag1:value1,tag2:value2\|T(\d+)/), + ], + ], + ]); + }); + + it('works with a sync callback', async () => { + const res = metricsDefault.timing('t1', () => 'oho'); + expect(res).toStrictEqual('oho'); + + const sendSpy = jest.spyOn(testClient.getTransport()!, 'send'); + + metricsCore.getMetricsAggregatorForClient(testClient, MetricsAggregator)!.flush(); + + expect(sendSpy).toHaveBeenCalledTimes(1); + expect(sendSpy).toHaveBeenCalledWith([ + { sent_at: expect.any(String) }, + [[{ length: expect.any(Number), type: 'statsd' }, expect.stringMatching(/t1@second:(0.\d+)\|d\|T(\d+)/)]], + ]); + }); + + it('works with an async callback', async () => { + const res = metricsDefault.timing('t1', async () => 'oho'); + expect(res).toBeInstanceOf(Promise); + expect(await res).toStrictEqual('oho'); + + const sendSpy = jest.spyOn(testClient.getTransport()!, 'send'); + + metricsCore.getMetricsAggregatorForClient(testClient, MetricsAggregator)!.flush(); + + expect(sendSpy).toHaveBeenCalledTimes(1); + expect(sendSpy).toHaveBeenCalledWith([ + { sent_at: expect.any(String) }, + [[{ length: expect.any(Number), type: 'statsd' }, expect.stringMatching(/t1@second:(0.\d+)\|d\|T(\d+)/)]], + ]); + }); +}); diff --git a/packages/integration-shims/src/metrics.ts b/packages/integration-shims/src/metrics.ts index 9af425e0f629..3f2414742501 100644 --- a/packages/integration-shims/src/metrics.ts +++ b/packages/integration-shims/src/metrics.ts @@ -13,4 +13,10 @@ export const metricsShim: Metrics = { distribution: warn, set: warn, gauge: warn, + timing: (_name: unknown, value: number | (() => unknown)) => { + warn(); + if (typeof value === 'function') { + return value(); + } + }, }; diff --git a/packages/types/src/metrics.ts b/packages/types/src/metrics.ts index 843068db0aef..474f5b94c207 100644 --- a/packages/types/src/metrics.ts +++ b/packages/types/src/metrics.ts @@ -1,5 +1,5 @@ import type { Client } from './client'; -import type { MeasurementUnit } from './measurement'; +import type { DurationUnit, MeasurementUnit } from './measurement'; import type { Primitive } from './misc'; export interface MetricData { @@ -99,4 +99,16 @@ export interface Metrics { * @experimental This API is experimental and might have breaking changes in the future. */ gauge(name: string, value: number, data?: MetricData): void; + + /** + * Adds a timing metric. + * The metric is added as a distribution metric. + * + * You can either directly capture a numeric `value`, or wrap a callback function in `timing`. + * In the latter case, the duration of the callback execution will be captured as a span & a metric. + * + * @experimental This API is experimental and might have breaking changes in the future. + */ + timing(name: string, value: number, unit?: DurationUnit, data?: Omit): void; + timing(name: string, callback: () => T, unit?: DurationUnit, data?: Omit): T; } From 567829766a1f236dfd80371ad6a2136b26fa5a3f Mon Sep 17 00:00:00 2001 From: Francesco Novy Date: Tue, 28 May 2024 09:40:58 +0200 Subject: [PATCH 2/6] fix linting --- packages/browser/src/metrics.ts | 2 +- packages/core/src/metrics/exports-default.ts | 8 +++++++- 2 files changed, 8 insertions(+), 2 deletions(-) diff --git a/packages/browser/src/metrics.ts b/packages/browser/src/metrics.ts index 3e2825e3e45c..39529af3e4a0 100644 --- a/packages/browser/src/metrics.ts +++ b/packages/browser/src/metrics.ts @@ -1,5 +1,5 @@ import { BrowserMetricsAggregator, metrics as metricsCore } from '@sentry/core'; -import type { MetricData, Metrics, DurationUnit } from '@sentry/types'; +import type { DurationUnit, MetricData, Metrics } from '@sentry/types'; /** * Adds a value to a counter metric diff --git a/packages/core/src/metrics/exports-default.ts b/packages/core/src/metrics/exports-default.ts index e118d8bb3985..1e4a6487b9a2 100644 --- a/packages/core/src/metrics/exports-default.ts +++ b/packages/core/src/metrics/exports-default.ts @@ -1,4 +1,10 @@ -import type { Client, MetricData, Metrics, DurationUnit, MetricsAggregator as MetricsAggregatorInterface } from '@sentry/types'; +import type { + Client, + DurationUnit, + MetricData, + Metrics, + MetricsAggregator as MetricsAggregatorInterface, +} from '@sentry/types'; import { MetricsAggregator } from './aggregator'; import { metrics as metricsCore } from './exports'; From f6442a5f2d9a0dcbd3c3d739e0febc4b22b5dfbd Mon Sep 17 00:00:00 2001 From: Francesco Novy Date: Tue, 28 May 2024 11:13:15 +0200 Subject: [PATCH 3/6] fix test --- packages/core/test/lib/metrics/timing.test.ts | 20 ++++++++++++++++--- 1 file changed, 17 insertions(+), 3 deletions(-) diff --git a/packages/core/test/lib/metrics/timing.test.ts b/packages/core/test/lib/metrics/timing.test.ts index 4e796ecaeb27..fa7c9f88da77 100644 --- a/packages/core/test/lib/metrics/timing.test.ts +++ b/packages/core/test/lib/metrics/timing.test.ts @@ -14,7 +14,6 @@ describe('metrics.timing', () => { }); beforeEach(() => { - jest.useFakeTimers('legacy'); testClient = new TestClient(options); setCurrentClient(testClient); }); @@ -78,7 +77,10 @@ describe('metrics.timing', () => { }); it('works with a sync callback', async () => { - const res = metricsDefault.timing('t1', () => 'oho'); + const res = metricsDefault.timing('t1', () => { + sleepSync(200); + return 'oho'; + }); expect(res).toStrictEqual('oho'); const sendSpy = jest.spyOn(testClient.getTransport()!, 'send'); @@ -93,7 +95,10 @@ describe('metrics.timing', () => { }); it('works with an async callback', async () => { - const res = metricsDefault.timing('t1', async () => 'oho'); + const res = metricsDefault.timing('t1', async () => { + await new Promise(resolve => setTimeout(resolve, 200)); + return 'oho'; + }); expect(res).toBeInstanceOf(Promise); expect(await res).toStrictEqual('oho'); @@ -108,3 +113,12 @@ describe('metrics.timing', () => { ]); }); }); + +function sleepSync(milliseconds: number): void { + const start = Date.now(); + for (let i = 0; i < 1e7; i++) { + if (new Date().getTime() - start > milliseconds) { + break; + } + } +} From 3ca7f7d7b0b5d086bf3c42258563a283031ba36e Mon Sep 17 00:00:00 2001 From: Francesco Novy Date: Tue, 28 May 2024 11:13:20 +0200 Subject: [PATCH 4/6] avoid weak map & fix minification --- .../rollup-utils/plugins/bundlePlugins.mjs | 3 +++ packages/core/src/metrics/metric-summary.ts | 21 ++++++++----------- 2 files changed, 12 insertions(+), 12 deletions(-) diff --git a/dev-packages/rollup-utils/plugins/bundlePlugins.mjs b/dev-packages/rollup-utils/plugins/bundlePlugins.mjs index 169062694d24..760fdc05daa6 100644 --- a/dev-packages/rollup-utils/plugins/bundlePlugins.mjs +++ b/dev-packages/rollup-utils/plugins/bundlePlugins.mjs @@ -121,7 +121,10 @@ export function makeTerserPlugin() { // These are used by instrument.ts in utils for identifying HTML elements & events '_sentryCaptured', '_sentryId', + // Keeps the frozen DSC on a Sentry Span '_frozenDsc', + // This keeps metrics summary on spans + '_metrics_summary', // These are used to keep span & scope relationships '_sentryRootSpan', '_sentryChildSpans', diff --git a/packages/core/src/metrics/metric-summary.ts b/packages/core/src/metrics/metric-summary.ts index f1324def357d..c8672bed8bc6 100644 --- a/packages/core/src/metrics/metric-summary.ts +++ b/packages/core/src/metrics/metric-summary.ts @@ -10,17 +10,17 @@ import type { MetricType } from './types'; */ type MetricSummaryStorage = Map; -let SPAN_METRIC_SUMMARY: WeakMap | undefined; +const METRICS_SPAN_FIELD = '_sentryMetrics'; -function getMetricStorageForSpan(span: Span): MetricSummaryStorage | undefined { - return SPAN_METRIC_SUMMARY ? SPAN_METRIC_SUMMARY.get(span) : undefined; -} +type SpanWithPotentialMetrics = Span & { + [METRICS_SPAN_FIELD]?: MetricSummaryStorage; +}; /** * Fetches the metric summary if it exists for the passed span */ export function getMetricSummaryJsonForSpan(span: Span): Record> | undefined { - const storage = getMetricStorageForSpan(span); + const storage = (span as SpanWithPotentialMetrics)[METRICS_SPAN_FIELD]; if (!storage) { return undefined; @@ -50,7 +50,10 @@ export function updateMetricSummaryOnSpan( tags: Record, bucketKey: string, ): void { - const storage = getMetricStorageForSpan(span) || new Map(); + const existingStorage = (span as SpanWithPotentialMetrics)[METRICS_SPAN_FIELD]; + const storage = + existingStorage || + ((span as SpanWithPotentialMetrics)[METRICS_SPAN_FIELD] = new Map()); const exportKey = `${metricType}:${sanitizedName}@${unit}`; const bucketItem = storage.get(bucketKey); @@ -79,10 +82,4 @@ export function updateMetricSummaryOnSpan( }, ]); } - - if (!SPAN_METRIC_SUMMARY) { - SPAN_METRIC_SUMMARY = new WeakMap(); - } - - SPAN_METRIC_SUMMARY.set(span, storage); } From d51e78733e6f68ce38d8f4cd64901d907610c3f9 Mon Sep 17 00:00:00 2001 From: Francesco Novy Date: Tue, 28 May 2024 15:40:09 +0200 Subject: [PATCH 5/6] make span active --- packages/core/src/metrics/exports.ts | 38 +++++++++++++++------------- 1 file changed, 21 insertions(+), 17 deletions(-) diff --git a/packages/core/src/metrics/exports.ts b/packages/core/src/metrics/exports.ts index 8e698210af15..711cf5afc8ab 100644 --- a/packages/core/src/metrics/exports.ts +++ b/packages/core/src/metrics/exports.ts @@ -2,7 +2,7 @@ import type { Client, DurationUnit, MetricData, MetricsAggregator as MetricsAggr import { getGlobalSingleton, logger, timestampInSeconds } from '@sentry/utils'; import { getClient } from '../currentScopes'; import { DEBUG_BUILD } from '../debug-build'; -import { startInactiveSpan } from '../tracing'; +import { startSpanManual } from '../tracing'; import { handleCallbackErrors } from '../utils/handleCallbackErrors'; import { getActiveSpan, getRootSpan, spanToJSON } from '../utils/spanUtils'; import { COUNTER_METRIC_TYPE, DISTRIBUTION_METRIC_TYPE, GAUGE_METRIC_TYPE, SET_METRIC_TYPE } from './constants'; @@ -111,23 +111,27 @@ function timing( // callback form if (typeof value === 'function') { const startTime = timestampInSeconds(); - const span = startInactiveSpan({ - op: 'metrics.timing', - name, - startTime, - onlyIfParent: true, - }); - - return handleCallbackErrors( - () => value(), - () => { - // no special error handling necessary + + return startSpanManual( + { + op: 'metrics.timing', + name, + startTime, + onlyIfParent: true, }, - () => { - const endTime = timestampInSeconds(); - const timeDiff = endTime - startTime; - distribution(aggregator, name, timeDiff, { ...data, unit: 'second' }); - span.end(endTime); + span => { + return handleCallbackErrors( + () => value(), + () => { + // no special error handling necessary + }, + () => { + const endTime = timestampInSeconds(); + const timeDiff = endTime - startTime; + distribution(aggregator, name, timeDiff, { ...data, unit: 'second' }); + span.end(endTime); + }, + ); }, ); } From 337e346693bff453b0960c3afa2f5ff4a5a791de Mon Sep 17 00:00:00 2001 From: Francesco Novy Date: Tue, 28 May 2024 16:02:31 +0200 Subject: [PATCH 6/6] fix tests --- .../suites/metrics/timing/test.ts | 22 +++++++++++++++---- packages/core/src/metrics/exports.ts | 5 +++-- 2 files changed, 21 insertions(+), 6 deletions(-) diff --git a/dev-packages/browser-integration-tests/suites/metrics/timing/test.ts b/dev-packages/browser-integration-tests/suites/metrics/timing/test.ts index 822d9bcf07bd..c6b369025c7a 100644 --- a/dev-packages/browser-integration-tests/suites/metrics/timing/test.ts +++ b/dev-packages/browser-integration-tests/suites/metrics/timing/test.ts @@ -67,8 +67,15 @@ sentryTest('allows to wrap sync methods with a timing metric', async ({ getLocal expect(transactionEvent).toBeDefined(); expect(transactionEvent.transaction).toEqual('manual span'); - // @ts-expect-error this is fine... - expect(transactionEvent._metrics_summary).toEqual({ + + const spans = transactionEvent.spans || []; + + expect(spans.length).toBe(1); + const span = spans[0]; + expect(span.op).toEqual('metrics.timing'); + expect(span.description).toEqual('timingSync'); + expect(span.timestamp! - span.start_timestamp).toEqual(duration); + expect(span._metrics_summary).toEqual({ 'd:timingSync@second': [ { count: 1, @@ -143,8 +150,15 @@ sentryTest('allows to wrap async methods with a timing metric', async ({ getLoca expect(transactionEvent).toBeDefined(); expect(transactionEvent.transaction).toEqual('manual span'); - // @ts-expect-error this is fine... - expect(transactionEvent._metrics_summary).toEqual({ + + const spans = transactionEvent.spans || []; + + expect(spans.length).toBe(1); + const span = spans[0]; + expect(span.op).toEqual('metrics.timing'); + expect(span.description).toEqual('timingAsync'); + expect(span.timestamp! - span.start_timestamp).toEqual(duration); + expect(span._metrics_summary).toEqual({ 'd:timingAsync@second': [ { count: 1, diff --git a/packages/core/src/metrics/exports.ts b/packages/core/src/metrics/exports.ts index 711cf5afc8ab..752471856153 100644 --- a/packages/core/src/metrics/exports.ts +++ b/packages/core/src/metrics/exports.ts @@ -54,6 +54,7 @@ function addToMetricsAggregator( const span = getActiveSpan(); const rootSpan = span ? getRootSpan(span) : undefined; + const transactionName = rootSpan && spanToJSON(rootSpan).description; const { unit, tags, timestamp } = data; const { release, environment } = client.getOptions(); @@ -64,8 +65,8 @@ function addToMetricsAggregator( if (environment) { metricTags.environment = environment; } - if (rootSpan) { - metricTags.transaction = spanToJSON(rootSpan).description || ''; + if (transactionName) { + metricTags.transaction = transactionName; } DEBUG_BUILD && logger.log(`Adding value of ${value} to ${metricType} metric ${name}`);