mirror of
https://github.com/TryGhost/Ghost.git
synced 2025-02-24 23:48:13 -05:00
Added basic instrumentation to the database connection pool (#19589)
no issue - To help debug potential causes of slow/aborted get helpers, it would be cool to get more visibility into how Ghost handles database connections, particularly if it has to spend a long time waiting to acquire a new connection from the pool. - Under the hood, knex uses a package called tarn (https://github.com/Vincit/tarn.js/tree/3.0.2) to manage the connection pool. Tarn provides some hooks for instrumentation, so we can use those to get some basic visibility into the connection pool. - This PR adds handling for creating, acquiring and releasing connections from Tarn's connection pool which logs some basic metrics, particularly the queue length and time it takes to acquire a connection.
This commit is contained in:
Chris Raible
GitHub
parent
1d4b076670
commit
e0dae46dfc
4 changed files with 385 additions and 0 deletions
142
ghost/core/core/server/data/db/ConnectionPoolInstrumentation.js
Normal file
142
ghost/core/core/server/data/db/ConnectionPoolInstrumentation.js
Normal file
|
|
@ -0,0 +1,142 @@
|
|||
class ConnectionPoolInstrumentation {
|
||||
constructor({knex, logging, metrics, config}) {
|
||||
this.knex = knex;
|
||||
this.pool = this.knex.client.pool;
|
||||
this.logging = logging;
|
||||
this.metrics = metrics;
|
||||
this.enabled = config.get('performanceMonitoring:connectionPool');
|
||||
this.requestStartTimes = {};
|
||||
this.createStartTimes = {};
|
||||
}
|
||||
|
||||
// Get the number of pending creates and acquires plus free and used connections
|
||||
getPoolMetrics() {
|
||||
return {
|
||||
numPendingCreates: this.pool.numPendingCreates(),
|
||||
numPendingAcquires: this.pool.numPendingAcquires(),
|
||||
numFree: this.pool.numFree(),
|
||||
numUsed: this.pool.numUsed()
|
||||
};
|
||||
}
|
||||
|
||||
handleCreateRequest(eventId) {
|
||||
// Track when the request was submitted for calculating wait time
|
||||
this.createStartTimes[eventId] = Date.now();
|
||||
const poolMetrics = this.getPoolMetrics();
|
||||
this.logging.debug(`[ConnectionPool] Creating a connection. EventID: ${eventId} Pending Creates: ${poolMetrics.numPendingCreates} Free: ${poolMetrics.numFree} Used: ${poolMetrics.numUsed}`);
|
||||
this.metrics.metric('metrics-connection-pool', {
|
||||
event: 'create-request',
|
||||
eventId,
|
||||
...poolMetrics
|
||||
});
|
||||
}
|
||||
|
||||
handleCreateSuccess(eventId, resource) {
|
||||
// Calculate the time it took to create the connection
|
||||
const timeToCreate = Date.now() - this.createStartTimes[eventId];
|
||||
// Delete the start time so we don't leak memory
|
||||
delete this.createStartTimes[eventId];
|
||||
this.logging.debug(`[ConnectionPool] Created a connection. EventID: ${eventId} Connection ID: ${resource.connectionId} Knex ID: ${resource.__knexUid} Time to Create: ${timeToCreate}ms`);
|
||||
this.metrics.metric('metrics-connection-pool', {
|
||||
event: 'create-success',
|
||||
eventId,
|
||||
connectionId: resource.connectionId,
|
||||
knexUid: resource.__knexUid,
|
||||
timeToCreate
|
||||
});
|
||||
}
|
||||
|
||||
handleCreateFail(eventId, err) {
|
||||
// Calculate the time it took to create the connection
|
||||
const timeToFail = Date.now() - this.createStartTimes[eventId];
|
||||
// Delete the start time so we don't leak memory
|
||||
delete this.createStartTimes[eventId];
|
||||
const poolMetrics = this.getPoolMetrics();
|
||||
this.logging.error(`[ConnectionPool] Failed to create a connection. EventID: ${eventId} Time to Create: ${timeToFail}ms`, err);
|
||||
this.metrics.metric('metrics-connection-pool', {
|
||||
event: 'create-fail',
|
||||
eventId,
|
||||
timeToFail,
|
||||
...poolMetrics
|
||||
});
|
||||
}
|
||||
|
||||
handleAcquireRequest(eventId) {
|
||||
// Track when the request was submitted for calculating wait time
|
||||
this.requestStartTimes[eventId] = Date.now();
|
||||
const poolMetrics = this.getPoolMetrics();
|
||||
this.logging.debug(`[ConnectionPool] Acquiring a connection. EventID: ${eventId} Pending Acquires: ${poolMetrics.numPendingAcquires} Free: ${poolMetrics.numFree} Used: ${poolMetrics.numUsed}`);
|
||||
this.metrics.metric('metrics-connection-pool', {
|
||||
event: 'acquire-request',
|
||||
eventId,
|
||||
...poolMetrics
|
||||
});
|
||||
}
|
||||
|
||||
handleAcquireSuccess(eventId, resource) {
|
||||
// Calculate the time it took to acquire the connection
|
||||
const timeToAcquire = Date.now() - this.requestStartTimes[eventId];
|
||||
// Delete the start time so we don't leak memory
|
||||
delete this.requestStartTimes[eventId];
|
||||
// Track when the connection was acquired for calculating lifetime upon release
|
||||
resource.connectionAcquired = Date.now();
|
||||
this.logging.debug(`[ConnectionPool] Acquired a connection. EventID: ${eventId} Connection ID: ${resource.connectionId} Knex Id: ${resource.__knexUid} Time to Acquire: ${timeToAcquire}ms`);
|
||||
this.metrics.metric('metrics-connection-pool', {
|
||||
event: 'acquire-success',
|
||||
eventId,
|
||||
connectionId: resource.connectionId,
|
||||
knexUid: resource.__knexUid,
|
||||
timeToAcquire
|
||||
});
|
||||
}
|
||||
|
||||
handleAcquireFail(eventId, err) {
|
||||
// Calculate the time it took to acquire the connection
|
||||
const timeToFail = Date.now() - this.requestStartTimes[eventId];
|
||||
// Delete the start time so we don't leak memory
|
||||
delete this.requestStartTimes[eventId];
|
||||
const poolMetrics = this.getPoolMetrics();
|
||||
this.logging.error(`[ConnectionPool] Failed to acquire a connection. EventID: ${eventId} Time to Acquire: ${timeToFail}ms`, err);
|
||||
this.metrics.metric('metrics-connection-pool', {
|
||||
event: 'acquire-fail',
|
||||
eventId,
|
||||
timeToFail,
|
||||
...poolMetrics
|
||||
});
|
||||
}
|
||||
|
||||
handleRelease(resource) {
|
||||
const lifetime = Date.now() - resource.connectionAcquired;
|
||||
this.logging.debug(`[ConnectionPool] Released a connection. Connection ID: ${resource.connectionId} Lifetime: ${lifetime}ms`);
|
||||
this.metrics.metric('metrics-connection-pool', {
|
||||
event: 'release',
|
||||
connectionId: resource.connectionId,
|
||||
knexUid: resource.__knexUid,
|
||||
lifetime
|
||||
});
|
||||
}
|
||||
|
||||
instrument() {
|
||||
if (this.enabled) {
|
||||
// Check to make sure these event listeners haven't already been added
|
||||
if (this.pool.emitter.eventNames().length === 0) {
|
||||
// Fires when a connection is requested to be created
|
||||
this.pool.on('createRequest', eventId => this.handleCreateRequest(eventId));
|
||||
// Fires when a connection is successfully created
|
||||
this.pool.on('createSuccess', (eventId, resource) => this.handleCreateSuccess(eventId, resource));
|
||||
// Fires when a connection fails to be created
|
||||
this.pool.on('createFail', (eventId, err) => this.handleCreateFail(eventId, err));
|
||||
// Fires when a connection is requested from the pool
|
||||
this.pool.on('acquireRequest', eventId => this.handleAcquireRequest(eventId));
|
||||
// Fires when a connection is allocated from the pool
|
||||
this.pool.on('acquireSuccess', (eventId, resource) => this.handleAcquireSuccess(eventId, resource));
|
||||
// Fires when a connection fails to be allocated from the pool
|
||||
this.pool.on('acquireFail', (eventId, err) => this.handleAcquireFail(eventId, err));
|
||||
// Fires when a connection is released back into the pool
|
||||
this.pool.on('release', resource => this.handleRelease(resource));
|
||||
}
|
||||
}
|
||||
}
|
||||
}
|
||||
|
||||
module.exports = ConnectionPoolInstrumentation;
|
||||
|
|
@ -4,8 +4,10 @@ const os = require('os');
|
|||
const fs = require('fs');
|
||||
|
||||
const logging = require('@tryghost/logging');
|
||||
const metrics = require('@tryghost/metrics');
|
||||
const config = require('../../../shared/config');
|
||||
const errors = require('@tryghost/errors');
|
||||
const ConnectionPoolInstrumentation = require('./ConnectionPoolInstrumentation');
|
||||
let knexInstance;
|
||||
|
||||
// @TODO:
|
||||
|
|
@ -62,6 +64,10 @@ function configure(dbConfig) {
|
|||
|
||||
if (!knexInstance && config.get('database') && config.get('database').client) {
|
||||
knexInstance = knex(configure(config.get('database')));
|
||||
if (config.get('performanceMonitoring:connectionPool')) {
|
||||
const instrumentation = new ConnectionPoolInstrumentation({knex: knexInstance, logging, metrics, config});
|
||||
instrumentation.instrument();
|
||||
}
|
||||
}
|
||||
|
||||
module.exports = knexInstance;
|
||||
|
|
|
|||
|
|
@ -1,3 +1,8 @@
|
|||
const logging = require('@tryghost/logging');
|
||||
const metrics = require('@tryghost/metrics');
|
||||
const config = require('../../../shared/config');
|
||||
const ConnectionPoolInstrumentation = require('./ConnectionPoolInstrumentation');
|
||||
|
||||
let connection;
|
||||
|
||||
Object.defineProperty(exports, 'knex', {
|
||||
|
|
@ -5,6 +10,10 @@ Object.defineProperty(exports, 'knex', {
|
|||
configurable: true,
|
||||
get: function get() {
|
||||
connection = connection || require('./connection');
|
||||
if (config.get('performanceMonitoring:connectionPool')) {
|
||||
const instrumentation = new ConnectionPoolInstrumentation({knex: connection, logging, metrics, config});
|
||||
instrumentation.instrument();
|
||||
}
|
||||
return connection;
|
||||
}
|
||||
});
|
||||
|
|
|
|||
|
|
@ -0,0 +1,228 @@
|
|||
const sinon = require('sinon');
|
||||
const ConnectionPoolInstrumentation = require('../../../../../core/server/data/db/ConnectionPoolInstrumentation');
|
||||
const should = require('should');
|
||||
var EventEmitter = require('events').EventEmitter;
|
||||
|
||||
describe('ConnectionPoolInstrumentation', function () {
|
||||
afterEach(function () {
|
||||
sinon.restore();
|
||||
});
|
||||
|
||||
it('getPoolMetrics', async function () {
|
||||
const knex = {
|
||||
client: {
|
||||
pool: {
|
||||
numPendingCreates: sinon.stub().returns(1),
|
||||
numPendingAcquires: sinon.stub().returns(2),
|
||||
numFree: sinon.stub().returns(3),
|
||||
numUsed: sinon.stub().returns(4)
|
||||
}
|
||||
}
|
||||
};
|
||||
const logging = {};
|
||||
const metrics = {};
|
||||
const config = {
|
||||
get: sinon.stub().returns(true)
|
||||
};
|
||||
const instrumentation = new ConnectionPoolInstrumentation({knex, logging, metrics, config});
|
||||
const result = instrumentation.getPoolMetrics();
|
||||
result.should.eql({
|
||||
numPendingCreates: 1,
|
||||
numPendingAcquires: 2,
|
||||
numFree: 3,
|
||||
numUsed: 4
|
||||
});
|
||||
});
|
||||
|
||||
it('should handle creating a request successfully', async function () {
|
||||
const knex = {
|
||||
client: {
|
||||
pool: {
|
||||
numPendingCreates: sinon.stub().returns(1),
|
||||
numPendingAcquires: sinon.stub().returns(2),
|
||||
numFree: sinon.stub().returns(3),
|
||||
numUsed: sinon.stub().returns(4)
|
||||
}
|
||||
}
|
||||
};
|
||||
const logging = {
|
||||
debug: sinon.stub()
|
||||
};
|
||||
const metrics = {
|
||||
metric: sinon.stub()
|
||||
};
|
||||
const config = {
|
||||
get: sinon.stub().returns(true)
|
||||
};
|
||||
const instrumentation = new ConnectionPoolInstrumentation({knex, logging, metrics, config});
|
||||
instrumentation.handleCreateRequest(1);
|
||||
instrumentation.handleCreateSuccess(1, {connectionId: 2, __knexUid: 3});
|
||||
logging.debug.calledTwice.should.be.true();
|
||||
metrics.metric.calledTwice.should.be.true();
|
||||
});
|
||||
|
||||
it('should handle creating a request unsuccessfully', async function () {
|
||||
const knex = {
|
||||
client: {
|
||||
pool: {
|
||||
numPendingCreates: sinon.stub().returns(1),
|
||||
numPendingAcquires: sinon.stub().returns(2),
|
||||
numFree: sinon.stub().returns(3),
|
||||
numUsed: sinon.stub().returns(4)
|
||||
}
|
||||
}
|
||||
};
|
||||
const logging = {
|
||||
debug: sinon.stub(),
|
||||
error: sinon.stub()
|
||||
};
|
||||
const metrics = {
|
||||
metric: sinon.stub()
|
||||
};
|
||||
const config = {
|
||||
get: sinon.stub().returns(true)
|
||||
};
|
||||
const instrumentation = new ConnectionPoolInstrumentation({knex, logging, metrics, config});
|
||||
instrumentation.handleCreateRequest(1);
|
||||
instrumentation.handleCreateFail(1, new Error('test'));
|
||||
logging.error.calledOnce.should.be.true();
|
||||
metrics.metric.calledTwice.should.be.true();
|
||||
});
|
||||
|
||||
it('should handle acquiring a connection successfully', async function () {
|
||||
const knex = {
|
||||
client: {
|
||||
pool: {
|
||||
numPendingCreates: sinon.stub().returns(1),
|
||||
numPendingAcquires: sinon.stub().returns(2),
|
||||
numFree: sinon.stub().returns(3),
|
||||
numUsed: sinon.stub().returns(4)
|
||||
}
|
||||
}
|
||||
};
|
||||
const logging = {
|
||||
debug: sinon.stub()
|
||||
};
|
||||
const metrics = {
|
||||
metric: sinon.stub()
|
||||
};
|
||||
const config = {
|
||||
get: sinon.stub().returns(true)
|
||||
};
|
||||
const instrumentation = new ConnectionPoolInstrumentation({knex, logging, metrics, config});
|
||||
instrumentation.handleAcquireRequest(1);
|
||||
instrumentation.handleAcquireSuccess(1, {connectionId: 2, __knexUid: 3});
|
||||
logging.debug.calledTwice.should.be.true();
|
||||
metrics.metric.calledTwice.should.be.true();
|
||||
});
|
||||
|
||||
it('should handle acquiring a connection unsuccessfully', async function () {
|
||||
const knex = {
|
||||
client: {
|
||||
pool: {
|
||||
numPendingCreates: sinon.stub().returns(1),
|
||||
numPendingAcquires: sinon.stub().returns(2),
|
||||
numFree: sinon.stub().returns(3),
|
||||
numUsed: sinon.stub().returns(4)
|
||||
}
|
||||
}
|
||||
};
|
||||
const logging = {
|
||||
debug: sinon.stub(),
|
||||
error: sinon.stub()
|
||||
};
|
||||
const metrics = {
|
||||
metric: sinon.stub()
|
||||
};
|
||||
const config = {
|
||||
get: sinon.stub().returns(true)
|
||||
};
|
||||
const instrumentation = new ConnectionPoolInstrumentation({knex, logging, metrics, config});
|
||||
instrumentation.handleAcquireRequest(1);
|
||||
instrumentation.handleAcquireFail(1, new Error('test'));
|
||||
logging.error.calledOnce.should.be.true();
|
||||
metrics.metric.calledTwice.should.be.true();
|
||||
});
|
||||
|
||||
it('should handle releasing a connection successfully', async function () {
|
||||
const knex = {
|
||||
client: {
|
||||
pool: {
|
||||
numPendingCreates: sinon.stub().returns(1),
|
||||
numPendingAcquires: sinon.stub().returns(2),
|
||||
numFree: sinon.stub().returns(3),
|
||||
numUsed: sinon.stub().returns(4)
|
||||
}
|
||||
}
|
||||
};
|
||||
const logging = {
|
||||
debug: sinon.stub()
|
||||
};
|
||||
const metrics = {
|
||||
metric: sinon.stub()
|
||||
};
|
||||
const config = {
|
||||
get: sinon.stub().returns(true)
|
||||
};
|
||||
const instrumentation = new ConnectionPoolInstrumentation({knex, logging, metrics, config});
|
||||
instrumentation.handleRelease(1);
|
||||
logging.debug.calledOnce.should.be.true();
|
||||
metrics.metric.calledOnce.should.be.true();
|
||||
});
|
||||
|
||||
it('should instrument the connection pool if enabled', async function () {
|
||||
const knex = {
|
||||
client: {
|
||||
pool: {
|
||||
numPendingCreates: sinon.stub().returns(1),
|
||||
numPendingAcquires: sinon.stub().returns(2),
|
||||
numFree: sinon.stub().returns(3),
|
||||
numUsed: sinon.stub().returns(4),
|
||||
on: sinon.stub(),
|
||||
emitter: new EventEmitter()
|
||||
}
|
||||
}
|
||||
};
|
||||
const logging = {
|
||||
debug: sinon.stub(),
|
||||
error: sinon.stub()
|
||||
};
|
||||
const metrics = {
|
||||
metric: sinon.stub()
|
||||
};
|
||||
const config = {
|
||||
get: sinon.stub().returns(true)
|
||||
};
|
||||
const instrumentation = new ConnectionPoolInstrumentation({knex, logging, metrics, config});
|
||||
instrumentation.instrument();
|
||||
knex.client.pool.on.callCount.should.eql(7);
|
||||
});
|
||||
|
||||
it('should not instrument the connection pool if disabled', async function () {
|
||||
const knex = {
|
||||
client: {
|
||||
pool: {
|
||||
numPendingCreates: sinon.stub().returns(1),
|
||||
numPendingAcquires: sinon.stub().returns(2),
|
||||
numFree: sinon.stub().returns(3),
|
||||
numUsed: sinon.stub().returns(4),
|
||||
on: sinon.stub(),
|
||||
emitter: new EventEmitter()
|
||||
}
|
||||
}
|
||||
};
|
||||
const logging = {
|
||||
debug: sinon.stub(),
|
||||
error: sinon.stub()
|
||||
};
|
||||
const metrics = {
|
||||
metric: sinon.stub()
|
||||
};
|
||||
const config = {
|
||||
get: sinon.stub().returns(false)
|
||||
};
|
||||
const instrumentation = new ConnectionPoolInstrumentation({knex, logging, metrics, config});
|
||||
instrumentation.instrument();
|
||||
knex.client.pool.on.callCount.should.eql(0);
|
||||
});
|
||||
});
|
||||
Loading…
Add table
Reference in a new issue