From fd7ed33253a7811b754113d3182df0be9065655e Mon Sep 17 00:00:00 2001 From: Sheetal Nandi Date: Fri, 24 Jan 2020 12:36:19 -0800 Subject: [PATCH] More logging for performance --- src/compiler/utilities.ts | 125 +++++++++++++++++++ src/executeCommandLine/executeCommandLine.ts | 102 --------------- src/server/editorServices.ts | 4 +- src/server/project.ts | 15 +++ src/server/session.ts | 2 + src/services/documentRegistry.ts | 9 +- 6 files changed, 153 insertions(+), 104 deletions(-) diff --git a/src/compiler/utilities.ts b/src/compiler/utilities.ts index 7fa1c520643..a2dc465f79b 100644 --- a/src/compiler/utilities.ts +++ b/src/compiler/utilities.ts @@ -6240,4 +6240,129 @@ namespace ts { const heritageClause = tryCast(node.parent.parent, isHeritageClause) ?? tryCast(node.parent.parent?.parent, isHeritageClause); return heritageClause?.token === SyntaxKind.ImplementsKeyword || heritageClause?.parent.kind === SyntaxKind.InterfaceDeclaration; } + + interface Statistic { + name: string; + value: string; + } + + function countLines(program: Program): number { + let count = 0; + forEach(program.getSourceFiles(), file => { + count += getLineStarts(file).length; + }); + return count; + } + + function padLeft(s: string, length: number) { + while (s.length < length) { + s = " " + s; + } + return s; + } + + function padRight(s: string, length: number) { + while (s.length < length) { + s = s + " "; + } + + return s; + } + + export interface StatisticsHost { + getMemoryUsage?(): number; + write(s: string): void; + newLine: string; + system: System; + } + + export function enableStatistics(host: StatisticsHost | System, compilerOptions: CompilerOptions) { + if (canReportDiagnostics(host, compilerOptions)) { + performance.enable(); + } + } + + export function reportStatistics(host: StatisticsHost | System, program: Program) { + let statistics: Statistic[]; + const compilerOptions = program.getCompilerOptions(); + if (canReportDiagnostics(host, compilerOptions)) { + statistics = []; + const memoryUsed = host.getMemoryUsage ? host.getMemoryUsage() : -1; + reportCountStatistic("Files", program.getSourceFiles().length); + reportCountStatistic("Lines", countLines(program)); + reportCountStatistic("Nodes", program.getNodeCount()); + reportCountStatistic("Identifiers", program.getIdentifierCount()); + reportCountStatistic("Symbols", program.getSymbolCount()); + reportCountStatistic("Types", program.getTypeCount()); + reportCountStatistic("Instantiations", program.getInstantiationCount()); + + if (memoryUsed >= 0) { + 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) { + const caches = program.getRelationCacheSizes(); + reportCountStatistic("Assignability cache size", caches.assignable); + reportCountStatistic("Identity cache size", caches.identity); + reportCountStatistic("Subtype cache size", caches.subtype); + reportCountStatistic("Strict subtype cache size", caches.strictSubtype); + 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")); + reportTimeStatistic("Parse time", programTime); + reportTimeStatistic("Bind time", bindTime); + reportTimeStatistic("Check time", checkTime); + reportTimeStatistic("Emit time", emitTime); + } + reportTimeStatistic("Total time", programTime + bindTime + checkTime + emitTime); + reportStatistics(); + + 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) { + host.write(padRight(name + ":", nameSize + 2) + padLeft(value.toString(), valueSize) + host.newLine); + } + } + + function reportStatisticalValue(name: string, value: string) { + statistics.push({ name, value }); + } + + function reportCountStatistic(name: string, count: number) { + reportStatisticalValue(name, "" + count); + } + + function reportTimeStatistic(name: string, time: number) { + reportStatisticalValue(name, (time / 1000).toFixed(2) + "s"); + } + } + + function canReportDiagnostics(host: StatisticsHost | System, compilerOptions: CompilerOptions) { + return (host === sys || (host as StatisticsHost).system === sys) && + (compilerOptions.diagnostics || compilerOptions.extendedDiagnostics); + } } diff --git a/src/executeCommandLine/executeCommandLine.ts b/src/executeCommandLine/executeCommandLine.ts index e66b55d9b55..583b36ec171 100644 --- a/src/executeCommandLine/executeCommandLine.ts +++ b/src/executeCommandLine/executeCommandLine.ts @@ -1,17 +1,4 @@ namespace ts { - interface Statistic { - name: string; - value: string; - } - - function countLines(program: Program): number { - let count = 0; - forEach(program.getSourceFiles(), file => { - count += getLineStarts(file).length; - }); - return count; - } - function updateReportDiagnostic( sys: System, existing: DiagnosticReporter, @@ -617,95 +604,6 @@ namespace ts { return createWatchProgram(watchCompilerHost); } - function canReportDiagnostics(system: System, compilerOptions: CompilerOptions) { - return system === sys && (compilerOptions.diagnostics || compilerOptions.extendedDiagnostics); - } - - function enableStatistics(sys: System, compilerOptions: CompilerOptions) { - if (canReportDiagnostics(sys, compilerOptions)) { - performance.enable(); - } - } - - function reportStatistics(sys: System, program: Program) { - let statistics: Statistic[]; - const compilerOptions = program.getCompilerOptions(); - if (canReportDiagnostics(sys, compilerOptions)) { - statistics = []; - const memoryUsed = sys.getMemoryUsage ? sys.getMemoryUsage() : -1; - reportCountStatistic("Files", program.getSourceFiles().length); - reportCountStatistic("Lines", countLines(program)); - reportCountStatistic("Nodes", program.getNodeCount()); - reportCountStatistic("Identifiers", program.getIdentifierCount()); - reportCountStatistic("Symbols", program.getSymbolCount()); - reportCountStatistic("Types", program.getTypeCount()); - reportCountStatistic("Instantiations", program.getInstantiationCount()); - - if (memoryUsed >= 0) { - 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) { - const caches = program.getRelationCacheSizes(); - reportCountStatistic("Assignability cache size", caches.assignable); - reportCountStatistic("Identity cache size", caches.identity); - reportCountStatistic("Subtype cache size", caches.subtype); - reportCountStatistic("Strict subtype cache size", caches.strictSubtype); - 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")); - reportTimeStatistic("Parse time", programTime); - reportTimeStatistic("Bind time", bindTime); - reportTimeStatistic("Check time", checkTime); - reportTimeStatistic("Emit time", emitTime); - } - reportTimeStatistic("Total time", programTime + bindTime + checkTime + emitTime); - reportStatistics(); - - 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 reportCountStatistic(name: string, count: number) { - reportStatisticalValue(name, "" + count); - } - - function reportTimeStatistic(name: string, time: number) { - reportStatisticalValue(name, (time / 1000).toFixed(2) + "s"); - } - } - function writeConfigFile( sys: System, reportDiagnostic: DiagnosticReporter, diff --git a/src/server/editorServices.ts b/src/server/editorServices.ts index 47ab9e6a12f..af3cbb6f496 100644 --- a/src/server/editorServices.ts +++ b/src/server/editorServices.ts @@ -668,11 +668,11 @@ namespace ts.server { extraFileExtensions: [], }; - this.documentRegistry = createDocumentRegistryInternal(this.host.useCaseSensitiveFileNames, this.currentDirectory, this); const watchLogLevel = this.logger.hasLevel(LogLevel.verbose) ? WatchLogLevel.Verbose : this.logger.loggingEnabled() ? WatchLogLevel.TriggerOnly : WatchLogLevel.None; const log: (s: string) => void = watchLogLevel !== WatchLogLevel.None ? (s => this.logger.info(s)) : noop; this.watchFactory = getWatchFactory(watchLogLevel, log, getDetailWatchInfo); + this.documentRegistry = createDocumentRegistryInternal(this.host.useCaseSensitiveFileNames, this.currentDirectory, this); } toPath(fileName: string) { @@ -1397,6 +1397,7 @@ namespace ts.server { } private deleteScriptInfo(info: ScriptInfo) { + this.logger.info(`Deleting script info: ${info.path}`); this.filenameToScriptInfo.delete(info.path); this.filenameToScriptInfoVersion.set(info.path, info.getVersion()); const realpath = info.getRealpathIfDifferent(); @@ -2404,6 +2405,7 @@ namespace ts.server { return; } info = new ScriptInfo(this.host, fileName, scriptKind!, !!hasMixedContent, path, this.filenameToScriptInfoVersion.get(path)); // TODO: GH#18217 + this.logger.info(`Created script info: ${info.path}`); this.filenameToScriptInfo.set(info.path, info); this.filenameToScriptInfoVersion.delete(info.path); if (!openedByClient) { diff --git a/src/server/project.ts b/src/server/project.ts index 05f73e4f07c..2bcf019b477 100644 --- a/src/server/project.ts +++ b/src/server/project.ts @@ -247,6 +247,8 @@ namespace ts.server { /*@internal*/ private symlinks: ReadonlyMap | undefined; + private readonly statisticsHost: StatisticsHost; + /*@internal*/ constructor( /*@internal*/ readonly projectName: string, @@ -275,6 +277,7 @@ namespace ts.server { // If files are listed explicitly or allowJs is specified, allow all extensions this.compilerOptions.allowNonTsExtensions = true; } + this.compilerOptions.extendedDiagnostics = true; this.languageServiceEnabled = !projectService.syntaxOnly; @@ -291,6 +294,13 @@ namespace ts.server { this.realpath = customRealpath || (path => host.realpath!(path)); } + this.statisticsHost = { + newLine: "", + getMemoryUsage: maybeBind(host, host.getMemoryUsage), + write: s => this.writeLog(s), + system: host + }; + // Use the current directory as resolution root only if the project created using current directory string this.resolutionCache = createResolutionCache(this, currentDirectory && this.currentDirectory, /*logChangesWhenResolvingModule*/ true); this.languageService = createLanguageService(this, this.documentRegistry, projectService.syntaxOnly); @@ -987,6 +997,7 @@ namespace ts.server { const oldProgram = this.program; Debug.assert(!this.isClosed(), "Called update graph worker of closed project"); this.writeLog(`Starting updateGraphWorker: Project: ${this.getProjectName()}`); + enableStatistics(this.statisticsHost, this.getCompilationSettings()); const start = timestamp(); this.hasInvalidatedResolution = this.resolutionCache.createHasInvalidatedResolution(); this.resolutionCache.startCachingPerDirectoryResolution(); @@ -1110,6 +1121,9 @@ namespace ts.server { else if (this.program !== oldProgram) { this.writeLog(`Different program with same set of files:: oldProgram.structureIsReused:: ${oldProgram && oldProgram.structureIsReused}`); } + if (this.program) { + reportStatistics(this.statisticsHost, this.program); + } return hasNewProgram; } @@ -1303,6 +1317,7 @@ namespace ts.server { this.lastCachedUnresolvedImportsList = undefined; this.resolutionCache.clear(); } + this.compilerOptions.extendedDiagnostics = true; this.markAsDirty(); } } diff --git a/src/server/session.ts b/src/server/session.ts index d38e49adc14..bf4623276f9 100644 --- a/src/server/session.ts +++ b/src/server/session.ts @@ -2623,9 +2623,11 @@ namespace ts.server { public executeWithRequestId(requestId: number, f: () => T) { try { this.setCurrentRequest(requestId); + this.logger.info(`Starting request: ${requestId}`); return f(); } finally { + this.logger.info(`Finished request: ${requestId}`); this.resetCurrentRequest(requestId); } } diff --git a/src/services/documentRegistry.ts b/src/services/documentRegistry.ts index decb66b5340..ec5752e553a 100644 --- a/src/services/documentRegistry.ts +++ b/src/services/documentRegistry.ts @@ -115,7 +115,7 @@ namespace ts { } /*@internal*/ - export function createDocumentRegistryInternal(useCaseSensitiveFileNames?: boolean, currentDirectory = "", externalCache?: ExternalDocumentCache): DocumentRegistry { + export function createDocumentRegistryInternal(useCaseSensitiveFileNames?: boolean, currentDirectory = "", externalCache?: ExternalDocumentCache, log: (s: string) => void = noop): DocumentRegistry { // Maps from compiler setting target (ES3, ES5, etc.) to all the cached documents we have // for those settings. const buckets = createMap>(); @@ -170,10 +170,12 @@ namespace ts { acquiring: boolean, scriptKind?: ScriptKind): SourceFile { + const start = timestamp(); const bucket = getOrUpdate>(buckets, key, createMap); let entry = bucket.get(path); const scriptTarget = scriptKind === ScriptKind.JSON ? ScriptTarget.JSON : compilationSettings.target || ScriptTarget.ES5; if (!entry && externalCache) { + log(`Creating document ${path}`); const sourceFile = externalCache.getDocument(key, path); if (sourceFile) { Debug.assert(acquiring); @@ -217,9 +219,12 @@ namespace ts { if (acquiring) { entry.languageServiceRefCount++; } + log(`${acquiring ? "acquiring" : "updating"} document ${path}`); } Debug.assert(entry.languageServiceRefCount !== 0); + const elapsed = timestamp() - start; + log(`${acquiring ? "acquiring" : "updating"} document ${path} elapsed: ${elapsed}ms`); return entry.sourceFile; } @@ -233,9 +238,11 @@ namespace ts { const bucket = Debug.checkDefined(buckets.get(key)); const entry = bucket.get(path)!; entry.languageServiceRefCount--; + log(`Releasing document: ${path}`); Debug.assert(entry.languageServiceRefCount >= 0); if (entry.languageServiceRefCount === 0) { + log(`Deleting document: ${path}`); bucket.delete(path); } }