src/performance/PerformanceStatistics.ts

   1 // Partial Copyright Jerome Benoit. 2021-2023. All Rights Reserved.
   2
   3 import { type PerformanceEntry, PerformanceObserver, performance } from 'node:perf_hooks'
   4 import type { URL } from 'node:url'
   5 import { parentPort } from 'node:worker_threads'
   6
   7 import { secondsToMilliseconds } from 'date-fns'
   8
   9 import {
  10   ConfigurationSection,
  11   type IncomingRequestCommand,
  12   type LogConfiguration,
  13   MessageType,
  14   type RequestCommand,
  15   type Statistics,
  16   type StorageConfiguration,
  17   type TimestampedData
  18 } from '../types/index.js'
  19 import {
  20   CircularArray,
  21   Configuration,
  22   Constants,
  23   JSONStringifyWithMapSupport,
  24   average,
  25   buildPerformanceStatisticsMessage,
  26   extractTimeSeriesValues,
  27   formatDurationSeconds,
  28   generateUUID,
  29   logPrefix,
  30   logger,
  31   max,
  32   median,
  33   min,
  34   nthPercentile,
  35   stdDeviation
  36 } from '../utils/index.js'
  37
  38 export class PerformanceStatistics {
  39   private static readonly instances: Map<string, PerformanceStatistics> = new Map<
  40   string,
  41   PerformanceStatistics
  42   >()
  43
  44   private readonly objId: string
  45   private readonly objName: string
  46   private performanceObserver!: PerformanceObserver
  47   private readonly statistics: Statistics
  48   private displayInterval?: NodeJS.Timeout
  49
  50   private constructor (objId: string, objName: string, uri: URL) {
  51     this.objId = objId
  52     this.objName = objName
  53     this.initializePerformanceObserver()
  54     this.statistics = {
  55       id: this.objId ?? 'Object id not specified',
  56       name: this.objName ?? 'Object name not specified',
  57       uri: uri.toString(),
  58       createdAt: new Date(),
  59       statisticsData: new Map()
  60     }
  61   }
  62
  63   public static getInstance (
  64     objId: string,
  65     objName: string,
  66     uri: URL
  67   ): PerformanceStatistics | undefined {
  68     if (!PerformanceStatistics.instances.has(objId)) {
  69       PerformanceStatistics.instances.set(objId, new PerformanceStatistics(objId, objName, uri))
  70     }
  71     return PerformanceStatistics.instances.get(objId)
  72   }
  73
  74   public static beginMeasure (id: string): string {
  75     const markId = `${id.charAt(0).toUpperCase()}${id.slice(1)}~${generateUUID()}`
  76     performance.mark(markId)
  77     return markId
  78   }
  79
  80   public static endMeasure (name: string, markId: string): void {
  81     try {
  82       performance.measure(name, markId)
  83     } catch (error) {
  84       if (error instanceof Error && error.message.includes('performance mark has not been set')) {
  85         /* Ignore */
  86       } else {
  87         throw error
  88       }
  89     }
  90     performance.clearMarks(markId)
  91     performance.clearMeasures(name)
  92   }
  93
  94   public addRequestStatistic (
  95     command: RequestCommand | IncomingRequestCommand,
  96     messageType: MessageType
  97   ): void {
  98     switch (messageType) {
  99       case MessageType.CALL_MESSAGE:
 100         if (
 101           this.statistics.statisticsData.has(command) &&
 102           this.statistics.statisticsData.get(command)?.requestCount != null
 103         ) {
 104           // eslint-disable-next-line @typescript-eslint/no-non-null-assertion
 105           ++this.statistics.statisticsData.get(command)!.requestCount!
 106         } else {
 107           this.statistics.statisticsData.set(command, {
 108             ...this.statistics.statisticsData.get(command),
 109             requestCount: 1
 110           })
 111         }
 112         break
 113       case MessageType.CALL_RESULT_MESSAGE:
 114         if (
 115           this.statistics.statisticsData.has(command) &&
 116           this.statistics.statisticsData.get(command)?.responseCount != null
 117         ) {
 118           // eslint-disable-next-line @typescript-eslint/no-non-null-assertion
 119           ++this.statistics.statisticsData.get(command)!.responseCount!
 120         } else {
 121           this.statistics.statisticsData.set(command, {
 122             ...this.statistics.statisticsData.get(command),
 123             responseCount: 1
 124           })
 125         }
 126         break
 127       case MessageType.CALL_ERROR_MESSAGE:
 128         if (
 129           this.statistics.statisticsData.has(command) &&
 130           this.statistics.statisticsData.get(command)?.errorCount != null
 131         ) {
 132           // eslint-disable-next-line @typescript-eslint/no-non-null-assertion
 133           ++this.statistics.statisticsData.get(command)!.errorCount!
 134         } else {
 135           this.statistics.statisticsData.set(command, {
 136             ...this.statistics.statisticsData.get(command),
 137             errorCount: 1
 138           })
 139         }
 140         break
 141       default:
 142         // eslint-disable-next-line @typescript-eslint/restrict-template-expressions
 143         logger.error(`${this.logPrefix()} wrong message type ${messageType}`)
 144         break
 145     }
 146   }
 147
 148   public start (): void {
 149     this.startLogStatisticsInterval()
 150     const performanceStorageConfiguration =
 151       Configuration.getConfigurationSection<StorageConfiguration>(
 152         ConfigurationSection.performanceStorage
 153       )
 154     if (performanceStorageConfiguration.enabled === true) {
 155       logger.info(
 156         `${this.logPrefix()} storage enabled: type ${performanceStorageConfiguration.type}, uri: ${
 157           performanceStorageConfiguration.uri
 158         }`
 159       )
 160     }
 161   }
 162
 163   public stop (): void {
 164     this.stopLogStatisticsInterval()
 165     performance.clearMarks()
 166     performance.clearMeasures()
 167     this.performanceObserver?.disconnect()
 168   }
 169
 170   public restart (): void {
 171     this.stop()
 172     this.start()
 173   }
 174
 175   private initializePerformanceObserver (): void {
 176     this.performanceObserver = new PerformanceObserver((performanceObserverList) => {
 177       const lastPerformanceEntry = performanceObserverList.getEntries()[0]
 178       // logger.debug(
 179       //   `${this.logPrefix()} '${lastPerformanceEntry.name}' performance entry: %j`,
 180       //   lastPerformanceEntry
 181       // )
 182       this.addPerformanceEntryToStatistics(lastPerformanceEntry)
 183     })
 184     this.performanceObserver.observe({ entryTypes: ['measure'] })
 185   }
 186
 187   private logStatistics (): void {
 188     logger.info(`${this.logPrefix()}`, {
 189       ...this.statistics,
 190       statisticsData: JSONStringifyWithMapSupport(this.statistics.statisticsData)
 191     })
 192   }
 193
 194   private startLogStatisticsInterval (): void {
 195     const logConfiguration = Configuration.getConfigurationSection<LogConfiguration>(
 196       ConfigurationSection.log
 197     )
 198     const logStatisticsInterval =
 199       logConfiguration.enabled === true
 200         ? // eslint-disable-next-line @typescript-eslint/no-non-null-assertion
 201         logConfiguration.statisticsInterval!
 202         : 0
 203     if (logStatisticsInterval > 0 && this.displayInterval == null) {
 204       this.displayInterval = setInterval(() => {
 205         this.logStatistics()
 206       }, secondsToMilliseconds(logStatisticsInterval))
 207       logger.info(
 208         `${this.logPrefix()} logged every ${formatDurationSeconds(logStatisticsInterval)}`
 209       )
 210     } else if (this.displayInterval != null) {
 211       logger.info(
 212         `${this.logPrefix()} already logged every ${formatDurationSeconds(logStatisticsInterval)}`
 213       )
 214     } else if (logConfiguration.enabled === true) {
 215       logger.info(
 216         `${this.logPrefix()} log interval is set to ${logStatisticsInterval}. Not logging statistics`
 217       )
 218     }
 219   }
 220
 221   private stopLogStatisticsInterval (): void {
 222     if (this.displayInterval != null) {
 223       clearInterval(this.displayInterval)
 224       delete this.displayInterval
 225     }
 226   }
 227
 228   private addPerformanceEntryToStatistics (entry: PerformanceEntry): void {
 229     // Initialize command statistics
 230     if (!this.statistics.statisticsData.has(entry.name)) {
 231       this.statistics.statisticsData.set(entry.name, {})
 232     }
 233     // Update current statistics
 234     // eslint-disable-next-line @typescript-eslint/no-non-null-assertion
 235     this.statistics.statisticsData.get(entry.name)!.timeMeasurementCount =
 236       (this.statistics.statisticsData.get(entry.name)?.timeMeasurementCount ?? 0) + 1
 237     // eslint-disable-next-line @typescript-eslint/no-non-null-assertion
 238     this.statistics.statisticsData.get(entry.name)!.currentTimeMeasurement = entry.duration
 239     // eslint-disable-next-line @typescript-eslint/no-non-null-assertion
 240     this.statistics.statisticsData.get(entry.name)!.minTimeMeasurement = min(
 241       entry.duration,
 242       this.statistics.statisticsData.get(entry.name)?.minTimeMeasurement ?? Infinity
 243     )
 244     // eslint-disable-next-line @typescript-eslint/no-non-null-assertion
 245     this.statistics.statisticsData.get(entry.name)!.maxTimeMeasurement = max(
 246       entry.duration,
 247       this.statistics.statisticsData.get(entry.name)?.maxTimeMeasurement ?? -Infinity
 248     )
 249     // eslint-disable-next-line @typescript-eslint/no-non-null-assertion
 250     this.statistics.statisticsData.get(entry.name)!.totalTimeMeasurement =
 251       (this.statistics.statisticsData.get(entry.name)?.totalTimeMeasurement ?? 0) + entry.duration
 252     this.statistics.statisticsData.get(entry.name)?.measurementTimeSeries instanceof CircularArray
 253       ? this.statistics.statisticsData
 254         .get(entry.name)
 255         ?.measurementTimeSeries?.push({ timestamp: entry.startTime, value: entry.duration })
 256       : // eslint-disable-next-line @typescript-eslint/no-non-null-assertion
 257         (this.statistics.statisticsData.get(entry.name)!.measurementTimeSeries =
 258           new CircularArray<TimestampedData>(Constants.DEFAULT_CIRCULAR_BUFFER_CAPACITY, {
 259             timestamp: entry.startTime,
 260             value: entry.duration
 261           }))
 262     const timeMeasurementValues = extractTimeSeriesValues(
 263       // eslint-disable-next-line @typescript-eslint/no-non-null-assertion
 264       this.statistics.statisticsData.get(entry.name)!.measurementTimeSeries!
 265     )
 266     // eslint-disable-next-line @typescript-eslint/no-non-null-assertion
 267     this.statistics.statisticsData.get(entry.name)!.avgTimeMeasurement =
 268       average(timeMeasurementValues)
 269     // eslint-disable-next-line @typescript-eslint/no-non-null-assertion
 270     this.statistics.statisticsData.get(entry.name)!.medTimeMeasurement =
 271       median(timeMeasurementValues)
 272     // eslint-disable-next-line @typescript-eslint/no-non-null-assertion
 273     this.statistics.statisticsData.get(entry.name)!.ninetyFiveThPercentileTimeMeasurement =
 274       nthPercentile(timeMeasurementValues, 95)
 275     // eslint-disable-next-line @typescript-eslint/no-non-null-assertion
 276     this.statistics.statisticsData.get(entry.name)!.stdDevTimeMeasurement = stdDeviation(
 277       timeMeasurementValues,
 278       // eslint-disable-next-line @typescript-eslint/no-non-null-assertion
 279       this.statistics.statisticsData.get(entry.name)!.avgTimeMeasurement
 280     )
 281     this.statistics.updatedAt = new Date()
 282     if (
 283       Configuration.getConfigurationSection<StorageConfiguration>(
 284         ConfigurationSection.performanceStorage
 285       ).enabled === true
 286     ) {
 287       parentPort?.postMessage(buildPerformanceStatisticsMessage(this.statistics))
 288     }
 289   }
 290
 291   private readonly logPrefix = (): string => {
 292     return logPrefix(` ${this.objName} | Performance statistics`)
 293   }
 294 }