Report time spent in updateGraph (#35675)

Add a response property indicating how much of the elapsed time (from
`onMessage` to `doOutput`) was spent in `updateGraph` calls.  If there's
no `updateGraph` call, the property is undefined, to save space (with
the downside that it's harder to tell whether a given telemetry event
could have had the property).

Fixes #34774

Author: amcasey

src/server/editorServices.ts

@@ -150,6 +150,15 @@ namespace ts.server {
 
     export type ProjectServiceEventHandler = (event: ProjectServiceEvent) => void;
 
+    /*@internal*/
+    export interface PerformanceEvent {
+        kind: "UpdateGraph";
+        durationMs: number;
+    }
+
+    /*@internal*/
+    export type PerformanceEventHandler = (event: PerformanceEvent) => void;
+
     export interface SafeList {
         [name: string]: { match: RegExp, exclude?: (string | number)[][], types?: string[] };
     }
@@ -612,6 +621,8 @@ namespace ts.server {
         /*@internal*/
         readonly watchFactory: WatchFactory<WatchType, Project>;
 
+        private performanceEventHandler?: PerformanceEventHandler;
+
         constructor(opts: ProjectServiceOptions) {
             this.host = opts.host;
             this.logger = opts.logger;
@@ -849,6 +860,13 @@ namespace ts.server {
             this.eventHandler(event);
         }
 
+        /* @internal */
+        sendUpdateGraphPerformanceEvent(durationMs: number) {
+            if (this.performanceEventHandler) {
+                this.performanceEventHandler({ kind: "UpdateGraph", durationMs });
+            }
+        }
+
         /* @internal */
         delayUpdateProjectGraphAndEnsureProjectStructureForOpenFiles(project: Project) {
             this.delayUpdateProjectGraph(project);
@@ -2551,6 +2569,11 @@ namespace ts.server {
             return info.sourceFileLike;
         }
 
+        /*@internal*/
+        setPerformanceEventHandler(performanceEventHandler: PerformanceEventHandler) {
+            this.performanceEventHandler = performanceEventHandler;
+        }
+
         setHostConfiguration(args: protocol.ConfigureRequestArguments) {
             if (args.file) {
                 const info = this.getScriptInfoForNormalizedPath(toNormalizedPath(args.file));

src/server/project.ts

@@ -1087,6 +1087,7 @@ namespace ts.server {
                 removed => this.detachScriptInfoFromProject(removed)
             );
             const elapsed = timestamp() - start;
+            this.projectService.sendUpdateGraphPerformanceEvent(elapsed);
             this.writeLog(`Finishing updateGraphWorker: Project: ${this.getProjectName()} Version: ${this.getProjectVersion()} structureChanged: ${hasNewProgram} Elapsed: ${elapsed}ms`);
             if (this.hasAddedorRemovedFiles) {
                 this.print();

src/server/protocol.ts

@@ -236,6 +236,12 @@ namespace ts.server.protocol {
          * Contains extra information that plugin can include to be passed on
          */
         metadata?: unknown;
+
+        /**
+         * Time spent updating the program graph, in milliseconds.
+         */
+        /* @internal */
+        updateGraphDurationMs?: number;
     }
 
     /**

src/server/session.ts

@@ -591,6 +591,8 @@ namespace ts.server {
         protected projectService: ProjectService;
         private changeSeq = 0;
 
+        private updateGraphDurationMs: number | undefined;
+
         private currentRequestId!: number;
         private errorCheck: MultistepOperation;
 
@@ -648,13 +650,23 @@ namespace ts.server {
                 syntaxOnly: opts.syntaxOnly,
             };
             this.projectService = new ProjectService(settings);
+            this.projectService.setPerformanceEventHandler(this.performanceEventHandler.bind(this));
             this.gcTimer = new GcTimer(this.host, /*delay*/ 7000, this.logger);
         }
 
         private sendRequestCompletedEvent(requestId: number): void {
             this.event<protocol.RequestCompletedEventBody>({ request_seq: requestId }, "requestCompleted");
         }
 
+        private performanceEventHandler(event: PerformanceEvent) {
+            switch (event.kind) {
+                case "UpdateGraph": {
+                    this.updateGraphDurationMs = (this.updateGraphDurationMs || 0) + event.durationMs;
+                    break;
+                }
+            }
+        }
+
         private defaultEventHandler(event: ProjectServiceEvent) {
             switch (event.eventName) {
                 case ProjectsUpdatedInBackgroundEvent:
@@ -795,7 +807,9 @@ namespace ts.server {
                 command: cmdName,
                 request_seq: reqSeq,
                 success,
+                updateGraphDurationMs: this.updateGraphDurationMs,
             };
+
             if (success) {
                 let metadata: unknown;
                 if (isArray(info)) {
@@ -2623,6 +2637,9 @@ namespace ts.server {
 
         public onMessage(message: string) {
             this.gcTimer.scheduleCollect();
+
+            this.updateGraphDurationMs = undefined;
+
             let start: number[] | undefined;
             if (this.logger.hasLevel(LogLevel.requestTime)) {
                 start = this.hrtime();

src/testRunner/unittests/tsserver/session.ts

@@ -100,7 +100,8 @@ namespace ts.server {
                     seq: 0,
                     message: "Unrecognized JSON command: foobar",
                     request_seq: 0,
-                    success: false
+                    success: false,
+                    updateGraphDurationMs: undefined,
                 };
                 expect(lastSent).to.deep.equal(expected);
             });
@@ -126,7 +127,8 @@ namespace ts.server {
                     success: true,
                     request_seq: 0,
                     seq: 0,
-                    body: undefined
+                    body: undefined,
+                    updateGraphDurationMs: undefined,
                 });
             });
             it("should handle literal types in request", () => {
@@ -326,7 +328,8 @@ namespace ts.server {
                     success: true,
                     request_seq: 0,
                     seq: 0,
-                    body: undefined
+                    body: undefined,
+                    updateGraphDurationMs: undefined,
                 });
             });
         });
@@ -416,7 +419,8 @@ namespace ts.server {
                     type: "response",
                     command,
                     body,
-                    success: true
+                    success: true,
+                    updateGraphDurationMs: undefined,
                 });
             });
         });
@@ -535,7 +539,8 @@ namespace ts.server {
                 type: "response",
                 command,
                 body,
-                success: true
+                success: true,
+                updateGraphDurationMs: undefined,
             });
         });
         it("can add and respond to new protocol handlers", () => {

tests/baselines/reference/api/tsserverlibrary.d.ts

@@ -9154,6 +9154,7 @@ declare namespace ts.server {
         readonly syntaxOnly?: boolean;
         /** Tracks projects that we have already sent telemetry for. */
         private readonly seenProjects;
+        private performanceEventHandler?;
         constructor(opts: ProjectServiceOptions);
         toPath(fileName: string): Path;
         private loadTypesMap;
@@ -9383,6 +9384,7 @@ declare namespace ts.server {
         private readonly gcTimer;
         protected projectService: ProjectService;
         private changeSeq;
+        private updateGraphDurationMs;
         private currentRequestId;
         private errorCheck;
         protected host: ServerHost;
@@ -9397,6 +9399,7 @@ declare namespace ts.server {
         private readonly noGetErrOnBackgroundUpdate?;
         constructor(opts: SessionOptions);
         private sendRequestCompletedEvent;
+        private performanceEventHandler;
         private defaultEventHandler;
         private projectsUpdatedInBackgroundEvent;
         logError(err: Error, cmd: string): void;