audiobookshelf/server/utils/profiler.js

const { performance, createHistogram } = require('perf_hooks')
const util = require('util')
const Logger = require('../Logger')

const histograms = new Map()
const MAX_RECENT_VALUES = 100
const MAX_LOG_STRING_LENGTH = 1800

function pushBoundedValue(values, value) {
  values.push(value)
  if (values.length > MAX_RECENT_VALUES) {
    values.shift()
  }
}

function formatFindOptionsForLog(findOptions) {
  const serialized = util.inspect(findOptions, {
    depth: 4,
    maxArrayLength: 20,
    maxStringLength: 200,
    breakLength: 120
  })

  if (serialized.length <= MAX_LOG_STRING_LENGTH) {
    return serialized
  }

  return `${serialized.slice(0, MAX_LOG_STRING_LENGTH - 3)}...`
}

function getPercentile(histogram, percentile) {
  if (!histogram || typeof histogram.percentile !== 'function' || !histogram.count) {
    return 0
  }

  return Math.round(histogram.percentile(percentile))
}

function getHistogramSummary(histogram) {
  return {
    count: histogram.count || 0,
    min: histogram.count ? histogram.min : 0,
    max: histogram.count ? histogram.max : 0,
    mean: histogram.count ? Math.round(histogram.mean) : 0,
    p50: getPercentile(histogram, 50),
    p95: getPercentile(histogram, 95),
    recentValues: Array.isArray(histogram.values) ? [...histogram.values] : []
  }
}

function callTimingHook(requestTiming, hookName, ...args) {
  if (!requestTiming || typeof requestTiming[hookName] !== 'function') return
  requestTiming[hookName](...args)
}

function createRequestScopedLogging(funcName, logging, requestTiming) {
  const logger = (...args) => {
    Logger.info(`[${funcName}] ${args[0]} Elapsed time: ${args[1]}ms`)
    if (typeof logging === 'function') {
      logging(...args)
    }
    callTimingHook(requestTiming, 'onQuery', ...args)
  }

  return logger
}

function createRequestScopedFindOptions(findOptions, funcName) {
  if (!findOptions || typeof findOptions !== 'object' || Array.isArray(findOptions)) {
    return {
      findOptions,
      requestTiming: null
    }
  }

  const requestTiming = findOptions.requestTiming || null

  return {
    requestTiming,
    findOptions: {
      ...findOptions,
      logging: createRequestScopedLogging(funcName, findOptions.logging, requestTiming),
      benchmark: true
    }
  }
}

function profile(asyncFunc, isFindQuery = true, funcName = asyncFunc.name) {
  if (!histograms.has(funcName)) {
    const histogram = createHistogram()
    histogram.values = []
    histograms.set(funcName, histogram)
  }
  const histogram = histograms.get(funcName)

  return async (...args) => {
    const requestScoped = isFindQuery ? createRequestScopedFindOptions(args[0], funcName) : { findOptions: args[0], requestTiming: null }
    const requestArgs = isFindQuery ? [requestScoped.findOptions, ...args.slice(1)] : args

    if (isFindQuery) {
      const findOptions = requestArgs[0]
      Logger.info(`[${funcName}] findOptions:`, formatFindOptionsForLog(findOptions))
    }
    const start = performance.now()
    callTimingHook(requestScoped.requestTiming, 'onStart', requestArgs[0])
    try {
      const result = await asyncFunc(...requestArgs)
      callTimingHook(requestScoped.requestTiming, 'onFinish', result)
      return result
    } catch (error) {
      Logger.error(`[${funcName}] failed`)
      callTimingHook(requestScoped.requestTiming, 'onError', error)
      throw error
    } finally {
      const end = performance.now()
      const duration = Math.max(1, Math.round(end - start))
      histogram.record(duration)
      pushBoundedValue(histogram.values, duration)
      Logger.info(`[${funcName}] duration: ${duration}ms`)
      Logger.info(`[${funcName}] histogram summary:`, getHistogramSummary(histogram))
    }
  }
}

module.exports = { profile }