refactor(@ngtools/webpack): add internal only benchmark timings

filipesilva · filipesilva · commit 376e335689f5 · 2017-09-28T23:43:04.000+01:00
diff --git a/packages/@ngtools/webpack/src/angular_compiler_plugin.ts b/packages/@ngtools/webpack/src/angular_compiler_plugin.ts
@@ -24,6 +24,7 @@ import {
   registerLocaleData,
   replaceResources,
 } from './transformers';
+import { time, timeEnd } from './benchmark';
 
 // These imports do not exist on Angular versions lower than 5, so we cannot use a static ES6
 // import. Instead we copy their types into './ngtools_api2.d.ts'.
@@ -300,29 +301,36 @@ export class AngularCompilerPlugin implements Tapable {
 
     if (this._JitMode) {
       // Create the TypeScript program.
+      time('_createOrUpdateProgram.ts.createProgram');
       this._program = ts.createProgram(
         this._tsFilenames,
         this._angularCompilerOptions,
         this._angularCompilerHost,
         this._program
       ) as ts.Program & Program;
+      timeEnd('_createOrUpdateProgram.ts.createProgram');
 
       return Promise.resolve();
     } else {
+      time('_createOrUpdateProgram.ng.createProgram');
       // Create the Angular program.
       this._program = createProgram({
         rootNames: this._tsFilenames,
         options: this._angularCompilerOptions,
         host: this._angularCompilerHost,
         oldProgram: this._program
       }) as ts.Program & Program;
+      timeEnd('_createOrUpdateProgram.ng.createProgram');
 
-      return this._program.loadNgStructureAsync();
+      time('_createOrUpdateProgram.ng.loadNgStructureAsync');
+      return this._program.loadNgStructureAsync()
+        .then(() => timeEnd('_createOrUpdateProgram.ng.loadNgStructureAsync'));
     }
   }
 
   private _getLazyRoutesFromNgtools() {
     try {
+      time('_getLazyRoutesFromNgtools');
       const result = __NGTOOLS_PRIVATE_API_2.listLazyRoutes({
         program: this._getTsProgram(),
         host: this._compilerHost,
@@ -332,6 +340,7 @@ export class AngularCompilerPlugin implements Tapable {
         }),
         entryModule: this._entryModule
       });
+      timeEnd('_getLazyRoutesFromNgtools');
       return result;
     } catch (err) {
       // We silence the error that the @angular/router could not be found. In that case, there is
@@ -345,6 +354,7 @@ export class AngularCompilerPlugin implements Tapable {
   }
 
   private _findLazyRoutesInAst(changedFilePaths: string[]): LazyRouteMap {
+    time('_findLazyRoutesInAst');
     const result: LazyRouteMap = Object.create(null);
     for (const filePath of changedFilePaths) {
       const fileLazyRoutes = findLazyRoutes(filePath, this._compilerHost, undefined,
@@ -354,6 +364,7 @@ export class AngularCompilerPlugin implements Tapable {
         result[routeKey] = route;
       }
     }
+    timeEnd('_findLazyRoutesInAst');
     return result;
   }
 
@@ -508,6 +519,7 @@ export class AngularCompilerPlugin implements Tapable {
   }
 
   private _make(compilation: any, cb: (err?: any, request?: any) => void) {
+    time('_make');
     this._compilation = compilation;
     if (this._compilation._ngToolsWebpackPluginInstance) {
       return cb(new Error('An @ngtools/webpack plugin already exist for this compilation.'));
@@ -516,8 +528,10 @@ export class AngularCompilerPlugin implements Tapable {
     this._compilation._ngToolsWebpackPluginInstance = this;
 
     // Create the resource loader with the webpack compilation.
+    time('_make.setResourceLoader');
     const resourceLoader = new WebpackResourceLoader(compilation);
     this._compilerHost.setResourceLoader(resourceLoader);
+    timeEnd('_make.setResourceLoader');
 
     this._donePromise = Promise.resolve()
       .then(() => {
@@ -532,26 +546,31 @@ export class AngularCompilerPlugin implements Tapable {
             .then(() => {
               // If there's still no entryModule try to resolve from mainPath.
               if (!this._entryModule && this._options.mainPath) {
+                time('_make.resolveEntryModuleFromMain');
                 const mainPath = path.resolve(this._basePath, this._options.mainPath);
                 this._entryModule = resolveEntryModuleFromMain(
                   mainPath, this._compilerHost, this._getTsProgram());
+                timeEnd('_make.resolveEntryModuleFromMain');
               }
             });
         }
       })
       .then(() => this._update())
       .then(() => {
+        timeEnd('_make');
         cb();
       }, (err: any) => {
         this._failedCompilation = true;
         compilation.errors.push(err.stack);
+        timeEnd('_make');
         cb();
       });
   }
 
   private _update() {
     // We only want to update on TS and template changes, but all kinds of files are on this
     // list, like package.json and .ngsummary.json files.
+    time('_update');
     let changedFiles = this._compilerHost.getChangedFilePaths()
       .filter(k => /(ts|html|css|scss|sass|less|styl)/.test(k));
 
@@ -580,6 +599,7 @@ export class AngularCompilerPlugin implements Tapable {
         if (changedFiles.length > 0 || this._firstRun) {
 
           // Go through each changed file and add transforms as needed.
+          time('_update.transformOps');
           const sourceFiles = this._getChangedTsFiles().map((fileName) => {
             const sourceFile = this._getTsProgram().getSourceFile(fileName);
             if (!sourceFile) {
@@ -627,13 +647,18 @@ export class AngularCompilerPlugin implements Tapable {
           for (let fileTransformOps of this._transformMap.values()) {
             transformOps.push(...fileTransformOps);
           }
+          timeEnd('_update.transformOps');
 
+          time('_update.makeTransform');
           const transformers: CustomTransformers = {
             beforeTs: transformOps.length > 0 ? [makeTransform(transformOps)] : []
           };
+          timeEnd('_update.makeTransform');
 
           // Emit files.
+          time('_update._emit');
           const { emitResult, diagnostics } = this._emit(sourceFiles, transformers);
+          timeEnd('_update._emit');
 
           // Report diagnostics.
           // TODO: check if the old _translateSourceMap function is needed.
@@ -659,6 +684,7 @@ export class AngularCompilerPlugin implements Tapable {
             this._failedCompilation = true;
           }
         }
+        timeEnd('_update');
       });
   }
 
@@ -678,6 +704,7 @@ export class AngularCompilerPlugin implements Tapable {
     sourceFiles: ts.SourceFile[],
     customTransformers: ts.CustomTransformers & CustomTransformers
   ) {
+    time('_emit');
     const program = this._program;
     const allDiagnostics: Diagnostics = [];
 
@@ -697,48 +724,68 @@ export class AngularCompilerPlugin implements Tapable {
         const tsProgram: ts.Program = program;
 
         // Check parameter diagnostics.
+        // TODO: check this only on initial program creation.
+        time('_emit.ts.getOptionsDiagnostics');
         shouldEmit = shouldEmit && checkDiagnostics(tsProgram.getOptionsDiagnostics());
+        timeEnd('_emit.ts.getOptionsDiagnostics');
 
         // Check syntactic diagnostics.
+        time('_emit.ts.getSyntacticDiagnostics');
         shouldEmit = shouldEmit && checkDiagnostics(tsProgram.getSyntacticDiagnostics());
+        timeEnd('_emit.ts.getSyntacticDiagnostics');
 
         // Check semantic diagnostics.
+        time('_emit.ts.getSemanticDiagnostics');
         shouldEmit = shouldEmit && checkDiagnostics(tsProgram.getSemanticDiagnostics());
+        timeEnd('_emit.ts.getSemanticDiagnostics');
 
         if (shouldEmit) {
           sourceFiles.forEach((sf) => {
+            const timeLabel = `_emit.ts+${sf.fileName}+.emit`;
+            time(timeLabel);
             emitResult = tsProgram.emit(sf, undefined, undefined, undefined,
               { before: customTransformers.beforeTs }
             );
             allDiagnostics.push(...emitResult.diagnostics);
+            timeEnd(timeLabel);
           });
         }
       } else {
         const angularProgram: Program = program;
 
         // Check parameter diagnostics.
+        // TODO: check this only on initial program creation.
+        time('_emit.ng.getTsOptionDiagnostics+getNgOptionDiagnostics');
         shouldEmit = shouldEmit && checkDiagnostics([
           ...angularProgram.getTsOptionDiagnostics(), ...angularProgram.getNgOptionDiagnostics()
         ]);
+        timeEnd('_emit.ng.getTsOptionDiagnostics+getNgOptionDiagnostics');
 
         // Check syntactic diagnostics.
+        time('_emit.ng.getTsSyntacticDiagnostics');
         shouldEmit = shouldEmit && checkDiagnostics(angularProgram.getTsSyntacticDiagnostics());
+        timeEnd('_emit.ng.getTsSyntacticDiagnostics');
 
         // Check TypeScript semantic and Angular structure diagnostics.
+        time('_emit.ng.getTsSemanticDiagnostics+getNgStructuralDiagnostics');
         shouldEmit = shouldEmit && checkDiagnostics(
           [...angularProgram.getTsSemanticDiagnostics(),
           ...angularProgram.getNgStructuralDiagnostics()
           ]);
+        timeEnd('_emit.ng.getTsSemanticDiagnostics+getNgStructuralDiagnostics');
 
         // Check Angular semantic diagnostics
         shouldEmit = shouldEmit && checkDiagnostics(angularProgram.getNgSemanticDiagnostics());
 
         if (shouldEmit) {
+          time('_emit.ng.emit');
           emitResult = angularProgram.emit({ emitFlags: EmitFlags.Default, customTransformers });
           allDiagnostics.push(...emitResult.diagnostics);
+          timeEnd('_emit.ng.emit');
         }
       }
     } catch (e) {
+      time('_emit.catch');
       // This function is available in the import below, but this way we avoid the dependency.
       // import { isSyntaxError } from '@angular/compiler';
       function isSyntaxError(error: Error): boolean {
@@ -759,7 +806,9 @@ export class AngularCompilerPlugin implements Tapable {
       }
       allDiagnostics.push(
         { category: ts.DiagnosticCategory.Error, messageText: errMsg, code, source: SOURCE });
+      timeEnd('_emit.catch');
     }
+    timeEnd('_emit');
     return { program, emitResult, diagnostics: allDiagnostics };
   }
 }
diff --git a/packages/@ngtools/webpack/src/benchmark.ts b/packages/@ngtools/webpack/src/benchmark.ts
@@ -0,0 +1,16 @@
+// Internal benchmark reporting flag.
+// Use with CLI --no-progress flag for best results.
+// This should be false for commited code.
+const _benchmark = false;
+
+export function time(label: string) {
+  if (_benchmark) {
+    console.time(label);
+  }
+}
+
+export function timeEnd(label: string) {
+  if (_benchmark) {
+    console.timeEnd(label);
+  }
+}
diff --git a/packages/@ngtools/webpack/src/loader.ts b/packages/@ngtools/webpack/src/loader.ts
@@ -4,6 +4,7 @@ import {AotPlugin} from './plugin';
 import {AngularCompilerPlugin} from './angular_compiler_plugin';
 import {TypeScriptFileRefactor} from './refactor';
 import {LoaderContext, ModuleReason} from './webpack';
+import {time, timeEnd} from './benchmark';
 
 interface Platform {
   name: string;
@@ -523,6 +524,8 @@ export function _exportModuleMap(plugin: AotPlugin, refactor: TypeScriptFileRefa
 export function ngcLoader(this: LoaderContext & { _compilation: any }, source: string | null) {
   const cb = this.async();
   const sourceFileName: string = this.resourcePath;
+  const timeLabel = `ngcLoader+${sourceFileName}+`;
+  time(timeLabel);
 
   const plugin = this._compilation._ngToolsWebpackPluginInstance;
   if (plugin) {
@@ -536,19 +539,27 @@ export function ngcLoader(this: LoaderContext & { _compilation: any }, source: s
     }
 
     if (plugin instanceof AngularCompilerPlugin) {
+      time(timeLabel + '.ngcLoader.AngularCompilerPlugin');
       plugin.done
         .then(() => {
+          timeEnd(timeLabel + '.ngcLoader.AngularCompilerPlugin');
           const result = plugin.getFile(sourceFileName);
           if (plugin.failedCompilation) {
             // Return an empty string if there is no result to prevent extra loader errors.
             // Plugin errors were already pushed to the compilation errors.
+            timeEnd(timeLabel);
             cb(null, result.outputText || '', result.sourceMap);
           } else {
-            cb(null, result.outputText, result.sourceMap);
-          }
-        })
-        .catch(err => cb(err));
+            timeEnd(timeLabel);
+          cb(null, result.outputText, result.sourceMap);
+        }
+      })
+      .catch(err => {
+        timeEnd(timeLabel + '.ngcLoader.AngularCompilerPlugin');
+        cb(err);
+        });
     } else if (plugin instanceof AotPlugin) {
+      time(timeLabel + '.ngcLoader.AotPlugin');
       if (plugin.compilerHost.readFile(sourceFileName) == source) {
         // In the case where the source is the same as the one in compilerHost, we don't have
         // extra TS loaders and there's no need to do any trickery.
@@ -557,40 +568,49 @@ export function ngcLoader(this: LoaderContext & { _compilation: any }, source: s
       const refactor = new TypeScriptFileRefactor(
         sourceFileName, plugin.compilerHost, plugin.program, source);
 
+
       Promise.resolve()
         .then(() => {
+          time(timeLabel + '.ngcLoader.AotPlugin.refactor');
+          let promise: Promise<any>;
           if (!plugin.skipCodeGeneration) {
-            return Promise.resolve()
+            promise = Promise.resolve()
               .then(() => _removeDecorators(refactor))
               .then(() => _refactorBootstrap(plugin, refactor))
               .then(() => _replaceExport(plugin, refactor))
               .then(() => _exportModuleMap(plugin, refactor));
           } else {
-            return Promise.resolve()
+            promise = Promise.resolve()
               .then(() => _replaceResources(refactor))
               .then(() => _removeModuleId(refactor))
               .then(() => _exportModuleMap(plugin, refactor));
           }
+          return promise.then(() => timeEnd(timeLabel + '.ngcLoader.AotPlugin.refactor'));
         })
         .then(() => {
           if (plugin.typeCheck) {
+            time(timeLabel + '.ngcLoader.AotPlugin.typeCheck');
             // Check all diagnostics from this and reverse dependencies also.
             if (!plugin.firstRun) {
               _diagnoseDeps(this._module.reasons, plugin, new Set<string>());
             }
             // We do this here because it will throw on error, resulting in rebuilding this file
             // the next time around if it changes.
             plugin.diagnose(sourceFileName);
+            timeEnd(timeLabel + '.ngcLoader.AotPlugin.typeCheck');
           }
         })
         .then(() => {
+          time(timeLabel + '.ngcLoader.AotPlugin.addDependency');
           // Add resources as dependencies.
           _getResourcesUrls(refactor).forEach((url: string) => {
             this.addDependency(path.resolve(path.dirname(sourceFileName), url));
           });
+          timeEnd(timeLabel + '.ngcLoader.AotPlugin.addDependency');
         })
         .then(() => {
           if (source) {
+            time(timeLabel + '.ngcLoader.AotPlugin.getDiagnostics');
             // We need to validate diagnostics. We ignore type checking though, to save time.
             const diagnostics = refactor.getDiagnostics(false);
             if (diagnostics.length) {
@@ -610,6 +630,7 @@ export function ngcLoader(this: LoaderContext & { _compilation: any }, source: s
               });
               throw new Error(message);
             }
+            timeEnd(timeLabel + '.ngcLoader.AotPlugin.getDiagnostics');
           }
 
           // Force a few compiler options to make sure we get the result we want.
@@ -619,13 +640,18 @@ export function ngcLoader(this: LoaderContext & { _compilation: any }, source: s
             sourceRoot: plugin.basePath
           });
 
+          time(timeLabel + '.ngcLoader.AotPlugin.transpile');
           const result = refactor.transpile(compilerOptions);
+          timeEnd(timeLabel + '.ngcLoader.AotPlugin.transpile');
 
+          timeEnd(timeLabel + '.ngcLoader.AotPlugin');
           if (plugin.failedCompilation && plugin.compilerOptions.noEmitOnError) {
             // Return an empty string to prevent extra loader errors (missing imports etc).
             // Plugin errors were already pushed to the compilation errors.
+            timeEnd(timeLabel);
             cb(null, '');
           } else {
+            timeEnd(timeLabel);
             cb(null, result.outputText, result.sourceMap);
           }
         })
@@ -661,6 +687,7 @@ export function ngcLoader(this: LoaderContext & { _compilation: any }, source: s
     const result = refactor.transpile(compilerOptions);
     // Webpack is going to take care of this.
     result.outputText = result.outputText.replace(/^\/\/# sourceMappingURL=[^\r\n]*/gm, '');
+    timeEnd(timeLabel);
     cb(null, result.outputText, result.sourceMap);
   }
 }
diff --git a/packages/@ngtools/webpack/src/plugin.ts b/packages/@ngtools/webpack/src/plugin.ts
