From aff306aa86dfca1530c917e05abee9f003c0da32 Mon Sep 17 00:00:00 2001 From: Sean McManus Date: Mon, 14 Sep 2026 07:11:59 -0700 Subject: [PATCH] Batch native debug Output writes --- Extension/src/Utility/Async/batchedWriter.ts | 65 ++++++ Extension/src/logger.ts | 13 +- Extension/src/main.ts | 10 +- Extension/test/unit/batchedWriter.test.ts | 225 ++++++++++++++++++ Extension/test/unit/logger.test.ts | 230 +++++++++++++++++++ 5 files changed, 538 insertions(+), 5 deletions(-) create mode 100644 Extension/src/Utility/Async/batchedWriter.ts create mode 100644 Extension/test/unit/batchedWriter.test.ts create mode 100644 Extension/test/unit/logger.test.ts diff --git a/Extension/src/Utility/Async/batchedWriter.ts b/Extension/src/Utility/Async/batchedWriter.ts new file mode 100644 index 000000000..9c0c36e2b --- /dev/null +++ b/Extension/src/Utility/Async/batchedWriter.ts @@ -0,0 +1,65 @@ +/* -------------------------------------------------------------------------------------------- + * Copyright (c) Microsoft Corporation. All Rights Reserved. + * See 'LICENSE' in the project root for license information. + * ------------------------------------------------------------------------------------------ */ + +type ScheduleFlush = (callback: () => void, delay: number) => () => void; + +export class BatchedWriter { + private buffer: string = ""; + private cancelFlush: (() => void) | undefined; + private flushGeneration: number = 0; + private disposed: boolean = false; + + constructor( + private readonly writer: (text: string) => void, + private readonly flushLength: number = 64 * 1024, + private readonly flushDelay: number = 50, + private readonly scheduleFlush: ScheduleFlush = (callback, delay) => { + const timer = setTimeout(callback, delay); + return () => clearTimeout(timer); + } + ) { } + + public append(text: string): void { + if (!text) { + return; + } + if (this.disposed) { + this.writer(text); + return; + } + + // Include this append before calling the writer so reentrant appends cannot overtake it. + // Keep each input intact; an oversized input is flushed synchronously, not truncated. + this.buffer += text; + if (this.buffer.length >= this.flushLength) { + this.flush(); + } else if (!this.cancelFlush) { + const generation = this.flushGeneration; + this.cancelFlush = this.scheduleFlush(() => { + if (generation === this.flushGeneration) { + this.flush(); + } + }, this.flushDelay); + } + } + + public flush(): void { + const text = this.buffer; + this.buffer = ""; + const cancel = this.cancelFlush; + this.cancelFlush = undefined; + ++this.flushGeneration; + cancel?.(); + if (text) { + this.writer(text); + } + } + + public dispose(): void { + // Reentrant or late writes must not leave another timer behind during shutdown. + this.disposed = true; + this.flush(); + } +} diff --git a/Extension/src/logger.ts b/Extension/src/logger.ts index d14bb531f..fcb14d9fb 100644 --- a/Extension/src/logger.ts +++ b/Extension/src/logger.ts @@ -11,6 +11,7 @@ import { getLoggingLevel } from './common'; import { sendInstrumentation } from './instrumentation'; import { CppSourceStr } from './LanguageServer/extension'; import { getLocalizedString, LocalizeStringParams } from './LanguageServer/localization'; +import { BatchedWriter } from './Utility/Async/batchedWriter'; nls.config({ messageFormat: nls.MessageFormat.bundle, bundleFormat: nls.BundleFormat.standalone })(); const localize: nls.LocalizeFunc = nls.loadMessageBundle(); @@ -88,7 +89,11 @@ export let debugChannel: vscode.OutputChannel | undefined; export let warningChannel: vscode.OutputChannel | undefined; export let sshChannel: vscode.OutputChannel | undefined; +let nativeDebugLogWriter: BatchedWriter | undefined; + export function getOutputChannel(): vscode.OutputChannel { + // Keep buffered native diagnostics ahead of other writes or operations on this channel. + nativeDebugLogWriter?.flush(); if (!outputChannel) { outputChannel = vscode.window.createOutputChannel(CppSourceStr); // Do not use CppSettings to avoid circular require() @@ -176,10 +181,16 @@ export function showWarning(params: ShowWarningParams): void { export function logLocalized(params: LocalizeStringParams): void { const output: string = getLocalizedString(params); - log(output); + if (!nativeDebugLogWriter) { + const channel = getOutputChannel(); + nativeDebugLogWriter = new BatchedWriter(text => channel.append(text)); + } + // OutputChannel.appendLine adds LF on every platform, independently of os.EOL. + nativeDebugLogWriter.append(`${output}\n`); } export function disposeOutputChannels(): void { + nativeDebugLogWriter?.dispose(); if (outputChannel) { outputChannel.dispose(); } diff --git a/Extension/src/main.ts b/Extension/src/main.ts index 45c1ef903..11ee87ee1 100644 --- a/Extension/src/main.ts +++ b/Extension/src/main.ts @@ -178,11 +178,13 @@ export async function deactivate(): Promise { DebuggerExtension.dispose(); void Telemetry.deactivate().catch(returns.undefined); disposables.forEach(d => d.dispose()); - if (languageServiceDisabled) { - return; + try { + if (!languageServiceDisabled) { + await LanguageServer.deactivate(); + } + } finally { + disposeOutputChannels(); } - await LanguageServer.deactivate(); - disposeOutputChannels(); } async function makeBinariesExecutable(): Promise { diff --git a/Extension/test/unit/batchedWriter.test.ts b/Extension/test/unit/batchedWriter.test.ts new file mode 100644 index 000000000..3570df124 --- /dev/null +++ b/Extension/test/unit/batchedWriter.test.ts @@ -0,0 +1,225 @@ +/* -------------------------------------------------------------------------------------------- + * Copyright (c) Microsoft Corporation. All Rights Reserved. + * See 'LICENSE' in the project root for license information. + * ------------------------------------------------------------------------------------------ */ + +import * as assert from 'assert'; +import { describe, it } from 'mocha'; +import { BatchedWriter } from '../../src/Utility/Async/batchedWriter'; + +interface ScheduledFlush { + callback(): void; + deadline: number; + canceled: boolean; +} + +class TestScheduler { + public readonly timers: ScheduledFlush[] = []; + private now: number = 0; + + public readonly schedule = (callback: () => void, delay: number): (() => void) => { + const timer: ScheduledFlush = { callback, deadline: this.now + delay, canceled: false }; + this.timers.push(timer); + return () => { timer.canceled = true; }; + }; + + public get pendingCount(): number { + return this.timers.filter(timer => !timer.canceled).length; + } + + public advance(milliseconds: number): void { + const end = this.now + milliseconds; + for (; ;) { + const next = this.timers.find(timer => !timer.canceled && timer.deadline <= end); + if (!next) { + break; + } + this.now = next.deadline; + next.canceled = true; + next.callback(); + } + this.now = end; + } +} + +function createWriter(flushLength: number = 64 * 1024, onWrite?: (text: string) => void): { + writer: BatchedWriter; + scheduler: TestScheduler; + chunks: string[]; +} { + const scheduler = new TestScheduler(); + const chunks: string[] = []; + const writer = new BatchedWriter(text => { + chunks.push(text); + onWrite?.(text); + }, flushLength, 50, scheduler.schedule); + return { writer, scheduler, chunks }; +} + +describe('BatchedWriter', () => { + it('preserves all text and ordering in a timer-flushed batch', () => { + const { writer, scheduler, chunks } = createWriter(); + const messages = ['first\n', '\n', ' indented\r\n', '路径/é/😀\n', 'last\0\t\n\n']; + messages.forEach(message => writer.append(message)); + + assert.strictEqual(scheduler.pendingCount, 1); + scheduler.advance(49); + assert.deepStrictEqual(chunks, []); + scheduler.advance(1); + assert.deepStrictEqual(chunks, [messages.join('')]); + assert.strictEqual(scheduler.pendingCount, 0); + }); + + it('does not postpone the first message deadline when more text arrives', () => { + const { writer, scheduler, chunks } = createWriter(); + writer.append('first\n'); + scheduler.advance(30); + writer.append('second\n'); + scheduler.advance(19); + assert.deepStrictEqual(chunks, []); + scheduler.advance(1); + assert.deepStrictEqual(chunks, ['first\nsecond\n']); + assert.strictEqual(scheduler.timers.length, 1); + }); + + it('flushes synchronously at the size threshold and cancels the timer', () => { + const { writer, scheduler, chunks } = createWriter(8); + writer.append('abc'); + writer.append('defgh'); + + assert.deepStrictEqual(chunks, ['abcdefgh']); + assert.strictEqual(scheduler.pendingCount, 0); + scheduler.timers[0].callback(); + scheduler.advance(50); + assert.deepStrictEqual(chunks, ['abcdefgh']); + }); + + it('keeps the complete threshold-crossing input in order', () => { + const { writer, scheduler, chunks } = createWriter(8); + writer.append('first-'); + writer.append('second'); + + assert.deepStrictEqual(chunks, ['first-second']); + assert.strictEqual(scheduler.pendingCount, 0); + }); + + it('writes an oversized input completely without splitting Unicode', () => { + const { writer, scheduler, chunks } = createWriter(8); + const oversized = '😀路径'.repeat(100) + '\r\n'; + writer.append('prefix\n'); + writer.append(oversized); + + assert.deepStrictEqual(chunks, ['prefix\n' + oversized]); + assert.strictEqual(scheduler.pendingCount, 0); + writer.append('tail\n'); + scheduler.advance(50); + assert.deepStrictEqual( + Buffer.concat(chunks.map(chunk => Buffer.from(chunk))), + Buffer.from('prefix\n' + oversized + 'tail\n')); + }); + + it('does not retain empty writes or create timers for them', () => { + const { writer, scheduler, chunks } = createWriter(); + writer.append(''); + writer.flush(); + writer.dispose(); + + assert.deepStrictEqual(chunks, []); + assert.strictEqual(scheduler.timers.length, 0); + }); + + it('ignores a canceled callback even after the next batch starts', () => { + const { writer, scheduler, chunks } = createWriter(); + writer.append('first'); + const canceledCallback = scheduler.timers[0].callback; + writer.flush(); + writer.flush(); + writer.append('second'); + canceledCallback(); + + assert.deepStrictEqual(chunks, ['first']); + assert.strictEqual(scheduler.pendingCount, 1); + scheduler.advance(50); + assert.deepStrictEqual(chunks, ['first', 'second']); + writer.flush(); + assert.deepStrictEqual(chunks, ['first', 'second']); + }); + + it('retains a reentrant append after all text that triggered a size flush', () => { + const { writer, scheduler, chunks } = createWriter(8, text => { + if (text === 'first-second') { + writer.append('third'); + } + }); + writer.append('first-'); + writer.append('second'); + + assert.deepStrictEqual(chunks, ['first-second']); + assert.strictEqual(scheduler.pendingCount, 1); + scheduler.advance(50); + assert.deepStrictEqual(chunks, ['first-second', 'third']); + assert.strictEqual(scheduler.pendingCount, 0); + }); + + it('retains reentrant text and its own deadline during a timer flush', () => { + const { writer, scheduler, chunks } = createWriter(undefined, text => { + if (text === 'first') { + writer.append('second'); + } + }); + writer.append('first'); + scheduler.advance(50); + + assert.deepStrictEqual(chunks, ['first']); + assert.strictEqual(scheduler.pendingCount, 1); + scheduler.advance(49); + assert.deepStrictEqual(chunks, ['first']); + scheduler.advance(1); + assert.deepStrictEqual(chunks, ['first', 'second']); + assert.strictEqual(scheduler.pendingCount, 0); + }); + + it('flushes pending and reentrant text on disposal without rearming', () => { + const { writer, scheduler, chunks } = createWriter(undefined, text => { + if (text === 'first') { + writer.append('second'); + } + }); + writer.append('first'); + const canceledCallback = scheduler.timers[0].callback; + writer.dispose(); + writer.dispose(); + canceledCallback(); + scheduler.advance(100); + + assert.deepStrictEqual(chunks, ['first', 'second']); + assert.strictEqual(scheduler.pendingCount, 0); + writer.append('late'); + assert.deepStrictEqual(chunks, ['first', 'second', 'late']); + assert.strictEqual(scheduler.pendingCount, 0); + }); + + it('bounds pending text and substantially reduces writes for a large burst', () => { + const flushLength = 64 * 1024; + let writtenLength = 0; + const { writer, scheduler, chunks } = createWriter(flushLength, text => { writtenLength += text.length; }); + const messages: string[] = []; + let receivedLength = 0; + for (let index = 0; index < 10000; ++index) { + const message = ` /workspace/路径/directory/file-${index}.cpp\r\n`; + messages.push(message); + receivedLength += message.length; + writer.append(message); + assert.ok(receivedLength - writtenLength < flushLength); + assert.ok(scheduler.pendingCount <= 1); + } + writer.dispose(); + + assert.deepStrictEqual( + Buffer.concat(chunks.map(chunk => Buffer.from(chunk))), + Buffer.from(messages.join(''))); + assert.ok(chunks.length < messages.length / 100); + assert.strictEqual(writtenLength, receivedLength); + assert.strictEqual(scheduler.pendingCount, 0); + }); +}); diff --git a/Extension/test/unit/logger.test.ts b/Extension/test/unit/logger.test.ts new file mode 100644 index 000000000..4f909cf42 --- /dev/null +++ b/Extension/test/unit/logger.test.ts @@ -0,0 +1,230 @@ +/* -------------------------------------------------------------------------------------------- + * Copyright (c) Microsoft Corporation. All Rights Reserved. + * See 'LICENSE' in the project root for license information. + * ------------------------------------------------------------------------------------------ */ + +import * as assert from 'assert'; +import { afterEach, beforeEach, describe, it } from 'mocha'; +import * as sinon from 'sinon'; +import type * as vscode from 'vscode'; +import type { LocalizeStringParams } from '../../src/LanguageServer/localization'; +import proxyquire = require('proxyquire'); + +type LoggerModule = typeof import('../../src/logger'); + +function createLogger(eol: string = '\n') { + const chunks: string[] = []; + let disposed = false; + const write = (text: string): void => { + assert.ok(!disposed, 'Output must be written before channel disposal'); + chunks.push(text); + }; + const append = sinon.spy(write); + const appendLine = sinon.spy((text: string): void => write(text + '\n')); + const show = sinon.spy(); + const dispose = sinon.spy(() => { disposed = true; }); + const channel: vscode.OutputChannel = { + name: 'C/C++', append, appendLine, show, dispose, + hide: sinon.spy(), clear: sinon.spy(), replace: sinon.spy() + }; + const createOutputChannel = sinon.stub().returns(channel); + const getLoggingLevel = sinon.stub().returns(7); + const sendInstrumentation = sinon.spy(); + const load = proxyquire.noCallThru(); + const localization = load('../../src/LanguageServer/localization', { + '../common': {}, + '../nativeStrings': { lookupString: (_id: number, args: string[]): string => `Translated: ${args.join(' ')}` } + }) as typeof import('../../src/LanguageServer/localization'); + const getLocalizedString = sinon.spy(localization.getLocalizedString); + const logger = load('../../src/logger', { + os: { EOL: eol }, + vscode: { window: { createOutputChannel } }, + './common': { getLoggingLevel }, + './instrumentation': { sendInstrumentation }, + './LanguageServer/extension': { CppSourceStr: 'C/C++' }, + './LanguageServer/localization': { getLocalizedString } + }) as LoggerModule; + return { logger, chunks, append, appendLine, show, dispose, createOutputChannel, getLoggingLevel, getLocalizedString, sendInstrumentation }; +} + +function message(text: string, indentSpaces: number = 0): LocalizeStringParams { + return { text, indentSpaces, stringId: 0, stringArgs: [] }; +} + +function loadDeactivation(logger: LoggerModule, deactivate: () => Promise): () => Promise { + const main = proxyquire.noCallThru()('../../src/main', { + vscode: {}, + 'vscode-tas-client': {}, + './Debugger/extension': { dispose: (): void => { } }, + './LanguageServer/extension': { deactivate }, + './common': {}, + './telemetry': { deactivate: async (): Promise => { } }, + './LanguageServer/cppBuildTaskProvider': {}, + './LanguageServer/localization': {}, + './LanguageServer/persistentState': {}, + './LanguageServer/settings': {}, + './Utility/Async/returns': { returns: { undefined: (): void => { } } }, + './cppTools1': { CppTools1: class { } }, + './id': {}, + './instrumentation': {}, + './logger': logger, + './platform': {} + }) as typeof import('../../src/main'); + return main.deactivate; +} + +describe('Native debug log output', () => { + let clock: sinon.SinonFakeTimers; + let fixture: ReturnType; + + beforeEach(() => { + clock = sinon.useFakeTimers({ toFake: ['setTimeout', 'clearTimeout'] }); + fixture = createLogger(); + }); + + afterEach(() => { + try { + fixture.logger.disposeOutputChannels(); + } finally { + clock.restore(); + } + }); + + for (const eol of ['\n', '\r\n']) { + it(`preserves localization and appendLine LF when os.EOL is ${JSON.stringify(eol)}`, () => { + fixture = createLogger(eol); + const params = [ + message('first\r\nsecond', 2), + message(''), + message('already terminated\n'), + message(' trailing \t\0😀'), + { text: 'fallback', stringId: 1, stringArgs: ['é', '路径'], indentSpaces: 4 } + ]; + params.forEach(param => fixture.logger.logLocalized(param)); + params[0].text = 'changed after notification'; + + assert.strictEqual(fixture.getLocalizedString.callCount, params.length); + assert.deepStrictEqual(fixture.chunks, ['loggingLevel: 7\n']); + clock.tick(49); + assert.strictEqual(fixture.append.callCount, 0); + clock.tick(1); + assert.deepStrictEqual(fixture.chunks, [ + 'loggingLevel: 7\n', + ' first\r\nsecond\n\nalready terminated\n\n trailing \t\0😀\n Translated: é 路径\n' + ]); + assert.strictEqual(fixture.append.callCount, 1); + assert.strictEqual(fixture.appendLine.callCount, 1); + assert.strictEqual(fixture.createOutputChannel.callCount, 1); + assert.strictEqual(fixture.show.callCount, 0); + }); + } + + it('keeps native and ordinary diagnostics in order without delaying ordinary writes', () => { + fixture = createLogger('\r\n'); + const subscriber = sinon.spy(); + fixture.logger.subscribeToAllLoggers(subscriber); + fixture.logger.logLocalized(message('native first')); + fixture.logger.log('ordinary'); + fixture.logger.logLocalized(message('native second')); + fixture.logger.getOutputChannelLogger().appendLineAtLevel(7, 'extension'); + fixture.logger.logLocalized(message('native third')); + fixture.logger.getOutputChannel().append('direct'); + + assert.strictEqual(fixture.chunks.join(''), + 'loggingLevel: 7\nnative first\nordinary\nnative second\nextension\r\nnative third\ndirect'); + assert.ok(subscriber.calledOnceWithExactly('extension\r\n')); + assert.strictEqual(fixture.sendInstrumentation.callCount, 1); + assert.strictEqual(clock.countTimers(), 0); + clock.tick(100); + assert.strictEqual(fixture.chunks.length, 7); + }); + + it('does not introduce logging-level filtering or show the Output panel', () => { + fixture.getLoggingLevel.returns(0); + fixture.logger.logLocalized(message('native diagnostic')); + clock.tick(50); + + assert.deepStrictEqual(fixture.chunks, ['native diagnostic\n']); + assert.strictEqual(fixture.show.callCount, 0); + fixture.logger.getOutputChannelLogger().appendLineAtLevel(1, 'filtered extension diagnostic'); + assert.deepStrictEqual(fixture.chunks, ['native diagnostic\n']); + }); + + it('flushes before an explicit request to show the channel', () => { + fixture.logger.logLocalized(message('pending')); + fixture.logger.showOutputChannel(); + + assert.deepStrictEqual(fixture.chunks, ['loggingLevel: 7\n', 'pending\n']); + assert.strictEqual(fixture.show.callCount, 1); + assert.strictEqual(clock.countTimers(), 0); + }); + + it('flushes once before disposing the channel and cancels its timer', () => { + fixture.logger.logLocalized(message('last diagnostic')); + fixture.logger.disposeOutputChannels(); + fixture.logger.disposeOutputChannels(); + + assert.deepStrictEqual(fixture.chunks, ['loggingLevel: 7\n', 'last diagnostic\n']); + assert.ok(fixture.append.calledBefore(fixture.dispose)); + assert.strictEqual(clock.countTimers(), 0); + clock.tick(1000); + assert.strictEqual(fixture.append.callCount, 1); + }); + + it('does not create a channel when disposing an unused logger', () => { + fixture.logger.disposeOutputChannels(); + assert.strictEqual(fixture.createOutputChannel.callCount, 0); + assert.strictEqual(clock.countTimers(), 0); + }); + + it('continues flushing during delayed shutdown and flushes the final diagnostics before disposal', async () => { + let completeShutdown: () => void = () => { throw new Error('Shutdown promise was not initialized'); }; + const shutdown = new Promise(resolve => { completeShutdown = resolve; }); + const deactivate = loadDeactivation(fixture.logger, () => shutdown); + fixture.logger.logLocalized(message('before shutdown')); + const deactivation = deactivate(); + fixture.logger.logLocalized(message('during shutdown')); + clock.tick(50); + + assert.strictEqual(fixture.dispose.callCount, 0); + assert.strictEqual(fixture.chunks.join(''), 'loggingLevel: 7\nbefore shutdown\nduring shutdown\n'); + fixture.logger.logLocalized(message('last diagnostic')); + completeShutdown(); + await deactivation; + + assert.strictEqual(fixture.chunks.join(''), 'loggingLevel: 7\nbefore shutdown\nduring shutdown\nlast diagnostic\n'); + assert.ok(fixture.append.calledBefore(fixture.dispose)); + assert.strictEqual(fixture.dispose.callCount, 1); + assert.strictEqual(clock.countTimers(), 0); + }); + + it('flushes and disposes Output even if language-server shutdown rejects', async () => { + const failure = new Error('Language-server shutdown failed'); + const deactivate = loadDeactivation(fixture.logger, async () => { + fixture.logger.logLocalized(message('shutdown diagnostic')); + throw failure; + }); + fixture.logger.logLocalized(message('pending')); + await assert.rejects(deactivate(), failure); + + assert.strictEqual(fixture.chunks.join(''), 'loggingLevel: 7\npending\nshutdown diagnostic\n'); + assert.ok(fixture.append.calledBefore(fixture.dispose)); + assert.strictEqual(fixture.dispose.callCount, 1); + assert.strictEqual(clock.countTimers(), 0); + }); + + it('coalesces a notification burst into substantially fewer channel appends', () => { + const messages: string[] = []; + for (let index = 0; index < 10000; ++index) { + const text = `/workspace/directory/file-${index}.cpp`; + messages.push(text + '\n'); + fixture.logger.logLocalized(message(text)); + } + fixture.logger.disposeOutputChannels(); + + assert.strictEqual(fixture.chunks.join(''), 'loggingLevel: 7\n' + messages.join('')); + assert.ok(fixture.append.callCount < messages.length / 100); + assert.strictEqual(fixture.appendLine.callCount, 1); + assert.strictEqual(clock.countTimers(), 0); + }); +});