| 1 | // Partial Copyright Jerome Benoit. 2021-2024. All Rights Reserved. |
| 2 | |
| 3 | import type { URL } from 'node:url' |
| 4 | |
| 5 | import { secondsToMilliseconds } from 'date-fns' |
| 6 | import { CircularBuffer } from 'mnemonist' |
| 7 | import { performance, type PerformanceEntry, PerformanceObserver } from 'node:perf_hooks' |
| 8 | import { parentPort } from 'node:worker_threads' |
| 9 | import { is, mean, median } from 'rambda' |
| 10 | |
| 11 | import { BaseError } from '../exception/index.js' |
| 12 | import { |
| 13 | ConfigurationSection, |
| 14 | type IncomingRequestCommand, |
| 15 | type LogConfiguration, |
| 16 | MapStringifyFormat, |
| 17 | MessageType, |
| 18 | type RequestCommand, |
| 19 | type Statistics, |
| 20 | type StatisticsData, |
| 21 | type StorageConfiguration, |
| 22 | type TimestampedData, |
| 23 | } from '../types/index.js' |
| 24 | import { |
| 25 | buildPerformanceStatisticsMessage, |
| 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 static readonly logPrefix = (): string => { |
| 47 | return logPrefix(' Performance statistics') |
| 48 | } |
| 49 | |
| 50 | private displayInterval?: NodeJS.Timeout |
| 51 | private readonly logPrefix = (): string => { |
| 52 | // eslint-disable-next-line @typescript-eslint/restrict-template-expressions |
| 53 | return logPrefix(` ${this.objName} | Performance statistics`) |
| 54 | } |
| 55 | |
| 56 | private readonly objId: string | undefined |
| 57 | private readonly objName: string | undefined |
| 58 | |
| 59 | private performanceObserver!: PerformanceObserver |
| 60 | |
| 61 | private readonly statistics: Statistics |
| 62 | |
| 63 | private constructor (objId: string, objName: string, uri: URL) { |
| 64 | this.objId = objId |
| 65 | this.objName = objName |
| 66 | this.initializePerformanceObserver() |
| 67 | this.statistics = { |
| 68 | createdAt: new Date(), |
| 69 | id: this.objId, |
| 70 | name: this.objName, |
| 71 | statisticsData: new Map(), |
| 72 | uri: uri.toString(), |
| 73 | } |
| 74 | } |
| 75 | |
| 76 | public static beginMeasure (id: string): string { |
| 77 | const markId = `${id.charAt(0).toUpperCase()}${id.slice(1)}~${generateUUID()}` |
| 78 | performance.mark(markId) |
| 79 | return markId |
| 80 | } |
| 81 | |
| 82 | public static deleteInstance (objId: string | undefined): boolean { |
| 83 | if (objId == null) { |
| 84 | const errMsg = 'Cannot delete performance statistics instance without specifying object id' |
| 85 | logger.error(`${PerformanceStatistics.logPrefix()} ${errMsg}`) |
| 86 | throw new BaseError(errMsg) |
| 87 | } |
| 88 | return PerformanceStatistics.instances.delete(objId) |
| 89 | } |
| 90 | |
| 91 | public static endMeasure (name: string, markId: string): void { |
| 92 | try { |
| 93 | performance.measure(name, markId) |
| 94 | } catch (error) { |
| 95 | if (is(Error, error) && error.message.includes('performance mark has not been set')) { |
| 96 | /* Ignore */ |
| 97 | } else { |
| 98 | throw error |
| 99 | } |
| 100 | } |
| 101 | performance.clearMarks(markId) |
| 102 | performance.clearMeasures(name) |
| 103 | } |
| 104 | |
| 105 | public static getInstance ( |
| 106 | objId: string | undefined, |
| 107 | objName: string | undefined, |
| 108 | uri: undefined | URL |
| 109 | ): PerformanceStatistics | undefined { |
| 110 | if (objId == null) { |
| 111 | const errMsg = 'Cannot get performance statistics instance without specifying object id' |
| 112 | logger.error(`${PerformanceStatistics.logPrefix()} ${errMsg}`) |
| 113 | throw new BaseError(errMsg) |
| 114 | } |
| 115 | if (objName == null) { |
| 116 | const errMsg = 'Cannot get performance statistics instance without specifying object name' |
| 117 | logger.error(`${PerformanceStatistics.logPrefix()} ${errMsg}`) |
| 118 | throw new BaseError(errMsg) |
| 119 | } |
| 120 | if (uri == null) { |
| 121 | const errMsg = 'Cannot get performance statistics instance without specifying object uri' |
| 122 | logger.error(`${PerformanceStatistics.logPrefix()} ${errMsg}`) |
| 123 | throw new BaseError(errMsg) |
| 124 | } |
| 125 | if (!PerformanceStatistics.instances.has(objId)) { |
| 126 | PerformanceStatistics.instances.set(objId, new PerformanceStatistics(objId, objName, uri)) |
| 127 | } |
| 128 | return PerformanceStatistics.instances.get(objId) |
| 129 | } |
| 130 | |
| 131 | private addPerformanceEntryToStatistics (entry: PerformanceEntry): void { |
| 132 | // Initialize command statistics |
| 133 | if (!this.statistics.statisticsData.has(entry.name)) { |
| 134 | this.statistics.statisticsData.set(entry.name, {}) |
| 135 | } |
| 136 | // Update current statistics |
| 137 | // eslint-disable-next-line @typescript-eslint/no-non-null-assertion |
| 138 | this.statistics.statisticsData.get(entry.name)!.timeMeasurementCount = |
| 139 | (this.statistics.statisticsData.get(entry.name)?.timeMeasurementCount ?? 0) + 1 |
| 140 | // eslint-disable-next-line @typescript-eslint/no-non-null-assertion |
| 141 | this.statistics.statisticsData.get(entry.name)!.currentTimeMeasurement = entry.duration |
| 142 | // eslint-disable-next-line @typescript-eslint/no-non-null-assertion |
| 143 | this.statistics.statisticsData.get(entry.name)!.minTimeMeasurement = min( |
| 144 | entry.duration, |
| 145 | this.statistics.statisticsData.get(entry.name)?.minTimeMeasurement ?? Number.POSITIVE_INFINITY |
| 146 | ) |
| 147 | // eslint-disable-next-line @typescript-eslint/no-non-null-assertion |
| 148 | this.statistics.statisticsData.get(entry.name)!.maxTimeMeasurement = max( |
| 149 | entry.duration, |
| 150 | this.statistics.statisticsData.get(entry.name)?.maxTimeMeasurement ?? Number.NEGATIVE_INFINITY |
| 151 | ) |
| 152 | // eslint-disable-next-line @typescript-eslint/no-non-null-assertion |
| 153 | this.statistics.statisticsData.get(entry.name)!.totalTimeMeasurement = |
| 154 | (this.statistics.statisticsData.get(entry.name)?.totalTimeMeasurement ?? 0) + entry.duration |
| 155 | if ( |
| 156 | !( |
| 157 | this.statistics.statisticsData.get(entry.name)?.measurementTimeSeries instanceof |
| 158 | CircularBuffer |
| 159 | ) |
| 160 | ) { |
| 161 | // eslint-disable-next-line @typescript-eslint/no-non-null-assertion |
| 162 | this.statistics.statisticsData.get(entry.name)!.measurementTimeSeries = |
| 163 | new CircularBuffer<TimestampedData>( |
| 164 | Array<TimestampedData>, |
| 165 | Constants.DEFAULT_CIRCULAR_BUFFER_CAPACITY |
| 166 | ) |
| 167 | } |
| 168 | this.statistics.statisticsData.get(entry.name)?.measurementTimeSeries?.push({ |
| 169 | timestamp: entry.startTime, |
| 170 | value: entry.duration, |
| 171 | }) |
| 172 | const timeMeasurementValues = extractTimeSeriesValues( |
| 173 | // eslint-disable-next-line @typescript-eslint/no-non-null-assertion |
| 174 | this.statistics.statisticsData.get(entry.name)! |
| 175 | .measurementTimeSeries as CircularBuffer<TimestampedData> |
| 176 | ) |
| 177 | // eslint-disable-next-line @typescript-eslint/no-non-null-assertion |
| 178 | this.statistics.statisticsData.get(entry.name)!.avgTimeMeasurement = mean(timeMeasurementValues) |
| 179 | // eslint-disable-next-line @typescript-eslint/no-non-null-assertion |
| 180 | this.statistics.statisticsData.get(entry.name)!.medTimeMeasurement = |
| 181 | median(timeMeasurementValues) |
| 182 | // eslint-disable-next-line @typescript-eslint/no-non-null-assertion |
| 183 | this.statistics.statisticsData.get(entry.name)!.ninetyFiveThPercentileTimeMeasurement = |
| 184 | nthPercentile(timeMeasurementValues, 95) |
| 185 | // eslint-disable-next-line @typescript-eslint/no-non-null-assertion |
| 186 | this.statistics.statisticsData.get(entry.name)!.stdDevTimeMeasurement = stdDeviation( |
| 187 | timeMeasurementValues, |
| 188 | // eslint-disable-next-line @typescript-eslint/no-non-null-assertion |
| 189 | this.statistics.statisticsData.get(entry.name)!.avgTimeMeasurement |
| 190 | ) |
| 191 | this.statistics.updatedAt = new Date() |
| 192 | if ( |
| 193 | Configuration.getConfigurationSection<StorageConfiguration>( |
| 194 | ConfigurationSection.performanceStorage |
| 195 | ).enabled === true |
| 196 | ) { |
| 197 | parentPort?.postMessage(buildPerformanceStatisticsMessage(this.statistics)) |
| 198 | } |
| 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<IncomingRequestCommand | RequestCommand | string, 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.toString()}. 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 | public addRequestStatistic ( |
| 257 | command: IncomingRequestCommand | RequestCommand, |
| 258 | messageType: MessageType |
| 259 | ): void { |
| 260 | switch (messageType) { |
| 261 | case MessageType.CALL_ERROR_MESSAGE: |
| 262 | if ( |
| 263 | this.statistics.statisticsData.has(command) && |
| 264 | this.statistics.statisticsData.get(command)?.errorCount != null |
| 265 | ) { |
| 266 | // eslint-disable-next-line @typescript-eslint/no-non-null-assertion |
| 267 | ++this.statistics.statisticsData.get(command)!.errorCount! |
| 268 | } else { |
| 269 | this.statistics.statisticsData.set(command, { |
| 270 | ...this.statistics.statisticsData.get(command), |
| 271 | errorCount: 1, |
| 272 | }) |
| 273 | } |
| 274 | break |
| 275 | case MessageType.CALL_MESSAGE: |
| 276 | if ( |
| 277 | this.statistics.statisticsData.has(command) && |
| 278 | this.statistics.statisticsData.get(command)?.requestCount != null |
| 279 | ) { |
| 280 | // eslint-disable-next-line @typescript-eslint/no-non-null-assertion |
| 281 | ++this.statistics.statisticsData.get(command)!.requestCount! |
| 282 | } else { |
| 283 | this.statistics.statisticsData.set(command, { |
| 284 | ...this.statistics.statisticsData.get(command), |
| 285 | requestCount: 1, |
| 286 | }) |
| 287 | } |
| 288 | break |
| 289 | case MessageType.CALL_RESULT_MESSAGE: |
| 290 | if ( |
| 291 | this.statistics.statisticsData.has(command) && |
| 292 | this.statistics.statisticsData.get(command)?.responseCount != null |
| 293 | ) { |
| 294 | // eslint-disable-next-line @typescript-eslint/no-non-null-assertion |
| 295 | ++this.statistics.statisticsData.get(command)!.responseCount! |
| 296 | } else { |
| 297 | this.statistics.statisticsData.set(command, { |
| 298 | ...this.statistics.statisticsData.get(command), |
| 299 | responseCount: 1, |
| 300 | }) |
| 301 | } |
| 302 | break |
| 303 | default: |
| 304 | // eslint-disable-next-line @typescript-eslint/restrict-template-expressions |
| 305 | logger.error(`${this.logPrefix()} wrong message type ${messageType}`) |
| 306 | break |
| 307 | } |
| 308 | } |
| 309 | |
| 310 | public restart (): void { |
| 311 | this.stop() |
| 312 | this.start() |
| 313 | } |
| 314 | |
| 315 | public start (): void { |
| 316 | this.startLogStatisticsInterval() |
| 317 | const performanceStorageConfiguration = |
| 318 | Configuration.getConfigurationSection<StorageConfiguration>( |
| 319 | ConfigurationSection.performanceStorage |
| 320 | ) |
| 321 | if (performanceStorageConfiguration.enabled === true) { |
| 322 | logger.info( |
| 323 | `${this.logPrefix()} storage enabled: type ${ |
| 324 | // eslint-disable-next-line @typescript-eslint/restrict-template-expressions |
| 325 | performanceStorageConfiguration.type |
| 326 | // eslint-disable-next-line @typescript-eslint/restrict-template-expressions |
| 327 | }, uri: ${performanceStorageConfiguration.uri}` |
| 328 | ) |
| 329 | } |
| 330 | } |
| 331 | |
| 332 | public stop (): void { |
| 333 | this.stopLogStatisticsInterval() |
| 334 | performance.clearMarks() |
| 335 | performance.clearMeasures() |
| 336 | this.performanceObserver.disconnect() |
| 337 | } |
| 338 | } |