Skip to content

Commit 03a2606

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 03a2606

File tree

7 files changed

+59
-53
lines changed

7 files changed

+59
-53
lines changed

‎src/compiler/binder.ts

Lines changed: 1 addition & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -181,7 +181,7 @@ namespace ts {
181181
perfLogger.logStopBindFile();
182182
performance.mark("afterBind");
183183
performance.measure("Bind", "beforeBind", "afterBind");
184-
tracing.end();
184+
tracing.end(tracing.Phase.Bind, "bindSourceFile", { path: file.path });
185185
}
186186

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

‎src/compiler/checker.ts

Lines changed: 9 additions & 9 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) {
@@ -36846,7 +36846,7 @@ namespace ts {
3684636846
checkSourceFileWorker(node);
3684736847
performance.mark("afterCheck");
3684836848
performance.measure("Check", "beforeCheck", "afterCheck");
36849-
tracing.end();
36849+
tracing.end(tracing.Phase.Check, "checkSourceFile", { path: node.path });
3685036850
}
3685136851

3685236852
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: 1 addition & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -629,7 +629,7 @@ namespace ts {
629629

630630
performance.mark("afterParse");
631631
performance.measure("Parse", "beforeParse", "afterParse");
632-
tracing.end();
632+
tracing.end(tracing.Phase.Parse, "createSourceFile", { path: fileName });
633633
return result;
634634
}
635635

‎src/compiler/program.ts

Lines changed: 5 additions & 5 deletions
Original file line numberDiff line numberDiff line change
@@ -780,7 +780,7 @@ 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+
tracing.begin(tracing.Phase.Program, "createProgram");
784784
performance.mark("beforeProgram");
785785

786786
const host = createProgramOptions.host || createCompilerHost(options);
@@ -1032,7 +1032,7 @@ namespace ts {
10321032
verifyCompilerOptions();
10331033
performance.mark("afterProgram");
10341034
performance.measure("Program", "beforeProgram", "afterProgram");
1035-
tracing.end();
1035+
tracing.end(tracing.Phase.Program, "createProgram");
10361036

10371037
return program;
10381038

@@ -1590,7 +1590,7 @@ namespace ts {
15901590

15911591
function emitBuildInfo(writeFileCallback?: WriteFileCallback): EmitResult {
15921592
Debug.assert(!outFile(options));
1593-
tracing.begin(tracing.Phase.Emit, "emitBuildInfo", {});
1593+
tracing.begin(tracing.Phase.Emit, "emitBuildInfo");
15941594
performance.mark("beforeEmit");
15951595
const emitResult = emitFiles(
15961596
notImplementedResolver,
@@ -1603,7 +1603,7 @@ namespace ts {
16031603

16041604
performance.mark("afterEmit");
16051605
performance.measure("Emit", "beforeEmit", "afterEmit");
1606-
tracing.end();
1606+
tracing.end(tracing.Phase.Emit, "emitBuildInfo");
16071607
return emitResult;
16081608
}
16091609

@@ -1666,7 +1666,7 @@ namespace ts {
16661666
function emit(sourceFile?: SourceFile, writeFileCallback?: WriteFileCallback, cancellationToken?: CancellationToken, emitOnlyDtsFiles?: boolean, transformers?: CustomTransformers, forceDtsEmit?: boolean): EmitResult {
16671667
tracing.begin(tracing.Phase.Emit, "emit", { path: sourceFile?.path });
16681668
const result = runWithCancellationToken(() => emitWorker(program, sourceFile, writeFileCallback, cancellationToken, emitOnlyDtsFiles, transformers, forceDtsEmit));
1669-
tracing.end();
1669+
tracing.end(tracing.Phase.Emit, "emit", { path: sourceFile?.path });
16701670
return result;
16711671
}
16721672

‎src/compiler/tracing.ts

Lines changed: 35 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,39 @@ 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 function begin(phase: Phase, name: string, args?: object) {
97+
writeEvent("B", phase, name, args);
98+
}
9699

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");
100+
export function end(phase: Phase, name: string, args?: object) {
101+
writeEvent("E", phase, name, args);
101102
}
102103

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

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");
108+
// Used for "Complete" (ph:"X") events
109+
const completeEvents: { phase: Phase, name: string, args?: object, time: number }[] = [];
110+
export function push(phase: Phase, name: string, args?: object) {
111+
completeEvents.push({ phase, name, args, time: 1000 * timestamp() });
112+
}
113+
export function pop() {
114+
Debug.assert(completeEvents.length > 0);
115+
const { phase, name, args, time } = completeEvents.pop()!;
116+
const dur = 1000 * timestamp() - time;
117+
writeEvent("X", phase, name, args, `"dur":${dur}`, time);
113118
}
114119

115-
export function instant(phase: Phase, name: string, args: object) {
116-
if (!traceFd) {
117-
return;
118-
}
120+
function writeEvent(eventType: string, phase: Phase, name: string, args: object | undefined, extras?: string,
121+
time: number = 1000 * timestamp()) {
122+
if (!traceFd) return;
119123
Debug.assert(fs);
120-
121124
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`);
125+
fs.writeSync(traceFd, `,{"pid":1,"tid":1,"ph":"${eventType}","cat":"${phase}","ts":${time},"name":"${name}"`);
126+
if (extras) fs.writeSync(traceFd, `,${extras}`);
127+
if (args) fs.writeSync(traceFd, `,"args":${JSON.stringify(args)}`);
128+
fs.writeSync(traceFd, `}\n`);
123129
performance.mark("endTracing");
124130
performance.measure("Tracing", "beginTracing", "endTracing");
125131
}

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