Skip to content

Commit 79ffd03

Browse files
amcaseyamcasey
authored
Add tracing support to tsserver (microsoft#41374)
* Add tracing support to tsserver Read the `TSS_TRACE` environment variable to determine which directory trace files should be written to. Notable changes from tsc tracing: 1) Drop all tracepoints that depend on type IDs 2) Write output to trace.PID.json 3) New, server-specific events (request/response, cancellation, etc) * Drop try-finally blocks that aren't strictly necessary * Fix lint error * Trace background work (for diagnostics) * Move try-finally blocks into session so tsc doesn't use them * Add missing try-finally * Use consistent capitalization * Inline canPop call where underlying variable is available * Clarify comments * Include PID in build-mode file names * Introduce more efficient popAll function * Trace throwIfCancellationRequested rather than isCancellationRequested * Remove unnecessary try-finally blocks * Add a command-line argument for consistency with logging * Fix rebase issues * Address PR feedback * Rename completionEvents to eventStack * Drop assertStackEmpty as hard-to-maintain and marginally valuable * Rename stepCancellation to stepCanceledEarly * Rename stepEarlyCancellation to stepCanceled and use flag instead * Check correct variable on exit
1 parent 4885dec commit 79ffd03

7 files changed

Lines changed: 99 additions & 28 deletions

File tree

‎src/compiler/checker.ts‎

Lines changed: 10 additions & 10 deletions
Original file line numberDiff line numberDiff line change
@@ -10973,7 +10973,7 @@ namespace ts {
1097310973
// very high likelihood we're dealing with an infinite generic type that perpetually generates
1097410974
// new type identities as we descend into it. We stop the recursion here and mark this type
1097510975
// and the outer types as having circular constraints.
10976-
tracing.instant(tracing.Phase.Check, "getImmediateBaseConstraint_DepthLimit", { typeId: t.id, originalTypeId: type.id, depth: constraintDepth });
10976+
tracing.instant(tracing.Phase.CheckTypes, "getImmediateBaseConstraint_DepthLimit", { typeId: t.id, originalTypeId: type.id, depth: constraintDepth });
1097710977
error(currentNode, Diagnostics.Type_instantiation_is_excessively_deep_and_possibly_infinite);
1097810978
nonTerminating = true;
1097910979
return t.immediateBaseConstraint = noConstraintType;
@@ -13083,7 +13083,7 @@ namespace ts {
1308313083
// caps union types at 5000 unique literal types and 1000 unique object types.
1308413084
const estimatedCount = (count / (len - i)) * len;
1308513085
if (estimatedCount > (primitivesOnly ? 25000000 : 1000000)) {
13086-
tracing.instant(tracing.Phase.Check, "removeSubtypes_DepthLimit", { typeIds: types.map(t => t.id) });
13086+
tracing.instant(tracing.Phase.CheckTypes, "removeSubtypes_DepthLimit", { typeIds: types.map(t => t.id) });
1308713087
error(currentNode, Diagnostics.Expression_produces_a_union_type_that_is_too_complex_to_represent);
1308813088
return false;
1308913089
}
@@ -13505,7 +13505,7 @@ namespace ts {
1350513505
function checkCrossProductUnion(types: readonly Type[]) {
1350613506
const size = reduceLeft(types, (n, t) => n * (t.flags & TypeFlags.Union ? (<UnionType>t).types.length : t.flags & TypeFlags.Never ? 0 : 1), 1);
1350713507
if (size >= 100000) {
13508-
tracing.instant(tracing.Phase.Check, "checkCrossProductUnion_DepthLimit", { typeIds: types.map(t => t.id), size });
13508+
tracing.instant(tracing.Phase.CheckTypes, "checkCrossProductUnion_DepthLimit", { typeIds: types.map(t => t.id), size });
1350913509
error(currentNode, Diagnostics.Expression_produces_a_union_type_that_is_too_complex_to_represent);
1351013510
return false;
1351113511
}
@@ -15381,7 +15381,7 @@ namespace ts {
1538115381
// We have reached 50 recursive type instantiations and there is a very high likelyhood we're dealing
1538215382
// with a combination of infinite generic types that perpetually generate new type identities. We stop
1538315383
// the recursion here by yielding the error type.
15384-
tracing.instant(tracing.Phase.Check, "instantiateType_DepthLimit", { typeId: type.id, instantiationDepth, instantiationCount });
15384+
tracing.instant(tracing.Phase.CheckTypes, "instantiateType_DepthLimit", { typeId: type.id, instantiationDepth, instantiationCount });
1538515385
error(currentNode, Diagnostics.Type_instantiation_is_excessively_deep_and_possibly_infinite);
1538615386
return errorType;
1538715387
}
@@ -16504,7 +16504,7 @@ namespace ts {
1650416504
reportIncompatibleStack();
1650516505
}
1650616506
if (overflow) {
16507-
tracing.instant(tracing.Phase.Check, "checkTypeRelatedTo_DepthLimit", { sourceId: source.id, targetId: target.id, depth });
16507+
tracing.instant(tracing.Phase.CheckTypes, "checkTypeRelatedTo_DepthLimit", { sourceId: source.id, targetId: target.id, depth });
1650816508
const diag = error(errorNode || currentNode, Diagnostics.Excessive_stack_depth_comparing_types_0_and_1, typeToString(source), typeToString(target));
1650916509
if (errorOutputContainer) {
1651016510
(errorOutputContainer.errors || (errorOutputContainer.errors = [])).push(diag);
@@ -17327,7 +17327,7 @@ namespace ts {
1732717327
}
1732817328

1732917329
if (expandingFlags === ExpandingFlags.Both) {
17330-
tracing.instant(tracing.Phase.Check, "recursiveTypeRelatedTo_DepthLimit", {
17330+
tracing.instant(tracing.Phase.CheckTypes, "recursiveTypeRelatedTo_DepthLimit", {
1733117331
sourceId: source.id,
1733217332
sourceIdStack: sourceStack.map(t => t.id),
1733317333
targetId: target.id,
@@ -17364,7 +17364,7 @@ namespace ts {
1736417364
}
1736517365

1736617366
function structuredTypeRelatedTo(source: Type, target: Type, reportErrors: boolean, intersectionState: IntersectionState): Ternary {
17367-
tracing.push(tracing.Phase.Check, "structuredTypeRelatedTo", { sourceId: source.id, targetId: target.id });
17367+
tracing.push(tracing.Phase.CheckTypes, "structuredTypeRelatedTo", { sourceId: source.id, targetId: target.id });
1736817368
const result = structuredTypeRelatedToWorker(source, target, reportErrors, intersectionState);
1736917369
tracing.pop();
1737017370
return result;
@@ -17860,7 +17860,7 @@ namespace ts {
1786017860
numCombinations *= countTypes(getTypeOfSymbol(sourceProperty));
1786117861
if (numCombinations > 25) {
1786217862
// We've reached the complexity limit.
17863-
tracing.instant(tracing.Phase.Check, "typeRelatedToDiscriminatedType_DepthLimit", { sourceId: source.id, targetId: target.id, numCombinations });
17863+
tracing.instant(tracing.Phase.CheckTypes, "typeRelatedToDiscriminatedType_DepthLimit", { sourceId: source.id, targetId: target.id, numCombinations });
1786417864
return Ternary.False;
1786517865
}
1786617866
}
@@ -18621,7 +18621,7 @@ namespace ts {
1862118621
function getVariancesWorker<TCache extends { variances?: VarianceFlags[] }>(typeParameters: readonly TypeParameter[] = emptyArray, cache: TCache, createMarkerType: (input: TCache, param: TypeParameter, marker: Type) => Type): VarianceFlags[] {
1862218622
let variances = cache.variances;
1862318623
if (!variances) {
18624-
tracing.push(tracing.Phase.Check, "getVariancesWorker", { arity: typeParameters.length, id: (cache as any).id ?? (cache as any).declaredType?.id ?? -1 });
18624+
tracing.push(tracing.Phase.CheckTypes, "getVariancesWorker", { arity: typeParameters.length, id: (cache as any).id ?? (cache as any).declaredType?.id ?? -1 });
1862518625
// The emptyArray singleton is used to signal a recursive invocation.
1862618626
cache.variances = emptyArray;
1862718627
variances = [];
@@ -21719,7 +21719,7 @@ namespace ts {
2171921719
if (flowDepth === 2000) {
2172021720
// We have made 2000 recursive invocations. To avoid overflowing the call stack we report an error
2172121721
// and disable further control flow analysis in the containing function or module body.
21722-
tracing.instant(tracing.Phase.Check, "getTypeAtFlowNode_DepthLimit", { flowId: flow.id });
21722+
tracing.instant(tracing.Phase.CheckTypes, "getTypeAtFlowNode_DepthLimit", { flowId: flow.id });
2172321723
flowAnalysisDisabled = true;
2172421724
reportFlowControlError(reference);
2172521725
return errorType;

‎src/compiler/program.ts‎

Lines changed: 1 addition & 1 deletion
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.push(tracing.Phase.Program, "createProgram", {}, /*separateBeginAndEnd*/ true);
783+
tracing.push(tracing.Phase.Program, "createProgram", { configFilePath: options.configFilePath, rootDir: options.rootDir }, /*separateBeginAndEnd*/ true);
784784
performance.mark("beforeProgram");
785785

786786
const host = createProgramOptions.host || createCompilerHost(options);

‎src/compiler/tracing.ts‎

Lines changed: 42 additions & 12 deletions
Original file line numberDiff line numberDiff line change
@@ -1,16 +1,24 @@
11
/*@internal*/
22
/** Tracing events for the compiler. */
33
namespace ts.tracing {
4+
export const enum Mode {
5+
Project,
6+
Build,
7+
Server,
8+
}
9+
410
let fs: typeof import("fs") | false | undefined;
511

612
let traceCount = 0;
713
let traceFd: number | undefined;
814

15+
let mode: Mode;
16+
917
let legendPath: string | undefined;
1018
const legend: TraceRecord[] = [];
1119

1220
/** Starts tracing for the given project (unless the `fs` module is unavailable). */
13-
export function startTracing(configFilePath: string | undefined, traceDir: string, isBuildMode: boolean) {
21+
export function startTracing(tracingMode: Mode, traceDir: string, configFilePath?: string) {
1422
Debug.assert(!traceFd, "Tracing already started");
1523

1624
if (fs === undefined) {
@@ -26,6 +34,8 @@ namespace ts.tracing {
2634
return;
2735
}
2836

37+
mode = tracingMode;
38+
2939
if (legendPath === undefined) {
3040
legendPath = combinePaths(traceDir, "legend.json");
3141
}
@@ -35,7 +45,10 @@ namespace ts.tracing {
3545
fs.mkdirSync(traceDir, { recursive: true });
3646
}
3747

38-
const countPart = isBuildMode ? `.${++traceCount}` : ``;
48+
const countPart =
49+
mode === Mode.Build ? `.${process.pid}-${++traceCount}` :
50+
mode === Mode.Server ? `.${process.pid}` :
51+
``;
3952
const tracePath = combinePaths(traceDir, `trace${countPart}.json`);
4053
const typesPath = combinePaths(traceDir, `types${countPart}.json`);
4154

@@ -58,13 +71,14 @@ namespace ts.tracing {
5871
}
5972

6073
/** Stops tracing for the in-progress project and dumps the type catalog (unless the `fs` module is unavailable). */
61-
export function stopTracing(typeCatalog: readonly Type[]) {
74+
export function stopTracing(typeCatalog?: readonly Type[]) {
6275
if (!traceFd) {
6376
Debug.assert(!fs, "Tracing is not in progress");
6477
return;
6578
}
6679

6780
Debug.assert(fs);
81+
Debug.assert(!!typeCatalog === (mode !== Mode.Server)); // Have a type catalog iff not in server mode
6882

6983
fs.writeSync(traceFd, `\n]\n`);
7084
fs.closeSync(traceFd);
@@ -88,17 +102,18 @@ namespace ts.tracing {
88102
Parse = "parse",
89103
Program = "program",
90104
Bind = "bind",
91-
Check = "check",
105+
Check = "check", // Before we get into checking types (e.g. checkSourceFile)
106+
CheckTypes = "checkTypes",
92107
Emit = "emit",
108+
Session = "session",
93109
}
94110

95111
export function instant(phase: Phase, name: string, args?: object) {
96112
if (!traceFd) return;
97113
writeEvent("I", phase, name, args, `"s":"g"`);
98114
}
99115

100-
// Used for "Complete" (ph:"X") events
101-
const completeEvents: { phase: Phase, name: string, args?: object, time: number, separateBeginAndEnd: boolean }[] = [];
116+
const eventStack: { phase: Phase, name: string, args?: object, time: number, separateBeginAndEnd: boolean }[] = [];
102117

103118
/**
104119
* @param separateBeginAndEnd - used for special cases where we need the trace point even if the event
@@ -111,25 +126,40 @@ namespace ts.tracing {
111126
if (separateBeginAndEnd) {
112127
writeEvent("B", phase, name, args);
113128
}
114-
completeEvents.push({ phase, name, args, time: 1000 * timestamp(), separateBeginAndEnd });
129+
eventStack.push({ phase, name, args, time: 1000 * timestamp(), separateBeginAndEnd });
115130
}
116131
export function pop() {
117132
if (!traceFd) return;
118-
Debug.assert(completeEvents.length > 0);
119-
const { phase, name, args, time, separateBeginAndEnd } = completeEvents.pop()!;
133+
Debug.assert(eventStack.length > 0);
134+
writeStackEvent(eventStack.length - 1, 1000 * timestamp());
135+
eventStack.length--;
136+
}
137+
export function popAll() {
138+
if (!traceFd) return;
139+
const endTime = 1000 * timestamp();
140+
for (let i = eventStack.length - 1; i >= 0; i--) {
141+
writeStackEvent(i, endTime);
142+
}
143+
eventStack.length = 0;
144+
}
145+
function writeStackEvent(index: number, endTime: number) {
146+
const { phase, name, args, time, separateBeginAndEnd } = eventStack[index];
120147
if (separateBeginAndEnd) {
121-
writeEvent("E", phase, name, args);
148+
writeEvent("E", phase, name, args, /*extras*/ undefined, endTime);
122149
}
123150
else {
124-
const dur = 1000 * timestamp() - time;
125-
writeEvent("X", phase, name, args, `"dur":${dur}`, time);
151+
writeEvent("X", phase, name, args, `"dur":${endTime - time}`, time);
126152
}
127153
}
128154

129155
function writeEvent(eventType: string, phase: Phase, name: string, args: object | undefined, extras?: string,
130156
time: number = 1000 * timestamp()) {
131157
Debug.assert(traceFd);
132158
Debug.assert(fs);
159+
160+
// In server mode, there's no easy way to dump type information, so we drop events that would require it.
161+
if (mode === Mode.Server && phase === Phase.CheckTypes) return;
162+
133163
performance.mark("beginTracing");
134164
fs.writeSync(traceFd, `,\n{"pid":1,"tid":1,"ph":"${eventType}","cat":"${phase}","ts":${time},"name":"${name}"`);
135165
if (extras) fs.writeSync(traceFd, `,${extras}`);

‎src/executeCommandLine/executeCommandLine.ts‎

Lines changed: 1 addition & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -621,7 +621,7 @@ namespace ts {
621621
}
622622

623623
if (canTrace(system, compilerOptions)) {
624-
tracing.startTracing(compilerOptions.configFilePath, compilerOptions.generateTrace!, isBuildMode);
624+
tracing.startTracing(isBuildMode ? tracing.Mode.Build : tracing.Mode.Project, compilerOptions.generateTrace!, compilerOptions.configFilePath);
625625
}
626626
}
627627

‎src/server/session.ts‎

Lines changed: 22 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -208,15 +208,25 @@ namespace ts.server {
208208
try {
209209
if (this.operationHost.isCancellationRequested()) {
210210
stop = true;
211+
tracing.instant(tracing.Phase.Session, "stepCanceled", { seq: this.requestId, early: true });
211212
}
212213
else {
214+
tracing.push(tracing.Phase.Session, "stepAction", { seq: this.requestId });
213215
action(this);
216+
tracing.pop();
214217
}
215218
}
216219
catch (e) {
220+
// Cancellation or an error may have left incomplete events on the tracing stack.
221+
tracing.popAll();
222+
217223
stop = true;
218224
// ignore cancellation request
219-
if (!(e instanceof OperationCanceledException)) {
225+
if (e instanceof OperationCanceledException) {
226+
tracing.instant(tracing.Phase.Session, "stepCanceled", { seq: this.requestId });
227+
}
228+
else {
229+
tracing.instant(tracing.Phase.Session, "stepError", { seq: this.requestId, message: (<Error>e).message });
220230
this.operationHost.logError(e, `delayed processing of request ${this.requestId}`);
221231
}
222232
}
@@ -914,6 +924,7 @@ namespace ts.server {
914924
}
915925

916926
public event<T extends object>(body: T, eventName: string): void {
927+
tracing.instant(tracing.Phase.Session, "event", { eventName });
917928
this.send(toEvent(eventName, body));
918929
}
919930

@@ -2915,8 +2926,12 @@ namespace ts.server {
29152926
request = <protocol.Request>JSON.parse(message);
29162927
relevantFile = request.arguments && (request as protocol.FileRequest).arguments.file ? (request as protocol.FileRequest).arguments : undefined;
29172928

2929+
tracing.instant(tracing.Phase.Session, "request", { seq: request.seq, command: request.command });
29182930
perfLogger.logStartCommand("" + request.command, message.substring(0, 100));
2931+
2932+
tracing.push(tracing.Phase.Session, "executeCommand", { seq: request.seq, command: request.command }, /*separateBeginAndEnd*/ true);
29192933
const { response, responseRequired } = this.executeCommand(request);
2934+
tracing.pop();
29202935

29212936
if (this.logger.hasLevel(LogLevel.requestTime)) {
29222937
const elapsedTime = hrTimeToMilliseconds(this.hrtime(start)).toFixed(4);
@@ -2930,6 +2945,7 @@ namespace ts.server {
29302945

29312946
// Note: Log before writing the response, else the editor can complete its activity before the server does
29322947
perfLogger.logStopCommand("" + request.command, "Success");
2948+
tracing.instant(tracing.Phase.Session, "response", { seq: request.seq, command: request.command, success: !!response });
29332949
if (response) {
29342950
this.doOutput(response, request.command, request.seq, /*success*/ true);
29352951
}
@@ -2938,15 +2954,20 @@ namespace ts.server {
29382954
}
29392955
}
29402956
catch (err) {
2957+
// Cancellation or an error may have left incomplete events on the tracing stack.
2958+
tracing.popAll();
2959+
29412960
if (err instanceof OperationCanceledException) {
29422961
// Handle cancellation exceptions
29432962
perfLogger.logStopCommand("" + (request && request.command), "Canceled: " + err);
2963+
tracing.instant(tracing.Phase.Session, "commandCanceled", { seq: request?.seq, command: request?.command });
29442964
this.doOutput({ canceled: true }, request!.command, request!.seq, /*success*/ true);
29452965
return;
29462966
}
29472967

29482968
this.logErrorWorker(err, message, relevantFile);
29492969
perfLogger.logStopCommand("" + (request && request.command), "Error: " + err);
2970+
tracing.instant(tracing.Phase.Session, "commandError", { seq: request?.seq, command: request?.command, message: (<Error>err).message });
29502971

29512972
this.doOutput(
29522973
/*info*/ undefined,

‎src/services/services.ts‎

Lines changed: 12 additions & 3 deletions
Original file line numberDiff line numberDiff line change
@@ -1126,16 +1126,22 @@ namespace ts {
11261126
return createLanguageServiceSourceFile(sourceFile.fileName, scriptSnapshot, sourceFile.languageVersion, version, /*setNodeParents*/ true, sourceFile.scriptKind);
11271127
}
11281128

1129+
const NoopCancellationToken: CancellationToken = {
1130+
isCancellationRequested: returnFalse,
1131+
throwIfCancellationRequested: noop,
1132+
};
1133+
11291134
class CancellationTokenObject implements CancellationToken {
1130-
constructor(private cancellationToken: HostCancellationToken | undefined) {
1135+
constructor(private cancellationToken: HostCancellationToken) {
11311136
}
11321137

11331138
public isCancellationRequested(): boolean {
1134-
return !!this.cancellationToken && this.cancellationToken.isCancellationRequested();
1139+
return this.cancellationToken.isCancellationRequested();
11351140
}
11361141

11371142
public throwIfCancellationRequested(): void {
11381143
if (this.isCancellationRequested()) {
1144+
tracing.instant(tracing.Phase.Session, "cancellationThrown", { kind: "CancellationTokenObject" });
11391145
throw new OperationCanceledException();
11401146
}
11411147
}
@@ -1166,6 +1172,7 @@ namespace ts {
11661172

11671173
public throwIfCancellationRequested(): void {
11681174
if (this.isCancellationRequested()) {
1175+
tracing.instant(tracing.Phase.Session, "cancellationThrown", { kind: "ThrottledCancellationToken" });
11691176
throw new OperationCanceledException();
11701177
}
11711178
}
@@ -1233,7 +1240,9 @@ namespace ts {
12331240
let lastProjectVersion: string;
12341241
let lastTypesRootVersion = 0;
12351242

1236-
const cancellationToken = new CancellationTokenObject(host.getCancellationToken && host.getCancellationToken());
1243+
const cancellationToken = host.getCancellationToken
1244+
? new CancellationTokenObject(host.getCancellationToken())
1245+
: NoopCancellationToken;
12371246

12381247
const currentDirectory = host.getCurrentDirectory();
12391248
// Check if the localized messages json is set, otherwise query the host for it

0 commit comments

Comments
 (0)