Add a response-time metric (#3948)

* Refactor existing metrics support into MetricHelper

This completes the refactor done at #3662 (comment) in anticipation of adding more metrics support, such as response size of an upstream service, or response time.

* Clean up

* Renames

* Add response time metrics

This adds around 30 new metrics to cover response times at a fairly granular level. We may be able to shrink the number of buckets with time, though I think using 30 metrics is probably okay given that I think may become our most important metric.

* Fix

Author: paulmelnikow

core/base-service/base-non-memory-caching.js

@@ -2,6 +2,7 @@
 
 const makeBadge = require('../../gh-badges/lib/make-badge')
 const BaseService = require('./base')
+const { MetricHelper } = require('./metric-helper')
 const { setCacheHeaders } = require('./cache-headers')
 const { makeSend } = require('./legacy-result-sender')
 const coalesceBadge = require('./coalesce-badge')
@@ -24,16 +25,19 @@ const { prepareRoute, namedParamsForMatch } = require('./route')
 // configured by the service, the user's request, and the server's default
 // cache length.
 module.exports = class NonMemoryCachingBaseService extends BaseService {
-  static register({ camp, requestCounter }, serviceConfig) {
+  static register({ camp, metricInstance }, serviceConfig) {
     const { cacheHeaders: cacheHeaderConfig } = serviceConfig
     const { _cacheLength: serviceDefaultCacheLengthSeconds } = this
     const { regex, captureNames } = prepareRoute(this.route)
 
-    const serviceRequestCounter = this._createServiceRequestCounter({
-      requestCounter,
+    const metricHelper = MetricHelper.create({
+      metricInstance,
+      ServiceClass: this,
     })
 
     camp.route(regex, async (queryParams, match, end, ask) => {
+      const metricHandle = metricHelper.startRequest()
+
       const namedParams = namedParamsForMatch(captureNames, match, this)
       const serviceData = await this.invoke(
         {},
@@ -64,7 +68,7 @@ module.exports = class NonMemoryCachingBaseService extends BaseService {
 
       makeSend(format, ask.res, end)(svg)
 
-      serviceRequestCounter.inc()
+      metricHandle.noteResponseSent()
     })
   }
 }

core/base-service/base-static.js

@@ -7,18 +7,20 @@ const {
   setCacheHeadersForStaticResource,
 } = require('./cache-headers')
 const { makeSend } = require('./legacy-result-sender')
+const { MetricHelper } = require('./metric-helper')
 const coalesceBadge = require('./coalesce-badge')
 const { prepareRoute, namedParamsForMatch } = require('./route')
 
 module.exports = class BaseStaticService extends BaseService {
-  static register({ camp, requestCounter }, serviceConfig) {
+  static register({ camp, metricInstance }, serviceConfig) {
     const {
       profiling: { makeBadge: shouldProfileMakeBadge },
     } = serviceConfig
     const { regex, captureNames } = prepareRoute(this.route)
 
-    const serviceRequestCounter = this._createServiceRequestCounter({
-      requestCounter,
+    const metricHelper = MetricHelper.create({
+      metricInstance,
+      ServiceClass: this,
     })
 
     camp.route(regex, async (queryParams, match, end, ask) => {
@@ -29,6 +31,8 @@ module.exports = class BaseStaticService extends BaseService {
         return
       }
 
+      const metricHandle = metricHelper.startRequest()
+
       const namedParams = namedParamsForMatch(captureNames, match, this)
       const serviceData = await this.invoke(
         {},
@@ -60,7 +64,7 @@ module.exports = class BaseStaticService extends BaseService {
 
       makeSend(format, ask.res, end)(svg)
 
-      serviceRequestCounter.inc()
+      metricHandle.noteResponseSent()
     })
   }
 }

core/base-service/base.js

@@ -3,12 +3,12 @@
  * @module
  */
 
-const decamelize = require('decamelize')
 // See available emoji at http://emoji.muan.co/
 const emojic = require('emojic')
 const Joi = require('@hapi/joi')
 const log = require('../server/log')
 const { AuthHelper } = require('./auth-helper')
+const { MetricHelper } = require('./metric-helper')
 const { assertValidCategory } = require('./categories')
 const checkErrorResponse = require('./check-error-response')
 const coalesceBadge = require('./coalesce-badge')
@@ -391,34 +391,26 @@ class BaseService {
     return serviceData
   }
 
-  static _createServiceRequestCounter({ requestCounter }) {
-    if (requestCounter) {
-      const { category, serviceFamily, name } = this
-      const service = decamelize(name)
-      return requestCounter.labels(category, serviceFamily, service)
-    } else {
-      // When metrics are disabled, return a mock counter.
-      return { inc: () => {} }
-    }
-  }
-
   static register(
-    { camp, handleRequest, githubApiProvider, requestCounter },
+    { camp, handleRequest, githubApiProvider, metricInstance },
     serviceConfig
   ) {
     const { cacheHeaders: cacheHeaderConfig, fetchLimitBytes } = serviceConfig
     const { regex, captureNames } = prepareRoute(this.route)
     const queryParams = getQueryParamNames(this.route)
 
-    const serviceRequestCounter = this._createServiceRequestCounter({
-      requestCounter,
+    const metricHelper = MetricHelper.create({
+      metricInstance,
+      ServiceClass: this,
     })
 
     camp.route(
       regex,
       handleRequest(cacheHeaderConfig, {
         queryParams,
         handler: async (queryParams, match, sendBadge, request) => {
+          const metricHandle = metricHelper.startRequest()
+
           const namedParams = namedParamsForMatch(captureNames, match, this)
           const serviceData = await this.invoke(
             {
@@ -441,7 +433,7 @@ class BaseService {
           const format = (match.slice(-1)[0] || '.svg').replace(/^\./, '')
           sendBadge(format, badgeData)
 
-          serviceRequestCounter.inc()
+          metricHandle.noteResponseSent()
         },
         cacheLength: this._cacheLength,
         fetchLimitBytes,

core/base-service/metric-helper.js

@@ -0,0 +1,45 @@
+'use strict'
+
+const { performance } = require('perf_hooks')
+
+class MetricHelper {
+  constructor({ metricInstance }, { category, serviceFamily, name }) {
+    if (metricInstance) {
+      this.metricInstance = metricInstance
+      this.serviceRequestCounter = metricInstance.createNumRequestCounter({
+        category,
+        serviceFamily,
+        name,
+      })
+    } else {
+      this.metricInstance = undefined
+      this.serviceRequestCounter = undefined
+    }
+  }
+
+  static create({ metricInstance, ServiceClass }) {
+    const { category, serviceFamily, name } = ServiceClass
+    return new this({ metricInstance }, { category, serviceFamily, name })
+  }
+
+  startRequest() {
+    const { metricInstance, serviceRequestCounter } = this
+
+    const requestStartTime = performance.now()
+
+    return {
+      noteResponseSent() {
+        if (metricInstance) {
+          const elapsedTime = performance.now() - requestStartTime
+          metricInstance.noteResponseTime(elapsedTime)
+        }
+
+        if (serviceRequestCounter) {
+          serviceRequestCounter.inc()
+        }
+      },
+    }
+  }
+}
+
+module.exports = { MetricHelper }

core/base-service/redirector.js

@@ -10,6 +10,7 @@ const {
   setCacheHeadersForStaticResource,
 } = require('./cache-headers')
 const { isValidCategory } = require('./categories')
+const { MetricHelper } = require('./metric-helper')
 const { isValidRoute, prepareRoute, namedParamsForMatch } = require('./route')
 const trace = require('./trace')
 
@@ -62,14 +63,15 @@ module.exports = function redirector(attrs) {
       return route
     }
 
-    static register({ camp, requestCounter }, { rasterUrl }) {
+    static register({ camp, metricInstance }, { rasterUrl }) {
       const { regex, captureNames } = prepareRoute({
         ...this.route,
         withPng: Boolean(rasterUrl),
       })
 
-      const serviceRequestCounter = this._createServiceRequestCounter({
-        requestCounter,
+      const metricHelper = MetricHelper.create({
+        metricInstance,
+        ServiceClass: this,
       })
 
       camp.route(regex, async (queryParams, match, end, ask) => {
@@ -80,6 +82,8 @@ module.exports = function redirector(attrs) {
           return
         }
 
+        const metricHandle = metricHelper.startRequest()
+
         const namedParams = namedParamsForMatch(captureNames, match, this)
         trace.logTrace(
           'inbound',
@@ -121,7 +125,7 @@ module.exports = function redirector(attrs) {
 
         ask.res.end()
 
-        serviceRequestCounter.inc()
+        metricHandle.noteResponseSent()
       })
     }
   }

core/server/prometheus-metrics.js

@@ -1,16 +1,59 @@
 'use strict'
 
+const decamelize = require('decamelize')
 const prometheus = require('prom-client')
 
 module.exports = class PrometheusMetrics {
   constructor() {
     this.register = new prometheus.Registry()
-    this.requestCounter = new prometheus.Counter({
-      name: 'service_requests_total',
-      help: 'Total service requests',
-      labelNames: ['category', 'family', 'service'],
-      registers: [this.register],
-    })
+    this.counters = {
+      numRequests: new prometheus.Counter({
+        name: 'service_requests_total',
+        help: 'Total service requests',
+        labelNames: ['category', 'family', 'service'],
+        registers: [this.register],
+      }),
+      responseTime: new prometheus.Histogram({
+        name: 'service_response_millis',
+        help: 'Service response time in milliseconds',
+        // 250 ms increments up to 2 seconds, then 500 ms increments up to 8
+        // seconds, then 1 second increments up to 15 seconds.
+        buckets: [
+          250,
+          500,
+          750,
+          1000,
+          1250,
+          1500,
+          1750,
+          2000,
+          2250,
+          2500,
+          2750,
+          3000,
+          3250,
+          3500,
+          3750,
+          4000,
+          4500,
+          5000,
+          5500,
+          6000,
+          6500,
+          7000,
+          7500,
+          8000,
+          9000,
+          10000,
+          11000,
+          12000,
+          13000,
+          14000,
+          15000,
+        ],
+        registers: [this.register],
+      }),
+    }
   }
 
   async initialize(server) {
@@ -30,4 +73,16 @@ module.exports = class PrometheusMetrics {
       this.interval = undefined
     }
   }
+
+  /**
+   * @returns {object} `{ inc() {} }`.
+   */
+  createNumRequestCounter({ category, serviceFamily, name }) {
+    const service = decamelize(name)
+    return this.counters.numRequests.labels(category, serviceFamily, service)
+  }
+
+  noteResponseTime(responseTime) {
+    return this.counters.responseTime.observe(responseTime)
+  }
 }

core/server/server.js

@@ -148,7 +148,7 @@ class Server {
       private: privateConfig,
     })
     if (publicConfig.metrics.prometheus.enabled) {
-      this.metrics = new PrometheusMetrics()
+      this.metricInstance = new PrometheusMetrics()
     }
   }
 
@@ -263,13 +263,12 @@ class Server {
    * load each service and register a Scoutcamp route for each service.
    */
   registerServices() {
-    const { config, camp } = this
+    const { config, camp, metricInstance } = this
     const { apiProvider: githubApiProvider } = this.githubConstellation
-    const { requestCounter } = this.metrics || {}
 
     loadServiceClasses().forEach(serviceClass =>
       serviceClass.register(
-        { camp, handleRequest, githubApiProvider, requestCounter },
+        { camp, handleRequest, githubApiProvider, metricInstance },
         {
           handleInternalErrors: config.public.handleInternalErrors,
           cacheHeaders: config.public.cacheHeaders,
@@ -309,10 +308,10 @@ class Server {
 
     this.cleanupMonitor = sysMonitor.setRoutes({ rateLimit }, camp)
 
-    const { githubConstellation, metrics } = this
+    const { githubConstellation, metricInstance } = this
     githubConstellation.initialize(camp)
-    if (metrics) {
-      metrics.initialize(camp)
+    if (metricInstance) {
+      metricInstance.initialize(camp)
     }
 
     const { apiProvider: githubApiProvider } = this.githubConstellation
@@ -355,8 +354,8 @@ class Server {
       this.githubConstellation = undefined
     }
 
-    if (this.metrics) {
-      this.metrics.stop()
+    if (this.metricInstance) {
+      this.metricInstance.stop()
     }
   }
 }