diff --git a/src/compiler/performance.ts b/src/compiler/performance.ts index 3f6c23f2b0735..341becea645ab 100644 --- a/src/compiler/performance.ts +++ b/src/compiler/performance.ts @@ -107,6 +107,28 @@ namespace ts.performance { durations.forEach((duration, measureName) => cb(measureName, duration)); } + export function forEachMark(cb: (markName: string) => void) { + marks.forEach((_time, markName) => cb(markName)); + } + + export function clearMeasures(name?: string) { + if (name !== undefined) durations.delete(name); + else durations.clear(); + performanceImpl?.clearMeasures(name); + } + + export function clearMarks(name?: string) { + if (name !== undefined) { + counts.delete(name); + marks.delete(name); + } + else { + counts.clear(); + marks.clear(); + } + performanceImpl?.clearMarks(name); + } + /** * Indicates whether the performance API is enabled. */ diff --git a/src/compiler/performanceCore.ts b/src/compiler/performanceCore.ts index ac40726ebb273..07492542a5ca4 100644 --- a/src/compiler/performanceCore.ts +++ b/src/compiler/performanceCore.ts @@ -13,6 +13,8 @@ namespace ts { export interface Performance { mark(name: string): void; measure(name: string, startMark?: string, endMark?: string): void; + clearMeasures(name?: string): void; + clearMarks(name?: string): void; now(): number; timeOrigin: number; } @@ -50,6 +52,8 @@ namespace ts { typeof performance.mark === "function" && typeof performance.measure === "function" && typeof performance.now === "function" && + typeof performance.clearMarks === "function" && + typeof performance.clearMeasures === "function" && typeof PerformanceObserver === "function"; } @@ -73,8 +77,8 @@ namespace ts { try { let performance: Performance; const { performance: nodePerformance, PerformanceObserver } = require("perf_hooks") as typeof import("perf_hooks"); - if (hasRequiredAPI(nodePerformance, PerformanceObserver)) { - performance = nodePerformance; + if (hasRequiredAPI(nodePerformance as unknown as Performance, PerformanceObserver)) { + performance = nodePerformance as unknown as Performance; // There is a bug in Node's performance.measure prior to 12.16.3/13.13.0 that does not // match the Web Performance API specification. Node's implementation did not allow // optional `start` and `end` arguments for `performance.measure`. @@ -95,7 +99,9 @@ namespace ts { if (end === "__performance.measure-fix__") { nodePerformance.clearMarks("__performance.measure-fix__"); } - } + }, + clearMarks(name) { return nodePerformance.clearMarks(name); }, + clearMeasures(name) { return (nodePerformance as unknown as Performance).clearMeasures(name); }, }; } return { diff --git a/src/compiler/tsbuildPublic.ts b/src/compiler/tsbuildPublic.ts index 8e24320933450..2b9d97f324ee2 100644 --- a/src/compiler/tsbuildPublic.ts +++ b/src/compiler/tsbuildPublic.ts @@ -404,6 +404,7 @@ namespace ts { return isParsedCommandLine(value) ? value : undefined; } + performance.mark("SolutionBuilder::beforeConfigFileParsing"); let diagnostic: Diagnostic | undefined; const { parseConfigFileHost, baseCompilerOptions, baseWatchOptions, extendedConfigCache, host } = state; let parsed: ParsedCommandLine | undefined; @@ -417,6 +418,8 @@ namespace ts { parseConfigFileHost.onUnRecoverableConfigFileDiagnostic = noop; } configFileCache.set(configFilePath, parsed || diagnostic!); + performance.mark("SolutionBuilder::afterConfigFileParsing"); + performance.measure("SolutionBuilder::Config file parsing", "SolutionBuilder::beforeConfigFileParsing", "SolutionBuilder::afterConfigFileParsing"); return parsed; } @@ -734,6 +737,7 @@ namespace ts { if (updateOutputFileStampsPending) { updateOutputTimestamps(state, config, projectPath); } + performance.mark("SolutionBuilder::Timestamps only updates"); return doneInvalidatedProject(state, projectPath); } }; @@ -847,6 +851,8 @@ namespace ts { function done(cancellationToken?: CancellationToken, writeFile?: WriteFileCallback, customTransformers?: CustomTransformers) { executeSteps(BuildStep.Done, cancellationToken, writeFile, customTransformers); + if (kind === InvalidatedProjectKind.Build) performance.mark("SolutionBuilder::Projects built"); + else performance.mark("SolutionBuilder::Bundles updated"); return doneInvalidatedProject(state, projectPath); } @@ -1809,7 +1815,10 @@ namespace ts { return prior; } + performance.mark("SolutionBuilder::beforeUpToDateCheck"); const actual = getUpToDateStatusWorker(state, project, resolvedPath); + performance.mark("SolutionBuilder::afterUpToDateCheck"); + performance.measure("SolutionBuilder::Up-to-date check", "SolutionBuilder::beforeUpToDateCheck", "SolutionBuilder::afterUpToDateCheck"); state.projectStatus.set(resolvedPath, actual); return actual; } @@ -1958,6 +1967,14 @@ namespace ts { } function build(state: SolutionBuilderState, project?: string, cancellationToken?: CancellationToken, writeFile?: WriteFileCallback, getCustomTransformers?: (project: string) => CustomTransformers, onlyReferences?: boolean): ExitStatus { + performance.mark("SolutionBuilder::beforeBuild"); + const result = buildWorker(state, project, cancellationToken, writeFile, getCustomTransformers, onlyReferences); + performance.mark("SolutionBuilder::afterBuild"); + performance.measure("SolutionBuilder::Build", "SolutionBuilder::beforeBuild", "SolutionBuilder::afterBuild"); + return result; + } + + function buildWorker(state: SolutionBuilderState, project: string | undefined, cancellationToken: CancellationToken | undefined, writeFile: WriteFileCallback | undefined, getCustomTransformers: ((project: string) => CustomTransformers) | undefined, onlyReferences: boolean | undefined): ExitStatus { const buildOrder = getBuildOrderFor(state, project, onlyReferences); if (!buildOrder) return ExitStatus.InvalidProject_OutputsSkipped; @@ -1986,7 +2003,15 @@ namespace ts { : ExitStatus.DiagnosticsPresent_OutputsSkipped; } - function clean(state: SolutionBuilderState, project?: string, onlyReferences?: boolean) { + function clean(state: SolutionBuilderState, project?: string, onlyReferences?: boolean): ExitStatus { + performance.mark("SolutionBuilder::beforeClean"); + const result = cleanWorker(state, project, onlyReferences); + performance.mark("SolutionBuilder::afterClean"); + performance.measure("SolutionBuilder::Clean", "SolutionBuilder::beforeClean", "SolutionBuilder::afterClean"); + return result; + } + + function cleanWorker(state: SolutionBuilderState, project: string | undefined, onlyReferences: boolean | undefined) { const buildOrder = getBuildOrderFor(state, project, onlyReferences); if (!buildOrder) return ExitStatus.InvalidProject_OutputsSkipped; @@ -2063,6 +2088,14 @@ namespace ts { } function buildNextInvalidatedProject(state: SolutionBuilderState, changeDetected: boolean) { + performance.mark("SolutionBuilder::beforeBuild"); + const buildOrder = buildNextInvalidatedProjectWorker(state, changeDetected); + performance.mark("SolutionBuilder::afterBuild"); + performance.measure("SolutionBuilder::Build", "SolutionBuilder::beforeBuild", "SolutionBuilder::afterBuild"); + if (buildOrder) reportErrorSummary(state, buildOrder); + } + + function buildNextInvalidatedProjectWorker(state: SolutionBuilderState, changeDetected: boolean) { state.timerToBuildInvalidatedProject = undefined; if (state.reportFileChangeDetected) { state.reportFileChangeDetected = false; @@ -2092,7 +2125,7 @@ namespace ts { } } disableCache(state); - reportErrorSummary(state, buildOrder); + return buildOrder; } function watchConfigFile(state: SolutionBuilderState, resolved: ResolvedConfigFileName, resolvedPath: ResolvedConfigFilePath, parsed: ParsedCommandLine | undefined) { @@ -2199,6 +2232,7 @@ namespace ts { function startWatching(state: SolutionBuilderState, buildOrder: AnyBuildOrder) { if (!state.watchAllProjectsPending) return; + performance.mark("SolutionBuilder::beforeWatcherCreation"); state.watchAllProjectsPending = false; for (const resolved of getBuildOrderFromAnyBuildOrder(buildOrder)) { const resolvedPath = toResolvedConfigFilePath(state, resolved); @@ -2217,6 +2251,8 @@ namespace ts { watchPackageJsonFiles(state, resolved, resolvedPath, cfg); } } + performance.mark("SolutionBuilder::afterWatcherCreation"); + performance.measure("SolutionBuilder::Watcher creation", "SolutionBuilder::beforeWatcherCreation", "SolutionBuilder::afterWatcherCreation"); } function stopWatching(state: SolutionBuilderState) { diff --git a/src/executeCommandLine/executeCommandLine.ts b/src/executeCommandLine/executeCommandLine.ts index 68d2e51e9d4eb..cb3ba0575a146 100644 --- a/src/executeCommandLine/executeCommandLine.ts +++ b/src/executeCommandLine/executeCommandLine.ts @@ -1,7 +1,14 @@ namespace ts { interface Statistic { name: string; - value: string; + value: number; + type: StatisticType; + } + + export enum StatisticType { + time, + count, + memory, } function countLines(program: Program): Map { @@ -14,15 +21,6 @@ namespace ts { return counts; } - function countNodes(program: Program): Map { - const counts = getCountsMap(); - forEach(program.getSourceFiles(), file => { - const key = getCountKey(program, file); - counts.set(key, counts.get(key)! + file.nodeCount); - }); - return counts; - } - function getCountsMap() { const counts = new Map(); counts.set("Library", 0); @@ -751,7 +749,16 @@ namespace ts { createBuilderStatusReporter(sys, shouldBePretty(sys, buildOptions)), createWatchStatusReporter(sys, buildOptions) ); - updateSolutionBuilderHost(sys, cb, buildHost); + const solutionPerformance = enableSolutionPerformance(sys, buildOptions); + updateSolutionBuilderHost(sys, cb, buildHost, solutionPerformance); + const onWatchStatusChange = buildHost.onWatchStatusChange; + buildHost.onWatchStatusChange = (d, newLine, options, errorCount) => { + onWatchStatusChange?.(d, newLine, options, errorCount); + if (d.code === Diagnostics.Found_0_errors_Watching_for_file_changes.code || + d.code === Diagnostics.Found_1_error_Watching_for_file_changes.code) { + reportSolutionBuilderTimes(builder, solutionPerformance); + } + }; const builder = createSolutionBuilderWithWatch(buildHost, projects, buildOptions, watchOptions); builder.build(); return builder; @@ -764,9 +771,11 @@ namespace ts { createBuilderStatusReporter(sys, shouldBePretty(sys, buildOptions)), createReportErrorSummary(sys, buildOptions) ); - updateSolutionBuilderHost(sys, cb, buildHost); + const solutionPerformance = enableSolutionPerformance(sys, buildOptions); + updateSolutionBuilderHost(sys, cb, buildHost, solutionPerformance); const builder = createSolutionBuilder(buildHost, projects, buildOptions); const exitStatus = buildOptions.clean ? builder.clean() : builder.build(); + reportSolutionBuilderTimes(builder, solutionPerformance); dumpTracingLegend(); // Will no-op if there hasn't been any tracing return sys.exit(exitStatus); } @@ -804,7 +813,7 @@ namespace ts { s => sys.write(s + sys.newLine), createReportErrorSummary(sys, options) ); - reportStatistics(sys, program); + reportStatistics(sys, program, /*builder*/ undefined); cb(program); return sys.exit(exitStatus); } @@ -828,7 +837,7 @@ namespace ts { reportDiagnostic, reportErrorSummary: createReportErrorSummary(sys, options), afterProgramEmitAndDiagnostics: builderProgram => { - reportStatistics(sys, builderProgram.getProgram()); + reportStatistics(sys, builderProgram.getProgram(), /*builder*/ undefined); cb(builderProgram); } }); @@ -838,22 +847,23 @@ namespace ts { function updateSolutionBuilderHost( sys: System, cb: ExecuteCommandLineCallbacks, - buildHost: SolutionBuilderHostBase + buildHost: SolutionBuilderHostBase, + solutionPerformance: SolutionPerformance | undefined, ) { - updateCreateProgram(sys, buildHost); + updateCreateProgram(sys, buildHost, /*isBuildMode*/ true); buildHost.afterProgramEmitAndDiagnostics = program => { - reportStatistics(sys, program.getProgram()); + reportStatistics(sys, program.getProgram(), solutionPerformance); cb(program); }; buildHost.afterEmitBundle = cb; } - function updateCreateProgram(sys: System, host: { createProgram: CreateProgram; }) { + function updateCreateProgram(sys: System, host: { createProgram: CreateProgram; }, isBuildMode: boolean) { const compileUsingBuilder = host.createProgram; host.createProgram = (rootNames, options, host, oldProgram, configFileParsingDiagnostics, projectReferences) => { Debug.assert(rootNames !== undefined || (options === undefined && !!oldProgram)); if (options !== undefined) { - enableStatisticsAndTracing(sys, options, /*isBuildMode*/ true); + enableStatisticsAndTracing(sys, options, isBuildMode); } return compileUsingBuilder(rootNames, options, host, oldProgram, configFileParsingDiagnostics, projectReferences); }; @@ -864,11 +874,11 @@ namespace ts { cb: ExecuteCommandLineCallbacks, watchCompilerHost: WatchCompilerHost, ) { - updateCreateProgram(sys, watchCompilerHost); + updateCreateProgram(sys, watchCompilerHost, /*isBuildMode*/ false); const emitFilesUsingBuilder = watchCompilerHost.afterProgramCreate!; // TODO: GH#18217 watchCompilerHost.afterProgramCreate = builderProgram => { emitFilesUsingBuilder(builderProgram); - reportStatistics(sys, builderProgram.getProgram()); + reportStatistics(sys, builderProgram.getProgram(), /*builder*/ undefined); cb(builderProgram); }; } @@ -920,6 +930,88 @@ namespace ts { return createWatchProgram(watchCompilerHost); } + interface SolutionPerformance { + addAggregateStatistic(s: Statistic): void; + forEachAggregateStatistics(cb: (s: Statistic) => void): void; + clear(): void; + } + + function enableSolutionPerformance(system: System, options: BuildOptions) { + if (system === sys && options.extendedDiagnostics) { + performance.enable(); + return createSolutionPerfomrance(); + } + } + + function createSolutionPerfomrance(): SolutionPerformance { + let statistics: ESMap | undefined; + return { + addAggregateStatistic, + forEachAggregateStatistics: forEachAggreateStatistics, + clear, + }; + + function addAggregateStatistic(s: Statistic) { + const existing = statistics?.get(s.name); + if (existing) { + if (existing.type === StatisticType.memory) existing.value = Math.max(existing.value, s.value); + else existing.value += s.value; + } + else { + (statistics ??= new Map()).set(s.name, s); + } + } + + function forEachAggreateStatistics(cb: (s: Statistic) => void) { + statistics?.forEach(cb); + } + + function clear() { + statistics = undefined; + } + } + + function reportSolutionBuilderTimes( + builder: SolutionBuilder, + solutionPerformance: SolutionPerformance | undefined) { + if (!solutionPerformance) return; + + if (!performance.isEnabled()) { + sys.write(Diagnostics.Performance_timings_for_diagnostics_or_extendedDiagnostics_are_not_available_in_this_session_A_native_implementation_of_the_Web_Performance_API_could_not_be_found.message + "\n"); + return; + } + + const statistics: Statistic[] = []; + statistics.push( + { name: "Projects in scope", value: getBuildOrderFromAnyBuildOrder(builder.getBuildOrder()).length, type: StatisticType.count }, + ); + reportSolutionBuilderCountStatistic("SolutionBuilder::Projects built"); + reportSolutionBuilderCountStatistic("SolutionBuilder::Timestamps only updates"); + reportSolutionBuilderCountStatistic("SolutionBuilder::Bundles updated"); + solutionPerformance.forEachAggregateStatistics(s => { + s.name = `Aggregate ${s.name}`; + statistics.push(s); + }); + performance.forEachMeasure((name, duration) => { + if (isSolutionMarkOrMeasure(name)) statistics.push({ name: `${getNameFromSolutionBuilderMarkOrMeasure(name)} time`, value: duration, type: StatisticType.time }); + }); + performance.disable(); + performance.enable(); + + reportAllStatistics(sys, statistics); + + function reportSolutionBuilderCountStatistic(name: string) { + const value = performance.getCount(name); + if (value) { + statistics.push({ name: getNameFromSolutionBuilderMarkOrMeasure(name), value, type: StatisticType.count }); + } + } + + function getNameFromSolutionBuilderMarkOrMeasure(name: string) { + return name.replace("SolutionBuilder::", ""); + } + } + function canReportDiagnostics(system: System, compilerOptions: CompilerOptions) { return system === sys && (compilerOptions.diagnostics || compilerOptions.extendedDiagnostics); } @@ -939,7 +1031,11 @@ namespace ts { } } - function reportStatistics(sys: System, program: Program) { + function isSolutionMarkOrMeasure(name: string) { + return startsWith(name, "SolutionBuilder::"); + } + + function reportStatistics(sys: System, program: Program, solutionPerformance: SolutionPerformance | undefined) { const compilerOptions = program.getCompilerOptions(); if (canTrace(sys, compilerOptions)) { @@ -953,18 +1049,13 @@ namespace ts { reportCountStatistic("Files", program.getSourceFiles().length); const lineCounts = countLines(program); - const nodeCounts = countNodes(program); if (compilerOptions.extendedDiagnostics) { for (const key of arrayFrom(lineCounts.keys())) { reportCountStatistic("Lines of " + key, lineCounts.get(key)!); } - for (const key of arrayFrom(nodeCounts.keys())) { - reportCountStatistic("Nodes of " + key, nodeCounts.get(key)!); - } } else { reportCountStatistic("Lines", reduceLeftIterator(lineCounts.values(), (sum, count) => sum + count, 0)); - reportCountStatistic("Nodes", reduceLeftIterator(nodeCounts.values(), (sum, count) => sum + count, 0)); } reportCountStatistic("Identifiers", program.getIdentifierCount()); @@ -973,7 +1064,7 @@ namespace ts { reportCountStatistic("Instantiations", program.getInstantiationCount()); if (memoryUsed >= 0) { - reportStatisticalValue("Memory used", Math.round(memoryUsed / 1000) + "K"); + reportStatisticalValue({ name: "Memory used", value: memoryUsed, type: StatisticType.memory }, /*aggregate*/ true); } const isPerformanceEnabled = performance.isEnabled(); @@ -988,7 +1079,9 @@ namespace ts { reportCountStatistic("Subtype cache size", caches.subtype); reportCountStatistic("Strict subtype cache size", caches.strictSubtype); if (isPerformanceEnabled) { - performance.forEachMeasure((name, duration) => reportTimeStatistic(`${name} time`, duration)); + performance.forEachMeasure((name, duration) => { + if (!isSolutionMarkOrMeasure(name)) reportTimeStatistic(`${name} time`, duration, /*aggregate*/ true); + }); } } else if (isPerformanceEnabled) { @@ -996,53 +1089,79 @@ namespace ts { // Note: To match the behavior of previous versions of the compiler, the reported parse time includes // I/O read time and processing time for triple-slash references and module imports, and the reported // emit time includes I/O write time. We preserve this behavior so we can accurately compare times. - reportTimeStatistic("I/O read", performance.getDuration("I/O Read")); - reportTimeStatistic("I/O write", performance.getDuration("I/O Write")); - reportTimeStatistic("Parse time", programTime); - reportTimeStatistic("Bind time", bindTime); - reportTimeStatistic("Check time", checkTime); - reportTimeStatistic("Emit time", emitTime); + reportTimeStatistic("I/O read", performance.getDuration("I/O Read"), /*aggregate*/ true); + reportTimeStatistic("I/O write", performance.getDuration("I/O Write"), /*aggregate*/ true); + reportTimeStatistic("Parse time", programTime, /*aggregate*/ true); + reportTimeStatistic("Bind time", bindTime, /*aggregate*/ true); + reportTimeStatistic("Check time", checkTime, /*aggregate*/ true); + reportTimeStatistic("Emit time", emitTime, /*aggregate*/ true); } if (isPerformanceEnabled) { - reportTimeStatistic("Total time", programTime + bindTime + checkTime + emitTime); + reportTimeStatistic("Total time", programTime + bindTime + checkTime + emitTime, /*aggregate*/ false); } - reportStatistics(); + reportAllStatistics(sys, statistics); if (!isPerformanceEnabled) { sys.write(Diagnostics.Performance_timings_for_diagnostics_or_extendedDiagnostics_are_not_available_in_this_session_A_native_implementation_of_the_Web_Performance_API_could_not_be_found.message + "\n"); } else { - performance.disable(); + if (solutionPerformance) { + // Clear selected marks and measures + performance.forEachMeasure(name => { + if (!isSolutionMarkOrMeasure(name)) performance.clearMeasures(name); + }); + performance.forEachMark(name => { + if (!isSolutionMarkOrMeasure(name)) performance.clearMarks(name); + }); + } + else { + performance.disable(); + } } } - function reportStatistics() { - let nameSize = 0; - let valueSize = 0; - for (const { name, value } of statistics) { - if (name.length > nameSize) { - nameSize = name.length; - } + function reportStatisticalValue(s: Statistic, aggregate: boolean) { + statistics.push(s); + if (aggregate) solutionPerformance?.addAggregateStatistic(s); + } - if (value.length > valueSize) { - valueSize = value.length; - } - } + function reportCountStatistic(name: string, count: number) { + reportStatisticalValue({ name, value: count, type: StatisticType.count }, /*aggregate*/ true); + } - for (const { name, value } of statistics) { - sys.write(padRight(name + ":", nameSize + 2) + padLeft(value.toString(), valueSize) + sys.newLine); - } + function reportTimeStatistic(name: string, time: number, aggregate: boolean) { + reportStatisticalValue({ name, value: time, type: StatisticType.time }, aggregate); } + } + + function reportAllStatistics(sys: System, statistics: Statistic[]) { + let nameSize = 0; + let valueSize = 0; + for (const s of statistics) { + if (s.name.length > nameSize) { + nameSize = s.name.length; + } - function reportStatisticalValue(name: string, value: string) { - statistics.push({ name, value }); + const value = statisticValue(s); + if (value.length > valueSize) { + valueSize = value.length; + } } - function reportCountStatistic(name: string, count: number) { - reportStatisticalValue(name, "" + count); + for (const s of statistics) { + sys.write(padRight(s.name + ":", nameSize + 2) + padLeft(statisticValue(s).toString(), valueSize) + sys.newLine); } + } - function reportTimeStatistic(name: string, time: number) { - reportStatisticalValue(name, (time / 1000).toFixed(2) + "s"); + function statisticValue(s: Statistic) { + switch (s.type) { + case StatisticType.count: + return "" + s.value; + case StatisticType.time: + return (s.value / 1000).toFixed(2) + "s"; + case StatisticType.memory: + return Math.round(s.value / 1000) + "K"; + default: + Debug.assertNever(s.type); } }