src/performance/PerformanceStatistics.ts

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