Merge pull request #32612 from mrcrane/etw-logger

Use optional module "@microsoft/typescript-etw" for ETW logging

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": {}
 }

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");
     }

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);

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;

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)}`);
+}

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<string>(_fs.readdirSync(path), dir => fileSystemEntryExists(combinePaths(path, dir), FileSystemEntryKind.Directory));
             }
 

src/compiler/tsconfig.json

@@ -10,6 +10,7 @@
         "core.ts",
         "debug.ts",
         "performance.ts",
+        "perfLogger.ts",
         "semver.ts",
 
         "types.ts",

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

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;
         }
 

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<T extends object>(body: T, eventName: string): void {
@@ -2509,6 +2511,8 @@ namespace ts.server {
             try {
                 request = <protocol.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,

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();
         }
     }
 

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`;