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