Tracing work

src/compiler/binder.ts

@@ -174,14 +174,15 @@ namespace ts {
     const binder = createBinder();
 
     export function bindSourceFile(file: SourceFile, options: CompilerOptions) {
-        tracing.begin(tracing.Phase.Bind, "bindSourceFile", { path: file.path });
+        const tracingData: tracing.EventData = [tracing.Phase.Bind, "bindSourceFile", { path: file.path }];
+        tracing.begin(...tracingData);
         performance.mark("beforeBind");
         perfLogger.logStartBindFile("" + file.fileName);
         binder(file, options);
         perfLogger.logStopBindFile();
         performance.mark("afterBind");
         performance.measure("Bind", "beforeBind", "afterBind");
-        tracing.end();
+        tracing.end(...tracingData);
     }
 
     function createBinder(): (file: SourceFile, options: CompilerOptions) => void {

src/compiler/checker.ts

@@ -17272,9 +17272,9 @@ namespace ts {
             }
 
             function structuredTypeRelatedTo(source: Type, target: Type, reportErrors: boolean, intersectionState: IntersectionState): Ternary {
-                tracing.begin(tracing.Phase.Check, "structuredTypeRelatedTo", { sourceId: source.id, targetId: target.id });
+                tracing.push(tracing.Phase.Check, "structuredTypeRelatedTo", { sourceId: source.id, targetId: target.id });
                 const result = structuredTypeRelatedToWorker(source, target, reportErrors, intersectionState);
-                tracing.end();
+                tracing.pop();
                 return result;
             }
 
@@ -18529,7 +18529,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.begin(tracing.Phase.Check, "getVariancesWorker", { arity: typeParameters.length, id: (cache as any).id ?? (cache as any).declaredType?.id ?? -1 });
+                tracing.push(tracing.Phase.Check, "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 = [];
@@ -18564,7 +18564,7 @@ namespace ts {
                     variances.push(variance);
                 }
                 cache.variances = variances;
-                tracing.end();
+                tracing.pop();
             }
             return variances;
         }
@@ -30979,7 +30979,7 @@ namespace ts {
         }
 
         function checkExpression(node: Expression | QualifiedName, checkMode?: CheckMode, forceTuple?: boolean): Type {
-            tracing.begin(tracing.Phase.Check, "checkExpression", { kind: node.kind, pos: node.pos, end: node.end });
+            tracing.push(tracing.Phase.Check, "checkExpression", { kind: node.kind, pos: node.pos, end: node.end });
             const saveCurrentNode = currentNode;
             currentNode = node;
             instantiationCount = 0;
@@ -30989,7 +30989,7 @@ namespace ts {
                 checkConstEnumAccess(node, type);
             }
             currentNode = saveCurrentNode;
-            tracing.end();
+            tracing.pop();
             return type;
         }
 
@@ -33780,10 +33780,10 @@ namespace ts {
         }
 
         function checkVariableDeclaration(node: VariableDeclaration) {
-            tracing.begin(tracing.Phase.Check, "checkVariableDeclaration", { kind: node.kind, pos: node.pos, end: node.end });
+            tracing.push(tracing.Phase.Check, "checkVariableDeclaration", { kind: node.kind, pos: node.pos, end: node.end });
             checkGrammarVariableDeclaration(node);
             checkVariableLikeDeclaration(node);
-            tracing.end();
+            tracing.pop();
         }
 
         function checkBindingElement(node: BindingElement) {
@@ -36854,12 +36854,13 @@ namespace ts {
         }
 
         function checkSourceFile(node: SourceFile) {
-            tracing.begin(tracing.Phase.Check, "checkSourceFile", { path: node.path });
+            const tracingData: tracing.EventData = [tracing.Phase.Check, "checkSourceFile", { path: node.path }];
+            tracing.begin(...tracingData);
             performance.mark("beforeCheck");
             checkSourceFileWorker(node);
             performance.mark("afterCheck");
             performance.measure("Check", "beforeCheck", "afterCheck");
-            tracing.end();
+            tracing.end(...tracingData);
         }
 
         function unusedIsError(kind: UnusedKind, isAmbient: boolean): boolean {

src/compiler/emitter.ts

@@ -300,17 +300,17 @@ namespace ts {
                     sourceFiles: sourceFileOrBundle.sourceFiles.map(file => relativeToBuildInfo(getNormalizedAbsolutePath(file.fileName, host.getCurrentDirectory())))
                 };
             }
-            tracing.begin(tracing.Phase.Emit, "emitJsFileOrBundle", { jsFilePath });
+            tracing.push(tracing.Phase.Emit, "emitJsFileOrBundle", { jsFilePath });
             emitJsFileOrBundle(sourceFileOrBundle, jsFilePath, sourceMapFilePath, relativeToBuildInfo);
-            tracing.end();
+            tracing.pop();
 
-            tracing.begin(tracing.Phase.Emit, "emitDeclarationFileOrBundle", { declarationFilePath });
+            tracing.push(tracing.Phase.Emit, "emitDeclarationFileOrBundle", { declarationFilePath });
             emitDeclarationFileOrBundle(sourceFileOrBundle, declarationFilePath, declarationMapPath, relativeToBuildInfo);
-            tracing.end();
+            tracing.pop();
 
-            tracing.begin(tracing.Phase.Emit, "emitBuildInfo", { buildInfoPath });
+            tracing.push(tracing.Phase.Emit, "emitBuildInfo", { buildInfoPath });
             emitBuildInfo(bundleBuildInfo, buildInfoPath);
-            tracing.end();
+            tracing.pop();
 
             if (!emitSkipped && emittedFilesList) {
                 if (!emitOnlyDtsFiles) {

src/compiler/parser.ts

@@ -614,7 +614,8 @@ namespace ts {
     }
 
     export function createSourceFile(fileName: string, sourceText: string, languageVersion: ScriptTarget, setParentNodes = false, scriptKind?: ScriptKind): SourceFile {
-        tracing.begin(tracing.Phase.Parse, "createSourceFile", { path: fileName });
+        const tracingData: tracing.EventData = [tracing.Phase.Parse, "createSourceFile", { path: fileName }];
+        tracing.begin(...tracingData);
         performance.mark("beforeParse");
         let result: SourceFile;
 
@@ -629,7 +630,7 @@ namespace ts {
 
         performance.mark("afterParse");
         performance.measure("Parse", "beforeParse", "afterParse");
-        tracing.end();
+        tracing.end(...tracingData);
         return result;
     }
 

src/compiler/program.ts

@@ -780,7 +780,8 @@ 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.begin(tracing.Phase.Program, "createProgram", {});
+        const tracingData: tracing.EventData = [tracing.Phase.Program, "createProgram"];
+        tracing.begin(...tracingData);
         performance.mark("beforeProgram");
 
         const host = createProgramOptions.host || createCompilerHost(options);
@@ -1032,7 +1033,7 @@ namespace ts {
         verifyCompilerOptions();
         performance.mark("afterProgram");
         performance.measure("Program", "beforeProgram", "afterProgram");
-        tracing.end();
+        tracing.end(...tracingData);
 
         return program;
 
@@ -1590,7 +1591,8 @@ namespace ts {
 
         function emitBuildInfo(writeFileCallback?: WriteFileCallback): EmitResult {
             Debug.assert(!outFile(options));
-            tracing.begin(tracing.Phase.Emit, "emitBuildInfo", {});
+            const tracingData: tracing.EventData = [tracing.Phase.Emit, "emitBuildInfo"];
+            tracing.begin(...tracingData);
             performance.mark("beforeEmit");
             const emitResult = emitFiles(
                 notImplementedResolver,
@@ -1603,7 +1605,7 @@ namespace ts {
 
             performance.mark("afterEmit");
             performance.measure("Emit", "beforeEmit", "afterEmit");
-            tracing.end();
+            tracing.end(...tracingData);
             return emitResult;
         }
 
@@ -1664,9 +1666,10 @@ namespace ts {
         }
 
         function emit(sourceFile?: SourceFile, writeFileCallback?: WriteFileCallback, cancellationToken?: CancellationToken, emitOnlyDtsFiles?: boolean, transformers?: CustomTransformers, forceDtsEmit?: boolean): EmitResult {
-            tracing.begin(tracing.Phase.Emit, "emit", { path: sourceFile?.path });
+            const tracingData: tracing.EventData = [tracing.Phase.Emit, "emit", { path: sourceFile?.path }];
+            tracing.begin(...tracingData);
             const result = runWithCancellationToken(() => emitWorker(program, sourceFile, writeFileCallback, cancellationToken, emitOnlyDtsFiles, transformers, forceDtsEmit));
-            tracing.end();
+            tracing.end(...tracingData);
             return result;
         }
 

src/compiler/tracing.ts

@@ -46,7 +46,15 @@ namespace ts.tracing {
         });
 
         traceFd = fs.openSync(tracePath, "w");
-        fs.writeSync(traceFd, `[\n`);
+
+        // Start with a prefix that contains some metadata that the devtools profiler expects (also avoids a warning on import)
+        const meta = { cat: "__metadata", ph: "M", ts: 1000 * timestamp(), pid: 1, tid: 1 };
+        fs.writeSync(traceFd,
+                     "[\n"
+                     + [{ name: "process_name", args: { name: "tsc" }, ...meta },
+                        { name: "thread_name", args: { name: "Main" }, ...meta },
+                        { name: "TracingStartedInBrowser", ...meta, cat: "disabled-by-default-devtools.timeline" }]
+                       .map(v => JSON.stringify(v)).join(",\n"));
     }
 
     /** Stops tracing for the in-progress project and dumps the type catalog (unless the `fs` module is unavailable). */
@@ -58,11 +66,7 @@ namespace ts.tracing {
 
         Debug.assert(fs);
 
-        // This both indicates that the trace is untruncated and conveniently
-        // ensures that the last array element won't have a trailing comma.
-        fs.writeSync(traceFd, `{"pid":1,"tid":1,"ph":"i","ts":${1000 * timestamp()},"name":"done","s":"g"}\n`);
-        fs.writeSync(traceFd, `]\n`);
-
+        fs.writeSync(traceFd, `\n]\n`);
         fs.closeSync(traceFd);
         traceFd = undefined;
 
@@ -88,38 +92,46 @@ namespace ts.tracing {
         Emit = "emit",
     }
 
-    export function begin(phase: Phase, name: string, args: object) {
-        if (!traceFd) {
-            return;
-        }
-        Debug.assert(fs);
+    export type EventData = [phase: Phase, name: string, args?: object];
 
-        performance.mark("beginTracing");
-        fs.writeSync(traceFd, `{"pid":1,"tid":1,"ph":"B","cat":"${phase}","ts":${1000 * timestamp()},"name":"${name}","args":{ "ts": ${JSON.stringify(args)} }},\n`);
-        performance.mark("endTracing");
-        performance.measure("Tracing", "beginTracing", "endTracing");
+    /** Note: `push`/`pop` should be used by default.
+     * `begin`/`end` are for special cases where we need the data point even if the event never
+     * terminates (typically for reducing a scenario too big to trace to one that can be completed).
+     * In the future we might implement an exit handler to dump unfinished events which would
+     * deprecate these operations.
+     */
+    export function begin(phase: Phase, name: string, args?: object) {
+        writeEvent("B", phase, name, args);
+    }
+    export function end(phase: Phase, name: string, args?: object) {
+        writeEvent("E", phase, name, args);
     }
 
-    export function end() {
-        if (!traceFd) {
-            return;
-        }
-        Debug.assert(fs);
+    export function instant(phase: Phase, name: string, args?: object) {
+        writeEvent("I", phase, name, args, `"s":"g"`);
+    }
 
-        performance.mark("beginTracing");
-        fs.writeSync(traceFd, `{"pid":1,"tid":1,"ph":"E","ts":${1000 * timestamp()}},\n`);
-        performance.mark("endTracing");
-        performance.measure("Tracing", "beginTracing", "endTracing");
+    // Used for "Complete" (ph:"X") events
+    const completeEvents: { phase: Phase, name: string, args?: object, time: number }[] = [];
+    export function push(phase: Phase, name: string, args?: object) {
+        completeEvents.push({ phase, name, args, time: 1000 * timestamp() });
+    }
+    export function pop() {
+        Debug.assert(completeEvents.length > 0);
+        const { phase, name, args, time } = completeEvents.pop()!;
+        const dur = 1000 * timestamp() - time;
+        writeEvent("X", phase, name, args, `"dur":${dur}`, time);
     }
 
-    export function instant(phase: Phase, name: string, args: object) {
-        if (!traceFd) {
-            return;
-        }
+    function writeEvent(eventType: string, phase: Phase, name: string, args: object | undefined, extras?: string,
+                       time: number = 1000 * timestamp()) {
+        if (!traceFd) return;
         Debug.assert(fs);
-
         performance.mark("beginTracing");
-        fs.writeSync(traceFd, `{"pid":1,"tid":1,"ph":"i","cat":"${phase}","ts":${1000 * timestamp()},"name":"${name}","s":"g","args":{ "ts": ${JSON.stringify(args)} }},\n`);
+        fs.writeSync(traceFd, `,\n{"pid":1,"tid":1,"ph":"${eventType}","cat":"${phase}","ts":${time},"name":"${name}"`);
+        if (extras) fs.writeSync(traceFd, `,${extras}`);
+        if (args) fs.writeSync(traceFd, `,"args":${JSON.stringify(args)}`);
+        fs.writeSync(traceFd, `}`);
         performance.mark("endTracing");
         performance.measure("Tracing", "beginTracing", "endTracing");
     }

src/compiler/transformer.ts

@@ -223,9 +223,9 @@ namespace ts {
         // Transform each node.
         const transformed: T[] = [];
         for (const node of nodes) {
-            tracing.begin(tracing.Phase.Emit, "transformNodes", node.kind === SyntaxKind.SourceFile ? { path: (node as any as SourceFile).path } : { kind: node.kind, pos: node.pos, end: node.end });
+            tracing.push(tracing.Phase.Emit, "transformNodes", node.kind === SyntaxKind.SourceFile ? { path: (node as any as SourceFile).path } : { kind: node.kind, pos: node.pos, end: node.end });
             transformed.push((allowDtsFiles ? transformation : transformRoot)(node));
-            tracing.end();
+            tracing.pop();
         }
 
         // prevent modification of the lexical environment.