Better log for update graph and delay operations

Author: sheetalkamat

src/compiler/utilities.ts

@@ -3592,7 +3592,10 @@ namespace ts {
         const watcher = addWatch(host, file, (fileName, cbOptional1?) => {
             const optionalInfo = cbOptional1 !== undefined ? ` ${cbOptional1}` : "";
             log(`${watcherCaption}Trigger: ${fileName}${optionalInfo} ${info}`);
+            const start = timestamp();
             cb(fileName, cbOptional1, optional);
+            const elapsed = timestamp() - start;
+            log(`${watcherCaption}Elapsed: ${elapsed}ms Trigger: ${fileName}${optionalInfo} ${info}`);
         }, optional);
         return {
             close: () => {

src/server/editorServices.ts

@@ -401,7 +401,7 @@ namespace ts.server {
 
             this.currentDirectory = this.host.getCurrentDirectory();
             this.toCanonicalFileName = createGetCanonicalFileName(this.host.useCaseSensitiveFileNames);
-            this.throttledOperations = new ThrottledOperations(this.host);
+            this.throttledOperations = new ThrottledOperations(this.host, this.logger);
 
             this.typingsInstaller.attach(this);
 

src/server/project.ts

@@ -789,7 +789,8 @@ namespace ts.server {
         private updateGraphWorker() {
             const oldProgram = this.program;
 
-            this.writeLog(`Starting Update graph worker: Project: ${this.getProjectName()}`);
+            this.writeLog(`Starting updateGraphWorker: Project: ${this.getProjectName()}`);
+            const start = timestamp();
             this.resolutionCache.startCachingPerDirectoryResolution();
             this.program = this.languageService.getProgram();
             this.resolutionCache.finishCachingPerDirectoryResolution();
@@ -843,8 +844,8 @@ namespace ts.server {
                         scriptInfoToDetach.detachFromProject(this);
                     }
                 });
-
-            this.writeLog(`Finishing Update graph worker: Project: ${this.getProjectName()}`);
+            const elapsed = timestamp() - start;
+            this.writeLog(`Finishing updateGraphWorker: Project: ${this.getProjectName()} structureChanged: ${hasChanges} Elapsed: ${elapsed}ms`);
             return hasChanges;
         }
 

src/server/server.ts

@@ -252,7 +252,7 @@ namespace ts.server {
             readonly typingSafeListLocation: string,
             private readonly npmLocation: string | undefined,
             private newLine: string) {
-            this.throttledOperations = new ThrottledOperations(host);
+            this.throttledOperations = new ThrottledOperations(host, this.logger);
             if (eventPort) {
                 const s = net.connect({ port: eventPort }, () => {
                     this.socket = s;

src/server/utilities.ts

@@ -173,10 +173,15 @@ namespace ts.server {
     export function createSortedArray<T>(): SortedArray<T> {
         return [] as SortedArray<T>;
     }
+}
 
+/* @internal */
+namespace ts.server {
     export class ThrottledOperations {
-        private pendingTimeouts: Map<any> = createMap<any>();
-        constructor(private readonly host: ServerHost) {
+        private readonly pendingTimeouts: Map<any> = createMap<any>();
+        private readonly logger?: Logger | undefined;
+        constructor(private readonly host: ServerHost, logger: Logger) {
+            this.logger = logger.hasLevel(LogLevel.verbose) && logger;
         }
 
         public schedule(operationId: string, delay: number, cb: () => void) {
@@ -187,10 +192,16 @@ namespace ts.server {
             }
             // schedule new operation, pass arguments
             this.pendingTimeouts.set(operationId, this.host.setTimeout(ThrottledOperations.run, delay, this, operationId, cb));
+            if (this.logger) {
+                this.logger.info(`Scheduled: ${operationId}${pendingTimeout ? ", Cancelled earlier one" : ""}`);
+            }
         }
 
         private static run(self: ThrottledOperations, operationId: string, cb: () => void) {
             self.pendingTimeouts.delete(operationId);
+            if (self.logger) {
+                self.logger.info(`Running: ${operationId}`);
+            }
             cb();
         }
     }
@@ -221,10 +232,7 @@ namespace ts.server {
             }
         }
     }
-}
 
-/* @internal */
-namespace ts.server {
     export function getBaseConfigFileName(configFilePath: NormalizedPath): "tsconfig.json" | "jsconfig.json" | undefined {
         const base = getBaseFileName(configFilePath);
         return base === "tsconfig.json" || base === "jsconfig.json" ? base : undefined;