From d0f0206e79f1e767e774a8b05eb4466f834cf98f Mon Sep 17 00:00:00 2001 From: illiakovalenko Date: Mon, 10 Jul 2023 12:31:35 +0300 Subject: [PATCH 1/2] [sitecore-jss][Next.js] Introduce performance metrics for debug logging --- .../nextjs/src/lib/middleware/index.ts | 11 ++++- .../src/lib/page-props-factory/index.ts | 6 +++ .../src/editing/editing-render-middleware.ts | 7 ++- packages/sitecore-jss-nextjs/src/index.ts | 1 + .../src/middleware/index.ts | 1 + .../middleware/multisite-middleware.test.ts | 19 +++++--- .../src/middleware/multisite-middleware.ts | 3 +- .../middleware/personalize-middleware.test.ts | 25 ++++++----- .../src/middleware/personalize-middleware.ts | 3 +- .../middleware/redirects-middleware.test.ts | 43 +++++++++++-------- .../src/middleware/redirects-middleware.ts | 3 +- packages/sitecore-jss/src/axios-fetcher.ts | 6 ++- packages/sitecore-jss/src/debug.ts | 1 + .../src/graphql-request-client.ts | 4 +- packages/sitecore-jss/src/native-fetcher.ts | 3 +- 15 files changed, 92 insertions(+), 44 deletions(-) diff --git a/packages/create-sitecore-jss/src/templates/nextjs/src/lib/middleware/index.ts b/packages/create-sitecore-jss/src/templates/nextjs/src/lib/middleware/index.ts index e0b0b535c5..c9384b2d6d 100644 --- a/packages/create-sitecore-jss/src/templates/nextjs/src/lib/middleware/index.ts +++ b/packages/create-sitecore-jss/src/templates/nextjs/src/lib/middleware/index.ts @@ -1,5 +1,6 @@ import { NextResponse } from 'next/server'; import type { NextFetchEvent, NextRequest } from 'next/server'; +import { debug } from '@sitecore-jss/sitecore-jss-nextjs/middleware'; import * as plugins from 'temp/middleware-plugins'; export interface MiddlewarePlugin { @@ -19,7 +20,15 @@ export default async function middleware( ): Promise { const response = NextResponse.next(); - return (Object.values(plugins) as MiddlewarePlugin[]) + debug.common('next middleware start'); + + const start = Date.now(); + + const finalRes = await (Object.values(plugins) as MiddlewarePlugin[]) .sort((p1, p2) => p1.order - p2.order) .reduce((p, plugin) => p.then((res) => plugin.exec(req, res, ev)), Promise.resolve(response)); + + debug.common('next middleware end in %dms', Date.now() - start); + + return finalRes; } diff --git a/packages/create-sitecore-jss/src/templates/nextjs/src/lib/page-props-factory/index.ts b/packages/create-sitecore-jss/src/templates/nextjs/src/lib/page-props-factory/index.ts index 2c5e62e2b8..a05073fef0 100644 --- a/packages/create-sitecore-jss/src/templates/nextjs/src/lib/page-props-factory/index.ts +++ b/packages/create-sitecore-jss/src/templates/nextjs/src/lib/page-props-factory/index.ts @@ -1,4 +1,5 @@ import { GetServerSidePropsContext, GetStaticPropsContext } from 'next'; +import { debug } from '@sitecore-jss/sitecore-jss-nextjs'; import { SitecorePageProps } from 'lib/page-props'; import * as plugins from 'temp/page-props-factory-plugins'; @@ -35,6 +36,9 @@ export class SitecorePagePropsFactory { public async create( context: GetServerSidePropsContext | GetStaticPropsContext ): Promise { + const startTimestamp = Date.now(); + debug.common('page-props-factory start'); + const extendedProps = await (Object.values(plugins) as Plugin[]) .sort((p1, p2) => p1.order - p2.order) .reduce(async (result, plugin) => { @@ -43,6 +47,8 @@ export class SitecorePagePropsFactory { return newProps; }, Promise.resolve({} as SitecorePageProps)); + debug.common('page-props-factory end in %dms', Date.now() - startTimestamp); + return extendedProps; } } diff --git a/packages/sitecore-jss-nextjs/src/editing/editing-render-middleware.ts b/packages/sitecore-jss-nextjs/src/editing/editing-render-middleware.ts index b38ba79a82..e3bc72f213 100644 --- a/packages/sitecore-jss-nextjs/src/editing/editing-render-middleware.ts +++ b/packages/sitecore-jss-nextjs/src/editing/editing-render-middleware.ts @@ -78,6 +78,8 @@ export class EditingRenderMiddleware { private handler = async (req: NextApiRequest, res: NextApiResponse): Promise => { const { method, query, body, headers } = req; + const startTimestamp = Date.now(); + debug.editing('editing render middleware start: %o', { method, query, @@ -172,7 +174,10 @@ export class EditingRenderMiddleware { const body = { html }; // Return expected JSON result - debug.editing('editing render middleware end: %o', { status: 200, body }); + debug.editing('editing render middleware end in %dms: %o', Date.now() - startTimestamp, { + status: 200, + body, + }); res.status(200).json(body); } catch (err) { const error = err as Record; diff --git a/packages/sitecore-jss-nextjs/src/index.ts b/packages/sitecore-jss-nextjs/src/index.ts index 5ccbb21b97..5a84e831ff 100644 --- a/packages/sitecore-jss-nextjs/src/index.ts +++ b/packages/sitecore-jss-nextjs/src/index.ts @@ -10,6 +10,7 @@ export { NativeDataFetcherConfig, HTMLLink, enableDebug, + debug, } from '@sitecore-jss/sitecore-jss'; // we will remove the root exports for these later diff --git a/packages/sitecore-jss-nextjs/src/middleware/index.ts b/packages/sitecore-jss-nextjs/src/middleware/index.ts index b9c1ecf305..3c62846310 100644 --- a/packages/sitecore-jss-nextjs/src/middleware/index.ts +++ b/packages/sitecore-jss-nextjs/src/middleware/index.ts @@ -1,3 +1,4 @@ +export { debug } from '@sitecore-jss/sitecore-jss'; export { RedirectsMiddleware, RedirectsMiddlewareConfig } from './redirects-middleware'; export { PersonalizeMiddleware, PersonalizeMiddlewareConfig } from './personalize-middleware'; export { MultisiteMiddleware, MultisiteMiddlewareConfig } from './multisite-middleware'; diff --git a/packages/sitecore-jss-nextjs/src/middleware/multisite-middleware.test.ts b/packages/sitecore-jss-nextjs/src/middleware/multisite-middleware.test.ts index d341aa68f0..2dcbe097ca 100644 --- a/packages/sitecore-jss-nextjs/src/middleware/multisite-middleware.test.ts +++ b/packages/sitecore-jss-nextjs/src/middleware/multisite-middleware.test.ts @@ -17,6 +17,11 @@ describe('MultisiteMiddleware', () => { const debugSpy = spy(debug, 'multisite'); const validateDebugLog = (message, ...params) => expect(debugSpy.args.find((log) => log[0] === message)).to.deep.equal([message, ...params]); + const validateEndMessageDebugLog = (message, params) => { + const logParams = debugSpy.args.find((log) => log[0] === message) as Array; + + expect(logParams[2]).to.deep.equal(params); + }; const siteName = 'foo'; @@ -235,7 +240,7 @@ describe('MultisiteMiddleware', () => { hostname: 'bar.net', }); - validateDebugLog('multisite middleware end: %o', { + validateEndMessageDebugLog('multisite middleware end in %dms: %o', { rewritePath: '/_site_foo/styleguide', siteName: 'foo', headers: { @@ -276,7 +281,7 @@ describe('MultisiteMiddleware', () => { hostname: 'localhost', }); - validateDebugLog('multisite middleware end: %o', { + validateEndMessageDebugLog('multisite middleware end in %dms: %o', { rewritePath: '/_site_foo/styleguide', siteName: 'foo', headers: { @@ -315,7 +320,7 @@ describe('MultisiteMiddleware', () => { hostname: 'foo.net', }); - validateDebugLog('multisite middleware end: %o', { + validateEndMessageDebugLog('multisite middleware end in %dms: %o', { rewritePath: '/_site_foo/styleguide', siteName: 'foo', headers: { @@ -354,7 +359,7 @@ describe('MultisiteMiddleware', () => { hostname: 'foo.net', }); - validateDebugLog('multisite middleware end: %o', { + validateEndMessageDebugLog('multisite middleware end in %dms: %o', { rewritePath: '/_site_foo/styleguide', siteName: 'foo', headers: { @@ -397,7 +402,7 @@ describe('MultisiteMiddleware', () => { hostname: 'foo.net', }); - validateDebugLog('multisite middleware end: %o', { + validateEndMessageDebugLog('multisite middleware end in %dms: %o', { rewritePath: '/_site_qsFoo/styleguide', siteName: 'qsFoo', headers: { @@ -441,7 +446,7 @@ describe('MultisiteMiddleware', () => { hostname: 'foo.net', }); - validateDebugLog('multisite middleware end: %o', { + validateEndMessageDebugLog('multisite middleware end in %dms: %o', { rewritePath: '/_site_foobar/styleguide', siteName: 'foobar', headers: { @@ -483,7 +488,7 @@ describe('MultisiteMiddleware', () => { hostname: 'foo.net', }); - validateDebugLog('multisite middleware end: %o', { + validateEndMessageDebugLog('multisite middleware end in %dms: %o', { rewritePath: '/_site_foo/styleguide', siteName: 'foo', headers: { diff --git a/packages/sitecore-jss-nextjs/src/middleware/multisite-middleware.ts b/packages/sitecore-jss-nextjs/src/middleware/multisite-middleware.ts index 5acb4ce992..69510af259 100644 --- a/packages/sitecore-jss-nextjs/src/middleware/multisite-middleware.ts +++ b/packages/sitecore-jss-nextjs/src/middleware/multisite-middleware.ts @@ -41,6 +41,7 @@ export class MultisiteMiddleware extends MiddlewareBase { const pathname = req.nextUrl.pathname; const language = this.getLanguage(req); const hostname = this.getHostHeader(req) || this.defaultHostname; + const startTimestamp = Date.now(); debug.multisite('multisite middleware start: %o', { pathname, @@ -82,7 +83,7 @@ export class MultisiteMiddleware extends MiddlewareBase { // Share rewrite path with following executed middlewares response.headers.set('x-sc-rewrite', rewritePath); - debug.multisite('multisite middleware end: %o', { + debug.multisite('multisite middleware end in %dms: %o', Date.now() - startTimestamp, { rewritePath, siteName, headers: this.extractDebugHeaders(response.headers), diff --git a/packages/sitecore-jss-nextjs/src/middleware/personalize-middleware.test.ts b/packages/sitecore-jss-nextjs/src/middleware/personalize-middleware.test.ts index 8eeecee1af..f24e87b269 100644 --- a/packages/sitecore-jss-nextjs/src/middleware/personalize-middleware.test.ts +++ b/packages/sitecore-jss-nextjs/src/middleware/personalize-middleware.test.ts @@ -19,6 +19,11 @@ describe('PersonalizeMiddleware', () => { const debugSpy = spy(debug, 'personalize'); const validateDebugLog = (message, ...params) => expect(debugSpy.args.find((log) => log[0] === message)).to.deep.equal([message, ...params]); + const validateEndMessageDebugLog = (message, params) => { + const logParams = debugSpy.args.find((log) => log[0] === message) as Array; + + expect(logParams[2]).to.deep.equal(params); + }; const hostname = 'foo.net'; const siteName = 'bar'; @@ -608,7 +613,7 @@ describe('PersonalizeMiddleware', () => { expect(executeExperience.calledWith(contentId, browserId, ua, pointOfSale, experienceParams)) .to.be.true; - validateDebugLog('personalize middleware end: %o', { + validateEndMessageDebugLog('personalize middleware end in %dms: %o', { rewritePath: '/_variantId_variant-2/styleguide', browserId: 'browser-id', headers: { @@ -670,7 +675,7 @@ describe('PersonalizeMiddleware', () => { expect(executeExperience.calledWith(contentId, browserId, ua, pointOfSale, experienceParams)) .to.be.true; - validateDebugLog('personalize middleware end: %o', { + validateEndMessageDebugLog('personalize middleware end in %dms: %o', { rewritePath: '/_variantId_variant-2/styleguide', browserId: 'browser-id', headers: { @@ -731,7 +736,7 @@ describe('PersonalizeMiddleware', () => { expect(executeExperience.calledWith(contentId, browserId, ua, pointOfSale, experienceParams)) .to.be.true; - validateDebugLog('personalize middleware end: %o', { + validateEndMessageDebugLog('personalize middleware end in %dms: %o', { rewritePath: '/_variantId_variant-2/styleguide', browserId: 'browser-id', headers: { @@ -785,7 +790,7 @@ describe('PersonalizeMiddleware', () => { expect(executeExperience.calledWith(contentId, browserId, ua, pointOfSale, experienceParams)) .to.be.true; - validateDebugLog('personalize middleware end: %o', { + validateEndMessageDebugLog('personalize middleware end in %dms: %o', { rewritePath: '/_variantId_variant-2/styleguide', browserId: 'browser-id', headers: { @@ -834,7 +839,7 @@ describe('PersonalizeMiddleware', () => { language: 'en', }); - validateDebugLog('personalize middleware end: %o', { + validateEndMessageDebugLog('personalize middleware end in %dms: %o', { rewritePath: '/_variantId_variant-2/styleguide', browserId: 'browser-id', headers: { @@ -894,7 +899,7 @@ describe('PersonalizeMiddleware', () => { }) ).to.be.true; - validateDebugLog('personalize middleware end: %o', { + validateEndMessageDebugLog('personalize middleware end in %dms: %o', { rewritePath: '/_variantId_variant-2/styleguide', browserId: 'browser-id', headers: { @@ -947,7 +952,7 @@ describe('PersonalizeMiddleware', () => { expect(executeExperience.calledWith(contentId, browserId, ua, pointOfSale, experienceParams)) .to.be.true; - validateDebugLog('personalize middleware end: %o', { + validateEndMessageDebugLog('personalize middleware end in %dms: %o', { rewritePath: '/_variantId_variant-2/styleguide', browserId: 'browser-id', headers: { @@ -1000,7 +1005,7 @@ describe('PersonalizeMiddleware', () => { expect(executeExperience.calledWith(contentId, browserId, ua, pointOfSale, experienceParams)) .to.be.true; - validateDebugLog('personalize middleware end: %o', { + validateEndMessageDebugLog('personalize middleware end in %dms: %o', { rewritePath: '/_variantId_variant-2/_site_nextjs-app/styleguide', browserId: 'browser-id', headers: { @@ -1052,7 +1057,7 @@ describe('PersonalizeMiddleware', () => { expect(executeExperience.calledWith(contentId, browserId, ua, pointOfSale, experienceParams)) .to.be.true; - validateDebugLog('personalize middleware end: %o', { + validateEndMessageDebugLog('personalize middleware end in %dms: %o', { rewritePath: '/_variantId_variant-2/styleguide', browserId: 'browser-id', headers: { @@ -1105,7 +1110,7 @@ describe('PersonalizeMiddleware', () => { expect(executeExperience.calledWith(contentId, browserId, ua, pointOfSale, experienceParams)) .to.be.true; - validateDebugLog('personalize middleware end: %o', { + validateEndMessageDebugLog('personalize middleware end in %dms: %o', { rewritePath: '/_variantId_variant-2/styleguide', browserId: 'browser-id', headers: { diff --git a/packages/sitecore-jss-nextjs/src/middleware/personalize-middleware.ts b/packages/sitecore-jss-nextjs/src/middleware/personalize-middleware.ts index ec91588d04..8975e2afe5 100644 --- a/packages/sitecore-jss-nextjs/src/middleware/personalize-middleware.ts +++ b/packages/sitecore-jss-nextjs/src/middleware/personalize-middleware.ts @@ -119,6 +119,7 @@ export class PersonalizeMiddleware extends MiddlewareBase { const pathname = req.nextUrl.pathname; const language = this.getLanguage(req); const hostname = this.getHostHeader(req) || this.defaultHostname; + const startTimestamp = Date.now(); let browserId = this.getBrowserId(req); debug.personalize('personalize middleware start: %o', { @@ -222,7 +223,7 @@ export class PersonalizeMiddleware extends MiddlewareBase { // Share site name with the following executed middlewares response.cookies.set(this.SITE_SYMBOL, site.name); - debug.personalize('personalize middleware end: %o', { + debug.personalize('personalize middleware end in %dms: %o', Date.now() - startTimestamp, { rewritePath, browserId, headers: this.extractDebugHeaders(response.headers), diff --git a/packages/sitecore-jss-nextjs/src/middleware/redirects-middleware.test.ts b/packages/sitecore-jss-nextjs/src/middleware/redirects-middleware.test.ts index fe4875bea5..107390ed15 100644 --- a/packages/sitecore-jss-nextjs/src/middleware/redirects-middleware.test.ts +++ b/packages/sitecore-jss-nextjs/src/middleware/redirects-middleware.test.ts @@ -22,6 +22,11 @@ describe('RedirectsMiddleware', () => { const debugSpy = spy(debug, 'redirects'); const validateDebugLog = (message, ...params) => expect(debugSpy.args.find((log) => log[0] === message)).to.deep.equal([message, ...params]); + const validateEndMessageDebugLog = (message, params) => { + const logParams = debugSpy.args.find((log) => log[0] === message) as Array; + + expect(logParams[2]).to.deep.equal(params); + }; const referrer = 'http://localhost:3000'; const hostname = 'foo.net'; @@ -172,7 +177,7 @@ describe('RedirectsMiddleware', () => { validateDebugLog('skipped (%s)', 'preview'); - validateDebugLog('redirects middleware end: %o', { + validateEndMessageDebugLog('redirects middleware end in %dms: %o', { headers: { 'x-middleware-next': '1', }, @@ -204,7 +209,7 @@ describe('RedirectsMiddleware', () => { validateDebugLog('skipped (%s)', 'preview'); - validateDebugLog('redirects middleware end: %o', { + validateEndMessageDebugLog('redirects middleware end in %dms: %o', { headers: { 'x-middleware-next': '1', }, @@ -237,7 +242,7 @@ describe('RedirectsMiddleware', () => { validateDebugLog('skipped (%s)', 'route excluded'); - validateDebugLog('redirects middleware end: %o', { + validateEndMessageDebugLog('redirects middleware end in %dms: %o', { headers: { 'x-middleware-next': '1', }, @@ -297,7 +302,7 @@ describe('RedirectsMiddleware', () => { validateDebugLog('skipped (redirects middleware is disabled)'); - validateDebugLog('redirects middleware end: %o', { + validateEndMessageDebugLog('redirects middleware end in %dms: %o', { headers: {}, redirected: undefined, status: undefined, @@ -326,7 +331,7 @@ describe('RedirectsMiddleware', () => { validateDebugLog('skipped (redirect does not exist)'); - validateDebugLog('redirects middleware end: %o', { + validateEndMessageDebugLog('redirects middleware end in %dms: %o', { headers: {}, redirected: undefined, status: undefined, @@ -383,7 +388,7 @@ describe('RedirectsMiddleware', () => { pathname: '/not-found', }); - validateDebugLog('redirects middleware end: %o', { + validateEndMessageDebugLog('redirects middleware end in %dms: %o', { headers: {}, redirected: undefined, status: 301, @@ -440,7 +445,7 @@ describe('RedirectsMiddleware', () => { language: 'en', }); - validateDebugLog('redirects middleware end: %o', { + validateEndMessageDebugLog('redirects middleware end in %dms: %o', { headers: {}, redirected: undefined, status: 301, @@ -497,7 +502,7 @@ describe('RedirectsMiddleware', () => { pathname: '/not-found', }); - validateDebugLog('redirects middleware end: %o', { + validateEndMessageDebugLog('redirects middleware end in %dms: %o', { headers: {}, redirected: undefined, status: 301, @@ -556,7 +561,7 @@ describe('RedirectsMiddleware', () => { pathname: '/not-found', }); - validateDebugLog('redirects middleware end: %o', { + validateEndMessageDebugLog('redirects middleware end in %dms: %o', { headers: {}, redirected: undefined, status: 301, @@ -602,7 +607,7 @@ describe('RedirectsMiddleware', () => { pathname: '/not-found', }); - validateDebugLog('redirects middleware end: %o', { + validateEndMessageDebugLog('redirects middleware end in %dms: %o', { headers: { 'set-cookie': 'sc_site=nextjs-app; Path=/', 'x-middleware-next': '1', @@ -657,7 +662,7 @@ describe('RedirectsMiddleware', () => { pathname: '/not-found', }); - validateDebugLog('redirects middleware end: %o', { + validateEndMessageDebugLog('redirects middleware end in %dms: %o', { headers: {}, redirected: undefined, status: 302, @@ -717,7 +722,7 @@ describe('RedirectsMiddleware', () => { pathname: '/not-found', }); - validateDebugLog('redirects middleware end: %o', { + validateEndMessageDebugLog('redirects middleware end in %dms: %o', { headers: {}, redirected: undefined, status: 301, @@ -769,7 +774,7 @@ describe('RedirectsMiddleware', () => { pathname: '/not-found', }); - validateDebugLog('redirects middleware end: %o', { + validateEndMessageDebugLog('redirects middleware end in %dms: %o', { headers: {}, redirected: undefined, status: 301, @@ -823,7 +828,7 @@ describe('RedirectsMiddleware', () => { pathname: '/not-found', }); - validateDebugLog('redirects middleware end: %o', { + validateEndMessageDebugLog('redirects middleware end in %dms: %o', { headers: {}, redirected: undefined, status: undefined, @@ -868,7 +873,7 @@ describe('RedirectsMiddleware', () => { pathname: '/not-found', }); - validateDebugLog('redirects middleware end: %o', { + validateEndMessageDebugLog('redirects middleware end in %dms: %o', { headers: { location: 'http://localhost:3000/found', 'set-cookie': 'sc_site=foo; Path=/', @@ -915,7 +920,7 @@ describe('RedirectsMiddleware', () => { pathname: '/not-found', }); - validateDebugLog('redirects middleware end: %o', { + validateEndMessageDebugLog('redirects middleware end in %dms: %o', { headers: { 'set-cookie': 'sc_site=learn2grow; Path=/', 'x-middleware-next': '1', @@ -964,7 +969,7 @@ describe('RedirectsMiddleware', () => { validateDebugLog('skipped (redirects middleware is disabled)'); - validateDebugLog('redirects middleware end: %o', { + validateEndMessageDebugLog('redirects middleware end in %dms: %o', { headers: { 'set-cookie': 'sc_site=learn2grow; Path=/', 'x-middleware-next': '1', @@ -1025,7 +1030,7 @@ describe('RedirectsMiddleware', () => { pathname: '/not-found', }); - validateDebugLog('redirects middleware end: %o', { + validateEndMessageDebugLog('redirects middleware end in %dms: %o', { headers: {}, redirected: undefined, status: 301, @@ -1086,7 +1091,7 @@ describe('RedirectsMiddleware', () => { language: 'en', }); - validateDebugLog('redirects middleware end: %o', { + validateEndMessageDebugLog('redirects middleware end in %dms: %o', { headers: {}, redirected: undefined, status: 301, diff --git a/packages/sitecore-jss-nextjs/src/middleware/redirects-middleware.ts b/packages/sitecore-jss-nextjs/src/middleware/redirects-middleware.ts index 0e5bfa4804..8f388217b6 100644 --- a/packages/sitecore-jss-nextjs/src/middleware/redirects-middleware.ts +++ b/packages/sitecore-jss-nextjs/src/middleware/redirects-middleware.ts @@ -66,6 +66,7 @@ export class RedirectsMiddleware extends MiddlewareBase { const language = this.getLanguage(req); const hostname = this.getHostHeader(req) || this.defaultHostname; let site: SiteInfo | undefined; + const startTimestamp = Date.now(); debug.redirects('redirects middleware start: %o', { pathname, @@ -141,7 +142,7 @@ export class RedirectsMiddleware extends MiddlewareBase { // Don't need to set when middleware is disabled site && response.cookies.set(this.SITE_SYMBOL, site.name); - debug.redirects('redirects middleware end: %o', { + debug.redirects('redirects middleware end in %dms: %o', Date.now() - startTimestamp, { redirected: response.redirected, status: response.status, url: response.url, diff --git a/packages/sitecore-jss/src/axios-fetcher.ts b/packages/sitecore-jss/src/axios-fetcher.ts index adcb7e0b7c..489dce4b2f 100644 --- a/packages/sitecore-jss/src/axios-fetcher.ts +++ b/packages/sitecore-jss/src/axios-fetcher.ts @@ -77,6 +77,8 @@ export class AxiosDataFetcher { this.instance.interceptors.request.use( (config: AxiosRequestConfig) => { debug('request: %o', config); + // passing timestamp for debug logging + config.headers.timestamp = Date.now(); return config; }, (error: unknown) => { @@ -97,7 +99,9 @@ export class AxiosDataFetcher { // Note we're removing redundant properties (already part of request log above) to trim down log entry // eslint-disable-next-line @typescript-eslint/no-unused-vars const { request, config, ...rest } = response; - debug('response: %o', rest); + const duration = Date.now() - config.headers.timestamp; + delete response.config.headers.timestamp; + debug('response in %dms: %o', duration, rest); return response; }, (error: unknown) => { diff --git a/packages/sitecore-jss/src/debug.ts b/packages/sitecore-jss/src/debug.ts index c62916210a..83e87a34b9 100644 --- a/packages/sitecore-jss/src/debug.ts +++ b/packages/sitecore-jss/src/debug.ts @@ -28,6 +28,7 @@ export const enableDebug = (namespaces: string) => debug.enable(namespaces); * See {@link https://www.npmjs.com/package/debug} for details. */ export default { + common: debug(`${rootNamespace}:common`), http: debug(`${rootNamespace}:http`), layout: debug(`${rootNamespace}:layout`), dictionary: debug(`${rootNamespace}:dictionary`), diff --git a/packages/sitecore-jss/src/graphql-request-client.ts b/packages/sitecore-jss/src/graphql-request-client.ts index bc42bceb1a..6300a176a1 100644 --- a/packages/sitecore-jss/src/graphql-request-client.ts +++ b/packages/sitecore-jss/src/graphql-request-client.ts @@ -82,6 +82,8 @@ export class GraphQLRequestClient implements GraphQLClient { query: string | DocumentNode, variables?: { [key: string]: unknown } ): Promise { + const startTimestamp = Date.now(); + return new Promise((resolve, reject) => { // Note we don't have access to raw request/response with graphql-request // (or nice hooks like we have with Axios), but we should log whatever we have. @@ -100,7 +102,7 @@ export class GraphQLRequestClient implements GraphQLClient { Promise.race(fetchWithOptionalTimeout).then( (data: T) => { this.abortTimeout?.clear(); - this.debug('response: %o', data); + this.debug('response in %dms: %o', Date.now() - startTimestamp, data); resolve(data); }, (error: ClientError) => { diff --git a/packages/sitecore-jss/src/native-fetcher.ts b/packages/sitecore-jss/src/native-fetcher.ts index 0cc551e58f..330f45a217 100644 --- a/packages/sitecore-jss/src/native-fetcher.ts +++ b/packages/sitecore-jss/src/native-fetcher.ts @@ -32,6 +32,7 @@ export class NativeDataFetcher { */ async fetch(url: string, data?: unknown): Promise> { const { debugger: debugOverride, fetch: fetchOverride, ...init } = this.config; + const startTimestamp = Date.now(); const fetchImpl = fetchOverride || fetch; const debug = debugOverride || debuggers.http; const requestInit = this.getRequestInit(init, data); @@ -80,7 +81,7 @@ export class NativeDataFetcher { debug('response error: %o', debugResponse); throw new Error(`HTTP ${response.status} ${response.statusText}`); } - debug('response: %o', debugResponse); + debug('response in %dms: %o', Date.now() - startTimestamp, debugResponse); return { ...response, data: respData as T, From 8603f0de721cb04694cd9df99752b04cc16f6c78 Mon Sep 17 00:00:00 2001 From: illiakovalenko Date: Mon, 10 Jul 2023 12:33:03 +0300 Subject: [PATCH 2/2] Update CHANGELOG --- CHANGELOG.md | 1 + 1 file changed, 1 insertion(+) diff --git a/CHANGELOG.md b/CHANGELOG.md index 86fb0d34a8..41ce4ed01b 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -13,6 +13,7 @@ Our versioning strategy is as follows: ### ๐ŸŽ‰ New Features & Improvements +* `[sitecore-jss]` `[sitecore-jss-nextjs]` `[templates/nextjs]` Introduce performance metrics for debug logging ([#1555](https://github.com/Sitecore/jss/pull/1555)) * `[templates/nextjs]` `[sitecore-jss-nextjs]` Support for out-of-process editing data caches was added. Vercel KV or a custom Redis cache can be used to improve editing in Pages and Experience Editor when using Vercel deployment as editing/rendering host ([#1530](https://github.com/Sitecore/jss/pull/1530)) ### ๐Ÿงน Chores