|
| 1 | +#!/usr/bin/env node |
| 2 | + |
| 3 | +/** |
| 4 | + * Benchmark to measure performance overhead of transport injection |
| 5 | + * Compares logging performance with and without transport injection |
| 6 | + */ |
| 7 | + |
| 8 | +const { performance } = require('perf_hooks') |
| 9 | + |
| 10 | +// Test configurations |
| 11 | +const NUM_LOGS = 10000 |
| 12 | +const WARMUP_LOGS = 1000 |
| 13 | + |
| 14 | +console.log('\n=== Transport Injection Performance Benchmark ===\n') |
| 15 | +console.log(`Iterations: ${NUM_LOGS.toLocaleString()}`) |
| 16 | +console.log(`Warmup: ${WARMUP_LOGS.toLocaleString()}\n`) |
| 17 | + |
| 18 | +// Helper to measure performance |
| 19 | +function benchmark(name, fn) { |
| 20 | + // Warmup |
| 21 | + for (let i = 0; i < WARMUP_LOGS; i++) { |
| 22 | + fn() |
| 23 | + } |
| 24 | + |
| 25 | + // Force GC if available |
| 26 | + if (global.gc) global.gc() |
| 27 | + |
| 28 | + // Actual benchmark |
| 29 | + const start = performance.now() |
| 30 | + for (let i = 0; i < NUM_LOGS; i++) { |
| 31 | + fn() |
| 32 | + } |
| 33 | + const end = performance.now() |
| 34 | + |
| 35 | + const totalMs = end - start |
| 36 | + const perLogUs = (totalMs * 1000) / NUM_LOGS |
| 37 | + |
| 38 | + console.log(`${name}:`) |
| 39 | + console.log(` Total: ${totalMs.toFixed(2)}ms`) |
| 40 | + console.log(` Per-log: ${perLogUs.toFixed(3)}μs`) |
| 41 | + console.log(` Rate: ${(NUM_LOGS / (totalMs / 1000)).toFixed(0)} logs/sec`) |
| 42 | + console.log('') |
| 43 | + |
| 44 | + return { totalMs, perLogUs } |
| 45 | +} |
| 46 | + |
| 47 | +// ==================== WINSTON ==================== |
| 48 | +console.log('--- Winston ---\n') |
| 49 | + |
| 50 | +// Without transport injection |
| 51 | +const winston1 = require('winston') |
| 52 | +const winstonLoggerBaseline = winston1.createLogger({ |
| 53 | + level: 'info', |
| 54 | + format: winston1.format.json(), |
| 55 | + transports: [new winston1.transports.Console({ silent: true })] |
| 56 | +}) |
| 57 | + |
| 58 | +const winstonBaseline = benchmark('Winston (baseline)', () => { |
| 59 | + winstonLoggerBaseline.info('test message', { userId: 12345, action: 'test' }) |
| 60 | +}) |
| 61 | + |
| 62 | +// With transport injection |
| 63 | +process.env.DD_LOG_CAPTURE_ENABLED = 'true' |
| 64 | +process.env.DD_LOG_CAPTURE_METHOD = 'transport' |
| 65 | +process.env.DD_LOG_CAPTURE_HOST = 'localhost' |
| 66 | +process.env.DD_LOG_CAPTURE_PORT = '9999' // Non-existent server (buffering only) |
| 67 | +process.env.DD_LOG_CAPTURE_FLUSH_INTERVAL_MS = '999999' // Very long (no flushing during test) |
| 68 | +process.env.DD_LOGS_INJECTION = 'true' |
| 69 | + |
| 70 | +require('../../index').init({ |
| 71 | + service: 'benchmark-test', |
| 72 | + env: 'test', |
| 73 | + version: '1.0.0' |
| 74 | +}) |
| 75 | + |
| 76 | +const winston2 = require('winston') |
| 77 | +const winstonLoggerWithTransport = winston2.createLogger({ |
| 78 | + level: 'info', |
| 79 | + format: winston2.format.json(), |
| 80 | + transports: [new winston2.transports.Console({ silent: true })] |
| 81 | +}) |
| 82 | + |
| 83 | +const winstonWithTransport = benchmark('Winston (with transport)', () => { |
| 84 | + winstonLoggerWithTransport.info('test message', { userId: 12345, action: 'test' }) |
| 85 | +}) |
| 86 | + |
| 87 | +const winstonOverheadUs = winstonWithTransport.perLogUs - winstonBaseline.perLogUs |
| 88 | +const winstonOverheadPct = ((winstonOverheadUs / winstonBaseline.perLogUs) * 100).toFixed(1) |
| 89 | +console.log(`Winston Overhead: ${winstonOverheadUs.toFixed(3)}μs (${winstonOverheadPct}%)\n`) |
| 90 | + |
| 91 | +// ==================== BUNYAN ==================== |
| 92 | +console.log('--- Bunyan ---\n') |
| 93 | + |
| 94 | +// Without transport injection |
| 95 | +delete require.cache[require.resolve('bunyan')] |
| 96 | +const bunyan1 = require('bunyan') |
| 97 | +const bunyanLoggerBaseline = bunyan1.createLogger({ |
| 98 | + name: 'benchmark-baseline', |
| 99 | + level: 'info', |
| 100 | + streams: [{ stream: { write: () => {} } }] // Null stream |
| 101 | +}) |
| 102 | + |
| 103 | +const bunyanBaseline = benchmark('Bunyan (baseline)', () => { |
| 104 | + bunyanLoggerBaseline.info({ userId: 12345, action: 'test' }, 'test message') |
| 105 | +}) |
| 106 | + |
| 107 | +// With transport injection (already initialized tracer above) |
| 108 | +delete require.cache[require.resolve('bunyan')] |
| 109 | +const bunyan2 = require('bunyan') |
| 110 | +const bunyanLoggerWithTransport = bunyan2.createLogger({ |
| 111 | + name: 'benchmark-with-transport', |
| 112 | + level: 'info', |
| 113 | + streams: [{ stream: { write: () => {} } }] // Null stream |
| 114 | +}) |
| 115 | + |
| 116 | +const bunyanWithTransport = benchmark('Bunyan (with transport)', () => { |
| 117 | + bunyanLoggerWithTransport.info({ userId: 12345, action: 'test' }, 'test message') |
| 118 | +}) |
| 119 | + |
| 120 | +const bunyanOverheadUs = bunyanWithTransport.perLogUs - bunyanBaseline.perLogUs |
| 121 | +const bunyanOverheadPct = ((bunyanOverheadUs / bunyanBaseline.perLogUs) * 100).toFixed(1) |
| 122 | +console.log(`Bunyan Overhead: ${bunyanOverheadUs.toFixed(3)}μs (${bunyanOverheadPct}%)\n`) |
| 123 | + |
| 124 | +// ==================== PINO ==================== |
| 125 | +console.log('--- Pino ---\n') |
| 126 | + |
| 127 | +// Without transport injection |
| 128 | +const pino1 = require('pino') |
| 129 | +const pinoLoggerBaseline = pino1({ level: 'info' }, { write: () => {} }) // Null destination |
| 130 | + |
| 131 | +const pinoBaseline = benchmark('Pino (baseline)', () => { |
| 132 | + pinoLoggerBaseline.info({ userId: 12345, action: 'test' }, 'test message') |
| 133 | +}) |
| 134 | + |
| 135 | +// With transport injection (already initialized tracer above) |
| 136 | +delete require.cache[require.resolve('pino')] |
| 137 | +const pino2 = require('pino') |
| 138 | +const pinoLoggerWithTransport = pino2({ level: 'info' }, { write: () => {} }) |
| 139 | + |
| 140 | +const pinoWithTransport = benchmark('Pino (with transport)', () => { |
| 141 | + pinoLoggerWithTransport.info({ userId: 12345, action: 'test' }, 'test message') |
| 142 | +}) |
| 143 | + |
| 144 | +const pinoOverheadUs = pinoWithTransport.perLogUs - pinoBaseline.perLogUs |
| 145 | +const pinoOverheadPct = ((pinoOverheadUs / pinoBaseline.perLogUs) * 100).toFixed(1) |
| 146 | +console.log(`Pino Overhead: ${pinoOverheadUs.toFixed(3)}μs (${pinoOverheadPct}%)\n`) |
| 147 | + |
| 148 | +// ==================== SUMMARY ==================== |
| 149 | +console.log('=== Summary ===\n') |
| 150 | +console.log('Per-Log Overhead:') |
| 151 | +console.log(` Winston: ${winstonOverheadUs.toFixed(3)}μs (${winstonOverheadPct}% increase)`) |
| 152 | +console.log(` Bunyan: ${bunyanOverheadUs.toFixed(3)}μs (${bunyanOverheadPct}% increase)`) |
| 153 | +console.log(` Pino: ${pinoOverheadUs.toFixed(3)}μs (${pinoOverheadPct}% increase)`) |
| 154 | +console.log('') |
| 155 | + |
| 156 | +// Memory info |
| 157 | +const memUsage = process.memoryUsage() |
| 158 | +console.log('Memory Usage:') |
| 159 | +console.log(` Heap Used: ${(memUsage.heapUsed / 1024 / 1024).toFixed(2)} MB`) |
| 160 | +console.log(` External: ${(memUsage.external / 1024 / 1024).toFixed(2)} MB`) |
| 161 | +console.log('') |
| 162 | + |
| 163 | +console.log('Note: Run with --expose-gc for accurate memory measurements') |
| 164 | +console.log('Example: node --expose-gc benchmark-overhead.js\n') |
| 165 | + |
| 166 | +process.exit(0) |
0 commit comments