microsoft/TypeScript
1
0
Fork 0
mirror of https://github.com/microsoft/TypeScript.git synced 2026-02-15 03:23:08 -06:00
Code Issues Packages Projects Releases 212 Wiki Activity

Add tracing support to tsserver (#41374)

Browse Source 
* 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
This commit is contained in:
Andrew Casey 2020-11-16 09:26:28 -08:00 committed by GitHub
parent 4885dec80d
commit 79ffd03f8b
No known key found for this signature in database
GPG Key ID: 4AEE18F83AFDEB23
7 changed files with 99 additions and 28 deletions
Show Stats Download Patch File Download Diff File Expand all files Collapse all files

20
src/compiler/checker.ts
View File

@ -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 ? (<UnionType>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<TCache extends { variances?: VarianceFlags[] }>(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;

2
src/compiler/program.ts
View File

@ -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<string, boolean>();
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);

54
src/compiler/tracing.ts
View File

@ -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}`);

2
src/executeCommandLine/executeCommandLine.ts
View File

@ -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);
}
}

23
src/server/session.ts
View File

@ -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: (<Error>e).message });
this.operationHost.logError(e, `delayed processing of request ${this.requestId}`);
}
}
@ -914,6 +924,7 @@ namespace ts.server {
}
public event<T extends object>(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 = <protocol.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: (<Error>err).message });
this.doOutput(
/*info*/ undefined,

15
src/services/services.ts
View File

@ -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

11
src/tsserver/server.ts
View File

@ -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(" ")}`);