Rewriting of the benchmarking feature

Fix changelog

Refactoring and more tests

Tests fix

Refactoring once more and tests fix

Unnecessary check removed

Tests fix once more

changelog.md

@@ -2,6 +2,7 @@
 - [FIXED] Confirmed that values modified in validation hooks are preserved [#3534](https://github.com/sequelize/sequelize/issues/3534)
 - [FIXED] Support lower case type names in SQLite [#5482](https://github.com/sequelize/sequelize/issues/5482)
 - [INTERNALS] Removed dependency on wellknown in favor of terraformer-wkt-parser
+- [ADDED] Benchmarking feature [#2494](https://github.com/sequelize/sequelize/issues/2494)
 
 # 3.20.0
 - [ADDED] rejectOnEmpty mode [#272](https://github.com/sequelize/sequelize/issues/272) [#5480](https://github.com/sequelize/sequelize/issues/5480)

lib/dialects/abstract/query.js

@@ -484,11 +484,6 @@ AbstractQuery.prototype.checkLoggingOption = function() {
     console.log('DEPRECATION WARNING: The logging-option should be either a function or false. Default: console.log');
     this.options.logging = console.log;
   }
-
-  if (this.options.logging === console.log) {
-    // using just console.log will break in node < 0.6
-    this.options.logging = function(s) { console.log(s); };
-  }
 };
 
 /**

lib/dialects/mssql/query.js

@@ -34,10 +34,10 @@ Query.prototype.run = function(sql, parameters) {
   //do we need benchmark for this query execution
   var benchmark = this.sequelize.options.benchmark || this.options.benchmark;
 
-  if (!benchmark) {
-    this.sequelize.log('Executing (' + (this.connection.uuid || 'default') + '): ' + this.sql, this.options);
-  } else {
+  if (benchmark) {
     var queryBegin = Date.now();
+  } else {
+    this.sequelize.log('Executing (' + (this.connection.uuid || 'default') + '): ' + this.sql, this.options);
   }
 
   var promise = new Utils.Promise(function(resolve, reject) {
@@ -73,7 +73,7 @@ Query.prototype.run = function(sql, parameters) {
         var request = new self.connection.lib.Request(self.sql, function(err) {
 
           if (benchmark) {
-            self.sequelize.log('Executed (' + (self.connection.uuid || 'default') + '): ' + self.sql + ' in ' + (Date.now() - queryBegin) + 'ms', self.options);
+            self.sequelize.log('Executed (' + (self.connection.uuid || 'default') + '): ' + self.sql, (Date.now() - queryBegin), self.options);
           }
 
           if (err) {

lib/dialects/mysql/query.js

@@ -30,17 +30,17 @@ Query.prototype.run = function(sql, parameters) {
   //do we need benchmark for this query execution
   var benchmark = this.sequelize.options.benchmark || this.options.benchmark;
 
-  if (!benchmark) {
-    this.sequelize.log('Executing (' + (this.connection.uuid || 'default') + '): ' + this.sql, this.options);
-  } else {
+  if (benchmark) {
     var queryBegin = Date.now();
+  } else {
+    this.sequelize.log('Executing (' + (this.connection.uuid || 'default') + '): ' + this.sql, this.options);
   }
 
   var promise = new Utils.Promise(function(resolve, reject) {
     self.connection.query(self.sql, function(err, results) {
 
       if (benchmark) {
-        self.sequelize.log('Executed (' + (self.connection.uuid || 'default') + '): ' + self.sql + ' in ' + (Date.now() - queryBegin) + 'ms', self.options);
+        self.sequelize.log('Executed (' + (self.connection.uuid || 'default') + '): ' + self.sql, (Date.now() - queryBegin), self.options);
       }
 
       if (err) {

lib/dialects/postgres/query.js

@@ -64,11 +64,11 @@ Query.prototype.run = function(sql, parameters) {
 
   //do we need benchmark for this query execution
   var benchmark = this.sequelize.options.benchmark || this.options.benchmark;
-  
-  if (!benchmark) {
-    this.sequelize.log('Executing (' + (this.client.uuid || 'default') + '): ' + this.sql, this.options);
-  } else {
+
+  if (benchmark) {
     var queryBegin = Date.now();
+  } else {
+    this.sequelize.log('Executing (' + (this.client.uuid || 'default') + '): ' + this.sql, this.options);
   }
 
   var promise = new Promise(function(resolve, reject) {
@@ -91,7 +91,7 @@ Query.prototype.run = function(sql, parameters) {
     query.on('end', function(result) {
 
       if (benchmark) {
-        self.sequelize.log('Executed (' + (self.client.uuid || 'default') + '): ' + self.sql + ' in ' + (Date.now() - queryBegin) + 'ms', self.options);
+        self.sequelize.log('Executed (' + (self.client.uuid || 'default') + '): ' + self.sql, (Date.now() - queryBegin), self.options);
       }
 
       if (receivedError) {

lib/dialects/sqlite/query.js

@@ -87,10 +87,10 @@ Query.prototype.run = function(sql, parameters) {
   //do we need benchmark for this query execution
   var benchmark = this.sequelize.options.benchmark || this.options.benchmark;
 
-  if (!benchmark) {
-    this.sequelize.log('Executing (' + (this.database.uuid || 'default') + '): ' + this.sql, this.options);
-  } else {
+  if (benchmark) {
     var queryBegin = Date.now();
+  } else {
+    this.sequelize.log('Executing (' + (this.database.uuid || 'default') + '): ' + this.sql, this.options);
   }
 
   promise = new Promise(function(resolve) {
@@ -104,7 +104,7 @@ Query.prototype.run = function(sql, parameters) {
             var afterExecute = function(err, results) {
 
               if (benchmark) {
-                self.sequelize.log('Executed (' + (self.database.uuid || 'default') + '): ' + self.sql + ' in ' + (Date.now() - queryBegin) + 'ms', self.options);
+                self.sequelize.log('Executed (' + (self.database.uuid || 'default') + '): ' + self.sql, (Date.now() - queryBegin), self.options);
               }
 
               if (err) {

lib/sequelize.js

@@ -75,6 +75,7 @@ var url = require('url')
  * @param {Object}   [options.sync={}] Default options for sequelize.sync
  * @param {String}   [options.timezone='+00:00'] The timezone used when converting a date from the database into a JavaScript date. The timezone is also used to SET TIMEZONE when connecting to the server, to ensure that the result of NOW, CURRENT_TIMESTAMP and other time related functions have in the right timezone. For best cross platform performance use the format +/-HH:MM. Will also accept string versions of timezones used by moment.js (e.g. 'America/Los_Angeles'); this is useful to capture daylight savings time changes.
  * @param {Function} [options.logging=console.log] A function that gets executed every time Sequelize would log something.
+ * @param {Boolean}  [options.benchmark=false] Pass query execution time in milliseconds as second argument to logging function (options.logging).
  * @param {Boolean}  [options.omitNull=false] A flag that defines if null values should be passed to SQL queries or not.
  * @param {Boolean}  [options.native=false] A flag that defines if native library shall be used or not. Currently only has an effect for postgres
  * @param {Boolean}  [options.replication=false] Use read / write replication. To enable replication, pass an object, with two properties, read and write. Write should be an object (a single server for handling writes), and read an array of object (several servers to handle reads). Each read/write server can have the following properties: `host`, `port`, `username`, `password`, `database`
@@ -90,7 +91,6 @@ var url = require('url')
  * @param {Array}    [options.retry.match] Only retry a query if the error matches one of these strings.
  * @param {Integer}  [options.retry.max] How many times a failing query is automatically retried.  Set to 0 to disable retrying on SQL_BUSY error.
  * @param {Boolean}  [options.typeValidation=false] Run built in type validators on insert and update, e.g. validate that arguments passed to integer fields are integer-like.
- * @param {Boolean}  [options.benchmark=false] Print query execution time in milliseconds when logging SQL.
 */
 
 /**
@@ -1332,6 +1332,11 @@ Sequelize.prototype.log = function() {
       options.logging = console.log;
     }
 
+    // second argument is sql-timings, when benchmarking option enabled
+    if ((this.options.benchmark || options.benchmark) && options.logging === console.log) {
+      args = [args[0] + ' Elapsed time: ' + args[1] + 'ms'];
+    }
+
     options.logging.apply(null, args);
   }
 };

test/integration/sequelize.test.js

@@ -223,6 +223,8 @@ describe(Support.getTestDialectTeaser('Sequelize'), function() {
   describe('query', function() {
     afterEach(function() {
       this.sequelize.options.quoteIdentifiers = true;
+
+      console.log.restore && console.log.restore();
     });
 
     beforeEach(function() {
@@ -249,6 +251,57 @@ describe(Support.getTestDialectTeaser('Sequelize'), function() {
       return this.sequelize.query(this.insertQuery);
     });
 
+    it('executes a query with global benchmarking option and default logger', function() {
+      var logger = sinon.spy(console, 'log');
+      var sequelize = Support.createSequelizeInstance({
+        logging: logger,
+        benchmark: true
+      });
+
+      return sequelize.query('select 1;').then(function() {
+        expect(logger.calledOnce).to.be.true;
+        expect(logger.args[0][0]).to.be.match(/Executed \(default\): select 1; Elapsed time: \d+ms/);
+      });
+    });
+
+    it('executes a query with global benchmarking option and custom logger', function() {
+      var logger = sinon.spy();
+      var sequelize = Support.createSequelizeInstance({
+        logging: logger,
+        benchmark: true
+      });
+
+      return sequelize.query('select 1;').then(function() {
+        expect(logger.calledOnce).to.be.true;
+        expect(logger.args[0][0]).to.be.equal('Executed (default): select 1;');
+        expect(typeof logger.args[0][1] === 'number').to.be.true;
+      });
+    });
+
+    it('executes a query with benchmarking option and default logger', function() {
+      var logger = sinon.spy(console, 'log');
+      return this.sequelize.query('select 1;', {
+        logging: logger,
+        benchmark: true
+      }).then(function() {
+        expect(logger.calledOnce).to.be.true;
+        expect(logger.args[0][0]).to.be.match(/Executed \(default\): select 1; Elapsed time: \d+ms/);
+      });
+    });
+
+    it('executes a query with benchmarking option and custom logger', function() {
+      var logger = sinon.spy();
+
+      return this.sequelize.query('select 1;', {
+        logging: logger,
+        benchmark: true
+      }).then(function() {
+        expect(logger.calledOnce).to.be.true;
+        expect(logger.args[0][0]).to.be.equal('Executed (default): select 1;');
+        expect(typeof logger.args[0][1] === 'number').to.be.true;
+      });
+    });
+
     it('executes select queries correctly', function() {
       var self = this;
       return self.sequelize.query(this.insertQuery).then(function() {

test/integration/sequelize/log.test.js

@@ -39,7 +39,7 @@ describe(Support.getTestDialectTeaser('Sequelize'), function() {
         });
 
         it('logs an empty string as info event', function() {
-          this.sequelize.log();
+          this.sequelize.log('');
           expect(this.spy.calledOnce).to.be.true;
         });
       });