feat(performance statistics): gather performance statistics (#257)

Author: SanderElias

scully/fileHanderPlugins/asciidoc.ts

@@ -8,7 +8,4 @@ const asciiDocPlugin = async (raw: string) => {
   return asciidoctor.convert(raw, {});
 };
 
-registerPlugin('fileHandler', 'adoc', {
-  alternateExtensions: ['asciidoc', 'asc'],
-  handler: asciiDocPlugin,
-});
+registerPlugin('fileHandler', 'adoc', asciiDocPlugin, ['asciidoc', 'asc']);

scully/fileHanderPlugins/markdown.ts

@@ -6,7 +6,4 @@ const markdownPlugin = async (raw: string) => {
   return marked(raw);
 };
 
-registerPlugin('fileHandler', 'md', {
-  alternateExtensions: ['markdown'],
-  handler: markdownPlugin,
-});
+registerPlugin('fileHandler', 'md', markdownPlugin, ['markdown']);

scully/pluginManagement/pluginRepository.ts

@@ -1,25 +1,22 @@
+import {performance} from 'perf_hooks';
 import {HandledRoute} from '../routerPlugins/addOptionalRoutesPlugin';
 import {logError, yellow} from '../utils/log';
+import {performanceIds} from '../utils/performanceIds';
 
 // export const configValidator = Symbol('configValidator');
 export const configValidator = `___Scully_Validate_config_plugin___`;
-
-export type PluginHandler = (...args: any) => Promise<any>;
-export interface Plugin {
-  handler: PluginHandler;
-}
+export const AlternateExtensionsForFilePlugin = Symbol('altfileextension');
 
 export type ErrorString = string;
 export type ConfigValidator = (HandledRoute) => ErrorString[];
 
-export interface FilePlugin {
-  alternateExtensions?: string[];
-  handler: PluginHandler;
-}
+type RoutePlugin = (route: string, config: any) => Promise<HandledRoute[]>;
+type RenderPlugin = (html: string, route: HandledRoute) => Promise<string>;
+type FilePlugin = (html: string) => Promise<string>;
 
 interface Plugins {
-  render: {[html: string]: PluginHandler};
-  router: {[path: string]: PluginHandler};
+  render: {[name: string]: RenderPlugin};
+  router: {[name: string]: RoutePlugin};
   fileHandler: {[fileExtension: string]: FilePlugin};
 }
 
@@ -35,7 +32,7 @@ export const registerPlugin = (
   type: PluginTypes,
   name: string,
   plugin: any,
-  validator = async (config?: any) => [],
+  pluginOptions: any = async (config?: any) => [],
   {replaceExistingPlugin = false} = {}
 ) => {
   if (!['router', 'render', 'fileHandler'].includes(type)) {
@@ -49,14 +46,42 @@ export const registerPlugin = (
   if (replaceExistingPlugin === false && plugins[type][name]) {
     throw new Error(`Plugin ${name} already exists`);
   }
-  if (type === 'router' && typeof validator !== 'function') {
-    logError(`
+  if (type === 'router') {
+    if (typeof pluginOptions !== 'function') {
+      logError(`
 ---------------
    Route plugin "${yellow(name)}" should have an config validator attached to '${plugin.name}'
 ---------------
 `);
-    plugin[configValidator] = async () => [];
+      plugin[configValidator] = async () => [];
+    } else {
+      plugin[configValidator] = pluginOptions;
+    }
   }
-  plugin[configValidator] = validator;
-  plugins[type][name] = plugin;
+  if (type === 'fileHandler') {
+    if (pluginOptions && Array.isArray(pluginOptions)) {
+      plugin[AlternateExtensionsForFilePlugin] = pluginOptions;
+    } else {
+      plugin[AlternateExtensionsForFilePlugin] = [];
+    }
+  }
+  plugins[type][name] = (...args) => wrap(type, name, plugin, args);
 };
+
+async function wrap(type: string, name: string, plugin: (...args) => any | FilePlugin, args: any) {
+  let id = `plugin-${type}:${name}-`;
+  if (type === 'router') {
+    id += args[0];
+  }
+  if (type === 'render') {
+    id += args[1].route;
+  }
+  if (type === 'fileHandler') {
+    plugin;
+  }
+  performance.mark('start' + id);
+  const result = await plugin(...args);
+  performance.mark('stop' + id);
+  performanceIds.add(id);
+  return result;
+}

scully/renderPlugins/content-render-utils/handleFile.ts

@@ -1,19 +1,19 @@
-import {FilePlugin, plugins} from '../../pluginManagement/pluginRepository';
+import {AlternateExtensionsForFilePlugin, plugins} from '../../pluginManagement/pluginRepository';
 import {logError} from '../../utils/log';
 export async function handleFile(extension: string, fileContent: string) {
   extension = extension.trim().toLowerCase();
   let plugin = plugins.fileHandler[extension];
   if (!plugin) {
     /** find by alternate extensions */
     const t = Object.entries(plugins.fileHandler).find(
-      ([name, pl]: [string, FilePlugin]) =>
-        pl.alternateExtensions && pl.alternateExtensions.includes(extension)
+      ([name, pl]: [string, () => any]) =>
+        pl[AlternateExtensionsForFilePlugin] && pl[AlternateExtensionsForFilePlugin].includes(extension)
     );
     if (t.length) {
       plugin = t[1];
     } else {
       throw new logError(`unknown filetype ${extension}`);
     }
   }
-  return plugin.handler(fileContent) as Promise<string>;
+  return plugin(fileContent) as Promise<string>;
 }

scully/renderPlugins/contentRenderPlugin.ts

@@ -6,7 +6,6 @@ import {handleFile} from './content-render-utils/handleFile';
 import {insertContent} from './content-render-utils/insertContent';
 import {readFileAndCheckPrePublishSlug} from './content-render-utils/readFileAndCheckPrePublishSlug';
 import {JSDOM} from 'jsdom';
-import {nodeModuleNameResolver} from 'typescript';
 
 registerPlugin('render', 'contentFolder', contentRenderPlugin);
 

scully/renderPlugins/launchedBrowser.ts

@@ -19,7 +19,7 @@ function obsBrowser(options: LaunchOptions = scullyConfig.puppeteerLaunchOptions
   if (showBrowser) {
     options.headless = false;
   }
-  // option.args= ['--no-sandbox', '--disable-setuid-sandbox'],
+  // options.args = ['--no-sandbox', '--disable-setuid-sandbox'];
 
   const {SCULLY_PUPPETEER_EXECUTABLE_PATH} = process.env;
   if (SCULLY_PUPPETEER_EXECUTABLE_PATH) {

scully/utils/defaultAction.ts

@@ -1,4 +1,6 @@
 import {cpus} from 'os';
+import {performance} from 'perf_hooks';
+import * as yargs from 'yargs';
 import {launchedBrowser} from '../renderPlugins/launchedBrowser';
 import {routeContentRenderer} from '../renderPlugins/routeContentRenderer';
 import {addOptionalRoutes, HandledRoute} from '../routerPlugins/addOptionalRoutesPlugin';
@@ -10,8 +12,7 @@ import {chunk} from './chunk';
 import {loadConfig, updateScullyConfig} from './config';
 import {ScullyConfig} from './interfacesandenums';
 import {log, logWarn} from './log';
-
-import * as yargs from 'yargs';
+import {performanceIds} from './performanceIds';
 
 const {baseFilter} = yargs
   .string('bf')
@@ -27,17 +28,23 @@ export const generateAll = async (config?: Partial<ScullyConfig>, localBaseFilte
   await loadConfig;
   try {
     log('Finding all routes in application.');
+    performance.mark('startTraverse');
     const unhandledRoutes = await traverseAppRoutes();
+    performance.mark('stopTraverse');
+    performanceIds.add('Traverse');
 
     if (unhandledRoutes.length < 1) {
       logWarn('No routes found in application, are you sure you installed the router? Terminating.');
       process.exit(15);
     }
 
+    performance.mark('startDiscovery');
+    performanceIds.add('Discovery');
     log('Pull in data to create additional routes.');
     const handledRoutes = await addOptionalRoutes(
       unhandledRoutes.filter((r: string) => r && r.startsWith(localBaseFilter))
     );
+    performance.mark('stopDiscovery');
     /** save routerinfo, so its available during rendering */
     if (localBaseFilter === '') {
       /** only store when the routes are complete  */
@@ -48,7 +55,10 @@ export const generateAll = async (config?: Partial<ScullyConfig>, localBaseFilte
     const browser = await launchedBrowser();
     /** start handling each route, works in chunked parallel mode  */
     // await doChunks(handledRoutes);
+    performance.mark('startRender');
+    performanceIds.add('Render');
     await renderParallel(handledRoutes);
+    performance.mark('stopRender');
     return handledRoutes;
   } catch (e) {
     // TODO: add better error handling

scully/utils/performanceIds.ts

@@ -0,0 +1,4 @@
+/**
+ * an constant to keep track of the id's for performance gathering
+ */
+export const performanceIds = new Set<string>();

scully/utils/startup.ts

@@ -1,7 +1,8 @@
 import {generateAll} from './defaultAction';
 import {ScullyConfig} from './interfacesandenums';
-import {performance, PerformanceObserver} from 'perf_hooks';
+import {performance, PerformanceObserver, PerformanceObserverCallback} from 'perf_hooks';
 import {log, yellow} from './log';
+import {performanceIds} from './performanceIds';
 
 /**
  * Starts the entire process
@@ -10,20 +11,23 @@ import {log, yellow} from './log';
 export const startScully = (config?: Partial<ScullyConfig>) => {
   let routeCount = 0;
   return new Promise(resolve => {
-    performance.mark('start');
-    const obs = new PerformanceObserver((list, observer) => {
-      const duration = list.getEntries()[0].duration;
-      performance.clearMarks();
-      observer.disconnect();
-      resolve({routeCount, duration});
-    });
+    performance.mark('startDuration');
+    performanceIds.add('Duration');
+    let innerResolve;
+    const durationProm = new Promise(r => (innerResolve = r));
+    const obs = new PerformanceObserver(measurePerformance(innerResolve));
     obs.observe({entryTypes: ['measure'], buffered: true});
-    generateAll(config).then(routes => {
-      routeCount = routes.length;
-      performance.mark('stop');
-      performance.measure('duration', 'start', 'stop');
+    const numberOfRoutesProm = generateAll(config).then(routes => {
+      performance.mark('stopDuration');
+      /** measure all performance checks */
+      [...performanceIds.values()].forEach(id => performance.measure(id, `start${id}`, `stop${id}`));
+      return routes.length;
     });
-  }).then(({routeCount: numberOfRoutes, duration}) => {
+    Promise.all([numberOfRoutesProm, durationProm]).then(([numberOfRoutes, durations]) =>
+      resolve({numberOfRoutes, durations})
+    );
+  }).then(({numberOfRoutes, durations}: {numberOfRoutes: number; durations: {[key: string]: number}}) => {
+    const duration = durations.Duration;
     // tslint:disable-next-line:variable-name
     const seconds = duration / 1000;
     const routesProSecond = Math.ceil((numberOfRoutes / seconds) * 100) / 100;
@@ -32,6 +36,30 @@ export const startScully = (config?: Partial<ScullyConfig>) => {
 Generating took ${yellow(Math.floor(seconds * 100) / 100)} seconds for ${yellow(numberOfRoutes)} pages:
   That is ${yellow(routesProSecond)} pages per second,
   or ${yellow(Math.ceil(singleTime))} milliseconds for each page.
+
+  Finding routes in the angular app took ${logSeconds(durations.Traverse)}
+  Pulling in route-data took ${logSeconds(durations.Discovery)}
+  Rendering the pages took ${logSeconds(durations.Render)}
+
 `);
   });
 };
+
+function measurePerformance(resolve: (value?: unknown) => void): PerformanceObserverCallback {
+  return (list, observer) => {
+    const durations = list
+      .getEntries()
+      .reduce((acc, entry) => ({...acc, [entry.name]: Math.floor(entry.duration * 100) / 100}), {});
+    // console.log(durations);
+    performance.clearMarks();
+    observer.disconnect();
+    resolve(durations);
+  };
+}
+
+function logSeconds(milliSeconds) {
+  if (milliSeconds < 1000) {
+    return yellow(Math.floor(milliSeconds)) + ' milliseconds';
+  }
+  return yellow(Math.floor(milliSeconds / 10) / 100) + ' seconds';
+}