Trace key operations

[amcasey]

Produce output in Chrome's event tracing format so that it can be viewed in Chrome/Edge.

Hat tip to @samccone for suggesting the format.

[amcasey]

There are some noteworthy rough edges:

1. I haven't thought through how to separate/combine the traces for different projects in build mode, so presently I just insert a counter into each path to prevent clobbering.
2. The new System APIs are ugly, but I think it's important to write as you go, so that you get something if you have to kill a very long build (e.g. customers reporting tens of minutes)
3. Some types are still only readable by means of typeToTypeNode and I'd really like to eliminate that because of how slow it is (not urgent since it happens after profiling is complete)

Updates:

1. Only use counters in build mode and print a separate legend file mapping them back to tsconfig paths.
2. Reverted - @RyanCavanaugh suggested using fs directly.
3. Will likely wait for a future PR.

[amcasey]

CI failures are because I didn't update the harness System impl(s). That can wait until next week.

[amcasey]

There are deliberately few trace events in the checker to avoid (excessively) skewing the runtime. If people would like to see more, e.g. for debugging, my inclination would be to add a separate mode (i.e. profiling trace vs activity trace). Note that the persistence format is JSON, so it's very easy to create enormous trace files (e.g. adding inferFromTypes tripled the file size for one sample project).

[rbuckton]

Have you looked at the sources for ts-perf? I made some headway doing the same thing with the existing performance.mark function and have code for generating Chrome timelines.

[amcasey]

Rough instructions for using it in its present state:

1. Append --generateTrace {folderName} to your regular tsc command line
2. Look in the resulting folder. If you used build mode, there will be a legend.json telling you what went where. Otherwise, there will be a trace.json file and a types.json files.
3. Navigate to edge://tracing or chrome://tracing and Load trace.json
4. Expand Process 1 with the little triangle in the left sidebar
5. Click on different blocks to see their payloads in the bottom pane
6. Open types.json in an editor
7. When you see a type ID in the tracing output, go-to-line {id} to find data about that type

[amcasey]

Having applied this to several repos now, I feel pretty confident that this is useful in its current state. Enriching it with additional tracepoints (e.g. for inference) or output (e.g. stack traces) can follow in future PRs.

[rbuckton]

In the future we might be able to move some of this logic to a conditionally loaded module, similar to the extended debug information for flow nodes in ~/src/debug/dbg.ts loaded by ~/src/compiler/debug.ts:

TypeScript/src/compiler/debug.ts

Lines 655 to 668 in d896353

	// attempt to load extended debugging information
	try {
	if (sys && sys.require) {
	const basePath = getDirectoryPath(resolvePath(sys.getExecutingFilePath()));
	const result = sys.require(basePath, "./compiler-debug") as RequireResult<ExtendedDebugModule>;
	if (!result.error) {
	result.module.init(ts);
	extendedDebugModule = result.module;
	}
	}
	}
	catch {
	// do nothing
	}

I've been thinking about moving more of ts.Debug into the external file to reduce the file size of tsc.js, typescript.js, and tsserver.js as well.

This obviously isn't something we need to do now, but we might want to consider putting it on the backlog.

[phryneas]

@amcasey I'm having the problem that checkExpression calls within a checkSourceFile call often check nodes from completely different files, so just having kind, pos and end is not enough to identify the node in any way.

I am running this patch against 4.1.0-beta to also get the fileName - but I guess that is not really effective.
Could this be done somehow in a better way - and would a PR for this be welcome?

diff --git a/lib/tsc.js b/lib/tsc.js
index c78b8d698ea730be5a363592a25eb5eb9815753b..4333d58e45d2b2a55724ce7f7894c482223fc36c 100644
--- a/lib/tsc.js
+++ b/lib/tsc.js
@@ -59317,7 +59317,13 @@ var ts;
             }
         }
         function checkExpression(node, checkMode, forceTuple) {
-            ts.tracing.begin("check", "checkExpression", { kind: node.kind, pos: node.pos, end: node.end });
+            var parent = node.parent;
+            while (parent && parent.kind !== 300 /*SyntaxKind.SourceFile*/) {
+                parent = parent.parent
+            }
+            var sourceFile = parent;
+
+            ts.tracing.begin("check", "checkExpression", { kind: node.kind, pos: node.pos, end: node.end, sourceFile: sourceFile && sourceFile.fileName || "unknown" });
             var saveCurrentNode = currentNode;
             currentNode = node;
             instantiationCount = 0;

[amcasey]

@phryneas Thanks for the patch! I had an early version that included similar code (there's actually a helper for walking up to the source file) but concluded that the extra tree walking was distorting the timing and the paths were bloating the log file excessively. Since readability wasn't a goal for v1, I left it out. When I've encountered the problem in practice, I've used code inspection on the frames that are in the right file plus types from later in the call stack to work out what was going on.

p.s. Sorry about the confusion this caused you - it's frustrating to waste time on things like that.