From 8128ce685129eae445f81209f48bd55d6139357a Mon Sep 17 00:00:00 2001 From: Wesley Wigham Date: Tue, 5 Jul 2016 16:39:04 -0700 Subject: [PATCH 1/4] Port performance tools from transforms branch --- Jakefile.js | 2 + src/compiler/binder.ts | 6 +-- src/compiler/checker.ts | 6 +-- src/compiler/core.ts | 2 + src/compiler/parser.ts | 6 +-- src/compiler/performance.ts | 98 +++++++++++++++++++++++++++++++++++++ src/compiler/program.ts | 21 +++----- src/compiler/tsc.ts | 21 +++----- src/compiler/tsconfig.json | 1 + 9 files changed, 125 insertions(+), 38 deletions(-) create mode 100644 src/compiler/performance.ts diff --git a/Jakefile.js b/Jakefile.js index 828f4b084d1fa..4164116a9683f 100644 --- a/Jakefile.js +++ b/Jakefile.js @@ -34,6 +34,7 @@ if (process.env.path !== undefined) { var compilerSources = [ "core.ts", + "performance.ts", "sys.ts", "types.ts", "scanner.ts", @@ -54,6 +55,7 @@ var compilerSources = [ var servicesSources = [ "core.ts", + "performance.ts", "sys.ts", "types.ts", "scanner.ts", diff --git a/src/compiler/binder.ts b/src/compiler/binder.ts index b7852a64d04de..ff9c0a29fe45b 100644 --- a/src/compiler/binder.ts +++ b/src/compiler/binder.ts @@ -3,8 +3,6 @@ /* @internal */ namespace ts { - export let bindTime = 0; - export const enum ModuleInstanceState { NonInstantiated = 0, Instantiated = 1, @@ -91,9 +89,9 @@ namespace ts { const binder = createBinder(); export function bindSourceFile(file: SourceFile, options: CompilerOptions) { - const start = new Date().getTime(); + const start = performance.mark(); binder(file, options); - bindTime += new Date().getTime() - start; + performance.measure("bindTime", start); } function createBinder(): (file: SourceFile, options: CompilerOptions) => void { diff --git a/src/compiler/checker.ts b/src/compiler/checker.ts index 6427b05c37aec..2e4ed64a21824 100644 --- a/src/compiler/checker.ts +++ b/src/compiler/checker.ts @@ -15,8 +15,6 @@ namespace ts { return node.id; } - export let checkTime = 0; - export function getSymbolId(symbol: Symbol): number { if (!symbol.id) { symbol.id = nextSymbolId; @@ -17011,11 +17009,11 @@ namespace ts { } function checkSourceFile(node: SourceFile) { - const start = new Date().getTime(); + const start = performance.mark(); checkSourceFileWorker(node); - checkTime += new Date().getTime() - start; + performance.measure("checkTime", start); } // Fully type check a source file and collect the relevant diagnostics. diff --git a/src/compiler/core.ts b/src/compiler/core.ts index fe4731a1c9144..2678fb7cabae7 100644 --- a/src/compiler/core.ts +++ b/src/compiler/core.ts @@ -1,4 +1,6 @@ /// +/// + /* @internal */ namespace ts { diff --git a/src/compiler/parser.ts b/src/compiler/parser.ts index d720cd0648f9d..e1f37139de3b3 100644 --- a/src/compiler/parser.ts +++ b/src/compiler/parser.ts @@ -2,8 +2,6 @@ /// namespace ts { - /* @internal */ export let parseTime = 0; - let NodeConstructor: new (kind: SyntaxKind, pos: number, end: number) => Node; let SourceFileConstructor: new (kind: SyntaxKind, pos: number, end: number) => Node; @@ -413,10 +411,10 @@ namespace ts { } export function createSourceFile(fileName: string, sourceText: string, languageVersion: ScriptTarget, setParentNodes = false, scriptKind?: ScriptKind): SourceFile { - const start = new Date().getTime(); + const start = performance.mark(); const result = Parser.parseSourceFile(fileName, sourceText, languageVersion, /*syntaxCursor*/ undefined, setParentNodes, scriptKind); - parseTime += new Date().getTime() - start; + performance.measure("parseTime", start); return result; } diff --git a/src/compiler/performance.ts b/src/compiler/performance.ts new file mode 100644 index 0000000000000..e309b7da1ac23 --- /dev/null +++ b/src/compiler/performance.ts @@ -0,0 +1,98 @@ +/*@internal*/ +namespace ts { + /** Performance measurements for the compiler. */ + export namespace performance { + declare const onProfilerEvent: { (markName: string): void; profiler: boolean; }; + declare const performance: { now?(): number } | undefined; + let profilerEvent: (markName: string) => void; + let markInternal: () => number; + let counters: Map; + let measures: Map; + + /** + * Emit a performance event if ts-profiler is connected. This is primarily used + * to generate heap snapshots. + * + * @param eventName A name for the event. + */ + export function emit(eventName: string) { + if (profilerEvent) { + profilerEvent(eventName); + } + } + + /** + * Increments a counter with the specified name. + * + * @param counterName The name of the counter. + */ + export function increment(counterName: string) { + if (counters) { + counters[counterName] = (getProperty(counters, counterName) || 0) + 1; + } + } + + /** + * Gets the value of the counter with the specified name. + * + * @param counterName The name of the counter. + */ + export function getCount(counterName: string) { + return counters && getProperty(counters, counterName) || 0; + } + + /** + * Marks the start of a performance measurement. + */ + export function mark() { + return measures ? markInternal() : 0; + } + + /** + * Adds a performance measurement with the specified name. + * + * @param measureName The name of the performance measurement. + * @param marker The timestamp of the starting mark. + */ + export function measure(measureName: string, marker: number) { + if (measures) { + measures[measureName] = (getProperty(measures, measureName) || 0) + (Date.now() - marker); + } + } + + /** + * Gets the total duration of all measurements with the supplied name. + * + * @param measureName The name of the measure whose durations should be accumulated. + */ + export function getDuration(measureName: string) { + return measures && getProperty(measures, measureName) || 0; + } + + /** Enables (and resets) performance measurements for the compiler. */ + export function enable() { + counters = { }; + measures = { + programTime: 0, + parseTime: 0, + bindTime: 0, + checkTime: 0, + emitTime: 0, + ioReadTime: 0, + ioWriteTime: 0, + }; + + profilerEvent = typeof onProfilerEvent === "function" && onProfilerEvent.profiler === true + ? onProfilerEvent + : undefined; + markInternal = performance && performance.now ? performance.now : Date.now ? Date.now : () => +(new Date()); + } + + /** Disables (and clears) performance measurements for the compiler. */ + export function disable() { + counters = undefined; + measures = undefined; + profilerEvent = undefined; + } + } +} \ No newline at end of file diff --git a/src/compiler/program.ts b/src/compiler/program.ts index 2e4492efa7b14..3bd4bd0c5cfe6 100644 --- a/src/compiler/program.ts +++ b/src/compiler/program.ts @@ -3,11 +3,6 @@ /// namespace ts { - /* @internal */ export let programTime = 0; - /* @internal */ export let emitTime = 0; - /* @internal */ export let ioReadTime = 0; - /* @internal */ export let ioWriteTime = 0; - /** The version of the TypeScript compiler release */ export const version = "2.0.0"; @@ -871,9 +866,9 @@ namespace ts { function getSourceFile(fileName: string, languageVersion: ScriptTarget, onError?: (message: string) => void): SourceFile { let text: string; try { - const start = new Date().getTime(); + const start = performance.mark(); text = sys.readFile(fileName, options.charset); - ioReadTime += new Date().getTime() - start; + performance.measure("ioReadTime", start); } catch (e) { if (onError) { @@ -940,7 +935,7 @@ namespace ts { function writeFile(fileName: string, data: string, writeByteOrderMark: boolean, onError?: (message: string) => void) { try { - const start = new Date().getTime(); + const start = performance.mark(); ensureDirectoriesExist(getDirectoryPath(normalizePath(fileName))); if (isWatchSet(options) && sys.createHash && sys.getModifiedTime) { @@ -950,7 +945,7 @@ namespace ts { sys.writeFile(fileName, data, writeByteOrderMark); } - ioWriteTime += new Date().getTime() - start; + performance.measure("ioWriteTime", start); } catch (e) { if (onError) { @@ -1104,7 +1099,7 @@ namespace ts { // Track source files that are JavaScript files found by searching under node_modules, as these shouldn't be compiled. const sourceFilesFoundSearchingNodeModules: Map = {}; - const start = new Date().getTime(); + const start = performance.mark(); host = host || createCompilerHost(options); @@ -1203,7 +1198,7 @@ namespace ts { verifyCompilerOptions(); - programTime += new Date().getTime() - start; + performance.measure("programTime", start); return program; @@ -1446,14 +1441,14 @@ namespace ts { // checked is to not pass the file to getEmitResolver. const emitResolver = getDiagnosticsProducingTypeChecker().getEmitResolver((options.outFile || options.out) ? undefined : sourceFile); - const start = new Date().getTime(); + const start = performance.mark(); const emitResult = emitFiles( emitResolver, getEmitHost(writeFileCallback), sourceFile); - emitTime += new Date().getTime() - start; + performance.measure("emitTime", start); return emitResult; } diff --git a/src/compiler/tsc.ts b/src/compiler/tsc.ts index e25ae37e21fa9..db59e962b315e 100644 --- a/src/compiler/tsc.ts +++ b/src/compiler/tsc.ts @@ -554,12 +554,7 @@ namespace ts { } function compile(fileNames: string[], compilerOptions: CompilerOptions, compilerHost: CompilerHost) { - ioReadTime = 0; - ioWriteTime = 0; - programTime = 0; - bindTime = 0; - checkTime = 0; - emitTime = 0; + if (compilerOptions.diagnostics) performance.enable(); const program = createProgram(fileNames, compilerOptions, compilerHost); const exitStatus = compileProgram(); @@ -587,13 +582,13 @@ 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", ioReadTime); - reportTimeStatistic("I/O write", ioWriteTime); - reportTimeStatistic("Parse time", programTime); - reportTimeStatistic("Bind time", bindTime); - reportTimeStatistic("Check time", checkTime); - reportTimeStatistic("Emit time", emitTime); - reportTimeStatistic("Total time", programTime + bindTime + checkTime + emitTime); + reportTimeStatistic("I/O read", performance.getDuration("ioReadTime")); + reportTimeStatistic("I/O write", performance.getDuration("ioWriteTime")); + reportTimeStatistic("Parse time", performance.getDuration("parseTime")); + reportTimeStatistic("Bind time", performance.getDuration("bindTime")); + reportTimeStatistic("Check time", performance.getDuration("checkTime")); + reportTimeStatistic("Emit time", performance.getDuration("emitTime")); + reportTimeStatistic("Total time", performance.getDuration("programTime") + performance.getDuration("bindTime") + performance.getDuration("checkTime") + performance.getDuration("emitTime")); } return { program, exitStatus }; diff --git a/src/compiler/tsconfig.json b/src/compiler/tsconfig.json index 76308c2cba4ff..0fa8b0c0dac36 100644 --- a/src/compiler/tsconfig.json +++ b/src/compiler/tsconfig.json @@ -10,6 +10,7 @@ }, "files": [ "core.ts", + "performance.ts", "sys.ts", "types.ts", "scanner.ts", From 6eb0d715188d3fabaa1c7078bd356b1d75f5fffb Mon Sep 17 00:00:00 2001 From: Wesley Wigham Date: Tue, 5 Jul 2016 17:03:19 -0700 Subject: [PATCH 2/4] Use friendlier names, add compiler option to print all recorded measures --- src/compiler/binder.ts | 2 +- src/compiler/checker.ts | 2 +- src/compiler/commandLineParser.ts | 4 ++++ src/compiler/parser.ts | 2 +- src/compiler/performance.ts | 9 ++++++++ src/compiler/program.ts | 8 +++---- src/compiler/sourcemap.ts | 4 ++++ src/compiler/tsc.ts | 38 ++++++++++++++++++++----------- src/compiler/types.ts | 1 + 9 files changed, 50 insertions(+), 20 deletions(-) diff --git a/src/compiler/binder.ts b/src/compiler/binder.ts index ff9c0a29fe45b..6059cd1f86ab1 100644 --- a/src/compiler/binder.ts +++ b/src/compiler/binder.ts @@ -91,7 +91,7 @@ namespace ts { export function bindSourceFile(file: SourceFile, options: CompilerOptions) { const start = performance.mark(); binder(file, options); - performance.measure("bindTime", start); + performance.measure("Bind", start); } function createBinder(): (file: SourceFile, options: CompilerOptions) => void { diff --git a/src/compiler/checker.ts b/src/compiler/checker.ts index 2e4ed64a21824..84250f9e63451 100644 --- a/src/compiler/checker.ts +++ b/src/compiler/checker.ts @@ -17013,7 +17013,7 @@ namespace ts { checkSourceFileWorker(node); - performance.measure("checkTime", start); + performance.measure("Check", start); } // Fully type check a source file and collect the relevant diagnostics. diff --git a/src/compiler/commandLineParser.ts b/src/compiler/commandLineParser.ts index 7b2aedb5d3ddf..d1da3c4b452b9 100644 --- a/src/compiler/commandLineParser.ts +++ b/src/compiler/commandLineParser.ts @@ -27,6 +27,10 @@ namespace ts { name: "diagnostics", type: "boolean", }, + { + name: "extendedDiagnostics", + type: "boolean", + }, { name: "emitBOM", type: "boolean" diff --git a/src/compiler/parser.ts b/src/compiler/parser.ts index e1f37139de3b3..204278f804c39 100644 --- a/src/compiler/parser.ts +++ b/src/compiler/parser.ts @@ -414,7 +414,7 @@ namespace ts { const start = performance.mark(); const result = Parser.parseSourceFile(fileName, sourceText, languageVersion, /*syntaxCursor*/ undefined, setParentNodes, scriptKind); - performance.measure("parseTime", start); + performance.measure("Parse", start); return result; } diff --git a/src/compiler/performance.ts b/src/compiler/performance.ts index e309b7da1ac23..bc673d825c923 100644 --- a/src/compiler/performance.ts +++ b/src/compiler/performance.ts @@ -60,6 +60,15 @@ namespace ts { } } + /** + * Iterate over each measure, performing some action + * + * @param cb The action to perform for each measure + */ + export function forEachMeasure(cb: (measureName: string, duration: number) => void) { + return forEachKey(measures, key => cb(key, measures[key])); + } + /** * Gets the total duration of all measurements with the supplied name. * diff --git a/src/compiler/program.ts b/src/compiler/program.ts index 3bd4bd0c5cfe6..dfac47c5fc18a 100644 --- a/src/compiler/program.ts +++ b/src/compiler/program.ts @@ -868,7 +868,7 @@ namespace ts { try { const start = performance.mark(); text = sys.readFile(fileName, options.charset); - performance.measure("ioReadTime", start); + performance.measure("I/O Read", start); } catch (e) { if (onError) { @@ -945,7 +945,7 @@ namespace ts { sys.writeFile(fileName, data, writeByteOrderMark); } - performance.measure("ioWriteTime", start); + performance.measure("I/O Write", start); } catch (e) { if (onError) { @@ -1198,7 +1198,7 @@ namespace ts { verifyCompilerOptions(); - performance.measure("programTime", start); + performance.measure("Program", start); return program; @@ -1448,7 +1448,7 @@ namespace ts { getEmitHost(writeFileCallback), sourceFile); - performance.measure("emitTime", start); + performance.measure("Emit", start); return emitResult; } diff --git a/src/compiler/sourcemap.ts b/src/compiler/sourcemap.ts index cf7c3d1eaaea7..2d8c36a3d0252 100644 --- a/src/compiler/sourcemap.ts +++ b/src/compiler/sourcemap.ts @@ -240,6 +240,8 @@ namespace ts { return; } + const start = performance.mark(); + const sourceLinePos = getLineAndCharacterOfPosition(currentSourceFile, pos); // Convert the location to be one-based. @@ -279,6 +281,8 @@ namespace ts { } updateLastEncodedAndRecordedSpans(); + + performance.measure("Source Map", start); } function getStartPos(range: TextRange) { diff --git a/src/compiler/tsc.ts b/src/compiler/tsc.ts index db59e962b315e..face11783f9a5 100644 --- a/src/compiler/tsc.ts +++ b/src/compiler/tsc.ts @@ -554,7 +554,8 @@ namespace ts { } function compile(fileNames: string[], compilerOptions: CompilerOptions, compilerHost: CompilerHost) { - if (compilerOptions.diagnostics) performance.enable(); + const hasDiagnostics = compilerOptions.diagnostics || compilerOptions.extendedDiagnostics; + if (hasDiagnostics) performance.enable(); const program = createProgram(fileNames, compilerOptions, compilerHost); const exitStatus = compileProgram(); @@ -565,7 +566,7 @@ namespace ts { }); } - if (compilerOptions.diagnostics) { + if (hasDiagnostics) { const memoryUsed = sys.getMemoryUsage ? sys.getMemoryUsage() : -1; reportCountStatistic("Files", program.getSourceFiles().length); reportCountStatistic("Lines", countLines(program)); @@ -578,17 +579,28 @@ namespace ts { reportStatisticalValue("Memory used", Math.round(memoryUsed / 1000) + "K"); } - // Individual component times. - // 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("ioReadTime")); - reportTimeStatistic("I/O write", performance.getDuration("ioWriteTime")); - reportTimeStatistic("Parse time", performance.getDuration("parseTime")); - reportTimeStatistic("Bind time", performance.getDuration("bindTime")); - reportTimeStatistic("Check time", performance.getDuration("checkTime")); - reportTimeStatistic("Emit time", performance.getDuration("emitTime")); - reportTimeStatistic("Total time", performance.getDuration("programTime") + performance.getDuration("bindTime") + performance.getDuration("checkTime") + performance.getDuration("emitTime")); + if (compilerOptions.extendedDiagnostics) { + performance.forEachMeasure((name, duration) => reportTimeStatistic(`${name} time`, duration)); + } + else { + // Individual component times. + // 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")); + const programTime = performance.getDuration("Program"); + const bindTime = performance.getDuration("Bind"); + const checkTime = performance.getDuration("Check"); + const emitTime = performance.getDuration("Emit"); + reportTimeStatistic("Parse time", programTime); + reportTimeStatistic("Bind time", bindTime); + reportTimeStatistic("Check time", checkTime); + reportTimeStatistic("Emit time", emitTime); + reportTimeStatistic("Total time", programTime + bindTime + checkTime + emitTime); + } + + performance.disable(); } return { program, exitStatus }; diff --git a/src/compiler/types.ts b/src/compiler/types.ts index 3a3a937ade77b..f025d0f47c5ec 100644 --- a/src/compiler/types.ts +++ b/src/compiler/types.ts @@ -2535,6 +2535,7 @@ namespace ts { declaration?: boolean; declarationDir?: string; /* @internal */ diagnostics?: boolean; + /* @internal */ extendedDiagnostics?: boolean; disableSizeLimit?: boolean; emitBOM?: boolean; emitDecoratorMetadata?: boolean; From e94ded91bbeba01d09dec471031f5b934e866b08 Mon Sep 17 00:00:00 2001 From: Wesley Wigham Date: Tue, 5 Jul 2016 17:04:01 -0700 Subject: [PATCH 3/4] Always print total time --- src/compiler/performance.ts | 14 +++++++------- src/compiler/tsc.ts | 10 +++++----- 2 files changed, 12 insertions(+), 12 deletions(-) diff --git a/src/compiler/performance.ts b/src/compiler/performance.ts index bc673d825c923..863ea7e76eb86 100644 --- a/src/compiler/performance.ts +++ b/src/compiler/performance.ts @@ -82,13 +82,13 @@ namespace ts { export function enable() { counters = { }; measures = { - programTime: 0, - parseTime: 0, - bindTime: 0, - checkTime: 0, - emitTime: 0, - ioReadTime: 0, - ioWriteTime: 0, + "I/O Read": 0, + "I/O Write": 0, + "Program": 0, + "Parse": 0, + "Bind": 0, + "Check": 0, + "Emit": 0, }; profilerEvent = typeof onProfilerEvent === "function" && onProfilerEvent.profiler === true diff --git a/src/compiler/tsc.ts b/src/compiler/tsc.ts index face11783f9a5..5468f5cf2bf54 100644 --- a/src/compiler/tsc.ts +++ b/src/compiler/tsc.ts @@ -579,6 +579,10 @@ namespace ts { reportStatisticalValue("Memory used", Math.round(memoryUsed / 1000) + "K"); } + const programTime = performance.getDuration("Program"); + const bindTime = performance.getDuration("Bind"); + const checkTime = performance.getDuration("Check"); + const emitTime = performance.getDuration("Emit"); if (compilerOptions.extendedDiagnostics) { performance.forEachMeasure((name, duration) => reportTimeStatistic(`${name} time`, duration)); } @@ -589,16 +593,12 @@ namespace ts { // 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")); - const programTime = performance.getDuration("Program"); - const bindTime = performance.getDuration("Bind"); - const checkTime = performance.getDuration("Check"); - const emitTime = performance.getDuration("Emit"); reportTimeStatistic("Parse time", programTime); reportTimeStatistic("Bind time", bindTime); reportTimeStatistic("Check time", checkTime); reportTimeStatistic("Emit time", emitTime); - reportTimeStatistic("Total time", programTime + bindTime + checkTime + emitTime); } + reportTimeStatistic("Total time", programTime + bindTime + checkTime + emitTime); performance.disable(); } From 005f209ba06b78f0331ade297eaa7ded575eba44 Mon Sep 17 00:00:00 2001 From: Wesley Wigham Date: Mon, 11 Jul 2016 12:40:18 -0700 Subject: [PATCH 4/4] + -> .getTime --- src/compiler/performance.ts | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/src/compiler/performance.ts b/src/compiler/performance.ts index 863ea7e76eb86..f40b191a1a591 100644 --- a/src/compiler/performance.ts +++ b/src/compiler/performance.ts @@ -94,7 +94,7 @@ namespace ts { profilerEvent = typeof onProfilerEvent === "function" && onProfilerEvent.profiler === true ? onProfilerEvent : undefined; - markInternal = performance && performance.now ? performance.now : Date.now ? Date.now : () => +(new Date()); + markInternal = performance && performance.now ? performance.now : Date.now ? Date.now : () => new Date().getTime(); } /** Disables (and clears) performance measurements for the compiler. */