From 53aaeef8b74fb68e7986e319f96e85dca3c2a407 Mon Sep 17 00:00:00 2001 From: hkobew Date: Mon, 23 Dec 2024 15:16:02 -0500 Subject: [PATCH 01/48] implement basic tracker class --- .../core/src/shared/utilities/processUtils.ts | 51 ++++++++++++++++++- 1 file changed, 50 insertions(+), 1 deletion(-) diff --git a/packages/core/src/shared/utilities/processUtils.ts b/packages/core/src/shared/utilities/processUtils.ts index 2e179da98b8..481813032f5 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,53 @@ export interface ChildProcessResult { export const eof = Symbol('EOF') +export class ChildProcessTracker extends Map { + static pollingInterval: number = 5000 + #processPoller: PollingSet + + public constructor() { + super() + this.#processPoller = new PollingSet(ChildProcessTracker.pollingInterval, () => {}) + } + + private cleanUpProcesses() { + const terminatedProcesses = Array.from(this.#processPoller.values()).filter( + (pid: number) => !this.has(pid) || this.get(pid)?.stopped + ) + for (const pid of terminatedProcesses) { + this.#processPoller.delete(pid) + } + } + + public monitorProcesses() { + this.cleanUpProcesses() + getLogger().debug(`Active running processes size: ${this.#processPoller.size}`) + + for (const pid of this.#processPoller.values()) { + const process = this.get(pid) + if (process) { + getLogger().debug(`Active running process: ${process.toString()}`) + } + } + } + + public override set(key: number, value: ChildProcess): this { + this.#processPoller.add(key) + super.set(key, value) + return this + } + + public override delete(key: number): boolean { + this.#processPoller.delete(key) + return super.delete(key) + } + + public override clear(): void { + this.#processPoller.clear() + super.clear() + } +} + /** * Convenience class to manage a child process * To use: @@ -68,7 +117,7 @@ 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: ChildProcessTracker = new ChildProcessTracker() #childProcess: proc.ChildProcess | undefined #processErrors: Error[] = [] #processResult: ChildProcessResult | undefined From d48f1b3faa0d89926bc3ee381ca9a8ded2d33c46 Mon Sep 17 00:00:00 2001 From: hkobew Date: Mon, 23 Dec 2024 16:25:38 -0500 Subject: [PATCH 02/48] add option in dev menu to start processes --- packages/core/src/dev/activation.ts | 19 +++++++++++++++++++ .../core/src/shared/utilities/processUtils.ts | 9 +++++---- 2 files changed, 24 insertions(+), 4 deletions(-) diff --git a/packages/core/src/dev/activation.ts b/packages/core/src/dev/activation.ts index b4100b191ce..5064567ca82 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 a ChildProcess manually that is invoked through our wrapper', + 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/utilities/processUtils.ts b/packages/core/src/shared/utilities/processUtils.ts index 481813032f5..4141dc705f3 100644 --- a/packages/core/src/shared/utilities/processUtils.ts +++ b/packages/core/src/shared/utilities/processUtils.ts @@ -63,13 +63,14 @@ export interface ChildProcessResult { export const eof = Symbol('EOF') -export class ChildProcessTracker extends Map { - static pollingInterval: number = 5000 +class ChildProcessTracker extends Map { + static pollingInterval: number = 1000 #processPoller: PollingSet public constructor() { super() - this.#processPoller = new PollingSet(ChildProcessTracker.pollingInterval, () => {}) + this.#processPoller = new PollingSet(ChildProcessTracker.pollingInterval, () => this.monitorProcesses()) + getLogger().debug(`ChildProcessTracker created with polling interval: ${ChildProcessTracker.pollingInterval}`) } private cleanUpProcesses() { @@ -94,7 +95,7 @@ export class ChildProcessTracker extends Map { } public override set(key: number, value: ChildProcess): this { - this.#processPoller.add(key) + this.#processPoller.start(key) super.set(key, value) return this } From 44fe332ee735f6d50f5bd5e73521102c818f95d4 Mon Sep 17 00:00:00 2001 From: hkobew Date: Thu, 26 Dec 2024 16:16:16 -0500 Subject: [PATCH 03/48] add dependency to track pid usage --- package-lock.json | 20 +++++++++++++++++++ package.json | 2 ++ .../core/src/shared/utilities/processUtils.ts | 17 +++++++++++----- 3 files changed, 34 insertions(+), 5 deletions(-) diff --git a/package-lock.json b/package-lock.json index 8a549622f37..75a0e6b914d 100644 --- a/package-lock.json +++ b/package-lock.json @@ -16,6 +16,8 @@ ], "dependencies": { "@types/node": "^22.7.5", + "@types/pidusage": "^2.0.5", + "pidusage": "^3.0.2", "vscode-nls": "^5.2.0", "vscode-nls-dev": "^4.0.4" }, @@ -9196,6 +9198,12 @@ "dev": true, "license": "MIT" }, + "node_modules/@types/pidusage": { + "version": "2.0.5", + "resolved": "https://registry.npmjs.org/@types/pidusage/-/pidusage-2.0.5.tgz", + "integrity": "sha512-MIiyZI4/MK9UGUXWt0jJcCZhVw7YdhBuTOuqP/BjuLDLZ2PmmViMIQgZiWxtaMicQfAz/kMrZ5T7PKxFSkTeUA==", + "license": "MIT" + }, "node_modules/@types/prettier": { "version": "2.7.0", "dev": true, @@ -16985,6 +16993,18 @@ "url": "https://github.com/sponsors/jonschlinkert" } }, + "node_modules/pidusage": { + "version": "3.0.2", + "resolved": "https://registry.npmjs.org/pidusage/-/pidusage-3.0.2.tgz", + "integrity": "sha512-g0VU+y08pKw5M8EZ2rIGiEBaB8wrQMjYGFfW2QVIfyT8V+fq8YFLkvlz4bz5ljvFDJYNFCWT3PWqcRr2FKO81w==", + "license": "MIT", + "dependencies": { + "safe-buffer": "^5.2.1" + }, + "engines": { + "node": ">=10" + } + }, "node_modules/pkg-dir": { "version": "4.2.0", "dev": true, diff --git a/package.json b/package.json index e658a3a916e..2fcc6d6c837 100644 --- a/package.json +++ b/package.json @@ -72,6 +72,8 @@ }, "dependencies": { "@types/node": "^22.7.5", + "@types/pidusage": "^2.0.5", + "pidusage": "^3.0.2", "vscode-nls": "^5.2.0", "vscode-nls-dev": "^4.0.4" } diff --git a/packages/core/src/shared/utilities/processUtils.ts b/packages/core/src/shared/utilities/processUtils.ts index 4141dc705f3..67211770b49 100644 --- a/packages/core/src/shared/utilities/processUtils.ts +++ b/packages/core/src/shared/utilities/processUtils.ts @@ -9,6 +9,7 @@ import * as logger from '../logger' import { Timeout, CancellationError, waitUntil } from './timeoutUtils' import { PollingSet } from './pollingSet' import { getLogger } from '../logger/logger' +import pidusage from 'pidusage' export interface RunParameterContext { /** Reports an error parsed from the stdin/stdout streams. */ @@ -82,15 +83,21 @@ class ChildProcessTracker extends Map { } } - public monitorProcesses() { + public async monitorProcesses() { this.cleanUpProcesses() getLogger().debug(`Active running processes size: ${this.#processPoller.size}`) for (const pid of this.#processPoller.values()) { - const process = this.get(pid) - if (process) { - getLogger().debug(`Active running process: ${process.toString()}`) - } + await this.monitorProcess(pid) + } + } + + private async monitorProcess(pid: number) { + if (this.has(pid)) { + const stats = await pidusage(pid) + getLogger().debug(`stats for ${pid}: %O`, stats) + } else { + getLogger().warn(`Missing process with id ${pid}`) } } From 9d40215bf79db1f8c142f6a387899ed7f806c59d Mon Sep 17 00:00:00 2001 From: hkobew Date: Fri, 27 Dec 2024 15:58:52 -0500 Subject: [PATCH 04/48] warn on exceeding thresholds --- .../core/src/shared/utilities/processUtils.ts | 15 +++++++++++++++ 1 file changed, 15 insertions(+) diff --git a/packages/core/src/shared/utilities/processUtils.ts b/packages/core/src/shared/utilities/processUtils.ts index 67211770b49..705ca6fad2d 100644 --- a/packages/core/src/shared/utilities/processUtils.ts +++ b/packages/core/src/shared/utilities/processUtils.ts @@ -66,6 +66,12 @@ export const eof = Symbol('EOF') class ChildProcessTracker extends Map { static pollingInterval: number = 1000 + static thresholds: { memory: number; cpu: number; time: number } = { + memory: 100 * 1024 * 1024, // 100 MB + cpu: 50, + time: 30 * 1000, // 30 seconds + } + #processPoller: PollingSet public constructor() { @@ -96,6 +102,15 @@ class ChildProcessTracker extends Map { if (this.has(pid)) { const stats = await pidusage(pid) getLogger().debug(`stats for ${pid}: %O`, stats) + if (stats.memory > ChildProcessTracker.thresholds.memory) { + getLogger().warn(`Process ${pid} exceeded memory threshold: ${stats.memory}`) + } + if (stats.cpu > ChildProcessTracker.thresholds.cpu) { + getLogger().warn(`Process ${pid} exceeded cpu threshold: ${stats.cpu}`) + } + if (stats.elapsed > ChildProcessTracker.thresholds.time) { + getLogger().warn(`Process ${pid} exceeded time threshold: ${stats.elapsed}`) + } } else { getLogger().warn(`Missing process with id ${pid}`) } From bcb6423861dd71455958f28b3a9996ac5d40cd6a Mon Sep 17 00:00:00 2001 From: hkobew Date: Mon, 30 Dec 2024 10:53:38 -0500 Subject: [PATCH 05/48] add first test case --- .../core/src/shared/utilities/pollingSet.ts | 2 +- .../core/src/shared/utilities/processUtils.ts | 85 ++++++++++++------- .../shared/utilities/processUtils.test.ts | 23 ++++- 3 files changed, 76 insertions(+), 34 deletions(-) diff --git a/packages/core/src/shared/utilities/pollingSet.ts b/packages/core/src/shared/utilities/pollingSet.ts index 321dde153b8..6f297c11bd8 100644 --- a/packages/core/src/shared/utilities/pollingSet.ts +++ b/packages/core/src/shared/utilities/pollingSet.ts @@ -44,7 +44,7 @@ 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) diff --git a/packages/core/src/shared/utilities/processUtils.ts b/packages/core/src/shared/utilities/processUtils.ts index 705ca6fad2d..958fe379f4a 100644 --- a/packages/core/src/shared/utilities/processUtils.ts +++ b/packages/core/src/shared/utilities/processUtils.ts @@ -62,45 +62,53 @@ export interface ChildProcessResult { signal?: string } +interface Tracker { + add(item: T): void + delete(item: T): void + has(item: T): boolean + size(): number + cleanUp(): void + monitor(): void | Promise +} + export const eof = Symbol('EOF') -class ChildProcessTracker extends Map { - static pollingInterval: number = 1000 +export class ChildProcessTracker implements Tracker { + static pollingInterval: number = 10000 static thresholds: { memory: number; cpu: number; time: number } = { memory: 100 * 1024 * 1024, // 100 MB cpu: 50, time: 30 * 1000, // 30 seconds } - - #processPoller: PollingSet + #processByPid: Map = new Map() + #pids: PollingSet public constructor() { - super() - this.#processPoller = new PollingSet(ChildProcessTracker.pollingInterval, () => this.monitorProcesses()) + this.#pids = new PollingSet(ChildProcessTracker.pollingInterval, () => this.monitor()) getLogger().debug(`ChildProcessTracker created with polling interval: ${ChildProcessTracker.pollingInterval}`) } - private cleanUpProcesses() { - const terminatedProcesses = Array.from(this.#processPoller.values()).filter( - (pid: number) => !this.has(pid) || this.get(pid)?.stopped + public cleanUp() { + const terminatedProcesses = Array.from(this.#pids.values()).filter( + (pid: number) => !this.#pids.has(pid) || this.#processByPid.get(pid)?.stopped ) for (const pid of terminatedProcesses) { - this.#processPoller.delete(pid) + this.#pids.delete(pid) } } - public async monitorProcesses() { - this.cleanUpProcesses() - getLogger().debug(`Active running processes size: ${this.#processPoller.size}`) + public async monitor() { + this.cleanUp() + getLogger().debug(`Active running processes size: ${this.#pids.size}`) - for (const pid of this.#processPoller.values()) { - await this.monitorProcess(pid) + for (const pid of this.#pids.values()) { + await this.checkProcessUsage(pid) } } - private async monitorProcess(pid: number) { - if (this.has(pid)) { - const stats = await pidusage(pid) + private async checkProcessUsage(pid: number): Promise { + if (this.#pids.has(pid)) { + const stats = await this.getUsage(pid) getLogger().debug(`stats for ${pid}: %O`, stats) if (stats.memory > ChildProcessTracker.thresholds.memory) { getLogger().warn(`Process ${pid} exceeded memory threshold: ${stats.memory}`) @@ -116,20 +124,33 @@ class ChildProcessTracker extends Map { } } - public override set(key: number, value: ChildProcess): this { - this.#processPoller.start(key) - super.set(key, value) - return this + public add(childProcess: ChildProcess) { + const pid = childProcess.pid() + this.#processByPid.set(pid, childProcess) + this.#pids.start(pid) + } + + public delete(childProcess: ChildProcess) { + const pid = childProcess.pid() + this.#processByPid.delete(pid) + this.#pids.delete(pid) } - public override delete(key: number): boolean { - this.#processPoller.delete(key) - return super.delete(key) + public size() { + return this.#pids.size } - public override clear(): void { - this.#processPoller.clear() - super.clear() + public has(childProcess: ChildProcess) { + return this.#pids.has(childProcess.pid()) + } + + private async getUsage(pid: number): Promise<{ memory: number; cpu: number; elapsed: number }> { + const stats = await pidusage(pid) + return { + memory: stats.memory, + cpu: stats.cpu, + elapsed: stats.elapsed, + } } } @@ -140,7 +161,7 @@ class ChildProcessTracker extends Map { * - call and await run to get the results (pass or fail) */ export class ChildProcess { - static #runningProcesses: ChildProcessTracker = new ChildProcessTracker() + static #runningProcesses: Tracker = new ChildProcessTracker() #childProcess: proc.ChildProcess | undefined #processErrors: Error[] = [] #processResult: ChildProcessResult | undefined @@ -213,7 +234,7 @@ export class ChildProcess { const args = this.#args.concat(options.extraArgs ?? []) const debugDetail = this.#log.logLevelEnabled('debug') - ? ` (running processes: ${ChildProcess.#runningProcesses.size})` + ? ` (running processes: ${ChildProcess.#runningProcesses.size()})` : '' this.#log.info(`Command: ${this.toString(options.logging === 'noparams')}${debugDetail}`) @@ -381,7 +402,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: ' @@ -391,7 +412,7 @@ export class ChildProcess { const dispose = () => { timeoutListener?.dispose() - ChildProcess.#runningProcesses.delete(pid) + ChildProcess.#runningProcesses.delete(this) } 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..ca7f52b7eb6 100644 --- a/packages/core/src/test/shared/utilities/processUtils.test.ts +++ b/packages/core/src/test/shared/utilities/processUtils.test.ts @@ -7,10 +7,12 @@ import assert from 'assert' import * as os from 'os' import * as path from 'path' import { makeTemporaryToolkitFolder, tryRemoveFolder } from '../../../shared/filesystemUtilities' -import { ChildProcess, eof } from '../../../shared/utilities/processUtils' +import { ChildProcess, ChildProcessTracker, eof } 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' describe('ChildProcess', async function () { let tempFolder: string @@ -350,3 +352,22 @@ describe('ChildProcess', async function () { await writeShellFile(filename, file) } }) + +describe('ChildProcessTracker', function () { + let tracker: ChildProcessTracker + let clock: FakeTimers.InstalledClock + before(function () { + clock = installFakeClock() + tracker = new ChildProcessTracker() + }) + + it('removes stopped processes every X seconds', async function () { + const childProcess = new ChildProcess('echo', ['hi']) + await childProcess.run() + tracker.add(childProcess) + childProcess.stop() + assert.strictEqual(tracker.has(childProcess), true) + await clock.tickAsync(ChildProcessTracker.pollingInterval) + assert.strictEqual(tracker.has(childProcess), false) + }) +}) From 8975c3314bd8483746f26f2193f8b98bb07fa0da Mon Sep 17 00:00:00 2001 From: hkobew Date: Mon, 30 Dec 2024 14:33:11 -0500 Subject: [PATCH 06/48] expand test suite --- .../core/src/shared/utilities/processUtils.ts | 14 +-- .../shared/utilities/processUtils.test.ts | 88 +++++++++++++++++-- 2 files changed, 90 insertions(+), 12 deletions(-) diff --git a/packages/core/src/shared/utilities/processUtils.ts b/packages/core/src/shared/utilities/processUtils.ts index 958fe379f4a..d78ec2d42d1 100644 --- a/packages/core/src/shared/utilities/processUtils.ts +++ b/packages/core/src/shared/utilities/processUtils.ts @@ -73,19 +73,23 @@ interface Tracker { export const eof = Symbol('EOF') +export interface ProcessStats { + memory: number + cpu: number + elapsed: number +} export class ChildProcessTracker implements Tracker { static pollingInterval: number = 10000 - static thresholds: { memory: number; cpu: number; time: number } = { + static thresholds: ProcessStats = { memory: 100 * 1024 * 1024, // 100 MB cpu: 50, - time: 30 * 1000, // 30 seconds + elapsed: 30 * 1000, // 30 seconds } #processByPid: Map = new Map() #pids: PollingSet public constructor() { this.#pids = new PollingSet(ChildProcessTracker.pollingInterval, () => this.monitor()) - getLogger().debug(`ChildProcessTracker created with polling interval: ${ChildProcessTracker.pollingInterval}`) } public cleanUp() { @@ -116,7 +120,7 @@ export class ChildProcessTracker implements Tracker { if (stats.cpu > ChildProcessTracker.thresholds.cpu) { getLogger().warn(`Process ${pid} exceeded cpu threshold: ${stats.cpu}`) } - if (stats.elapsed > ChildProcessTracker.thresholds.time) { + if (stats.elapsed > ChildProcessTracker.thresholds.elapsed) { getLogger().warn(`Process ${pid} exceeded time threshold: ${stats.elapsed}`) } } else { @@ -144,7 +148,7 @@ export class ChildProcessTracker implements Tracker { return this.#pids.has(childProcess.pid()) } - private async getUsage(pid: number): Promise<{ memory: number; cpu: number; elapsed: number }> { + public async getUsage(pid: number): Promise { const stats = await pidusage(pid) return { memory: stats.memory, diff --git a/packages/core/src/test/shared/utilities/processUtils.test.ts b/packages/core/src/test/shared/utilities/processUtils.test.ts index ca7f52b7eb6..5028ca3fb41 100644 --- a/packages/core/src/test/shared/utilities/processUtils.test.ts +++ b/packages/core/src/test/shared/utilities/processUtils.test.ts @@ -7,12 +7,15 @@ import assert from 'assert' import * as os from 'os' import * as path from 'path' import { makeTemporaryToolkitFolder, tryRemoveFolder } from '../../../shared/filesystemUtilities' -import { ChildProcess, ChildProcessTracker, eof } from '../../../shared/utilities/processUtils' +import { ChildProcess, 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 Sinon from 'sinon' +import { assertLogsContain } from '../../globalSetup.test' describe('ChildProcess', async function () { let tempFolder: string @@ -353,6 +356,10 @@ describe('ChildProcess', async function () { } }) +function getSleepCmd() { + return isWin() ? 'timeout' : 'sleep' +} + describe('ChildProcessTracker', function () { let tracker: ChildProcessTracker let clock: FakeTimers.InstalledClock @@ -361,13 +368,80 @@ describe('ChildProcessTracker', function () { tracker = new ChildProcessTracker() }) - it('removes stopped processes every X seconds', async function () { - const childProcess = new ChildProcess('echo', ['hi']) - await childProcess.run() + it(`removes stopped processes every ${ChildProcessTracker.pollingInterval / 1000} seconds`, async function () { + // Start a 'sleep' command, check it only removes after we stop it. + const childProcess = new ChildProcess(getSleepCmd(), ['90']) + childProcess.run().catch(() => assert.fail('sleep command threw an error')) + tracker.add(childProcess) + assert.strictEqual(tracker.has(childProcess), true, 'failed to add sleep command') + + await clock.tickAsync(ChildProcessTracker.pollingInterval) + assert.strictEqual(tracker.has(childProcess), true, 'process was mistakenly removed') + childProcess.stop(true) + + await clock.tickAsync(ChildProcessTracker.pollingInterval) + assert.strictEqual(tracker.has(childProcess), false, 'process was not removed after stopping') + }) + + it('multiple processes from same command are tracked seperately', async function () { + const childProcess1 = new ChildProcess(getSleepCmd(), ['90']) + const childProcess2 = new ChildProcess(getSleepCmd(), ['90']) + childProcess1.run().catch(() => assert.fail('sleep command threw an error')) + childProcess2.run().catch(() => assert.fail('sleep command threw an error')) + + tracker.add(childProcess1) + tracker.add(childProcess2) + + assert.strictEqual(tracker.has(childProcess1), true, 'Missing first process') + assert.strictEqual(tracker.has(childProcess2), true, 'Missing second process') + assert.strictEqual(tracker.size(), 2) + + childProcess1.stop() + await clock.tickAsync(ChildProcessTracker.pollingInterval + 1) + assert.strictEqual(tracker.has(childProcess2), true, 'first process was not removed after stopping it') + assert.strictEqual(tracker.size(), 1) + + childProcess2.stop() + await clock.tickAsync(ChildProcessTracker.pollingInterval + 1) + assert.strictEqual(tracker.size(), 0, 'second process was not removed after stopping it') + }) + + it('logs a warning message when system usage exceeds threshold', async function () { + const childProcess = new ChildProcess(getSleepCmd(), ['90']) + childProcess.run().catch(() => assert.fail('sleep command threw an error')) tracker.add(childProcess) - childProcess.stop() - assert.strictEqual(tracker.has(childProcess), true) + + const usageMock = Sinon.stub(ChildProcessTracker.prototype, 'getUsage') + const highCpu: ProcessStats = { + cpu: ChildProcessTracker.thresholds.cpu + 1, + memory: 0, + elapsed: 0, + } + const highMemory: ProcessStats = { + cpu: 0, + memory: ChildProcessTracker.thresholds.memory + 1, + elapsed: 0, + } + + const highTime: ProcessStats = { + cpu: 0, + memory: 0, + elapsed: ChildProcessTracker.thresholds.elapsed + 1, + } + + usageMock.resolves(highCpu) + + await clock.tickAsync(ChildProcessTracker.pollingInterval) + assertLogsContain('exceeded cpu threshold', false, 'warn') + + usageMock.resolves(highMemory) await clock.tickAsync(ChildProcessTracker.pollingInterval) - assert.strictEqual(tracker.has(childProcess), false) + assertLogsContain('exceeded memory threshold', false, 'warn') + + usageMock.resolves(highTime) + await clock.tickAsync(ChildProcessTracker.pollingInterval) + assertLogsContain('exceeded time threshold', false, 'warn') + + usageMock.restore() }) }) From 72681fd96253cd64e48789d02ccee2b84513aecc Mon Sep 17 00:00:00 2001 From: hkobew Date: Tue, 31 Dec 2024 11:20:45 -0500 Subject: [PATCH 07/48] simplify and expand test suite --- .../core/src/shared/utilities/pollingSet.ts | 5 +++ .../core/src/shared/utilities/processUtils.ts | 31 +++++++++++-------- .../shared/utilities/processUtils.test.ts | 22 +++++++------ 3 files changed, 35 insertions(+), 23 deletions(-) diff --git a/packages/core/src/shared/utilities/pollingSet.ts b/packages/core/src/shared/utilities/pollingSet.ts index 6f297c11bd8..a9f7ef60fe4 100644 --- a/packages/core/src/shared/utilities/pollingSet.ts +++ b/packages/core/src/shared/utilities/pollingSet.ts @@ -49,4 +49,9 @@ export class PollingSet extends Set { this.add(id) this.pollTimer = this.pollTimer ?? globals.clock.setInterval(() => this.poll(), this.interval) } + + public override clear(): void { + this.pollTimer = undefined + super.clear() + } } diff --git a/packages/core/src/shared/utilities/processUtils.ts b/packages/core/src/shared/utilities/processUtils.ts index d78ec2d42d1..029ecb3e1fa 100644 --- a/packages/core/src/shared/utilities/processUtils.ts +++ b/packages/core/src/shared/utilities/processUtils.ts @@ -62,13 +62,14 @@ export interface ChildProcessResult { signal?: string } -interface Tracker { +interface Tracker { add(item: T): void - delete(item: T): void + delete(id: P): void has(item: T): boolean size(): number cleanUp(): void monitor(): void | Promise + clear(): void } export const eof = Symbol('EOF') @@ -78,9 +79,9 @@ export interface ProcessStats { cpu: number elapsed: number } -export class ChildProcessTracker implements Tracker { - static pollingInterval: number = 10000 - static thresholds: ProcessStats = { +export class ChildProcessTracker implements Tracker { + static readonly pollingInterval: number = 10000 + static readonly thresholds: ProcessStats = { memory: 100 * 1024 * 1024, // 100 MB cpu: 50, elapsed: 30 * 1000, // 30 seconds @@ -94,10 +95,10 @@ export class ChildProcessTracker implements Tracker { public cleanUp() { const terminatedProcesses = Array.from(this.#pids.values()).filter( - (pid: number) => !this.#pids.has(pid) || this.#processByPid.get(pid)?.stopped + (pid: number) => this.#processByPid.get(pid)?.stopped ) for (const pid of terminatedProcesses) { - this.#pids.delete(pid) + this.delete(pid) } } @@ -134,10 +135,9 @@ export class ChildProcessTracker implements Tracker { this.#pids.start(pid) } - public delete(childProcess: ChildProcess) { - const pid = childProcess.pid() - this.#processByPid.delete(pid) - this.#pids.delete(pid) + public delete(childProcessId: number) { + this.#processByPid.delete(childProcessId) + this.#pids.delete(childProcessId) } public size() { @@ -156,6 +156,11 @@ export class ChildProcessTracker implements Tracker { elapsed: stats.elapsed, } } + + public clear() { + this.#pids.clear() + this.#processByPid.clear() + } } /** @@ -165,7 +170,7 @@ export class ChildProcessTracker implements Tracker { * - call and await run to get the results (pass or fail) */ export class ChildProcess { - static #runningProcesses: Tracker = new ChildProcessTracker() + static #runningProcesses: Tracker = new ChildProcessTracker() #childProcess: proc.ChildProcess | undefined #processErrors: Error[] = [] #processResult: ChildProcessResult | undefined @@ -416,7 +421,7 @@ export class ChildProcess { const dispose = () => { timeoutListener?.dispose() - ChildProcess.#runningProcesses.delete(this) + 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 5028ca3fb41..4952bc1d64c 100644 --- a/packages/core/src/test/shared/utilities/processUtils.test.ts +++ b/packages/core/src/test/shared/utilities/processUtils.test.ts @@ -6,6 +6,7 @@ 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, ChildProcessTracker, eof, ProcessStats } from '../../../shared/utilities/processUtils' import { sleep } from '../../../shared/utilities/timeoutUtils' @@ -14,7 +15,6 @@ import { fs } from '../../../shared' import * as FakeTimers from '@sinonjs/fake-timers' import { installFakeClock } from '../../testUtil' import { isWin } from '../../../shared/vscode/env' -import Sinon from 'sinon' import { assertLogsContain } from '../../globalSetup.test' describe('ChildProcess', async function () { @@ -368,6 +368,14 @@ describe('ChildProcessTracker', function () { tracker = new ChildProcessTracker() }) + afterEach(function () { + tracker.clear() + }) + + 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 childProcess = new ChildProcess(getSleepCmd(), ['90']) @@ -388,22 +396,16 @@ describe('ChildProcessTracker', function () { const childProcess2 = new ChildProcess(getSleepCmd(), ['90']) childProcess1.run().catch(() => assert.fail('sleep command threw an error')) childProcess2.run().catch(() => assert.fail('sleep command threw an error')) - tracker.add(childProcess1) tracker.add(childProcess2) assert.strictEqual(tracker.has(childProcess1), true, 'Missing first process') assert.strictEqual(tracker.has(childProcess2), true, 'Missing second process') - assert.strictEqual(tracker.size(), 2) childProcess1.stop() - await clock.tickAsync(ChildProcessTracker.pollingInterval + 1) + await clock.tickAsync(ChildProcessTracker.pollingInterval) assert.strictEqual(tracker.has(childProcess2), true, 'first process was not removed after stopping it') assert.strictEqual(tracker.size(), 1) - - childProcess2.stop() - await clock.tickAsync(ChildProcessTracker.pollingInterval + 1) - assert.strictEqual(tracker.size(), 0, 'second process was not removed after stopping it') }) it('logs a warning message when system usage exceeds threshold', async function () { @@ -411,7 +413,7 @@ describe('ChildProcessTracker', function () { childProcess.run().catch(() => assert.fail('sleep command threw an error')) tracker.add(childProcess) - const usageMock = Sinon.stub(ChildProcessTracker.prototype, 'getUsage') + const usageMock = sinon.stub(ChildProcessTracker.prototype, 'getUsage') const highCpu: ProcessStats = { cpu: ChildProcessTracker.thresholds.cpu + 1, memory: 0, @@ -442,6 +444,6 @@ describe('ChildProcessTracker', function () { await clock.tickAsync(ChildProcessTracker.pollingInterval) assertLogsContain('exceeded time threshold', false, 'warn') - usageMock.restore() + sinon.restore() }) }) From 5c652b61df62b5a20750eea0abd6f7616b45eef6 Mon Sep 17 00:00:00 2001 From: hkobew Date: Tue, 31 Dec 2024 13:14:13 -0500 Subject: [PATCH 08/48] add more tests --- .../shared/utilities/processUtils.test.ts | 35 +++++++++++++++++-- 1 file changed, 33 insertions(+), 2 deletions(-) diff --git a/packages/core/src/test/shared/utilities/processUtils.test.ts b/packages/core/src/test/shared/utilities/processUtils.test.ts index 4952bc1d64c..9274a678217 100644 --- a/packages/core/src/test/shared/utilities/processUtils.test.ts +++ b/packages/core/src/test/shared/utilities/processUtils.test.ts @@ -363,13 +363,17 @@ function getSleepCmd() { 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 () { @@ -413,7 +417,6 @@ describe('ChildProcessTracker', function () { childProcess.run().catch(() => assert.fail('sleep command threw an error')) tracker.add(childProcess) - const usageMock = sinon.stub(ChildProcessTracker.prototype, 'getUsage') const highCpu: ProcessStats = { cpu: ChildProcessTracker.thresholds.cpu + 1, memory: 0, @@ -443,7 +446,35 @@ describe('ChildProcessTracker', function () { usageMock.resolves(highTime) await clock.tickAsync(ChildProcessTracker.pollingInterval) assertLogsContain('exceeded time threshold', false, 'warn') + }) + + it('includes pid in logs', async function () { + const childProcess = new ChildProcess(getSleepCmd(), ['90']) + childProcess.run().catch(() => assert.fail('sleep command threw an error')) + tracker.add(childProcess) + + usageMock.resolves({ + cpu: ChildProcessTracker.thresholds.cpu + 1, + memory: 0, + elapsed: 0, + }) + + await clock.tickAsync(ChildProcessTracker.pollingInterval) + assertLogsContain(childProcess.pid().toString(), false, 'warn') + }) + + it('does not log for processes within threshold', async function () { + const childProcess = new ChildProcess(getSleepCmd(), ['90']) + childProcess.run().catch(() => assert.fail('sleep command threw an error')) + + usageMock.resolves({ + cpu: ChildProcessTracker.thresholds.cpu - 1, + memory: ChildProcessTracker.thresholds.memory - 1, + elapsed: ChildProcessTracker.thresholds.elapsed - 1, + }) + + await clock.tickAsync(ChildProcessTracker.pollingInterval) - sinon.restore() + assert.throws(() => assertLogsContain(childProcess.pid().toString(), false, 'warn')) }) }) From 6bb8c7430ddab6c89d271f2b2f6c4693406c4849 Mon Sep 17 00:00:00 2001 From: hkobew Date: Tue, 31 Dec 2024 14:05:53 -0500 Subject: [PATCH 09/48] refactor --- .../core/src/shared/utilities/processUtils.ts | 18 ++++++++---------- 1 file changed, 8 insertions(+), 10 deletions(-) diff --git a/packages/core/src/shared/utilities/processUtils.ts b/packages/core/src/shared/utilities/processUtils.ts index 029ecb3e1fa..3d719f30e33 100644 --- a/packages/core/src/shared/utilities/processUtils.ts +++ b/packages/core/src/shared/utilities/processUtils.ts @@ -67,8 +67,6 @@ interface Tracker { delete(id: P): void has(item: T): boolean size(): number - cleanUp(): void - monitor(): void | Promise clear(): void } @@ -79,7 +77,7 @@ export interface ProcessStats { cpu: number elapsed: number } -export class ChildProcessTracker implements Tracker { +export class ChildProcessTracker { static readonly pollingInterval: number = 10000 static readonly thresholds: ProcessStats = { memory: 100 * 1024 * 1024, // 100 MB @@ -93,7 +91,7 @@ export class ChildProcessTracker implements Tracker { this.#pids = new PollingSet(ChildProcessTracker.pollingInterval, () => this.monitor()) } - public cleanUp() { + private cleanUp() { const terminatedProcesses = Array.from(this.#pids.values()).filter( (pid: number) => this.#processByPid.get(pid)?.stopped ) @@ -102,7 +100,7 @@ export class ChildProcessTracker implements Tracker { } } - public async monitor() { + private async monitor() { this.cleanUp() getLogger().debug(`Active running processes size: ${this.#pids.size}`) @@ -148,6 +146,11 @@ export class ChildProcessTracker implements Tracker { return this.#pids.has(childProcess.pid()) } + public clear() { + this.#pids.clear() + this.#processByPid.clear() + } + public async getUsage(pid: number): Promise { const stats = await pidusage(pid) return { @@ -156,11 +159,6 @@ export class ChildProcessTracker implements Tracker { elapsed: stats.elapsed, } } - - public clear() { - this.#pids.clear() - this.#processByPid.clear() - } } /** From a9224d3c5f37db9da08bdac8590be9e6638e5f9f Mon Sep 17 00:00:00 2001 From: hkobew Date: Tue, 31 Dec 2024 14:56:18 -0500 Subject: [PATCH 10/48] remove tracker interface --- packages/core/src/shared/utilities/processUtils.ts | 10 +--------- 1 file changed, 1 insertion(+), 9 deletions(-) diff --git a/packages/core/src/shared/utilities/processUtils.ts b/packages/core/src/shared/utilities/processUtils.ts index 3d719f30e33..a1062f2f277 100644 --- a/packages/core/src/shared/utilities/processUtils.ts +++ b/packages/core/src/shared/utilities/processUtils.ts @@ -62,14 +62,6 @@ export interface ChildProcessResult { signal?: string } -interface Tracker { - add(item: T): void - delete(id: P): void - has(item: T): boolean - size(): number - clear(): void -} - export const eof = Symbol('EOF') export interface ProcessStats { @@ -168,7 +160,7 @@ export class ChildProcessTracker { * - call and await run to get the results (pass or fail) */ export class ChildProcess { - static #runningProcesses: Tracker = new ChildProcessTracker() + static #runningProcesses = new ChildProcessTracker() #childProcess: proc.ChildProcess | undefined #processErrors: Error[] = [] #processResult: ChildProcessResult | undefined From 4bfff0ad09c8ff4cbf0c37332ef0b80123a5664a Mon Sep 17 00:00:00 2001 From: hkobew Date: Fri, 3 Jan 2025 09:46:17 -0500 Subject: [PATCH 11/48] refactor wording --- packages/core/src/dev/activation.ts | 2 +- packages/core/src/shared/utilities/processUtils.ts | 3 +++ 2 files changed, 4 insertions(+), 1 deletion(-) diff --git a/packages/core/src/dev/activation.ts b/packages/core/src/dev/activation.ts index 5064567ca82..b986a95e44e 100644 --- a/packages/core/src/dev/activation.ts +++ b/packages/core/src/dev/activation.ts @@ -130,7 +130,7 @@ const menuOptions: () => Record = () => { }, startChildProcess: { label: 'ChildProcess: Start child process', - detail: 'start a ChildProcess manually that is invoked through our wrapper', + detail: 'Start ChildProcess from our utility wrapper for testing', executor: startChildProcess, }, } diff --git a/packages/core/src/shared/utilities/processUtils.ts b/packages/core/src/shared/utilities/processUtils.ts index a1062f2f277..d2b6f035918 100644 --- a/packages/core/src/shared/utilities/processUtils.ts +++ b/packages/core/src/shared/utilities/processUtils.ts @@ -139,6 +139,9 @@ export class ChildProcessTracker { } public clear() { + for (const childProcess of this.#processByPid.values()) { + childProcess.stop(true) + } this.#pids.clear() this.#processByPid.clear() } From 2df75062fe2cea60958692cf40b8a9645894b1c1 Mon Sep 17 00:00:00 2001 From: hkobew Date: Fri, 3 Jan 2025 10:11:01 -0500 Subject: [PATCH 12/48] use topic logger --- packages/core/src/shared/logger/logger.ts | 2 +- .../core/src/shared/utilities/processUtils.ts | 25 ++++++++++++------- 2 files changed, 17 insertions(+), 10 deletions(-) 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/processUtils.ts b/packages/core/src/shared/utilities/processUtils.ts index d2b6f035918..346b4151e6e 100644 --- a/packages/core/src/shared/utilities/processUtils.ts +++ b/packages/core/src/shared/utilities/processUtils.ts @@ -76,6 +76,7 @@ export class ChildProcessTracker { cpu: 50, elapsed: 30 * 1000, // 30 seconds } + static readonly logger = getLogger('childProcess') #processByPid: Map = new Map() #pids: PollingSet @@ -94,7 +95,7 @@ export class ChildProcessTracker { private async monitor() { this.cleanUp() - getLogger().debug(`Active running processes size: ${this.#pids.size}`) + ChildProcessTracker.logger.debug(`Active running processes size: ${this.#pids.size}`) for (const pid of this.#pids.values()) { await this.checkProcessUsage(pid) @@ -102,20 +103,26 @@ export class ChildProcessTracker { } private async checkProcessUsage(pid: number): Promise { - if (this.#pids.has(pid)) { - const stats = await this.getUsage(pid) - getLogger().debug(`stats for ${pid}: %O`, stats) + if (!this.#pids.has(pid)) { + ChildProcessTracker.logger.warn(`ChildProcess: Missing process with id ${pid}`) + return + } + const stats = await this.getUsage(pid) + if (stats) { + ChildProcessTracker.logger.debug(`stats for ${pid}: %O`, stats) if (stats.memory > ChildProcessTracker.thresholds.memory) { - getLogger().warn(`Process ${pid} exceeded memory threshold: ${stats.memory}`) + ChildProcessTracker.logger.warn( + `ChildProcess: Process ${pid} exceeded memory threshold: ${stats.memory}` + ) } if (stats.cpu > ChildProcessTracker.thresholds.cpu) { - getLogger().warn(`Process ${pid} exceeded cpu threshold: ${stats.cpu}`) + ChildProcessTracker.logger.warn(`ChildProcess: Process ${pid} exceeded cpu threshold: ${stats.cpu}`) } if (stats.elapsed > ChildProcessTracker.thresholds.elapsed) { - getLogger().warn(`Process ${pid} exceeded time threshold: ${stats.elapsed}`) + ChildProcessTracker.logger.warn( + `ChildProcess: Process ${pid} exceeded time threshold: ${stats.elapsed}` + ) } - } else { - getLogger().warn(`Missing process with id ${pid}`) } } From efe336e1db71ccb0dd52fe05c86bbdc92ad43e57 Mon Sep 17 00:00:00 2001 From: hkobew Date: Fri, 3 Jan 2025 10:11:19 -0500 Subject: [PATCH 13/48] improve test performance by properly stopping timer --- .../core/src/shared/utilities/pollingSet.ts | 2 +- .../shared/utilities/processUtils.test.ts | 35 ++++++++++--------- 2 files changed, 19 insertions(+), 18 deletions(-) diff --git a/packages/core/src/shared/utilities/pollingSet.ts b/packages/core/src/shared/utilities/pollingSet.ts index a9f7ef60fe4..1f0d57c1843 100644 --- a/packages/core/src/shared/utilities/pollingSet.ts +++ b/packages/core/src/shared/utilities/pollingSet.ts @@ -51,7 +51,7 @@ export class PollingSet extends Set { } public override clear(): void { - this.pollTimer = undefined + this.clearTimer() super.clear() } } diff --git a/packages/core/src/test/shared/utilities/processUtils.test.ts b/packages/core/src/test/shared/utilities/processUtils.test.ts index 9274a678217..882cb3311ff 100644 --- a/packages/core/src/test/shared/utilities/processUtils.test.ts +++ b/packages/core/src/test/shared/utilities/processUtils.test.ts @@ -394,23 +394,24 @@ describe('ChildProcessTracker', function () { await clock.tickAsync(ChildProcessTracker.pollingInterval) assert.strictEqual(tracker.has(childProcess), false, 'process was not removed after stopping') }) - - it('multiple processes from same command are tracked seperately', async function () { - const childProcess1 = new ChildProcess(getSleepCmd(), ['90']) - const childProcess2 = new ChildProcess(getSleepCmd(), ['90']) - childProcess1.run().catch(() => assert.fail('sleep command threw an error')) - childProcess2.run().catch(() => assert.fail('sleep command threw an error')) - tracker.add(childProcess1) - tracker.add(childProcess2) - - assert.strictEqual(tracker.has(childProcess1), true, 'Missing first process') - assert.strictEqual(tracker.has(childProcess2), true, 'Missing second process') - - childProcess1.stop() - await clock.tickAsync(ChildProcessTracker.pollingInterval) - assert.strictEqual(tracker.has(childProcess2), true, 'first process was not removed after stopping it') - assert.strictEqual(tracker.size(), 1) - }) + for (const _ of Array.from({ length: 1000 })) { + it('multiple processes from same command are tracked seperately', async function () { + const childProcess1 = new ChildProcess(getSleepCmd(), ['90']) + const childProcess2 = new ChildProcess(getSleepCmd(), ['90']) + childProcess1.run().catch(() => assert.fail('sleep command threw an error')) + childProcess2.run().catch(() => assert.fail('sleep command threw an error')) + tracker.add(childProcess1) + tracker.add(childProcess2) + + assert.strictEqual(tracker.has(childProcess1), true, 'Missing first process') + assert.strictEqual(tracker.has(childProcess2), true, 'Missing second process') + + childProcess1.stop() + await clock.tickAsync(ChildProcessTracker.pollingInterval) + assert.strictEqual(tracker.has(childProcess2), true, 'second process was mistakenly removed') + assert.strictEqual(tracker.has(childProcess1), false, 'first process was not removed after stopping it') + }) + } it('logs a warning message when system usage exceeds threshold', async function () { const childProcess = new ChildProcess(getSleepCmd(), ['90']) From 30ab5b5c7f8486de9cb9988f9adc309e0c6a94e0 Mon Sep 17 00:00:00 2001 From: hkobew Date: Fri, 3 Jan 2025 10:20:26 -0500 Subject: [PATCH 14/48] fix circular dep --- packages/core/src/shared/utilities/pollingSet.ts | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/packages/core/src/shared/utilities/pollingSet.ts b/packages/core/src/shared/utilities/pollingSet.ts index 1f0d57c1843..68ee34c4c21 100644 --- a/packages/core/src/shared/utilities/pollingSet.ts +++ b/packages/core/src/shared/utilities/pollingSet.ts @@ -3,7 +3,7 @@ * SPDX-License-Identifier: Apache-2.0 */ -import { globals } from '..' +import globals from '../extensionGlobals' /** * A useful abstraction that does the following: From 10537e124a01218a16960e364210f3352586e1ab Mon Sep 17 00:00:00 2001 From: hkobew Date: Fri, 3 Jan 2025 10:22:50 -0500 Subject: [PATCH 15/48] add debugging messages for flaky test --- packages/core/src/shared/utilities/processUtils.ts | 2 ++ packages/core/src/test/shared/utilities/processUtils.test.ts | 1 + 2 files changed, 3 insertions(+) diff --git a/packages/core/src/shared/utilities/processUtils.ts b/packages/core/src/shared/utilities/processUtils.ts index 346b4151e6e..2cc8e1739ad 100644 --- a/packages/core/src/shared/utilities/processUtils.ts +++ b/packages/core/src/shared/utilities/processUtils.ts @@ -85,10 +85,12 @@ export class ChildProcessTracker { } private cleanUp() { + console.log('in clean up') const terminatedProcesses = Array.from(this.#pids.values()).filter( (pid: number) => this.#processByPid.get(pid)?.stopped ) for (const pid of terminatedProcesses) { + console.log('removing %s', pid) this.delete(pid) } } diff --git a/packages/core/src/test/shared/utilities/processUtils.test.ts b/packages/core/src/test/shared/utilities/processUtils.test.ts index 882cb3311ff..e31877894f9 100644 --- a/packages/core/src/test/shared/utilities/processUtils.test.ts +++ b/packages/core/src/test/shared/utilities/processUtils.test.ts @@ -407,6 +407,7 @@ describe('ChildProcessTracker', function () { assert.strictEqual(tracker.has(childProcess2), true, 'Missing second process') childProcess1.stop() + console.log('child process 1 stopped') await clock.tickAsync(ChildProcessTracker.pollingInterval) assert.strictEqual(tracker.has(childProcess2), true, 'second process was mistakenly removed') assert.strictEqual(tracker.has(childProcess1), false, 'first process was not removed after stopping it') From 46a556bdb28522185069a1fd2d7d0cc093cd0040 Mon Sep 17 00:00:00 2001 From: hkobew Date: Fri, 3 Jan 2025 10:31:44 -0500 Subject: [PATCH 16/48] add safe wrapper around stop --- packages/core/src/shared/utilities/processUtils.ts | 5 ++--- .../src/test/shared/utilities/processUtils.test.ts | 10 +++++++--- 2 files changed, 9 insertions(+), 6 deletions(-) diff --git a/packages/core/src/shared/utilities/processUtils.ts b/packages/core/src/shared/utilities/processUtils.ts index 2cc8e1739ad..56b99284c88 100644 --- a/packages/core/src/shared/utilities/processUtils.ts +++ b/packages/core/src/shared/utilities/processUtils.ts @@ -85,12 +85,10 @@ export class ChildProcessTracker { } private cleanUp() { - console.log('in clean up') const terminatedProcesses = Array.from(this.#pids.values()).filter( (pid: number) => this.#processByPid.get(pid)?.stopped ) for (const pid of terminatedProcesses) { - console.log('removing %s', pid) this.delete(pid) } } @@ -173,6 +171,7 @@ export class ChildProcessTracker { */ export class ChildProcess { static #runningProcesses = new ChildProcessTracker() + static stopTimeout = 3000 #childProcess: proc.ChildProcess | undefined #processErrors: Error[] = [] #processResult: ChildProcessResult | undefined @@ -389,7 +388,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') diff --git a/packages/core/src/test/shared/utilities/processUtils.test.ts b/packages/core/src/test/shared/utilities/processUtils.test.ts index e31877894f9..d5a56ac5141 100644 --- a/packages/core/src/test/shared/utilities/processUtils.test.ts +++ b/packages/core/src/test/shared/utilities/processUtils.test.ts @@ -360,6 +360,11 @@ function getSleepCmd() { return isWin() ? 'timeout' : 'sleep' } +async function stopAndWait(cp: ChildProcess) { + cp.stop(true) + await waitUntil(async () => cp.stopped, { timeout: ChildProcess.stopTimeout * 2, interval: 100, truthy: true }) +} + describe('ChildProcessTracker', function () { let tracker: ChildProcessTracker let clock: FakeTimers.InstalledClock @@ -389,7 +394,7 @@ describe('ChildProcessTracker', function () { await clock.tickAsync(ChildProcessTracker.pollingInterval) assert.strictEqual(tracker.has(childProcess), true, 'process was mistakenly removed') - childProcess.stop(true) + await stopAndWait(childProcess) await clock.tickAsync(ChildProcessTracker.pollingInterval) assert.strictEqual(tracker.has(childProcess), false, 'process was not removed after stopping') @@ -406,8 +411,7 @@ describe('ChildProcessTracker', function () { assert.strictEqual(tracker.has(childProcess1), true, 'Missing first process') assert.strictEqual(tracker.has(childProcess2), true, 'Missing second process') - childProcess1.stop() - console.log('child process 1 stopped') + await stopAndWait(childProcess1) await clock.tickAsync(ChildProcessTracker.pollingInterval) assert.strictEqual(tracker.has(childProcess2), true, 'second process was mistakenly removed') assert.strictEqual(tracker.has(childProcess1), false, 'first process was not removed after stopping it') From 3c1531f68014db51589a3638176652297c5f7853 Mon Sep 17 00:00:00 2001 From: hkobew Date: Fri, 3 Jan 2025 10:46:31 -0500 Subject: [PATCH 17/48] avoid waitUntil with stubbed clock --- .../src/test/shared/utilities/processUtils.test.ts | 11 ++++++----- 1 file changed, 6 insertions(+), 5 deletions(-) diff --git a/packages/core/src/test/shared/utilities/processUtils.test.ts b/packages/core/src/test/shared/utilities/processUtils.test.ts index d5a56ac5141..86f8a2e83db 100644 --- a/packages/core/src/test/shared/utilities/processUtils.test.ts +++ b/packages/core/src/test/shared/utilities/processUtils.test.ts @@ -360,9 +360,10 @@ function getSleepCmd() { return isWin() ? 'timeout' : 'sleep' } -async function stopAndWait(cp: ChildProcess) { +// ChildProcess.stop is non-async and doesn't wait for the process to be stopped. +async function stopAndWait(cp: ChildProcess, clock: FakeTimers.InstalledClock) { cp.stop(true) - await waitUntil(async () => cp.stopped, { timeout: ChildProcess.stopTimeout * 2, interval: 100, truthy: true }) + await clock.tickAsync(ChildProcess.stopTimeout) } describe('ChildProcessTracker', function () { @@ -394,12 +395,12 @@ describe('ChildProcessTracker', function () { await clock.tickAsync(ChildProcessTracker.pollingInterval) assert.strictEqual(tracker.has(childProcess), true, 'process was mistakenly removed') - await stopAndWait(childProcess) + await stopAndWait(childProcess, clock) await clock.tickAsync(ChildProcessTracker.pollingInterval) assert.strictEqual(tracker.has(childProcess), false, 'process was not removed after stopping') }) - for (const _ of Array.from({ length: 1000 })) { + for (const _ of Array.from({ length: 100 })) { it('multiple processes from same command are tracked seperately', async function () { const childProcess1 = new ChildProcess(getSleepCmd(), ['90']) const childProcess2 = new ChildProcess(getSleepCmd(), ['90']) @@ -411,7 +412,7 @@ describe('ChildProcessTracker', function () { assert.strictEqual(tracker.has(childProcess1), true, 'Missing first process') assert.strictEqual(tracker.has(childProcess2), true, 'Missing second process') - await stopAndWait(childProcess1) + await stopAndWait(childProcess1, clock) await clock.tickAsync(ChildProcessTracker.pollingInterval) assert.strictEqual(tracker.has(childProcess2), true, 'second process was mistakenly removed') assert.strictEqual(tracker.has(childProcess1), false, 'first process was not removed after stopping it') From e9b4605c0d796d4deb8b3a5d7e0c801867757f88 Mon Sep 17 00:00:00 2001 From: hkobew Date: Fri, 3 Jan 2025 11:16:51 -0500 Subject: [PATCH 18/48] remove dependency --- package-lock.json | 20 ------- package.json | 2 - .../core/src/shared/utilities/processUtils.ts | 55 ++++++++++++++----- .../shared/utilities/processUtils.test.ts | 13 ----- 4 files changed, 42 insertions(+), 48 deletions(-) diff --git a/package-lock.json b/package-lock.json index 75a0e6b914d..8a549622f37 100644 --- a/package-lock.json +++ b/package-lock.json @@ -16,8 +16,6 @@ ], "dependencies": { "@types/node": "^22.7.5", - "@types/pidusage": "^2.0.5", - "pidusage": "^3.0.2", "vscode-nls": "^5.2.0", "vscode-nls-dev": "^4.0.4" }, @@ -9198,12 +9196,6 @@ "dev": true, "license": "MIT" }, - "node_modules/@types/pidusage": { - "version": "2.0.5", - "resolved": "https://registry.npmjs.org/@types/pidusage/-/pidusage-2.0.5.tgz", - "integrity": "sha512-MIiyZI4/MK9UGUXWt0jJcCZhVw7YdhBuTOuqP/BjuLDLZ2PmmViMIQgZiWxtaMicQfAz/kMrZ5T7PKxFSkTeUA==", - "license": "MIT" - }, "node_modules/@types/prettier": { "version": "2.7.0", "dev": true, @@ -16993,18 +16985,6 @@ "url": "https://github.com/sponsors/jonschlinkert" } }, - "node_modules/pidusage": { - "version": "3.0.2", - "resolved": "https://registry.npmjs.org/pidusage/-/pidusage-3.0.2.tgz", - "integrity": "sha512-g0VU+y08pKw5M8EZ2rIGiEBaB8wrQMjYGFfW2QVIfyT8V+fq8YFLkvlz4bz5ljvFDJYNFCWT3PWqcRr2FKO81w==", - "license": "MIT", - "dependencies": { - "safe-buffer": "^5.2.1" - }, - "engines": { - "node": ">=10" - } - }, "node_modules/pkg-dir": { "version": "4.2.0", "dev": true, diff --git a/package.json b/package.json index 2fcc6d6c837..e658a3a916e 100644 --- a/package.json +++ b/package.json @@ -72,8 +72,6 @@ }, "dependencies": { "@types/node": "^22.7.5", - "@types/pidusage": "^2.0.5", - "pidusage": "^3.0.2", "vscode-nls": "^5.2.0", "vscode-nls-dev": "^4.0.4" } diff --git a/packages/core/src/shared/utilities/processUtils.ts b/packages/core/src/shared/utilities/processUtils.ts index 56b99284c88..a9ef46364bc 100644 --- a/packages/core/src/shared/utilities/processUtils.ts +++ b/packages/core/src/shared/utilities/processUtils.ts @@ -9,7 +9,7 @@ import * as logger from '../logger' import { Timeout, CancellationError, waitUntil } from './timeoutUtils' import { PollingSet } from './pollingSet' import { getLogger } from '../logger/logger' -import pidusage from 'pidusage' +import { isWin } from '../vscode/env' export interface RunParameterContext { /** Reports an error parsed from the stdin/stdout streams. */ @@ -67,14 +67,12 @@ export const eof = Symbol('EOF') export interface ProcessStats { memory: number cpu: number - elapsed: number } export class ChildProcessTracker { static readonly pollingInterval: number = 10000 static readonly thresholds: ProcessStats = { memory: 100 * 1024 * 1024, // 100 MB cpu: 50, - elapsed: 30 * 1000, // 30 seconds } static readonly logger = getLogger('childProcess') #processByPid: Map = new Map() @@ -118,11 +116,6 @@ export class ChildProcessTracker { if (stats.cpu > ChildProcessTracker.thresholds.cpu) { ChildProcessTracker.logger.warn(`ChildProcess: Process ${pid} exceeded cpu threshold: ${stats.cpu}`) } - if (stats.elapsed > ChildProcessTracker.thresholds.elapsed) { - ChildProcessTracker.logger.warn( - `ChildProcess: Process ${pid} exceeded time threshold: ${stats.elapsed}` - ) - } } } @@ -154,11 +147,47 @@ export class ChildProcessTracker { } public async getUsage(pid: number): Promise { - const stats = await pidusage(pid) - return { - memory: stats.memory, - cpu: stats.cpu, - elapsed: stats.elapsed, + const 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, + } + } + const 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, + } + } + try { + return isWin() ? getWindowsUsage() : getUnixUsage() + } catch (e) { + ChildProcessTracker.logger.warn(`ChildProcess: Failed to get process stats for ${pid}: ${e}`) + return { cpu: 0, memory: 0 } } } } diff --git a/packages/core/src/test/shared/utilities/processUtils.test.ts b/packages/core/src/test/shared/utilities/processUtils.test.ts index 86f8a2e83db..e867bb7d887 100644 --- a/packages/core/src/test/shared/utilities/processUtils.test.ts +++ b/packages/core/src/test/shared/utilities/processUtils.test.ts @@ -427,18 +427,10 @@ describe('ChildProcessTracker', function () { const highCpu: ProcessStats = { cpu: ChildProcessTracker.thresholds.cpu + 1, memory: 0, - elapsed: 0, } const highMemory: ProcessStats = { cpu: 0, memory: ChildProcessTracker.thresholds.memory + 1, - elapsed: 0, - } - - const highTime: ProcessStats = { - cpu: 0, - memory: 0, - elapsed: ChildProcessTracker.thresholds.elapsed + 1, } usageMock.resolves(highCpu) @@ -449,10 +441,6 @@ describe('ChildProcessTracker', function () { usageMock.resolves(highMemory) await clock.tickAsync(ChildProcessTracker.pollingInterval) assertLogsContain('exceeded memory threshold', false, 'warn') - - usageMock.resolves(highTime) - await clock.tickAsync(ChildProcessTracker.pollingInterval) - assertLogsContain('exceeded time threshold', false, 'warn') }) it('includes pid in logs', async function () { @@ -477,7 +465,6 @@ describe('ChildProcessTracker', function () { usageMock.resolves({ cpu: ChildProcessTracker.thresholds.cpu - 1, memory: ChildProcessTracker.thresholds.memory - 1, - elapsed: ChildProcessTracker.thresholds.elapsed - 1, }) await clock.tickAsync(ChildProcessTracker.pollingInterval) From c1975f9754ccd620c1de163c66b00360a318df05 Mon Sep 17 00:00:00 2001 From: hkobew Date: Fri, 3 Jan 2025 11:28:38 -0500 Subject: [PATCH 19/48] avoid circular dep --- packages/core/src/shared/utilities/processUtils.ts | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/packages/core/src/shared/utilities/processUtils.ts b/packages/core/src/shared/utilities/processUtils.ts index a9ef46364bc..7e7b34d0808 100644 --- a/packages/core/src/shared/utilities/processUtils.ts +++ b/packages/core/src/shared/utilities/processUtils.ts @@ -9,7 +9,6 @@ import * as logger from '../logger' import { Timeout, CancellationError, waitUntil } from './timeoutUtils' import { PollingSet } from './pollingSet' import { getLogger } from '../logger/logger' -import { isWin } from '../vscode/env' export interface RunParameterContext { /** Reports an error parsed from the stdin/stdout streams. */ @@ -184,7 +183,8 @@ export class ChildProcessTracker { } } try { - return isWin() ? getWindowsUsage() : getUnixUsage() + // isWin() leads to circular dependency. + return process.platform === 'win32' ? getWindowsUsage() : getUnixUsage() } catch (e) { ChildProcessTracker.logger.warn(`ChildProcess: Failed to get process stats for ${pid}: ${e}`) return { cpu: 0, memory: 0 } From 59f8215f3f5992be03664b8a01b2c691824921cc Mon Sep 17 00:00:00 2001 From: hkobew Date: Fri, 3 Jan 2025 11:29:48 -0500 Subject: [PATCH 20/48] fix logging statements --- packages/core/src/shared/utilities/processUtils.ts | 10 ++++------ 1 file changed, 4 insertions(+), 6 deletions(-) diff --git a/packages/core/src/shared/utilities/processUtils.ts b/packages/core/src/shared/utilities/processUtils.ts index 7e7b34d0808..0ed88df0bfd 100644 --- a/packages/core/src/shared/utilities/processUtils.ts +++ b/packages/core/src/shared/utilities/processUtils.ts @@ -101,19 +101,17 @@ export class ChildProcessTracker { private async checkProcessUsage(pid: number): Promise { if (!this.#pids.has(pid)) { - ChildProcessTracker.logger.warn(`ChildProcess: Missing process with id ${pid}`) + ChildProcessTracker.logger.warn(`Missing process with id ${pid}`) return } const stats = await this.getUsage(pid) if (stats) { ChildProcessTracker.logger.debug(`stats for ${pid}: %O`, stats) if (stats.memory > ChildProcessTracker.thresholds.memory) { - ChildProcessTracker.logger.warn( - `ChildProcess: Process ${pid} exceeded memory threshold: ${stats.memory}` - ) + ChildProcessTracker.logger.warn(`Process ${pid} exceeded memory threshold: ${stats.memory}`) } if (stats.cpu > ChildProcessTracker.thresholds.cpu) { - ChildProcessTracker.logger.warn(`ChildProcess: Process ${pid} exceeded cpu threshold: ${stats.cpu}`) + ChildProcessTracker.logger.warn(`Process ${pid} exceeded cpu threshold: ${stats.cpu}`) } } } @@ -186,7 +184,7 @@ export class ChildProcessTracker { // isWin() leads to circular dependency. return process.platform === 'win32' ? getWindowsUsage() : getUnixUsage() } catch (e) { - ChildProcessTracker.logger.warn(`ChildProcess: Failed to get process stats for ${pid}: ${e}`) + ChildProcessTracker.logger.warn(`Failed to get process stats for ${pid}: ${e}`) return { cpu: 0, memory: 0 } } } From 39175c054f6a5ac464ab0fd6a52dbdaac2d1050c Mon Sep 17 00:00:00 2001 From: hkobew Date: Fri, 3 Jan 2025 11:38:12 -0500 Subject: [PATCH 21/48] clean up tests --- .../shared/utilities/processUtils.test.ts | 22 +++++++++---------- 1 file changed, 11 insertions(+), 11 deletions(-) diff --git a/packages/core/src/test/shared/utilities/processUtils.test.ts b/packages/core/src/test/shared/utilities/processUtils.test.ts index e867bb7d887..336a05960c3 100644 --- a/packages/core/src/test/shared/utilities/processUtils.test.ts +++ b/packages/core/src/test/shared/utilities/processUtils.test.ts @@ -366,6 +366,12 @@ async function stopAndWait(cp: ChildProcess, clock: FakeTimers.InstalledClock) { await clock.tickAsync(ChildProcess.stopTimeout) } +function startSleepProcess(timeout: number = 90) { + const childProcess = new ChildProcess(getSleepCmd(), [timeout.toString()]) + childProcess.run().catch(() => assert.fail('sleep command threw an error')) + return childProcess +} + describe('ChildProcessTracker', function () { let tracker: ChildProcessTracker let clock: FakeTimers.InstalledClock @@ -388,8 +394,7 @@ describe('ChildProcessTracker', function () { it(`removes stopped processes every ${ChildProcessTracker.pollingInterval / 1000} seconds`, async function () { // Start a 'sleep' command, check it only removes after we stop it. - const childProcess = new ChildProcess(getSleepCmd(), ['90']) - childProcess.run().catch(() => assert.fail('sleep command threw an error')) + const childProcess = startSleepProcess() tracker.add(childProcess) assert.strictEqual(tracker.has(childProcess), true, 'failed to add sleep command') @@ -402,10 +407,8 @@ describe('ChildProcessTracker', function () { }) for (const _ of Array.from({ length: 100 })) { it('multiple processes from same command are tracked seperately', async function () { - const childProcess1 = new ChildProcess(getSleepCmd(), ['90']) - const childProcess2 = new ChildProcess(getSleepCmd(), ['90']) - childProcess1.run().catch(() => assert.fail('sleep command threw an error')) - childProcess2.run().catch(() => assert.fail('sleep command threw an error')) + const childProcess1 = startSleepProcess() + const childProcess2 = startSleepProcess() tracker.add(childProcess1) tracker.add(childProcess2) @@ -420,8 +423,7 @@ describe('ChildProcessTracker', function () { } it('logs a warning message when system usage exceeds threshold', async function () { - const childProcess = new ChildProcess(getSleepCmd(), ['90']) - childProcess.run().catch(() => assert.fail('sleep command threw an error')) + const childProcess = startSleepProcess() tracker.add(childProcess) const highCpu: ProcessStats = { @@ -444,14 +446,12 @@ describe('ChildProcessTracker', function () { }) it('includes pid in logs', async function () { - const childProcess = new ChildProcess(getSleepCmd(), ['90']) - childProcess.run().catch(() => assert.fail('sleep command threw an error')) + const childProcess = startSleepProcess() tracker.add(childProcess) usageMock.resolves({ cpu: ChildProcessTracker.thresholds.cpu + 1, memory: 0, - elapsed: 0, }) await clock.tickAsync(ChildProcessTracker.pollingInterval) From e04eefe3eba3426e716110c3e7d1a012bbb9100d Mon Sep 17 00:00:00 2001 From: hkobew Date: Fri, 3 Jan 2025 11:53:09 -0500 Subject: [PATCH 22/48] increase waiting period to avoid flakiness --- packages/core/src/test/shared/utilities/processUtils.test.ts | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/packages/core/src/test/shared/utilities/processUtils.test.ts b/packages/core/src/test/shared/utilities/processUtils.test.ts index 336a05960c3..5a249eaa66e 100644 --- a/packages/core/src/test/shared/utilities/processUtils.test.ts +++ b/packages/core/src/test/shared/utilities/processUtils.test.ts @@ -363,7 +363,7 @@ function getSleepCmd() { // ChildProcess.stop is non-async and doesn't wait for the process to be stopped. async function stopAndWait(cp: ChildProcess, clock: FakeTimers.InstalledClock) { cp.stop(true) - await clock.tickAsync(ChildProcess.stopTimeout) + await clock.tickAsync(ChildProcess.stopTimeout * 2) } function startSleepProcess(timeout: number = 90) { From abf3603ae31f66b2aeeeee82b752208f460f8e48 Mon Sep 17 00:00:00 2001 From: hkobew Date: Mon, 6 Jan 2025 10:33:43 -0500 Subject: [PATCH 23/48] add some debugging information for flaky test --- .../core/src/test/shared/utilities/processUtils.test.ts | 7 ++++++- 1 file changed, 6 insertions(+), 1 deletion(-) diff --git a/packages/core/src/test/shared/utilities/processUtils.test.ts b/packages/core/src/test/shared/utilities/processUtils.test.ts index 5a249eaa66e..7668391786c 100644 --- a/packages/core/src/test/shared/utilities/processUtils.test.ts +++ b/packages/core/src/test/shared/utilities/processUtils.test.ts @@ -364,6 +364,7 @@ function getSleepCmd() { async function stopAndWait(cp: ChildProcess, clock: FakeTimers.InstalledClock) { cp.stop(true) await clock.tickAsync(ChildProcess.stopTimeout * 2) + assert.ok(cp.stopped, `Failed to stop process with id: ${cp.pid()}`) } function startSleepProcess(timeout: number = 90) { @@ -405,7 +406,7 @@ describe('ChildProcessTracker', function () { await clock.tickAsync(ChildProcessTracker.pollingInterval) assert.strictEqual(tracker.has(childProcess), false, 'process was not removed after stopping') }) - for (const _ of Array.from({ length: 100 })) { + for (const _ of Array.from({ length: 1000 })) { it('multiple processes from same command are tracked seperately', async function () { const childProcess1 = startSleepProcess() const childProcess2 = startSleepProcess() @@ -417,6 +418,10 @@ describe('ChildProcessTracker', function () { await stopAndWait(childProcess1, clock) await clock.tickAsync(ChildProcessTracker.pollingInterval) + if (tracker.has(childProcess1)) { + console.log('process: %O', childProcess1) + console.log('tracker: %O', tracker) + } assert.strictEqual(tracker.has(childProcess2), true, 'second process was mistakenly removed') assert.strictEqual(tracker.has(childProcess1), false, 'first process was not removed after stopping it') }) From 4f2eaf07475cdf81c3a603dd71a1d631316326b3 Mon Sep 17 00:00:00 2001 From: hkobew Date: Mon, 6 Jan 2025 11:32:22 -0500 Subject: [PATCH 24/48] handle result and process individually and explicitly --- .../shared/utilities/processUtils.test.ts | 96 ++++++++++++------- 1 file changed, 60 insertions(+), 36 deletions(-) diff --git a/packages/core/src/test/shared/utilities/processUtils.test.ts b/packages/core/src/test/shared/utilities/processUtils.test.ts index 7668391786c..9b1acb54567 100644 --- a/packages/core/src/test/shared/utilities/processUtils.test.ts +++ b/packages/core/src/test/shared/utilities/processUtils.test.ts @@ -8,7 +8,13 @@ import * as os from 'os' import * as path from 'path' import * as sinon from 'sinon' import { makeTemporaryToolkitFolder, tryRemoveFolder } from '../../../shared/filesystemUtilities' -import { ChildProcess, ChildProcessTracker, eof, ProcessStats } 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' @@ -356,21 +362,24 @@ describe('ChildProcess', async function () { } }) +interface RunningProcess { + childProcess: ChildProcess + result: Promise +} + function getSleepCmd() { return isWin() ? 'timeout' : 'sleep' } -// ChildProcess.stop is non-async and doesn't wait for the process to be stopped. -async function stopAndWait(cp: ChildProcess, clock: FakeTimers.InstalledClock) { - cp.stop(true) - await clock.tickAsync(ChildProcess.stopTimeout * 2) - assert.ok(cp.stopped, `Failed to stop process with id: ${cp.pid()}`) +async function stopAndWait(runningProcess: RunningProcess): Promise { + runningProcess.childProcess.stop(true) + await runningProcess.result } -function startSleepProcess(timeout: number = 90) { +function startSleepProcess(timeout: number = 90): RunningProcess { const childProcess = new ChildProcess(getSleepCmd(), [timeout.toString()]) - childProcess.run().catch(() => assert.fail('sleep command threw an error')) - return childProcess + const result = childProcess.run().catch(() => assert.fail('sleep command threw an error')) + return { childProcess, result } } describe('ChildProcessTracker', function () { @@ -395,41 +404,51 @@ describe('ChildProcessTracker', function () { it(`removes stopped processes every ${ChildProcessTracker.pollingInterval / 1000} seconds`, async function () { // Start a 'sleep' command, check it only removes after we stop it. - const childProcess = startSleepProcess() - tracker.add(childProcess) - assert.strictEqual(tracker.has(childProcess), true, 'failed to add sleep command') + 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(childProcess), true, 'process was mistakenly removed') - await stopAndWait(childProcess, clock) + assert.strictEqual(tracker.has(runningProcess.childProcess), true, 'process was mistakenly removed') + await stopAndWait(runningProcess) await clock.tickAsync(ChildProcessTracker.pollingInterval) - assert.strictEqual(tracker.has(childProcess), false, 'process was not removed after stopping') + assert.strictEqual(tracker.has(runningProcess.childProcess), false, 'process was not removed after stopping') }) for (const _ of Array.from({ length: 1000 })) { it('multiple processes from same command are tracked seperately', async function () { - const childProcess1 = startSleepProcess() - const childProcess2 = startSleepProcess() - tracker.add(childProcess1) - tracker.add(childProcess2) + const runningProcess1 = startSleepProcess() + const runningProcess2 = startSleepProcess() + tracker.add(runningProcess1.childProcess) + tracker.add(runningProcess2.childProcess) - assert.strictEqual(tracker.has(childProcess1), true, 'Missing first process') - assert.strictEqual(tracker.has(childProcess2), true, 'Missing second process') + assert.strictEqual(tracker.has(runningProcess1.childProcess), true, 'Missing first process') + assert.strictEqual(tracker.has(runningProcess2.childProcess), true, 'Missing second process') - await stopAndWait(childProcess1, clock) + await stopAndWait(runningProcess1) await clock.tickAsync(ChildProcessTracker.pollingInterval) - if (tracker.has(childProcess1)) { - console.log('process: %O', childProcess1) - console.log('tracker: %O', tracker) - } - assert.strictEqual(tracker.has(childProcess2), true, 'second process was mistakenly removed') - assert.strictEqual(tracker.has(childProcess1), false, 'first process was not removed after stopping it') + 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 childProcess = startSleepProcess() - tracker.add(childProcess) + const runningProcess = startSleepProcess() + tracker.add(runningProcess.childProcess) const highCpu: ProcessStats = { cpu: ChildProcessTracker.thresholds.cpu + 1, @@ -448,11 +467,13 @@ describe('ChildProcessTracker', function () { usageMock.resolves(highMemory) await clock.tickAsync(ChildProcessTracker.pollingInterval) assertLogsContain('exceeded memory threshold', false, 'warn') + + await stopAndWait(runningProcess) }) it('includes pid in logs', async function () { - const childProcess = startSleepProcess() - tracker.add(childProcess) + const runningProcess = startSleepProcess() + tracker.add(runningProcess.childProcess) usageMock.resolves({ cpu: ChildProcessTracker.thresholds.cpu + 1, @@ -460,12 +481,13 @@ describe('ChildProcessTracker', function () { }) await clock.tickAsync(ChildProcessTracker.pollingInterval) - assertLogsContain(childProcess.pid().toString(), false, 'warn') + assertLogsContain(runningProcess.childProcess.pid().toString(), false, 'warn') + + await stopAndWait(runningProcess) }) it('does not log for processes within threshold', async function () { - const childProcess = new ChildProcess(getSleepCmd(), ['90']) - childProcess.run().catch(() => assert.fail('sleep command threw an error')) + const runningProcess = startSleepProcess() usageMock.resolves({ cpu: ChildProcessTracker.thresholds.cpu - 1, @@ -474,6 +496,8 @@ describe('ChildProcessTracker', function () { await clock.tickAsync(ChildProcessTracker.pollingInterval) - assert.throws(() => assertLogsContain(childProcess.pid().toString(), false, 'warn')) + assert.throws(() => assertLogsContain(runningProcess.childProcess.pid().toString(), false, 'warn')) + + await stopAndWait(runningProcess) }) }) From b0976b32e718a678a0ef95b28151a8107e425782 Mon Sep 17 00:00:00 2001 From: hkobew Date: Mon, 6 Jan 2025 11:48:40 -0500 Subject: [PATCH 25/48] remove repeat tests --- .../shared/utilities/processUtils.test.ts | 59 +++++++++---------- 1 file changed, 29 insertions(+), 30 deletions(-) diff --git a/packages/core/src/test/shared/utilities/processUtils.test.ts b/packages/core/src/test/shared/utilities/processUtils.test.ts index 9b1acb54567..93d042f904d 100644 --- a/packages/core/src/test/shared/utilities/processUtils.test.ts +++ b/packages/core/src/test/shared/utilities/processUtils.test.ts @@ -415,36 +415,35 @@ describe('ChildProcessTracker', function () { await clock.tickAsync(ChildProcessTracker.pollingInterval) assert.strictEqual(tracker.has(runningProcess.childProcess), false, 'process was not removed after stopping') }) - for (const _ of Array.from({ length: 1000 })) { - 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('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() From ec3abbfc4a792a85ce1376c23f991fd61794a04b Mon Sep 17 00:00:00 2001 From: hkobew Date: Mon, 6 Jan 2025 12:41:38 -0500 Subject: [PATCH 26/48] reword logging statement --- packages/core/src/shared/utilities/processUtils.ts | 8 ++++---- .../core/src/test/shared/utilities/processUtils.test.ts | 2 +- 2 files changed, 5 insertions(+), 5 deletions(-) diff --git a/packages/core/src/shared/utilities/processUtils.ts b/packages/core/src/shared/utilities/processUtils.ts index 0ed88df0bfd..de6d5875c79 100644 --- a/packages/core/src/shared/utilities/processUtils.ts +++ b/packages/core/src/shared/utilities/processUtils.ts @@ -68,7 +68,7 @@ export interface ProcessStats { cpu: number } export class ChildProcessTracker { - static readonly pollingInterval: number = 10000 + static readonly pollingInterval: number = 10000 // Check usage every 10 seconds static readonly thresholds: ProcessStats = { memory: 100 * 1024 * 1024, // 100 MB cpu: 50, @@ -106,7 +106,7 @@ export class ChildProcessTracker { } const stats = await this.getUsage(pid) if (stats) { - ChildProcessTracker.logger.debug(`stats for ${pid}: %O`, 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}`) } @@ -127,7 +127,7 @@ export class ChildProcessTracker { this.#pids.delete(childProcessId) } - public size() { + public get size() { return this.#pids.size } @@ -271,7 +271,7 @@ export class ChildProcess { const args = this.#args.concat(options.extraArgs ?? []) const debugDetail = this.#log.logLevelEnabled('debug') - ? ` (running processes: ${ChildProcess.#runningProcesses.size()})` + ? ` (running processes: ${ChildProcess.#runningProcesses.size})` : '' this.#log.info(`Command: ${this.toString(options.logging === 'noparams')}${debugDetail}`) diff --git a/packages/core/src/test/shared/utilities/processUtils.test.ts b/packages/core/src/test/shared/utilities/processUtils.test.ts index 93d042f904d..3a12ae01df5 100644 --- a/packages/core/src/test/shared/utilities/processUtils.test.ts +++ b/packages/core/src/test/shared/utilities/processUtils.test.ts @@ -442,7 +442,7 @@ describe('ChildProcessTracker', function () { 'second process was not removed after stopping it' ) - assert.strictEqual(tracker.size(), 0, 'expected tracker to be empty') + assert.strictEqual(tracker.size, 0, 'expected tracker to be empty') }) it('logs a warning message when system usage exceeds threshold', async function () { From 9f24127bae95e5a6f36f12dfd00d3e849b966bac Mon Sep 17 00:00:00 2001 From: hkobew Date: Tue, 7 Jan 2025 11:09:12 -0500 Subject: [PATCH 27/48] add dummy command --- packages/amazonq/package.json | 5 +++++ packages/core/package.nls.json | 1 + packages/core/src/extension.ts | 5 +++++ packages/toolkit/package.json | 5 +++++ 4 files changed, 16 insertions(+) diff --git a/packages/amazonq/package.json b/packages/amazonq/package.json index 9e144c171a3..b9f09c19688 100644 --- a/packages/amazonq/package.json +++ b/packages/amazonq/package.json @@ -595,6 +595,11 @@ "title": "%AWS.command.viewLogs%", "category": "%AWS.amazonq.title%" }, + { + "command": "aws.amazonq.viewActiveProcesses", + "title": "%AWS.command.viewActiveProcesses%", + "category": "%AWS.title%" + }, { "command": "aws.amazonq.github", "title": "%AWS.command.github%", diff --git a/packages/core/package.nls.json b/packages/core/package.nls.json index cab4f52dcee..63c703949b7 100644 --- a/packages/core/package.nls.json +++ b/packages/core/package.nls.json @@ -176,6 +176,7 @@ "AWS.command.submitFeedback": "Send Feedback...", "AWS.command.downloadSchemaItemCode": "Download Code Bindings", "AWS.command.viewLogs": "View Logs", + "AWS.command.viewActiveProcesses": "View Active Subprocesses", "AWS.command.cloudWatchLogs.searchLogGroup": "Search Log Group", "AWS.command.cloudWatchLogs.tailLogGroup": "Tail Log Group", "AWS.command.sam.newTemplate": "Create new SAM Template", diff --git a/packages/core/src/extension.ts b/packages/core/src/extension.ts index 00fd730b490..bc8bcf7681c 100644 --- a/packages/core/src/extension.ts +++ b/packages/core/src/extension.ts @@ -171,6 +171,11 @@ export async function activateCommon( await activateViewsShared(extContext.extensionContext) + context.subscriptions.push( + Commands.register(`aws.${contextPrefix}.viewActiveProcesses`, () => + console.log('running viewActiveProcesses command') + ) + ) return extContext } diff --git a/packages/toolkit/package.json b/packages/toolkit/package.json index b93cd063334..ded124972f2 100644 --- a/packages/toolkit/package.json +++ b/packages/toolkit/package.json @@ -3146,6 +3146,11 @@ "title": "%AWS.command.viewLogs%", "category": "%AWS.title%" }, + { + "command": "aws.toolkit.viewActiveProcesses", + "title": "%AWS.command.viewActiveProcesses%", + "category": "%AWS.title%" + }, { "command": "aws.toolkit.help", "title": "%AWS.command.help%", From 2d316751ca55779853fe9e8ca50c55d4f3376523 Mon Sep 17 00:00:00 2001 From: hkobew Date: Tue, 7 Jan 2025 11:23:42 -0500 Subject: [PATCH 28/48] convert tracker to singleton class --- packages/core/src/shared/utilities/processUtils.ts | 10 ++++++++-- .../src/test/shared/utilities/processUtils.test.ts | 2 +- 2 files changed, 9 insertions(+), 3 deletions(-) diff --git a/packages/core/src/shared/utilities/processUtils.ts b/packages/core/src/shared/utilities/processUtils.ts index de6d5875c79..b7ad97fc822 100644 --- a/packages/core/src/shared/utilities/processUtils.ts +++ b/packages/core/src/shared/utilities/processUtils.ts @@ -74,10 +74,16 @@ export class ChildProcessTracker { cpu: 50, } static readonly logger = getLogger('childProcess') + static #instance: ChildProcessTracker + + static get instance(): ChildProcessTracker { + return (this.#instance ??= new ChildProcessTracker()) + } + #processByPid: Map = new Map() #pids: PollingSet - public constructor() { + private constructor() { this.#pids = new PollingSet(ChildProcessTracker.pollingInterval, () => this.monitor()) } @@ -197,7 +203,7 @@ export class ChildProcessTracker { * - call and await run to get the results (pass or fail) */ export class ChildProcess { - static #runningProcesses = new ChildProcessTracker() + static #runningProcesses = ChildProcessTracker.instance static stopTimeout = 3000 #childProcess: proc.ChildProcess | undefined #processErrors: Error[] = [] diff --git a/packages/core/src/test/shared/utilities/processUtils.test.ts b/packages/core/src/test/shared/utilities/processUtils.test.ts index 3a12ae01df5..d68b697ca33 100644 --- a/packages/core/src/test/shared/utilities/processUtils.test.ts +++ b/packages/core/src/test/shared/utilities/processUtils.test.ts @@ -389,7 +389,7 @@ describe('ChildProcessTracker', function () { before(function () { clock = installFakeClock() - tracker = new ChildProcessTracker() + tracker = ChildProcessTracker.instance usageMock = sinon.stub(ChildProcessTracker.prototype, 'getUsage') }) From ee81478d7475ec61c3d2cf7590e08c0b7193a81d Mon Sep 17 00:00:00 2001 From: hkobew Date: Tue, 7 Jan 2025 12:07:45 -0500 Subject: [PATCH 29/48] log all usage at info level --- packages/core/src/extension.ts | 6 +- .../core/src/shared/utilities/processUtils.ts | 59 +++++++++++++------ 2 files changed, 45 insertions(+), 20 deletions(-) diff --git a/packages/core/src/extension.ts b/packages/core/src/extension.ts index bc8bcf7681c..ca2fad9be32 100644 --- a/packages/core/src/extension.ts +++ b/packages/core/src/extension.ts @@ -52,6 +52,7 @@ import { registerCommands } from './commands' import endpoints from '../resources/endpoints.json' import { getLogger, maybeShowMinVscodeWarning, setupUninstallHandler } from './shared' import { showViewLogsMessage } from './shared/utilities/messages' +import { ChildProcessTracker } from './shared/utilities/processUtils' disableAwsSdkWarning() @@ -172,8 +173,9 @@ export async function activateCommon( await activateViewsShared(extContext.extensionContext) context.subscriptions.push( - Commands.register(`aws.${contextPrefix}.viewActiveProcesses`, () => - console.log('running viewActiveProcesses command') + Commands.register( + `aws.${contextPrefix}.viewActiveProcesses`, + async () => await ChildProcessTracker.instance.logAllUsage() ) ) return extContext diff --git a/packages/core/src/shared/utilities/processUtils.ts b/packages/core/src/shared/utilities/processUtils.ts index b7ad97fc822..d9db0180241 100644 --- a/packages/core/src/shared/utilities/processUtils.ts +++ b/packages/core/src/shared/utilities/processUtils.ts @@ -2,7 +2,6 @@ * Copyright Amazon.com, Inc. or its affiliates. All Rights Reserved. * SPDX-License-Identifier: Apache-2.0 */ - import * as proc from 'child_process' // eslint-disable-line no-restricted-imports import * as crossSpawn from 'cross-spawn' import * as logger from '../logger' @@ -62,7 +61,7 @@ export interface ChildProcessResult { } export const eof = Symbol('EOF') - +type pid = number export interface ProcessStats { memory: number cpu: number @@ -70,26 +69,27 @@ export interface ProcessStats { export class ChildProcessTracker { static readonly pollingInterval: number = 10000 // Check usage every 10 seconds static readonly thresholds: ProcessStats = { - memory: 100 * 1024 * 1024, // 100 MB + memory: 100, // 100 MB cpu: 50, } - static readonly logger = getLogger('childProcess') + readonly logger: logger.Logger static #instance: ChildProcessTracker static get instance(): ChildProcessTracker { return (this.#instance ??= new ChildProcessTracker()) } - #processByPid: Map = new Map() - #pids: PollingSet + #processByPid: Map = new Map() + #pids: PollingSet private constructor() { + this.logger = getLogger('childProcess') 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 + (pid: pid) => this.#processByPid.get(pid)?.stopped ) for (const pid of terminatedProcesses) { this.delete(pid) @@ -98,26 +98,26 @@ export class ChildProcessTracker { private async monitor() { this.cleanUp() - ChildProcessTracker.logger.debug(`Active running processes size: ${this.#pids.size}`) + this.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 { + private async checkProcessUsage(pid: pid): Promise { if (!this.#pids.has(pid)) { - ChildProcessTracker.logger.warn(`Missing process with id ${pid}`) + this.logger.warn(`Missing process with id ${pid}`) return } const stats = await this.getUsage(pid) if (stats) { - ChildProcessTracker.logger.debug(`Process ${pid} usage: %O`, stats) + this.logger.debug(`Process ${pid} usage: %O`, stats) if (stats.memory > ChildProcessTracker.thresholds.memory) { - ChildProcessTracker.logger.warn(`Process ${pid} exceeded memory threshold: ${stats.memory}`) + this.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}`) + this.logger.warn(`Process ${pid} exceeded cpu threshold: ${stats.cpu}`) } } } @@ -128,7 +128,7 @@ export class ChildProcessTracker { this.#pids.start(pid) } - public delete(childProcessId: number) { + public delete(childProcessId: pid) { this.#processByPid.delete(childProcessId) this.#pids.delete(childProcessId) } @@ -149,7 +149,30 @@ export class ChildProcessTracker { this.#processByPid.clear() } - public async getUsage(pid: number): Promise { + public async getAllUsage(): Promise> { + return new Map( + await Promise.all( + Array.from(this.#pids).map(async (pid: pid) => { + const stats = await this.getUsage(pid) + return [pid, stats] as const + }) + ) + ) + } + + public async logAllUsage(): Promise { + if (this.size === 0) { + this.logger.info('No active subprocesses') + return + } + const usage = await this.getAllUsage() + const logMsg = Array.from(usage.entries()).reduce((acc, [pid, stats]) => { + return acc + `Process ${pid}: ${stats.cpu}% cpu, ${stats.memory} MB of memory\n` + }, '') + this.logger.info(`Active Subprocesses (${this.size} active)\n${logMsg}`) + } + + public async getUsage(pid: pid): Promise { const getWindowsUsage = () => { const cpuOutput = proc .execFileSync('wmic', [ @@ -170,7 +193,7 @@ export class ChildProcessTracker { return { cpu: isNaN(cpuPercentage) ? 0 : cpuPercentage, - memory: memoryBytes, + memory: memoryBytes / (1024 * 1024), } } const getUnixUsage = () => { @@ -183,14 +206,14 @@ export class ChildProcessTracker { return { cpu: isNaN(cpuPercentage) ? 0 : cpuPercentage, - memory: memoryBytes, + memory: memoryBytes / (1024 * 1024), } } 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}`) + this.logger.warn(`Failed to get process stats for ${pid}: ${e}`) return { cpu: 0, memory: 0 } } } From 63855940559970df6ab8ba3d577df8bbe1e6e99b Mon Sep 17 00:00:00 2001 From: hkobew Date: Tue, 7 Jan 2025 12:19:13 -0500 Subject: [PATCH 30/48] switch command name --- packages/amazonq/package.json | 4 ++-- packages/core/package.nls.json | 2 +- packages/core/src/extension.ts | 2 +- packages/toolkit/package.json | 4 ++-- 4 files changed, 6 insertions(+), 6 deletions(-) diff --git a/packages/amazonq/package.json b/packages/amazonq/package.json index b9f09c19688..3dc7cf4cff5 100644 --- a/packages/amazonq/package.json +++ b/packages/amazonq/package.json @@ -596,8 +596,8 @@ "category": "%AWS.amazonq.title%" }, { - "command": "aws.amazonq.viewActiveProcesses", - "title": "%AWS.command.viewActiveProcesses%", + "command": "aws.amazonq.logActiveProcceses", + "title": "%AWS.command.logActiveProcceses%", "category": "%AWS.title%" }, { diff --git a/packages/core/package.nls.json b/packages/core/package.nls.json index 63c703949b7..ffd1c9b8d00 100644 --- a/packages/core/package.nls.json +++ b/packages/core/package.nls.json @@ -176,7 +176,7 @@ "AWS.command.submitFeedback": "Send Feedback...", "AWS.command.downloadSchemaItemCode": "Download Code Bindings", "AWS.command.viewLogs": "View Logs", - "AWS.command.viewActiveProcesses": "View Active Subprocesses", + "AWS.command.logActiveProcceses": "Log All Active Subprocesses", "AWS.command.cloudWatchLogs.searchLogGroup": "Search Log Group", "AWS.command.cloudWatchLogs.tailLogGroup": "Tail Log Group", "AWS.command.sam.newTemplate": "Create new SAM Template", diff --git a/packages/core/src/extension.ts b/packages/core/src/extension.ts index ca2fad9be32..49398797495 100644 --- a/packages/core/src/extension.ts +++ b/packages/core/src/extension.ts @@ -174,7 +174,7 @@ export async function activateCommon( context.subscriptions.push( Commands.register( - `aws.${contextPrefix}.viewActiveProcesses`, + `aws.${contextPrefix}.logActiveProcceses`, async () => await ChildProcessTracker.instance.logAllUsage() ) ) diff --git a/packages/toolkit/package.json b/packages/toolkit/package.json index ded124972f2..1bfeb3b6ce6 100644 --- a/packages/toolkit/package.json +++ b/packages/toolkit/package.json @@ -3147,8 +3147,8 @@ "category": "%AWS.title%" }, { - "command": "aws.toolkit.viewActiveProcesses", - "title": "%AWS.command.viewActiveProcesses%", + "command": "aws.toolkit.logActiveProcceses", + "title": "%AWS.command.logActiveProcceses%", "category": "%AWS.title%" }, { From b3d1fd4b8c4477d930d63234790adbe6edac6ae4 Mon Sep 17 00:00:00 2001 From: hkobew Date: Tue, 7 Jan 2025 12:55:12 -0500 Subject: [PATCH 31/48] add testing --- .../core/src/shared/utilities/processUtils.ts | 2 +- .../shared/utilities/processUtils.test.ts | 36 +++++++++++++++++++ 2 files changed, 37 insertions(+), 1 deletion(-) diff --git a/packages/core/src/shared/utilities/processUtils.ts b/packages/core/src/shared/utilities/processUtils.ts index d9db0180241..90e8c8d5cb4 100644 --- a/packages/core/src/shared/utilities/processUtils.ts +++ b/packages/core/src/shared/utilities/processUtils.ts @@ -162,7 +162,7 @@ export class ChildProcessTracker { public async logAllUsage(): Promise { if (this.size === 0) { - this.logger.info('No active subprocesses') + this.logger.info('No Active Subprocesses') return } const usage = await this.getAllUsage() diff --git a/packages/core/src/test/shared/utilities/processUtils.test.ts b/packages/core/src/test/shared/utilities/processUtils.test.ts index d68b697ca33..7198e13a1e2 100644 --- a/packages/core/src/test/shared/utilities/processUtils.test.ts +++ b/packages/core/src/test/shared/utilities/processUtils.test.ts @@ -400,6 +400,7 @@ describe('ChildProcessTracker', function () { after(function () { clock.uninstall() + usageMock.restore() }) it(`removes stopped processes every ${ChildProcessTracker.pollingInterval / 1000} seconds`, async function () { @@ -500,3 +501,38 @@ describe('ChildProcessTracker', function () { await stopAndWait(runningProcess) }) }) + +describe('ChildProcessTracker.logAllUsage', function () { + let tracker: ChildProcessTracker + + before(function () { + tracker = ChildProcessTracker.instance + }) + + afterEach(function () { + tracker.clear() + }) + + it('logAllUsage includes only active processes', async function () { + const runningProcess1 = startSleepProcess() + const runningProcess2 = startSleepProcess() + + tracker.add(runningProcess1.childProcess) + tracker.add(runningProcess2.childProcess) + + assert.ok(tracker.has(runningProcess1.childProcess), 'Missing first process') + assert.ok(tracker.has(runningProcess2.childProcess), 'Missing seconds process') + + await stopAndWait(runningProcess1) + + await tracker.logAllUsage() + + assert.throws(() => assertLogsContain(runningProcess1.childProcess.pid().toString(), false, 'info')) + assertLogsContain(runningProcess2.childProcess.pid().toString(), false, 'info') + }) + + it('logAllUsage defaults to empty message when empty', async function () { + await tracker.logAllUsage() + assertLogsContain('No Active Subprocesses', false, 'info') + }) +}) From be8fffbf51d0b3526f14959af57394b5b9f08d9c Mon Sep 17 00:00:00 2001 From: hkobew Date: Tue, 7 Jan 2025 13:49:07 -0500 Subject: [PATCH 32/48] refactor tests to avoid mocking when not necessary --- .../shared/utilities/processUtils.test.ts | 194 +++++++++--------- 1 file changed, 98 insertions(+), 96 deletions(-) diff --git a/packages/core/src/test/shared/utilities/processUtils.test.ts b/packages/core/src/test/shared/utilities/processUtils.test.ts index 7198e13a1e2..d27b378d5e5 100644 --- a/packages/core/src/test/shared/utilities/processUtils.test.ts +++ b/packages/core/src/test/shared/utilities/processUtils.test.ts @@ -384,133 +384,135 @@ function startSleepProcess(timeout: number = 90): RunningProcess { describe('ChildProcessTracker', function () { let tracker: ChildProcessTracker - let clock: FakeTimers.InstalledClock - let usageMock: sinon.SinonStub before(function () { - clock = installFakeClock() tracker = ChildProcessTracker.instance - usageMock = sinon.stub(ChildProcessTracker.prototype, 'getUsage') }) afterEach(function () { tracker.clear() - usageMock.reset() }) - after(function () { - clock.uninstall() - usageMock.restore() - }) - - 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') - }) + describe('tracking functionality', function () { + let clock: FakeTimers.InstalledClock + let usageMock: sinon.SinonStub - 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) + before(function () { + clock = installFakeClock() + tracker = ChildProcessTracker.instance + usageMock = sinon.stub(ChildProcessTracker.prototype, 'getUsage') + }) - assert.strictEqual(tracker.has(runningProcess1.childProcess), true, 'Missing first process') - assert.strictEqual(tracker.has(runningProcess2.childProcess), true, 'Missing second process') + afterEach(function () { + usageMock.reset() + }) - 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') - }) + after(function () { + clock.uninstall() + usageMock.restore() + }) - it('logs a warning message when system usage exceeds threshold', async function () { - const runningProcess = startSleepProcess() - tracker.add(runningProcess.childProcess) + 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' + ) + }) - const highCpu: ProcessStats = { - cpu: ChildProcessTracker.thresholds.cpu + 1, - memory: 0, - } - const highMemory: ProcessStats = { - cpu: 0, - memory: ChildProcessTracker.thresholds.memory + 1, - } + 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') + }) - usageMock.resolves(highCpu) + it('logs a warning message when system usage exceeds threshold', async function () { + const runningProcess = startSleepProcess() + tracker.add(runningProcess.childProcess) - await clock.tickAsync(ChildProcessTracker.pollingInterval) - assertLogsContain('exceeded cpu threshold', false, 'warn') + const highCpu: ProcessStats = { + cpu: ChildProcessTracker.thresholds.cpu + 1, + memory: 0, + } + const highMemory: ProcessStats = { + cpu: 0, + memory: ChildProcessTracker.thresholds.memory + 1, + } - usageMock.resolves(highMemory) - await clock.tickAsync(ChildProcessTracker.pollingInterval) - assertLogsContain('exceeded memory threshold', false, 'warn') + usageMock.resolves(highCpu) - await stopAndWait(runningProcess) - }) + await clock.tickAsync(ChildProcessTracker.pollingInterval) + assertLogsContain('exceeded cpu threshold', false, 'warn') - it('includes pid in logs', async function () { - const runningProcess = startSleepProcess() - tracker.add(runningProcess.childProcess) + usageMock.resolves(highMemory) + await clock.tickAsync(ChildProcessTracker.pollingInterval) + assertLogsContain('exceeded memory threshold', false, 'warn') - usageMock.resolves({ - cpu: ChildProcessTracker.thresholds.cpu + 1, - memory: 0, + await stopAndWait(runningProcess) }) - await clock.tickAsync(ChildProcessTracker.pollingInterval) - assertLogsContain(runningProcess.childProcess.pid().toString(), false, 'warn') + it('includes pid in logs', async function () { + const runningProcess = startSleepProcess() + tracker.add(runningProcess.childProcess) - await stopAndWait(runningProcess) - }) + usageMock.resolves({ + cpu: ChildProcessTracker.thresholds.cpu + 1, + memory: 0, + }) - it('does not log for processes within threshold', async function () { - const runningProcess = startSleepProcess() + await clock.tickAsync(ChildProcessTracker.pollingInterval) + assertLogsContain(runningProcess.childProcess.pid().toString(), false, 'warn') - usageMock.resolves({ - cpu: ChildProcessTracker.thresholds.cpu - 1, - memory: ChildProcessTracker.thresholds.memory - 1, + await stopAndWait(runningProcess) }) - await clock.tickAsync(ChildProcessTracker.pollingInterval) - - assert.throws(() => assertLogsContain(runningProcess.childProcess.pid().toString(), false, 'warn')) + it('does not log for processes within threshold', async function () { + const runningProcess = startSleepProcess() - await stopAndWait(runningProcess) - }) -}) + usageMock.resolves({ + cpu: ChildProcessTracker.thresholds.cpu - 1, + memory: ChildProcessTracker.thresholds.memory - 1, + }) -describe('ChildProcessTracker.logAllUsage', function () { - let tracker: ChildProcessTracker + await clock.tickAsync(ChildProcessTracker.pollingInterval) - before(function () { - tracker = ChildProcessTracker.instance - }) + assert.throws(() => assertLogsContain(runningProcess.childProcess.pid().toString(), false, 'warn')) - afterEach(function () { - tracker.clear() + await stopAndWait(runningProcess) + }) }) it('logAllUsage includes only active processes', async function () { From 6572e6b64d77fabc3107f8a3f7b1562b3deaa744 Mon Sep 17 00:00:00 2001 From: hkobew Date: Tue, 7 Jan 2025 14:03:47 -0500 Subject: [PATCH 33/48] add changelog --- .../Feature-db34038d-d2bf-4b6e-b4dc-ac84c0156ab5.json | 4 ++++ .../Feature-82e8146f-5dec-4af6-8f55-482471fdb4ad.json | 4 ++++ 2 files changed, 8 insertions(+) create mode 100644 packages/amazonq/.changes/next-release/Feature-db34038d-d2bf-4b6e-b4dc-ac84c0156ab5.json create mode 100644 packages/toolkit/.changes/next-release/Feature-82e8146f-5dec-4af6-8f55-482471fdb4ad.json diff --git a/packages/amazonq/.changes/next-release/Feature-db34038d-d2bf-4b6e-b4dc-ac84c0156ab5.json b/packages/amazonq/.changes/next-release/Feature-db34038d-d2bf-4b6e-b4dc-ac84c0156ab5.json new file mode 100644 index 00000000000..75a5b1179e0 --- /dev/null +++ b/packages/amazonq/.changes/next-release/Feature-db34038d-d2bf-4b6e-b4dc-ac84c0156ab5.json @@ -0,0 +1,4 @@ +{ + "type": "Feature", + "description": "Subprocesses are now tracked and visible by \"Log All Active Subprocesses\" in command palette" +} diff --git a/packages/toolkit/.changes/next-release/Feature-82e8146f-5dec-4af6-8f55-482471fdb4ad.json b/packages/toolkit/.changes/next-release/Feature-82e8146f-5dec-4af6-8f55-482471fdb4ad.json new file mode 100644 index 00000000000..75a5b1179e0 --- /dev/null +++ b/packages/toolkit/.changes/next-release/Feature-82e8146f-5dec-4af6-8f55-482471fdb4ad.json @@ -0,0 +1,4 @@ +{ + "type": "Feature", + "description": "Subprocesses are now tracked and visible by \"Log All Active Subprocesses\" in command palette" +} From 31fd2b942b7aec61172507bf3fd40c7a15e79efb Mon Sep 17 00:00:00 2001 From: hkobew Date: Tue, 7 Jan 2025 14:32:51 -0500 Subject: [PATCH 34/48] add tests for telemetry --- .../src/shared/telemetry/vscodeTelemetry.json | 15 +++++++++++++ .../core/src/shared/utilities/processUtils.ts | 22 +++++++++++-------- .../shared/utilities/processUtils.test.ts | 18 ++++++++++++++- 3 files changed, 45 insertions(+), 10 deletions(-) diff --git a/packages/core/src/shared/telemetry/vscodeTelemetry.json b/packages/core/src/shared/telemetry/vscodeTelemetry.json index 5e32b249d4f..5fb07e912fc 100644 --- a/packages/core/src/shared/telemetry/vscodeTelemetry.json +++ b/packages/core/src/shared/telemetry/vscodeTelemetry.json @@ -1,5 +1,10 @@ { "types": [ + { + "name": "size", + "type": "int", + "description": "A generic size for when units are clear" + }, { "name": "amazonGenerateApproachLatency", "type": "double", @@ -372,6 +377,16 @@ } ] }, + { + "name": "ide_logActiveProcesses", + "description": "Emitted when user invokes logActiveProcesses command", + "metadata": [ + { + "type": "size", + "required": true + } + ] + }, { "name": "vscode_executeCommand", "description": "Emitted whenever a registered Toolkit command is executed", diff --git a/packages/core/src/shared/utilities/processUtils.ts b/packages/core/src/shared/utilities/processUtils.ts index 90e8c8d5cb4..e87fc648b48 100644 --- a/packages/core/src/shared/utilities/processUtils.ts +++ b/packages/core/src/shared/utilities/processUtils.ts @@ -8,6 +8,7 @@ import * as logger from '../logger' import { Timeout, CancellationError, waitUntil } from './timeoutUtils' import { PollingSet } from './pollingSet' import { getLogger } from '../logger/logger' +import { telemetry } from '../telemetry' export interface RunParameterContext { /** Reports an error parsed from the stdin/stdout streams. */ @@ -161,15 +162,18 @@ export class ChildProcessTracker { } public async logAllUsage(): Promise { - if (this.size === 0) { - this.logger.info('No Active Subprocesses') - return - } - const usage = await this.getAllUsage() - const logMsg = Array.from(usage.entries()).reduce((acc, [pid, stats]) => { - return acc + `Process ${pid}: ${stats.cpu}% cpu, ${stats.memory} MB of memory\n` - }, '') - this.logger.info(`Active Subprocesses (${this.size} active)\n${logMsg}`) + telemetry.ide_logActiveProcesses.run(async (span) => { + span.record({ size: this.size }) + if (this.size === 0) { + this.logger.info('No Active Subprocesses') + return + } + const usage = await this.getAllUsage() + const logMsg = Array.from(usage.entries()).reduce((acc, [pid, stats]) => { + return acc + `Process ${pid}: ${stats.cpu}% cpu, ${stats.memory} MB of memory\n` + }, '') + this.logger.info(`Active Subprocesses (${this.size} active)\n${logMsg}`) + }) } public async getUsage(pid: pid): Promise { diff --git a/packages/core/src/test/shared/utilities/processUtils.test.ts b/packages/core/src/test/shared/utilities/processUtils.test.ts index d27b378d5e5..87c6f8a5587 100644 --- a/packages/core/src/test/shared/utilities/processUtils.test.ts +++ b/packages/core/src/test/shared/utilities/processUtils.test.ts @@ -19,7 +19,7 @@ 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 { assertTelemetry, installFakeClock } from '../../testUtil' import { isWin } from '../../../shared/vscode/env' import { assertLogsContain } from '../../globalSetup.test' @@ -537,4 +537,20 @@ describe('ChildProcessTracker', function () { await tracker.logAllUsage() assertLogsContain('No Active Subprocesses', false, 'info') }) + + it('logAllUsage emits telemetry with size equal to number of processes (empty)', async function () { + await tracker.logAllUsage() + assertTelemetry('ide_logActiveProcesses', { size: 0 }) + }) + + it('logsAllUsage emits telemetry to number of processes (nonempty)', async function () { + const size = 10 + for (const _ of Array.from({ length: size })) { + const runningProcess = startSleepProcess() + tracker.add(runningProcess.childProcess) + } + + await tracker.logAllUsage() + assertTelemetry('ide_logActiveProcesses', { size: size }) + }) }) From c0bc44e537fd46e79c8c3d5d44883ef87cf36739 Mon Sep 17 00:00:00 2001 From: hkobew Date: Wed, 8 Jan 2025 11:20:02 -0500 Subject: [PATCH 35/48] implement telemetry for exceeding thresholds --- .../src/shared/telemetry/vscodeTelemetry.json | 16 ++++++++++++ .../core/src/shared/utilities/processUtils.ts | 26 ++++++++++++++----- .../shared/utilities/processUtils.test.ts | 9 ++++--- 3 files changed, 41 insertions(+), 10 deletions(-) diff --git a/packages/core/src/shared/telemetry/vscodeTelemetry.json b/packages/core/src/shared/telemetry/vscodeTelemetry.json index 5e32b249d4f..c5990d0a2ee 100644 --- a/packages/core/src/shared/telemetry/vscodeTelemetry.json +++ b/packages/core/src/shared/telemetry/vscodeTelemetry.json @@ -1,5 +1,11 @@ { "types": [ + { + "name": "systemResource", + "type": "string", + "allowedValues": ["cpu", "memory"], + "description": "The type of system resource being measured" + }, { "name": "amazonGenerateApproachLatency", "type": "double", @@ -372,6 +378,16 @@ } ] }, + { + "name": "ide_childProcessWarning", + "description": "Child Process warning due to high system usage", + "metadata": [ + { + "type": "systemResource", + "required": true + } + ] + }, { "name": "vscode_executeCommand", "description": "Emitted whenever a registered Toolkit command is executed", diff --git a/packages/core/src/shared/utilities/processUtils.ts b/packages/core/src/shared/utilities/processUtils.ts index de6d5875c79..2d5714bbe33 100644 --- a/packages/core/src/shared/utilities/processUtils.ts +++ b/packages/core/src/shared/utilities/processUtils.ts @@ -9,6 +9,7 @@ import * as logger from '../logger' import { Timeout, CancellationError, waitUntil } from './timeoutUtils' import { PollingSet } from './pollingSet' import { getLogger } from '../logger/logger' +import { telemetry } from '../telemetry' export interface RunParameterContext { /** Reports an error parsed from the stdin/stdout streams. */ @@ -100,18 +101,29 @@ export class ChildProcessTracker { } private async checkProcessUsage(pid: number): Promise { + const doesExceedThreshold = (resource: keyof ProcessStats, value: number) => { + const threshold = ChildProcessTracker.thresholds[resource] + return value > threshold + } + const warn = (resource: keyof ProcessStats, value: number) => { + telemetry.ide_childProcessWarning.run((span) => { + ChildProcessTracker.logger.warn(`Process ${pid} exceeded ${resource} threshold: ${value}`) + span.record({ systemResource: resource }) + }) + } + if (!this.#pids.has(pid)) { ChildProcessTracker.logger.warn(`Missing process with id ${pid}`) return } const stats = await 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}`) + if (!stats) { + ChildProcessTracker.logger.warn(`Failed to get process stats for ${pid}`) + return + } + for (const resource of Object.keys(ChildProcessTracker.thresholds) as (keyof ProcessStats)[]) { + if (doesExceedThreshold(resource, stats[resource])) { + warn(resource as keyof ProcessStats, stats[resource]) } } } diff --git a/packages/core/src/test/shared/utilities/processUtils.test.ts b/packages/core/src/test/shared/utilities/processUtils.test.ts index 3a12ae01df5..de513914775 100644 --- a/packages/core/src/test/shared/utilities/processUtils.test.ts +++ b/packages/core/src/test/shared/utilities/processUtils.test.ts @@ -19,7 +19,7 @@ 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 { assertTelemetry, installFakeClock } from '../../testUtil' import { isWin } from '../../../shared/vscode/env' import { assertLogsContain } from '../../globalSetup.test' @@ -445,7 +445,7 @@ describe('ChildProcessTracker', function () { assert.strictEqual(tracker.size, 0, 'expected tracker to be empty') }) - it('logs a warning message when system usage exceeds threshold', async function () { + it('logs a warning message and emits metric when system usage exceeds threshold', async function () { const runningProcess = startSleepProcess() tracker.add(runningProcess.childProcess) @@ -462,10 +462,12 @@ describe('ChildProcessTracker', function () { await clock.tickAsync(ChildProcessTracker.pollingInterval) assertLogsContain('exceeded cpu threshold', false, 'warn') + assertTelemetry('ide_childProcessWarning', { systemResource: 'cpu' }) usageMock.resolves(highMemory) await clock.tickAsync(ChildProcessTracker.pollingInterval) assertLogsContain('exceeded memory threshold', false, 'warn') + assertTelemetry('ide_childProcessWarning', { systemResource: 'memory' }) await stopAndWait(runningProcess) }) @@ -485,7 +487,7 @@ describe('ChildProcessTracker', function () { await stopAndWait(runningProcess) }) - it('does not log for processes within threshold', async function () { + it('does not log or emit telemetry for processes within threshold', async function () { const runningProcess = startSleepProcess() usageMock.resolves({ @@ -496,6 +498,7 @@ describe('ChildProcessTracker', function () { await clock.tickAsync(ChildProcessTracker.pollingInterval) assert.throws(() => assertLogsContain(runningProcess.childProcess.pid().toString(), false, 'warn')) + assert.throws(() => assertTelemetry('ide_childProcessWarning', {})) await stopAndWait(runningProcess) }) From 1286ee2980ec64e81892280c3d69bb6d727f7bd3 Mon Sep 17 00:00:00 2001 From: hkobew Date: Wed, 8 Jan 2025 13:22:08 -0500 Subject: [PATCH 36/48] add process as str to telemetry --- .../src/shared/telemetry/vscodeTelemetry.json | 9 +++++++++ .../core/src/shared/utilities/processUtils.ts | 17 +++++++++++++---- .../shared/utilities/processUtils.test.ts | 19 +++++++++++++++---- 3 files changed, 37 insertions(+), 8 deletions(-) diff --git a/packages/core/src/shared/telemetry/vscodeTelemetry.json b/packages/core/src/shared/telemetry/vscodeTelemetry.json index 5dd9b3ed0f7..d5086315b62 100644 --- a/packages/core/src/shared/telemetry/vscodeTelemetry.json +++ b/packages/core/src/shared/telemetry/vscodeTelemetry.json @@ -5,6 +5,11 @@ "type": "int", "description": "A generic size for when units are clear" }, + { + "name": "childProcess", + "type": "string", + "description": "A string representation of a ChildProcess" + }, { "name": "systemResource", "type": "string", @@ -400,6 +405,10 @@ { "type": "systemResource", "required": true + }, + { + "type": "childProcess", + "required": true } ] }, diff --git a/packages/core/src/shared/utilities/processUtils.ts b/packages/core/src/shared/utilities/processUtils.ts index a52c8880fcf..b8ccd8b4c4a 100644 --- a/packages/core/src/shared/utilities/processUtils.ts +++ b/packages/core/src/shared/utilities/processUtils.ts @@ -113,18 +113,18 @@ export class ChildProcessTracker { } const warn = (resource: keyof ProcessStats, value: number) => { telemetry.ide_childProcessWarning.run((span) => { - this.logger.warn(`Process ${pid} exceeded ${resource} threshold: ${value}`) - span.record({ systemResource: resource }) + this.logger.warn(`Process ${this.getProcessAsStr(pid)} exceeded ${resource} threshold: ${value}`) + span.record({ systemResource: resource, childProcess: this.getProcessAsStr(pid) }) }) } if (!this.#pids.has(pid)) { - this.logger.warn(`Missing process with id ${pid}`) + this.logger.warn(`Missing process with pid ${pid}`) return } const stats = await this.getUsage(pid) if (!stats) { - this.logger.warn(`Failed to get process stats for ${pid}`) + this.logger.warn(`Failed to get process stats for process with pid ${pid}`) return } for (const resource of Object.keys(ChildProcessTracker.thresholds) as (keyof ProcessStats)[]) { @@ -134,6 +134,15 @@ export class ChildProcessTracker { } } + public getProcessAsStr(pid: pid): string { + try { + return this.#processByPid.get(pid)!.toString() + } catch (e) { + this.logger.warn(`Missing process with pid ${pid}`) + return `pid: ${pid}` + } + } + public add(childProcess: ChildProcess) { const pid = childProcess.pid() this.#processByPid.set(pid, childProcess) diff --git a/packages/core/src/test/shared/utilities/processUtils.test.ts b/packages/core/src/test/shared/utilities/processUtils.test.ts index 60ed9facfde..07dc28f661a 100644 --- a/packages/core/src/test/shared/utilities/processUtils.test.ts +++ b/packages/core/src/test/shared/utilities/processUtils.test.ts @@ -472,7 +472,10 @@ describe('ChildProcessTracker', function () { await clock.tickAsync(ChildProcessTracker.pollingInterval) assertLogsContain('exceeded cpu threshold', false, 'warn') - assertTelemetry('ide_childProcessWarning', { systemResource: 'cpu' }) + assertTelemetry('ide_childProcessWarning', { + systemResource: 'cpu', + childProcess: runningProcess.childProcess.toString(), + }) await stopAndWait(runningProcess) }) @@ -488,7 +491,10 @@ describe('ChildProcessTracker', function () { usageMock.resolves(highMemory) await clock.tickAsync(ChildProcessTracker.pollingInterval) assertLogsContain('exceeded memory threshold', false, 'warn') - assertTelemetry('ide_childProcessWarning', { systemResource: 'memory' }) + assertTelemetry('ide_childProcessWarning', { + systemResource: 'memory', + childProcess: runningProcess.childProcess.toString(), + }) await stopAndWait(runningProcess) }) @@ -525,7 +531,6 @@ describe('ChildProcessTracker', function () { }) it('logAllUsage includes only active processes', async function () { - console.log('start') const runningProcess1 = startSleepProcess() const runningProcess2 = startSleepProcess() @@ -541,7 +546,6 @@ describe('ChildProcessTracker', function () { console.log('logAllUsage called') assert.throws(() => assertLogsContain(runningProcess1.childProcess.pid().toString(), false, 'info')) assertLogsContain(runningProcess2.childProcess.pid().toString(), false, 'info') - console.log('end') }) it('logAllUsage defaults to empty message when empty', async function () { @@ -564,4 +568,11 @@ describe('ChildProcessTracker', function () { await tracker.logAllUsage() assertTelemetry('ide_logActiveProcesses', { size: size }) }) + + it('getProcessAsStr logs warning when its missing', async function () { + const runningProcess1 = startSleepProcess() + tracker.clear() + tracker.getProcessAsStr(runningProcess1.childProcess.pid()) + assertLogsContain(runningProcess1.childProcess.pid().toString(), false, 'warn') + }) }) From e25df1be397f9eaae4a219986311d07109eb3656 Mon Sep 17 00:00:00 2001 From: hkobew Date: Wed, 8 Jan 2025 13:25:25 -0500 Subject: [PATCH 37/48] remove explicit adding now that tracker is singleton --- .../src/test/shared/utilities/processUtils.test.ts | 13 +------------ 1 file changed, 1 insertion(+), 12 deletions(-) diff --git a/packages/core/src/test/shared/utilities/processUtils.test.ts b/packages/core/src/test/shared/utilities/processUtils.test.ts index 07dc28f661a..d673dbc72e1 100644 --- a/packages/core/src/test/shared/utilities/processUtils.test.ts +++ b/packages/core/src/test/shared/utilities/processUtils.test.ts @@ -399,7 +399,6 @@ describe('ChildProcessTracker', function () { before(function () { clock = installFakeClock() - tracker = ChildProcessTracker.instance usageMock = sinon.stub(ChildProcessTracker.prototype, 'getUsage') }) @@ -415,7 +414,6 @@ describe('ChildProcessTracker', function () { 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) @@ -433,8 +431,6 @@ describe('ChildProcessTracker', function () { 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') @@ -461,7 +457,6 @@ describe('ChildProcessTracker', function () { it('logs a warning message and emits metric when cpu exceeds threshold', async function () { const runningProcess = startSleepProcess() - tracker.add(runningProcess.childProcess) const highCpu: ProcessStats = { cpu: ChildProcessTracker.thresholds.cpu + 1, @@ -482,7 +477,6 @@ describe('ChildProcessTracker', function () { it('logs a warning message and emits metric when memory exceeds threshold', async function () { const runningProcess = startSleepProcess() - tracker.add(runningProcess.childProcess) const highMemory: ProcessStats = { cpu: 0, memory: ChildProcessTracker.thresholds.memory + 1, @@ -501,7 +495,6 @@ describe('ChildProcessTracker', function () { it('includes pid in logs', async function () { const runningProcess = startSleepProcess() - tracker.add(runningProcess.childProcess) usageMock.resolves({ cpu: ChildProcessTracker.thresholds.cpu + 1, @@ -534,9 +527,6 @@ describe('ChildProcessTracker', function () { const runningProcess1 = startSleepProcess() const runningProcess2 = startSleepProcess() - tracker.add(runningProcess1.childProcess) - tracker.add(runningProcess2.childProcess) - assert.ok(tracker.has(runningProcess1.childProcess), 'Missing first process') assert.ok(tracker.has(runningProcess2.childProcess), 'Missing seconds process') @@ -561,8 +551,7 @@ describe('ChildProcessTracker', function () { it('logsAllUsage emits telemetry to number of processes (nonempty)', async function () { const size = 10 for (const _ of Array.from({ length: size })) { - const runningProcess = startSleepProcess() - tracker.add(runningProcess.childProcess) + startSleepProcess() } await tracker.logAllUsage() From 5090323e4f87789c5b22c9b44dda18fd3eea1534 Mon Sep 17 00:00:00 2001 From: hkobew Date: Wed, 8 Jan 2025 13:31:20 -0500 Subject: [PATCH 38/48] add a safety clear before tests run --- packages/core/src/test/shared/utilities/processUtils.test.ts | 1 + 1 file changed, 1 insertion(+) diff --git a/packages/core/src/test/shared/utilities/processUtils.test.ts b/packages/core/src/test/shared/utilities/processUtils.test.ts index d673dbc72e1..37dd26e954b 100644 --- a/packages/core/src/test/shared/utilities/processUtils.test.ts +++ b/packages/core/src/test/shared/utilities/processUtils.test.ts @@ -387,6 +387,7 @@ describe('ChildProcessTracker', function () { before(function () { tracker = ChildProcessTracker.instance + tracker.clear() // Avoid bleed-through of other tests running child processes. }) afterEach(function () { From 7685707e2685e4834b878bfc8c7db583ce8844b0 Mon Sep 17 00:00:00 2001 From: hkobew Date: Wed, 8 Jan 2025 13:59:57 -0500 Subject: [PATCH 39/48] regroup tests --- .../shared/utilities/processUtils.test.ts | 53 ++++++++++--------- 1 file changed, 27 insertions(+), 26 deletions(-) diff --git a/packages/core/src/test/shared/utilities/processUtils.test.ts b/packages/core/src/test/shared/utilities/processUtils.test.ts index 37dd26e954b..5c2b24b347b 100644 --- a/packages/core/src/test/shared/utilities/processUtils.test.ts +++ b/packages/core/src/test/shared/utilities/processUtils.test.ts @@ -524,39 +524,40 @@ describe('ChildProcessTracker', function () { }) }) - it('logAllUsage includes only active processes', async function () { - const runningProcess1 = startSleepProcess() - const runningProcess2 = startSleepProcess() + describe('logAllUsage', function () { + it('includes only active processes', async function () { + const runningProcess1 = startSleepProcess() + const runningProcess2 = startSleepProcess() - assert.ok(tracker.has(runningProcess1.childProcess), 'Missing first process') - assert.ok(tracker.has(runningProcess2.childProcess), 'Missing seconds process') + assert.ok(tracker.has(runningProcess1.childProcess), 'Missing first process') + assert.ok(tracker.has(runningProcess2.childProcess), 'Missing seconds process') - await stopAndWait(runningProcess1) + await stopAndWait(runningProcess1) - await tracker.logAllUsage() - console.log('logAllUsage called') - assert.throws(() => assertLogsContain(runningProcess1.childProcess.pid().toString(), false, 'info')) - assertLogsContain(runningProcess2.childProcess.pid().toString(), false, 'info') - }) + await tracker.logAllUsage() + assert.throws(() => assertLogsContain(runningProcess1.childProcess.pid().toString(), false, 'info')) + assertLogsContain(runningProcess2.childProcess.pid().toString(), false, 'info') + }) - it('logAllUsage defaults to empty message when empty', async function () { - await tracker.logAllUsage() - assertLogsContain('No Active Subprocesses', false, 'info') - }) + it('defaults to empty message when empty', async function () { + await tracker.logAllUsage() + assertLogsContain('No Active Subprocesses', false, 'info') + }) - it('logAllUsage emits telemetry with size equal to number of processes (empty)', async function () { - await tracker.logAllUsage() - assertTelemetry('ide_logActiveProcesses', { size: 0 }) - }) + it('emits telemetry with size equal to number of processes (empty)', async function () { + await tracker.logAllUsage() + assertTelemetry('ide_logActiveProcesses', { size: 0 }) + }) - it('logsAllUsage emits telemetry to number of processes (nonempty)', async function () { - const size = 10 - for (const _ of Array.from({ length: size })) { - startSleepProcess() - } + it('emits telemetry to number of processes (nonempty)', async function () { + const size = 10 + for (const _ of Array.from({ length: size })) { + startSleepProcess() + } - await tracker.logAllUsage() - assertTelemetry('ide_logActiveProcesses', { size: size }) + await tracker.logAllUsage() + assertTelemetry('ide_logActiveProcesses', { size: size }) + }) }) it('getProcessAsStr logs warning when its missing', async function () { From 7a702fffe3ecfd4bda3f8765ec56ade67ece80d4 Mon Sep 17 00:00:00 2001 From: hkobew Date: Wed, 15 Jan 2025 09:51:40 -0500 Subject: [PATCH 40/48] refactor sub-functions --- .../core/src/shared/utilities/processUtils.ts | 24 ++++++++++--------- .../shared/utilities/processUtils.test.ts | 8 +++---- 2 files changed, 17 insertions(+), 15 deletions(-) diff --git a/packages/core/src/shared/utilities/processUtils.ts b/packages/core/src/shared/utilities/processUtils.ts index de6d5875c79..3fcd7864438 100644 --- a/packages/core/src/shared/utilities/processUtils.ts +++ b/packages/core/src/shared/utilities/processUtils.ts @@ -104,7 +104,7 @@ export class ChildProcessTracker { ChildProcessTracker.logger.warn(`Missing process with id ${pid}`) return } - const stats = await this.getUsage(pid) + const stats = this.getUsage(pid) if (stats) { ChildProcessTracker.logger.debug(`Process ${pid} usage: %O`, stats) if (stats.memory > ChildProcessTracker.thresholds.memory) { @@ -143,8 +143,16 @@ export class ChildProcessTracker { this.#processByPid.clear() } - public async getUsage(pid: number): Promise { - const getWindowsUsage = () => { + 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', @@ -167,7 +175,8 @@ export class ChildProcessTracker { memory: memoryBytes, } } - const getUnixUsage = () => { + + 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() @@ -180,13 +189,6 @@ export class ChildProcessTracker { memory: memoryBytes, } } - 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 } - } } } diff --git a/packages/core/src/test/shared/utilities/processUtils.test.ts b/packages/core/src/test/shared/utilities/processUtils.test.ts index 3a12ae01df5..0e6f474ed10 100644 --- a/packages/core/src/test/shared/utilities/processUtils.test.ts +++ b/packages/core/src/test/shared/utilities/processUtils.test.ts @@ -458,12 +458,12 @@ describe('ChildProcessTracker', function () { memory: ChildProcessTracker.thresholds.memory + 1, } - usageMock.resolves(highCpu) + usageMock.returns(highCpu) await clock.tickAsync(ChildProcessTracker.pollingInterval) assertLogsContain('exceeded cpu threshold', false, 'warn') - usageMock.resolves(highMemory) + usageMock.returns(highMemory) await clock.tickAsync(ChildProcessTracker.pollingInterval) assertLogsContain('exceeded memory threshold', false, 'warn') @@ -474,7 +474,7 @@ describe('ChildProcessTracker', function () { const runningProcess = startSleepProcess() tracker.add(runningProcess.childProcess) - usageMock.resolves({ + usageMock.returns({ cpu: ChildProcessTracker.thresholds.cpu + 1, memory: 0, }) @@ -488,7 +488,7 @@ describe('ChildProcessTracker', function () { it('does not log for processes within threshold', async function () { const runningProcess = startSleepProcess() - usageMock.resolves({ + usageMock.returns({ cpu: ChildProcessTracker.thresholds.cpu - 1, memory: ChildProcessTracker.thresholds.memory - 1, }) From 7622e5c040d7e488835cc82d7969222ca30897aa Mon Sep 17 00:00:00 2001 From: hkobew Date: Fri, 17 Jan 2025 12:51:00 -0500 Subject: [PATCH 41/48] add units to process stat keys --- .../core/src/shared/utilities/processUtils.ts | 42 ++++++++++--------- .../shared/utilities/processUtils.test.ts | 14 +++---- 2 files changed, 30 insertions(+), 26 deletions(-) diff --git a/packages/core/src/shared/utilities/processUtils.ts b/packages/core/src/shared/utilities/processUtils.ts index 4da327a2d2e..6be695b9941 100644 --- a/packages/core/src/shared/utilities/processUtils.ts +++ b/packages/core/src/shared/utilities/processUtils.ts @@ -8,7 +8,7 @@ import * as logger from '../logger' import { Timeout, CancellationError, waitUntil } from './timeoutUtils' import { PollingSet } from './pollingSet' import { getLogger } from '../logger/logger' -import { telemetry } from '../telemetry' +import { SystemResource, telemetry } from '../telemetry' export interface RunParameterContext { /** Reports an error parsed from the stdin/stdout streams. */ @@ -64,14 +64,18 @@ export interface ChildProcessResult { export const eof = Symbol('EOF') type pid = number export interface ProcessStats { - memory: number - cpu: number + memoryBytes: number + cpuPercent: number +} + +function toTelemetryResource(k: keyof ProcessStats): SystemResource { + return k === 'cpuPercent' ? 'cpu' : 'memory' } export class ChildProcessTracker { static readonly pollingInterval: number = 10000 // Check usage every 10 seconds static readonly thresholds: ProcessStats = { - memory: 100, // 100 MB - cpu: 50, + memoryBytes: 100 * 1024 * 1024, // 100 MB + cpuPercent: 50, } readonly logger: logger.Logger static #instance: ChildProcessTracker @@ -111,7 +115,7 @@ export class ChildProcessTracker { const threshold = ChildProcessTracker.thresholds[resource] return value > threshold } - const warn = (resource: keyof ProcessStats, value: number) => { + const warn = (resource: SystemResource, value: number) => { telemetry.ide_childProcessWarning.run((span) => { this.logger.warn(`Process ${this.getProcessAsStr(pid)} exceeded ${resource} threshold: ${value}`) span.record({ systemResource: resource, childProcess: this.getProcessAsStr(pid) }) @@ -127,9 +131,9 @@ export class ChildProcessTracker { this.logger.warn(`Failed to get process stats for process with pid ${pid}`) return } - for (const resource of Object.keys(ChildProcessTracker.thresholds) as (keyof ProcessStats)[]) { - if (doesExceedThreshold(resource, stats[resource])) { - warn(resource as keyof ProcessStats, stats[resource]) + for (const processStat of Object.keys(ChildProcessTracker.thresholds) as (keyof ProcessStats)[]) { + if (doesExceedThreshold(processStat, stats[processStat])) { + warn(toTelemetryResource(processStat), stats[processStat]) } } } @@ -190,7 +194,7 @@ export class ChildProcessTracker { } const usage = await this.getAllUsage() const logMsg = Array.from(usage.entries()).reduce((acc, [pid, stats]) => { - return acc + `Process ${pid}: ${stats.cpu}% cpu, ${stats.memory} MB of memory\n` + return acc + `Process ${pid}: ${stats.cpuPercent}% cpu, ${stats.memoryBytes} B of memory\n` }, '') this.logger.info(`Active Subprocesses (${this.size} active)\n${logMsg}`) }) @@ -202,10 +206,10 @@ export class ChildProcessTracker { return process.platform === 'win32' ? getWindowsUsage() : getUnixUsage() } catch (e) { this.logger.warn(`Failed to get process stats for ${pid}: ${e}`) - return { cpu: 0, memory: 0 } + return { cpuPercent: 0, memoryBytes: 0 } } - function getWindowsUsage() { + function getWindowsUsage(): ProcessStats { const cpuOutput = proc .execFileSync('wmic', [ 'path', @@ -224,12 +228,12 @@ export class ChildProcessTracker { const memoryBytes = parseInt(memOutput.split('\n')[1]) * 1024 return { - cpu: isNaN(cpuPercentage) ? 0 : cpuPercentage, - memory: memoryBytes / (1024 * 1024), + cpuPercent: isNaN(cpuPercentage) ? 0 : cpuPercentage, + memoryBytes, } } - function getUnixUsage() { + function getUnixUsage(): ProcessStats { const cpuMemOutput = proc.execFileSync('ps', ['-p', pid.toString(), '-o', '%cpu,%mem']).toString() const rssOutput = proc.execFileSync('ps', ['-p', pid.toString(), '-o', 'rss']).toString() @@ -238,16 +242,16 @@ export class ChildProcessTracker { const memoryBytes = parseInt(rssOutput.split('\n')[1]) * 1024 return { - cpu: isNaN(cpuPercentage) ? 0 : cpuPercentage, - memory: memoryBytes / (1024 * 1024), + cpuPercent: isNaN(cpuPercentage) ? 0 : cpuPercentage, + memoryBytes, } } } } export interface ProcessStats { - memory: number - cpu: number + memoryBytes: number + cpuPercent: number } export class ChildProcess { static #runningProcesses = ChildProcessTracker.instance diff --git a/packages/core/src/test/shared/utilities/processUtils.test.ts b/packages/core/src/test/shared/utilities/processUtils.test.ts index 5c2b24b347b..0f63488196e 100644 --- a/packages/core/src/test/shared/utilities/processUtils.test.ts +++ b/packages/core/src/test/shared/utilities/processUtils.test.ts @@ -460,8 +460,8 @@ describe('ChildProcessTracker', function () { const runningProcess = startSleepProcess() const highCpu: ProcessStats = { - cpu: ChildProcessTracker.thresholds.cpu + 1, - memory: 0, + cpuPercent: ChildProcessTracker.thresholds.cpuPercent + 1, + memoryBytes: 0, } usageMock.resolves(highCpu) @@ -479,8 +479,8 @@ describe('ChildProcessTracker', function () { it('logs a warning message and emits metric when memory exceeds threshold', async function () { const runningProcess = startSleepProcess() const highMemory: ProcessStats = { - cpu: 0, - memory: ChildProcessTracker.thresholds.memory + 1, + cpuPercent: 0, + memoryBytes: ChildProcessTracker.thresholds.memoryBytes + 1, } usageMock.resolves(highMemory) @@ -498,7 +498,7 @@ describe('ChildProcessTracker', function () { const runningProcess = startSleepProcess() usageMock.resolves({ - cpu: ChildProcessTracker.thresholds.cpu + 1, + cpu: ChildProcessTracker.thresholds.cpuPercent + 1, memory: 0, }) @@ -512,8 +512,8 @@ describe('ChildProcessTracker', function () { const runningProcess = startSleepProcess() usageMock.resolves({ - cpu: ChildProcessTracker.thresholds.cpu - 1, - memory: ChildProcessTracker.thresholds.memory - 1, + cpu: ChildProcessTracker.thresholds.cpuPercent - 1, + memory: ChildProcessTracker.thresholds.memoryBytes - 1, }) await clock.tickAsync(ChildProcessTracker.pollingInterval) From bf515e0bec0d13eeb4e4c6764cec03e678987615 Mon Sep 17 00:00:00 2001 From: hkobew Date: Fri, 17 Jan 2025 12:59:09 -0500 Subject: [PATCH 42/48] resolve circ dep --- packages/core/src/shared/utilities/processUtils.ts | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/packages/core/src/shared/utilities/processUtils.ts b/packages/core/src/shared/utilities/processUtils.ts index 6be695b9941..2bbd5d8b0ea 100644 --- a/packages/core/src/shared/utilities/processUtils.ts +++ b/packages/core/src/shared/utilities/processUtils.ts @@ -8,7 +8,7 @@ import * as logger from '../logger' import { Timeout, CancellationError, waitUntil } from './timeoutUtils' import { PollingSet } from './pollingSet' import { getLogger } from '../logger/logger' -import { SystemResource, telemetry } from '../telemetry' +import { SystemResource, telemetry } from '../telemetry/telemetry' export interface RunParameterContext { /** Reports an error parsed from the stdin/stdout streams. */ From 045f9f0e7f82b75261a07ea2671a7186b1a98cbf Mon Sep 17 00:00:00 2001 From: hkobew Date: Fri, 17 Jan 2025 13:17:40 -0500 Subject: [PATCH 43/48] fix failing tests --- packages/core/src/shared/utilities/processUtils.ts | 9 +++++---- .../src/test/shared/utilities/processUtils.test.ts | 12 ++++++------ 2 files changed, 11 insertions(+), 10 deletions(-) diff --git a/packages/core/src/shared/utilities/processUtils.ts b/packages/core/src/shared/utilities/processUtils.ts index 2bbd5d8b0ea..d9fb5c67041 100644 --- a/packages/core/src/shared/utilities/processUtils.ts +++ b/packages/core/src/shared/utilities/processUtils.ts @@ -111,10 +111,6 @@ export class ChildProcessTracker { } private async checkProcessUsage(pid: number): Promise { - const doesExceedThreshold = (resource: keyof ProcessStats, value: number) => { - const threshold = ChildProcessTracker.thresholds[resource] - return value > threshold - } const warn = (resource: SystemResource, value: number) => { telemetry.ide_childProcessWarning.run((span) => { this.logger.warn(`Process ${this.getProcessAsStr(pid)} exceeded ${resource} threshold: ${value}`) @@ -136,6 +132,11 @@ export class ChildProcessTracker { warn(toTelemetryResource(processStat), stats[processStat]) } } + + function doesExceedThreshold(resource: keyof ProcessStats, value: number) { + const threshold = ChildProcessTracker.thresholds[resource] + return value > threshold + } } public getProcessAsStr(pid: pid): string { diff --git a/packages/core/src/test/shared/utilities/processUtils.test.ts b/packages/core/src/test/shared/utilities/processUtils.test.ts index 0f63488196e..7d4919467bf 100644 --- a/packages/core/src/test/shared/utilities/processUtils.test.ts +++ b/packages/core/src/test/shared/utilities/processUtils.test.ts @@ -464,7 +464,7 @@ describe('ChildProcessTracker', function () { memoryBytes: 0, } - usageMock.resolves(highCpu) + usageMock.returns(highCpu) await clock.tickAsync(ChildProcessTracker.pollingInterval) assertLogsContain('exceeded cpu threshold', false, 'warn') @@ -483,7 +483,7 @@ describe('ChildProcessTracker', function () { memoryBytes: ChildProcessTracker.thresholds.memoryBytes + 1, } - usageMock.resolves(highMemory) + usageMock.returns(highMemory) await clock.tickAsync(ChildProcessTracker.pollingInterval) assertLogsContain('exceeded memory threshold', false, 'warn') assertTelemetry('ide_childProcessWarning', { @@ -497,9 +497,9 @@ describe('ChildProcessTracker', function () { it('includes pid in logs', async function () { const runningProcess = startSleepProcess() - usageMock.resolves({ - cpu: ChildProcessTracker.thresholds.cpuPercent + 1, - memory: 0, + usageMock.returns({ + cpuPercent: 0, + memoryBytes: ChildProcessTracker.thresholds.memoryBytes + 1, }) await clock.tickAsync(ChildProcessTracker.pollingInterval) @@ -511,7 +511,7 @@ describe('ChildProcessTracker', function () { it('does not log for processes within threshold', async function () { const runningProcess = startSleepProcess() - usageMock.resolves({ + usageMock.returns({ cpu: ChildProcessTracker.thresholds.cpuPercent - 1, memory: ChildProcessTracker.thresholds.memoryBytes - 1, }) From 30dd7d4466cb894480d85335041b1c0bf2ff4b3c Mon Sep 17 00:00:00 2001 From: hkobew Date: Fri, 17 Jan 2025 13:41:55 -0500 Subject: [PATCH 44/48] rename commands and remove outdated changelog --- .../Feature-db34038d-d2bf-4b6e-b4dc-ac84c0156ab5.json | 4 ---- packages/amazonq/package.json | 4 ++-- packages/core/package.nls.json | 2 +- packages/core/src/extension.ts | 2 +- packages/core/src/shared/telemetry/vscodeTelemetry.json | 4 ++-- .../Feature-82e8146f-5dec-4af6-8f55-482471fdb4ad.json | 4 ---- packages/toolkit/package.json | 4 ++-- 7 files changed, 8 insertions(+), 16 deletions(-) delete mode 100644 packages/amazonq/.changes/next-release/Feature-db34038d-d2bf-4b6e-b4dc-ac84c0156ab5.json delete mode 100644 packages/toolkit/.changes/next-release/Feature-82e8146f-5dec-4af6-8f55-482471fdb4ad.json diff --git a/packages/amazonq/.changes/next-release/Feature-db34038d-d2bf-4b6e-b4dc-ac84c0156ab5.json b/packages/amazonq/.changes/next-release/Feature-db34038d-d2bf-4b6e-b4dc-ac84c0156ab5.json deleted file mode 100644 index 75a5b1179e0..00000000000 --- a/packages/amazonq/.changes/next-release/Feature-db34038d-d2bf-4b6e-b4dc-ac84c0156ab5.json +++ /dev/null @@ -1,4 +0,0 @@ -{ - "type": "Feature", - "description": "Subprocesses are now tracked and visible by \"Log All Active Subprocesses\" in command palette" -} diff --git a/packages/amazonq/package.json b/packages/amazonq/package.json index a108bbd35ca..9481ad0cceb 100644 --- a/packages/amazonq/package.json +++ b/packages/amazonq/package.json @@ -596,8 +596,8 @@ "category": "%AWS.amazonq.title%" }, { - "command": "aws.amazonq.logActiveProcceses", - "title": "%AWS.command.logActiveProcceses%", + "command": "aws.amazonq.showExtStats", + "title": "%AWS.command.showExtStats%", "category": "%AWS.title%" }, { diff --git a/packages/core/package.nls.json b/packages/core/package.nls.json index f19d7c0f63b..803d709fba4 100644 --- a/packages/core/package.nls.json +++ b/packages/core/package.nls.json @@ -177,7 +177,7 @@ "AWS.command.submitFeedback": "Send Feedback...", "AWS.command.downloadSchemaItemCode": "Download Code Bindings", "AWS.command.viewLogs": "View Logs", - "AWS.command.logActiveProcceses": "Log All Active Subprocesses", + "AWS.command.showExtStats": "Show Extension Stats", "AWS.command.cloudWatchLogs.searchLogGroup": "Search Log Group", "AWS.command.cloudWatchLogs.tailLogGroup": "Tail Log Group", "AWS.command.sam.newTemplate": "Create new SAM Template", diff --git a/packages/core/src/extension.ts b/packages/core/src/extension.ts index 49398797495..dad3cadb202 100644 --- a/packages/core/src/extension.ts +++ b/packages/core/src/extension.ts @@ -174,7 +174,7 @@ export async function activateCommon( context.subscriptions.push( Commands.register( - `aws.${contextPrefix}.logActiveProcceses`, + `aws.${contextPrefix}.showExtStats`, async () => await ChildProcessTracker.instance.logAllUsage() ) ) diff --git a/packages/core/src/shared/telemetry/vscodeTelemetry.json b/packages/core/src/shared/telemetry/vscodeTelemetry.json index d5086315b62..1cae24e9e8a 100644 --- a/packages/core/src/shared/telemetry/vscodeTelemetry.json +++ b/packages/core/src/shared/telemetry/vscodeTelemetry.json @@ -389,8 +389,8 @@ ] }, { - "name": "ide_logActiveProcesses", - "description": "Emitted when user invokes logActiveProcesses command", + "name": "ide_reportPerformance", + "description": "Emitted when user invokes reportPerformance command", "metadata": [ { "type": "size", diff --git a/packages/toolkit/.changes/next-release/Feature-82e8146f-5dec-4af6-8f55-482471fdb4ad.json b/packages/toolkit/.changes/next-release/Feature-82e8146f-5dec-4af6-8f55-482471fdb4ad.json deleted file mode 100644 index 75a5b1179e0..00000000000 --- a/packages/toolkit/.changes/next-release/Feature-82e8146f-5dec-4af6-8f55-482471fdb4ad.json +++ /dev/null @@ -1,4 +0,0 @@ -{ - "type": "Feature", - "description": "Subprocesses are now tracked and visible by \"Log All Active Subprocesses\" in command palette" -} diff --git a/packages/toolkit/package.json b/packages/toolkit/package.json index f48b2f47b31..0c4a5d05063 100644 --- a/packages/toolkit/package.json +++ b/packages/toolkit/package.json @@ -3147,8 +3147,8 @@ "category": "%AWS.title%" }, { - "command": "aws.toolkit.logActiveProcceses", - "title": "%AWS.command.logActiveProcceses%", + "command": "aws.toolkit.showExtStats", + "title": "%AWS.command.showExtStats%", "category": "%AWS.title%" }, { From 73b4210026c36b957771ecbef085978f015800b5 Mon Sep 17 00:00:00 2001 From: hkobew Date: Fri, 17 Jan 2025 13:45:44 -0500 Subject: [PATCH 45/48] update changelog --- .../Feature-31e78111-a241-44e5-9163-a81c5ef380d6.json | 4 ++++ .../Feature-db12e8e0-fc45-46e9-81e7-62d85aee2140.json | 4 ++++ 2 files changed, 8 insertions(+) create mode 100644 packages/amazonq/.changes/next-release/Feature-31e78111-a241-44e5-9163-a81c5ef380d6.json create mode 100644 packages/toolkit/.changes/next-release/Feature-db12e8e0-fc45-46e9-81e7-62d85aee2140.json diff --git a/packages/amazonq/.changes/next-release/Feature-31e78111-a241-44e5-9163-a81c5ef380d6.json b/packages/amazonq/.changes/next-release/Feature-31e78111-a241-44e5-9163-a81c5ef380d6.json new file mode 100644 index 00000000000..61d36fee962 --- /dev/null +++ b/packages/amazonq/.changes/next-release/Feature-31e78111-a241-44e5-9163-a81c5ef380d6.json @@ -0,0 +1,4 @@ +{ + "type": "Feature", + "description": "New command \"Show Extension Stats\" to see some runtime performance stats." +} diff --git a/packages/toolkit/.changes/next-release/Feature-db12e8e0-fc45-46e9-81e7-62d85aee2140.json b/packages/toolkit/.changes/next-release/Feature-db12e8e0-fc45-46e9-81e7-62d85aee2140.json new file mode 100644 index 00000000000..61d36fee962 --- /dev/null +++ b/packages/toolkit/.changes/next-release/Feature-db12e8e0-fc45-46e9-81e7-62d85aee2140.json @@ -0,0 +1,4 @@ +{ + "type": "Feature", + "description": "New command \"Show Extension Stats\" to see some runtime performance stats." +} From 0762cb722abb4061a0e9129577b159b16be21946 Mon Sep 17 00:00:00 2001 From: hkobew Date: Fri, 17 Jan 2025 13:53:59 -0500 Subject: [PATCH 46/48] update telemetry --- .../core/src/shared/telemetry/vscodeTelemetry.json | 10 +++++----- packages/core/src/shared/utilities/processUtils.ts | 4 ++-- .../src/test/shared/utilities/processUtils.test.ts | 4 ++-- 3 files changed, 9 insertions(+), 9 deletions(-) diff --git a/packages/core/src/shared/telemetry/vscodeTelemetry.json b/packages/core/src/shared/telemetry/vscodeTelemetry.json index 1cae24e9e8a..66a6a2daa10 100644 --- a/packages/core/src/shared/telemetry/vscodeTelemetry.json +++ b/packages/core/src/shared/telemetry/vscodeTelemetry.json @@ -1,9 +1,9 @@ { "types": [ { - "name": "size", + "name": "numChildProcesses", "type": "int", - "description": "A generic size for when units are clear" + "description": "number of child processes actively running" }, { "name": "childProcess", @@ -389,11 +389,11 @@ ] }, { - "name": "ide_reportPerformance", - "description": "Emitted when user invokes reportPerformance command", + "name": "ide_showExtStats", + "description": "Emitted when user invokes show extensions stats command", "metadata": [ { - "type": "size", + "type": "numChildProcesses", "required": true } ] diff --git a/packages/core/src/shared/utilities/processUtils.ts b/packages/core/src/shared/utilities/processUtils.ts index d9fb5c67041..5f0b86e2d57 100644 --- a/packages/core/src/shared/utilities/processUtils.ts +++ b/packages/core/src/shared/utilities/processUtils.ts @@ -187,8 +187,8 @@ export class ChildProcessTracker { } public async logAllUsage(): Promise { - await telemetry.ide_logActiveProcesses.run(async (span) => { - span.record({ size: this.size }) + await telemetry.ide_showExtStats.run(async (span) => { + span.record({ numChildProcesses: this.size }) if (this.size === 0) { this.logger.info('No Active Subprocesses') return diff --git a/packages/core/src/test/shared/utilities/processUtils.test.ts b/packages/core/src/test/shared/utilities/processUtils.test.ts index 7d4919467bf..7d471312545 100644 --- a/packages/core/src/test/shared/utilities/processUtils.test.ts +++ b/packages/core/src/test/shared/utilities/processUtils.test.ts @@ -546,7 +546,7 @@ describe('ChildProcessTracker', function () { it('emits telemetry with size equal to number of processes (empty)', async function () { await tracker.logAllUsage() - assertTelemetry('ide_logActiveProcesses', { size: 0 }) + assertTelemetry('ide_showExtStats', { numChildProcesses: 0 }) }) it('emits telemetry to number of processes (nonempty)', async function () { @@ -556,7 +556,7 @@ describe('ChildProcessTracker', function () { } await tracker.logAllUsage() - assertTelemetry('ide_logActiveProcesses', { size: size }) + assertTelemetry('ide_showExtStats', { numChildProcesses: size }) }) }) From 628a9d3e6a24aa125e482e73b8d118e4e2c6aa17 Mon Sep 17 00:00:00 2001 From: hkobew Date: Fri, 17 Jan 2025 13:55:39 -0500 Subject: [PATCH 47/48] make it clear it is currently being logged --- packages/core/package.nls.json | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/packages/core/package.nls.json b/packages/core/package.nls.json index 803d709fba4..6a672f21121 100644 --- a/packages/core/package.nls.json +++ b/packages/core/package.nls.json @@ -177,7 +177,7 @@ "AWS.command.submitFeedback": "Send Feedback...", "AWS.command.downloadSchemaItemCode": "Download Code Bindings", "AWS.command.viewLogs": "View Logs", - "AWS.command.showExtStats": "Show Extension Stats", + "AWS.command.showExtStats": "Log Extension Stats", "AWS.command.cloudWatchLogs.searchLogGroup": "Search Log Group", "AWS.command.cloudWatchLogs.tailLogGroup": "Tail Log Group", "AWS.command.sam.newTemplate": "Create new SAM Template", From b329ede891d774221e5c92312cb42745e1d25c30 Mon Sep 17 00:00:00 2001 From: hkobew Date: Fri, 17 Jan 2025 14:00:11 -0500 Subject: [PATCH 48/48] update changelog to match --- .../Feature-31e78111-a241-44e5-9163-a81c5ef380d6.json | 2 +- .../Feature-db12e8e0-fc45-46e9-81e7-62d85aee2140.json | 2 +- 2 files changed, 2 insertions(+), 2 deletions(-) diff --git a/packages/amazonq/.changes/next-release/Feature-31e78111-a241-44e5-9163-a81c5ef380d6.json b/packages/amazonq/.changes/next-release/Feature-31e78111-a241-44e5-9163-a81c5ef380d6.json index 61d36fee962..8ad644c97f8 100644 --- a/packages/amazonq/.changes/next-release/Feature-31e78111-a241-44e5-9163-a81c5ef380d6.json +++ b/packages/amazonq/.changes/next-release/Feature-31e78111-a241-44e5-9163-a81c5ef380d6.json @@ -1,4 +1,4 @@ { "type": "Feature", - "description": "New command \"Show Extension Stats\" to see some runtime performance stats." + "description": "New command \"Log Extension Stats\" to see some runtime performance stats." } diff --git a/packages/toolkit/.changes/next-release/Feature-db12e8e0-fc45-46e9-81e7-62d85aee2140.json b/packages/toolkit/.changes/next-release/Feature-db12e8e0-fc45-46e9-81e7-62d85aee2140.json index 61d36fee962..8ad644c97f8 100644 --- a/packages/toolkit/.changes/next-release/Feature-db12e8e0-fc45-46e9-81e7-62d85aee2140.json +++ b/packages/toolkit/.changes/next-release/Feature-db12e8e0-fc45-46e9-81e7-62d85aee2140.json @@ -1,4 +1,4 @@ { "type": "Feature", - "description": "New command \"Show Extension Stats\" to see some runtime performance stats." + "description": "New command \"Log Extension Stats\" to see some runtime performance stats." }