Add tracing support to tsserver (#41374)

* Add tracing support to tsserver

Read the `TSS_TRACE` environment variable to determine which directory
trace files should be written to.

Notable changes from tsc tracing:
1) Drop all tracepoints that depend on type IDs
2) Write output to trace.PID.json
3) New, server-specific events (request/response, cancellation, etc)

* Drop try-finally blocks that aren't strictly necessary

* Fix lint error

* Trace background work (for diagnostics)

* Move try-finally blocks into session so tsc doesn't use them

* Add missing try-finally

* Use consistent capitalization

* Inline canPop call where underlying variable is available

* Clarify comments

* Include PID in build-mode file names

* Introduce more efficient popAll function

* Trace throwIfCancellationRequested rather than isCancellationRequested

* Remove unnecessary try-finally blocks

* Add a command-line argument for consistency with logging

* Fix rebase issues

* Address PR feedback

* Rename completionEvents to eventStack

* Drop assertStackEmpty as hard-to-maintain and marginally valuable

* Rename stepCancellation to stepCanceledEarly

* Rename stepEarlyCancellation to stepCanceled and use flag instead

* Check correct variable on exit

Author: amcasey

src/compiler/checker.ts

@@ -10973,7 +10973,7 @@ namespace ts {
                         // very high likelihood we're dealing with an infinite generic type that perpetually generates
                         // new type identities as we descend into it. We stop the recursion here and mark this type
                         // and the outer types as having circular constraints.
-                        tracing.instant(tracing.Phase.Check, "getImmediateBaseConstraint_DepthLimit", { typeId: t.id, originalTypeId: type.id, depth: constraintDepth });
+                        tracing.instant(tracing.Phase.CheckTypes, "getImmediateBaseConstraint_DepthLimit", { typeId: t.id, originalTypeId: type.id, depth: constraintDepth });
                         error(currentNode, Diagnostics.Type_instantiation_is_excessively_deep_and_possibly_infinite);
                         nonTerminating = true;
                         return t.immediateBaseConstraint = noConstraintType;
@@ -13083,7 +13083,7 @@ namespace ts {
                             // caps union types at 5000 unique literal types and 1000 unique object types.
                             const estimatedCount = (count / (len - i)) * len;
                             if (estimatedCount > (primitivesOnly ? 25000000 : 1000000)) {
-                                tracing.instant(tracing.Phase.Check, "removeSubtypes_DepthLimit", { typeIds: types.map(t => t.id) });
+                                tracing.instant(tracing.Phase.CheckTypes, "removeSubtypes_DepthLimit", { typeIds: types.map(t => t.id) });
                                 error(currentNode, Diagnostics.Expression_produces_a_union_type_that_is_too_complex_to_represent);
                                 return false;
                             }
@@ -13505,7 +13505,7 @@ namespace ts {
         function checkCrossProductUnion(types: readonly Type[]) {
             const size = reduceLeft(types, (n, t) => n * (t.flags & TypeFlags.Union ? (<UnionType>t).types.length : t.flags & TypeFlags.Never ? 0 : 1), 1);
             if (size >= 100000) {
-                tracing.instant(tracing.Phase.Check, "checkCrossProductUnion_DepthLimit", { typeIds: types.map(t => t.id), size });
+                tracing.instant(tracing.Phase.CheckTypes, "checkCrossProductUnion_DepthLimit", { typeIds: types.map(t => t.id), size });
                 error(currentNode, Diagnostics.Expression_produces_a_union_type_that_is_too_complex_to_represent);
                 return false;
             }
@@ -15381,7 +15381,7 @@ namespace ts {
                 // We have reached 50 recursive type instantiations and there is a very high likelyhood we're dealing
                 // with a combination of infinite generic types that perpetually generate new type identities. We stop
                 // the recursion here by yielding the error type.
-                tracing.instant(tracing.Phase.Check, "instantiateType_DepthLimit", { typeId: type.id, instantiationDepth, instantiationCount });
+                tracing.instant(tracing.Phase.CheckTypes, "instantiateType_DepthLimit", { typeId: type.id, instantiationDepth, instantiationCount });
                 error(currentNode, Diagnostics.Type_instantiation_is_excessively_deep_and_possibly_infinite);
                 return errorType;
             }
@@ -16504,7 +16504,7 @@ namespace ts {
                 reportIncompatibleStack();
             }
             if (overflow) {
-                tracing.instant(tracing.Phase.Check, "checkTypeRelatedTo_DepthLimit", { sourceId: source.id, targetId: target.id, depth });
+                tracing.instant(tracing.Phase.CheckTypes, "checkTypeRelatedTo_DepthLimit", { sourceId: source.id, targetId: target.id, depth });
                 const diag = error(errorNode || currentNode, Diagnostics.Excessive_stack_depth_comparing_types_0_and_1, typeToString(source), typeToString(target));
                 if (errorOutputContainer) {
                     (errorOutputContainer.errors || (errorOutputContainer.errors = [])).push(diag);
@@ -17327,7 +17327,7 @@ namespace ts {
                 }
 
                 if (expandingFlags === ExpandingFlags.Both) {
-                    tracing.instant(tracing.Phase.Check, "recursiveTypeRelatedTo_DepthLimit", {
+                    tracing.instant(tracing.Phase.CheckTypes, "recursiveTypeRelatedTo_DepthLimit", {
                         sourceId: source.id,
                         sourceIdStack: sourceStack.map(t => t.id),
                         targetId: target.id,
@@ -17364,7 +17364,7 @@ namespace ts {
             }
 
             function structuredTypeRelatedTo(source: Type, target: Type, reportErrors: boolean, intersectionState: IntersectionState): Ternary {
-                tracing.push(tracing.Phase.Check, "structuredTypeRelatedTo", { sourceId: source.id, targetId: target.id });
+                tracing.push(tracing.Phase.CheckTypes, "structuredTypeRelatedTo", { sourceId: source.id, targetId: target.id });
                 const result = structuredTypeRelatedToWorker(source, target, reportErrors, intersectionState);
                 tracing.pop();
                 return result;
@@ -17860,7 +17860,7 @@ namespace ts {
                     numCombinations *= countTypes(getTypeOfSymbol(sourceProperty));
                     if (numCombinations > 25) {
                         // We've reached the complexity limit.
-                        tracing.instant(tracing.Phase.Check, "typeRelatedToDiscriminatedType_DepthLimit", { sourceId: source.id, targetId: target.id, numCombinations });
+                        tracing.instant(tracing.Phase.CheckTypes, "typeRelatedToDiscriminatedType_DepthLimit", { sourceId: source.id, targetId: target.id, numCombinations });
                         return Ternary.False;
                     }
                 }
@@ -18621,7 +18621,7 @@ namespace ts {
         function getVariancesWorker<TCache extends { variances?: VarianceFlags[] }>(typeParameters: readonly TypeParameter[] = emptyArray, cache: TCache, createMarkerType: (input: TCache, param: TypeParameter, marker: Type) => Type): VarianceFlags[] {
             let variances = cache.variances;
             if (!variances) {
-                tracing.push(tracing.Phase.Check, "getVariancesWorker", { arity: typeParameters.length, id: (cache as any).id ?? (cache as any).declaredType?.id ?? -1 });
+                tracing.push(tracing.Phase.CheckTypes, "getVariancesWorker", { arity: typeParameters.length, id: (cache as any).id ?? (cache as any).declaredType?.id ?? -1 });
                 // The emptyArray singleton is used to signal a recursive invocation.
                 cache.variances = emptyArray;
                 variances = [];
@@ -21719,7 +21719,7 @@ namespace ts {
                 if (flowDepth === 2000) {
                     // We have made 2000 recursive invocations. To avoid overflowing the call stack we report an error
                     // and disable further control flow analysis in the containing function or module body.
-                    tracing.instant(tracing.Phase.Check, "getTypeAtFlowNode_DepthLimit", { flowId: flow.id });
+                    tracing.instant(tracing.Phase.CheckTypes, "getTypeAtFlowNode_DepthLimit", { flowId: flow.id });
                     flowAnalysisDisabled = true;
                     reportFlowControlError(reference);
                     return errorType;

src/compiler/program.ts

@@ -780,7 +780,7 @@ namespace ts {
         // Track source files that are source files found by searching under node_modules, as these shouldn't be compiled.
         const sourceFilesFoundSearchingNodeModules = new Map<string, boolean>();
 
-        tracing.push(tracing.Phase.Program, "createProgram", {}, /*separateBeginAndEnd*/ true);
+        tracing.push(tracing.Phase.Program, "createProgram", { configFilePath: options.configFilePath, rootDir: options.rootDir }, /*separateBeginAndEnd*/ true);
         performance.mark("beforeProgram");
 
         const host = createProgramOptions.host || createCompilerHost(options);

src/compiler/tracing.ts

@@ -1,16 +1,24 @@
 /*@internal*/
 /** Tracing events for the compiler. */
 namespace ts.tracing {
+    export const enum Mode {
+        Project,
+        Build,
+        Server,
+    }
+
     let fs: typeof import("fs") | false | undefined;
 
     let traceCount = 0;
     let traceFd: number | undefined;
 
+    let mode: Mode;
+
     let legendPath: string | undefined;
     const legend: TraceRecord[] = [];
 
     /** Starts tracing for the given project (unless the `fs` module is unavailable). */
-    export function startTracing(configFilePath: string | undefined, traceDir: string, isBuildMode: boolean) {
+    export function startTracing(tracingMode: Mode, traceDir: string, configFilePath?: string) {
         Debug.assert(!traceFd, "Tracing already started");
 
         if (fs === undefined) {
@@ -26,6 +34,8 @@ namespace ts.tracing {
             return;
         }
 
+        mode = tracingMode;
+
         if (legendPath === undefined) {
             legendPath = combinePaths(traceDir, "legend.json");
         }
@@ -35,7 +45,10 @@ namespace ts.tracing {
             fs.mkdirSync(traceDir, { recursive: true });
         }
 
-        const countPart = isBuildMode ? `.${++traceCount}` : ``;
+        const countPart =
+            mode === Mode.Build ? `.${process.pid}-${++traceCount}` :
+            mode === Mode.Server ? `.${process.pid}` :
+            ``;
         const tracePath = combinePaths(traceDir, `trace${countPart}.json`);
         const typesPath = combinePaths(traceDir, `types${countPart}.json`);
 
@@ -58,13 +71,14 @@ namespace ts.tracing {
     }
 
     /** Stops tracing for the in-progress project and dumps the type catalog (unless the `fs` module is unavailable). */
-    export function stopTracing(typeCatalog: readonly Type[]) {
+    export function stopTracing(typeCatalog?: readonly Type[]) {
         if (!traceFd) {
             Debug.assert(!fs, "Tracing is not in progress");
             return;
         }
 
         Debug.assert(fs);
+        Debug.assert(!!typeCatalog === (mode !== Mode.Server)); // Have a type catalog iff not in server mode
 
         fs.writeSync(traceFd, `\n]\n`);
         fs.closeSync(traceFd);
@@ -88,17 +102,18 @@ namespace ts.tracing {
         Parse = "parse",
         Program = "program",
         Bind = "bind",
-        Check = "check",
+        Check = "check", // Before we get into checking types (e.g. checkSourceFile)
+        CheckTypes = "checkTypes",
         Emit = "emit",
+        Session = "session",
     }
 
     export function instant(phase: Phase, name: string, args?: object) {
         if (!traceFd) return;
         writeEvent("I", phase, name, args, `"s":"g"`);
     }
 
-    // Used for "Complete" (ph:"X") events
-    const completeEvents: { phase: Phase, name: string, args?: object, time: number, separateBeginAndEnd: boolean }[] = [];
+    const eventStack: { phase: Phase, name: string, args?: object, time: number, separateBeginAndEnd: boolean }[] = [];
 
     /**
      * @param separateBeginAndEnd - used for special cases where we need the trace point even if the event
@@ -111,25 +126,40 @@ namespace ts.tracing {
         if (separateBeginAndEnd) {
             writeEvent("B", phase, name, args);
         }
-        completeEvents.push({ phase, name, args, time: 1000 * timestamp(), separateBeginAndEnd });
+        eventStack.push({ phase, name, args, time: 1000 * timestamp(), separateBeginAndEnd });
     }
     export function pop() {
         if (!traceFd) return;
-        Debug.assert(completeEvents.length > 0);
-        const { phase, name, args, time, separateBeginAndEnd } = completeEvents.pop()!;
+        Debug.assert(eventStack.length > 0);
+        writeStackEvent(eventStack.length - 1, 1000 * timestamp());
+        eventStack.length--;
+    }
+    export function popAll() {
+        if (!traceFd) return;
+        const endTime = 1000 * timestamp();
+        for (let i = eventStack.length - 1; i >= 0; i--) {
+            writeStackEvent(i, endTime);
+        }
+        eventStack.length = 0;
+    }
+    function writeStackEvent(index: number, endTime: number) {
+        const { phase, name, args, time, separateBeginAndEnd } = eventStack[index];
         if (separateBeginAndEnd) {
-            writeEvent("E", phase, name, args);
+            writeEvent("E", phase, name, args, /*extras*/ undefined, endTime);
         }
         else {
-            const dur = 1000 * timestamp() - time;
-            writeEvent("X", phase, name, args, `"dur":${dur}`, time);
+            writeEvent("X", phase, name, args, `"dur":${endTime - time}`, time);
         }
     }
 
     function writeEvent(eventType: string, phase: Phase, name: string, args: object | undefined, extras?: string,
                        time: number = 1000 * timestamp()) {
         Debug.assert(traceFd);
         Debug.assert(fs);
+
+        // In server mode, there's no easy way to dump type information, so we drop events that would require it.
+        if (mode === Mode.Server && phase === Phase.CheckTypes) return;
+
         performance.mark("beginTracing");
         fs.writeSync(traceFd, `,\n{"pid":1,"tid":1,"ph":"${eventType}","cat":"${phase}","ts":${time},"name":"${name}"`);
         if (extras) fs.writeSync(traceFd, `,${extras}`);

src/executeCommandLine/executeCommandLine.ts

@@ -621,7 +621,7 @@ namespace ts {
         }
 
         if (canTrace(system, compilerOptions)) {
-            tracing.startTracing(compilerOptions.configFilePath, compilerOptions.generateTrace!, isBuildMode);
+            tracing.startTracing(isBuildMode ? tracing.Mode.Build : tracing.Mode.Project, compilerOptions.generateTrace!, compilerOptions.configFilePath);
         }
     }
 

src/server/session.ts

@@ -208,15 +208,25 @@ namespace ts.server {
             try {
                 if (this.operationHost.isCancellationRequested()) {
                     stop = true;
+                    tracing.instant(tracing.Phase.Session, "stepCanceled", { seq: this.requestId, early: true });
                 }
                 else {
+                    tracing.push(tracing.Phase.Session, "stepAction", { seq: this.requestId });
                     action(this);
+                    tracing.pop();
                 }
             }
             catch (e) {
+                // Cancellation or an error may have left incomplete events on the tracing stack.
+                tracing.popAll();
+
                 stop = true;
                 // ignore cancellation request
-                if (!(e instanceof OperationCanceledException)) {
+                if (e instanceof OperationCanceledException) {
+                    tracing.instant(tracing.Phase.Session, "stepCanceled", { seq: this.requestId });
+                }
+                else {
+                    tracing.instant(tracing.Phase.Session, "stepError", { seq: this.requestId, message: (<Error>e).message });
                     this.operationHost.logError(e, `delayed processing of request ${this.requestId}`);
                 }
             }
@@ -914,6 +924,7 @@ namespace ts.server {
         }
 
         public event<T extends object>(body: T, eventName: string): void {
+            tracing.instant(tracing.Phase.Session, "event", { eventName });
             this.send(toEvent(eventName, body));
         }
 
@@ -2915,8 +2926,12 @@ namespace ts.server {
                 request = <protocol.Request>JSON.parse(message);
                 relevantFile = request.arguments && (request as protocol.FileRequest).arguments.file ? (request as protocol.FileRequest).arguments : undefined;
 
+                tracing.instant(tracing.Phase.Session, "request", { seq: request.seq, command: request.command });
                 perfLogger.logStartCommand("" + request.command, message.substring(0, 100));
+
+                tracing.push(tracing.Phase.Session, "executeCommand", { seq: request.seq, command: request.command }, /*separateBeginAndEnd*/ true);
                 const { response, responseRequired } = this.executeCommand(request);
+                tracing.pop();
 
                 if (this.logger.hasLevel(LogLevel.requestTime)) {
                     const elapsedTime = hrTimeToMilliseconds(this.hrtime(start)).toFixed(4);
@@ -2930,6 +2945,7 @@ 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");
+                tracing.instant(tracing.Phase.Session, "response", { seq: request.seq, command: request.command, success: !!response });
                 if (response) {
                     this.doOutput(response, request.command, request.seq, /*success*/ true);
                 }
@@ -2938,15 +2954,20 @@ namespace ts.server {
                 }
             }
             catch (err) {
+                // Cancellation or an error may have left incomplete events on the tracing stack.
+                tracing.popAll();
+
                 if (err instanceof OperationCanceledException) {
                     // Handle cancellation exceptions
                     perfLogger.logStopCommand("" + (request && request.command), "Canceled: " + err);
+                    tracing.instant(tracing.Phase.Session, "commandCanceled", { seq: request?.seq, command: request?.command });
                     this.doOutput({ canceled: true }, request!.command, request!.seq, /*success*/ true);
                     return;
                 }
 
                 this.logErrorWorker(err, message, relevantFile);
                 perfLogger.logStopCommand("" + (request && request.command), "Error: " + err);
+                tracing.instant(tracing.Phase.Session, "commandError", { seq: request?.seq, command: request?.command, message: (<Error>err).message });
 
                 this.doOutput(
                     /*info*/ undefined,

src/services/services.ts

@@ -1126,16 +1126,22 @@ namespace ts {
         return createLanguageServiceSourceFile(sourceFile.fileName, scriptSnapshot, sourceFile.languageVersion, version, /*setNodeParents*/ true, sourceFile.scriptKind);
     }
 
+    const NoopCancellationToken: CancellationToken = {
+        isCancellationRequested: returnFalse,
+        throwIfCancellationRequested: noop,
+    };
+
     class CancellationTokenObject implements CancellationToken {
-        constructor(private cancellationToken: HostCancellationToken | undefined) {
+        constructor(private cancellationToken: HostCancellationToken) {
         }
 
         public isCancellationRequested(): boolean {
-            return !!this.cancellationToken && this.cancellationToken.isCancellationRequested();
+            return this.cancellationToken.isCancellationRequested();
         }
 
         public throwIfCancellationRequested(): void {
             if (this.isCancellationRequested()) {
+                tracing.instant(tracing.Phase.Session, "cancellationThrown", { kind: "CancellationTokenObject" });
                 throw new OperationCanceledException();
             }
         }
@@ -1166,6 +1172,7 @@ namespace ts {
 
         public throwIfCancellationRequested(): void {
             if (this.isCancellationRequested()) {
+                tracing.instant(tracing.Phase.Session, "cancellationThrown", { kind: "ThrottledCancellationToken" });
                 throw new OperationCanceledException();
             }
         }
@@ -1233,7 +1240,9 @@ namespace ts {
         let lastProjectVersion: string;
         let lastTypesRootVersion = 0;
 
-        const cancellationToken = new CancellationTokenObject(host.getCancellationToken && host.getCancellationToken());
+        const cancellationToken = host.getCancellationToken
+            ? new CancellationTokenObject(host.getCancellationToken())
+            : NoopCancellationToken;
 
         const currentDirectory = host.getCurrentDirectory();
         // Check if the localized messages json is set, otherwise query the host for it