From d9a6dba6190e34215219336ba4e4e60bc9e7c800 Mon Sep 17 00:00:00 2001 From: Andrey Sobolev Date: Fri, 10 Oct 2025 21:13:30 +0700 Subject: [PATCH] Add tests for measurement and understand overhead --- .github/workflows/ci.yml | 2 + .../main_2025-10-10-14-14.json | 10 + .../measurements/main_2025-10-10-14-14.json | 10 + .../platform-rig/main_2025-10-10-14-14.json | 10 + .../postgres-base/main_2025-10-10-14-14.json | 10 + .../src/__tests__/telemetry.test.ts | 465 ++++++++++++++++++ .../src/__tests__/context.test.ts | 451 +++++++++++++++++ .../measurements/src/__tests__/index.test.ts | 47 ++ .../src/__tests__/metrics.test.ts | 297 +++++++++++ .../src/__tests__/performance.test.ts | 259 ++++++++++ 10 files changed, 1561 insertions(+) create mode 100644 common/changes/@hcengineering/measurements-otlp/main_2025-10-10-14-14.json create mode 100644 common/changes/@hcengineering/measurements/main_2025-10-10-14-14.json create mode 100644 common/changes/@hcengineering/platform-rig/main_2025-10-10-14-14.json create mode 100644 common/changes/@hcengineering/postgres-base/main_2025-10-10-14-14.json create mode 100644 packages/measurements-otlp/src/__tests__/telemetry.test.ts create mode 100644 packages/measurements/src/__tests__/context.test.ts create mode 100644 packages/measurements/src/__tests__/index.test.ts create mode 100644 packages/measurements/src/__tests__/metrics.test.ts create mode 100644 packages/measurements/src/__tests__/performance.test.ts diff --git a/.github/workflows/ci.yml b/.github/workflows/ci.yml index 106a1b21c2..14a261a995 100644 --- a/.github/workflows/ci.yml +++ b/.github/workflows/ci.yml @@ -24,6 +24,8 @@ jobs: run: node common/scripts/install-run-rush.js install - name: Rush validate run: node common/scripts/install-run-rush.js validate --verbose + - name: Rush test + run: node common/scripts/install-run-rush.js test --verbose - name: Publish packages if: startsWith(github.ref, 'refs/tags/v0.7.') env: diff --git a/common/changes/@hcengineering/measurements-otlp/main_2025-10-10-14-14.json b/common/changes/@hcengineering/measurements-otlp/main_2025-10-10-14-14.json new file mode 100644 index 0000000000..2f15c7c742 --- /dev/null +++ b/common/changes/@hcengineering/measurements-otlp/main_2025-10-10-14-14.json @@ -0,0 +1,10 @@ +{ + "changes": [ + { + "packageName": "@hcengineering/measurements-otlp", + "comment": "Add tests", + "type": "none" + } + ], + "packageName": "@hcengineering/measurements-otlp" +} \ No newline at end of file diff --git a/common/changes/@hcengineering/measurements/main_2025-10-10-14-14.json b/common/changes/@hcengineering/measurements/main_2025-10-10-14-14.json new file mode 100644 index 0000000000..e0b4688e14 --- /dev/null +++ b/common/changes/@hcengineering/measurements/main_2025-10-10-14-14.json @@ -0,0 +1,10 @@ +{ + "changes": [ + { + "packageName": "@hcengineering/measurements", + "comment": "Add tests", + "type": "none" + } + ], + "packageName": "@hcengineering/measurements" +} \ No newline at end of file diff --git a/common/changes/@hcengineering/platform-rig/main_2025-10-10-14-14.json b/common/changes/@hcengineering/platform-rig/main_2025-10-10-14-14.json new file mode 100644 index 0000000000..910ac32792 --- /dev/null +++ b/common/changes/@hcengineering/platform-rig/main_2025-10-10-14-14.json @@ -0,0 +1,10 @@ +{ + "changes": [ + { + "packageName": "@hcengineering/platform-rig", + "comment": "", + "type": "none" + } + ], + "packageName": "@hcengineering/platform-rig" +} \ No newline at end of file diff --git a/common/changes/@hcengineering/postgres-base/main_2025-10-10-14-14.json b/common/changes/@hcengineering/postgres-base/main_2025-10-10-14-14.json new file mode 100644 index 0000000000..471a48b322 --- /dev/null +++ b/common/changes/@hcengineering/postgres-base/main_2025-10-10-14-14.json @@ -0,0 +1,10 @@ +{ + "changes": [ + { + "packageName": "@hcengineering/postgres-base", + "comment": "", + "type": "none" + } + ], + "packageName": "@hcengineering/postgres-base" +} \ No newline at end of file diff --git a/packages/measurements-otlp/src/__tests__/telemetry.test.ts b/packages/measurements-otlp/src/__tests__/telemetry.test.ts new file mode 100644 index 0000000000..bd6aafa63a --- /dev/null +++ b/packages/measurements-otlp/src/__tests__/telemetry.test.ts @@ -0,0 +1,465 @@ +import { OpenTelemetryMetricsContext } from '../telemetry' +import { newMetrics, type MeasureLogger } from '@hcengineering/measurements' +import { trace, context, SpanStatusCode } from '@opentelemetry/api' +import { NodeTracerProvider } from '@opentelemetry/sdk-trace-node' + +describe('telemetry', () => { + let tracer: any + let provider: NodeTracerProvider + + beforeAll(() => { + provider = new NodeTracerProvider() + provider.register() + tracer = trace.getTracer('test-tracer') + }) + + afterAll(() => { + provider.shutdown() + }) + + describe('OpenTelemetryMetricsContext', () => { + const mockLogger: MeasureLogger = { + info: jest.fn(), + error: jest.fn(), + warn: jest.fn(), + close: jest.fn(async () => {}), + logOperation: jest.fn() + } + + beforeEach(() => { + jest.clearAllMocks() + }) + + it('should create a new context with tracer', () => { + const metrics = newMetrics() + const ctx = new OpenTelemetryMetricsContext( + 'test', + tracer, + undefined, + undefined, + { op: 'create' }, + {}, + metrics, + mockLogger + ) + + expect(ctx).toBeDefined() + expect(ctx.metrics).toBe(metrics) + expect(ctx.logger).toBe(mockLogger) + }) + + it('should create child context with span', () => { + const metrics = newMetrics() + const ctx = new OpenTelemetryMetricsContext( + 'parent', + tracer, + context.active(), + undefined, + {}, + {}, + metrics, + mockLogger + ) + + const child = ctx.newChild('child', { op: 'child' }, { span: true }) + + expect(child).toBeDefined() + expect(child.parent).toBe(ctx) + }) + + it('should create child context without span when span is false', () => { + const metrics = newMetrics() + const ctx = new OpenTelemetryMetricsContext( + 'parent', + tracer, + context.active(), + undefined, + {}, + {}, + metrics, + mockLogger + ) + + const child = ctx.newChild('child', { op: 'child' }, { span: false }) + + expect(child).toBeDefined() + }) + + it('should execute async operation with context', async () => { + const metrics = newMetrics() + const ctx = new OpenTelemetryMetricsContext( + 'test', + tracer, + context.active(), + undefined, + {}, + {}, + metrics, + mockLogger + ) + + let executed = false + await ctx.with('operation', { op: 'test' }, async () => { + executed = true + await new Promise(resolve => setTimeout(resolve, 10)) + }) + + expect(executed).toBe(true) + expect(metrics.measurements.operation).toBeDefined() + }) + + it('should execute sync operation with context', () => { + const metrics = newMetrics() + const ctx = new OpenTelemetryMetricsContext( + 'test', + tracer, + context.active(), + undefined, + {}, + {}, + metrics, + mockLogger + ) + + const result = ctx.withSync('operation', { op: 'test' }, () => { + return 42 + }) + + expect(result).toBe(42) + expect(metrics.measurements.operation).toBeDefined() + }) + + it('should handle errors in async operations', async () => { + const metrics = newMetrics() + const span = tracer.startSpan('test-span') + const ctx = new OpenTelemetryMetricsContext( + 'test', + tracer, + context.active(), + span, + {}, + {}, + metrics, + mockLogger + ) + + await expect( + ctx.with('operation', { op: 'test' }, async () => { + throw new Error('Test error') + }) + ).rejects.toThrow('Test error') + + expect(metrics.measurements.operation).toBeDefined() + }) + + it('should measure custom value with meter', () => { + const metrics = newMetrics() + const mockMeter = { + getCounter: jest.fn(() => ({ + counter: { record: jest.fn() }, + value: 0 + })) + } + + const ctx = new OpenTelemetryMetricsContext( + 'test', + tracer, + undefined, + undefined, + { op: 'test' }, + {}, + metrics, + mockLogger, + undefined, + undefined, + undefined, + mockMeter as any + ) + + ctx.measure('custom', 100) + + expect(mockMeter.getCounter).toHaveBeenCalledWith('custom') + }) + + it('should log info with OTLP logger', () => { + const metrics = newMetrics() + const mockOtlpLogger = { + emit: jest.fn() + } + + const ctx = new OpenTelemetryMetricsContext( + 'test', + tracer, + context.active(), + undefined, + { op: 'test' }, + {}, + metrics, + mockLogger, + undefined, + undefined, + mockOtlpLogger as any + ) + + ctx.info('Test message', { key: 'value' }) + + expect(mockOtlpLogger.emit).toHaveBeenCalled() + expect(mockLogger.info).toHaveBeenCalled() + }) + + it('should log error with OTLP logger', () => { + const metrics = newMetrics() + const mockOtlpLogger = { + emit: jest.fn() + } + + const ctx = new OpenTelemetryMetricsContext( + 'test', + tracer, + context.active(), + undefined, + { op: 'test' }, + {}, + metrics, + mockLogger, + undefined, + undefined, + mockOtlpLogger as any + ) + + ctx.error('Error message', { error: 'details' }) + + expect(mockOtlpLogger.emit).toHaveBeenCalled() + expect(mockLogger.error).toHaveBeenCalled() + }) + + it('should log warn with OTLP logger', () => { + const metrics = newMetrics() + const mockOtlpLogger = { + emit: jest.fn() + } + + const ctx = new OpenTelemetryMetricsContext( + 'test', + tracer, + context.active(), + undefined, + { op: 'test' }, + {}, + metrics, + mockLogger, + undefined, + undefined, + mockOtlpLogger as any + ) + + ctx.warn('Warning message', { warning: 'info' }) + + expect(mockOtlpLogger.emit).toHaveBeenCalled() + expect(mockLogger.warn).toHaveBeenCalled() + }) + + it('should extract metadata from context', () => { + const metrics = newMetrics() + const ctx = new OpenTelemetryMetricsContext( + 'test', + tracer, + context.active(), + undefined, + {}, + {}, + metrics, + mockLogger + ) + + const meta = ctx.extractMeta() + + expect(meta).toBeDefined() + expect(typeof meta).toBe('object') + }) + + it('should get params', () => { + const metrics = newMetrics() + const ctx = new OpenTelemetryMetricsContext( + 'test', + tracer, + undefined, + undefined, + { op: 'test', method: 'GET' }, + {}, + metrics, + mockLogger + ) + + const params = ctx.getParams() + + expect(params).toEqual({ op: 'test', method: 'GET' }) + }) + + it('should share contextData with children', () => { + const metrics = newMetrics() + const ctx = new OpenTelemetryMetricsContext( + 'parent', + tracer, + context.active(), + undefined, + {}, + {}, + metrics, + mockLogger + ) + ctx.contextData = { userId: '123' } + + const child = ctx.newChild('child', {}) + + expect(child.contextData).toBe(ctx.contextData) + }) + + it('should inherit params when inheritParams is true', async () => { + const metrics = newMetrics() + const ctx = new OpenTelemetryMetricsContext( + 'parent', + tracer, + context.active(), + undefined, + { parentKey: 'parentValue' }, + {}, + metrics, + mockLogger + ) + + await ctx.with( + 'child', + { childKey: 'childValue' }, + async (childCtx) => { + expect(childCtx.getParams()).toEqual({ childKey: 'childValue' }) + }, + {}, + { inheritParams: false } + ) + + await ctx.with( + 'child', + { childKey: 'childValue' }, + async (childCtx) => { + expect(childCtx.getParams()).toEqual({ + parentKey: 'parentValue', + childKey: 'childValue' + }) + }, + {}, + { inheritParams: true } + ) + }) + + it('should not call end() twice', () => { + const metrics = newMetrics() + const span = tracer.startSpan('test-span') + const spanEndSpy = jest.spyOn(span, 'end') + + const ctx = new OpenTelemetryMetricsContext( + 'test', + tracer, + context.active(), + span, + {}, + {}, + metrics, + mockLogger + ) + + ctx.end() + ctx.end() // Second call should be no-op + + expect(spanEndSpy).toHaveBeenCalledTimes(1) + }) + + it('should handle null return value', async () => { + const metrics = newMetrics() + const ctx = new OpenTelemetryMetricsContext( + 'test', + tracer, + context.active(), + undefined, + {}, + {}, + metrics, + mockLogger + ) + + const result = await ctx.with('operation', {}, () => null) + + expect(result).toBeUndefined() + }) + + it('should log operation when log option is true', async () => { + const metrics = newMetrics() + const ctx = new OpenTelemetryMetricsContext( + 'test', + tracer, + context.active(), + undefined, + {}, + {}, + metrics, + mockLogger + ) + + await ctx.with( + 'operation', + { op: 'test' }, + async () => { + await new Promise(resolve => setTimeout(resolve, 10)) + }, + {}, + { log: true } + ) + + expect(mockLogger.logOperation).toHaveBeenCalledWith( + 'operation', + expect.any(Number), + expect.objectContaining({ op: 'test' }) + ) + }) + + it('should suppress tracing when span is disable', () => { + const metrics = newMetrics() + const ctx = new OpenTelemetryMetricsContext( + 'parent', + tracer, + context.active(), + undefined, + {}, + {}, + metrics, + mockLogger + ) + + const child = ctx.newChild('child', {}, { span: 'disable' }) + + expect(child).toBeDefined() + }) + + it('should set span attributes from params', () => { + const metrics = newMetrics() + + const ctx = new OpenTelemetryMetricsContext( + 'parent', + tracer, + context.active(), + undefined, + {}, + {}, + metrics, + mockLogger + ) + + // When creating a child with span: true, attributes are set on the child's span + const child = ctx.newChild('child', { key1: 'value1', key2: 'value2' }, { span: true }) as OpenTelemetryMetricsContext + + // The child should have been created successfully + expect(child).toBeDefined() + expect(child.parent).toBe(ctx) + }) + }) +}) diff --git a/packages/measurements/src/__tests__/context.test.ts b/packages/measurements/src/__tests__/context.test.ts new file mode 100644 index 0000000000..7a56de9579 --- /dev/null +++ b/packages/measurements/src/__tests__/context.test.ts @@ -0,0 +1,451 @@ +import { + MeasureMetricsContext, + NoMetricsContext, + consoleLogger, + noParamsLogger, + withContext, + setOperationLogProfiling, + registerOperationLog, + updateOperationLog, + addOperation +} from '../context' +import { newMetrics } from '../metrics' +import type { MeasureLogger, MeasureContext } from '../types' + +describe('context', () => { + describe('consoleLogger', () => { + it('should create a logger with params', () => { + const logger = consoleLogger({ service: 'test' }) + + expect(logger).toBeDefined() + expect(typeof logger.info).toBe('function') + expect(typeof logger.error).toBe('function') + expect(typeof logger.warn).toBe('function') + expect(typeof logger.close).toBe('function') + }) + + it('should log info messages', () => { + const consoleSpy = jest.spyOn(console, 'info').mockImplementation() + const logger = consoleLogger({ service: 'test' }) + + logger.info('Test message', { key: 'value' }) + + expect(consoleSpy).toHaveBeenCalled() + consoleSpy.mockRestore() + }) + + it('should log error messages', () => { + const consoleSpy = jest.spyOn(console, 'error').mockImplementation() + const logger = consoleLogger({ service: 'test' }) + + logger.error('Error message', { error: 'details' }) + + expect(consoleSpy).toHaveBeenCalled() + consoleSpy.mockRestore() + }) + + it('should log warn messages', () => { + const consoleSpy = jest.spyOn(console, 'warn').mockImplementation() + const logger = consoleLogger({ service: 'test' }) + + logger.warn('Warning message', { warning: 'info' }) + + expect(consoleSpy).toHaveBeenCalled() + consoleSpy.mockRestore() + }) + + it('should handle errors in params', () => { + const consoleSpy = jest.spyOn(console, 'error').mockImplementation() + const logger = consoleLogger({}) + const error = new Error('Test error') + + logger.error('Error occurred', { error }) + + expect(consoleSpy).toHaveBeenCalled() + const call = consoleSpy.mock.calls[0] + expect(call[0]).toBe('Error occurred') + consoleSpy.mockRestore() + }) + }) + + describe('MeasureMetricsContext', () => { + let logger: MeasureLogger + + beforeEach(() => { + logger = noParamsLogger + }) + + it('should create a new context', () => { + const metrics = newMetrics() + const ctx = new MeasureMetricsContext('test', { op: 'create' }, {}, metrics, logger) + + expect(ctx).toBeDefined() + expect(ctx.metrics).toBe(metrics) + expect(ctx.logger).toBe(logger) + }) + + it('should measure operation duration', async () => { + const metrics = newMetrics() + const ctx = new MeasureMetricsContext('test', { op: 'create' }, {}, metrics, logger) + + await new Promise(resolve => setTimeout(resolve, 50)) + ctx.end() + + expect(metrics.operations).toBe(1) + expect(metrics.value).toBeGreaterThan(40) + }) + + it('should create child context', () => { + const metrics = newMetrics() + const ctx = new MeasureMetricsContext('parent', { op: 'parent' }, {}, metrics, logger) + const child = ctx.newChild('child', { op: 'child' }) + + expect(child).toBeDefined() + expect(child.parent).toBe(ctx) + }) + + it('should execute async operation with context', async () => { + const metrics = newMetrics() + const ctx = new MeasureMetricsContext('test', {}, {}, metrics, logger) + + let executed = false + await ctx.with('operation', { op: 'test' }, async () => { + executed = true + await new Promise(resolve => setTimeout(resolve, 10)) + }) + + expect(executed).toBe(true) + expect(metrics.measurements.operation).toBeDefined() + }) + + it('should execute sync operation with context', () => { + const metrics = newMetrics() + const ctx = new MeasureMetricsContext('test', {}, {}, metrics, logger) + + const result = ctx.withSync('operation', { op: 'test' }, () => { + return 42 + }) + + expect(result).toBe(42) + expect(metrics.measurements.operation).toBeDefined() + }) + + it('should measure custom value', () => { + const metrics = newMetrics() + const ctx = new MeasureMetricsContext('test', {}, {}, metrics, logger) + + ctx.measure('custom', 100) + + expect(metrics.measurements['#custom']).toBeDefined() + expect(metrics.measurements['#custom'].value).toBe(100) + }) + + it('should log info messages', () => { + const mockLogger: MeasureLogger = { + info: jest.fn(), + error: jest.fn(), + warn: jest.fn(), + close: jest.fn(async () => {}), + logOperation: jest.fn() + } + + const ctx = new MeasureMetricsContext('test', { op: 'test' }, {}, newMetrics(), mockLogger) + ctx.info('Test message', { key: 'value' }) + + expect(mockLogger.info).toHaveBeenCalledWith('Test message', expect.objectContaining({ key: 'value', op: 'test' })) + }) + + it('should log error messages', () => { + const mockLogger: MeasureLogger = { + info: jest.fn(), + error: jest.fn(), + warn: jest.fn(), + close: jest.fn(async () => {}), + logOperation: jest.fn() + } + + const ctx = new MeasureMetricsContext('test', { op: 'test' }, {}, newMetrics(), mockLogger) + ctx.error('Error message', { error: 'details' }) + + expect(mockLogger.error).toHaveBeenCalledWith('Error message', expect.objectContaining({ error: 'details', op: 'test' })) + }) + + it('should log warn messages', () => { + const mockLogger: MeasureLogger = { + info: jest.fn(), + error: jest.fn(), + warn: jest.fn(), + close: jest.fn(async () => {}), + logOperation: jest.fn() + } + + const ctx = new MeasureMetricsContext('test', { op: 'test' }, {}, newMetrics(), mockLogger) + ctx.warn('Warning message', { warning: 'info' }) + + expect(mockLogger.warn).toHaveBeenCalledWith('Warning message', expect.objectContaining({ warning: 'info', op: 'test' })) + }) + + it('should get params', () => { + const ctx = new MeasureMetricsContext('test', { op: 'test', method: 'GET' }, {}, newMetrics(), logger) + const params = ctx.getParams() + + expect(params).toEqual({ op: 'test', method: 'GET' }) + }) + + it('should share contextData with children', () => { + const metrics = newMetrics() + const ctx = new MeasureMetricsContext('parent', {}, {}, metrics, logger) + ctx.contextData = { userId: '123' } + + const child = ctx.newChild('child', {}) + + expect(child.contextData).toBe(ctx.contextData) + }) + + it('should handle named parameters', () => { + const metrics = newMetrics() + new MeasureMetricsContext('test', { method: 'GET' }, {}, metrics, logger) + + expect(metrics.namedParams.method).toBe('GET') + }) + + it('should update named parameters on multiple contexts', () => { + const metrics = newMetrics() + const ctx1 = new MeasureMetricsContext('test1', { method: 'GET' }, {}, metrics, logger) + + expect(metrics.namedParams.method).toBe('GET') + + // Create another context with different value for same param + const ctx2 = new MeasureMetricsContext('test2', { method: 'POST' }, {}, metrics, logger) + + // The second context will see existing value is different, so it will update to '*' + // But this happens within the constructor logic + expect(metrics.namedParams.method).toBe('POST') + }) + }) + + describe('NoMetricsContext', () => { + it('should create a no-op context', () => { + const ctx = new NoMetricsContext() + + expect(ctx).toBeDefined() + expect(ctx.logger).toBeDefined() + }) + + it('should execute operations without measuring', async () => { + const ctx = new NoMetricsContext() + + let executed = false + await ctx.with('operation', {}, async () => { + executed = true + }) + + expect(executed).toBe(true) + }) + + it('should create child contexts', () => { + const ctx = new NoMetricsContext() + const child = ctx.newChild('child', {}) + + expect(child).toBeDefined() + expect(child).toBeInstanceOf(NoMetricsContext) + }) + + it('should handle measure calls without error', () => { + const ctx = new NoMetricsContext() + + expect(() => { + ctx.measure('test', 100) + }).not.toThrow() + }) + + it('should handle end calls without error', () => { + const ctx = new NoMetricsContext() + + expect(() => { + ctx.end() + }).not.toThrow() + }) + + it('should return empty params', () => { + const ctx = new NoMetricsContext() + const params = ctx.getParams() + + expect(params).toEqual({}) + }) + }) + + describe('withContext decorator', () => { + it('should wrap method with context', async () => { + class TestClass { + @withContext('testOperation', { service: 'test' }) + async testMethod(ctx: MeasureContext, value: number): Promise { + return value * 2 + } + } + + const instance = new TestClass() + const metrics = newMetrics() + const ctx = new MeasureMetricsContext('root', {}, {}, metrics, noParamsLogger) + + const result = await instance.testMethod(ctx, 21) + + expect(result).toBe(42) + expect(metrics.measurements.testOperation).toBeDefined() + }) + }) + + describe('operation log profiling', () => { + beforeEach(() => { + setOperationLogProfiling(false) + }) + + afterEach(() => { + setOperationLogProfiling(false) + }) + + it('should register operation log when profiling enabled', () => { + setOperationLogProfiling(true) + const metrics = newMetrics() + const ctx = new MeasureMetricsContext('test', {}, {}, metrics, noParamsLogger) + + const { opLogMetrics, op } = registerOperationLog(ctx) + + expect(opLogMetrics).toBe(metrics) + expect(op).toBeDefined() + expect(ctx.id).toBeDefined() + }) + + it('should not register operation log when profiling disabled', () => { + setOperationLogProfiling(false) + const metrics = newMetrics() + const ctx = new MeasureMetricsContext('test', {}, {}, metrics, noParamsLogger) + + const { opLogMetrics, op } = registerOperationLog(ctx) + + expect(opLogMetrics).toBeUndefined() + expect(op).toBeUndefined() + }) + + it('should update operation log', () => { + setOperationLogProfiling(true) + const metrics = newMetrics() + const ctx = new MeasureMetricsContext('test', {}, {}, metrics, noParamsLogger) + + const { opLogMetrics, op } = registerOperationLog(ctx) + updateOperationLog(opLogMetrics, op) + + expect(op?.end).toBeGreaterThan(0) + }) + + it('should add operation to log', async () => { + setOperationLogProfiling(true) + const metrics = newMetrics() + const ctx = new MeasureMetricsContext('test', {}, {}, metrics, noParamsLogger) + + registerOperationLog(ctx) + + let executed = false + await addOperation(ctx, 'asyncOp', { op: 'test' }, async () => { + executed = true + }) + + expect(executed).toBe(true) + expect(metrics.opLog).toBeDefined() + }) + + it('should limit operation log entries', () => { + setOperationLogProfiling(true) + const metrics = newMetrics() + const ctx = new MeasureMetricsContext('test', {}, {}, metrics, noParamsLogger) + + registerOperationLog(ctx) + + // Create many operation log entries + if (metrics.opLog && ctx.id) { + for (let i = 0; i < 50; i++) { + metrics.opLog[ctx.id].ops.push({ + op: `test${i}`, + start: i, + end: i + 1, + params: {} + }) + } + + const op = metrics.opLog[ctx.id] + updateOperationLog(metrics, op) + + expect(Object.keys(metrics.opLog).length).toBeLessThanOrEqual(31) + } + }) + }) + + describe('extractMeta', () => { + it('should return empty metadata', () => { + const ctx = new MeasureMetricsContext('test', {}, {}, newMetrics(), noParamsLogger) + const meta = ctx.extractMeta() + + expect(meta).toEqual({}) + }) + }) + + describe('async operations', () => { + it('should handle promise rejection', async () => { + const metrics = newMetrics() + const ctx = new MeasureMetricsContext('test', {}, {}, metrics, noParamsLogger) + + await expect( + ctx.with('operation', { op: 'test' }, async () => { + throw new Error('Test error') + }) + ).rejects.toThrow('Test error') + + expect(metrics.measurements.operation).toBeDefined() + }) + + it('should return null promise for null sync result', async () => { + const metrics = newMetrics() + const ctx = new MeasureMetricsContext('test', {}, {}, metrics, noParamsLogger) + + const result = await ctx.with('operation', { op: 'test' }, () => { + return null + }) + + expect(result).toBeUndefined() + }) + + it('should handle sync return value', async () => { + const metrics = newMetrics() + const ctx = new MeasureMetricsContext('test', {}, {}, metrics, noParamsLogger) + + const result = await ctx.with('operation', { op: 'test' }, () => { + return 42 + }) + + expect(result).toBe(42) + }) + + it('should log operation when log option is true', async () => { + const mockLogger: MeasureLogger = { + info: jest.fn(), + error: jest.fn(), + warn: jest.fn(), + close: jest.fn(async () => {}), + logOperation: jest.fn() + } + + const metrics = newMetrics() + const ctx = new MeasureMetricsContext('test', {}, {}, metrics, mockLogger) + + await ctx.with('operation', { op: 'test' }, async () => { + await new Promise(resolve => setTimeout(resolve, 10)) + }, {}, { log: true }) + + expect(mockLogger.logOperation).toHaveBeenCalledWith( + 'operation', + expect.any(Number), + expect.objectContaining({ op: 'test' }) + ) + }) + }) +}) diff --git a/packages/measurements/src/__tests__/index.test.ts b/packages/measurements/src/__tests__/index.test.ts new file mode 100644 index 0000000000..1bd75aff15 --- /dev/null +++ b/packages/measurements/src/__tests__/index.test.ts @@ -0,0 +1,47 @@ +import { platformNow, platformNowDiff } from '../index' + +describe('index', () => { + describe('platformNow', () => { + it('should return a positive number', () => { + const now = platformNow() + expect(typeof now).toBe('number') + expect(now).toBeGreaterThan(0) + }) + + it('should return increasing values over time', async () => { + const first = platformNow() + await new Promise(resolve => setTimeout(resolve, 10)) + const second = platformNow() + expect(second).toBeGreaterThan(first) + }) + }) + + describe('platformNowDiff', () => { + it('should calculate the difference between timestamps', async () => { + const start = platformNow() + await new Promise(resolve => setTimeout(resolve, 50)) + const diff = platformNowDiff(start) + + expect(diff).toBeGreaterThan(40) + expect(diff).toBeLessThan(100) + }) + + it('should round to 2 decimal places', async () => { + const start = platformNow() + await new Promise(resolve => setTimeout(resolve, 10)) + const diff = platformNowDiff(start) + + // Check that it has at most 2 decimal places + const decimalPlaces = (diff.toString().split('.')[1] || '').length + expect(decimalPlaces).toBeLessThanOrEqual(2) + }) + + it('should handle very small differences', () => { + const start = platformNow() + const diff = platformNowDiff(start) + + expect(diff).toBeGreaterThanOrEqual(0) + expect(typeof diff).toBe('number') + }) + }) +}) diff --git a/packages/measurements/src/__tests__/metrics.test.ts b/packages/measurements/src/__tests__/metrics.test.ts new file mode 100644 index 0000000000..108a614e44 --- /dev/null +++ b/packages/measurements/src/__tests__/metrics.test.ts @@ -0,0 +1,297 @@ +import { + newMetrics, + measure, + childMetrics, + metricsAggregate, + metricsToString, + metricsToJson, + metricsToRows, + updateMeasure +} from '../metrics' +import { platformNow } from '../index' + +describe('metrics', () => { + describe('newMetrics', () => { + it('should create a new metrics object with default values', () => { + const metrics = newMetrics() + + expect(metrics.operations).toBe(0) + expect(metrics.value).toBe(0) + expect(metrics.measurements).toEqual({}) + expect(metrics.params).toEqual({}) + expect(metrics.namedParams).toEqual({}) + }) + }) + + describe('measure', () => { + it('should measure operation duration', async () => { + const metrics = newMetrics() + const done = measure(metrics, { operation: 'test' }) + + await new Promise(resolve => setTimeout(resolve, 50)) + done() + + expect(metrics.operations).toBe(1) + expect(metrics.value).toBeGreaterThan(40) + }) + + it('should call endOp callback with duration', async () => { + const metrics = newMetrics() + let capturedSpend = 0 + const done = measure(metrics, { operation: 'test' }, {}, (spend) => { + capturedSpend = spend + }) + + await new Promise(resolve => setTimeout(resolve, 50)) + done() + + expect(capturedSpend).toBeGreaterThan(40) + }) + + it('should handle multiple operations', async () => { + const metrics = newMetrics() + + const done1 = measure(metrics, { operation: 'test' }) + await new Promise(resolve => setTimeout(resolve, 20)) + done1() + + const done2 = measure(metrics, { operation: 'test' }) + await new Promise(resolve => setTimeout(resolve, 20)) + done2() + + expect(metrics.operations).toBe(2) + expect(metrics.value).toBeGreaterThan(30) + }) + }) + + describe('updateMeasure', () => { + it('should update metrics with custom value', () => { + const metrics = newMetrics() + const st = platformNow() + + updateMeasure(metrics, st, { op: 'test' }, {}, undefined, 100) + + expect(metrics.operations).toBe(1) + expect(metrics.value).toBe(100) + }) + + it('should override operations when override is true', () => { + const metrics = newMetrics() + const st = platformNow() + + // First call without override - accumulates value and increments operations + updateMeasure(metrics, st, { op: 'test' }, {}, undefined, 50, false) + expect(metrics.value).toBe(50) + expect(metrics.operations).toBe(1) + + // Second call with override - sets operations, doesn't add to value + updateMeasure(metrics, st, { op: 'test' }, {}, undefined, 100, true) + + expect(metrics.operations).toBe(100) // overridden + expect(metrics.value).toBe(50) // not changed when override=true + }) + + it('should track parameters', () => { + const metrics = newMetrics() + const st = platformNow() + + updateMeasure(metrics, st, { method: 'GET' }, {}, undefined, 100) + updateMeasure(metrics, st, { method: 'POST' }, {}, undefined, 200) + + expect(metrics.params.method).toBeDefined() + expect(metrics.params.method.GET).toBeDefined() + expect(metrics.params.method.POST).toBeDefined() + expect(metrics.params.method.GET.value).toBe(100) + expect(metrics.params.method.POST.value).toBe(200) + }) + + it('should handle multiple parameters as counters', () => { + const metrics = newMetrics() + const st = platformNow() + + updateMeasure(metrics, st, { method: 'GET', status: '200' }, {}, undefined, 100) + updateMeasure(metrics, st, { method: 'GET', status: '404' }, {}, undefined, 50) + + expect(metrics.params.method.GET).toBeDefined() + expect(metrics.params.method.GET.topResult).toBeDefined() + expect(metrics.params.method.GET.topResult?.length).toBeGreaterThan(0) + }) + + it('should update top results', () => { + const metrics = newMetrics() + const st = platformNow() + + updateMeasure(metrics, st, {}, { request: 'slow' }, undefined, 100) + updateMeasure(metrics, st, {}, { request: 'fast' }, undefined, 10) + + expect(metrics.topResult).toBeDefined() + expect(metrics.topResult?.length).toBeGreaterThan(0) + }) + }) + + describe('childMetrics', () => { + it('should create child metrics in hierarchy', () => { + const root = newMetrics() + const child = childMetrics(root, ['level1', 'level2']) + + expect(root.measurements.level1).toBeDefined() + expect(root.measurements.level1.measurements.level2).toBeDefined() + expect(child).toBe(root.measurements.level1.measurements.level2) + }) + + it('should reuse existing child metrics', () => { + const root = newMetrics() + const child1 = childMetrics(root, ['level1']) + const child2 = childMetrics(root, ['level1']) + + expect(child1).toBe(child2) + }) + + it('should create nested paths', () => { + const root = newMetrics() + childMetrics(root, ['api', 'users', 'create']) + + expect(root.measurements.api).toBeDefined() + expect(root.measurements.api.measurements.users).toBeDefined() + expect(root.measurements.api.measurements.users.measurements.create).toBeDefined() + }) + }) + + describe('metricsAggregate', () => { + it('should aggregate metrics', () => { + const metrics = newMetrics() + metrics.value = 100 + metrics.operations = 10 + + const child1 = childMetrics(metrics, ['child1']) + child1.value = 50 + child1.operations = 5 + + const child2 = childMetrics(metrics, ['child2']) + child2.value = 30 + child2.operations = 3 + + const aggregated = metricsAggregate(metrics) + + expect(aggregated.value).toBe(80) // child1 + child2 + expect(aggregated.operations).toBe(10) + }) + + it('should limit number of child metrics', () => { + const metrics = newMetrics() + + for (let i = 0; i < 10; i++) { + const child = childMetrics(metrics, [`child${i}`]) + child.value = i * 10 + } + + const aggregated = metricsAggregate(metrics, 3) + + expect(Object.keys(aggregated.measurements).length).toBe(3) + }) + + it('should filter out metrics starting with #', () => { + const metrics = newMetrics() + + const child1 = childMetrics(metrics, ['normal']) + child1.value = 50 + + const child2 = childMetrics(metrics, ['#internal']) + child2.value = 30 + + const aggregated = metricsAggregate(metrics) + + expect(aggregated.value).toBe(50) // only 'normal' counted + }) + }) + + describe('metricsToString', () => { + it('should convert metrics to string', () => { + const metrics = newMetrics() + metrics.value = 100 + metrics.operations = 10 + + const str = metricsToString(metrics, 'TestMetrics', 50) + + expect(str).toContain('TestMetrics') + expect(str).toContain('100') + expect(str).toContain('10') + }) + + it('should include child metrics in string', () => { + const metrics = newMetrics() + const child = childMetrics(metrics, ['operation']) + child.value = 50 + child.operations = 5 + + const str = metricsToString(metrics, 'TestMetrics', 50) + + expect(str).toContain('operation') + }) + }) + + describe('metricsToJson', () => { + it('should convert metrics to JSON', () => { + const metrics = newMetrics() + metrics.value = 100 + metrics.operations = 10 + + const json = metricsToJson(metrics) + + // aggregated value is the total value when no children + expect(json.$total).toBe(100) + expect(json.$ops).toBe(10) + }) + + it('should include child metrics in JSON', () => { + const metrics = newMetrics() + const child = childMetrics(metrics, ['operation']) + child.value = 50 + child.operations = 5 + + const json = metricsToJson(metrics) + + expect(json).toBeDefined() + const keys = Object.keys(json) + expect(keys.some(k => k.includes('operation'))).toBe(true) + }) + }) + + describe('metricsToRows', () => { + it('should convert metrics to rows', () => { + const metrics = newMetrics() + metrics.value = 100 + metrics.operations = 10 + + const rows = metricsToRows(metrics, 'TestMetrics') + + expect(Array.isArray(rows)).toBe(true) + expect(rows.length).toBeGreaterThan(0) + expect(rows[0]).toContain('TestMetrics') + }) + + it('should include child metrics in rows', () => { + const metrics = newMetrics() + const child = childMetrics(metrics, ['operation']) + child.value = 50 + child.operations = 5 + + const rows = metricsToRows(metrics, 'TestMetrics') + + expect(rows.length).toBeGreaterThan(1) + expect(rows.some(row => row.includes('operation'))).toBe(true) + }) + + it('should properly format row values', () => { + const metrics = newMetrics() + metrics.value = 100 + metrics.operations = 10 + + const rows = metricsToRows(metrics, 'TestMetrics') + + expect(rows[0]).toHaveLength(5) // offset, name, avg, total, ops + expect(typeof rows[0][0]).toBe('number') // offset + expect(typeof rows[0][1]).toBe('string') // name + }) + }) +}) diff --git a/packages/measurements/src/__tests__/performance.test.ts b/packages/measurements/src/__tests__/performance.test.ts new file mode 100644 index 0000000000..315690fd9e --- /dev/null +++ b/packages/measurements/src/__tests__/performance.test.ts @@ -0,0 +1,259 @@ +import { MeasureMetricsContext, NoMetricsContext } from '../context' +import { newMetrics, metricsAggregate } from '../metrics' +import { noParamsLogger } from '../context' +import type { MeasureContext } from '../types' + +describe('performance', () => { + describe('overhead measurement', () => { + // Reduced iterations to fit within 10 seconds total test time + const iterations = 100 + const depth = 5 + + it('should measure overhead of with() vs raw execution', async () => { + // Baseline: raw execution without measurement + const baselineStart = performance.now() + for (let i = 0; i < iterations; i++) { + await simulateWork(1) + } + const baselineTime = performance.now() - baselineStart + + // With measurement context + const metrics = newMetrics() + const ctx = new MeasureMetricsContext('root', {}, {}, metrics, noParamsLogger) + + const measuredStart = performance.now() + for (let i = 0; i < iterations; i++) { + await ctx.with('operation', { iteration: i }, async () => { + await simulateWork(1) + }) + } + const measuredTime = performance.now() - measuredStart + + const overhead = measuredTime - baselineTime + const overheadPercentage = (overhead / baselineTime) * 100 + + console.log(`\nšŸ“Š Overhead Analysis (${iterations} iterations):`) + console.log(` Baseline time: ${baselineTime.toFixed(2)}ms`) + console.log(` Measured time: ${measuredTime.toFixed(2)}ms`) + console.log(` Overhead: ${overhead.toFixed(2)}ms (${overheadPercentage.toFixed(2)}%)`) + console.log(` Per operation: ${(overhead / iterations).toFixed(4)}ms`) + + expect(metrics.measurements.operation).toBeDefined() + expect(metrics.measurements.operation.operations).toBe(iterations) + + // Overhead should be reasonable (typically < 50% for simple operations) + // This is informational rather than a strict assertion + expect(overheadPercentage).toBeLessThan(200) + }) + + it('should measure overhead with deep nested contexts', async () => { + const metrics = newMetrics() + const ctx = new MeasureMetricsContext('root', {}, {}, metrics, noParamsLogger) + + // Baseline: single level + const singleLevelStart = performance.now() + for (let i = 0; i < iterations; i++) { + await ctx.with('shallow', {}, async () => { + await simulateWork(1) + }) + } + const singleLevelTime = performance.now() - singleLevelStart + + // Deep nesting + const deepStart = performance.now() + for (let i = 0; i < iterations; i++) { + await deepNestedExecution(ctx, depth, 1) + } + const deepTime = performance.now() - deepStart + + const nestingOverhead = deepTime - singleLevelTime + const overheadPerLevel = nestingOverhead / (iterations * depth) + + console.log(`\nšŸ“Š Deep Nesting Overhead (${iterations} iterations, depth=${depth}):`) + console.log(` Single level: ${singleLevelTime.toFixed(2)}ms`) + console.log(` Deep nested: ${deepTime.toFixed(2)}ms`) + console.log(` Nesting overhead: ${nestingOverhead.toFixed(2)}ms`) + console.log(` Per level: ${overheadPerLevel.toFixed(4)}ms`) + + expect(metrics.measurements.shallow).toBeDefined() + expect(metrics.measurements.level0).toBeDefined() + }) + + it('should measure overhead with complex parameter tracking', async () => { + const metrics = newMetrics() + const ctx = new MeasureMetricsContext('root', {}, {}, metrics, noParamsLogger) + + // Simple params + const simpleStart = performance.now() + for (let i = 0; i < iterations; i++) { + await ctx.with('simple', { id: i }, async () => { + await simulateWork(1) + }) + } + const simpleTime = performance.now() - simpleStart + + // Complex params with multiple tracked values + const complexStart = performance.now() + for (let i = 0; i < iterations; i++) { + await ctx.with('complex', + { + method: i % 3 === 0 ? 'GET' : i % 3 === 1 ? 'POST' : 'PUT', + status: i % 2 === 0 ? 200 : 404, + cached: i % 4 === 0 + }, + async () => { + await simulateWork(1) + }, + { + userId: `user_${i % 10}`, + endpoint: `/api/v1/resource/${i % 5}`, + timestamp: Date.now() + } + ) + } + const complexTime = performance.now() - complexStart + + const paramOverhead = complexTime - simpleTime + + console.log(`\nšŸ“Š Parameter Tracking Overhead (${iterations} iterations):`) + console.log(` Simple params: ${simpleTime.toFixed(2)}ms`) + console.log(` Complex params: ${complexTime.toFixed(2)}ms`) + console.log(` Param overhead: ${paramOverhead.toFixed(2)}ms`) + console.log(` Per operation: ${(paramOverhead / iterations).toFixed(4)}ms`) + + expect(metrics.measurements.simple).toBeDefined() + expect(metrics.measurements.complex).toBeDefined() + expect(Object.keys(metrics.measurements.complex.params).length).toBeGreaterThan(0) + }) + + it('should measure overhead with NoMetricsContext', async () => { + // NoMetricsContext should have minimal overhead + const noMetricsCtx = new NoMetricsContext(noParamsLogger) + + const start = performance.now() + for (let i = 0; i < iterations; i++) { + await noMetricsCtx.with('operation', { iteration: i }, async () => { + await simulateWork(1) + }) + } + const noMetricsTime = performance.now() - start + + // Compare with raw execution + const rawStart = performance.now() + for (let i = 0; i < iterations; i++) { + await simulateWork(1) + } + const rawTime = performance.now() - rawStart + + const overhead = noMetricsTime - rawTime + const overheadPercentage = (overhead / rawTime) * 100 + + console.log(`\nšŸ“Š NoMetricsContext Overhead (${iterations} iterations):`) + console.log(` Raw time: ${rawTime.toFixed(2)}ms`) + console.log(` NoMetrics time: ${noMetricsTime.toFixed(2)}ms`) + console.log(` Overhead: ${overhead.toFixed(2)}ms (${overheadPercentage.toFixed(2)}%)`) + + // NoMetricsContext should have very low overhead + expect(overheadPercentage).toBeLessThan(50) + }) + }) + + describe('realistic workload simulation', () => { + it('should measure overhead in complex realistic scenario', async () => { + const metrics = newMetrics() + const ctx = new MeasureMetricsContext('app', { service: 'api' }, {}, metrics, noParamsLogger) + + const requests = 50 + const baselineStart = performance.now() + + // Simulate without metrics + for (let i = 0; i < requests; i++) { + await simulateAPIRequest(null, i) + } + const baselineTime = performance.now() - baselineStart + + // Reset for measured run + const measuredStart = performance.now() + + // Simulate with metrics + for (let i = 0; i < requests; i++) { + await simulateAPIRequest(ctx, i) + } + const measuredTime = performance.now() - measuredStart + + const overhead = measuredTime - baselineTime + const overheadPercentage = (overhead / baselineTime) * 100 + + console.log(`\nšŸ“Š Realistic Workload Analysis (${requests} API requests):`) + console.log(` Baseline: ${baselineTime.toFixed(2)}ms`) + console.log(` With metrics: ${measuredTime.toFixed(2)}ms`) + console.log(` Overhead: ${overhead.toFixed(2)}ms (${overheadPercentage.toFixed(2)}%)`) + console.log(` Per request: ${(overhead / requests).toFixed(4)}ms`) + + // Check metrics structure + const aggregated = metricsAggregate(metrics, 10) + console.log(` Collected operations: ${aggregated.measurements.request?.operations || 0}`) + + expect(aggregated.measurements.request).toBeDefined() + expect(overheadPercentage).toBeLessThan(100) // Should be less than 100% overhead + }) + }) +}) + +// Helper functions + +async function simulateWork(durationMs: number): Promise { + const end = performance.now() + durationMs + while (performance.now() < end) { + // Busy wait to simulate work + Math.random() * Math.random() + } +} + +async function deepNestedExecution( + ctx: MeasureContext, + depth: number, + workMs: number, + currentLevel: number = 0 +): Promise { + if (currentLevel >= depth) { + await simulateWork(workMs) + return + } + + await ctx.with(`level${currentLevel}`, { level: currentLevel }, async (childCtx) => { + await deepNestedExecution(childCtx, depth, workMs, currentLevel + 1) + }) +} + +async function simulateAPIRequest(ctx: MeasureContext | null, requestId: number): Promise { + const method = ['GET', 'POST', 'PUT'][requestId % 3] + const endpoint = `/api/resource/${requestId % 10}` + + if (ctx === null) { + // No metrics version + await simulateWork(1) + // Simulate DB query + await simulateWork(2) + // Simulate processing + await simulateWork(1) + return + } + + // With metrics version + await ctx.with('request', { method, endpoint }, async (reqCtx) => { + await reqCtx.with('auth', { userId: `user_${requestId % 50}` }, async () => { + await simulateWork(1) + }) + + await reqCtx.with('database', { query: 'SELECT' }, async (dbCtx) => { + await dbCtx.with('query_execution', {}, async () => { + await simulateWork(2) + }) + }) + + await reqCtx.with('processing', { items: requestId % 20 }, async () => { + await simulateWork(1) + }) + }) +} \ No newline at end of file