Merge pull request #5154 from sushantdhiman/feat-488

Feat #488 : Benchmarks based on the pure JS Date.now()

lib/dialects/mssql/query.js

@@ -30,7 +30,14 @@ Query.prototype.run = function(sql, parameters) {
   var self = this;
   this.sql = sql;
 
+  //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 {
+    var queryBegin = Date.now();
+  }
 
   var promise = new Utils.Promise(function(resolve, reject) {
       // TRANSACTION SUPPORT
@@ -63,6 +70,11 @@ Query.prototype.run = function(sql, parameters) {
         var results = [];
 
         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);
+          }
+
           if (err) {
             err.sql = sql;
             reject(self.formatError(err));

lib/dialects/mysql/query.js

@@ -26,10 +26,22 @@ Query.prototype.run = function(sql, parameters) {
   var self = this;
   this.sql = sql;
 
+  //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 {
+    var queryBegin = Date.now();
+  }
 
   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);
+      }
+
       if (err) {
         err.sql = sql;
 

lib/dialects/postgres/query.js

@@ -62,7 +62,14 @@ Query.prototype.run = function(sql, parameters) {
     , query = ((parameters && parameters.length) ? this.client.query(this.sql, parameters) : this.client.query(this.sql))
     , rows = [];
 
+  //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 {
+    var queryBegin = Date.now();
+  }
 
   var promise = new Promise(function(resolve, reject) {
     query.on('row', function(row) {
@@ -82,6 +89,11 @@ 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);
+      }
+
       if (receivedError) {
         return;
       }

lib/dialects/sqlite/query.js

@@ -84,7 +84,14 @@ Query.prototype.run = function(sql, parameters) {
     this.sql = sql;
   }
 
+  //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 {
+    var queryBegin = Date.now();
+  }
 
   promise = new Promise(function(resolve) {
     var columnTypes = {};
@@ -95,6 +102,11 @@ Query.prototype.run = function(sql, parameters) {
         } else {
           resolve(new Promise(function(resolve, reject) {
             var afterExecute = function(err, results) {
+
+              if (benchmark) {
+                self.sequelize.log('Executed (' + (self.database.uuid || 'default') + '): ' + self.sql + ' in ' + (Date.now() - queryBegin) + 'ms', self.options);
+              }
+
               if (err) {
                 err.sql = self.sql;
                 reject(self.formatError(err));

lib/model.js

@@ -992,7 +992,7 @@ Model.prototype.sync = function(options) {
     });
 
     return Promise.map(indexes, function (index) {
-      return self.QueryInterface.addIndex(self.getTableName(options), _.assign({logging: options.logging}, index), self.tableName);
+      return self.QueryInterface.addIndex(self.getTableName(options), _.assign({logging: options.logging, benchmark: options.benchmark}, index), self.tableName);
     });
   }).then(function () {
     if (options.hooks) {
@@ -1006,6 +1006,7 @@ Model.prototype.sync = function(options) {
  * @param {Object}   [options]
  * @param {Boolean}  [options.cascade=false]   Also drop all objects depending on this table, such as views. Only works in postgres
  * @param {Function} [options.logging=false]   A function that gets executed while running the query to log the sql.
+ * @param {Boolean}  [options.benchmark=false] Print query execution time in milliseconds when logging SQL.
  * @return {Promise}
  */
 Model.prototype.drop = function(options) {
@@ -1024,6 +1025,7 @@ Model.prototype.dropSchema = function(schema) {
  * @param {Object} [options]
  * @param {String} [options.schemaDelimiter='.'] The character(s) that separates the schema name from the table name
  * @param {Function} [options.logging=false] A function that gets executed while running the query to log the sql.
+ * @param {Boolean}  [options.benchmark=false] Print query execution time in milliseconds when logging SQL.
  * @return {this}
  */
 Model.prototype.schema = function(schema, options) { // testhint options:none
@@ -1057,6 +1059,7 @@ Model.prototype.schema = function(schema, options) { // testhint options:none
  *
  * @param {Object}   [options] The hash of options from any query. You can use one model to access tables with matching schemas by overriding `getTableName` and using custom key/values to alter the name of the table. (eg. subscribers_1, subscribers_2)
  * @param {Function} [options.logging=false] A function that gets executed while running the query to log the sql.
+ * @param {Boolean}  [options.benchmark=false] Print query execution time in milliseconds when logging SQL.
  * @return {String|Object}
  */
 Model.prototype.getTableName = function(options) { // testhint options:none
@@ -1304,6 +1307,7 @@ Model.prototype.all = function(options) {
  * @param  {Function}                  [options.logging=false] A function that gets executed while running the query to log the sql.
  * @param  {Object}                    [options.having]
  * @param  {String}                    [options.searchPath=DEFAULT] An optional parameter to specify the schema search_path (Postgres only)
+ * @param  {Boolean}                   [options.benchmark=false] Print query execution time in milliseconds when logging SQL.
  *
  * @see    {Sequelize#query}
  * @return {Promise<Array<Instance>>}
@@ -1504,7 +1508,8 @@ Model.prototype.find = Model.prototype.findOne;
  * @param {DataType|String} [options.dataType] The type of the result. If `field` is a field in this Model, the default will be the type of that field, otherwise defaults to float.
  * @param {boolean}         [options.distinct] Applies DISTINCT to the field being aggregated over
  * @param {Transaction}     [options.transaction] Transaction to run query under
- * @param {boolean}         [options.plain] When `true`, the first returned value of `aggregateFunction` is cast to `dataType` and returned. If additional attributes are specified, along with `group` clauses, set `plain` to `false` to return all values of all returned rows.  Defaults to `true`
+ * @param {Boolean}         [options.plain] When `true`, the first returned value of `aggregateFunction` is cast to `dataType` and returned. If additional attributes are specified, along with `group` clauses, set `plain` to `false` to return all values of all returned rows.  Defaults to `true`
+ * @param {Boolean}         [options.benchmark=false] Print query execution time in milliseconds when logging SQL.
  *
  * @return {Promise<options.dataType|object>}                Returns the aggregate result cast to `options.dataType`, unless `options.plain` is false, in which case the complete data result is returned.
  */
@@ -1558,6 +1563,7 @@ Model.prototype.aggregate = function(attribute, aggregateFunction, options) {
  * @param {Transaction}   [options.transaction] Transaction to run query under
  * @param {Function}      [options.logging=false] A function that gets executed while running the query to log the sql.
  * @param {String}        [options.searchPath=DEFAULT] An optional parameter to specify the schema search_path (Postgres only)
+ * @param {Boolean}       [options.benchmark=false] Print query execution time in milliseconds when logging SQL.
  *
  * @return {Promise<Integer>}
  */
@@ -1793,6 +1799,7 @@ Model.prototype.bulkBuild = function(valueSets, options) { // testhint options:n
  * @param {Transaction}   [options.transaction] Transaction to run query under
  * @param {Function}      [options.logging=false] A function that gets executed while running the query to log the sql.
  * @param {String}        [options.searchPath=DEFAULT] An optional parameter to specify the schema search_path (Postgres only)
+ * @param {Boolean}       [options.benchmark=false] Print query execution time in milliseconds when logging SQL.
  *
  * @return {Promise<Instance>}
  */
@@ -1817,6 +1824,7 @@ Model.prototype.create = function(values, options) {
  * @param {Object}   [options.defaults] Default values to use if building a new instance
  * @param {Object}   [options.transaction] Transaction to run query under
  * @param {Function} [options.logging=false] A function that gets executed while running the query to log the sql.
+ * @param {Boolean}  [options.benchmark=false] Print query execution time in milliseconds when logging SQL.
  *
  * @return {Promise<Instance,initialized>}
  * @alias findOrBuild
@@ -1993,6 +2001,7 @@ Model.prototype.findCreateFind = function(options) {
  * @param  {Transaction}  [options.transaction] Transaction to run query under
  * @param  {Function}     [options.logging=false] A function that gets executed while running the query to log the sql.
  * @param  {String}       [options.searchPath=DEFAULT] An optional parameter to specify the schema search_path (Postgres only)
+ * @param  {Boolean}      [options.benchmark=false] Print query execution time in milliseconds when logging SQL.
  *
  * @alias insertOrUpdate
  * @return {Promise<created>} Returns a boolean indicating whether the row was created or updated.
@@ -2056,6 +2065,7 @@ Model.prototype.insertOrUpdate = Model.prototype.upsert;
  * @param  {Function}     [options.logging=false]          A function that gets executed while running the query to log the sql.
  * @param  {Boolean}      [options.returning=false] Append RETURNING * to get back auto generated values (Postgres only)
  * @param  {String}       [options.searchPath=DEFAULT] An optional parameter to specify the schema search_path (Postgres only)
+ * @param  {Boolean}      [options.benchmark=false] Print query execution time in milliseconds when logging SQL.
  *
  * @return {Promise<Array<Instance>>}
  */
@@ -2206,6 +2216,8 @@ Model.prototype.bulkCreate = function(records, options) {
  * @param {Transaction}      [options.transaction] Transaction to run query under
  * @param {Boolean|function} [options.logging] A function that logs sql queries, or false for no logging
  * @param {String}           [options.searchPath=DEFAULT] An optional parameter to specify the schema search_path (Postgres only)
+ * @param {Boolean}          [options.benchmark=false] Print query execution time in milliseconds when logging SQL.
+ *
  * @return {Promise}
  *
  * @see {Model#destroy} for more information
@@ -2229,6 +2241,7 @@ Model.prototype.truncate = function(options) {
  * @param  {Boolean}      [options.cascade=false]         Only used in conjunction with TRUNCATE. Truncates  all tables that have foreign-key references to the named table, or to any tables added to the group due to CASCADE.
  * @param  {Transaction}  [options.transaction] Transaction to run query under
  * @param  {Function}     [options.logging=false]         A function that gets executed while running the query to log the sql.
+ * @param  {Boolean}      [options.benchmark=false]       Print query execution time in milliseconds when logging SQL.
  * @return {Promise<Integer>} The number of destroyed rows
  */
 Model.prototype.destroy = function(options) {
@@ -2259,7 +2272,7 @@ Model.prototype.destroy = function(options) {
   }).then(function() {
     // Get daos and run beforeDestroy hook on each record individually
     if (options.individualHooks) {
-      return self.findAll({where: options.where, transaction: options.transaction, logging: options.logging}).map(function(instance) {
+      return self.findAll({where: options.where, transaction: options.transaction, logging: options.logging, benchmark: options.benchmark}).map(function(instance) {
         return self.runHooks('beforeDestroy', instance, options).then(function() {
           return instance;
         });
@@ -2308,6 +2321,7 @@ Model.prototype.destroy = function(options) {
  * @param  {Boolean}      [options.individualHooks=false] If set to true, restore will find all records within the where parameter and will execute before / after bulkRestore hooks on each row
  * @param  {Number}       [options.limit]                 How many rows to undelete
  * @param  {Function}     [options.logging=false]         A function that gets executed while running the query to log the sql.
+ * @param  {Boolean}      [options.benchmark=false]       Print query execution time in milliseconds when logging SQL.
  * @param  {Transaction}  [options.transaction] Transaction to run query under
  *
  * @return {Promise<undefined>}
@@ -2335,7 +2349,7 @@ Model.prototype.restore = function(options) {
   }).then(function() {
     // Get daos and run beforeRestore hook on each record individually
     if (options.individualHooks) {
-      return self.findAll({where: options.where, transaction: options.transaction, logging: options.logging, paranoid: false}).map(function(instance) {
+      return self.findAll({where: options.where, transaction: options.transaction, logging: options.logging, benchmark: options.benchmark, paranoid: false}).map(function(instance) {
         return self.runHooks('beforeRestore', instance, options).then(function() {
           return instance;
         });
@@ -2385,6 +2399,7 @@ Model.prototype.restore = function(options) {
  * @param  {Boolean}      [options.returning=false]       Return the affected rows (only for postgres)
  * @param  {Number}       [options.limit]                 How many rows to update (only for mysql and mariadb)
  * @param  {Function}     [options.logging=false] A function that gets executed while running the query to log the sql.
+ * @param  {Boolean}      [options.benchmark=false] Print query execution time in milliseconds when logging SQL.
  * @param  {Transaction}  [options.transaction] Transaction to run query under
  *
  * @return {Promise<Array<affectedCount,affectedRows>>}
@@ -2470,7 +2485,7 @@ Model.prototype.update = function(values, options) {
 
     // Get instances and run beforeUpdate hook on each record individually
     if (options.individualHooks) {
-      return self.findAll({where: options.where, transaction: options.transaction, logging: options.logging}).then(function(_instances) {
+      return self.findAll({where: options.where, transaction: options.transaction, logging: options.logging, benchmark: options.benchmark}).then(function(_instances) {
         instances = _instances;
         if (!instances.length) {
           return [];

lib/sequelize.js

@@ -81,7 +81,8 @@ var url = require('url')
  * @param {Boolean}  [options.quoteIdentifiers=true] Set to `false` to make table names and attributes case-insensitive on Postgres and skip double quoting of them.
  * @param {String}   [options.transactionType='DEFERRED'] Set the default transaction type. See `Sequelize.Transaction.TYPES` for possible options. Sqlite only.
  * @param {String}   [options.isolationLevel='REPEATABLE_READ'] Set the default transaction isolation level. See `Sequelize.Transaction.ISOLATION_LEVELS` for possible options.
- * @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.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.
 */
 
 /**
@@ -147,7 +148,8 @@ var Sequelize = function(database, username, password, options) {
     transactionType: Transaction.TYPES.DEFERRED,
     isolationLevel: Transaction.ISOLATION_LEVELS.REPEATABLE_READ,
     databaseVersion: 0,
-    typeValidation: false
+    typeValidation: false,
+    benchmark: false
   }, options || {});
 
   if (this.options.dialect === 'postgresql') {