Custom instrumentation to identify expensive overload resolution instances

src/compiler/checker.ts

@@ -24155,11 +24155,56 @@ namespace ts {
             // Whether the call is an error is determined by assignability of the arguments. The subtype pass
             // is just important for choosing the best signature. So in the case where there is only one
             // signature, the subtype pass is useless. So skipping it is an optimization.
+
             if (candidates.length > 1) {
+                const oldCounts = { nextSymbolId, nextNodeId, subtype: subtypeRelation.size, assignable: assignableRelation.size, comparable: comparableRelation.size, identity: identityRelation.size, enum: enumRelation.size };
+                performance.mark("beforeChooseOverloadSubtype");
                 result = chooseOverload(candidates, subtypeRelation, signatureHelpTrailingComma);
+                performance.mark("afterChooseOverloadSubtype");
+                const newCounts = { nextSymbolId, nextNodeId, subtype: subtypeRelation.size, assignable: assignableRelation.size, comparable: comparableRelation.size, identity: identityRelation.size, enum: enumRelation.size };
+                performance.measureOverload("beforeChooseOverloadSubtype", "afterChooseOverloadSubtype", {
+                    kind: "subtype",
+                    nodePos: nodePosToString(node),
+                    candidateCount: candidates.length,
+                    symbolName: getSymbolName(result || candidates[0]),
+                    jsxName: getJsxElementName(node),
+                    succeeded: !!result,
+                    symbolCount: newCounts.nextSymbolId - oldCounts.nextSymbolId,
+                    nodeCount: newCounts.nextNodeId - oldCounts.nextNodeId,
+                    subtypeCount: newCounts.subtype - oldCounts.subtype,
+                    assignableCount: newCounts.assignable - oldCounts.assignable,
+                    comparableCount: newCounts.comparable - oldCounts.comparable,
+                    identityCount: newCounts.identity - oldCounts.identity,
+                    enumCount: newCounts.enum - oldCounts.enum,
+                });
             }
             if (!result) {
+                // const subtypeRelation = createMap<RelationComparisonResult>();
+                // const assignableRelation = createMap<RelationComparisonResult>();
+                // const comparableRelation = createMap<RelationComparisonResult>();
+                // const identityRelation = createMap<RelationComparisonResult>();
+                // const enumRelation = createMap<RelationComparisonResult>();
+
+                const oldCounts = { nextSymbolId, nextNodeId, subtype: subtypeRelation.size, assignable: assignableRelation.size, comparable: comparableRelation.size, identity: identityRelation.size, enum: enumRelation.size };
+                performance.mark("beforeChooseOverloadAssignable");
                 result = chooseOverload(candidates, assignableRelation, signatureHelpTrailingComma);
+                performance.mark("afterChooseOverloadAssignable");
+                const newCounts = { nextSymbolId, nextNodeId, subtype: subtypeRelation.size, assignable: assignableRelation.size, comparable: comparableRelation.size, identity: identityRelation.size, enum: enumRelation.size };
+                performance.measureOverload("beforeChooseOverloadAssignable", "afterChooseOverloadAssignable", {
+                    kind: "assignment",
+                    nodePos: nodePosToString(node),
+                    candidateCount: candidates.length,
+                    symbolName: getSymbolName(result || candidates[0]),
+                    jsxName: getJsxElementName(node),
+                    succeeded: !!result,
+                    symbolCount: newCounts.nextSymbolId - oldCounts.nextSymbolId,
+                    nodeCount: newCounts.nextNodeId - oldCounts.nextNodeId,
+                    subtypeCount: newCounts.subtype - oldCounts.subtype,
+                    assignableCount: newCounts.assignable - oldCounts.assignable,
+                    comparableCount: newCounts.comparable - oldCounts.comparable,
+                    identityCount: newCounts.identity - oldCounts.identity,
+                    enumCount: newCounts.enum - oldCounts.enum,
+                });
             }
             if (result) {
                 return result;
@@ -24251,6 +24296,37 @@ namespace ts {
 
             return produceDiagnostics || !args ? resolveErrorCall(node) : getCandidateForOverloadFailure(node, candidates, args, !!candidatesOutArray);
 
+            function getSymbolName(signature: Signature): string {
+                const decl = signature.declaration;
+                const symbol = decl && getSymbolOfNode(decl);
+                return symbol ? getSymbolNameRecursive(symbol) : "_Unknown_";
+            }
+
+            function getJsxElementName(node: Node): string | undefined {
+                return isJsxOpeningLikeElement(node) ? getTextOfNode(node.tagName) : undefined;
+            }
+
+            function getSymbolNameRecursive(symbol: Symbol): string {
+                let name = unescapeLeadingUnderscores(symbol.escapedName);
+                if (name === "__type") {
+                    if (symbol.declarations.length === 1) {
+                        const decl = symbol.declarations[0];
+                        if (decl.kind === SyntaxKind.FunctionType) {
+                            const parent = decl.parent;
+                            if (parent && isTypeAliasDeclaration(parent)) {
+                                name = getTextOfNode(parent.name);
+                            }
+                        }
+                    }
+                }
+                if (name.startsWith("__") && !symbol.parent) {
+                    name = name + "::" + getSymbolId(symbol);
+                }
+              return symbol.parent
+                    ? (getSymbolNameRecursive(symbol.parent) || "_Unknown_") + "." + name
+                    : name;
+            }
+
             function chooseOverload(candidates: Signature[], relation: Map<RelationComparisonResult>, signatureHelpTrailingComma = false) {
                 candidatesForArgumentError = undefined;
                 candidateForArgumentArityError = undefined;

src/compiler/performance.ts

@@ -18,6 +18,27 @@ namespace ts.performance {
     let counts: Map<number>;
     let marks: Map<number>;
     let measures: Map<number>;
+    let overloadMeasures: ChooseOverloadMeasure[];
+
+    export interface ChooseOverloadStats {
+        kind: "subtype" | "assignment",
+        candidateCount: number,
+        nodePos: string,
+        symbolName: string,
+        jsxName: string | undefined,
+        succeeded: boolean,
+        symbolCount: number,
+        nodeCount: number,
+        subtypeCount: number,
+        assignableCount: number,
+        comparableCount: number,
+        identityCount: number,
+        enumCount: number,
+    }
+
+    export interface ChooseOverloadMeasure extends ChooseOverloadStats {
+        timeMs: number
+    }
 
     export interface Timer {
         enter(): void;
@@ -84,6 +105,14 @@ namespace ts.performance {
         }
     }
 
+    export function measureOverload(startMarkName: string, endMarkName: string, stats: ChooseOverloadStats) {
+        if (enabled) {
+            const end = marks.get(endMarkName)!;
+            const start = marks.get(startMarkName)!;
+            overloadMeasures.push({ ...stats, timeMs: (end - start) });
+        }
+    }
+
     /**
      * Gets the number of times a marker was encountered.
      *
@@ -113,11 +142,16 @@ namespace ts.performance {
         });
     }
 
+    export function getOverloadMeasures(): readonly ChooseOverloadMeasure[] {
+        return overloadMeasures;
+    }
+
     /** Enables (and resets) performance measurements for the compiler. */
     export function enable() {
         counts = createMap<number>();
         marks = createMap<number>();
         measures = createMap<number>();
+        overloadMeasures = [];
         enabled = true;
         profilerStart = timestamp();
     }

src/tsc/executeCommandLine.ts

@@ -646,6 +646,45 @@ namespace ts {
                 reportCountStatistic("Identity cache size", caches.identity);
                 reportCountStatistic("Subtype cache size", caches.subtype);
                 performance.forEachMeasure((name, duration) => reportTimeStatistic(`${name} time`, duration));
+
+                const overloadMeasures = performance.getOverloadMeasures();
+                const overloadStatistics = overloadMeasures.slice();
+                const overloadMeasureGroups = group(overloadMeasures, s => s.kind + "::" + s.symbolName + (s.jsxName ? "::" + s.jsxName : ""));
+                const groupedOverloadStatistics = overloadMeasureGroups.map(measures => ({
+                    symbolName: measures[0].symbolName,
+                    jsxName: measures[0].jsxName,
+                    kind: measures[0].kind,
+                    candidateCount: measures[0].candidateCount,
+                    count: measures.length,
+                    timeMs: measures.map(m => m.timeMs).reduce((a, b) => a + b, 0),
+                    symbolCount: measures.map(m => m.symbolCount).reduce((a, b) => a + b, 0),
+                    nodeCount: measures.map(m => m.nodeCount).reduce((a, b) => a + b, 0),
+                    subtypeCount: measures.map(m => m.subtypeCount).reduce((a, b) => a + b, 0),
+                    assignableCount: measures.map(m => m.assignableCount).reduce((a, b) => a + b, 0),
+                    comparableCount: measures.map(m => m.comparableCount).reduce((a, b) => a + b, 0),
+                    identityCount: measures.map(m => m.identityCount).reduce((a, b) => a + b, 0),
+                    enumCount: measures.map(m => m.enumCount).reduce((a, b) => a + b, 0),
+                }));
+
+                const topCount = 5;
+
+                sys.write("Individual callsites" + sys.newLine);
+                sys.write(sys.newLine);
+
+                writeTop(overloadStatistics, topCount, "time", s => s.timeMs);
+                writeTop(overloadStatistics, topCount, "symbols", s => s.symbolCount);
+                writeTop(overloadStatistics, topCount, "subtype checks", s => s.subtypeCount);
+                writeTop(overloadStatistics, topCount, "assignability checks", s => s.assignableCount);
+                writeTop(overloadStatistics, topCount, "identity checks", s => s.identityCount);
+
+                sys.write("Aggregated by function" + sys.newLine);
+                sys.write(sys.newLine);
+
+                writeTop(groupedOverloadStatistics, topCount, "time", s => s.timeMs);
+                writeTop(groupedOverloadStatistics, topCount, "symbols", s => s.symbolCount);
+                writeTop(groupedOverloadStatistics, topCount, "subtype checks", s => s.subtypeCount);
+                writeTop(groupedOverloadStatistics, topCount, "assignability checks", s => s.assignableCount);
+                writeTop(groupedOverloadStatistics, topCount, "identity checks", s => s.identityCount);
             }
             else {
                 // Individual component times.
@@ -665,6 +704,18 @@ namespace ts {
             performance.disable();
         }
 
+        function writeTop<T>(collection: T[], count: number, propName: string, propFn: (t: T) => number) {
+            sys.write("Top " + count + " by " + propName + sys.newLine);
+            for (const stat of takeAtMost(count, collection.sort((a, b) => propFn(b) - propFn(a)))) {
+                sys.write(JSON.stringify(stat) + sys.newLine);
+            }
+            sys.write(sys.newLine);
+        }
+
+        function takeAtMost<T>(count: number, array: readonly T[]): readonly T[] {
+            return array.slice(0, Math.min(array.length, count));
+        }
+
         function reportStatistics() {
             let nameSize = 0;
             let valueSize = 0;
@@ -691,8 +742,8 @@ namespace ts {
             reportStatisticalValue(name, "" + count);
         }
 
-        function reportTimeStatistic(name: string, time: number) {
-            reportStatisticalValue(name, (time / 1000).toFixed(2) + "s");
+        function reportTimeStatistic(name: string, timeMs: number) {
+            reportStatisticalValue(name, (timeMs / 1000).toFixed(2) + "s");
         }
     }