feat: add db query latency metrics (#473)

* feat: add db metrics
Signed-off-by: Moritz Johner <beller.moritz@googlemail.com>

* fix: use base unit

Signed-off-by: Moritz Johner <beller.moritz@googlemail.com>

lib/db/client-applications-store.js

@@ -1,6 +1,9 @@
 /* eslint camelcase:off */
 'use strict';
 
+const metricsHelper = require('./metrics-helper');
+const { DB_TIME } = require('../events');
+
 const COLUMNS = [
     'app_name',
     'created_at',
@@ -35,15 +38,22 @@ const remapRow = (input, old = {}) => ({
 });
 
 class ClientApplicationsDb {
-    constructor(db) {
+    constructor(db, eventBus) {
         this.db = db;
+        this.eventBus = eventBus;
     }
 
     updateRow(details, prev) {
         details.updatedAt = 'now()';
         return this.db(TABLE)
             .where('app_name', details.appName)
-            .update(remapRow(details, prev));
+            .update(remapRow(details, prev))
+            .then(
+                metricsHelper.wrapTimer(this.eventBus, DB_TIME, {
+                    store: 'applications',
+                    action: 'updateRow',
+                })
+            );
     }
 
     insertNewRow(details) {
@@ -63,7 +73,13 @@ class ClientApplicationsDb {
                 } else {
                     return this.insertNewRow(data);
                 }
-            });
+            })
+            .then(
+                metricsHelper.wrapTimer(this.eventBus, DB_TIME, {
+                    store: 'applications',
+                    action: 'upsert',
+                })
+            );
     }
 
     getAll() {
@@ -71,7 +87,13 @@ class ClientApplicationsDb {
             .select(COLUMNS)
             .from(TABLE)
             .orderBy('app_name', 'asc')
-            .map(mapRow);
+            .map(mapRow)
+            .then(
+                metricsHelper.wrapTimer(this.eventBus, DB_TIME, {
+                    store: 'applications',
+                    action: 'getAll',
+                })
+            );
     }
 
     getApplication(appName) {

lib/db/client-instance-store.js

@@ -1,6 +1,9 @@
 /* eslint camelcase: "off" */
 'use strict';
 
+const metricsHelper = require('./metrics-helper');
+const { DB_TIME } = require('../events');
+
 const COLUMNS = [
     'app_name',
     'instance_id',
@@ -23,8 +26,9 @@ const mapRow = row => ({
 });
 
 class ClientInstanceStore {
-    constructor(db, getLogger) {
+    constructor(db, eventBus, getLogger) {
         this.db = db;
+        this.eventBus = eventBus;
         this.logger = getLogger('client-instance-store.js');
         const clearer = () => this._removeInstancesOlderThanTwoDays();
         setTimeout(clearer, 10).unref();
@@ -72,7 +76,13 @@ class ClientInstanceStore {
                 } else {
                     return this.insertNewRow(details);
                 }
-            });
+            })
+            .then(
+                metricsHelper.wrapTimer(this.eventBus, DB_TIME, {
+                    store: 'instance',
+                    action: 'insert',
+                })
+            );
     }
 
     getAll() {
@@ -80,7 +90,13 @@ class ClientInstanceStore {
             .select(COLUMNS)
             .from(TABLE)
             .orderBy('last_seen', 'desc')
-            .map(mapRow);
+            .map(mapRow)
+            .then(
+                metricsHelper.wrapTimer(this.eventBus, DB_TIME, {
+                    store: 'instance',
+                    action: 'getAll',
+                })
+            );
     }
 
     getByAppName(appName) {

lib/db/client-metrics-store.js

@@ -1,14 +1,17 @@
 'use strict';
 
 const { EventEmitter } = require('events');
+const metricsHelper = require('./metrics-helper');
+const { DB_TIME } = require('../events');
 
 const TEN_SECONDS = 10 * 1000;
 
 class ClientMetricsStore extends EventEmitter {
-    constructor(metricsDb, getLogger, pollInterval = TEN_SECONDS) {
+    constructor(metricsDb, eventBus, getLogger, pollInterval = TEN_SECONDS) {
         super();
         this.logger = getLogger('client-metrics-store.js');
         this.metricsDb = metricsDb;
+        this.eventBus = eventBus;
         this.highestIdSeen = 0;
 
         this._init(pollInterval);
@@ -45,7 +48,12 @@ class ClientMetricsStore extends EventEmitter {
 
     // Insert new client metrics
     insert(metrics) {
-        return this.metricsDb.insert(metrics);
+        return this.metricsDb.insert(metrics).then(
+            metricsHelper.wrapTimer(this.eventBus, DB_TIME, {
+                store: 'metrics',
+                action: 'insert',
+            })
+        );
     }
 
     destroy() {

lib/db/client-metrics-store.test.js

@@ -1,6 +1,7 @@
 'use strict';
 
 const test = require('ava');
+const { EventEmitter } = require('events');
 const ClientMetricStore = require('./client-metrics-store');
 const lolex = require('lolex');
 const getLogger = require('../../test/fixtures/no-logger');
@@ -24,8 +25,8 @@ function getMockDb() {
 
 test.cb('should call database on startup', t => {
     const mock = getMockDb();
-
+    const ee = new EventEmitter();
-    const store = new ClientMetricStore(mock, getLogger);
+    const store = new ClientMetricStore(mock, ee, getLogger);
 
     t.plan(2);
 
@@ -42,8 +43,8 @@ test.cb('should start poller even if inital database fetch fails', t => {
     const clock = lolex.install();
     const mock = getMockDb();
     mock.getMetricsLastHour = () => Promise.reject('oops');
-
+    const ee = new EventEmitter();
-    const store = new ClientMetricStore(mock, getLogger, 100);
+    const store = new ClientMetricStore(mock, ee, getLogger, 100);
 
     const metrics = [];
     store.on('metrics', m => metrics.push(m));
@@ -64,7 +65,8 @@ test.cb('should poll for updates', t => {
     const clock = lolex.install();
 
     const mock = getMockDb();
-    const store = new ClientMetricStore(mock, getLogger, 100);
+    const ee = new EventEmitter();
+    const store = new ClientMetricStore(mock, ee, getLogger, 100);
 
     const metrics = [];
     store.on('metrics', m => metrics.push(m));

lib/db/index.js

@@ -9,7 +9,7 @@ const ClientMetricsDb = require('./client-metrics-db');
 const ClientMetricsStore = require('./client-metrics-store');
 const ClientApplicationsStore = require('./client-applications-store');
 
-module.exports.createStores = config => {
+module.exports.createStores = (config, eventBus) => {
     const getLogger = config.getLogger;
     const db = createDb(config);
     const eventStore = new EventStore(db, getLogger);
@@ -20,8 +20,16 @@ module.exports.createStores = config => {
         eventStore,
         featureToggleStore: new FeatureToggleStore(db, eventStore, getLogger),
         strategyStore: new StrategyStore(db, eventStore, getLogger),
-        clientApplicationsStore: new ClientApplicationsStore(db, getLogger),
+        clientApplicationsStore: new ClientApplicationsStore(
-        clientInstanceStore: new ClientInstanceStore(db, getLogger),
+            db,
-        clientMetricsStore: new ClientMetricsStore(clientMetricsDb, getLogger),
+            eventBus,
+            getLogger
+        ),
+        clientInstanceStore: new ClientInstanceStore(db, eventBus, getLogger),
+        clientMetricsStore: new ClientMetricsStore(
+            clientMetricsDb,
+            eventBus,
+            getLogger
+        ),
     };
 };

lib/db/metrics-helper.js

@@ -0,0 +1,23 @@
+'use strict';
+
+const timer = require('../timer');
+
+// wrapTimer keeps track of the timing of a async operation and emits
+// a event on the given eventBus once the operation is complete
+//
+// the returned function is designed to be used as a .then(<func>) argument.
+// It transparently passes the data to the following .then(<func>)
+//
+// usage: promise.then(wrapTimer(bus, type, { payload: 'ok' }))
+const wrapTimer = (eventBus, event, args = {}) => {
+    const t = timer.new();
+    return data => {
+        args.time = t();
+        eventBus.emit(event, args);
+        return data;
+    };
+};
+
+module.exports = {
+    wrapTimer,
+};

lib/events.js

@@ -2,4 +2,5 @@
 
 module.exports = {
     REQUEST_TIME: 'request_time',
+    DB_TIME: 'db_time',
 };

lib/metrics.js

@@ -30,6 +30,12 @@ exports.startMonitoring = (
         labelNames: ['path', 'method', 'status'],
         percentiles: [0.1, 0.5, 0.9, 0.99],
     });
+    const dbDuration = new client.Summary({
+        name: 'db_query_duration_seconds',
+        help: 'DB query duration time',
+        labelNames: ['store', 'action'],
+        percentiles: [0.1, 0.5, 0.9, 0.99],
+    });
     const featureToggleUpdateTotal = new client.Counter({
         name: 'feature_toggle_update_total',
         help: 'Number of times a toggle has  been updated',
@@ -45,6 +51,10 @@ exports.startMonitoring = (
         requestDuration.labels(path, method, statusCode).observe(time);
     });
 
+    eventBus.on(events.DB_TIME, ({ store, action, time }) => {
+        dbDuration.labels(store, action).observe(time);
+    });
+
     eventStore.on(FEATURE_CREATED, ({ data }) => {
         featureToggleUpdateTotal.labels(data.name).inc();
     });

lib/metrics.test.js

@@ -5,7 +5,7 @@ const { EventEmitter } = require('events');
 const eventBus = new EventEmitter();
 const eventStore = new EventEmitter();
 const clientMetricsStore = new EventEmitter();
-const { REQUEST_TIME } = require('./events');
+const { REQUEST_TIME, DB_TIME } = require('./events');
 const { FEATURE_UPDATED } = require('./event-type');
 const { startMonitoring } = require('./metrics');
 const { register: prometheusRegister } = require('prom-client');
@@ -56,3 +56,17 @@ test('should collect metrics for client metric reports', t => {
         /feature_toggle_usage_total{toggle="TestToggle",active="true"} 10\nfeature_toggle_usage_total{toggle="TestToggle",active="false"} 5/
     );
 });
+
+test('should collect metrics for db query timings', t => {
+    eventBus.emit(DB_TIME, {
+        store: 'foo',
+        action: 'bar',
+        time: 0.1337,
+    });
+
+    const metrics = prometheusRegister.metrics();
+    t.regex(
+        metrics,
+        /db_query_duration_seconds{quantile="0\.99",store="foo",action="bar"} 0.1337/
+    );
+});

lib/server-impl.js

@@ -16,8 +16,8 @@ const { addEventHook } = require('./event-hook');
 async function createApp(options) {
     // Database dependencies (stateful)
     const logger = options.getLogger('server-impl.js');
-    const stores = createStores(options);
     const eventBus = new EventEmitter();
+    const stores = createStores(options, eventBus);
 
     const config = Object.assign(
         {

lib/timer.js

@@ -0,0 +1,28 @@
+'use strict';
+
+const NS_TO_S = 1e9;
+
+// seconds takes a tuple of [seconds, nanoseconds]
+// and returns the time in seconds
+const seconds = diff => diff[0] + diff[1] / NS_TO_S;
+
+module.exports = {
+    // new returns a timer function. Call it to measure the time since the call to new().
+    // the timer function returns the duration in seconds
+    //
+    // usage:
+    //
+    // t = timer.new()
+    // setTimeout(() => {
+    //   diff = t()
+    //   console.log(diff) // 0.500003192s
+    // }, 500)
+    //
+    new: () => {
+        const now = process.hrtime();
+        // the timer function returns the time in seconds
+        // since new() was called
+        return () => seconds(process.hrtime(now));
+    },
+    seconds,
+};

lib/timer.test.js

@@ -0,0 +1,32 @@
+'use strict';
+
+const test = require('ava');
+const timer = require('./timer');
+
+function timeout(fn, ms) {
+    return new Promise(resolve =>
+        setTimeout(() => {
+            fn();
+            resolve();
+        }, ms)
+    );
+}
+
+test('should calculate the correct time in seconds', t => {
+    t.is(timer.seconds([1, 0]), 1);
+    t.is(timer.seconds([0, 1e6]), 0.001);
+    t.is(timer.seconds([1, 1e6]), 1.001);
+    t.is(timer.seconds([1, 552]), 1.000000552);
+});
+
+test('timer should track the time', async t => {
+    const tt = timer.new();
+    let diff;
+    await timeout(() => {
+        diff = tt();
+    }, 20);
+    if (diff > 0.019 && diff < 0.05) {
+        return t.pass();
+    }
+    t.fail();
+});

test/e2e/helpers/database-init.js

@@ -1,5 +1,6 @@
 'use strict';
 
+const { EventEmitter } = require('events');
 const migrator = require('../../../migrator');
 const { createStores } = require('../../../lib/db');
 const { createDb } = require('../../../lib/db/db-pool');
@@ -59,11 +60,12 @@ module.exports = async function init(databaseSchema = 'test', getLogger) {
     };
 
     const db = createDb(options);
+    const eventBus = new EventEmitter();
 
     await db.raw(`CREATE SCHEMA IF NOT EXISTS ${options.databaseSchema}`);
     await migrator(options);
     await db.destroy();
-    const stores = await createStores(options);
+    const stores = await createStores(options, eventBus);
     await resetDatabase(stores);
     await setupDatabase(stores);