diff --git a/package.json b/package.json index 2f1b44cbb0..a90be2f813 100644 --- a/package.json +++ b/package.json @@ -42,6 +42,7 @@ "@types/gulp-sourcemaps": "0.0.32", "@types/jake": "latest", "@types/merge2": "latest", + "@types/microsoft__typescript-etw": "latest", "@types/minimatch": "latest", "@types/minimist": "latest", "@types/mkdirp": "latest", @@ -109,7 +110,8 @@ "browser": { "fs": false, "os": false, - "path": false + "path": false, + "@microsoft/typescript-etw": false }, "dependencies": {} } diff --git a/src/compiler/binder.ts b/src/compiler/binder.ts index 3445d26e4c..25c275fe96 100644 --- a/src/compiler/binder.ts +++ b/src/compiler/binder.ts @@ -106,7 +106,9 @@ namespace ts { export function bindSourceFile(file: SourceFile, options: CompilerOptions) { performance.mark("beforeBind"); + perfLogger.logStartBindFile("" + file.fileName); binder(file, options); + perfLogger.logStopBindFile(); performance.mark("afterBind"); performance.measure("Bind", "beforeBind", "afterBind"); } diff --git a/src/compiler/moduleNameResolver.ts b/src/compiler/moduleNameResolver.ts index 94f835caff..98e82a6843 100644 --- a/src/compiler/moduleNameResolver.ts +++ b/src/compiler/moduleNameResolver.ts @@ -665,6 +665,7 @@ namespace ts { } } + perfLogger.logStartResolveModule(moduleName /* , containingFile, ModuleResolutionKind[moduleResolution]*/); switch (moduleResolution) { case ModuleResolutionKind.NodeJs: result = nodeModuleNameResolver(moduleName, containingFile, compilerOptions, host, cache, redirectedReference); @@ -675,6 +676,8 @@ namespace ts { default: return Debug.fail(`Unexpected moduleResolution: ${moduleResolution}`); } + if (result && result.resolvedModule) perfLogger.logInfoEvent(`Module "${moduleName}" resolved to "${result.resolvedModule.resolvedFileName}"`); + perfLogger.logStopResolveModule((result && result.resolvedModule) ? "" + result.resolvedModule.resolvedFileName : "null"); if (perFolderCache) { perFolderCache.set(moduleName, result); diff --git a/src/compiler/parser.ts b/src/compiler/parser.ts index e87701cddb..4515af1989 100644 --- a/src/compiler/parser.ts +++ b/src/compiler/parser.ts @@ -512,12 +512,16 @@ namespace ts { export function createSourceFile(fileName: string, sourceText: string, languageVersion: ScriptTarget, setParentNodes = false, scriptKind?: ScriptKind): SourceFile { performance.mark("beforeParse"); let result: SourceFile; + + perfLogger.logStartParseSourceFile(fileName); if (languageVersion === ScriptTarget.JSON) { result = Parser.parseSourceFile(fileName, sourceText, languageVersion, /*syntaxCursor*/ undefined, setParentNodes, ScriptKind.JSON); } else { result = Parser.parseSourceFile(fileName, sourceText, languageVersion, /*syntaxCursor*/ undefined, setParentNodes, scriptKind); } + perfLogger.logStopParseSourceFile(); + performance.mark("afterParse"); performance.measure("Parse", "beforeParse", "afterParse"); return result; diff --git a/src/compiler/perfLogger.ts b/src/compiler/perfLogger.ts new file mode 100644 index 0000000000..974e231d15 --- /dev/null +++ b/src/compiler/perfLogger.ts @@ -0,0 +1,43 @@ +/* @internal */ +namespace ts { + type PerfLogger = typeof import("@microsoft/typescript-etw"); // tslint:disable-line:no-implicit-dependencies + const nullLogger: PerfLogger = { + logEvent: noop, + logErrEvent: noop, + logPerfEvent: noop, + logInfoEvent: noop, + logStartCommand: noop, + logStopCommand: noop, + logStartUpdateProgram: noop, + logStopUpdateProgram: noop, + logStartUpdateGraph: noop, + logStopUpdateGraph: noop, + logStartResolveModule: noop, + logStopResolveModule: noop, + logStartParseSourceFile: noop, + logStopParseSourceFile: noop, + logStartReadFile: noop, + logStopReadFile: noop, + logStartBindFile: noop, + logStopBindFile: noop, + logStartScheduledOperation: noop, + logStopScheduledOperation: noop, + }; + + // Load optional module to enable Event Tracing for Windows + // See https://github.com/microsoft/typescript-etw for more information + let etwModule; + try { + // require() will throw an exception if the module is not installed + // It may also return undefined if not installed properly + etwModule = require("@microsoft/typescript-etw"); // tslint:disable-line:no-implicit-dependencies + } + catch (e) { + etwModule = undefined; + } + + /** Performance logger that will generate ETW events if possible */ + export const perfLogger: PerfLogger = etwModule ? etwModule : nullLogger; + + perfLogger.logInfoEvent(`Starting TypeScript v${versionMajorMinor} with command line: ${JSON.stringify(process.argv)}`); +} diff --git a/src/compiler/sys.ts b/src/compiler/sys.ts index 50080e0da7..583aaad3cd 100644 --- a/src/compiler/sys.ts +++ b/src/compiler/sys.ts @@ -1134,7 +1134,7 @@ namespace ts { return (directoryName, callback) => fsWatchFile(directoryName, () => callback(directoryName), PollingInterval.Medium); } - function readFile(fileName: string, _encoding?: string): string | undefined { + function readFileWorker(fileName: string, _encoding?: string): string | undefined { if (!fileExists(fileName)) { return undefined; } @@ -1163,7 +1163,15 @@ namespace ts { return buffer.toString("utf8"); } + function readFile(fileName: string, _encoding?: string): string | undefined { + perfLogger.logStartReadFile(fileName); + const file = readFileWorker(fileName, _encoding); + perfLogger.logStopReadFile(); + return file; + } + function writeFile(fileName: string, data: string, writeByteOrderMark?: boolean): void { + perfLogger.logEvent("WriteFile: " + fileName); // If a BOM is required, emit one if (writeByteOrderMark) { data = byteOrderMarkIndicator + data; @@ -1183,6 +1191,7 @@ namespace ts { } function getAccessibleFileSystemEntries(path: string): FileSystemEntries { + perfLogger.logEvent("ReadDir: " + (path || ".")); try { const entries = _fs.readdirSync(path || ".").sort(); const files: string[] = []; @@ -1244,6 +1253,7 @@ namespace ts { } function getDirectories(path: string): string[] { + perfLogger.logEvent("ReadDir: " + path); return filter(_fs.readdirSync(path), dir => fileSystemEntryExists(combinePaths(path, dir), FileSystemEntryKind.Directory)); } diff --git a/src/compiler/tsconfig.json b/src/compiler/tsconfig.json index f5e16b0d12..c90c6f35b3 100644 --- a/src/compiler/tsconfig.json +++ b/src/compiler/tsconfig.json @@ -10,6 +10,7 @@ "core.ts", "debug.ts", "performance.ts", + "perfLogger.ts", "semver.ts", "types.ts", diff --git a/src/compiler/watch.ts b/src/compiler/watch.ts index dad4b8f67c..7e2e9430f7 100644 --- a/src/compiler/watch.ts +++ b/src/compiler/watch.ts @@ -1005,13 +1005,19 @@ namespace ts { switch (reloadLevel) { case ConfigFileProgramReloadLevel.Partial: - return reloadFileNamesFromConfigFile(); + perfLogger.logStartUpdateProgram("PartialConfigReload"); + reloadFileNamesFromConfigFile(); + break; case ConfigFileProgramReloadLevel.Full: - return reloadConfigFile(); + perfLogger.logStartUpdateProgram("FullConfigReload"); + reloadConfigFile(); + break; default: + perfLogger.logStartUpdateProgram("SynchronizeProgram"); synchronizeProgram(); - return; + break; } + perfLogger.logStopUpdateProgram("Done"); } function reloadFileNamesFromConfigFile() { diff --git a/src/server/project.ts b/src/server/project.ts index 579ae4d932..91ac212ea1 100644 --- a/src/server/project.ts +++ b/src/server/project.ts @@ -851,6 +851,7 @@ namespace ts.server { * @returns: true if set of files in the project stays the same and false - otherwise. */ updateGraph(): boolean { + perfLogger.logStartUpdateGraph(); this.resolutionCache.startRecordingFilesWithChangedResolutions(); const hasNewProgram = this.updateGraphWorker(); @@ -886,6 +887,7 @@ namespace ts.server { if (hasNewProgram) { this.projectProgramVersion++; } + perfLogger.logStopUpdateGraph(); return !hasNewProgram; } diff --git a/src/server/session.ts b/src/server/session.ts index d663ca0924..4ae5282a74 100644 --- a/src/server/session.ts +++ b/src/server/session.ts @@ -731,7 +731,9 @@ namespace ts.server { } return; } - this.host.write(formatMessage(msg, this.logger, this.byteLength, this.host.newLine)); + const msgText = formatMessage(msg, this.logger, this.byteLength, this.host.newLine); + perfLogger.logEvent(`Response message size: ${msgText.length}`); + this.host.write(msgText); } public event(body: T, eventName: string): void { @@ -2509,6 +2511,8 @@ namespace ts.server { try { request = JSON.parse(message); relevantFile = request.arguments && (request as protocol.FileRequest).arguments.file ? (request as protocol.FileRequest).arguments : undefined; + + perfLogger.logStartCommand("" + request.command, message.substring(0, 100)); const { response, responseRequired } = this.executeCommand(request); if (this.logger.hasLevel(LogLevel.requestTime)) { @@ -2521,6 +2525,8 @@ namespace ts.server { } } + // Note: Log before writing the response, else the editor can complete its activity before the server does + perfLogger.logStopCommand("" + request.command, "Success"); if (response) { this.doOutput(response, request.command, request.seq, /*success*/ true); } @@ -2531,10 +2537,14 @@ namespace ts.server { catch (err) { if (err instanceof OperationCanceledException) { // Handle cancellation exceptions + perfLogger.logStopCommand("" + (request && request.command), "Canceled: " + err); this.doOutput({ canceled: true }, request!.command, request!.seq, /*success*/ true); return; } + this.logErrorWorker(err, message, relevantFile); + perfLogger.logStopCommand("" + (request && request.command), "Error: " + err); + this.doOutput( /*info*/ undefined, request ? request.command : CommandNames.Unknown, diff --git a/src/server/utilities.ts b/src/server/utilities.ts index fd38c6a432..d5e17520ce 100644 --- a/src/server/utilities.ts +++ b/src/server/utilities.ts @@ -150,11 +150,13 @@ namespace ts.server { } private static run(self: ThrottledOperations, operationId: string, cb: () => void) { + perfLogger.logStartScheduledOperation(operationId); self.pendingTimeouts.delete(operationId); if (self.logger) { self.logger.info(`Running: ${operationId}`); } cb(); + perfLogger.logStopScheduledOperation(); } } @@ -174,6 +176,7 @@ namespace ts.server { private static run(self: GcTimer) { self.timerId = undefined; + perfLogger.logStartScheduledOperation("GC collect"); const log = self.logger.hasLevel(LogLevel.requestTime); const before = log && self.host.getMemoryUsage!(); // TODO: GH#18217 @@ -182,6 +185,7 @@ namespace ts.server { const after = self.host.getMemoryUsage!(); // TODO: GH#18217 self.logger.perftrc(`GC::before ${before}, after ${after}`); } + perfLogger.logStopScheduledOperation(); } } diff --git a/src/tsserver/server.ts b/src/tsserver/server.ts index a9fbf2f3b6..13bba67664 100644 --- a/src/tsserver/server.ts +++ b/src/tsserver/server.ts @@ -180,6 +180,18 @@ namespace ts.server { } msg(s: string, type: Msg = Msg.Err) { + switch (type) { + case Msg.Info: + perfLogger.logInfoEvent(s); + break; + case Msg.Perf: + perfLogger.logPerfEvent(s); + break; + default: // Msg.Err + perfLogger.logErrEvent(s); + break; + } + if (!this.canWrite) return; s = `[${nowString()}] ${s}\n`;