Skip to content

Commit fe7ec1e

Browse files
elibarzilayelibarzilay
committed
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.
1 parent 5d021b4 commit fe7ec1e

File tree

7 files changed

+76
-58
lines changed

7 files changed

+76
-58
lines changed

‎src/compiler/binder.ts

Lines changed: 3 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -174,14 +174,15 @@ namespace ts {
174174
const binder = createBinder();
175175

176176
export function bindSourceFile(file: SourceFile, options: CompilerOptions) {
177-
tracing.begin(tracing.Phase.Bind, "bindSourceFile", { path: file.path });
177+
const tracingData: tracing.EventData = [tracing.Phase.Bind, "bindSourceFile", { path: file.path }];
178+
tracing.begin(...tracingData);
178179
performance.mark("beforeBind");
179180
perfLogger.logStartBindFile("" + file.fileName);
180181
binder(file, options);
181182
perfLogger.logStopBindFile();
182183
performance.mark("afterBind");
183184
performance.measure("Bind", "beforeBind", "afterBind");
184-
tracing.end();
185+
tracing.end(...tracingData);
185186
}
186187

187188
function createBinder(): (file: SourceFile, options: CompilerOptions) => void {

‎src/compiler/checker.ts

Lines changed: 11 additions & 10 deletions
Original file line numberDiff line numberDiff line change
@@ -17272,9 +17272,9 @@ namespace ts {
1727217272
}
1727317273

1727417274
function structuredTypeRelatedTo(source: Type, target: Type, reportErrors: boolean, intersectionState: IntersectionState): Ternary {
17275-
tracing.begin(tracing.Phase.Check, "structuredTypeRelatedTo", { sourceId: source.id, targetId: target.id });
17275+
tracing.push(tracing.Phase.Check, "structuredTypeRelatedTo", { sourceId: source.id, targetId: target.id });
1727617276
const result = structuredTypeRelatedToWorker(source, target, reportErrors, intersectionState);
17277-
tracing.end();
17277+
tracing.pop();
1727817278
return result;
1727917279
}
1728017280

@@ -18529,7 +18529,7 @@ namespace ts {
1852918529
function getVariancesWorker<TCache extends { variances?: VarianceFlags[] }>(typeParameters: readonly TypeParameter[] = emptyArray, cache: TCache, createMarkerType: (input: TCache, param: TypeParameter, marker: Type) => Type): VarianceFlags[] {
1853018530
let variances = cache.variances;
1853118531
if (!variances) {
18532-
tracing.begin(tracing.Phase.Check, "getVariancesWorker", { arity: typeParameters.length, id: (cache as any).id ?? (cache as any).declaredType?.id ?? -1 });
18532+
tracing.push(tracing.Phase.Check, "getVariancesWorker", { arity: typeParameters.length, id: (cache as any).id ?? (cache as any).declaredType?.id ?? -1 });
1853318533
// The emptyArray singleton is used to signal a recursive invocation.
1853418534
cache.variances = emptyArray;
1853518535
variances = [];
@@ -18564,7 +18564,7 @@ namespace ts {
1856418564
variances.push(variance);
1856518565
}
1856618566
cache.variances = variances;
18567-
tracing.end();
18567+
tracing.pop();
1856818568
}
1856918569
return variances;
1857018570
}
@@ -30979,7 +30979,7 @@ namespace ts {
3097930979
}
3098030980

3098130981
function checkExpression(node: Expression | QualifiedName, checkMode?: CheckMode, forceTuple?: boolean): Type {
30982-
tracing.begin(tracing.Phase.Check, "checkExpression", { kind: node.kind, pos: node.pos, end: node.end });
30982+
tracing.push(tracing.Phase.Check, "checkExpression", { kind: node.kind, pos: node.pos, end: node.end });
3098330983
const saveCurrentNode = currentNode;
3098430984
currentNode = node;
3098530985
instantiationCount = 0;
@@ -30989,7 +30989,7 @@ namespace ts {
3098930989
checkConstEnumAccess(node, type);
3099030990
}
3099130991
currentNode = saveCurrentNode;
30992-
tracing.end();
30992+
tracing.pop();
3099330993
return type;
3099430994
}
3099530995

@@ -33780,10 +33780,10 @@ namespace ts {
3378033780
}
3378133781

3378233782
function checkVariableDeclaration(node: VariableDeclaration) {
33783-
tracing.begin(tracing.Phase.Check, "checkVariableDeclaration", { kind: node.kind, pos: node.pos, end: node.end });
33783+
tracing.push(tracing.Phase.Check, "checkVariableDeclaration", { kind: node.kind, pos: node.pos, end: node.end });
3378433784
checkGrammarVariableDeclaration(node);
3378533785
checkVariableLikeDeclaration(node);
33786-
tracing.end();
33786+
tracing.pop();
3378733787
}
3378833788

3378933789
function checkBindingElement(node: BindingElement) {
@@ -36854,12 +36854,13 @@ namespace ts {
3685436854
}
3685536855

3685636856
function checkSourceFile(node: SourceFile) {
36857-
tracing.begin(tracing.Phase.Check, "checkSourceFile", { path: node.path });
36857+
const tracingData: tracing.EventData = [tracing.Phase.Check, "checkSourceFile", { path: node.path }];
36858+
tracing.begin(...tracingData);
3685836859
performance.mark("beforeCheck");
3685936860
checkSourceFileWorker(node);
3686036861
performance.mark("afterCheck");
3686136862
performance.measure("Check", "beforeCheck", "afterCheck");
36862-
tracing.end();
36863+
tracing.end(...tracingData);
3686336864
}
3686436865

3686536866
function unusedIsError(kind: UnusedKind, isAmbient: boolean): boolean {

‎src/compiler/emitter.ts

Lines changed: 6 additions & 6 deletions
Original file line numberDiff line numberDiff line change
@@ -300,17 +300,17 @@ namespace ts {
300300
sourceFiles: sourceFileOrBundle.sourceFiles.map(file => relativeToBuildInfo(getNormalizedAbsolutePath(file.fileName, host.getCurrentDirectory())))
301301
};
302302
}
303-
tracing.begin(tracing.Phase.Emit, "emitJsFileOrBundle", { jsFilePath });
303+
tracing.push(tracing.Phase.Emit, "emitJsFileOrBundle", { jsFilePath });
304304
emitJsFileOrBundle(sourceFileOrBundle, jsFilePath, sourceMapFilePath, relativeToBuildInfo);
305-
tracing.end();
305+
tracing.pop();
306306

307-
tracing.begin(tracing.Phase.Emit, "emitDeclarationFileOrBundle", { declarationFilePath });
307+
tracing.push(tracing.Phase.Emit, "emitDeclarationFileOrBundle", { declarationFilePath });
308308
emitDeclarationFileOrBundle(sourceFileOrBundle, declarationFilePath, declarationMapPath, relativeToBuildInfo);
309-
tracing.end();
309+
tracing.pop();
310310

311-
tracing.begin(tracing.Phase.Emit, "emitBuildInfo", { buildInfoPath });
311+
tracing.push(tracing.Phase.Emit, "emitBuildInfo", { buildInfoPath });
312312
emitBuildInfo(bundleBuildInfo, buildInfoPath);
313-
tracing.end();
313+
tracing.pop();
314314

315315
if (!emitSkipped && emittedFilesList) {
316316
if (!emitOnlyDtsFiles) {

‎src/compiler/parser.ts

Lines changed: 3 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -614,7 +614,8 @@ namespace ts {
614614
}
615615

616616
export function createSourceFile(fileName: string, sourceText: string, languageVersion: ScriptTarget, setParentNodes = false, scriptKind?: ScriptKind): SourceFile {
617-
tracing.begin(tracing.Phase.Parse, "createSourceFile", { path: fileName });
617+
const tracingData: tracing.EventData = [tracing.Phase.Parse, "createSourceFile", { path: fileName }];
618+
tracing.begin(...tracingData);
618619
performance.mark("beforeParse");
619620
let result: SourceFile;
620621

@@ -629,7 +630,7 @@ namespace ts {
629630

630631
performance.mark("afterParse");
631632
performance.measure("Parse", "beforeParse", "afterParse");
632-
tracing.end();
633+
tracing.end(...tracingData);
633634
return result;
634635
}
635636

‎src/compiler/program.ts

Lines changed: 9 additions & 6 deletions
Original file line numberDiff line numberDiff line change
@@ -780,7 +780,8 @@ namespace ts {
780780
// Track source files that are source files found by searching under node_modules, as these shouldn't be compiled.
781781
const sourceFilesFoundSearchingNodeModules = new Map<string, boolean>();
782782

783-
tracing.begin(tracing.Phase.Program, "createProgram", {});
783+
const tracingData: tracing.EventData = [tracing.Phase.Program, "createProgram"];
784+
tracing.begin(...tracingData);
784785
performance.mark("beforeProgram");
785786

786787
const host = createProgramOptions.host || createCompilerHost(options);
@@ -1032,7 +1033,7 @@ namespace ts {
10321033
verifyCompilerOptions();
10331034
performance.mark("afterProgram");
10341035
performance.measure("Program", "beforeProgram", "afterProgram");
1035-
tracing.end();
1036+
tracing.end(...tracingData);
10361037

10371038
return program;
10381039

@@ -1590,7 +1591,8 @@ namespace ts {
15901591

15911592
function emitBuildInfo(writeFileCallback?: WriteFileCallback): EmitResult {
15921593
Debug.assert(!outFile(options));
1593-
tracing.begin(tracing.Phase.Emit, "emitBuildInfo", {});
1594+
const tracingData: tracing.EventData = [tracing.Phase.Emit, "emitBuildInfo"];
1595+
tracing.begin(...tracingData);
15941596
performance.mark("beforeEmit");
15951597
const emitResult = emitFiles(
15961598
notImplementedResolver,
@@ -1603,7 +1605,7 @@ namespace ts {
16031605

16041606
performance.mark("afterEmit");
16051607
performance.measure("Emit", "beforeEmit", "afterEmit");
1606-
tracing.end();
1608+
tracing.end(...tracingData);
16071609
return emitResult;
16081610
}
16091611

@@ -1664,9 +1666,10 @@ namespace ts {
16641666
}
16651667

16661668
function emit(sourceFile?: SourceFile, writeFileCallback?: WriteFileCallback, cancellationToken?: CancellationToken, emitOnlyDtsFiles?: boolean, transformers?: CustomTransformers, forceDtsEmit?: boolean): EmitResult {
1667-
tracing.begin(tracing.Phase.Emit, "emit", { path: sourceFile?.path });
1669+
const tracingData: tracing.EventData = [tracing.Phase.Emit, "emit", { path: sourceFile?.path }];
1670+
tracing.begin(...tracingData);
16681671
const result = runWithCancellationToken(() => emitWorker(program, sourceFile, writeFileCallback, cancellationToken, emitOnlyDtsFiles, transformers, forceDtsEmit));
1669-
tracing.end();
1672+
tracing.end(...tracingData);
16701673
return result;
16711674
}
16721675

‎src/compiler/tracing.ts

Lines changed: 42 additions & 30 deletions
Original file line numberDiff line numberDiff line change
@@ -46,7 +46,15 @@ namespace ts.tracing {
4646
});
4747

4848
traceFd = fs.openSync(tracePath, "w");
49-
fs.writeSync(traceFd, `[\n`);
49+
50+
// Start with a prefix that contains some metadata that the devtools profiler expects (also avoids a warning on import)
51+
const meta = { cat: "__metadata", ph: "M", ts: 1000 * timestamp(), pid: 1, tid: 1 };
52+
fs.writeSync(traceFd,
53+
"[\n"
54+
+ [{ name: "process_name", args: { name: "tsc" }, ...meta },
55+
{ name: "thread_name", args: { name: "Main" }, ...meta },
56+
{ name: "TracingStartedInBrowser", ...meta, cat: "disabled-by-default-devtools.timeline" }]
57+
.map(v => JSON.stringify(v)).join(",\n"));
5058
}
5159

5260
/** 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 {
5866

5967
Debug.assert(fs);
6068

61-
// This both indicates that the trace is untruncated and conveniently
62-
// ensures that the last array element won't have a trailing comma.
63-
fs.writeSync(traceFd, `{"pid":1,"tid":1,"ph":"i","ts":${1000 * timestamp()},"name":"done","s":"g"}\n`);
64-
fs.writeSync(traceFd, `]\n`);
65-
69+
fs.writeSync(traceFd, `\n]\n`);
6670
fs.closeSync(traceFd);
6771
traceFd = undefined;
6872

@@ -88,38 +92,46 @@ namespace ts.tracing {
8892
Emit = "emit",
8993
}
9094

91-
export function begin(phase: Phase, name: string, args: object) {
92-
if (!traceFd) {
93-
return;
94-
}
95-
Debug.assert(fs);
95+
export type EventData = [phase: Phase, name: string, args?: object];
9696

97-
performance.mark("beginTracing");
98-
fs.writeSync(traceFd, `{"pid":1,"tid":1,"ph":"B","cat":"${phase}","ts":${1000 * timestamp()},"name":"${name}","args":{ "ts": ${JSON.stringify(args)} }},\n`);
99-
performance.mark("endTracing");
100-
performance.measure("Tracing", "beginTracing", "endTracing");
97+
/** Note: `push`/`pop` should be used by default.
98+
* `begin`/`end` are for special cases where we need the data point even if the event never
99+
* terminates (typically for reducing a scenario too big to trace to one that can be completed).
100+
* In the future we might implement an exit handler to dump unfinished events which would
101+
* deprecate these operations.
102+
*/
103+
export function begin(phase: Phase, name: string, args?: object) {
104+
writeEvent("B", phase, name, args);
105+
}
106+
export function end(phase: Phase, name: string, args?: object) {
107+
writeEvent("E", phase, name, args);
101108
}
102109

103-
export function end() {
104-
if (!traceFd) {
105-
return;
106-
}
107-
Debug.assert(fs);
110+
export function instant(phase: Phase, name: string, args?: object) {
111+
writeEvent("I", phase, name, args, `"s":"g"`);
112+
}
108113

109-
performance.mark("beginTracing");
110-
fs.writeSync(traceFd, `{"pid":1,"tid":1,"ph":"E","ts":${1000 * timestamp()}},\n`);
111-
performance.mark("endTracing");
112-
performance.measure("Tracing", "beginTracing", "endTracing");
114+
// Used for "Complete" (ph:"X") events
115+
const completeEvents: { phase: Phase, name: string, args?: object, time: number }[] = [];
116+
export function push(phase: Phase, name: string, args?: object) {
117+
completeEvents.push({ phase, name, args, time: 1000 * timestamp() });
118+
}
119+
export function pop() {
120+
Debug.assert(completeEvents.length > 0);
121+
const { phase, name, args, time } = completeEvents.pop()!;
122+
const dur = 1000 * timestamp() - time;
123+
writeEvent("X", phase, name, args, `"dur":${dur}`, time);
113124
}
114125

115-
export function instant(phase: Phase, name: string, args: object) {
116-
if (!traceFd) {
117-
return;
118-
}
126+
function writeEvent(eventType: string, phase: Phase, name: string, args: object | undefined, extras?: string,
127+
time: number = 1000 * timestamp()) {
128+
if (!traceFd) return;
119129
Debug.assert(fs);
120-
121130
performance.mark("beginTracing");
122-
fs.writeSync(traceFd, `{"pid":1,"tid":1,"ph":"i","cat":"${phase}","ts":${1000 * timestamp()},"name":"${name}","s":"g","args":{ "ts": ${JSON.stringify(args)} }},\n`);
131+
fs.writeSync(traceFd, `,\n{"pid":1,"tid":1,"ph":"${eventType}","cat":"${phase}","ts":${time},"name":"${name}"`);
132+
if (extras) fs.writeSync(traceFd, `,${extras}`);
133+
if (args) fs.writeSync(traceFd, `,"args":${JSON.stringify(args)}`);
134+
fs.writeSync(traceFd, `}`);
123135
performance.mark("endTracing");
124136
performance.measure("Tracing", "beginTracing", "endTracing");
125137
}

‎src/compiler/transformer.ts

Lines changed: 2 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -223,9 +223,9 @@ namespace ts {
223223
// Transform each node.
224224
const transformed: T[] = [];
225225
for (const node of nodes) {
226-
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 });
226+
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 });
227227
transformed.push((allowDtsFiles ? transformation : transformRoot)(node));
228-
tracing.end();
228+
tracing.pop();
229229
}
230230

231231
// prevent modification of the lexical environment.

0 commit comments

Comments
 (0)