@W-18760780 Integrate opentelemetry into performance.js

packages/pwa-kit-react-sdk/CHANGELOG.md

@@ -2,6 +2,7 @@
 - Fix the performance logging so that it'll capture all SSR queries, even those that result in errors [#2486](https://github.com/SalesforceCommerceCloud/pwa-kit/pull/2486)
 - Created an opentelemetry server for SSR tracer intialization [#2617](https://github.com/SalesforceCommerceCloud/pwa-kit/pull/2617)
 - Created opentelemetry.js file with utility functions to log OTel spans and metrics [#2705] (https://github.com/SalesforceCommerceCloud/pwa-kit/pull/2705)
+- Update performance.js with usage of opentelemetry spans and add cleanups [#2722](https://github.com/SalesforceCommerceCloud/pwa-kit/pull/2722)
 
 ## v3.10.0 (May 22, 2025)
 - Fix the performance logging util to use the correct delimiter for the server-timing header. [#2225](https://github.com/SalesforceCommerceCloud/pwa-kit/pull/2295)

packages/pwa-kit-react-sdk/setup-jest.js

@@ -40,4 +40,25 @@ jest.mock('@salesforce/pwa-kit-runtime/utils/ssr-config', () => {
 // The global performance object is available in production
 // environments for both the server and the client.
 // It's just the jest environment that this is not available
-global.performance = performance
+if (global.performance) {
+    // global.performance exists but is missing methods from perf_hooks in jest
+    if (typeof performance.mark === 'function' && !global.performance.mark) {
+        global.performance.mark = performance.mark.bind(performance)
+    }
+    if (typeof performance.measure === 'function' && !global.performance.measure) {
+        global.performance.measure = performance.measure.bind(performance)
+    }
+    if (typeof performance.clearMarks === 'function' && !global.performance.clearMarks) {
+        global.performance.clearMarks = performance.clearMarks.bind(performance)
+    }
+    if (typeof performance.clearMeasures === 'function' && !global.performance.clearMeasures) {
+        global.performance.clearMeasures = performance.clearMeasures.bind(performance)
+    }
+} else {
+    global.performance = performance
+}
+
+// This is needed for spans created in jest environment to not be no-op spans, otherwise the spans will lack attributes
+import {BasicTracerProvider} from '@opentelemetry/sdk-trace-base'
+const provider = new BasicTracerProvider()
+provider.register()

packages/pwa-kit-react-sdk/src/ssr/server/react-rendering.js

@@ -222,6 +222,11 @@ export const render = async (req, res, next) => {
         // Here, we use Express's convention to invoke error middleware.
         // Note, we don't have an error handling middleware yet! This is calling the
         // default error handling middleware provided by Express
+
+        if (res.__performanceTimer) {
+            res.__performanceTimer.cleanup()
+        }
+
         return next(e)
     }
 
@@ -244,6 +249,8 @@ export const render = async (req, res, next) => {
         res.set('Cache-Control', NO_CACHE)
     }
 
+    res.__performanceTimer.cleanup()
+
     if (redirectUrl) {
         res.redirect(routerContext.status || 302, redirectUrl)
     } else {

packages/pwa-kit-react-sdk/src/ssr/server/react-rendering.test.js

@@ -739,6 +739,50 @@ describe('The Node SSR Environment', () => {
                     'max-age=0, nocache, nostore, must-revalidate'
                 )
             }
+        },
+        {
+            description: `Performance timer cleanup is called during rendering`,
+            req: {url: '/pwa/', query: {__server_timing: '1'}},
+            mocks: () => {
+                // Mock PerformanceTimer to spy on cleanup
+                const PerformanceTimer = jest.requireActual('../../utils/performance').default
+                const originalCleanup = PerformanceTimer.prototype.cleanup
+                const cleanupSpy = jest.fn(originalCleanup)
+                PerformanceTimer.prototype.cleanup = cleanupSpy
+
+                // Store the spy for assertions
+                global.performanceCleanupSpy = cleanupSpy
+            },
+            assertions: (res) => {
+                expect(res.statusCode).toBe(200)
+                expect(global.performanceCleanupSpy).toHaveBeenCalled()
+                expect(global.performanceCleanupSpy).toHaveBeenCalledTimes(1)
+
+                // Clean up global
+                delete global.performanceCleanupSpy
+            }
+        },
+        {
+            description: `Performance timer cleanup is called even when rendering throws an error`,
+            req: {url: '/unknown-error/'}, // This URL causes an error
+            mocks: () => {
+                // Mock PerformanceTimer to spy on cleanup
+                const PerformanceTimer = jest.requireActual('../../utils/performance').default
+                const originalCleanup = PerformanceTimer.prototype.cleanup
+                const cleanupSpy = jest.fn(originalCleanup)
+                PerformanceTimer.prototype.cleanup = cleanupSpy
+
+                // Store the spy for assertions
+                global.performanceCleanupSpyError = cleanupSpy
+            },
+            assertions: (res) => {
+                expect(res.statusCode).toBe(500)
+                expect(global.performanceCleanupSpyError).toHaveBeenCalled()
+                expect(global.performanceCleanupSpyError).toHaveBeenCalledTimes(1)
+
+                // Clean up global
+                delete global.performanceCleanupSpyError
+            }
         }
     ]
 

packages/pwa-kit-react-sdk/src/utils/opentelemetry.js

@@ -24,7 +24,6 @@ const logSpanData = (span, event = 'start', res = null) => {
     const startTime = span.startTime
     const endTime = event === 'start' ? startTime : span.endTime
     const duration = event === 'start' ? 0 : hrTimeToMilliseconds(span.duration)
-
     // Create the span data object that matches the expected format
     const spanData = {
         traceId: spanContext.traceId,

packages/pwa-kit-react-sdk/src/utils/performance.js

@@ -5,6 +5,8 @@
  * For full license text, see the LICENSE file in the repo root or https://opensource.org/licenses/BSD-3-Clause
  */
 import logger from './logger-instance'
+import {createChildSpan, endSpan, logPerformanceMetric} from './opentelemetry'
+
 export const PERFORMANCE_MARKS = {
     total: 'ssr.total',
     renderToString: 'ssr.render-to-string',
@@ -32,11 +34,10 @@ export default class PerformanceTimer {
     }
     constructor(options = {}) {
         this.enabled = options.enabled || false
-        this.marks = {
-            start: new Map(),
-            end: new Map()
-        }
         this.metrics = []
+        this.spans = new Map()
+        this.spanTimeouts = new Map()
+        this.maxSpanDuration = options.maxSpanDuration || 30000 // 30 seconds default
     }
 
     /**
@@ -61,15 +62,13 @@ export default class PerformanceTimer {
     }
 
     /**
-     * A utility function to format and log the performance metrics.
-     *
-     * @function
-     * @private
+     * Logs all performance metrics
      */
     log() {
+        // Log each metric once with the standardized format
         this.metrics.forEach((metric) => {
-            logger.info(`${metric.name} - ${metric.duration}ms ${metric.detail || ''}`, {
-                namespace: 'performance'
+            logPerformanceMetric(metric.name, metric.duration, {
+                'performance.detail': metric.detail || ''
             })
         })
     }
@@ -78,50 +77,151 @@ export default class PerformanceTimer {
      * This is a utility function to create performance marks.
      * The data will be used in console logs and the http response header `server-timing`.
      *
-     * @function
-     * @private
+     * @param {string} name - Unique identifier for the performance measurement.
+     * Must be the same for both start and end marks of a pair. E.g. 'ssr.render-to-string'
+     *
+     * @param {string} type - Mark type, either 'start' or 'end'. 'start' creates spans and browser marks,
+     * 'end' completes measurement and cleanup.
+     *
+     * @param {Object} [options={}] - Optional configuration object
+     * @param {string|Object} [options.detail=''] - Additional metadata for the mark
+     * included in logs and tracing attributes.
      */
     mark(name, type, options = {}) {
-        if (!this.enabled) {
+        const {detail = ''} = options
+        if (!name || !type || !this.enabled) {
             return
         }
 
-        if (!name) {
-            logger.warn('Performance mark cannot be created because the name is undefined.', {
-                namespace: 'performance'
-            })
+        if (type !== this.MARKER_TYPES.START && type !== this.MARKER_TYPES.END) {
+            logger.warn('Invalid mark type', {type, name, namespace: 'PerformanceTimer.mark'})
             return
         }
 
-        if (type !== this.MARKER_TYPES.START && type !== this.MARKER_TYPES.END) {
-            logger.warn(
-                'Performance mark cannot be created because the type must be either "start" or "end".',
-                {
-                    namespace: 'performance'
+        try {
+            // Format detail as a string if it's an object
+            const formattedDetail = typeof detail === 'object' ? JSON.stringify(detail) : detail
+
+            performance.mark(`${name}.${type}`, {
+                detail: formattedDetail
+            })
+
+            // Only create spans for 'start' events and store them for later use
+            if (type === this.MARKER_TYPES.START) {
+                if (!this.spans.has(name)) {
+                    const span = createChildSpan(name, {
+                        performance_mark: name,
+                        performance_type: type,
+                        performance_detail: formattedDetail
+                    })
+                    if (span) {
+                        this.spans.set(name, span)
+
+                        // Set up automatic cleanup for orphaned spans
+                        const timeoutId = setTimeout(() => {
+                            this._cleanupOrphanedSpan(name, 'timeout')
+                        }, this.maxSpanDuration)
+                        this.spanTimeouts.set(name, timeoutId)
+                    }
                 }
-            )
-            return
-        }
+            } else if (type === this.MARKER_TYPES.END) {
+                const startMark = `${name}.${this.MARKER_TYPES.START}`
+                const endMark = `${name}.${this.MARKER_TYPES.END}`
 
-        const timestamp = performance.now()
-        const isEnd = type === this.MARKER_TYPES.END
-        const storage = isEnd ? this.marks.end : this.marks.start
-        storage.set(name, {
-            name,
-            timestamp,
-            detail: options.detail
-        })
+                try {
+                    const measure = performance.measure(name, startMark, endMark)
 
-        if (isEnd) {
-            const startMark = this.marks.start.get(name)
-            if (startMark) {
-                const measurement = {
-                    name,
-                    duration: timestamp - startMark.timestamp,
-                    detail: options.detail
+                    // Add the metric to the metrics array for Server-Timing header
+                    this.metrics.push({
+                        name,
+                        duration: measure.duration,
+                        detail: formattedDetail
+                    })
+
+                    // End the corresponding span if it exists and clear timeout
+                    const span = this.spans.get(name)
+                    if (span) {
+                        endSpan(span)
+                        this.spans.delete(name)
+
+                        // Clear the timeout since span completed normally
+                        const timeoutId = this.spanTimeouts.get(name)
+                        if (timeoutId) {
+                            clearTimeout(timeoutId)
+                            this.spanTimeouts.delete(name)
+                        }
+                    }
+
+                    // Clear the marks
+                    performance.clearMarks(startMark)
+                    performance.clearMarks(endMark)
+                    performance.clearMeasures(name)
+                } catch (error) {
+                    logger.warn('Failed to measure performance mark', {
+                        name,
+                        error: error.message,
+                        startMark,
+                        endMark,
+                        namespace: 'PerformanceTimer.mark'
+                    })
                 }
-                this.metrics.push(measurement)
+            }
+        } catch (error) {
+            if (error.name === 'SyntaxError') {
+                logger.warn('Invalid performance mark name', {name, error: error.message})
+            } else {
+                logger.error('Error creating performance mark', {
+                    name,
+                    type,
+                    error: error.message,
+                    stack: error.stack,
+                    namespace: 'PerformanceTimer.mark'
+                })
             }
         }
     }
+
+    /**
+     * Helper method to clean up a specific orphaned span
+     * @private
+     */
+    _cleanupOrphanedSpan(name, reason = 'manual') {
+        const span = this.spans.get(name)
+        if (span) {
+            logger.warn('Cleaning up orphaned span', {
+                name,
+                error: 'Deleting orphaned span (reason: ' + reason + ' cleanup)',
+                namespace: 'PerformanceTimer._cleanupOrphanedSpan'
+            })
+            endSpan(span)
+            this.spans.delete(name)
+        }
+
+        // Clear the timeout
+        const timeoutId = this.spanTimeouts.get(name)
+        if (timeoutId) {
+            clearTimeout(timeoutId)
+            this.spanTimeouts.delete(name)
+        }
+    }
+
+    /**
+     * Clean up all orphaned spans and clear all timeouts
+     * Call this when the timer is no longer needed or when you want to force cleanup
+     */
+    cleanup() {
+        // Clean up any orphaned spans
+        this.spans.forEach((span, name) => {
+            this._cleanupOrphanedSpan(name, 'manual_cleanup')
+        })
+
+        // Clear any remaining timeouts
+        this.spanTimeouts.forEach((timeoutId) => {
+            clearTimeout(timeoutId)
+        })
+        this.spanTimeouts.clear()
+
+        // Clear metrics as well
+        this.metrics = []
+    }
 }