|
| 1 | +import { vi, describe, it, expect, beforeEach, afterEach } from 'vitest'; |
| 2 | +import * as fs from 'node:fs'; |
| 3 | +import { |
| 4 | + initStartupProfiler, |
| 5 | + profileCheckpoint, |
| 6 | + finalizeStartupProfile, |
| 7 | + getStartupReport, |
| 8 | + resetStartupProfiler, |
| 9 | +} from './startupProfiler.js'; |
| 10 | + |
| 11 | +vi.mock('node:fs'); |
| 12 | + |
| 13 | +describe('startupProfiler', () => { |
| 14 | + const savedEnv: Record<string, string | undefined> = {}; |
| 15 | + |
| 16 | + function saveEnv(...keys: string[]) { |
| 17 | + for (const k of keys) { |
| 18 | + savedEnv[k] = process.env[k]; |
| 19 | + } |
| 20 | + } |
| 21 | + |
| 22 | + function restoreEnv() { |
| 23 | + for (const [k, v] of Object.entries(savedEnv)) { |
| 24 | + if (v !== undefined) { |
| 25 | + process.env[k] = v; |
| 26 | + } else { |
| 27 | + delete process.env[k]; |
| 28 | + } |
| 29 | + } |
| 30 | + } |
| 31 | + |
| 32 | + beforeEach(() => { |
| 33 | + resetStartupProfiler(); |
| 34 | + vi.restoreAllMocks(); |
| 35 | + saveEnv('QWEN_CODE_PROFILE_STARTUP', 'SANDBOX'); |
| 36 | + delete process.env['QWEN_CODE_PROFILE_STARTUP']; |
| 37 | + delete process.env['SANDBOX']; |
| 38 | + }); |
| 39 | + |
| 40 | + afterEach(() => { |
| 41 | + restoreEnv(); |
| 42 | + }); |
| 43 | + |
| 44 | + function enableProfiler() { |
| 45 | + process.env['QWEN_CODE_PROFILE_STARTUP'] = '1'; |
| 46 | + process.env['SANDBOX'] = '1'; |
| 47 | + } |
| 48 | + |
| 49 | + describe('when disabled (no env var)', () => { |
| 50 | + it('should return null from getStartupReport', () => { |
| 51 | + initStartupProfiler(); |
| 52 | + profileCheckpoint('test'); |
| 53 | + expect(getStartupReport()).toBeNull(); |
| 54 | + }); |
| 55 | + |
| 56 | + it('should not write any files on finalize', () => { |
| 57 | + initStartupProfiler(); |
| 58 | + profileCheckpoint('test'); |
| 59 | + finalizeStartupProfile('session-1'); |
| 60 | + expect(fs.mkdirSync).not.toHaveBeenCalled(); |
| 61 | + expect(fs.writeFileSync).not.toHaveBeenCalled(); |
| 62 | + }); |
| 63 | + }); |
| 64 | + |
| 65 | + describe('when outside sandbox (SANDBOX not set)', () => { |
| 66 | + it('should not enable profiler even with QWEN_CODE_PROFILE_STARTUP=1', () => { |
| 67 | + process.env['QWEN_CODE_PROFILE_STARTUP'] = '1'; |
| 68 | + delete process.env['SANDBOX']; |
| 69 | + |
| 70 | + initStartupProfiler(); |
| 71 | + profileCheckpoint('test'); |
| 72 | + expect(getStartupReport()).toBeNull(); |
| 73 | + }); |
| 74 | + }); |
| 75 | + |
| 76 | + describe('when enabled (QWEN_CODE_PROFILE_STARTUP=1 + SANDBOX)', () => { |
| 77 | + beforeEach(() => { |
| 78 | + enableProfiler(); |
| 79 | + }); |
| 80 | + |
| 81 | + it('should collect checkpoints and return a report', () => { |
| 82 | + initStartupProfiler(); |
| 83 | + profileCheckpoint('phase_a'); |
| 84 | + profileCheckpoint('phase_b'); |
| 85 | + profileCheckpoint('phase_c'); |
| 86 | + |
| 87 | + const report = getStartupReport(); |
| 88 | + expect(report).not.toBeNull(); |
| 89 | + expect(report!.phases).toHaveLength(3); |
| 90 | + expect(report!.phases[0]!.name).toBe('phase_a'); |
| 91 | + expect(report!.phases[1]!.name).toBe('phase_b'); |
| 92 | + expect(report!.phases[2]!.name).toBe('phase_c'); |
| 93 | + expect(report!.totalMs).toBeGreaterThanOrEqual(0); |
| 94 | + expect(report!.processUptimeAtT0Ms).toBeGreaterThan(0); |
| 95 | + expect(report!.nodeVersion).toBe(process.version); |
| 96 | + expect(report!.platform).toBe(process.platform); |
| 97 | + expect(report!.arch).toBe(process.arch); |
| 98 | + }); |
| 99 | + |
| 100 | + it('should have non-negative durations for each phase', () => { |
| 101 | + initStartupProfiler(); |
| 102 | + profileCheckpoint('a'); |
| 103 | + profileCheckpoint('b'); |
| 104 | + |
| 105 | + const report = getStartupReport(); |
| 106 | + for (const phase of report!.phases) { |
| 107 | + expect(phase.durationMs).toBeGreaterThanOrEqual(0); |
| 108 | + expect(phase.startMs).toBeGreaterThanOrEqual(0); |
| 109 | + } |
| 110 | + }); |
| 111 | + |
| 112 | + it('should write JSON file on finalize and print path to stderr', () => { |
| 113 | + vi.mocked(fs.mkdirSync).mockReturnValue(undefined); |
| 114 | + vi.mocked(fs.writeFileSync).mockReturnValue(undefined); |
| 115 | + const stderrSpy = vi |
| 116 | + .spyOn(process.stderr, 'write') |
| 117 | + .mockReturnValue(true); |
| 118 | + |
| 119 | + initStartupProfiler(); |
| 120 | + profileCheckpoint('main_entry'); |
| 121 | + profileCheckpoint('after_load_settings'); |
| 122 | + finalizeStartupProfile('test-session-123'); |
| 123 | + |
| 124 | + expect(fs.mkdirSync).toHaveBeenCalledWith( |
| 125 | + expect.stringContaining('startup-perf'), |
| 126 | + { recursive: true }, |
| 127 | + ); |
| 128 | + expect(fs.writeFileSync).toHaveBeenCalledTimes(1); |
| 129 | + |
| 130 | + const writtenPath = vi.mocked(fs.writeFileSync).mock |
| 131 | + .calls[0]![0] as string; |
| 132 | + expect(writtenPath).toContain('startup-perf'); |
| 133 | + expect(writtenPath).toContain('test-session-123'); |
| 134 | + expect(writtenPath).toMatch(/\.json$/); |
| 135 | + |
| 136 | + const writtenContent = JSON.parse( |
| 137 | + vi.mocked(fs.writeFileSync).mock.calls[0]![1] as string, |
| 138 | + ); |
| 139 | + expect(writtenContent.sessionId).toBe('test-session-123'); |
| 140 | + expect(writtenContent.phases).toHaveLength(2); |
| 141 | + expect(writtenContent.totalMs).toBeGreaterThanOrEqual(0); |
| 142 | + |
| 143 | + expect(stderrSpy).toHaveBeenCalledWith( |
| 144 | + expect.stringContaining('Startup profile written to:'), |
| 145 | + ); |
| 146 | + }); |
| 147 | + |
| 148 | + it('should use report timestamp for filename (no double Date call)', () => { |
| 149 | + vi.mocked(fs.mkdirSync).mockReturnValue(undefined); |
| 150 | + vi.mocked(fs.writeFileSync).mockReturnValue(undefined); |
| 151 | + vi.spyOn(process.stderr, 'write').mockReturnValue(true); |
| 152 | + |
| 153 | + initStartupProfiler(); |
| 154 | + profileCheckpoint('test'); |
| 155 | + finalizeStartupProfile('s1'); |
| 156 | + |
| 157 | + const writtenPath = vi.mocked(fs.writeFileSync).mock |
| 158 | + .calls[0]![0] as string; |
| 159 | + const writtenContent = JSON.parse( |
| 160 | + vi.mocked(fs.writeFileSync).mock.calls[0]![1] as string, |
| 161 | + ); |
| 162 | + // Filename should contain the same timestamp as the report (with colons/dots replaced) |
| 163 | + const expectedTs = writtenContent.timestamp.replace(/[:.]/g, '-'); |
| 164 | + expect(writtenPath).toContain(expectedTs); |
| 165 | + }); |
| 166 | + |
| 167 | + it('should not finalize twice', () => { |
| 168 | + vi.mocked(fs.mkdirSync).mockReturnValue(undefined); |
| 169 | + vi.mocked(fs.writeFileSync).mockReturnValue(undefined); |
| 170 | + vi.spyOn(process.stderr, 'write').mockReturnValue(true); |
| 171 | + |
| 172 | + initStartupProfiler(); |
| 173 | + profileCheckpoint('test'); |
| 174 | + finalizeStartupProfile('s1'); |
| 175 | + finalizeStartupProfile('s1'); |
| 176 | + |
| 177 | + expect(fs.writeFileSync).toHaveBeenCalledTimes(1); |
| 178 | + }); |
| 179 | + |
| 180 | + it('should use "unknown" as sessionId in both filename and JSON when not provided', () => { |
| 181 | + vi.mocked(fs.mkdirSync).mockReturnValue(undefined); |
| 182 | + vi.mocked(fs.writeFileSync).mockReturnValue(undefined); |
| 183 | + vi.spyOn(process.stderr, 'write').mockReturnValue(true); |
| 184 | + |
| 185 | + initStartupProfiler(); |
| 186 | + profileCheckpoint('test'); |
| 187 | + finalizeStartupProfile(); |
| 188 | + |
| 189 | + const writtenPath = vi.mocked(fs.writeFileSync).mock |
| 190 | + .calls[0]![0] as string; |
| 191 | + expect(writtenPath).toContain('unknown'); |
| 192 | + |
| 193 | + const writtenContent = JSON.parse( |
| 194 | + vi.mocked(fs.writeFileSync).mock.calls[0]![1] as string, |
| 195 | + ); |
| 196 | + expect(writtenContent.sessionId).toBe('unknown'); |
| 197 | + }); |
| 198 | + |
| 199 | + it('should not throw when file write fails', () => { |
| 200 | + vi.mocked(fs.mkdirSync).mockImplementation(() => { |
| 201 | + throw new Error('Permission denied'); |
| 202 | + }); |
| 203 | + const stderrSpy = vi |
| 204 | + .spyOn(process.stderr, 'write') |
| 205 | + .mockReturnValue(true); |
| 206 | + |
| 207 | + initStartupProfiler(); |
| 208 | + profileCheckpoint('test'); |
| 209 | + |
| 210 | + expect(() => finalizeStartupProfile('s1')).not.toThrow(); |
| 211 | + expect(stderrSpy).toHaveBeenCalledWith( |
| 212 | + expect.stringContaining('Warning'), |
| 213 | + ); |
| 214 | + }); |
| 215 | + |
| 216 | + it('should return null after reset', () => { |
| 217 | + initStartupProfiler(); |
| 218 | + profileCheckpoint('test'); |
| 219 | + expect(getStartupReport()).not.toBeNull(); |
| 220 | + |
| 221 | + resetStartupProfiler(); |
| 222 | + expect(getStartupReport()).toBeNull(); |
| 223 | + }); |
| 224 | + }); |
| 225 | +}); |
0 commit comments