Better log for update graph and delay operations

sheetalkamat · sheetalkamat · commit 680994ea42e8 · 2017-09-06T16:34:31.000-07:00
diff --git a/src/compiler/utilities.ts b/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: () => {
diff --git a/src/server/editorServices.ts b/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);
 
diff --git a/src/server/project.ts b/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;
         }
 
diff --git a/src/server/server.ts b/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;
diff --git a/src/server/utilities.ts b/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;

Original file line number	Diff line number	Diff line change
`@@ -173,10 +173,15 @@ namespace ts.server {`
`173`	`173`	`export function createSortedArray<T>(): SortedArray<T> {`
`174`	`174`	`return [] as SortedArray<T>;`
`175`	`175`	`}`
	`176`	`+}`
`176`	`177`
	`178`	`+/* @internal */`
	`179`	`+namespace ts.server {`
`177`	`180`	`export class ThrottledOperations {`
`178`		`- private pendingTimeouts: Map<any> = createMap<any>();`
`179`		`- constructor(private readonly host: ServerHost) {`
	`181`	`+ private readonly pendingTimeouts: Map<any> = createMap<any>();`
	`182`	`+ private readonly logger?: Logger \| undefined;`
	`183`	`+ constructor(private readonly host: ServerHost, logger: Logger) {`
	`184`	`+ this.logger = logger.hasLevel(LogLevel.verbose) && logger;`
`180`	`185`	`}`
`181`	`186`
`182`	`187`	`public schedule(operationId: string, delay: number, cb: () => void) {`
`@@ -187,10 +192,16 @@ namespace ts.server {`
`187`	`192`	`}`
`188`	`193`	`// schedule new operation, pass arguments`
`189`	`194`	`this.pendingTimeouts.set(operationId, this.host.setTimeout(ThrottledOperations.run, delay, this, operationId, cb));`
	`195`	`+ if (this.logger) {`
	`196`	+ this.logger.info(`Scheduled: ${operationId}${pendingTimeout ? ", Cancelled earlier one" : ""}`);
	`197`	`+ }`
`190`	`198`	`}`
`191`	`199`
`192`	`200`	`private static run(self: ThrottledOperations, operationId: string, cb: () => void) {`
`193`	`201`	`self.pendingTimeouts.delete(operationId);`
	`202`	`+ if (self.logger) {`
	`203`	+ self.logger.info(`Running: ${operationId}`);
	`204`	`+ }`
`194`	`205`	`cb();`
`195`	`206`	`}`
`196`	`207`	`}`
`@@ -221,10 +232,7 @@ namespace ts.server {`
`221`	`232`	`}`
`222`	`233`	`}`
`223`	`234`	`}`
`224`		`-}`
`225`	`235`
`226`		`-/* @internal */`
`227`		`-namespace ts.server {`
`228`	`236`	`export function getBaseConfigFileName(configFilePath: NormalizedPath): "tsconfig.json" \| "jsconfig.json" \| undefined {`
`229`	`237`	`const base = getBaseFileName(configFilePath);`
`230`	`238`	`return base === "tsconfig.json" \|\| base === "jsconfig.json" ? base : undefined;`