diff --git a/src/compiler/checker.ts b/src/compiler/checker.ts index 93a59dd4cce..55f3a8cd480 100644 --- a/src/compiler/checker.ts +++ b/src/compiler/checker.ts @@ -10973,7 +10973,7 @@ namespace ts { // very high likelihood we're dealing with an infinite generic type that perpetually generates // new type identities as we descend into it. We stop the recursion here and mark this type // and the outer types as having circular constraints. - tracing.instant(tracing.Phase.Check, "getImmediateBaseConstraint_DepthLimit", { typeId: t.id, originalTypeId: type.id, depth: constraintDepth }); + tracing.instant(tracing.Phase.CheckTypes, "getImmediateBaseConstraint_DepthLimit", { typeId: t.id, originalTypeId: type.id, depth: constraintDepth }); error(currentNode, Diagnostics.Type_instantiation_is_excessively_deep_and_possibly_infinite); nonTerminating = true; return t.immediateBaseConstraint = noConstraintType; @@ -13083,7 +13083,7 @@ namespace ts { // caps union types at 5000 unique literal types and 1000 unique object types. const estimatedCount = (count / (len - i)) * len; if (estimatedCount > (primitivesOnly ? 25000000 : 1000000)) { - tracing.instant(tracing.Phase.Check, "removeSubtypes_DepthLimit", { typeIds: types.map(t => t.id) }); + tracing.instant(tracing.Phase.CheckTypes, "removeSubtypes_DepthLimit", { typeIds: types.map(t => t.id) }); error(currentNode, Diagnostics.Expression_produces_a_union_type_that_is_too_complex_to_represent); return false; } @@ -13505,7 +13505,7 @@ namespace ts { function checkCrossProductUnion(types: readonly Type[]) { const size = reduceLeft(types, (n, t) => n * (t.flags & TypeFlags.Union ? (t).types.length : t.flags & TypeFlags.Never ? 0 : 1), 1); if (size >= 100000) { - tracing.instant(tracing.Phase.Check, "checkCrossProductUnion_DepthLimit", { typeIds: types.map(t => t.id), size }); + tracing.instant(tracing.Phase.CheckTypes, "checkCrossProductUnion_DepthLimit", { typeIds: types.map(t => t.id), size }); error(currentNode, Diagnostics.Expression_produces_a_union_type_that_is_too_complex_to_represent); return false; } @@ -15381,7 +15381,7 @@ namespace ts { // We have reached 50 recursive type instantiations and there is a very high likelyhood we're dealing // with a combination of infinite generic types that perpetually generate new type identities. We stop // the recursion here by yielding the error type. - tracing.instant(tracing.Phase.Check, "instantiateType_DepthLimit", { typeId: type.id, instantiationDepth, instantiationCount }); + tracing.instant(tracing.Phase.CheckTypes, "instantiateType_DepthLimit", { typeId: type.id, instantiationDepth, instantiationCount }); error(currentNode, Diagnostics.Type_instantiation_is_excessively_deep_and_possibly_infinite); return errorType; } @@ -16504,7 +16504,7 @@ namespace ts { reportIncompatibleStack(); } if (overflow) { - tracing.instant(tracing.Phase.Check, "checkTypeRelatedTo_DepthLimit", { sourceId: source.id, targetId: target.id, depth }); + tracing.instant(tracing.Phase.CheckTypes, "checkTypeRelatedTo_DepthLimit", { sourceId: source.id, targetId: target.id, depth }); const diag = error(errorNode || currentNode, Diagnostics.Excessive_stack_depth_comparing_types_0_and_1, typeToString(source), typeToString(target)); if (errorOutputContainer) { (errorOutputContainer.errors || (errorOutputContainer.errors = [])).push(diag); @@ -17327,7 +17327,7 @@ namespace ts { } if (expandingFlags === ExpandingFlags.Both) { - tracing.instant(tracing.Phase.Check, "recursiveTypeRelatedTo_DepthLimit", { + tracing.instant(tracing.Phase.CheckTypes, "recursiveTypeRelatedTo_DepthLimit", { sourceId: source.id, sourceIdStack: sourceStack.map(t => t.id), targetId: target.id, @@ -17364,7 +17364,7 @@ namespace ts { } function structuredTypeRelatedTo(source: Type, target: Type, reportErrors: boolean, intersectionState: IntersectionState): Ternary { - tracing.push(tracing.Phase.Check, "structuredTypeRelatedTo", { sourceId: source.id, targetId: target.id }); + tracing.push(tracing.Phase.CheckTypes, "structuredTypeRelatedTo", { sourceId: source.id, targetId: target.id }); const result = structuredTypeRelatedToWorker(source, target, reportErrors, intersectionState); tracing.pop(); return result; @@ -17860,7 +17860,7 @@ namespace ts { numCombinations *= countTypes(getTypeOfSymbol(sourceProperty)); if (numCombinations > 25) { // We've reached the complexity limit. - tracing.instant(tracing.Phase.Check, "typeRelatedToDiscriminatedType_DepthLimit", { sourceId: source.id, targetId: target.id, numCombinations }); + tracing.instant(tracing.Phase.CheckTypes, "typeRelatedToDiscriminatedType_DepthLimit", { sourceId: source.id, targetId: target.id, numCombinations }); return Ternary.False; } } @@ -18621,7 +18621,7 @@ namespace ts { function getVariancesWorker(typeParameters: readonly TypeParameter[] = emptyArray, cache: TCache, createMarkerType: (input: TCache, param: TypeParameter, marker: Type) => Type): VarianceFlags[] { let variances = cache.variances; if (!variances) { - tracing.push(tracing.Phase.Check, "getVariancesWorker", { arity: typeParameters.length, id: (cache as any).id ?? (cache as any).declaredType?.id ?? -1 }); + tracing.push(tracing.Phase.CheckTypes, "getVariancesWorker", { arity: typeParameters.length, id: (cache as any).id ?? (cache as any).declaredType?.id ?? -1 }); // The emptyArray singleton is used to signal a recursive invocation. cache.variances = emptyArray; variances = []; @@ -21719,7 +21719,7 @@ namespace ts { if (flowDepth === 2000) { // We have made 2000 recursive invocations. To avoid overflowing the call stack we report an error // and disable further control flow analysis in the containing function or module body. - tracing.instant(tracing.Phase.Check, "getTypeAtFlowNode_DepthLimit", { flowId: flow.id }); + tracing.instant(tracing.Phase.CheckTypes, "getTypeAtFlowNode_DepthLimit", { flowId: flow.id }); flowAnalysisDisabled = true; reportFlowControlError(reference); return errorType; diff --git a/src/compiler/program.ts b/src/compiler/program.ts index 33c3b67e9ed..8d4efc3e941 100644 --- a/src/compiler/program.ts +++ b/src/compiler/program.ts @@ -780,7 +780,7 @@ namespace ts { // Track source files that are source files found by searching under node_modules, as these shouldn't be compiled. const sourceFilesFoundSearchingNodeModules = new Map(); - tracing.push(tracing.Phase.Program, "createProgram", {}, /*separateBeginAndEnd*/ true); + tracing.push(tracing.Phase.Program, "createProgram", { configFilePath: options.configFilePath, rootDir: options.rootDir }, /*separateBeginAndEnd*/ true); performance.mark("beforeProgram"); const host = createProgramOptions.host || createCompilerHost(options); diff --git a/src/compiler/tracing.ts b/src/compiler/tracing.ts index 95deeb1b33c..d6ebbc08518 100644 --- a/src/compiler/tracing.ts +++ b/src/compiler/tracing.ts @@ -1,16 +1,24 @@ /*@internal*/ /** Tracing events for the compiler. */ namespace ts.tracing { + export const enum Mode { + Project, + Build, + Server, + } + let fs: typeof import("fs") | false | undefined; let traceCount = 0; let traceFd: number | undefined; + let mode: Mode; + let legendPath: string | undefined; const legend: TraceRecord[] = []; /** Starts tracing for the given project (unless the `fs` module is unavailable). */ - export function startTracing(configFilePath: string | undefined, traceDir: string, isBuildMode: boolean) { + export function startTracing(tracingMode: Mode, traceDir: string, configFilePath?: string) { Debug.assert(!traceFd, "Tracing already started"); if (fs === undefined) { @@ -26,6 +34,8 @@ namespace ts.tracing { return; } + mode = tracingMode; + if (legendPath === undefined) { legendPath = combinePaths(traceDir, "legend.json"); } @@ -35,7 +45,10 @@ namespace ts.tracing { fs.mkdirSync(traceDir, { recursive: true }); } - const countPart = isBuildMode ? `.${++traceCount}` : ``; + const countPart = + mode === Mode.Build ? `.${process.pid}-${++traceCount}` : + mode === Mode.Server ? `.${process.pid}` : + ``; const tracePath = combinePaths(traceDir, `trace${countPart}.json`); const typesPath = combinePaths(traceDir, `types${countPart}.json`); @@ -58,13 +71,14 @@ namespace ts.tracing { } /** Stops tracing for the in-progress project and dumps the type catalog (unless the `fs` module is unavailable). */ - export function stopTracing(typeCatalog: readonly Type[]) { + export function stopTracing(typeCatalog?: readonly Type[]) { if (!traceFd) { Debug.assert(!fs, "Tracing is not in progress"); return; } Debug.assert(fs); + Debug.assert(!!typeCatalog === (mode !== Mode.Server)); // Have a type catalog iff not in server mode fs.writeSync(traceFd, `\n]\n`); fs.closeSync(traceFd); @@ -88,8 +102,10 @@ namespace ts.tracing { Parse = "parse", Program = "program", Bind = "bind", - Check = "check", + Check = "check", // Before we get into checking types (e.g. checkSourceFile) + CheckTypes = "checkTypes", Emit = "emit", + Session = "session", } export function instant(phase: Phase, name: string, args?: object) { @@ -97,8 +113,7 @@ namespace ts.tracing { writeEvent("I", phase, name, args, `"s":"g"`); } - // Used for "Complete" (ph:"X") events - const completeEvents: { phase: Phase, name: string, args?: object, time: number, separateBeginAndEnd: boolean }[] = []; + const eventStack: { phase: Phase, name: string, args?: object, time: number, separateBeginAndEnd: boolean }[] = []; /** * @param separateBeginAndEnd - used for special cases where we need the trace point even if the event @@ -111,18 +126,29 @@ namespace ts.tracing { if (separateBeginAndEnd) { writeEvent("B", phase, name, args); } - completeEvents.push({ phase, name, args, time: 1000 * timestamp(), separateBeginAndEnd }); + eventStack.push({ phase, name, args, time: 1000 * timestamp(), separateBeginAndEnd }); } export function pop() { if (!traceFd) return; - Debug.assert(completeEvents.length > 0); - const { phase, name, args, time, separateBeginAndEnd } = completeEvents.pop()!; + Debug.assert(eventStack.length > 0); + writeStackEvent(eventStack.length - 1, 1000 * timestamp()); + eventStack.length--; + } + export function popAll() { + if (!traceFd) return; + const endTime = 1000 * timestamp(); + for (let i = eventStack.length - 1; i >= 0; i--) { + writeStackEvent(i, endTime); + } + eventStack.length = 0; + } + function writeStackEvent(index: number, endTime: number) { + const { phase, name, args, time, separateBeginAndEnd } = eventStack[index]; if (separateBeginAndEnd) { - writeEvent("E", phase, name, args); + writeEvent("E", phase, name, args, /*extras*/ undefined, endTime); } else { - const dur = 1000 * timestamp() - time; - writeEvent("X", phase, name, args, `"dur":${dur}`, time); + writeEvent("X", phase, name, args, `"dur":${endTime - time}`, time); } } @@ -130,6 +156,10 @@ namespace ts.tracing { time: number = 1000 * timestamp()) { Debug.assert(traceFd); Debug.assert(fs); + + // In server mode, there's no easy way to dump type information, so we drop events that would require it. + if (mode === Mode.Server && phase === Phase.CheckTypes) return; + performance.mark("beginTracing"); fs.writeSync(traceFd, `,\n{"pid":1,"tid":1,"ph":"${eventType}","cat":"${phase}","ts":${time},"name":"${name}"`); if (extras) fs.writeSync(traceFd, `,${extras}`); diff --git a/src/executeCommandLine/executeCommandLine.ts b/src/executeCommandLine/executeCommandLine.ts index 54ed94e375b..f8e07a34bb3 100644 --- a/src/executeCommandLine/executeCommandLine.ts +++ b/src/executeCommandLine/executeCommandLine.ts @@ -621,7 +621,7 @@ namespace ts { } if (canTrace(system, compilerOptions)) { - tracing.startTracing(compilerOptions.configFilePath, compilerOptions.generateTrace!, isBuildMode); + tracing.startTracing(isBuildMode ? tracing.Mode.Build : tracing.Mode.Project, compilerOptions.generateTrace!, compilerOptions.configFilePath); } } diff --git a/src/server/session.ts b/src/server/session.ts index 73a86adf7c1..a842694bb9a 100644 --- a/src/server/session.ts +++ b/src/server/session.ts @@ -208,15 +208,25 @@ namespace ts.server { try { if (this.operationHost.isCancellationRequested()) { stop = true; + tracing.instant(tracing.Phase.Session, "stepCanceled", { seq: this.requestId, early: true }); } else { + tracing.push(tracing.Phase.Session, "stepAction", { seq: this.requestId }); action(this); + tracing.pop(); } } catch (e) { + // Cancellation or an error may have left incomplete events on the tracing stack. + tracing.popAll(); + stop = true; // ignore cancellation request - if (!(e instanceof OperationCanceledException)) { + if (e instanceof OperationCanceledException) { + tracing.instant(tracing.Phase.Session, "stepCanceled", { seq: this.requestId }); + } + else { + tracing.instant(tracing.Phase.Session, "stepError", { seq: this.requestId, message: (e).message }); this.operationHost.logError(e, `delayed processing of request ${this.requestId}`); } } @@ -914,6 +924,7 @@ namespace ts.server { } public event(body: T, eventName: string): void { + tracing.instant(tracing.Phase.Session, "event", { eventName }); this.send(toEvent(eventName, body)); } @@ -2915,8 +2926,12 @@ namespace ts.server { request = JSON.parse(message); relevantFile = request.arguments && (request as protocol.FileRequest).arguments.file ? (request as protocol.FileRequest).arguments : undefined; + tracing.instant(tracing.Phase.Session, "request", { seq: request.seq, command: request.command }); perfLogger.logStartCommand("" + request.command, message.substring(0, 100)); + + tracing.push(tracing.Phase.Session, "executeCommand", { seq: request.seq, command: request.command }, /*separateBeginAndEnd*/ true); const { response, responseRequired } = this.executeCommand(request); + tracing.pop(); if (this.logger.hasLevel(LogLevel.requestTime)) { const elapsedTime = hrTimeToMilliseconds(this.hrtime(start)).toFixed(4); @@ -2930,6 +2945,7 @@ namespace ts.server { // Note: Log before writing the response, else the editor can complete its activity before the server does perfLogger.logStopCommand("" + request.command, "Success"); + tracing.instant(tracing.Phase.Session, "response", { seq: request.seq, command: request.command, success: !!response }); if (response) { this.doOutput(response, request.command, request.seq, /*success*/ true); } @@ -2938,15 +2954,20 @@ namespace ts.server { } } catch (err) { + // Cancellation or an error may have left incomplete events on the tracing stack. + tracing.popAll(); + if (err instanceof OperationCanceledException) { // Handle cancellation exceptions perfLogger.logStopCommand("" + (request && request.command), "Canceled: " + err); + tracing.instant(tracing.Phase.Session, "commandCanceled", { seq: request?.seq, command: request?.command }); this.doOutput({ canceled: true }, request!.command, request!.seq, /*success*/ true); return; } this.logErrorWorker(err, message, relevantFile); perfLogger.logStopCommand("" + (request && request.command), "Error: " + err); + tracing.instant(tracing.Phase.Session, "commandError", { seq: request?.seq, command: request?.command, message: (err).message }); this.doOutput( /*info*/ undefined, diff --git a/src/services/services.ts b/src/services/services.ts index 89292f09cf5..f909360a28d 100644 --- a/src/services/services.ts +++ b/src/services/services.ts @@ -1126,16 +1126,22 @@ namespace ts { return createLanguageServiceSourceFile(sourceFile.fileName, scriptSnapshot, sourceFile.languageVersion, version, /*setNodeParents*/ true, sourceFile.scriptKind); } + const NoopCancellationToken: CancellationToken = { + isCancellationRequested: returnFalse, + throwIfCancellationRequested: noop, + }; + class CancellationTokenObject implements CancellationToken { - constructor(private cancellationToken: HostCancellationToken | undefined) { + constructor(private cancellationToken: HostCancellationToken) { } public isCancellationRequested(): boolean { - return !!this.cancellationToken && this.cancellationToken.isCancellationRequested(); + return this.cancellationToken.isCancellationRequested(); } public throwIfCancellationRequested(): void { if (this.isCancellationRequested()) { + tracing.instant(tracing.Phase.Session, "cancellationThrown", { kind: "CancellationTokenObject" }); throw new OperationCanceledException(); } } @@ -1166,6 +1172,7 @@ namespace ts { public throwIfCancellationRequested(): void { if (this.isCancellationRequested()) { + tracing.instant(tracing.Phase.Session, "cancellationThrown", { kind: "ThrottledCancellationToken" }); throw new OperationCanceledException(); } } @@ -1233,7 +1240,9 @@ namespace ts { let lastProjectVersion: string; let lastTypesRootVersion = 0; - const cancellationToken = new CancellationTokenObject(host.getCancellationToken && host.getCancellationToken()); + const cancellationToken = host.getCancellationToken + ? new CancellationTokenObject(host.getCancellationToken()) + : NoopCancellationToken; const currentDirectory = host.getCurrentDirectory(); // Check if the localized messages json is set, otherwise query the host for it diff --git a/src/tsserver/server.ts b/src/tsserver/server.ts index 306cbd7bba3..b8eb923767c 100644 --- a/src/tsserver/server.ts +++ b/src/tsserver/server.ts @@ -564,6 +564,9 @@ namespace ts.server { exit() { this.logger.info("Exiting..."); this.projectService.closeLog(); + if (traceDir) { + tracing.stopTracing(ts.emptyArray); + } process.exit(0); } @@ -977,6 +980,14 @@ namespace ts.server { const telemetryEnabled = hasArgument(Arguments.EnableTelemetry); const noGetErrOnBackgroundUpdate = hasArgument("--noGetErrOnBackgroundUpdate"); + const commandLineTraceDir = findArgument("--traceDirectory"); + const traceDir = commandLineTraceDir + ? stripQuotes(commandLineTraceDir) + : process.env.TSS_TRACE; + if (traceDir) { + tracing.startTracing(tracing.Mode.Server, traceDir); + } + logger.info(`Starting TS Server`); logger.info(`Version: ${version}`); logger.info(`Arguments: ${process.argv.join(" ")}`);