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..8ad644c97f8 --- /dev/null +++ b/packages/amazonq/.changes/next-release/Feature-31e78111-a241-44e5-9163-a81c5ef380d6.json @@ -0,0 +1,4 @@ +{ + "type": "Feature", + "description": "New command \"Log Extension Stats\" to see some runtime performance stats." +} diff --git a/packages/amazonq/package.json b/packages/amazonq/package.json index 9aeda69ec65..9481ad0cceb 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.showExtStats", + "title": "%AWS.command.showExtStats%", + "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 833ed7aad7f..6a672f21121 100644 --- a/packages/core/package.nls.json +++ b/packages/core/package.nls.json @@ -177,6 +177,7 @@ "AWS.command.submitFeedback": "Send Feedback...", "AWS.command.downloadSchemaItemCode": "Download Code Bindings", "AWS.command.viewLogs": "View Logs", + "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", diff --git a/packages/core/src/extension.ts b/packages/core/src/extension.ts index 00fd730b490..dad3cadb202 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() @@ -171,6 +172,12 @@ export async function activateCommon( await activateViewsShared(extContext.extensionContext) + context.subscriptions.push( + Commands.register( + `aws.${contextPrefix}.showExtStats`, + async () => await ChildProcessTracker.instance.logAllUsage() + ) + ) return extContext } diff --git a/packages/core/src/shared/telemetry/vscodeTelemetry.json b/packages/core/src/shared/telemetry/vscodeTelemetry.json index 5e32b249d4f..66a6a2daa10 100644 --- a/packages/core/src/shared/telemetry/vscodeTelemetry.json +++ b/packages/core/src/shared/telemetry/vscodeTelemetry.json @@ -1,5 +1,21 @@ { "types": [ + { + "name": "numChildProcesses", + "type": "int", + "description": "number of child processes actively running" + }, + { + "name": "childProcess", + "type": "string", + "description": "A string representation of a ChildProcess" + }, + { + "name": "systemResource", + "type": "string", + "allowedValues": ["cpu", "memory"], + "description": "The type of system resource being measured" + }, { "name": "amazonGenerateApproachLatency", "type": "double", @@ -372,6 +388,30 @@ } ] }, + { + "name": "ide_showExtStats", + "description": "Emitted when user invokes show extensions stats command", + "metadata": [ + { + "type": "numChildProcesses", + "required": true + } + ] + }, + { + "name": "ide_childProcessWarning", + "description": "Child Process warning due to high system usage", + "metadata": [ + { + "type": "systemResource", + "required": true + }, + { + "type": "childProcess", + "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 3fcd7864438..5f0b86e2d57 100644 --- a/packages/core/src/shared/utilities/processUtils.ts +++ b/packages/core/src/shared/utilities/processUtils.ts @@ -2,13 +2,13 @@ * 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' import { Timeout, CancellationError, waitUntil } from './timeoutUtils' import { PollingSet } from './pollingSet' import { getLogger } from '../logger/logger' +import { SystemResource, telemetry } from '../telemetry/telemetry' export interface RunParameterContext { /** Reports an error parsed from the stdin/stdout streams. */ @@ -62,28 +62,39 @@ 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 * 1024 * 1024, // 100 MB - cpu: 50, + memoryBytes: 100 * 1024 * 1024, // 100 MB + cpuPercent: 50, } - static readonly logger = getLogger('childProcess') - #processByPid: Map = new Map() - #pids: PollingSet + readonly logger: logger.Logger + static #instance: ChildProcessTracker + + static get instance(): ChildProcessTracker { + return (this.#instance ??= new ChildProcessTracker()) + } + + #processByPid: Map = new Map() + #pids: PollingSet - public constructor() { + 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) @@ -92,7 +103,7 @@ 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) @@ -100,20 +111,41 @@ export class ChildProcessTracker { } private async checkProcessUsage(pid: number): Promise { + 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) }) + }) + } + if (!this.#pids.has(pid)) { - ChildProcessTracker.logger.warn(`Missing process with id ${pid}`) + this.logger.warn(`Missing process with pid ${pid}`) return } const stats = this.getUsage(pid) - if (stats) { - ChildProcessTracker.logger.debug(`Process ${pid} usage: %O`, stats) - if (stats.memory > ChildProcessTracker.thresholds.memory) { - ChildProcessTracker.logger.warn(`Process ${pid} exceeded memory threshold: ${stats.memory}`) - } - if (stats.cpu > ChildProcessTracker.thresholds.cpu) { - ChildProcessTracker.logger.warn(`Process ${pid} exceeded cpu threshold: ${stats.cpu}`) + if (!stats) { + this.logger.warn(`Failed to get process stats for process with pid ${pid}`) + return + } + for (const processStat of Object.keys(ChildProcessTracker.thresholds) as (keyof ProcessStats)[]) { + if (doesExceedThreshold(processStat, stats[processStat])) { + 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 { + try { + return this.#processByPid.get(pid)!.toString() + } catch (e) { + this.logger.warn(`Missing process with pid ${pid}`) + return `pid: ${pid}` + } } public add(childProcess: ChildProcess) { @@ -122,7 +154,7 @@ export class ChildProcessTracker { this.#pids.start(pid) } - public delete(childProcessId: number) { + public delete(childProcessId: pid) { this.#processByPid.delete(childProcessId) this.#pids.delete(childProcessId) } @@ -143,16 +175,42 @@ export class ChildProcessTracker { this.#processByPid.clear() } + public async getAllUsage(): Promise> { + return new Map( + await Promise.all( + Array.from(this.#pids).map(async (pid: pid) => { + const stats = this.getUsage(pid) + return [pid, stats] as const + }) + ) + ) + } + + public async logAllUsage(): Promise { + await telemetry.ide_showExtStats.run(async (span) => { + span.record({ numChildProcesses: 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.cpuPercent}% cpu, ${stats.memoryBytes} B of memory\n` + }, '') + this.logger.info(`Active Subprocesses (${this.size} active)\n${logMsg}`) + }) + } + 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 } + this.logger.warn(`Failed to get process stats for ${pid}: ${e}`) + return { cpuPercent: 0, memoryBytes: 0 } } - function getWindowsUsage() { + function getWindowsUsage(): ProcessStats { const cpuOutput = proc .execFileSync('wmic', [ 'path', @@ -171,12 +229,12 @@ export class ChildProcessTracker { const memoryBytes = parseInt(memOutput.split('\n')[1]) * 1024 return { - cpu: isNaN(cpuPercentage) ? 0 : cpuPercentage, - memory: memoryBytes, + 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() @@ -185,21 +243,19 @@ export class ChildProcessTracker { const memoryBytes = parseInt(rssOutput.split('\n')[1]) * 1024 return { - cpu: isNaN(cpuPercentage) ? 0 : cpuPercentage, - memory: memoryBytes, + cpuPercent: isNaN(cpuPercentage) ? 0 : cpuPercentage, + memoryBytes, } } } } -/** - * Convenience class to manage a child process - * To use: - * - instantiate - * - call and await run to get the results (pass or fail) - */ +export interface ProcessStats { + memoryBytes: number + cpuPercent: number +} 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 0e6f474ed10..7d471312545 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' @@ -384,119 +384,186 @@ 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 = new ChildProcessTracker() - usageMock = sinon.stub(ChildProcessTracker.prototype, 'getUsage') + tracker = ChildProcessTracker.instance + tracker.clear() // Avoid bleed-through of other tests running child processes. }) afterEach(function () { tracker.clear() - usageMock.reset() }) - after(function () { - clock.uninstall() - }) + describe('tracking functionality', function () { + let clock: FakeTimers.InstalledClock + let usageMock: sinon.SinonStub - 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') + before(function () { + clock = installFakeClock() + usageMock = sinon.stub(ChildProcessTracker.prototype, 'getUsage') + }) - await clock.tickAsync(ChildProcessTracker.pollingInterval) - assert.strictEqual(tracker.has(runningProcess.childProcess), true, 'process was mistakenly removed') - await stopAndWait(runningProcess) + afterEach(function () { + usageMock.reset() + }) - await clock.tickAsync(ChildProcessTracker.pollingInterval) - assert.strictEqual(tracker.has(runningProcess.childProcess), false, 'process was not removed after stopping') - }) + after(function () { + clock.uninstall() + usageMock.restore() + }) - 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(`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() + assert.strictEqual(tracker.has(runningProcess.childProcess), true, 'failed to add sleep command') + + await clock.tickAsync(ChildProcessTracker.pollingInterval) + assert.strictEqual(tracker.has(runningProcess.childProcess), true, 'process was mistakenly removed') + await stopAndWait(runningProcess) + + await clock.tickAsync(ChildProcessTracker.pollingInterval) + assert.strictEqual( + tracker.has(runningProcess.childProcess), + false, + 'process was not removed after stopping' + ) + }) - it('logs a warning message when system usage exceeds threshold', async function () { - const runningProcess = startSleepProcess() - tracker.add(runningProcess.childProcess) + it('multiple processes from same command are tracked seperately', async function () { + const runningProcess1 = startSleepProcess() + const runningProcess2 = startSleepProcess() + + 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') + }) - const highCpu: ProcessStats = { - cpu: ChildProcessTracker.thresholds.cpu + 1, - memory: 0, - } - const highMemory: ProcessStats = { - cpu: 0, - memory: ChildProcessTracker.thresholds.memory + 1, - } + it('logs a warning message and emits metric when cpu exceeds threshold', async function () { + const runningProcess = startSleepProcess() - usageMock.returns(highCpu) + const highCpu: ProcessStats = { + cpuPercent: ChildProcessTracker.thresholds.cpuPercent + 1, + memoryBytes: 0, + } - await clock.tickAsync(ChildProcessTracker.pollingInterval) - assertLogsContain('exceeded cpu threshold', false, 'warn') + usageMock.returns(highCpu) - usageMock.returns(highMemory) - await clock.tickAsync(ChildProcessTracker.pollingInterval) - assertLogsContain('exceeded memory threshold', false, 'warn') + await clock.tickAsync(ChildProcessTracker.pollingInterval) + assertLogsContain('exceeded cpu threshold', false, 'warn') + assertTelemetry('ide_childProcessWarning', { + systemResource: 'cpu', + childProcess: runningProcess.childProcess.toString(), + }) - await stopAndWait(runningProcess) - }) + await stopAndWait(runningProcess) + }) - it('includes pid in logs', async function () { - const runningProcess = startSleepProcess() - tracker.add(runningProcess.childProcess) + it('logs a warning message and emits metric when memory exceeds threshold', async function () { + const runningProcess = startSleepProcess() + const highMemory: ProcessStats = { + cpuPercent: 0, + memoryBytes: ChildProcessTracker.thresholds.memoryBytes + 1, + } + + usageMock.returns(highMemory) + await clock.tickAsync(ChildProcessTracker.pollingInterval) + assertLogsContain('exceeded memory threshold', false, 'warn') + assertTelemetry('ide_childProcessWarning', { + systemResource: 'memory', + childProcess: runningProcess.childProcess.toString(), + }) - usageMock.returns({ - 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() + + usageMock.returns({ + cpuPercent: 0, + memoryBytes: ChildProcessTracker.thresholds.memoryBytes + 1, + }) - await stopAndWait(runningProcess) + await clock.tickAsync(ChildProcessTracker.pollingInterval) + assertLogsContain(runningProcess.childProcess.pid().toString(), false, 'warn') + + await stopAndWait(runningProcess) + }) + + it('does not log for processes within threshold', async function () { + const runningProcess = startSleepProcess() + + usageMock.returns({ + cpu: ChildProcessTracker.thresholds.cpuPercent - 1, + memory: ChildProcessTracker.thresholds.memoryBytes - 1, + }) + + await clock.tickAsync(ChildProcessTracker.pollingInterval) + + assert.throws(() => assertLogsContain(runningProcess.childProcess.pid().toString(), false, 'warn')) + assert.throws(() => assertTelemetry('ide_childProcessWarning', {})) + await stopAndWait(runningProcess) + }) }) - it('does not log for processes within threshold', async function () { - const runningProcess = 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') + + await stopAndWait(runningProcess1) - usageMock.returns({ - cpu: ChildProcessTracker.thresholds.cpu - 1, - memory: ChildProcessTracker.thresholds.memory - 1, + await tracker.logAllUsage() + assert.throws(() => assertLogsContain(runningProcess1.childProcess.pid().toString(), false, 'info')) + assertLogsContain(runningProcess2.childProcess.pid().toString(), false, 'info') }) - await clock.tickAsync(ChildProcessTracker.pollingInterval) + it('defaults to empty message when empty', async function () { + await tracker.logAllUsage() + assertLogsContain('No Active Subprocesses', false, 'info') + }) - assert.throws(() => assertLogsContain(runningProcess.childProcess.pid().toString(), false, 'warn')) + it('emits telemetry with size equal to number of processes (empty)', async function () { + await tracker.logAllUsage() + assertTelemetry('ide_showExtStats', { numChildProcesses: 0 }) + }) - await stopAndWait(runningProcess) + 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_showExtStats', { numChildProcesses: 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') }) }) 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..8ad644c97f8 --- /dev/null +++ b/packages/toolkit/.changes/next-release/Feature-db12e8e0-fc45-46e9-81e7-62d85aee2140.json @@ -0,0 +1,4 @@ +{ + "type": "Feature", + "description": "New command \"Log Extension Stats\" to see some runtime performance stats." +} diff --git a/packages/toolkit/package.json b/packages/toolkit/package.json index 26ca248630a..0c4a5d05063 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.showExtStats", + "title": "%AWS.command.showExtStats%", + "category": "%AWS.title%" + }, { "command": "aws.toolkit.help", "title": "%AWS.command.help%",