more server prometheus monitoring (#732)

packages/server/app.js

@@ -22,6 +22,7 @@ const { ApolloServer, ForbiddenError } = require('apollo-server-express')
 
 const { buildContext } = require('./modules/shared')
 const knex = require('./db/knex')
+const { monitorActiveConnections } = require('./logging/httpServerMonitoring')
 const { buildErrorFormatter } = require('@/modules/core/graph/setup')
 const { isDevEnv, isTestEnv } = require('@/modules/core/helpers/envHelper')
 
@@ -36,15 +37,13 @@ exports.buildApolloServer = (optionOverrides) => {
   const debug = optionOverrides?.debug || isDevEnv() || isTestEnv()
   const { graph } = require('./modules')
 
-  // (Re-)Initialise prometheus metrics
-  prometheusClient.register.clear()
-  prometheusClient.collectDefaultMetrics()
-
   // Init metrics
+  prometheusClient.register.removeSingleMetric('speckle_server_apollo_connect')
   const metricConnectCounter = new prometheusClient.Counter({
     name: 'speckle_server_apollo_connect',
     help: 'Number of connects'
   })
+  prometheusClient.register.removeSingleMetric('speckle_server_apollo_clients')
   const metricConnectedClients = new prometheusClient.Gauge({
     name: 'speckle_server_apollo_clients',
     help: 'Number of currently connected clients'
@@ -173,6 +172,7 @@ exports.startHttp = async (app, customPortOverride) => {
   }
 
   const server = http.createServer(app)
+  monitorActiveConnections(server)
 
   if (customPortOverride || customPortOverride === 0) port = customPortOverride
   app.set('port', port)

packages/server/knexfile.js

@@ -49,7 +49,8 @@ const config = {
     connection: connectionUri || 'postgres://localhost/speckle2_dev',
     migrations: {
       directory: migrationDirs
-    }
+    },
+    pool: { min: 2, max: 4 }
   },
   production: {
     client: 'pg',

packages/server/logging/expressMonitoring.js

@@ -0,0 +1,25 @@
+/* istanbul ignore file */
+/* eslint-disable no-unused-vars */
+'use strict'
+
+const prometheusClient = require('prom-client')
+const responseTime = require('response-time')
+
+let metricRequestDuration = null
+
+module.exports = {
+  createRequestDurationMiddleware() {
+    if (metricRequestDuration === null) {
+      metricRequestDuration = new prometheusClient.Summary({
+        name: 'speckle_server_request_duration',
+        help: 'Summary of express request duration',
+        labelNames: ['route']
+      })
+    }
+    return responseTime(function (req, res, time) {
+      let route = 'unknown'
+      if (req.route && req.route.path) route = req.route.path
+      metricRequestDuration.labels(route).observe(time / 1000)
+    })
+  }
+}

packages/server/logging/httpServerMonitoring.js

@@ -0,0 +1,30 @@
+/* istanbul ignore file */
+/* eslint-disable no-unused-vars */
+'use strict'
+
+const prometheusClient = require('prom-client')
+
+let metricActiveConnections = null
+
+module.exports = {
+  monitorActiveConnections(httpServer) {
+    if (metricActiveConnections !== null) {
+      prometheusClient.register.removeSingleMetric('speckle_server_active_connections')
+    }
+
+    metricActiveConnections = new prometheusClient.Gauge({
+      name: 'speckle_server_active_connections',
+      help: 'Number of active http connections',
+      async collect() {
+        let connectionCount = await new Promise((resolve, reject) => {
+          httpServer.getConnections(function (error, count) {
+            if (error) resolve(-1)
+            else resolve(count)
+          })
+        })
+        if (isNaN(connectionCount)) connectionCount = -1
+        this.set(connectionCount)
+      }
+    })
+  }
+}

packages/server/logging/index.js

@@ -2,10 +2,25 @@
 const Sentry = require('@sentry/node')
 const Tracing = require('@sentry/tracing')
 const { machineIdSync } = require('node-machine-id')
+const prometheusClient = require('prom-client')
+
+const { createRequestDurationMiddleware } = require('./expressMonitoring')
+const { initKnexPrometheusMetrics } = require('./knexMonitoring')
+
+let prometheusInitialized = false
 
 module.exports = function (app) {
   const id = machineIdSync()
 
+  if (!prometheusInitialized) {
+    prometheusInitialized = true
+    prometheusClient.register.clear()
+    prometheusClient.collectDefaultMetrics()
+    initKnexPrometheusMetrics()
+  }
+
+  app.use(createRequestDurationMiddleware())
+
   if (process.env.DISABLE_TRACING !== 'true' && process.env.SENTRY_DSN) {
     Sentry.setUser({ id })
 

packages/server/logging/knexMonitoring.js

@@ -0,0 +1,73 @@
+/* istanbul ignore file */
+/* eslint-disable no-unused-vars */
+'use strict'
+
+const knex = require('../db/knex')
+const prometheusClient = require('prom-client')
+
+let metricFree = null
+let metricUsed = null
+let metricPendingAquires = null
+let metricQueryDuration = null
+let metricQueryErrors = null
+
+const queryStartTime = {}
+
+module.exports = {
+  initKnexPrometheusMetrics() {
+    metricFree = new prometheusClient.Gauge({
+      name: 'speckle_server_knex_free',
+      help: 'Number of free DB connections',
+      collect() {
+        this.set(knex.client.pool.numFree())
+      }
+    })
+
+    metricUsed = new prometheusClient.Gauge({
+      name: 'speckle_server_knex_used',
+      help: 'Number of used DB connections',
+      collect() {
+        this.set(knex.client.pool.numUsed())
+      }
+    })
+
+    metricPendingAquires = new prometheusClient.Gauge({
+      name: 'speckle_server_knex_pending',
+      help: 'Number of pending DB connection aquires',
+      collect() {
+        this.set(knex.client.pool.numPendingAcquires())
+      }
+    })
+
+    metricQueryDuration = new prometheusClient.Summary({
+      name: 'speckle_server_knex_query_duration',
+      help: 'Summary of the DB query durations in seconds'
+    })
+
+    metricQueryErrors = new prometheusClient.Counter({
+      name: 'speckle_server_knex_query_errors',
+      help: 'Number of DB queries with errors'
+    })
+
+    knex.on('query', (data) => {
+      const queryId = data.__knexQueryUid + ''
+      queryStartTime[queryId] = Date.now()
+    })
+
+    knex.on('query-response', (data, obj, builder) => {
+      const queryId = obj.__knexQueryUid + ''
+      const durationSec = (Date.now() - queryStartTime[queryId]) / 1000
+      delete queryStartTime[queryId]
+      if (!isNaN(durationSec)) metricQueryDuration.observe(durationSec)
+    })
+
+    knex.on('query-error', (err, querySpec) => {
+      const queryId = querySpec.__knexQueryUid + ''
+      const durationSec = (Date.now() - queryStartTime[queryId]) / 1000
+      delete queryStartTime[queryId]
+
+      if (!isNaN(durationSec)) metricQueryDuration.observe(durationSec)
+      metricQueryErrors.inc()
+    })
+  }
+}

packages/server/package.json

@@ -65,6 +65,7 @@
     "pg-query-stream": "^4.2.1",
     "prom-client": "^14.0.1",
     "redis": "^3.1.1",
+    "response-time": "^2.3.2",
     "sanitize-html": "^2.4.0",
     "sharp": "^0.29.3",
     "string-pixel-width": "^1.10.0",