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