finished pg provider and some other fixes

Author: Guilherme Oenning

lib/miniprofiler.js

@@ -27,6 +27,7 @@ var popupRenderPosition = 'left';
 
 // EXPORTS
 exports.configure = configure;
+configure();
 
 for (let framework of ['koa', 'express', 'hapi']) {
   let func = require(`./middlewares/${framework}.js`);
@@ -174,8 +175,6 @@ function results(req, res, lastPathSegment, done) {
 	var body = '';
 	req.on('data', function(data) {
 		body += data;
-		if (body.length > 1e6)
-			req.connection.destroy();
 	});
 
 	req.on('end', function() {
@@ -222,13 +221,12 @@ function include(id) {
  */
 function configure(options){
 	options = options || {};
-	if(options) {
-		storage = options.storage || storage;
-		ignoredPaths = options.ignoredPaths || ignoredPaths;
-		trivialDurationThresholdMilliseconds = options.trivialDurationThresholdMilliseconds || trivialDurationThresholdMilliseconds;
-		popupShowTimeWithChildren = options.popupShowTimeWithChildren || popupShowTimeWithChildren;
-		popupRenderPosition = options.popupRenderPosition || popupRenderPosition;
-	}
+
+	storage = options.storage || storage;
+	ignoredPaths = options.ignoredPaths || ignoredPaths;
+	trivialDurationThresholdMilliseconds = options.trivialDurationThresholdMilliseconds || trivialDurationThresholdMilliseconds;
+	popupShowTimeWithChildren = options.popupShowTimeWithChildren || popupShowTimeWithChildren;
+	popupRenderPosition = options.popupRenderPosition || popupRenderPosition;
 }
 
 /*
@@ -249,6 +247,7 @@ function startProfiling(request, enabled) {
 		currentRequestExtension.customTimings = {};
 		debug(`Profiling started for ${path} with id ${currentRequestExtension.id}`);
 	}
+
 	currentRequestExtension.timeQuery = function() {
 		var args = Array.prototype.slice.call(arguments, enabled ? 0 : 3);
 		if (enabled) {
@@ -258,6 +257,15 @@ function startProfiling(request, enabled) {
 			arguments[2].apply(this, args);
 		}
 	};
+
+	currentRequestExtension.startTimeQuery = function(type, query) {
+		return startTimeQuery.call(this, currentRequestExtension, type, query);
+	};
+
+	currentRequestExtension.stopTimeQuery = function(timing) {
+		return stopTimeQuery.call(this, timing);
+	};
+
 	currentRequestExtension.step = function(name, call) {
 		//var args = Array.prototype.slice.call(arguments, enabled ? 0 : 2);
 		if (enabled) {
@@ -266,6 +274,7 @@ function startProfiling(request, enabled) {
 			call();
 		}
 	};
+
 	currentRequestExtension.include = function() {
 		return enabled ? include(currentRequestExtension.id) : '';
 	};
@@ -283,9 +292,14 @@ function stopProfiling(request){
 	var extension = request.miniprofiler;
 	var time = process.hrtime();
 	debug(`Profiling stopped for ${path} with id ${extension.id}`);
-	if(extension.stepGraph.parent != null){
-		throw new Error('profiling ended while still in a function, was left in ['+extension.stepGraph.name+']');
-	}
+
+	/*
+	 * Do we still need this?
+	 *
+	 if(extension.stepGraph.parent != null){
+	 	 throw new Error('profiling ended while still in a function, was left in ['+extension.stepGraph.name+']');
+	 }
+	*/
 
 	extension.stopTime = time;
 	extension.stepGraph.stopTime = time;
@@ -340,13 +354,35 @@ function step(name, request, call) {
  *  to have ended the query.
  */
 function timeQuery(extension, type, query, executeFunction) {
-  debug(`Started timed query "${type}" with command "${query}"`);
+	var timing = startTimeQuery(extension, type, query);
+	var params = Array.prototype.slice.call(arguments, 4);
+
+	for(var i = 0; i < params.length; i++){
+		if(_.isFunction(params[i])){
+			var param = params[i];
+			params[i] = function() {
+				debug(`Stopped timed query "${type}" with command "${query}"`);
+				extension.stopTimeQuery(timing);
+				var ret = param.apply(this, arguments);
+				return ret;
+			};
+		}
+	}
+
+	var ret = executeFunction.apply(this, params);
+	return ret;
+}
+
+function stopTimeQuery(timing) {
+	timing.stopTime = process.hrtime();
+}
+
+function startTimeQuery(extension, type, query) {
+	debug(`Started timed query "${type}" with command "${query}"`);
 
 	var time = process.hrtime();
 	var startDate = Date.now();
 
-	var params = Array.prototype.slice.call(arguments, 4);
-
 	extension.stepGraph.customTimings[type] = extension.stepGraph.customTimings[type] || [];
 
 	var customTiming = {
@@ -360,31 +396,21 @@ function timeQuery(extension, type, query, executeFunction) {
 
 	extension.stepGraph.customTimings[type].push(customTiming);
 
-	for(var i = 0; i < params.length; i++){
-		if(_.isFunction(params[i])){
-			var param = params[i];
-			params[i] = function() {
-				debug(`Stopped timed query "${type}" with command "${query}"`);
-				customTiming.stopTime = process.hrtime();
-				var ret = param.apply(this, arguments);
-				return ret;
-			};
-		}
-	}
-
-	var ret = executeFunction.apply(this, params);
-
-	return ret;
+	return customTiming;
 }
 
 function unstep(name, request) {
 	var time = process.hrtime();
 
 	var extension = request.miniprofiler;
 
-	if(extension.stepGraph.name != name){
-		throw new Error('profiling stepped out of the wrong function, found ['+name+'] expected ['+extension.stepGraph.name+']');
-	}
+	/*
+	 * Do we still need this?
+	 *
+	 if(extension.stepGraph.name != name){
+	   throw new Error('profiling stepped out of the wrong function, found ['+name+'] expected ['+extension.stepGraph.name+']');
+	 }
+	*/
 
 	extension.stepGraph.stopTime = time;
 
@@ -407,10 +433,14 @@ function describePerformance(root, request) {
 }
 
 function diff(start, stop){
+	/*
+	 * Do we still need this?
+	 *
 	if (!stop) {
 		stop = process.hrtime();
 		debug('missing stop, using', stop);
 	}
+	*/
 	var deltaSecs = stop[0] - start[0];
 	var deltaNanoSecs = stop[1] - start[1];
 

lib/providers/miniprofiler.pg.js

@@ -7,8 +7,17 @@ module.exports = function(pg) {
     name: 'pg',
     handler: function(req, res, next) {
 
-      pg.Client.prototype.query = !req.miniprofiler.enabled ? pgQuery : function(config, values, callback) {
-        req.miniprofiler.timeQuery('sql', config.toString(), pgQuery.bind(this), config, values, callback);
+      pg.Client.prototype.query = !req.miniprofiler || !req.miniprofiler.enabled ? pgQuery : function(config, values, callback) {
+        if (callback) {
+          req.miniprofiler.timeQuery('sql', config.toString(), pgQuery.bind(this), config, values, callback);
+        } else {
+          var timing = req.miniprofiler.startTimeQuery('sql', config.toString());
+          var query = pgQuery.call(this, config, values, callback);
+          query.on('end', function() {
+            req.miniprofiler.stopTimeQuery(timing);
+          });
+          return query;
+        }
       };
 
       next();

lib/providers/miniprofiler.redis.js

@@ -8,7 +8,7 @@ module.exports = function(redis) {
     name: 'redis',
     handler: function(req, res, next) {
 
-      redis.RedisClient.prototype.internal_send_command = !req.miniprofiler.enabled ? redisSendCommand : function(command, args, callback) {
+      redis.RedisClient.prototype.internal_send_command = !req.miniprofiler || !req.miniprofiler.enabled ? redisSendCommand : function(command, args, callback) {
         var query = `${command} ${args.join(', ')}`.trim();
         if (this.ready && blacklist.indexOf(command) == -1)
           req.miniprofiler.timeQuery('redis', query, redisSendCommand.bind(this), command, args, callback);

package.json

@@ -11,7 +11,7 @@
 
     "mocha": "mocha tests/ -c",
     "mocha-coverage": "istanbul cover ./node_modules/mocha/bin/_mocha -- tests/ -R spec",
-    "check-coverage": "istanbul check-coverage --statements 80 --branches 80 --functions 80 --lines 80",
+    "check-coverage": "istanbul check-coverage --statements 95 --branches 95 --functions 95 --lines 95",
     "update-coveralls": "cat coverage/lcov.info | sed s/.usr.src.miniprofiler/./ | node ./node_modules/coveralls/bin/coveralls.js"
   },
   "repository": {

tests/basic-test.js

@@ -22,28 +22,5 @@ module.exports = function(server) {
       });
     });
 
-    it('Custom timed query should be profiled', function(done) {
-      server.get('/js-sleep', (err, response) => {
-        var ids = JSON.parse(response.headers['x-miniprofiler-ids']);
-        expect(ids).to.have.lengthOf(1);
-
-        server.post('/mini-profiler-resources/results/', { id: ids[0], popup: 1 }, (err, response, body) => {
-          var result = JSON.parse(body);
-          expect(result.Id).to.equal(ids[0]);
-          expect(result.Name).to.equal('/js-sleep');
-          expect(result.DurationMilliseconds).to.be.above(40);
-          expect(result.Root.Children).to.be.empty;
-          expect(result.Root.CustomTimings).to.have.property('custom');
-          expect(result.Root.CustomTimings.custom).to.have.lengthOf(1);
-
-          expect(result.Root.CustomTimings.custom[0].ExecuteType).to.be.equal('custom');
-          expect(result.Root.CustomTimings.custom[0].CommandString).to.be.equal('Sleeping...');
-          expect(result.Root.CustomTimings.custom[0].DurationMilliseconds).to.be.below(result.DurationMilliseconds);
-          done();
-        });
-      });
-
-    });
-
   });
 };

tests/provider-pg-test.js

@@ -5,28 +5,30 @@ module.exports = function(server) {
     before(server.setUp.bind(null, 'default'));
     after(server.tearDown);
 
-    it('Should profile postgres SELECT command', function(done) {
-      server.get('/pg-select', (err, response) => {
-        var ids = JSON.parse(response.headers['x-miniprofiler-ids']);
-        expect(ids).to.have.lengthOf(1);
+    for (let url of ['/pg-select', '/pg-select-event']) {
 
-        server.post('/mini-profiler-resources/results/', { id: ids[0], popup: 1 }, (err, response, body) => {
-          var result = JSON.parse(body);
+      it(`Should profile postgres SELECT command for url '${url}'`, function(done) {
+        server.get(url, (err, response) => {
+          var ids = JSON.parse(response.headers['x-miniprofiler-ids']);
+          expect(ids).to.have.lengthOf(1);
 
-          expect(result.Id).to.equal(ids[0]);
-          expect(result.Name).to.equal('/pg-select');
-          expect(result.Root.Children).to.be.empty;
-          expect(result.Root.CustomTimings).to.have.property('sql');
-          expect(result.Root.CustomTimings.sql).to.have.lengthOf(1);
+          server.post('/mini-profiler-resources/results/', { id: ids[0], popup: 1 }, (err, response, body) => {
+            var result = JSON.parse(body);
 
-          expect(result.Root.CustomTimings.sql[0].ExecuteType).to.be.equal('sql');
-          expect(result.Root.CustomTimings.sql[0].CommandString).to.be.equal('SELECT $1::int AS number');
-          expect(result.Root.CustomTimings.sql[0].DurationMilliseconds).to.be.below(result.DurationMilliseconds);
-          done();
+            expect(result.Id).to.equal(ids[0]);
+            expect(result.Name).to.equal(url);
+            expect(result.Root.Children).to.be.empty;
+            expect(result.Root.CustomTimings).to.have.property('sql');
+            expect(result.Root.CustomTimings.sql).to.have.lengthOf(1);
+
+            expect(result.Root.CustomTimings.sql[0].ExecuteType).to.be.equal('sql');
+            expect(result.Root.CustomTimings.sql[0].CommandString).to.be.equal('SELECT $1::int AS number');
+            expect(result.Root.CustomTimings.sql[0].DurationMilliseconds).to.be.below(result.DurationMilliseconds);
+            done();
+          });
         });
       });
 
-    });
-
+    }
   });
 };

tests/servers/express/default.js

@@ -29,12 +29,31 @@ app.get('/step-two', (req, res) => {
   });
 });
 
+app.get('/step-parallel', (req, res) => {
+	var count = 0;
+	var finish = () => {
+		if (++count == 2)
+			res.send(req.miniprofiler.include());
+	};
+
+  req.miniprofiler.step('Step 1', finish);
+  req.miniprofiler.step('Step 2', finish);
+});
+
 app.get('/js-sleep', function(req, res) {
 	req.miniprofiler.timeQuery('custom', 'Sleeping...', setTimeout, function() {
 		res.send(req.miniprofiler.include());
 	}, 50);
 });
 
+app.get('/js-sleep-start-stop', function(req, res) {
+	var timing = req.miniprofiler.startTimeQuery('custom', 'Sleeping...');
+	setTimeout(function() {
+		req.miniprofiler.stopTimeQuery(timing);
+		res.send(req.miniprofiler.include());
+	}, 50);
+});
+
 app.get('/redis-set-key', function(req, res) {
   client.set('key', 'Awesome!', () => {
 		res.send(req.miniprofiler.include());
@@ -57,4 +76,13 @@ app.get('/pg-select', function(req, res) {
   });
 });
 
+app.get('/pg-select-event', function(req, res) {
+  pg.connect(connString, function(err, pgClient, done) {
+    var query = pgClient.query('SELECT $1::int AS number', ['1']);
+		query.on('end', function() {
+      res.send(req.miniprofiler.include());
+		});
+  });
+});
+
 module.exports = app;

tests/servers/express/unprofiled.js

@@ -1,7 +1,11 @@
 var miniprofiler = require('../../../lib/miniprofiler.js');
 var express = require('express');
+var redis = require('redis');
+var pg = require('pg');
+var connString = `postgres://docker:docker@${process.env.PG_PORT_5432_TCP_ADDR}/docker`;
 
 var app = express();
+var client = redis.createClient(6379, process.env.REDIS_PORT_6379_TCP_ADDR);
 
 var disableMiniProfiler = (req) => {
   return false;
@@ -17,4 +21,18 @@ app.get('/', (req, res) => {
 	}, 50);
 });
 
+app.get('/pg', (req, res) => {
+  pg.connect(connString, function(err, pgClient, done) {
+    pgClient.query('SELECT $1::int AS number', ['1'], function(err, result) {
+      res.send(req.miniprofiler.include());
+    });
+  });
+});
+
+app.get('/redis', (req, res) => {
+  client.set('key', 'Awesome!', () => {
+		res.send(req.miniprofiler.include());
+  });
+});
+
 module.exports = app;