[sitecore-jss][Next.js] Introduce performance metrics for debug loggi…

…ng (#1555)

* [sitecore-jss][Next.js] Introduce performance metrics for debug logging

* Update CHANGELOG

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]` `[templates/react]` `[templates/vue]` `[templates/angular]`  Introduce layout service REST configuration name environment variable ([#1543](https://github.com/Sitecore/jss/pull/1543))
 * `[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))
 

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<NextResponse> {
   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;
 }

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<SitecorePageProps> {
+    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;
   }
 }

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<void> => {
     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<string, unknown>;

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

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';

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<unknown>;
+
+    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: {

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),

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<unknown>;
+
+    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: {

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),