Tracing work

* Fix: `E` events need to have the same information that is on the
  corresponding `B` events.  (Superseded below.)

* Use `I` (not `i`) for instant events, so they show in devtools
  too.  (Though they don't go through the flame chart as they do in
  `about://tracing`, so they're not nearly as useful.)

* Abstract the code that writes the records in a single `writeEvent`
  local function.

* Make `args` optional, and default to `undefined` (which will not add
  them) at all.

* Drop the `{ "ts": ... }` wrapper around the `args`, after verifying
  that having arguments with names like `begin`, `end`, `pos`, `id`
  doesn't interfere with either UIs.

* Add `tracing.push`/`tracing.pop` for complete events, change a few
  `.begin`/`.end` to use these.  (The caveat is that until there's an exit
  handler to dump unterminated events, these won't show in the dump.  When
  that's done the push/pop variant can be used everywhere.)

* Add meta lines to name the process and the thread, and a line that
  avoids the warning when opening in devtools.

Author: elibarzilay

src/compiler/binder.ts

@@ -181,7 +181,7 @@ namespace ts {
         perfLogger.logStopBindFile();
         performance.mark("afterBind");
         performance.measure("Bind", "beforeBind", "afterBind");
-        tracing.end();
+        tracing.end(tracing.Phase.Bind, "bindSourceFile", { path: file.path });
     }
 
     function createBinder(): (file: SourceFile, options: CompilerOptions) => void {

src/compiler/checker.ts

@@ -17104,9 +17104,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;
             }
 
@@ -18320,7 +18320,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 = [];
@@ -18355,7 +18355,7 @@ namespace ts {
                     variances.push(variance);
                 }
                 cache.variances = variances;
-                tracing.end();
+                tracing.pop();
             }
             return variances;
         }
@@ -30599,7 +30599,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;
@@ -30609,7 +30609,7 @@ namespace ts {
                 checkConstEnumAccess(node, type);
             }
             currentNode = saveCurrentNode;
-            tracing.end();
+            tracing.pop();
             return type;
         }
 
@@ -33403,10 +33403,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) {
@@ -36476,7 +36476,7 @@ namespace ts {
             checkSourceFileWorker(node);
             performance.mark("afterCheck");
             performance.measure("Check", "beforeCheck", "afterCheck");
-            tracing.end();
+            tracing.end(tracing.Phase.Check, "checkSourceFile", { path: node.path });
         }
 
         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

@@ -629,7 +629,7 @@ namespace ts {
 
         performance.mark("afterParse");
         performance.measure("Parse", "beforeParse", "afterParse");
-        tracing.end();
+        tracing.end(tracing.Phase.Parse, "createSourceFile", { path: fileName });
         return result;
     }
 

src/compiler/program.ts

@@ -734,7 +734,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.begin(tracing.Phase.Program, "createProgram", {});
+        tracing.begin(tracing.Phase.Program, "createProgram");
         performance.mark("beforeProgram");
 
         const host = createProgramOptions.host || createCompilerHost(options);
@@ -984,7 +984,7 @@ namespace ts {
         verifyCompilerOptions();
         performance.mark("afterProgram");
         performance.measure("Program", "beforeProgram", "afterProgram");
-        tracing.end();
+        tracing.end(tracing.Phase.Program, "createProgram");
 
         return program;
 
@@ -1508,7 +1508,7 @@ namespace ts {
 
         function emitBuildInfo(writeFileCallback?: WriteFileCallback): EmitResult {
             Debug.assert(!outFile(options));
-            tracing.begin(tracing.Phase.Emit, "emitBuildInfo", {});
+            tracing.begin(tracing.Phase.Emit, "emitBuildInfo");
             performance.mark("beforeEmit");
             const emitResult = emitFiles(
                 notImplementedResolver,
@@ -1521,7 +1521,7 @@ namespace ts {
 
             performance.mark("afterEmit");
             performance.measure("Emit", "beforeEmit", "afterEmit");
-            tracing.end();
+            tracing.end(tracing.Phase.Emit, "emitBuildInfo");
             return emitResult;
         }
 
@@ -1584,7 +1584,7 @@ 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 result = runWithCancellationToken(() => emitWorker(program, sourceFile, writeFileCallback, cancellationToken, emitOnlyDtsFiles, transformers, forceDtsEmit));
-            tracing.end();
+            tracing.end(tracing.Phase.Emit, "emit", { path: sourceFile?.path });
             return result;
         }
 

src/compiler/tracing.ts

@@ -46,7 +46,16 @@ 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,")
+                     + "\n");
     }
 
     /** Stops tracing for the in-progress project and dumps the type catalog (unless the `fs` module is unavailable). */
@@ -58,11 +67,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.closeSync(traceFd);
         traceFd = undefined;
 
@@ -88,38 +93,39 @@ namespace ts.tracing {
         Emit = "emit",
     }
 
-    export function begin(phase: Phase, name: string, args: object) {
-        if (!traceFd) {
-            return;
-        }
-        Debug.assert(fs);
+    export function begin(phase: Phase, name: string, args?: object) {
+        writeEvent("B", phase, name, args);
+    }
 
-        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");
+    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, `,{"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, `}\n`);
         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.