Skip to content

Commit eb3f357

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 1074fd4 commit eb3f357

File tree

7 files changed

+76
-57
lines changed

7 files changed

+76
-57
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 tracingInfo: tracing.EventData = [tracing.Phase.Bind, "bindSourceFile", { path: file.path }];
178+
tracing.begin(...tracingInfo);
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(...tracingInfo);
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
@@ -17259,9 +17259,9 @@ namespace ts {
1725917259
}
1726017260

1726117261
function structuredTypeRelatedTo(source: Type, target: Type, reportErrors: boolean, intersectionState: IntersectionState): Ternary {
17262-
tracing.begin(tracing.Phase.Check, "structuredTypeRelatedTo", { sourceId: source.id, targetId: target.id });
17262+
tracing.push(tracing.Phase.Check, "structuredTypeRelatedTo", { sourceId: source.id, targetId: target.id });
1726317263
const result = structuredTypeRelatedToWorker(source, target, reportErrors, intersectionState);
17264-
tracing.end();
17264+
tracing.pop();
1726517265
return result;
1726617266
}
1726717267

@@ -18516,7 +18516,7 @@ namespace ts {
1851618516
function getVariancesWorker<TCache extends { variances?: VarianceFlags[] }>(typeParameters: readonly TypeParameter[] = emptyArray, cache: TCache, createMarkerType: (input: TCache, param: TypeParameter, marker: Type) => Type): VarianceFlags[] {
1851718517
let variances = cache.variances;
1851818518
if (!variances) {
18519-
tracing.begin(tracing.Phase.Check, "getVariancesWorker", { arity: typeParameters.length, id: (cache as any).id ?? (cache as any).declaredType?.id ?? -1 });
18519+
tracing.push(tracing.Phase.Check, "getVariancesWorker", { arity: typeParameters.length, id: (cache as any).id ?? (cache as any).declaredType?.id ?? -1 });
1852018520
// The emptyArray singleton is used to signal a recursive invocation.
1852118521
cache.variances = emptyArray;
1852218522
variances = [];
@@ -18551,7 +18551,7 @@ namespace ts {
1855118551
variances.push(variance);
1855218552
}
1855318553
cache.variances = variances;
18554-
tracing.end();
18554+
tracing.pop();
1855518555
}
1855618556
return variances;
1855718557
}
@@ -30966,7 +30966,7 @@ namespace ts {
3096630966
}
3096730967

3096830968
function checkExpression(node: Expression | QualifiedName, checkMode?: CheckMode, forceTuple?: boolean): Type {
30969-
tracing.begin(tracing.Phase.Check, "checkExpression", { kind: node.kind, pos: node.pos, end: node.end });
30969+
tracing.push(tracing.Phase.Check, "checkExpression", { kind: node.kind, pos: node.pos, end: node.end });
3097030970
const saveCurrentNode = currentNode;
3097130971
currentNode = node;
3097230972
instantiationCount = 0;
@@ -30976,7 +30976,7 @@ namespace ts {
3097630976
checkConstEnumAccess(node, type);
3097730977
}
3097830978
currentNode = saveCurrentNode;
30979-
tracing.end();
30979+
tracing.pop();
3098030980
return type;
3098130981
}
3098230982

@@ -33767,10 +33767,10 @@ namespace ts {
3376733767
}
3376833768

3376933769
function checkVariableDeclaration(node: VariableDeclaration) {
33770-
tracing.begin(tracing.Phase.Check, "checkVariableDeclaration", { kind: node.kind, pos: node.pos, end: node.end });
33770+
tracing.push(tracing.Phase.Check, "checkVariableDeclaration", { kind: node.kind, pos: node.pos, end: node.end });
3377133771
checkGrammarVariableDeclaration(node);
3377233772
checkVariableLikeDeclaration(node);
33773-
tracing.end();
33773+
tracing.pop();
3377433774
}
3377533775

3377633776
function checkBindingElement(node: BindingElement) {
@@ -36841,12 +36841,13 @@ namespace ts {
3684136841
}
3684236842

3684336843
function checkSourceFile(node: SourceFile) {
36844-
tracing.begin(tracing.Phase.Check, "checkSourceFile", { path: node.path });
36844+
const tracingInfo: tracing.EventData = [tracing.Phase.Check, "checkSourceFile", { path: node.path }];
36845+
tracing.begin(...tracingInfo);
3684536846
performance.mark("beforeCheck");
3684636847
checkSourceFileWorker(node);
3684736848
performance.mark("afterCheck");
3684836849
performance.measure("Check", "beforeCheck", "afterCheck");
36849-
tracing.end();
36850+
tracing.end(...tracingInfo);
3685036851
}
3685136852

3685236853
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 tracingInfo: tracing.EventData = [tracing.Phase.Parse, "createSourceFile", { path: fileName }];
618+
tracing.begin(...tracingInfo);
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(...tracingInfo);
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 tracingInfo: tracing.EventData = [tracing.Phase.Program, "createProgram"];
784+
tracing.begin(...tracingInfo);
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(...tracingInfo);
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 tracingInfo: tracing.EventData = [tracing.Phase.Emit, "emitBuildInfo"];
1595+
tracing.begin(...tracingInfo);
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(...tracingInfo);
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 tracingInfo: tracing.EventData = [tracing.Phase.Emit, "emit", { path: sourceFile?.path }];
1670+
tracing.begin(...tracingInfo);
16681671
const result = runWithCancellationToken(() => emitWorker(program, sourceFile, writeFileCallback, cancellationToken, emitOnlyDtsFiles, transformers, forceDtsEmit));
1669-
tracing.end();
1672+
tracing.end(...tracingInfo);
16701673
return result;
16711674
}
16721675

‎src/compiler/tracing.ts

Lines changed: 42 additions & 29 deletions
Original file line numberDiff line numberDiff line change
@@ -46,7 +46,16 @@ 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,")
58+
+ "\n");
5059
}
5160

5261
/** 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 {
5867

5968
Debug.assert(fs);
6069

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`);
6470
fs.writeSync(traceFd, `]\n`);
65-
6671
fs.closeSync(traceFd);
6772
traceFd = undefined;
6873

@@ -88,38 +93,46 @@ namespace ts.tracing {
8893
Emit = "emit",
8994
}
9095

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

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");
98+
/** Note: `push`/`pop` should be used by default.
99+
* `begin`/`end` aren for special cases where we need the data point even if the event never
100+
* terminates (typically for reducing a scenario too big to trace to one that can be completed).
101+
* In the future we might implement an exit handler to dump unfinished events which would
102+
* deprecate these operations.
103+
*/
104+
export function begin(phase: Phase, name: string, args?: object) {
105+
writeEvent("B", phase, name, args);
106+
}
107+
export function end(phase: Phase, name: string, args?: object) {
108+
writeEvent("E", phase, name, args);
101109
}
102110

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

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");
115+
// Used for "Complete" (ph:"X") events
116+
const completeEvents: { phase: Phase, name: string, args?: object, time: number }[] = [];
117+
export function push(phase: Phase, name: string, args?: object) {
118+
completeEvents.push({ phase, name, args, time: 1000 * timestamp() });
119+
}
120+
export function pop() {
121+
Debug.assert(completeEvents.length > 0);
122+
const { phase, name, args, time } = completeEvents.pop()!;
123+
const dur = 1000 * timestamp() - time;
124+
writeEvent("X", phase, name, args, `"dur":${dur}`, time);
113125
}
114126

115-
export function instant(phase: Phase, name: string, args: object) {
116-
if (!traceFd) {
117-
return;
118-
}
127+
function writeEvent(eventType: string, phase: Phase, name: string, args: object | undefined, extras?: string,
128+
time: number = 1000 * timestamp()) {
129+
if (!traceFd) return;
119130
Debug.assert(fs);
120-
121131
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`);
132+
fs.writeSync(traceFd, `,{"pid":1,"tid":1,"ph":"${eventType}","cat":"${phase}","ts":${time},"name":"${name}"`);
133+
if (extras) fs.writeSync(traceFd, `,${extras}`);
134+
if (args) fs.writeSync(traceFd, `,"args":${JSON.stringify(args)}`);
135+
fs.writeSync(traceFd, `}\n`);
123136
performance.mark("endTracing");
124137
performance.measure("Tracing", "beginTracing", "endTracing");
125138
}

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