382 lines
12 KiB
TypeScript
382 lines
12 KiB
TypeScript
/**
|
|
* Performance Monitor Unit Tests
|
|
*
|
|
* Tests for trackDuration helper and PerformanceTracker class
|
|
*/
|
|
|
|
import { describe, it, expect, vi, beforeEach, afterEach, type Mock } from 'vitest'
|
|
import {
|
|
trackDuration,
|
|
PerformanceTracker,
|
|
createPerformanceTracker,
|
|
DEFAULT_SLOW_THRESHOLD_MS,
|
|
type TrackDurationOptions
|
|
} from '../../src/main/services/logger/performance-monitor'
|
|
import logger from '../../src/main/services/logger/index'
|
|
|
|
// Mock the logger to avoid noisy output during tests
|
|
vi.mock('../../src/main/services/logger/index', () => ({
|
|
default: {
|
|
debug: vi.fn(),
|
|
info: vi.fn(),
|
|
warn: vi.fn(),
|
|
error: vi.fn(),
|
|
child: vi.fn().mockReturnThis()
|
|
}
|
|
}))
|
|
|
|
describe('Performance Monitor', () => {
|
|
beforeEach(() => {
|
|
vi.clearAllMocks()
|
|
})
|
|
|
|
afterEach(() => {
|
|
vi.clearAllMocks()
|
|
})
|
|
|
|
describe('trackDuration', () => {
|
|
it('should track duration of successful async operation', async () => {
|
|
const mockFn = vi.fn().mockResolvedValue('test result')
|
|
|
|
const result = await trackDuration(mockFn, {
|
|
operationName: 'TestOperation'
|
|
})
|
|
|
|
expect(result.result).toBe('test result')
|
|
expect(result.durationMs).toBeGreaterThanOrEqual(0)
|
|
expect(result.isSlow).toBe(false)
|
|
expect(mockFn).toHaveBeenCalledTimes(1)
|
|
})
|
|
|
|
it('should mark operation as slow when exceeding threshold', async () => {
|
|
const slowFn = vi
|
|
.fn()
|
|
.mockImplementation(() => new Promise((resolve) => setTimeout(() => resolve('slow'), 50)))
|
|
|
|
const result = await trackDuration(slowFn, {
|
|
operationName: 'SlowOperation',
|
|
slowThresholdMs: 10
|
|
})
|
|
|
|
expect(result.result).toBe('slow')
|
|
expect(result.durationMs).toBeGreaterThan(10)
|
|
expect(result.isSlow).toBe(true)
|
|
})
|
|
|
|
it('should log with custom log level', async () => {
|
|
const mockFn = vi.fn().mockResolvedValue('result')
|
|
|
|
await trackDuration(mockFn, {
|
|
operationName: 'CustomLevelOp',
|
|
logLevel: 'info'
|
|
})
|
|
|
|
expect(logger.info).toHaveBeenCalled()
|
|
expect(logger.warn).not.toHaveBeenCalled()
|
|
})
|
|
|
|
it('should log warning for slow operations', async () => {
|
|
const slowFn = vi
|
|
.fn()
|
|
.mockImplementation(() => new Promise((resolve) => setTimeout(() => resolve('slow'), 100)))
|
|
|
|
await trackDuration(slowFn, {
|
|
operationName: 'SlowOp',
|
|
slowThresholdMs: 50
|
|
})
|
|
|
|
expect(logger.warn).toHaveBeenCalled()
|
|
const warnCall = (logger.warn as Mock).mock.calls[0][0]
|
|
expect(warnCall).toContain('SLOW')
|
|
expect(warnCall).toContain('50ms threshold')
|
|
})
|
|
|
|
it('should include context in logs', async () => {
|
|
const mockFn = vi.fn().mockResolvedValue('result')
|
|
|
|
await trackDuration(mockFn, {
|
|
operationName: 'ContextOp',
|
|
context: { userId: 123, customField: 'test' }
|
|
})
|
|
|
|
expect(logger.debug).toHaveBeenCalled()
|
|
const contextCall = (logger.debug as Mock).mock.calls[0][1]
|
|
expect(contextCall).toMatchObject({
|
|
operation: 'ContextOp',
|
|
userId: 123
|
|
})
|
|
// Also check the custom field is included
|
|
expect(contextCall.customField).toBe('test')
|
|
})
|
|
|
|
it('should log error and duration when operation fails', async () => {
|
|
const errorFn = vi.fn().mockRejectedValue(new Error('Test error'))
|
|
|
|
await expect(
|
|
trackDuration(errorFn, {
|
|
operationName: 'ErrorOp'
|
|
})
|
|
).rejects.toThrow('Test error')
|
|
|
|
expect(logger.error).toHaveBeenCalled()
|
|
const errorCall = (logger.error as Mock).mock.calls[0][0]
|
|
expect(errorCall).toContain('failed after')
|
|
expect(errorCall).toContain('ErrorOp')
|
|
})
|
|
|
|
it('should use custom message in logs', async () => {
|
|
const mockFn = vi.fn().mockResolvedValue('result')
|
|
|
|
await trackDuration(mockFn, {
|
|
operationName: 'TestOp',
|
|
message: 'Custom message for this operation'
|
|
})
|
|
|
|
expect(logger.debug).toHaveBeenCalled()
|
|
const messageCall = (logger.debug as Mock).mock.calls[0][0]
|
|
expect(messageCall).toContain('Custom message for this operation')
|
|
})
|
|
|
|
it('should have default threshold of 1000ms', async () => {
|
|
const slowFn = vi
|
|
.fn()
|
|
.mockImplementation(() => new Promise((resolve) => setTimeout(() => resolve('slow'), 100)))
|
|
|
|
const result = await trackDuration(slowFn, {
|
|
operationName: 'DefaultThresholdOp'
|
|
})
|
|
|
|
// 100ms should NOT be slow with default 1000ms threshold
|
|
expect(result.isSlow).toBe(false)
|
|
expect(result.durationMs).toBeLessThan(1000)
|
|
})
|
|
})
|
|
|
|
describe('PerformanceTracker', () => {
|
|
it('should track multiple operations', async () => {
|
|
const tracker = new PerformanceTracker('TestService', 1000)
|
|
|
|
const mockFn1 = vi.fn().mockResolvedValue('result1')
|
|
const mockFn2 = vi.fn().mockResolvedValue('result2')
|
|
|
|
const result1 = await tracker.track('Operation1', mockFn1)
|
|
const result2 = await tracker.track('Operation2', mockFn2)
|
|
|
|
expect(result1).toBe('result1')
|
|
expect(result2).toBe('result2')
|
|
|
|
const metrics = tracker.getMetrics()
|
|
expect(metrics.count).toBe(2)
|
|
expect(metrics.minDurationMs).toBeGreaterThanOrEqual(0)
|
|
expect(metrics.maxDurationMs).toBeGreaterThanOrEqual(0)
|
|
})
|
|
|
|
it('should calculate correct metrics', async () => {
|
|
const tracker = new PerformanceTracker('TestService', 1000)
|
|
|
|
// Track operations with known durations
|
|
tracker.recordDuration(100)
|
|
tracker.recordDuration(200)
|
|
tracker.recordDuration(300)
|
|
|
|
const metrics = tracker.getMetrics()
|
|
|
|
expect(metrics.count).toBe(3)
|
|
expect(metrics.totalDurationMs).toBe(600)
|
|
expect(metrics.minDurationMs).toBe(100)
|
|
expect(metrics.maxDurationMs).toBe(300)
|
|
expect(metrics.avgDurationMs).toBe(200)
|
|
})
|
|
|
|
it('should track slow operations count', async () => {
|
|
const tracker = new PerformanceTracker('TestService', 50)
|
|
|
|
tracker.recordDuration(30) // Normal
|
|
tracker.recordDuration(100) // Slow
|
|
tracker.recordDuration(40) // Normal
|
|
tracker.recordDuration(150) // Slow
|
|
|
|
const metrics = tracker.getMetrics()
|
|
expect(metrics.slowOperationCount).toBe(2)
|
|
})
|
|
|
|
it('should log warnings for slow operations', async () => {
|
|
const tracker = new PerformanceTracker('TestService', 10)
|
|
|
|
const slowFn = vi
|
|
.fn()
|
|
.mockImplementation(() => new Promise((resolve) => setTimeout(() => resolve('slow'), 50)))
|
|
|
|
await tracker.track('SlowOp', slowFn)
|
|
|
|
expect(logger.warn).toHaveBeenCalled()
|
|
const warnCall = (logger.warn as Mock).mock.calls[0][0]
|
|
expect(warnCall).toContain('[TestService]')
|
|
expect(warnCall).toContain('SLOW')
|
|
})
|
|
|
|
it('should include context in operation logs', async () => {
|
|
const tracker = new PerformanceTracker('DatabaseService', 1000)
|
|
|
|
const mockFn = vi.fn().mockResolvedValue('data')
|
|
|
|
await tracker.track('getUser', mockFn, { userId: 456, table: 'users' })
|
|
|
|
expect(logger.debug).toHaveBeenCalled()
|
|
const contextCall = (logger.debug as Mock).mock.calls[0][1]
|
|
expect(contextCall).toMatchObject({
|
|
operation: 'getUser',
|
|
userId: 456
|
|
})
|
|
})
|
|
|
|
it('should log summary with aggregated metrics', () => {
|
|
const tracker = new PerformanceTracker('TestService', 1000)
|
|
|
|
tracker.recordDuration(100)
|
|
tracker.recordDuration(200)
|
|
tracker.recordDuration(300)
|
|
|
|
tracker.logSummary('info', 'Test Summary')
|
|
|
|
expect(logger.info).toHaveBeenCalled()
|
|
const summaryCall = (logger.info as Mock).mock.calls[0]
|
|
expect(summaryCall[0]).toContain('Test Summary')
|
|
expect(summaryCall[1]).toMatchObject({
|
|
totalOperations: 3,
|
|
slowOperations: 0
|
|
})
|
|
})
|
|
|
|
it('should include slow percentage in summary', () => {
|
|
const tracker = new PerformanceTracker('TestService', 50)
|
|
|
|
tracker.recordDuration(30) // Normal
|
|
tracker.recordDuration(100) // Slow
|
|
|
|
tracker.logSummary()
|
|
|
|
expect(logger.info).toHaveBeenCalled()
|
|
const summaryCall = (logger.info as Mock).mock.calls[0][1]
|
|
expect(summaryCall.slowPercentage).toContain('%')
|
|
})
|
|
|
|
it('should reset metrics when reset() is called', () => {
|
|
const tracker = new PerformanceTracker('TestService', 1000)
|
|
|
|
tracker.recordDuration(100)
|
|
tracker.recordDuration(200)
|
|
|
|
tracker.reset()
|
|
|
|
const metrics = tracker.getMetrics()
|
|
expect(metrics.count).toBe(0)
|
|
expect(metrics.totalDurationMs).toBe(0)
|
|
expect(metrics.slowOperationCount).toBe(0)
|
|
})
|
|
|
|
it('should return zero metrics when no operations tracked', () => {
|
|
const tracker = new PerformanceTracker('EmptyService')
|
|
|
|
const metrics = tracker.getMetrics()
|
|
|
|
expect(metrics.count).toBe(0)
|
|
expect(metrics.totalDurationMs).toBe(0)
|
|
expect(metrics.minDurationMs).toBe(0)
|
|
expect(metrics.maxDurationMs).toBe(0)
|
|
expect(metrics.avgDurationMs).toBe(0)
|
|
expect(metrics.slowOperationCount).toBe(0)
|
|
})
|
|
|
|
it('should use custom logger if provided', () => {
|
|
const customLogger = {
|
|
debug: vi.fn(),
|
|
info: vi.fn(),
|
|
warn: vi.fn(),
|
|
error: vi.fn()
|
|
} as unknown as typeof logger
|
|
|
|
const tracker = new PerformanceTracker('TestService', 1000, customLogger)
|
|
tracker.recordDuration(100)
|
|
|
|
// Should use custom logger
|
|
expect(customLogger.debug).not.toHaveBeenCalled() // We called recordDuration directly
|
|
tracker.logSummary()
|
|
expect(customLogger.info).toHaveBeenCalled()
|
|
})
|
|
})
|
|
|
|
describe('createPerformanceTracker', () => {
|
|
it('should create a tracker with default threshold', () => {
|
|
const tracker = createPerformanceTracker('MyService')
|
|
|
|
expect(tracker).toBeInstanceOf(PerformanceTracker)
|
|
const metrics = tracker.getMetrics()
|
|
expect(metrics.count).toBe(0)
|
|
})
|
|
|
|
it('should create a tracker with custom threshold', () => {
|
|
const tracker = createPerformanceTracker('FastService', 100)
|
|
|
|
tracker.recordDuration(150)
|
|
|
|
const metrics = tracker.getMetrics()
|
|
expect(metrics.slowOperationCount).toBe(1) // 150 > 100
|
|
})
|
|
|
|
it('should use operation name in logs', async () => {
|
|
const tracker = createPerformanceTracker('MyCustomService', 1000)
|
|
|
|
const mockFn = vi.fn().mockResolvedValue('result')
|
|
await tracker.track('TestOperation', mockFn)
|
|
|
|
expect(logger.debug).toHaveBeenCalled()
|
|
const call = (logger.debug as Mock).mock.calls[0][0]
|
|
expect(call).toContain('[MyCustomService]')
|
|
expect(call).toContain('TestOperation')
|
|
})
|
|
})
|
|
|
|
describe('Integration scenarios', () => {
|
|
it('should track a sequence of operations with varying speeds', async () => {
|
|
const tracker = new PerformanceTracker('DataPipeline', 100)
|
|
|
|
const fastOp = vi.fn().mockResolvedValue('fast')
|
|
const mediumOp = vi
|
|
.fn()
|
|
.mockImplementation(() => new Promise((resolve) => setTimeout(() => resolve('medium'), 50)))
|
|
const slowOp = vi
|
|
.fn()
|
|
.mockImplementation(() => new Promise((resolve) => setTimeout(() => resolve('slow'), 200)))
|
|
|
|
await tracker.track('FastExtract', fastOp)
|
|
await tracker.track('MediumTransform', mediumOp)
|
|
await tracker.track('SlowLoad', slowOp)
|
|
|
|
const metrics = tracker.getMetrics()
|
|
expect(metrics.count).toBe(3)
|
|
expect(metrics.slowOperationCount).toBe(1) // Only SlowLoad > 100ms
|
|
expect(metrics.maxDurationMs).toBeGreaterThan(150)
|
|
})
|
|
|
|
it('should handle errors gracefully in tracker', async () => {
|
|
const tracker = new PerformanceTracker('ErrorProneService', 1000)
|
|
|
|
const errorFn = vi.fn().mockRejectedValue(new Error('Expected error'))
|
|
|
|
await expect(tracker.track('FailingOp', errorFn)).rejects.toThrow('Expected error')
|
|
|
|
expect(logger.error).toHaveBeenCalled()
|
|
const errorCall = (logger.error as Mock).mock.calls[0][0]
|
|
expect(errorCall).toContain('[ErrorProneService]')
|
|
expect(errorCall).toContain('failed after')
|
|
})
|
|
})
|
|
|
|
describe('Constants', () => {
|
|
it('should export DEFAULT_SLOW_THRESHOLD_MS as 1000', () => {
|
|
expect(DEFAULT_SLOW_THRESHOLD_MS).toBe(1000)
|
|
})
|
|
})
|
|
})
|