diff --git a/packages/core/src/dev/activation.ts b/packages/core/src/dev/activation.ts index 41af4d2d5fb..0033eaa8548 100644 --- a/packages/core/src/dev/activation.ts +++ b/packages/core/src/dev/activation.ts @@ -24,6 +24,7 @@ import { getSessionId } from '../shared/telemetry/util' import { NotificationsController } from '../notifications/controller' import { DevNotificationsState } from '../notifications/types' import { QuickPickItem } from 'vscode' +import { ChildProcess } from '../shared/utilities/processUtils' interface MenuOption { readonly label: string @@ -44,6 +45,7 @@ export type DevFunction = | 'editAuthConnections' | 'notificationsSend' | 'forceIdeCrash' + | 'startChildProcess' export type DevOptions = { context: vscode.ExtensionContext @@ -126,6 +128,11 @@ const menuOptions: () => Record = () => { detail: `Will SIGKILL ExtHost, { pid: ${process.pid}, sessionId: '${getSessionId().slice(0, 8)}-...' }, but the IDE itself will not crash.`, executor: forceQuitIde, }, + startChildProcess: { + label: 'ChildProcess: Start child process', + detail: 'Start ChildProcess from our utility wrapper for testing', + executor: startChildProcess, + }, } } @@ -578,3 +585,15 @@ async function editNotifications() { await targetNotificationsController.pollForEmergencies() }) } + +async function startChildProcess() { + const result = await createInputBox({ + title: 'Enter a command', + }).prompt() + if (result) { + const [command, ...args] = result?.toString().split(' ') ?? [] + getLogger().info(`Starting child process: '${command}'`) + const processResult = await ChildProcess.run(command, args, { collect: true }) + getLogger().info(`Child process exited with code ${processResult.exitCode}`) + } +} diff --git a/packages/core/src/shared/logger/logger.ts b/packages/core/src/shared/logger/logger.ts index 9cc04aa6585..d5bf5f13380 100644 --- a/packages/core/src/shared/logger/logger.ts +++ b/packages/core/src/shared/logger/logger.ts @@ -5,7 +5,7 @@ import * as vscode from 'vscode' -export type LogTopic = 'crashMonitoring' | 'dev/beta' | 'notifications' | 'test' | 'unknown' +export type LogTopic = 'crashMonitoring' | 'dev/beta' | 'notifications' | 'test' | 'childProcess' | 'unknown' class ErrorLog { constructor( diff --git a/packages/core/src/shared/utilities/pollingSet.ts b/packages/core/src/shared/utilities/pollingSet.ts index d8c4f7c6ded..d344ea4185d 100644 --- a/packages/core/src/shared/utilities/pollingSet.ts +++ b/packages/core/src/shared/utilities/pollingSet.ts @@ -44,9 +44,14 @@ export class PollingSet extends Set { this.clearTimer() } } - + // TODO(hkobew): Overwrite the add method instead of adding seperate method. If we add item to set, timer should always start. public start(id: T): void { this.add(id) this.pollTimer = this.pollTimer ?? globals.clock.setInterval(() => this.poll(), this.interval) } + + public override clear(): void { + this.clearTimer() + super.clear() + } } diff --git a/packages/core/src/shared/utilities/processUtils.ts b/packages/core/src/shared/utilities/processUtils.ts index 2e179da98b8..3fcd7864438 100644 --- a/packages/core/src/shared/utilities/processUtils.ts +++ b/packages/core/src/shared/utilities/processUtils.ts @@ -7,6 +7,8 @@ import * as proc from 'child_process' // eslint-disable-line no-restricted-impor import * as crossSpawn from 'cross-spawn' import * as logger from '../logger' import { Timeout, CancellationError, waitUntil } from './timeoutUtils' +import { PollingSet } from './pollingSet' +import { getLogger } from '../logger/logger' export interface RunParameterContext { /** Reports an error parsed from the stdin/stdout streams. */ @@ -61,6 +63,135 @@ export interface ChildProcessResult { export const eof = Symbol('EOF') +export interface ProcessStats { + memory: number + cpu: number +} +export class ChildProcessTracker { + static readonly pollingInterval: number = 10000 // Check usage every 10 seconds + static readonly thresholds: ProcessStats = { + memory: 100 * 1024 * 1024, // 100 MB + cpu: 50, + } + static readonly logger = getLogger('childProcess') + #processByPid: Map = new Map() + #pids: PollingSet + + public constructor() { + this.#pids = new PollingSet(ChildProcessTracker.pollingInterval, () => this.monitor()) + } + + private cleanUp() { + const terminatedProcesses = Array.from(this.#pids.values()).filter( + (pid: number) => this.#processByPid.get(pid)?.stopped + ) + for (const pid of terminatedProcesses) { + this.delete(pid) + } + } + + private async monitor() { + this.cleanUp() + ChildProcessTracker.logger.debug(`Active running processes size: ${this.#pids.size}`) + + for (const pid of this.#pids.values()) { + await this.checkProcessUsage(pid) + } + } + + private async checkProcessUsage(pid: number): Promise { + if (!this.#pids.has(pid)) { + ChildProcessTracker.logger.warn(`Missing process with id ${pid}`) + return + } + const stats = this.getUsage(pid) + if (stats) { + ChildProcessTracker.logger.debug(`Process ${pid} usage: %O`, stats) + if (stats.memory > ChildProcessTracker.thresholds.memory) { + ChildProcessTracker.logger.warn(`Process ${pid} exceeded memory threshold: ${stats.memory}`) + } + if (stats.cpu > ChildProcessTracker.thresholds.cpu) { + ChildProcessTracker.logger.warn(`Process ${pid} exceeded cpu threshold: ${stats.cpu}`) + } + } + } + + public add(childProcess: ChildProcess) { + const pid = childProcess.pid() + this.#processByPid.set(pid, childProcess) + this.#pids.start(pid) + } + + public delete(childProcessId: number) { + this.#processByPid.delete(childProcessId) + this.#pids.delete(childProcessId) + } + + public get size() { + return this.#pids.size + } + + public has(childProcess: ChildProcess) { + return this.#pids.has(childProcess.pid()) + } + + public clear() { + for (const childProcess of this.#processByPid.values()) { + childProcess.stop(true) + } + this.#pids.clear() + this.#processByPid.clear() + } + + public getUsage(pid: number): ProcessStats { + try { + // isWin() leads to circular dependency. + return process.platform === 'win32' ? getWindowsUsage() : getUnixUsage() + } catch (e) { + ChildProcessTracker.logger.warn(`Failed to get process stats for ${pid}: ${e}`) + return { cpu: 0, memory: 0 } + } + + function getWindowsUsage() { + const cpuOutput = proc + .execFileSync('wmic', [ + 'path', + 'Win32_PerfFormattedData_PerfProc_Process', + 'where', + `IDProcess=${pid}`, + 'get', + 'PercentProcessorTime', + ]) + .toString() + const memOutput = proc + .execFileSync('wmic', ['process', 'where', `ProcessId=${pid}`, 'get', 'WorkingSetSize']) + .toString() + + const cpuPercentage = parseFloat(cpuOutput.split('\n')[1]) + const memoryBytes = parseInt(memOutput.split('\n')[1]) * 1024 + + return { + cpu: isNaN(cpuPercentage) ? 0 : cpuPercentage, + memory: memoryBytes, + } + } + + function getUnixUsage() { + const cpuMemOutput = proc.execFileSync('ps', ['-p', pid.toString(), '-o', '%cpu,%mem']).toString() + const rssOutput = proc.execFileSync('ps', ['-p', pid.toString(), '-o', 'rss']).toString() + + const cpuMemLines = cpuMemOutput.split('\n')[1].trim().split(/\s+/) + const cpuPercentage = parseFloat(cpuMemLines[0]) + const memoryBytes = parseInt(rssOutput.split('\n')[1]) * 1024 + + return { + cpu: isNaN(cpuPercentage) ? 0 : cpuPercentage, + memory: memoryBytes, + } + } + } +} + /** * Convenience class to manage a child process * To use: @@ -68,7 +199,8 @@ export const eof = Symbol('EOF') * - call and await run to get the results (pass or fail) */ export class ChildProcess { - static #runningProcesses: Map = new Map() + static #runningProcesses = new ChildProcessTracker() + static stopTimeout = 3000 #childProcess: proc.ChildProcess | undefined #processErrors: Error[] = [] #processResult: ChildProcessResult | undefined @@ -285,7 +417,7 @@ export class ChildProcess { child.kill(signal) if (force === true) { - waitUntil(async () => this.stopped, { timeout: 3000, interval: 200, truthy: true }) + waitUntil(async () => this.stopped, { timeout: ChildProcess.stopTimeout, interval: 200, truthy: true }) .then((stopped) => { if (!stopped) { child.kill('SIGKILL') @@ -309,7 +441,7 @@ export class ChildProcess { if (pid === undefined) { return } - ChildProcess.#runningProcesses.set(pid, this) + ChildProcess.#runningProcesses.add(this) const timeoutListener = options?.timeout?.token.onCancellationRequested(({ agent }) => { const message = agent === 'user' ? 'Cancelled: ' : 'Timed out: ' @@ -319,7 +451,7 @@ export class ChildProcess { const dispose = () => { timeoutListener?.dispose() - ChildProcess.#runningProcesses.delete(pid) + ChildProcess.#runningProcesses.delete(this.pid()) } process.on('exit', dispose) diff --git a/packages/core/src/test/shared/utilities/processUtils.test.ts b/packages/core/src/test/shared/utilities/processUtils.test.ts index c6e3da722db..0e6f474ed10 100644 --- a/packages/core/src/test/shared/utilities/processUtils.test.ts +++ b/packages/core/src/test/shared/utilities/processUtils.test.ts @@ -6,11 +6,22 @@ import assert from 'assert' import * as os from 'os' import * as path from 'path' +import * as sinon from 'sinon' import { makeTemporaryToolkitFolder, tryRemoveFolder } from '../../../shared/filesystemUtilities' -import { ChildProcess, eof } from '../../../shared/utilities/processUtils' +import { + ChildProcess, + ChildProcessResult, + ChildProcessTracker, + eof, + ProcessStats, +} from '../../../shared/utilities/processUtils' import { sleep } from '../../../shared/utilities/timeoutUtils' import { Timeout, waitUntil } from '../../../shared/utilities/timeoutUtils' import { fs } from '../../../shared' +import * as FakeTimers from '@sinonjs/fake-timers' +import { installFakeClock } from '../../testUtil' +import { isWin } from '../../../shared/vscode/env' +import { assertLogsContain } from '../../globalSetup.test' describe('ChildProcess', async function () { let tempFolder: string @@ -350,3 +361,142 @@ describe('ChildProcess', async function () { await writeShellFile(filename, file) } }) + +interface RunningProcess { + childProcess: ChildProcess + result: Promise +} + +function getSleepCmd() { + return isWin() ? 'timeout' : 'sleep' +} + +async function stopAndWait(runningProcess: RunningProcess): Promise { + runningProcess.childProcess.stop(true) + await runningProcess.result +} + +function startSleepProcess(timeout: number = 90): RunningProcess { + const childProcess = new ChildProcess(getSleepCmd(), [timeout.toString()]) + const result = childProcess.run().catch(() => assert.fail('sleep command threw an error')) + return { childProcess, result } +} + +describe('ChildProcessTracker', function () { + let tracker: ChildProcessTracker + let clock: FakeTimers.InstalledClock + let usageMock: sinon.SinonStub + + before(function () { + clock = installFakeClock() + tracker = new ChildProcessTracker() + usageMock = sinon.stub(ChildProcessTracker.prototype, 'getUsage') + }) + + afterEach(function () { + tracker.clear() + usageMock.reset() + }) + + after(function () { + clock.uninstall() + }) + + it(`removes stopped processes every ${ChildProcessTracker.pollingInterval / 1000} seconds`, async function () { + // Start a 'sleep' command, check it only removes after we stop it. + const runningProcess = startSleepProcess() + tracker.add(runningProcess.childProcess) + assert.strictEqual(tracker.has(runningProcess.childProcess), true, 'failed to add sleep command') + + await clock.tickAsync(ChildProcessTracker.pollingInterval) + assert.strictEqual(tracker.has(runningProcess.childProcess), true, 'process was mistakenly removed') + await stopAndWait(runningProcess) + + await clock.tickAsync(ChildProcessTracker.pollingInterval) + assert.strictEqual(tracker.has(runningProcess.childProcess), false, 'process was not removed after stopping') + }) + + it('multiple processes from same command are tracked seperately', async function () { + const runningProcess1 = startSleepProcess() + const runningProcess2 = startSleepProcess() + tracker.add(runningProcess1.childProcess) + tracker.add(runningProcess2.childProcess) + + assert.strictEqual(tracker.has(runningProcess1.childProcess), true, 'Missing first process') + assert.strictEqual(tracker.has(runningProcess2.childProcess), true, 'Missing second process') + + await stopAndWait(runningProcess1) + await clock.tickAsync(ChildProcessTracker.pollingInterval) + assert.strictEqual(tracker.has(runningProcess2.childProcess), true, 'second process was mistakenly removed') + assert.strictEqual( + tracker.has(runningProcess1.childProcess), + false, + 'first process was not removed after stopping it' + ) + + await stopAndWait(runningProcess2) + await clock.tickAsync(ChildProcessTracker.pollingInterval) + assert.strictEqual( + tracker.has(runningProcess2.childProcess), + false, + 'second process was not removed after stopping it' + ) + + assert.strictEqual(tracker.size, 0, 'expected tracker to be empty') + }) + + it('logs a warning message when system usage exceeds threshold', async function () { + const runningProcess = startSleepProcess() + tracker.add(runningProcess.childProcess) + + const highCpu: ProcessStats = { + cpu: ChildProcessTracker.thresholds.cpu + 1, + memory: 0, + } + const highMemory: ProcessStats = { + cpu: 0, + memory: ChildProcessTracker.thresholds.memory + 1, + } + + usageMock.returns(highCpu) + + await clock.tickAsync(ChildProcessTracker.pollingInterval) + assertLogsContain('exceeded cpu threshold', false, 'warn') + + usageMock.returns(highMemory) + await clock.tickAsync(ChildProcessTracker.pollingInterval) + assertLogsContain('exceeded memory threshold', false, 'warn') + + await stopAndWait(runningProcess) + }) + + it('includes pid in logs', async function () { + const runningProcess = startSleepProcess() + tracker.add(runningProcess.childProcess) + + usageMock.returns({ + cpu: ChildProcessTracker.thresholds.cpu + 1, + memory: 0, + }) + + await clock.tickAsync(ChildProcessTracker.pollingInterval) + assertLogsContain(runningProcess.childProcess.pid().toString(), false, 'warn') + + await stopAndWait(runningProcess) + }) + + it('does not log for processes within threshold', async function () { + const runningProcess = startSleepProcess() + + usageMock.returns({ + cpu: ChildProcessTracker.thresholds.cpu - 1, + memory: ChildProcessTracker.thresholds.memory - 1, + }) + + await clock.tickAsync(ChildProcessTracker.pollingInterval) + + assert.throws(() => assertLogsContain(runningProcess.childProcess.pid().toString(), false, 'warn')) + + await stopAndWait(runningProcess) + }) +})