src/performance/PerformanceStatistics.ts

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