diff --git a/lib/db/client-applications-store.js b/lib/db/client-applications-store.js index 172acc9d1b..32a49f268a 100644 --- a/lib/db/client-applications-store.js +++ b/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) { diff --git a/lib/db/client-instance-store.js b/lib/db/client-instance-store.js index 849cbeab43..7745b4c579 100644 --- a/lib/db/client-instance-store.js +++ b/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) { diff --git a/lib/db/client-metrics-store.js b/lib/db/client-metrics-store.js index a511b89094..095ea90995 100644 --- a/lib/db/client-metrics-store.js +++ b/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() { diff --git a/lib/db/client-metrics-store.test.js b/lib/db/client-metrics-store.test.js index cbd6a74439..3b7bad1461 100644 --- a/lib/db/client-metrics-store.test.js +++ b/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 store = new ClientMetricStore(mock, getLogger); + const ee = new EventEmitter(); + 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 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)); @@ -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)); diff --git a/lib/db/index.js b/lib/db/index.js index f8fd658293..94ceb67efe 100644 --- a/lib/db/index.js +++ b/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), - clientInstanceStore: new ClientInstanceStore(db, getLogger), - clientMetricsStore: new ClientMetricsStore(clientMetricsDb, getLogger), + clientApplicationsStore: new ClientApplicationsStore( + db, + eventBus, + getLogger + ), + clientInstanceStore: new ClientInstanceStore(db, eventBus, getLogger), + clientMetricsStore: new ClientMetricsStore( + clientMetricsDb, + eventBus, + getLogger + ), }; }; diff --git a/lib/db/metrics-helper.js b/lib/db/metrics-helper.js new file mode 100644 index 0000000000..7926bfa41d --- /dev/null +++ b/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() argument. +// It transparently passes the data to the following .then() +// +// 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, +}; diff --git a/lib/events.js b/lib/events.js index ba1cb7926e..905b90b5af 100644 --- a/lib/events.js +++ b/lib/events.js @@ -2,4 +2,5 @@ module.exports = { REQUEST_TIME: 'request_time', + DB_TIME: 'db_time', }; diff --git a/lib/metrics.js b/lib/metrics.js index d1958d99c9..48435679bb 100644 --- a/lib/metrics.js +++ b/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(); }); diff --git a/lib/metrics.test.js b/lib/metrics.test.js index 04c2b0b44f..bb5e72ab83 100644 --- a/lib/metrics.test.js +++ b/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/ + ); +}); diff --git a/lib/server-impl.js b/lib/server-impl.js index 18c40681bb..378ada13b1 100644 --- a/lib/server-impl.js +++ b/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( { diff --git a/lib/timer.js b/lib/timer.js new file mode 100644 index 0000000000..b74c9f54ca --- /dev/null +++ b/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, +}; diff --git a/lib/timer.test.js b/lib/timer.test.js new file mode 100644 index 0000000000..94c3e7a3a0 --- /dev/null +++ b/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(); +}); diff --git a/test/e2e/helpers/database-init.js b/test/e2e/helpers/database-init.js index 01b3d46393..2a0c74b347 100644 --- a/test/e2e/helpers/database-init.js +++ b/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);