Add query timing information

Author: kevinburke

lib/client.js

@@ -3,6 +3,7 @@ var EventEmitter = require('events').EventEmitter;
 var util = require('util');
 var pgPass = require('pgpass');
 var TypeOverrides = require('./type-overrides');
+var debug = require('debug')('pg');
 
 var ConnectionParameters = require(__dirname + '/connection-parameters');
 var Query = require(__dirname + '/query');
@@ -160,6 +161,9 @@ Client.prototype.connect = function(callback) {
     self.readyForQuery = true;
     self._pulseQueryQueue();
     if(activeQuery) {
+      if(this.queryStartTime) {
+        debug('query time: ', Date.now() - this.queryStartTime);
+      }
       activeQuery.handleReadyForQuery();
     }
   });
@@ -295,6 +299,7 @@ Client.prototype._pulseQueryQueue = function() {
     if(this.activeQuery) {
       this.readyForQuery = false;
       this.hasExecuted = true;
+      this.queryStartTime = Date.now();
       this.activeQuery.submit(this.connection);
     } else if(this.hasExecuted) {
       this.activeQuery = null;

lib/pool.js

@@ -1,5 +1,6 @@
 var EventEmitter = require('events').EventEmitter;
 
+var debug = require('debug')('pg');
 var defaults = require(__dirname + '/defaults');
 var genericPool = require('generic-pool');
 
@@ -73,7 +74,9 @@ var pools = {
     //monkey-patch with connect method
     pool.connect = function(cb) {
       var domain = process.domain;
+      var acquireStart = Date.now();
       pool.acquire(function(err, client) {
+        debug('pool count: ', client.poolCount + 1, 'acquire time', Date.now() - acquireStart);
         if(domain) {
           cb = domain.bind(cb);
         }

package.json

@@ -19,6 +19,7 @@
   "main": "./lib",
   "dependencies": {
     "buffer-writer": "1.0.0",
+    "debug": "~2.2.0",
     "generic-pool": "2.1.1",
     "packet-reader": "0.2.0",
     "pg-connection-string": "0.1.3",