Report aggregate statistics for solution as well as some solution perf numbers (#50267)

* Report aggregate statistics for solution as well as some solution perf numbers
This change under --extendedDiagnostics aggregates the diagnostics from all projects built and reports it at the end. Apart from that it also outputs some measurements for work that happens in tsc --build like finding if projects are uptodate etc.
Also removes unnecessary node count per suggestion

* Apply suggestions from code review

Co-authored-by: Ron Buckton <ron.buckton@microsoft.com>

* Fix condition

* Remove extra time

Co-authored-by: Ron Buckton <ron.buckton@microsoft.com>
This commit is contained in:
Sheetal Nandi 2022-08-11 13:20:48 -07:00 committed by GitHub
parent 075ee3d4b6
commit b19741c65d
No known key found for this signature in database
GPG Key ID: 4AEE18F83AFDEB23
4 changed files with 249 additions and 66 deletions

View File

@ -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.
*/

View File

@ -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 {

View File

@ -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) {

View File

@ -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<number> {
@ -14,15 +21,6 @@ namespace ts {
return counts;
}
function countNodes(program: Program): Map<number> {
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<string, number>();
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<EmitAndSemanticDiagnosticsBuilderProgram>
buildHost: SolutionBuilderHostBase<EmitAndSemanticDiagnosticsBuilderProgram>,
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<T extends BuilderProgram>(sys: System, host: { createProgram: CreateProgram<T>; }) {
function updateCreateProgram<T extends BuilderProgram>(sys: System, host: { createProgram: CreateProgram<T>; }, 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<EmitAndSemanticDiagnosticsBuilderProgram>,
) {
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<string, Statistic> | 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<EmitAndSemanticDiagnosticsBuilderProgram>,
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;
}
if (value.length > valueSize) {
valueSize = value.length;
}
}
for (const { name, value } of statistics) {
sys.write(padRight(name + ":", nameSize + 2) + padLeft(value.toString(), valueSize) + sys.newLine);
}
}
function reportStatisticalValue(name: string, value: string) {
statistics.push({ name, value });
function reportStatisticalValue(s: Statistic, aggregate: boolean) {
statistics.push(s);
if (aggregate) solutionPerformance?.addAggregateStatistic(s);
}
function reportCountStatistic(name: string, count: number) {
reportStatisticalValue(name, "" + count);
reportStatisticalValue({ name, value: count, type: StatisticType.count }, /*aggregate*/ true);
}
function reportTimeStatistic(name: string, time: number) {
reportStatisticalValue(name, (time / 1000).toFixed(2) + "s");
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;
}
const value = statisticValue(s);
if (value.length > valueSize) {
valueSize = value.length;
}
}
for (const s of statistics) {
sys.write(padRight(s.name + ":", nameSize + 2) + padLeft(statisticValue(s).toString(), valueSize) + sys.newLine);
}
}
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);
}
}