From 965f8401018aef769f78feee22944a7f26962bbf Mon Sep 17 00:00:00 2001 From: Nick Reese Date: Mon, 7 Mar 2022 23:00:40 +0100 Subject: [PATCH] Feat/perf improvements (#241) * add perf to hooks * Add perf to Page, Elder, Plugins. * Remove perf from what is passed into Page. * Finish modularizing hooks. * rename bootstrap to startup. * get tests passing --- src/Elder.ts | 41 ++++++++++++++++++ src/__tests__/Elder.spec.ts | 5 ++- .../__snapshots__/Elder.spec.ts.snap | 42 +++++++++++++++++++ src/hooks/hookEntityDefinitions.ts | 1 + src/hooks/hookInterface.ts | 23 ++++++---- src/hooks/index.ts | 6 +-- src/plugins/__tests__/plugins.spec.ts | 10 +++++ src/plugins/index.ts | 8 ++++ src/utils/Page.ts | 2 +- src/utils/__tests__/Page.spec.ts | 5 +++ .../__tests__/__snapshots__/Page.spec.ts.snap | 40 ++++++++++++++++++ .../__tests__/__snapshots__/perf.spec.ts.snap | 3 +- src/utils/__tests__/perf.spec.ts | 12 +++++- src/utils/__tests__/prepareRunHook.spec.ts | 2 +- src/utils/perf.ts | 22 +++++++++- src/utils/prepareRunHook.ts | 9 +++- src/utils/prepareServer.ts | 3 +- 17 files changed, 211 insertions(+), 23 deletions(-) diff --git a/src/Elder.ts b/src/Elder.ts index 27c30520..9fbab16e 100644 --- a/src/Elder.ts +++ b/src/Elder.ts @@ -36,6 +36,7 @@ import workerBuild from './workerBuild'; import { inlineSvelteComponent } from './partialHydration/inlineSvelteComponent'; import elderJsShortcodes from './shortcodes'; import prepareRouter from './routes/prepareRouter'; +import perf, { displayPerfTimings } from './utils/perf'; class Elder { bootstrapComplete: Promise; @@ -70,6 +71,10 @@ class Elder { shortcodes: ShortcodeDefs; + perf: any; + + uid: string; + router: (any) => any; constructor(initializationOptions: InitializationOptions = {}) { @@ -77,6 +82,7 @@ class Elder { this.bootstrapComplete = new Promise((resolve) => { this.markBootstrapComplete = resolve; }); + this.uid = 'startup'; // merge the given config with the project and defaults; this.settings = getConfig(initializationOptions); @@ -96,8 +102,13 @@ class Elder { this.server = prepareServer({ bootstrapComplete: this.bootstrapComplete }); } + perf(this, true); + + this.perf.start('startup'); + // plugins are run first as they have routes, hooks, and shortcodes. plugins(this).then(async ({ pluginRoutes, pluginHooks, pluginShortcodes }) => { + this.perf.start('startup.validations'); /** * Finalize Routes * Add in user routes @@ -203,6 +214,8 @@ class Elder { .map((shortcode) => validateShortcode(shortcode)) .filter(Boolean as any as ExcludesFalse); + this.perf.end('startup.validations'); + /** * * Almost ready for customize hooks and bootstrap @@ -243,16 +256,21 @@ class Elder { await this.runHook('bootstrap', this); // collect all of our requests + this.perf.start('startup.routes'); await asyncForEach(Object.keys(this.routes), async (routeName) => { + this.perf.start(`startup.routes.${routeName}`); const route = this.routes[routeName]; let allRequestsForRoute = []; if (typeof route.all === 'function') { + this.perf.start(`startup.routes.${routeName}`); allRequestsForRoute = await route.all({ settings: createReadOnlyProxy(this.settings, 'settings', `${routeName} all function`), query: createReadOnlyProxy(this.query, 'query', `${routeName} all function`), helpers: createReadOnlyProxy(this.helpers, 'helpers', `${routeName} all function`), data: createReadOnlyProxy(this.data, 'data', `${routeName} all function`), + perf: this.perf.prefix(`startup.routes.${routeName}.all`), }); + this.perf.end(`startup.routes.${routeName}`); } else if (Array.isArray(route.all)) { allRequestsForRoute = route.all; } @@ -270,10 +288,14 @@ class Elder { return out; }, []); this.allRequests = this.allRequests.concat(allRequestsForRoute); + this.perf.end(`startup.routes.${routeName}`); }); + this.perf.end(`startup.routes`); + await this.runHook('allRequests', this); + this.perf.start(`startup.setPermalinks`); await asyncForEach(this.allRequests, async (request) => { if (!this.routes[request.route] || !this.routes[request.route].permalink) { if (!request.route) { @@ -303,6 +325,9 @@ class Elder { this.serverLookupObject[request.permalink] = request; } }); + this.perf.end(`startup.setPermalinks`); + + this.perf.start(`startup.validatePermalinks`); if (this.allRequests.length !== new Set(this.allRequests.map((r) => r.permalink)).size) { // useful error logging for when there are duplicate permalinks. @@ -318,10 +343,26 @@ class Elder { } } } + this.perf.end(`startup.validatePermalinks`); + this.perf.start(`startup.prepareRouter`); this.router = prepareRouter(this); + this.perf.end(`startup.prepareRouter`); this.markBootstrapComplete(this); + + this.perf.end('startup'); + this.perf.stop(); + + const t = this.perf.timings.slice(-1)[0] && Math.round(this.perf.timings.slice(-1)[0].duration * 10) / 10; + if (t && t > 0) { + console.log( + `Elder.js Startup: ${t}ms. ${t > 5000 ? `For details set debug.performance: true in elder.config.js` : ''}`, + ); + if (this.settings.debug.performance) { + displayPerfTimings([...this.perf.timings]); + } + } }); }); } diff --git a/src/__tests__/Elder.spec.ts b/src/__tests__/Elder.spec.ts index aca5c5af..92120ba5 100644 --- a/src/__tests__/Elder.spec.ts +++ b/src/__tests__/Elder.spec.ts @@ -58,7 +58,7 @@ describe('#Elder', () => { for (const pluginHook of page.hooks) { if (pluginHook.$$meta.type === 'plugin') { // eslint-disable-next-line - await pluginHook.run({}); + await pluginHook.run({}); } } } @@ -111,6 +111,7 @@ describe('#Elder', () => { const elder = await new Elder({ context: 'server', worker: false }); await elder.bootstrap(); await elder.worker([]); + delete elder.perf.timings; expect(normalizeSnapshot(elder)).toMatchSnapshot(); }); @@ -200,6 +201,8 @@ describe('#Elder', () => { const { Elder } = require(`..${sep}index`); const elder = await new Elder({ context: 'server', worker: false }); await elder.bootstrap(); + + delete elder.perf.timings; expect(normalizeSnapshot(elder)).toMatchSnapshot(); }); }); diff --git a/src/__tests__/__snapshots__/Elder.spec.ts.snap b/src/__tests__/__snapshots__/Elder.spec.ts.snap index ea62b31e..8623dafb 100644 --- a/src/__tests__/__snapshots__/Elder.spec.ts.snap +++ b/src/__tests__/__snapshots__/Elder.spec.ts.snap @@ -27,6 +27,7 @@ Object { "errors", ], "props": Array [ + "perf", "hookInterface", "errors", ], @@ -47,6 +48,7 @@ Object { "query", ], "props": Array [ + "perf", "helpers", "data", "settings", @@ -72,6 +74,7 @@ Object { "allRequests", ], "props": Array [ + "perf", "helpers", "data", "settings", @@ -107,6 +110,7 @@ Object { "serverLookupObject", ], "props": Array [ + "perf", "errors", "query", "helpers", @@ -147,6 +151,7 @@ Object { "route", ], "props": Array [ + "perf", "helpers", "data", "settings", @@ -183,6 +188,7 @@ Object { "footerStack", ], "props": Array [ + "perf", "data", "request", "errors", @@ -224,6 +230,7 @@ Object { "customJsStack", ], "props": Array [ + "perf", "helpers", "data", "settings", @@ -258,6 +265,7 @@ Object { "footerStack", ], "props": Array [ + "perf", "helpers", "data", "settings", @@ -296,6 +304,7 @@ Object { "headString", ], "props": Array [ + "perf", "helpers", "data", "settings", @@ -318,6 +327,7 @@ Object { "htmlString", ], "props": Array [ + "perf", "helpers", "data", "settings", @@ -342,6 +352,7 @@ Object { "htmlString", ], "props": Array [ + "perf", "helpers", "data", "settings", @@ -367,6 +378,7 @@ Object { "errors", ], "props": Array [ + "perf", "request", "htmlString", "query", @@ -392,6 +404,7 @@ Object { "location": "Page.ts, build.ts", "mutable": Array [], "props": Array [ + "perf", "helpers", "data", "settings", @@ -409,6 +422,7 @@ Object { "location": "build.ts", "mutable": Array [], "props": Array [ + "perf", "helpers", "data", "settings", @@ -558,6 +572,12 @@ Object { }, ], "markBootstrapComplete": [Function], + "perf": Object { + "end": [Function], + "prefix": [Function], + "start": [Function], + "stop": [Function], + }, "query": Object {}, "router": [Function], "routes": Object { @@ -632,6 +652,7 @@ Object { "shortcode": "svelteComponent", }, ], + "uid": "startup", } `; @@ -669,6 +690,7 @@ Object { "errors", ], "props": Array [ + "perf", "hookInterface", "errors", ], @@ -689,6 +711,7 @@ Object { "query", ], "props": Array [ + "perf", "helpers", "data", "settings", @@ -714,6 +737,7 @@ Object { "allRequests", ], "props": Array [ + "perf", "helpers", "data", "settings", @@ -749,6 +773,7 @@ Object { "serverLookupObject", ], "props": Array [ + "perf", "errors", "query", "helpers", @@ -789,6 +814,7 @@ Object { "route", ], "props": Array [ + "perf", "helpers", "data", "settings", @@ -825,6 +851,7 @@ Object { "footerStack", ], "props": Array [ + "perf", "data", "request", "errors", @@ -866,6 +893,7 @@ Object { "customJsStack", ], "props": Array [ + "perf", "helpers", "data", "settings", @@ -900,6 +928,7 @@ Object { "footerStack", ], "props": Array [ + "perf", "helpers", "data", "settings", @@ -938,6 +967,7 @@ Object { "headString", ], "props": Array [ + "perf", "helpers", "data", "settings", @@ -960,6 +990,7 @@ Object { "htmlString", ], "props": Array [ + "perf", "helpers", "data", "settings", @@ -984,6 +1015,7 @@ Object { "htmlString", ], "props": Array [ + "perf", "helpers", "data", "settings", @@ -1009,6 +1041,7 @@ Object { "errors", ], "props": Array [ + "perf", "request", "htmlString", "query", @@ -1034,6 +1067,7 @@ Object { "location": "Page.ts, build.ts", "mutable": Array [], "props": Array [ + "perf", "helpers", "data", "settings", @@ -1051,6 +1085,7 @@ Object { "location": "build.ts", "mutable": Array [], "props": Array [ + "perf", "helpers", "data", "settings", @@ -1210,6 +1245,12 @@ Object { }, ], "markBootstrapComplete": [Function], + "perf": Object { + "end": [Function], + "prefix": [Function], + "start": [Function], + "stop": [Function], + }, "query": Object {}, "router": [Function], "routes": Object { @@ -1291,5 +1332,6 @@ Object { "shortcode": "svelteComponent", }, ], + "uid": "startup", } `; diff --git a/src/hooks/hookEntityDefinitions.ts b/src/hooks/hookEntityDefinitions.ts index fa88538c..2a647598 100644 --- a/src/hooks/hookEntityDefinitions.ts +++ b/src/hooks/hookEntityDefinitions.ts @@ -46,6 +46,7 @@ const hookEntityDefinitions = { "The compiled HTML response for a route containing all of the HTML from the Route's layout and template. ", serverLookupObject: `A key value object where the key is the relative permalink and the object is the 'request' object used by the Elder.js server.`, runHook: `The function that powers hooks. 'await runhook('hookName', objectContainingProps)`, + perf: `Includes two functions: perf.start('thingToTrack') and perf.end('thingToTrack') which allows easily adding tracking to Elder.js' perf reporting which can be toggled under debug.performance in your elder.config.js file.`, }; // eslint-disable-next-line import/prefer-default-export diff --git a/src/hooks/hookInterface.ts b/src/hooks/hookInterface.ts index 15c3773d..587c0431 100644 --- a/src/hooks/hookInterface.ts +++ b/src/hooks/hookInterface.ts @@ -6,7 +6,7 @@ import type { HookInterface } from './types'; export const hookInterface: Array = [ { hook: 'customizeHooks', - props: ['hookInterface', 'errors'], + props: ['perf', 'hookInterface', 'errors'], mutable: ['hookInterface', 'errors'], context: 'Used to modify what hooks can mutate which properties all hooks.', use: `

This hook receives the hookInterface.ts file which defines all hook interactions. You can customize all 'props' and 'mutable' of @@ -17,7 +17,7 @@ export const hookInterface: Array = [ }, { hook: 'bootstrap', - props: ['helpers', 'data', 'settings', 'routes', 'hooks', 'query', 'errors'], + props: ['perf', 'helpers', 'data', 'settings', 'routes', 'hooks', 'query', 'errors'], mutable: ['errors', 'helpers', 'data', 'settings', 'query'], context: 'Routes, plugins, and hooks have been collected and validated.', use: `

    @@ -31,7 +31,7 @@ export const hookInterface: Array = [ }, { hook: 'allRequests', - props: ['helpers', 'data', 'settings', 'allRequests', 'routes', 'query', 'errors'], + props: ['perf', 'helpers', 'data', 'settings', 'allRequests', 'routes', 'query', 'errors'], mutable: ['errors', 'allRequests'], context: `allRequests which represents all of the request objects have been collected from route and plugins. This makes the 'allRequests' array mutable.`, use: `

    The main use here is to allow users to adjust the requests that Elder.js is aware of.

      @@ -49,6 +49,7 @@ export const hookInterface: Array = [ { hook: 'middleware', props: [ + 'perf', 'errors', 'query', 'helpers', @@ -96,7 +97,7 @@ export const hookInterface: Array = [ { hook: 'request', - props: ['helpers', 'data', 'settings', 'request', 'allRequests', 'query', 'errors', 'routes', 'route'], + props: ['perf', 'helpers', 'data', 'settings', 'request', 'allRequests', 'query', 'errors', 'routes', 'route'], mutable: ['errors', 'helpers', 'data', 'settings', 'request', 'route'], context: `This is executed at the beginning the request object being processed.`, use: `

      This hook gives access to the entire state of a request lifecycle before it starts.

      @@ -115,6 +116,7 @@ export const hookInterface: Array = [ { hook: 'data', props: [ + 'perf', 'data', 'request', 'errors', @@ -160,6 +162,7 @@ export const hookInterface: Array = [ { hook: 'shortcodes', props: [ + 'perf', 'helpers', 'data', 'settings', @@ -185,6 +188,7 @@ export const hookInterface: Array = [ { hook: 'stacks', props: [ + 'perf', 'helpers', 'data', 'settings', @@ -230,7 +234,7 @@ export const hookInterface: Array = [ { hook: 'head', - props: ['helpers', 'data', 'settings', 'request', 'headString', 'query', 'errors'], + props: ['perf', 'helpers', 'data', 'settings', 'request', 'headString', 'query', 'errors'], mutable: ['errors', 'headString'], context: 'Executed just before writing the tag to the page.', use: `

      This hook's headSting represents everything that will be written to <head> tag.

      @@ -243,6 +247,7 @@ export const hookInterface: Array = [ { hook: 'compileHtml', props: [ + 'perf', 'helpers', 'data', 'settings', @@ -264,7 +269,7 @@ export const hookInterface: Array = [ { hook: 'html', - props: ['helpers', 'data', 'settings', 'request', 'htmlString', 'query', 'errors'], + props: ['perf', 'helpers', 'data', 'settings', 'request', 'htmlString', 'query', 'errors'], mutable: ['errors', 'htmlString'], context: 'Executed when all of the html has been compiled.', use: `

      This hook receives the full html of the document. With great power comes great responsibility.

      @@ -280,7 +285,7 @@ export const hookInterface: Array = [ { hook: 'requestComplete', - props: ['request', 'htmlString', 'query', 'settings', 'errors', 'timings', 'data'], + props: ['perf', 'request', 'htmlString', 'query', 'settings', 'errors', 'timings', 'data'], mutable: ['errors'], context: 'This hook marks the end of the request lifecycle.', use: `

      This hook is triggered on an individual 'request object' completing whether Elder.js is being used in the "build" or a "server" mode.

      @@ -297,7 +302,7 @@ export const hookInterface: Array = [ }, { hook: 'error', - props: ['helpers', 'data', 'settings', 'request', 'query', 'errors'], + props: ['perf', 'helpers', 'data', 'settings', 'request', 'query', 'errors'], mutable: [], context: 'Executed only if the script has encountered errors and they are pushed to the errors array.', use: `

      As the script encounters errors, they are collected and presented on this hook at the end of a request and the end of an entire build.

      `, @@ -308,7 +313,7 @@ export const hookInterface: Array = [ { hook: 'buildComplete', - props: ['helpers', 'data', 'settings', 'timings', 'query', 'errors', 'routes', 'allRequests'], + props: ['perf', 'helpers', 'data', 'settings', 'timings', 'query', 'errors', 'routes', 'allRequests'], mutable: [], context: 'Executed after a build is complete', use: `

      Contains whether the build was successful. If not it contains errors for the entire build. Also includes diff --git a/src/hooks/index.ts b/src/hooks/index.ts index f5824a0d..25cca1d8 100644 --- a/src/hooks/index.ts +++ b/src/hooks/index.ts @@ -5,6 +5,7 @@ import { parseBuildPerf } from '../utils'; import externalHelpers from '../externalHelpers'; import { HookOptions } from './types'; import prepareShortcodeParser from '../utils/prepareShortcodeParser'; +import { displayPerfTimings } from '../utils/perf'; const hooks: Array = [ { @@ -212,10 +213,7 @@ const hooks: Array = [ if (!settings.build && process.env.NODE_ENV !== 'production') { if (settings.debug.performance) { console.log(`${Math.round(timings.slice(-1)[0].duration * 10) / 10}ms: \t ${request.permalink}`); - const outTimings = [...timings]; - const display = outTimings.sort((a, b) => a.duration - b.duration).map((t) => ({ ...t, ms: t.duration })); - - console.table(display, ['name', 'ms']); + displayPerfTimings([...timings]); } else { console.log(request.permalink); } diff --git a/src/plugins/__tests__/plugins.spec.ts b/src/plugins/__tests__/plugins.spec.ts index 69b3e5f6..6a6dd3d4 100644 --- a/src/plugins/__tests__/plugins.spec.ts +++ b/src/plugins/__tests__/plugins.spec.ts @@ -2,6 +2,11 @@ import path from 'path'; const findComponent = () => ({ ssr: true, client: true, iife: undefined }); +const perf = { + start: () => {}, + end: () => {}, +}; + describe('#plugins', () => { beforeEach(() => jest.resetModules()); @@ -31,6 +36,7 @@ describe('#plugins', () => { // eslint-disable-next-line global-require const plugins = require('../index').default; const { pluginRoutes, pluginHooks, pluginShortcodes } = await plugins({ + perf, settings: { plugins: {}, srcDir: 'test/src', @@ -51,6 +57,7 @@ describe('#plugins', () => { // eslint-disable-next-line global-require const plugins = require('../index').default; const { pluginRoutes, pluginHooks, pluginShortcodes } = await plugins({ + perf, settings: { plugins: { 'elder-plugin-upload-s3': { @@ -86,6 +93,7 @@ describe('#plugins', () => { // eslint-disable-next-line global-require const plugins = require('../index').default; const { pluginRoutes, pluginHooks, pluginShortcodes } = await plugins({ + perf, settings: { plugins: { 'elder-plugin-upload-s3': { @@ -142,6 +150,7 @@ describe('#plugins', () => { // eslint-disable-next-line global-require const plugins = require('../index').default; const { pluginRoutes, pluginHooks, pluginShortcodes } = await plugins({ + perf, settings: { plugins: { 'elder-plugin-upload-s3': { @@ -214,6 +223,7 @@ describe('#plugins', () => { // eslint-disable-next-line global-require const plugins = require('../index').default; const { pluginRoutes, pluginHooks, pluginShortcodes } = await plugins({ + perf, settings: { plugins: { 'elder-plugin-upload-s3': { diff --git a/src/plugins/index.ts b/src/plugins/index.ts index cbf80f99..90c499ab 100644 --- a/src/plugins/index.ts +++ b/src/plugins/index.ts @@ -35,6 +35,7 @@ export const pluginVersionCheck = (elderVersion: string, pluginVersion: string): }; async function plugins(elder: Elder) { + elder.perf.start('startup.plugins'); /** * Plugin initialization * * Collect plugin routes @@ -50,6 +51,8 @@ async function plugins(elder: Elder) { let usesNodeModulesFolder = false; const pluginName = pluginNames[i]; + elder.perf.start(`startup.plugins.${pluginName}`); + const pluginConfigFromConfig = elder.settings.plugins[pluginName]; let plugin: PluginOptions | undefined; @@ -83,6 +86,7 @@ async function plugins(elder: Elder) { } if (typeof plugin.init === 'function' || (plugin.init && typeof plugin.init.then === 'function')) { + elder.perf.start(`startup.plugins.${pluginName}.init`); plugin = // eslint-disable-next-line no-await-in-loop (await plugin.init({ @@ -90,6 +94,7 @@ async function plugins(elder: Elder) { config: defaultsDeep(pluginConfigFromConfig, plugin.config), settings: createReadOnlyProxy(elder.settings, 'Settings', 'plugin init()'), })) || plugin; + elder.perf.end(`startup.plugins.${pluginName}.init`); } if (plugin.minimumElderjsVersion) { @@ -303,7 +308,10 @@ async function plugins(elder: Elder) { }); } } + + elder.perf.end(`startup.plugins.${pluginName}`); } + elder.perf.end('startup.plugins'); return { pluginRoutes, pluginHooks, pluginShortcodes }; } diff --git a/src/utils/Page.ts b/src/utils/Page.ts index 9daf1bd4..084de7a5 100644 --- a/src/utils/Page.ts +++ b/src/utils/Page.ts @@ -27,7 +27,7 @@ const buildPage = async (page) => { settings: createReadOnlyProxy(page.settings, 'settings', `${page.request.route}: data function`), request: createReadOnlyProxy(page.request, 'request', `${page.request.route}: data function`), errors: page.errors, - perf: page.perf, + perf: page.perf.prefix('data'), allRequests: createReadOnlyProxy(page.allRequests, 'allRequests', `${page.request.route}: data function`), next: page.next, }); diff --git a/src/utils/__tests__/Page.spec.ts b/src/utils/__tests__/Page.spec.ts index 31546035..6655c9dd 100644 --- a/src/utils/__tests__/Page.spec.ts +++ b/src/utils/__tests__/Page.spec.ts @@ -29,6 +29,7 @@ jest.mock('../perf', () => (page) => { start: jest.fn(), end: jest.fn(), stop: jest.fn(), + prefix: jest.fn(), }; }); @@ -208,6 +209,10 @@ describe('#Page', () => { errors: [], runHook, shortcodes: [], + perf: { + start: () => {}, + stop: () => {}, + }, }; it('initialize and build', async () => { diff --git a/src/utils/__tests__/__snapshots__/Page.spec.ts.snap b/src/utils/__tests__/__snapshots__/Page.spec.ts.snap index f37df1ea..313c817e 100644 --- a/src/utils/__tests__/__snapshots__/Page.spec.ts.snap +++ b/src/utils/__tests__/__snapshots__/Page.spec.ts.snap @@ -62,6 +62,7 @@ Object { }, ], }, + "prefix": [MockFunction], "start": [MockFunction] { "calls": Array [ Array [ @@ -339,6 +340,19 @@ Object { }, ], }, + "prefix": [MockFunction] { + "calls": Array [ + Array [ + "data", + ], + ], + "results": Array [ + Object { + "type": "return", + "value": undefined, + }, + ], + }, "start": [MockFunction] { "calls": Array [ Array [ @@ -560,6 +574,19 @@ Object { }, ], }, + "prefix": [MockFunction] { + "calls": Array [ + Array [ + "data", + ], + ], + "results": Array [ + Object { + "type": "return", + "value": undefined, + }, + ], + }, "start": [MockFunction] { "calls": Array [ Array [ @@ -1051,6 +1078,19 @@ Object { }, ], }, + "prefix": [MockFunction] { + "calls": Array [ + Array [ + "data", + ], + ], + "results": Array [ + Object { + "type": "return", + "value": undefined, + }, + ], + }, "start": [MockFunction] { "calls": Array [ Array [ diff --git a/src/utils/__tests__/__snapshots__/perf.spec.ts.snap b/src/utils/__tests__/__snapshots__/perf.spec.ts.snap index b76f0eea..0e0e81f0 100644 --- a/src/utils/__tests__/__snapshots__/perf.spec.ts.snap +++ b/src/utils/__tests__/__snapshots__/perf.spec.ts.snap @@ -1,10 +1,11 @@ // Jest Snapshot v1, https://goo.gl/fbAQLP -exports[`#perf works in performance 1`] = ` +exports[`#perf works in performance and mocks 1`] = ` Object { "htmlString": "", "perf": Object { "end": [Function], + "prefix": [Function], "start": [Function], "stop": [Function], "timings": Array [ diff --git a/src/utils/__tests__/perf.spec.ts b/src/utils/__tests__/perf.spec.ts index 6f936f1b..6820e4d8 100644 --- a/src/utils/__tests__/perf.spec.ts +++ b/src/utils/__tests__/perf.spec.ts @@ -17,7 +17,7 @@ class PerformanceObserverMock { } describe('#perf', () => { - it('works in performance', () => { + it('works in performance and mocks', () => { function MockPage() { this.uid = 'xxxxxxxx'; this.htmlString = ''; @@ -45,6 +45,12 @@ describe('#perf', () => { mockPage.perf.start('test'); mockPage.perf.end('test'); + + const prefixed = mockPage.perf.prefix('prefix'); + + prefixed.start('prefix'); + prefixed.end('prefix'); + mockPage.perf.stop(); expect(normalizeSnapshot(mockPage)).toMatchSnapshot(); @@ -53,8 +59,12 @@ describe('#perf', () => { 'mark test-start-xxxxxxxx', 'mark test-end-xxxxxxxx', 'measure test-xxxxxxxx', + 'mark prefix.prefix-start-xxxxxxxx', + 'mark prefix.prefix-end-xxxxxxxx', + 'measure prefix.prefix-xxxxxxxx', ]); }); + it('works in non performance', () => { function MockPage() { this.uid = 'xxxxxxxx'; diff --git a/src/utils/__tests__/prepareRunHook.spec.ts b/src/utils/__tests__/prepareRunHook.spec.ts index 303c2075..d92d149e 100644 --- a/src/utils/__tests__/prepareRunHook.spec.ts +++ b/src/utils/__tests__/prepareRunHook.spec.ts @@ -58,7 +58,7 @@ describe('#prepareRunHook', () => { }, magicNumber: 42, }; - const perf = { start: jest.fn(), end: jest.fn() }; + const perf = { start: jest.fn(), end: jest.fn(), prefix: () => {} }; let prepareRunHookFn = prepareRunHook({ hooks: [hooks[0], hooks[1]], allSupportedHooks, settings }); it('throws for unknown hook', async () => { diff --git a/src/utils/perf.ts b/src/utils/perf.ts index 38b6eeb7..a2913e13 100644 --- a/src/utils/perf.ts +++ b/src/utils/perf.ts @@ -1,4 +1,5 @@ import { performance, PerformanceObserver } from 'perf_hooks'; +import { Elder } from '..'; import Page from './Page'; /** * A little helper around perf_hooks. @@ -7,8 +8,13 @@ import Page from './Page'; * This allows you to pass in a page.perf.start('name') and then page.perf.end('name') and the result is stored in a timings array. * */ -const perf = (page: Page) => { - if (page.settings.debug.performance) { + +export type TPerfTiming = { name: string; duration: number }; + +export type TPerfTimings = TPerfTiming[]; + +const perf = (page: Page | Elder, force = false) => { + if (page.settings.debug.performance || force) { let obs = new PerformanceObserver((items) => { items.getEntries().forEach((entry) => { if (entry.name.includes(page.uid)) { @@ -27,6 +33,7 @@ const perf = (page: Page) => { * @param {String} label */ start: (label: string) => { + console.log(`${label}-start-${page.uid}`); performance.mark(`${label}-start-${page.uid}`); }, /** @@ -55,6 +62,17 @@ const perf = (page: Page) => { stop: placeholder, }; } + + // eslint-disable-next-line no-param-reassign + page.perf.prefix = (pre) => { + console.log('prefix', pre); + return { start: (name) => page.perf.start(`${pre}.${name}`), end: (name) => page.perf.end(`${pre}.${name}`) }; + }; }; export default perf; + +export const displayPerfTimings = (timings: TPerfTimings) => { + const display = timings.sort((a, b) => a.duration - b.duration).map((t) => ({ ...t, ms: t.duration })); + console.table(display, ['name', 'ms']); +}; diff --git a/src/utils/prepareRunHook.ts b/src/utils/prepareRunHook.ts index c9baecf4..347dd4ed 100644 --- a/src/utils/prepareRunHook.ts +++ b/src/utils/prepareRunHook.ts @@ -13,8 +13,10 @@ function prepareRunHook({ hooks, allSupportedHooks, settings }) { } const hookProps = hookDefinition.props.reduce((out, cv) => { + if (cv === 'perf') return out; // perf added and prefixed below + if (Object.hasOwnProperty.call(props, cv)) { - if (!hookDefinition.mutable.includes(cv)) { + if (!hookDefinition.mutable.includes(cv) && cv !== 'perf') { out[cv] = createReadOnlyProxy(props[cv], cv, hookName); } else { out[cv] = props[cv]; @@ -44,7 +46,10 @@ function prepareRunHook({ hooks, allSupportedHooks, settings }) { return p.then(async () => { if (props.perf) props.perf.start(`hook.${hookName}.${hook.name}`); try { - let hookResponse = await hook.run(hookProps); + let hookResponse = await hook.run({ + ...hookProps, + perf: props.perf.prefix(`hook.${hookName}.${hook.name}`), + }); if (!hookResponse) hookResponse = {}; diff --git a/src/utils/prepareServer.ts b/src/utils/prepareServer.ts index b9c23259..504045ed 100644 --- a/src/utils/prepareServer.ts +++ b/src/utils/prepareServer.ts @@ -1,7 +1,8 @@ function prepareServer({ bootstrapComplete }) { // eslint-disable-next-line consistent-return return async function prepServer(req, res, next) { - const { runHook, ...bootstrap } = await bootstrapComplete; + // eslint-disable-next-line @typescript-eslint/no-unused-vars + const { runHook, perf, ...bootstrap } = await bootstrapComplete; await runHook('middleware', { ...bootstrap,