diff --git a/common/changes/@microsoft/rush/performance-marks_2025-07-03-20-39.json b/common/changes/@microsoft/rush/performance-marks_2025-07-03-20-39.json new file mode 100644 index 00000000000..119a27c4be8 --- /dev/null +++ b/common/changes/@microsoft/rush/performance-marks_2025-07-03-20-39.json @@ -0,0 +1,10 @@ +{ + "changes": [ + { + "packageName": "@microsoft/rush", + "comment": "Add performance measures around various operations, include performance entries in telemetry payload.", + "type": "none" + } + ], + "packageName": "@microsoft/rush" +} \ No newline at end of file diff --git a/common/reviews/api/rush-lib.api.md b/common/reviews/api/rush-lib.api.md index 1d64af11050..a12154b0277 100644 --- a/common/reviews/api/rush-lib.api.md +++ b/common/reviews/api/rush-lib.api.md @@ -23,6 +23,7 @@ import { JsonNull } from '@rushstack/node-core-library'; import { JsonObject } from '@rushstack/node-core-library'; import { LookupByPath } from '@rushstack/lookup-by-path'; import { PackageNameParser } from '@rushstack/node-core-library'; +import type { PerformanceEntry as PerformanceEntry_2 } from 'node:perf_hooks'; import type { StdioSummarizer } from '@rushstack/terminal'; import { SyncHook } from 'tapable'; import { SyncWaterfallHook } from 'tapable'; @@ -884,6 +885,7 @@ export interface ITelemetryData { readonly machineInfo?: ITelemetryMachineInfo; readonly name: string; readonly operationResults?: Record; + readonly performanceEntries?: readonly PerformanceEntry_2[]; readonly platform?: string; readonly result: 'Succeeded' | 'Failed'; readonly rushVersion?: string; diff --git a/libraries/rush-lib/src/api/Rush.ts b/libraries/rush-lib/src/api/Rush.ts index 814c6931e1e..ba146179a2d 100644 --- a/libraries/rush-lib/src/api/Rush.ts +++ b/libraries/rush-lib/src/api/Rush.ts @@ -15,6 +15,7 @@ import { CommandLineMigrationAdvisor } from '../cli/CommandLineMigrationAdvisor' import { EnvironmentVariableNames } from './EnvironmentConfiguration'; import type { IBuiltInPluginConfiguration } from '../pluginFramework/PluginLoader/BuiltInPluginLoader'; import { RushPnpmCommandLine } from '../cli/RushPnpmCommandLine'; +import { measureAsyncFn } from '../utilities/performance'; /** * Options to pass to the rush "launch" functions. @@ -93,8 +94,9 @@ export class Rush { alreadyReportedNodeTooNewError: options.alreadyReportedNodeTooNewError, builtInPluginConfigurations: options.builtInPluginConfigurations }); + // CommandLineParser.executeAsync() should never reject the promise // eslint-disable-next-line no-console - parser.executeAsync().catch(console.error); // CommandLineParser.executeAsync() should never reject the promise + measureAsyncFn('rush:parser:executeAsync', () => parser.executeAsync()).catch(console.error); } /** diff --git a/libraries/rush-lib/src/cli/RushCommandLineParser.ts b/libraries/rush-lib/src/cli/RushCommandLineParser.ts index 1fc0cd36de2..02c7bcb285a 100644 --- a/libraries/rush-lib/src/cli/RushCommandLineParser.ts +++ b/libraries/rush-lib/src/cli/RushCommandLineParser.ts @@ -65,6 +65,8 @@ import { InstallAutoinstallerAction } from './actions/InstallAutoinstallerAction import { LinkPackageAction } from './actions/LinkPackageAction'; import { BridgePackageAction } from './actions/BridgePackageAction'; +import { measureAsyncFn } from '../utilities/performance'; + /** * Options for `RushCommandLineParser`. */ @@ -219,7 +221,9 @@ export class RushCommandLineParser extends CommandLineParser { this._terminalProvider.verboseEnabled = this._terminalProvider.debugEnabled = process.argv.indexOf('--debug') >= 0; - await this.pluginManager.tryInitializeUnassociatedPluginsAsync(); + await measureAsyncFn('rush:initializeUnassociatedPlugins', () => + this.pluginManager.tryInitializeUnassociatedPluginsAsync() + ); return await super.executeAsync(args); } @@ -298,7 +302,7 @@ export class RushCommandLineParser extends CommandLineParser { } try { - await super.onExecuteAsync(); + await measureAsyncFn('rush:commandLineParser:onExecuteAsync', () => super.onExecuteAsync()); } finally { if (this.telemetry) { this.flushTelemetry(); diff --git a/libraries/rush-lib/src/cli/actions/BaseInstallAction.ts b/libraries/rush-lib/src/cli/actions/BaseInstallAction.ts index ea10d9c1a9c..b13b34fe681 100644 --- a/libraries/rush-lib/src/cli/actions/BaseInstallAction.ts +++ b/libraries/rush-lib/src/cli/actions/BaseInstallAction.ts @@ -24,6 +24,7 @@ import { SUBSPACE_LONG_ARG_NAME, type SelectionParameterSet } from '../parsing/S import type { RushConfigurationProject } from '../../api/RushConfigurationProject'; import type { Subspace } from '../../api/Subspace'; import { getVariantAsync, VARIANT_PARAMETER } from '../../api/Variants'; +import { measureAsyncFn } from '../../utilities/performance'; /** * Temporary data structure used by `BaseInstallAction.runAsync()` @@ -285,7 +286,9 @@ export abstract class BaseInstallAction extends BaseRushAction { installSuccessful = false; throw error; } finally { - await purgeManager.startDeleteAllAsync(); + await measureAsyncFn('rush:installManager:startDeleteAllAsync', () => + purgeManager.startDeleteAllAsync() + ); stopwatch.stop(); this._collectTelemetry(stopwatch, installManagerOptions, installSuccessful); @@ -327,7 +330,7 @@ export abstract class BaseInstallAction extends BaseRushAction { installManagerOptions ); - await installManager.doInstallAsync(); + await measureAsyncFn('rush:installManager:doInstallAsync', () => installManager.doInstallAsync()); } private _collectTelemetry( diff --git a/libraries/rush-lib/src/cli/actions/BaseRushAction.ts b/libraries/rush-lib/src/cli/actions/BaseRushAction.ts index 77f02864097..048cf51ca2b 100644 --- a/libraries/rush-lib/src/cli/actions/BaseRushAction.ts +++ b/libraries/rush-lib/src/cli/actions/BaseRushAction.ts @@ -14,6 +14,9 @@ import { Utilities } from '../../utilities/Utilities'; import type { RushGlobalFolder } from '../../api/RushGlobalFolder'; import type { RushSession } from '../../pluginFramework/RushSession'; import type { IRushCommand } from '../../pluginFramework/RushLifeCycle'; +import { measureAsyncFn } from '../../utilities/performance'; + +const PERF_PREFIX: string = 'rush:action'; export interface IBaseRushActionOptions extends ICommandLineActionOptions { /** @@ -75,7 +78,7 @@ export abstract class BaseConfiglessRushAction extends CommandLineAction impleme this.terminal.write(`Starting "rush ${this.actionName}"\n`); } - return await this.runAsync(); + await measureAsyncFn(`${PERF_PREFIX}:runAsync`, () => this.runAsync()); } /** @@ -121,15 +124,19 @@ export abstract class BaseRushAction extends BaseConfiglessRushAction { this._throwPluginErrorIfNeed(); - await this.parser.pluginManager.tryInitializeAssociatedCommandPluginsAsync(this.actionName); + await measureAsyncFn(`${PERF_PREFIX}:initializePluginsAsync`, () => + this.parser.pluginManager.tryInitializeAssociatedCommandPluginsAsync(this.actionName) + ); this._throwPluginErrorIfNeed(); const { hooks: sessionHooks } = this.rushSession; - if (sessionHooks.initialize.isUsed()) { - // Avoid the cost of compiling the hook if it wasn't tapped. - await sessionHooks.initialize.promise(this); - } + await measureAsyncFn(`${PERF_PREFIX}:initializePlugins`, async () => { + if (sessionHooks.initialize.isUsed()) { + // Avoid the cost of compiling the hook if it wasn't tapped. + await sessionHooks.initialize.promise(this); + } + }); return super.onExecuteAsync(); } diff --git a/libraries/rush-lib/src/cli/scriptActions/GlobalScriptAction.ts b/libraries/rush-lib/src/cli/scriptActions/GlobalScriptAction.ts index 58f5310f707..3efb9b3d6a2 100644 --- a/libraries/rush-lib/src/cli/scriptActions/GlobalScriptAction.ts +++ b/libraries/rush-lib/src/cli/scriptActions/GlobalScriptAction.ts @@ -20,6 +20,7 @@ import { Utilities } from '../../utilities/Utilities'; import { Stopwatch } from '../../utilities/Stopwatch'; import { Autoinstaller } from '../../logic/Autoinstaller'; import type { IGlobalCommandConfig, IShellCommandTokenContext } from '../../api/CommandLineConfiguration'; +import { measureAsyncFn } from '../../utilities/performance'; /** * Constructor parameters for GlobalScriptAction. @@ -120,7 +121,9 @@ export class GlobalScriptAction extends BaseScriptAction { this.commandLineConfiguration?.additionalPathFolders.slice() || []; if (this._autoinstallerName) { - await this._prepareAutoinstallerNameAsync(); + await measureAsyncFn('rush:globalScriptAction:prepareAutoinstaller', () => + this._prepareAutoinstallerNameAsync() + ); const autoinstallerNameBinPath: string = path.join(this._autoinstallerFullPath, 'node_modules', '.bin'); additionalPathFolders.push(autoinstallerNameBinPath); diff --git a/libraries/rush-lib/src/cli/scriptActions/PhasedScriptAction.ts b/libraries/rush-lib/src/cli/scriptActions/PhasedScriptAction.ts index 355176763e0..1a38d88537f 100644 --- a/libraries/rush-lib/src/cli/scriptActions/PhasedScriptAction.ts +++ b/libraries/rush-lib/src/cli/scriptActions/PhasedScriptAction.ts @@ -59,6 +59,9 @@ import { getVariantAsync, VARIANT_PARAMETER } from '../../api/Variants'; import { Selection } from '../../logic/Selection'; import { NodeDiagnosticDirPlugin } from '../../logic/operations/NodeDiagnosticDirPlugin'; import { DebugHashesPlugin } from '../../logic/operations/DebugHashesPlugin'; +import { measureAsyncFn, measureFn } from '../../utilities/performance'; + +const PERF_PREFIX: 'rush:phasedScriptAction' = 'rush:phasedScriptAction'; /** * Constructor parameters for PhasedScriptAction. @@ -180,18 +183,7 @@ export class PhasedScriptAction extends BaseScriptAction { this.hooks = new PhasedCommandHooks(); - const terminal: Terminal = new Terminal(this.rushSession.terminalProvider); - this._terminal = terminal; - - // Generates the default operation graph - new PhasedOperationPlugin().apply(this.hooks); - // Splices in sharded phases to the operation graph. - new ShardedPhasedOperationPlugin().apply(this.hooks); - // Applies the Shell Operation Runner to selected operations - new ShellOperationRunnerPlugin().apply(this.hooks); - - new WeightedOperationPlugin().apply(this.hooks); - new ValidateOperationsPlugin(terminal).apply(this.hooks); + this._terminal = new Terminal(this.rushSession.terminalProvider); this._parallelismParameter = this._enableParallelism ? this.defineStringParameter({ @@ -334,52 +326,61 @@ export class PhasedScriptAction extends BaseScriptAction { } public async runAsync(): Promise { + const stopwatch: Stopwatch = Stopwatch.start(); + if (this._alwaysInstall || this._installParameter?.value) { - const { doBasicInstallAsync } = await import( - /* webpackChunkName: 'doBasicInstallAsync' */ - '../../logic/installManager/doBasicInstallAsync' - ); + await measureAsyncFn(`${PERF_PREFIX}:install`, async () => { + const { doBasicInstallAsync } = await import( + /* webpackChunkName: 'doBasicInstallAsync' */ + '../../logic/installManager/doBasicInstallAsync' + ); - const variant: string | undefined = await getVariantAsync( - this._variantParameter, - this.rushConfiguration, - true - ); - await doBasicInstallAsync({ - terminal: this._terminal, - rushConfiguration: this.rushConfiguration, - rushGlobalFolder: this.rushGlobalFolder, - isDebug: this.parser.isDebug, - variant, - beforeInstallAsync: (subspace: Subspace) => - this.rushSession.hooks.beforeInstall.promise(this, subspace, variant), - afterInstallAsync: (subspace: Subspace) => - this.rushSession.hooks.afterInstall.promise(this, subspace, variant), - // Eventually we may want to allow a subspace to be selected here - subspace: this.rushConfiguration.defaultSubspace + const variant: string | undefined = await getVariantAsync( + this._variantParameter, + this.rushConfiguration, + true + ); + await doBasicInstallAsync({ + terminal: this._terminal, + rushConfiguration: this.rushConfiguration, + rushGlobalFolder: this.rushGlobalFolder, + isDebug: this.parser.isDebug, + variant, + beforeInstallAsync: (subspace: Subspace) => + this.rushSession.hooks.beforeInstall.promise(this, subspace, variant), + afterInstallAsync: (subspace: Subspace) => + this.rushSession.hooks.afterInstall.promise(this, subspace, variant), + // Eventually we may want to allow a subspace to be selected here + subspace: this.rushConfiguration.defaultSubspace + }); }); } if (!this._runsBeforeInstall) { - // TODO: Replace with last-install.flag when "rush link" and "rush unlink" are removed - const lastLinkFlag: FlagFile = new FlagFile( - this.rushConfiguration.defaultSubspace.getSubspaceTempFolderPath(), - RushConstants.lastLinkFlagFilename, - {} - ); - // Only check for a valid link flag when subspaces is not enabled - if (!(await lastLinkFlag.isValidAsync()) && !this.rushConfiguration.subspacesFeatureEnabled) { - const useWorkspaces: boolean = - this.rushConfiguration.pnpmOptions && this.rushConfiguration.pnpmOptions.useWorkspaces; - if (useWorkspaces) { - throw new Error('Link flag invalid.\nDid you run "rush install" or "rush update"?'); - } else { - throw new Error('Link flag invalid.\nDid you run "rush link"?'); + await measureAsyncFn(`${PERF_PREFIX}:checkInstallFlag`, async () => { + // TODO: Replace with last-install.flag when "rush link" and "rush unlink" are removed + const lastLinkFlag: FlagFile = new FlagFile( + this.rushConfiguration.defaultSubspace.getSubspaceTempFolderPath(), + RushConstants.lastLinkFlagFilename, + {} + ); + // Only check for a valid link flag when subspaces is not enabled + if (!(await lastLinkFlag.isValidAsync()) && !this.rushConfiguration.subspacesFeatureEnabled) { + const useWorkspaces: boolean = + this.rushConfiguration.pnpmOptions && this.rushConfiguration.pnpmOptions.useWorkspaces; + if (useWorkspaces) { + throw new Error('Link flag invalid.\nDid you run "rush install" or "rush update"?'); + } else { + throw new Error('Link flag invalid.\nDid you run "rush link"?'); + } } - } + }); } - this._doBeforeTask(); + measureFn(`${PERF_PREFIX}:doBeforeTask`, () => this._doBeforeTask()); + + const hooks: PhasedCommandHooks = this.hooks; + const terminal: ITerminal = this._terminal; // if this is parallelizable, then use the value from the flag (undefined or a number), // if parallelism is not enabled, then restrict to 1 core @@ -387,35 +388,45 @@ export class PhasedScriptAction extends BaseScriptAction { ? parseParallelism(this._parallelismParameter?.value) : 1; - const terminal: ITerminal = this._terminal; - - const stopwatch: Stopwatch = Stopwatch.start(); - - const showTimeline: boolean = this._timelineParameter ? this._timelineParameter.value : false; - if (showTimeline) { - const { ConsoleTimelinePlugin } = await import( - /* webpackChunkName: 'ConsoleTimelinePlugin' */ - '../../logic/operations/ConsoleTimelinePlugin' - ); - new ConsoleTimelinePlugin(terminal).apply(this.hooks); - } - const includePhaseDeps: boolean = this._includePhaseDeps?.value ?? false; - const diagnosticDir: string | undefined = this._nodeDiagnosticDirParameter.value; - if (diagnosticDir) { - new NodeDiagnosticDirPlugin({ - diagnosticDir - }).apply(this.hooks); - } + await measureAsyncFn(`${PERF_PREFIX}:applyStandardPlugins`, async () => { + // Generates the default operation graph + new PhasedOperationPlugin().apply(hooks); + // Splices in sharded phases to the operation graph. + new ShardedPhasedOperationPlugin().apply(hooks); + // Applies the Shell Operation Runner to selected operations + new ShellOperationRunnerPlugin().apply(hooks); + + new WeightedOperationPlugin().apply(hooks); + new ValidateOperationsPlugin(terminal).apply(hooks); + + const showTimeline: boolean = this._timelineParameter?.value ?? false; + if (showTimeline) { + const { ConsoleTimelinePlugin } = await import( + /* webpackChunkName: 'ConsoleTimelinePlugin' */ + '../../logic/operations/ConsoleTimelinePlugin' + ); + new ConsoleTimelinePlugin(terminal).apply(this.hooks); + } - // Enable the standard summary - new OperationResultSummarizerPlugin(terminal).apply(this.hooks); + const diagnosticDir: string | undefined = this._nodeDiagnosticDirParameter.value; + if (diagnosticDir) { + new NodeDiagnosticDirPlugin({ + diagnosticDir + }).apply(this.hooks); + } + + // Enable the standard summary + new OperationResultSummarizerPlugin(terminal).apply(this.hooks); + }); const { hooks: sessionHooks } = this.rushSession; if (sessionHooks.runAnyPhasedCommand.isUsed()) { - // Avoid the cost of compiling the hook if it wasn't tapped. - await sessionHooks.runAnyPhasedCommand.promise(this); + await measureAsyncFn(`${PERF_PREFIX}:runAnyPhasedCommand`, async () => { + // Avoid the cost of compiling the hook if it wasn't tapped. + await sessionHooks.runAnyPhasedCommand.promise(this); + }); } const hookForAction: AsyncSeriesHook | undefined = sessionHooks.runPhasedCommand.get( @@ -423,8 +434,10 @@ export class PhasedScriptAction extends BaseScriptAction { ); if (hookForAction) { - // Run the more specific hook for a command with this name after the general hook - await hookForAction.promise(this); + await measureAsyncFn(`${PERF_PREFIX}:runPhasedCommand`, async () => { + // Run the more specific hook for a command with this name after the general hook + await hookForAction.promise(this); + }); } const isQuietMode: boolean = !this._verboseParameter.value; @@ -435,22 +448,22 @@ export class PhasedScriptAction extends BaseScriptAction { let buildCacheConfiguration: BuildCacheConfiguration | undefined; let cobuildConfiguration: CobuildConfiguration | undefined; if (!this._disableBuildCache) { - buildCacheConfiguration = await BuildCacheConfiguration.tryLoadAsync( - terminal, - this.rushConfiguration, - this.rushSession - ); - cobuildConfiguration = await CobuildConfiguration.tryLoadAsync( - terminal, - this.rushConfiguration, - this.rushSession - ); - await cobuildConfiguration?.createLockProviderAsync(terminal); + await measureAsyncFn(`${PERF_PREFIX}:configureBuildCache`, async () => { + [buildCacheConfiguration, cobuildConfiguration] = await Promise.all([ + BuildCacheConfiguration.tryLoadAsync(terminal, this.rushConfiguration, this.rushSession), + CobuildConfiguration.tryLoadAsync(terminal, this.rushConfiguration, this.rushSession) + ]); + if (cobuildConfiguration) { + await cobuildConfiguration.createLockProviderAsync(terminal); + } + }); } try { - const projectSelection: Set = - await this._selectionParameters.getSelectedProjectsAsync(terminal); + const projectSelection: Set = await measureAsyncFn( + `${PERF_PREFIX}:getSelectedProjects`, + () => this._selectionParameters.getSelectedProjectsAsync(terminal) + ); if (!projectSelection.size) { terminal.writeLine( @@ -459,67 +472,69 @@ export class PhasedScriptAction extends BaseScriptAction { return; } - const isWatch: boolean = this._watchParameter?.value || this._alwaysWatch; - - if (isWatch && this._noIPCParameter?.value === false) { - new ( - await import( - /* webpackChunkName: 'IPCOperationRunnerPlugin' */ '../../logic/operations/IPCOperationRunnerPlugin' - ) - ).IPCOperationRunnerPlugin().apply(this.hooks); - } - const customParametersByName: Map = new Map(); for (const [configParameter, parserParameter] of this.customParameters) { customParametersByName.set(configParameter.longName, parserParameter); } - if (buildCacheConfiguration?.buildCacheEnabled) { - terminal.writeVerboseLine(`Incremental strategy: cache restoration`); - new CacheableOperationPlugin({ - allowWarningsInSuccessfulBuild: - !!this.rushConfiguration.experimentsConfiguration.configuration - .buildCacheWithAllowWarningsInSuccessfulBuild, - buildCacheConfiguration, - cobuildConfiguration, - terminal - }).apply(this.hooks); + const isWatch: boolean = this._watchParameter?.value || this._alwaysWatch; - if (this._debugBuildCacheIdsParameter.value) { - new DebugHashesPlugin(terminal).apply(this.hooks); + await measureAsyncFn(`${PERF_PREFIX}:applySituationalPlugins`, async () => { + if (isWatch && this._noIPCParameter?.value === false) { + new ( + await import( + /* webpackChunkName: 'IPCOperationRunnerPlugin' */ '../../logic/operations/IPCOperationRunnerPlugin' + ) + ).IPCOperationRunnerPlugin().apply(this.hooks); } - } else if (!this._disableBuildCache) { - terminal.writeVerboseLine(`Incremental strategy: output preservation`); - // Explicitly disabling the build cache also disables legacy skip detection. - new LegacySkipPlugin({ - allowWarningsInSuccessfulBuild: - this.rushConfiguration.experimentsConfiguration.configuration - .buildSkipWithAllowWarningsInSuccessfulBuild, - terminal, - changedProjectsOnly, - isIncrementalBuildAllowed: this._isIncrementalBuildAllowed - }).apply(this.hooks); - } else { - terminal.writeVerboseLine(`Incremental strategy: none (full rebuild)`); - } - const showBuildPlan: boolean = this._cobuildPlanParameter?.value ?? false; + if (buildCacheConfiguration?.buildCacheEnabled) { + terminal.writeVerboseLine(`Incremental strategy: cache restoration`); + new CacheableOperationPlugin({ + allowWarningsInSuccessfulBuild: + !!this.rushConfiguration.experimentsConfiguration.configuration + .buildCacheWithAllowWarningsInSuccessfulBuild, + buildCacheConfiguration, + cobuildConfiguration, + terminal + }).apply(this.hooks); + + if (this._debugBuildCacheIdsParameter.value) { + new DebugHashesPlugin(terminal).apply(this.hooks); + } + } else if (!this._disableBuildCache) { + terminal.writeVerboseLine(`Incremental strategy: output preservation`); + // Explicitly disabling the build cache also disables legacy skip detection. + new LegacySkipPlugin({ + allowWarningsInSuccessfulBuild: + this.rushConfiguration.experimentsConfiguration.configuration + .buildSkipWithAllowWarningsInSuccessfulBuild, + terminal, + changedProjectsOnly, + isIncrementalBuildAllowed: this._isIncrementalBuildAllowed + }).apply(this.hooks); + } else { + terminal.writeVerboseLine(`Incremental strategy: none (full rebuild)`); + } + + const showBuildPlan: boolean = this._cobuildPlanParameter?.value ?? false; - if (showBuildPlan) { - if (!buildCacheConfiguration?.buildCacheEnabled) { - throw new Error('You must have build cache enabled to use this option.'); + if (showBuildPlan) { + if (!buildCacheConfiguration?.buildCacheEnabled) { + throw new Error('You must have build cache enabled to use this option.'); + } + const { BuildPlanPlugin } = await import('../../logic/operations/BuildPlanPlugin'); + new BuildPlanPlugin(terminal).apply(this.hooks); } - const { BuildPlanPlugin } = await import('../../logic/operations/BuildPlanPlugin'); - new BuildPlanPlugin(terminal).apply(this.hooks); - } - const { configuration: experiments } = this.rushConfiguration.experimentsConfiguration; - if (this.rushConfiguration?.isPnpm && experiments?.usePnpmSyncForInjectedDependencies) { - const { PnpmSyncCopyOperationPlugin } = await import( - '../../logic/operations/PnpmSyncCopyOperationPlugin' - ); - new PnpmSyncCopyOperationPlugin(terminal).apply(this.hooks); - } + const { configuration: experiments } = this.rushConfiguration.experimentsConfiguration; + if (this.rushConfiguration?.isPnpm && experiments?.usePnpmSyncForInjectedDependencies) { + const { PnpmSyncCopyOperationPlugin } = await import( + '../../logic/operations/PnpmSyncCopyOperationPlugin' + ); + new PnpmSyncCopyOperationPlugin(terminal).apply(this.hooks); + } + }); const relevantProjects: Set = Selection.expandAllDependencies(projectSelection); @@ -527,7 +542,9 @@ export class PhasedScriptAction extends BaseScriptAction { const projectConfigurations: ReadonlyMap = this ._runsBeforeInstall ? new Map() - : await RushProjectConfiguration.tryLoadForProjectsAsync(relevantProjects, terminal); + : await measureAsyncFn(`${PERF_PREFIX}:loadProjectConfigurations`, () => + RushProjectConfiguration.tryLoadForProjectsAsync(relevantProjects, terminal) + ); const initialCreateOperationsContext: ICreateOperationsContext = { buildCacheConfiguration, @@ -577,7 +594,9 @@ export class PhasedScriptAction extends BaseScriptAction { terminal }; - const internalOptions: IRunPhasesOptions = await this._runInitialPhasesAsync(initialInternalOptions); + const internalOptions: IRunPhasesOptions = await measureAsyncFn(`${PERF_PREFIX}:runInitialPhases`, () => + this._runInitialPhasesAsync(initialInternalOptions) + ); if (isWatch) { if (buildCacheConfiguration) { @@ -589,7 +608,9 @@ export class PhasedScriptAction extends BaseScriptAction { terminal.writeDebugLine(`Watch mode exited.`); } } finally { - await cobuildConfiguration?.destroyLockProviderAsync(); + if (cobuildConfiguration) { + await cobuildConfiguration.destroyLockProviderAsync(); + } } } @@ -604,28 +625,35 @@ export class PhasedScriptAction extends BaseScriptAction { const { projectConfigurations } = initialCreateOperationsContext; const { projectSelection } = initialCreateOperationsContext; - const operations: Set = await this.hooks.createOperations.promise( - new Set(), - initialCreateOperationsContext + const operations: Set = await measureAsyncFn(`${PERF_PREFIX}:createOperations`, () => + this.hooks.createOperations.promise(new Set(), initialCreateOperationsContext) ); - terminal.write('Analyzing repo state... '); - const repoStateStopwatch: Stopwatch = new Stopwatch(); - repoStateStopwatch.start(); - - const analyzer: ProjectChangeAnalyzer = new ProjectChangeAnalyzer(this.rushConfiguration); - const getInputsSnapshotAsync: GetInputsSnapshotAsyncFn | undefined = - await analyzer._tryGetSnapshotProviderAsync( - projectConfigurations, - terminal, - // We need to include all dependencies, otherwise build cache id calculation will be incorrect - Selection.expandAllDependencies(projectSelection) - ); - const initialSnapshot: IInputsSnapshot | undefined = await getInputsSnapshotAsync?.(); - - repoStateStopwatch.stop(); - terminal.writeLine(`DONE (${repoStateStopwatch.toString()})`); - terminal.writeLine(); + const [getInputsSnapshotAsync, initialSnapshot] = await measureAsyncFn( + `${PERF_PREFIX}:analyzeRepoState`, + async () => { + terminal.write('Analyzing repo state... '); + const repoStateStopwatch: Stopwatch = new Stopwatch(); + repoStateStopwatch.start(); + + const analyzer: ProjectChangeAnalyzer = new ProjectChangeAnalyzer(this.rushConfiguration); + const innerGetInputsSnapshotAsync: GetInputsSnapshotAsyncFn | undefined = + await analyzer._tryGetSnapshotProviderAsync( + projectConfigurations, + terminal, + // We need to include all dependencies, otherwise build cache id calculation will be incorrect + Selection.expandAllDependencies(projectSelection) + ); + const innerInitialSnapshot: IInputsSnapshot | undefined = innerGetInputsSnapshotAsync + ? await innerGetInputsSnapshotAsync() + : undefined; + + repoStateStopwatch.stop(); + terminal.writeLine(`DONE (${repoStateStopwatch.toString()})`); + terminal.writeLine(); + return [innerGetInputsSnapshotAsync, innerInitialSnapshot]; + } + ); const initialExecuteOperationsContext: IExecuteOperationsContext = { ...initialCreateOperationsContext, @@ -636,7 +664,9 @@ export class PhasedScriptAction extends BaseScriptAction { ...partialExecutionManagerOptions, inputsSnapshot: initialSnapshot, beforeExecuteOperationsAsync: async (records: Map) => { - await this.hooks.beforeExecuteOperations.promise(records, initialExecuteOperationsContext); + await measureAsyncFn(`${PERF_PREFIX}:beforeExecuteOperations`, () => + this.hooks.beforeExecuteOperations.promise(records, initialExecuteOperationsContext) + ); } }; @@ -649,7 +679,9 @@ export class PhasedScriptAction extends BaseScriptAction { terminal }; - await this._executeOperationsAsync(initialOptions); + await measureAsyncFn(`${PERF_PREFIX}:executeOperations`, () => + this._executeOperationsAsync(initialOptions) + ); return { ...options, @@ -822,8 +854,10 @@ export class PhasedScriptAction extends BaseScriptAction { // Loop until Ctrl+C while (!abortSignal.aborted) { // On the initial invocation, this promise will return immediately with the full set of projects - const { changedProjects, inputsSnapshot: state } = - await projectWatcher.waitForChangeAsync(onWaitingForChanges); + const { changedProjects, inputsSnapshot: state } = await measureAsyncFn( + `${PERF_PREFIX}:waitForChanges`, + () => projectWatcher.waitForChangeAsync(onWaitingForChanges) + ); if (abortSignal.aborted) { return; @@ -855,9 +889,8 @@ export class PhasedScriptAction extends BaseScriptAction { invalidateOperation }; - const operations: Set = await this.hooks.createOperations.promise( - new Set(), - executeOperationsContext + const operations: Set = await measureAsyncFn(`${PERF_PREFIX}:createOperations`, () => + this.hooks.createOperations.promise(new Set(), executeOperationsContext) ); const executeOptions: IExecutionOperationsOptions = { @@ -870,7 +903,9 @@ export class PhasedScriptAction extends BaseScriptAction { ...executionManagerOptions, inputsSnapshot: state, beforeExecuteOperationsAsync: async (records: Map) => { - await this.hooks.beforeExecuteOperations.promise(records, executeOperationsContext); + await measureAsyncFn(`${PERF_PREFIX}:beforeExecuteOperations`, () => + this.hooks.beforeExecuteOperations.promise(records, executeOperationsContext) + ); } }, terminal @@ -878,7 +913,9 @@ export class PhasedScriptAction extends BaseScriptAction { try { // Delegate the the underlying command, for only the projects that need reprocessing - await this._executeOperationsAsync(executeOptions); + await measureAsyncFn(`${PERF_PREFIX}:executeOperations`, () => + this._executeOperationsAsync(executeOptions) + ); } catch (err) { // In watch mode, we want to rebuild even if the original build failed. if (!(err instanceof AlreadyReportedError)) { @@ -905,10 +942,16 @@ export class PhasedScriptAction extends BaseScriptAction { let result: IExecutionResult | undefined; try { - result = await executionManager.executeAsync(); - success = result.status === OperationStatus.Success; + const definiteResult: IExecutionResult = await measureAsyncFn( + `${PERF_PREFIX}:executeOperationsInner`, + () => executionManager.executeAsync() + ); + success = definiteResult.status === OperationStatus.Success; + result = definiteResult; - await this.hooks.afterExecuteOperations.promise(result, options.executeOperationsContext); + await measureAsyncFn(`${PERF_PREFIX}:afterExecuteOperations`, () => + this.hooks.afterExecuteOperations.promise(definiteResult, options.executeOperationsContext) + ); stopwatch.stop(); @@ -938,119 +981,123 @@ export class PhasedScriptAction extends BaseScriptAction { } if (!ignoreHooks) { - this._doAfterTask(); + measureFn(`${PERF_PREFIX}:doAfterTask`, () => this._doAfterTask()); } if (this.parser.telemetry) { - const jsonOperationResults: Record = {}; - - const extraData: IPhasedCommandTelemetry = { - // Fields preserved across the command invocation - ...this._selectionParameters.getTelemetry(), - ...this.getParameterStringMap(), - isWatch, - // Fields specific to the current operation set - isInitial, - - countAll: 0, - countSuccess: 0, - countSuccessWithWarnings: 0, - countFailure: 0, - countBlocked: 0, - countFromCache: 0, - countSkipped: 0, - countNoOp: 0 - }; - - const { _changedProjectsOnlyParameter: changedProjectsOnlyParameter } = this; - if (changedProjectsOnlyParameter) { - // Overwrite this value since we allow changing it at runtime. - extraData[changedProjectsOnlyParameter.scopedLongName ?? changedProjectsOnlyParameter.longName] = - this._changedProjectsOnly; - } + const logEntry: ITelemetryData = measureFn(`${PERF_PREFIX}:prepareTelemetry`, () => { + const jsonOperationResults: Record = {}; + + const extraData: IPhasedCommandTelemetry = { + // Fields preserved across the command invocation + ...this._selectionParameters.getTelemetry(), + ...this.getParameterStringMap(), + isWatch, + // Fields specific to the current operation set + isInitial, + + countAll: 0, + countSuccess: 0, + countSuccessWithWarnings: 0, + countFailure: 0, + countBlocked: 0, + countFromCache: 0, + countSkipped: 0, + countNoOp: 0 + }; + + const { _changedProjectsOnlyParameter: changedProjectsOnlyParameter } = this; + if (changedProjectsOnlyParameter) { + // Overwrite this value since we allow changing it at runtime. + extraData[changedProjectsOnlyParameter.scopedLongName ?? changedProjectsOnlyParameter.longName] = + this._changedProjectsOnly; + } - if (result) { - const { operationResults } = result; - - const nonSilentDependenciesByOperation: Map> = new Map(); - function getNonSilentDependencies(operation: Operation): ReadonlySet { - let realDependencies: Set | undefined = nonSilentDependenciesByOperation.get(operation); - if (!realDependencies) { - realDependencies = new Set(); - nonSilentDependenciesByOperation.set(operation, realDependencies); - for (const dependency of operation.dependencies) { - const dependencyRecord: IOperationExecutionResult | undefined = - operationResults.get(dependency); - if (dependencyRecord?.silent) { - for (const deepDependency of getNonSilentDependencies(dependency)) { - realDependencies.add(deepDependency); + if (result) { + const { operationResults } = result; + + const nonSilentDependenciesByOperation: Map> = new Map(); + function getNonSilentDependencies(operation: Operation): ReadonlySet { + let realDependencies: Set | undefined = nonSilentDependenciesByOperation.get(operation); + if (!realDependencies) { + realDependencies = new Set(); + nonSilentDependenciesByOperation.set(operation, realDependencies); + for (const dependency of operation.dependencies) { + const dependencyRecord: IOperationExecutionResult | undefined = + operationResults.get(dependency); + if (dependencyRecord?.silent) { + for (const deepDependency of getNonSilentDependencies(dependency)) { + realDependencies.add(deepDependency); + } + } else { + realDependencies.add(dependency.name!); } - } else { - realDependencies.add(dependency.name!); } } + return realDependencies; } - return realDependencies; - } - for (const [operation, operationResult] of operationResults) { - if (operationResult.silent) { - // Architectural operation. Ignore. - continue; - } + for (const [operation, operationResult] of operationResults) { + if (operationResult.silent) { + // Architectural operation. Ignore. + continue; + } - const { _operationMetadataManager: operationMetadataManager } = - operationResult as OperationExecutionRecord; - - const { startTime, endTime } = operationResult.stopwatch; - jsonOperationResults[operation.name!] = { - startTimestampMs: startTime, - endTimestampMs: endTime, - nonCachedDurationMs: operationResult.nonCachedDurationMs, - wasExecutedOnThisMachine: operationMetadataManager?.wasCobuilt !== true, - result: operationResult.status, - dependencies: Array.from(getNonSilentDependencies(operation)).sort() - }; - - extraData.countAll++; - switch (operationResult.status) { - case OperationStatus.Success: - extraData.countSuccess++; - break; - case OperationStatus.SuccessWithWarning: - extraData.countSuccessWithWarnings++; - break; - case OperationStatus.Failure: - extraData.countFailure++; - break; - case OperationStatus.Blocked: - extraData.countBlocked++; - break; - case OperationStatus.FromCache: - extraData.countFromCache++; - break; - case OperationStatus.Skipped: - extraData.countSkipped++; - break; - case OperationStatus.NoOp: - extraData.countNoOp++; - break; - default: - // Do nothing. - break; + const { _operationMetadataManager: operationMetadataManager } = + operationResult as OperationExecutionRecord; + + const { startTime, endTime } = operationResult.stopwatch; + jsonOperationResults[operation.name!] = { + startTimestampMs: startTime, + endTimestampMs: endTime, + nonCachedDurationMs: operationResult.nonCachedDurationMs, + wasExecutedOnThisMachine: operationMetadataManager?.wasCobuilt !== true, + result: operationResult.status, + dependencies: Array.from(getNonSilentDependencies(operation)).sort() + }; + + extraData.countAll++; + switch (operationResult.status) { + case OperationStatus.Success: + extraData.countSuccess++; + break; + case OperationStatus.SuccessWithWarning: + extraData.countSuccessWithWarnings++; + break; + case OperationStatus.Failure: + extraData.countFailure++; + break; + case OperationStatus.Blocked: + extraData.countBlocked++; + break; + case OperationStatus.FromCache: + extraData.countFromCache++; + break; + case OperationStatus.Skipped: + extraData.countSkipped++; + break; + case OperationStatus.NoOp: + extraData.countNoOp++; + break; + default: + // Do nothing. + break; + } } } - } - const logEntry: ITelemetryData = { - name: this.actionName, - durationInSeconds: stopwatch.duration, - result: success ? 'Succeeded' : 'Failed', - extraData, - operationResults: jsonOperationResults - }; + const innerLogEntry: ITelemetryData = { + name: this.actionName, + durationInSeconds: stopwatch.duration, + result: success ? 'Succeeded' : 'Failed', + extraData, + operationResults: jsonOperationResults + }; + + return innerLogEntry; + }); - this.hooks.beforeLog.call(logEntry); + measureFn(`${PERF_PREFIX}:beforeLog`, () => this.hooks.beforeLog.call(logEntry)); this.parser.telemetry.log(logEntry); diff --git a/libraries/rush-lib/src/logic/Telemetry.ts b/libraries/rush-lib/src/logic/Telemetry.ts index 66de0da2c1b..28c2976d829 100644 --- a/libraries/rush-lib/src/logic/Telemetry.ts +++ b/libraries/rush-lib/src/logic/Telemetry.ts @@ -3,11 +3,13 @@ import * as os from 'os'; import * as path from 'path'; +import type { PerformanceEntry } from 'node:perf_hooks'; import { FileSystem, type FileSystemStats, JsonFile } from '@rushstack/node-core-library'; import type { RushConfiguration } from '../api/RushConfiguration'; import { Rush } from '../api/Rush'; import type { RushSession } from '../pluginFramework/RushSession'; +import { collectPerformanceEntries } from '../utilities/performance'; /** * @beta @@ -129,6 +131,12 @@ export interface ITelemetryData { readonly operationResults?: Record; readonly extraData?: { [key: string]: string | number | boolean }; + + /** + * Performance marks and measures collected during the execution of this command. + * This is an array of `PerformanceEntry` objects, which can include marks, measures, and function timings. + */ + readonly performanceEntries?: readonly PerformanceEntry[]; } const MAX_FILE_COUNT: number = 100; @@ -141,6 +149,7 @@ export class Telemetry { private _rushConfiguration: RushConfiguration; private _rushSession: RushSession; private _flushAsyncTasks: Set> = new Set(); + private _telemetryStartTime: number = 0; public constructor(rushConfiguration: RushConfiguration, rushSession: RushSession) { this._rushConfiguration = rushConfiguration; @@ -159,6 +168,8 @@ export class Telemetry { const cpus: os.CpuInfo[] = os.cpus(); const data: ITelemetryData = { ...telemetryData, + performanceEntries: + telemetryData.performanceEntries || collectPerformanceEntries(this._telemetryStartTime), machineInfo: telemetryData.machineInfo || { machineArchitecture: os.arch(), // The Node.js model is sometimes padded, for example: @@ -172,6 +183,7 @@ export class Telemetry { platform: telemetryData.platform || process.platform, rushVersion: telemetryData.rushVersion || Rush.version }; + this._telemetryStartTime = performance.now(); this._store.push(data); } diff --git a/libraries/rush-lib/src/logic/test/Telemetry.test.ts b/libraries/rush-lib/src/logic/test/Telemetry.test.ts index d98795c26de..aebc60ef4a9 100644 --- a/libraries/rush-lib/src/logic/test/Telemetry.test.ts +++ b/libraries/rush-lib/src/logic/test/Telemetry.test.ts @@ -20,6 +20,8 @@ describe(Telemetry.name, () => { }); beforeEach(() => { + performance.clearMarks(); + performance.clearMeasures(); jest.clearAllMocks(); }); @@ -42,7 +44,8 @@ describe(Telemetry.name, () => { timestampMs: new Date().getTime(), platform: process.platform, rushVersion: Rush.version, - machineInfo: {} as ITelemetryMachineInfo + machineInfo: {} as ITelemetryMachineInfo, + performanceEntries: [] }; const logData2: ITelemetryData = { @@ -52,7 +55,8 @@ describe(Telemetry.name, () => { timestampMs: new Date().getTime(), platform: process.platform, rushVersion: Rush.version, - machineInfo: {} as ITelemetryMachineInfo + machineInfo: {} as ITelemetryMachineInfo, + performanceEntries: [] }; telemetry.log(logData1); @@ -96,7 +100,8 @@ describe(Telemetry.name, () => { timestampMs: new Date().getTime(), platform: process.platform, rushVersion: Rush.version, - machineInfo: {} as ITelemetryMachineInfo + machineInfo: {} as ITelemetryMachineInfo, + performanceEntries: [] }; telemetry.log(logData); diff --git a/libraries/rush-lib/src/start.ts b/libraries/rush-lib/src/start.ts index b4da75c1edc..27c4e17d3b6 100644 --- a/libraries/rush-lib/src/start.ts +++ b/libraries/rush-lib/src/start.ts @@ -3,4 +3,8 @@ import { Rush } from './api/Rush'; +performance.mark('rush:start'); + Rush.launch(Rush.version, { isManaged: false }); + +// Rush.launch has async side effects, so no point ending the measurement. diff --git a/libraries/rush-lib/src/utilities/performance.ts b/libraries/rush-lib/src/utilities/performance.ts new file mode 100644 index 00000000000..ced7757096e --- /dev/null +++ b/libraries/rush-lib/src/utilities/performance.ts @@ -0,0 +1,67 @@ +// Copyright (c) Microsoft Corporation. All rights reserved. Licensed under the MIT license. +// See LICENSE in the project root for license information. + +import type { PerformanceEntry } from 'node:perf_hooks'; + +/** + * Starts a performance measurement that can be disposed later to record the elapsed time. + * @param name - The name of the performance measurement. This should be unique for each measurement. + * @returns A Disposable object that, when disposed, will end and record the performance measurement. + */ +export function measureUntilDisposed(name: string): Disposable { + const start: number = performance.now(); + + return { + [Symbol.dispose]() { + performance.measure(name, { + start + }); + } + }; +} + +/** + * Measures the execution time of a Promise-returning function. + * @param name - The name of the performance measurement. This should be unique for each measurement. + * @param fn - A function that returns a Promise. This function will be executed, and its execution time will be measured. + * @returns A Promise that resolves with the result of the function. + */ +export function measureAsyncFn(name: string, fn: () => Promise): Promise { + const start: number = performance.now(); + return fn().finally(() => { + performance.measure(name, { + start + }); + }); +} + +/** + * Measures the execution time of a synchronous function. + * @param name - The name of the performance measurement. This should be unique for each measurement. + * @param fn - A function that returns a value. This function will be executed, and its execution time will be measured. + * @returns The result of the function. + */ +export function measureFn(name: string, fn: () => T): T { + const start: number = performance.now(); + try { + return fn(); + } finally { + performance.measure(name, { + start + }); + } +} + +/** + * Collects performance measurements that were created after a specified start time. + * @param startTime - The start time in milliseconds from which to collect performance measurements. + * @returns An array of `PerformanceEntry` objects with start times greater than or equal to the specified start time. + */ +export function collectPerformanceEntries(startTime: number): PerformanceEntry[] { + const entries: PerformanceEntry[] = performance.getEntries(); + const startIndex: number = entries.findIndex((entry) => entry.startTime >= startTime); + if (startIndex === -1) { + return []; // No entries found after the specified start time + } + return entries.slice(startIndex); +} diff --git a/rush.json b/rush.json index cc0be06d919..46241fd5092 100644 --- a/rush.json +++ b/rush.json @@ -304,7 +304,7 @@ * that read these JSON files and do something with them. These scripts are typically registered * in the "eventHooks" section. */ - // "telemetryEnabled": false, + "telemetryEnabled": true, /** * Allows creation of hotfix changes. This feature is experimental so it is disabled by default.