Add query times to debug

chrisveness · Apr 13, 2020 · 9ef0c19 · 9ef0c19
1 parent 98a55e3
commit 9ef0c19
Showing 1 changed file with 17 additions and 7 deletions.
diff --git a/lib/mysqldb.js b/lib/mysqldb.js
@@ -2,8 +2,9 @@
 /* Manage MySQL database connections.                                                             */
 /* - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - -  */
 
-import mysql from 'mysql2/promise.js'; // fast mysql driver
-import Debug from 'debug';             // small debugging utility
+import mysql           from 'mysql2/promise.js'; // fast mysql driver
+import Debug           from 'debug';             // small debugging utility
+import { performance } from 'perf_hooks';        // nodejs.org/api/perf_hooks.html
 
 const debug = Debug('app:mysql'); // mysql db queries
 
@@ -22,13 +23,19 @@ class MysqlDb {
      * @returns Array containing array of result rows and array of fields.
      *
      * @example
-     *   const [ books ] = await Db.query('Select * From Books Where Author = ?', [ 'David' ]);
+     *   const [ books ] = await Db.query('Select * From Books Where Author = :author', { author: 'David' });
      */
     static async query(sql, values) {
         if (!connectionPool) await setupConnectionPool();
-        debug('MysqlDb.query', sql.trim().split('\n')[0]+(sql.trim().split('\n').length>1?'...':''));
 
-        return connectionPool.query(sql, values);
+        const t1 = performance.now();
+
+        const [ rows, fields ] = await connectionPool.query(sql, values);
+
+        const t2 = performance.now();
+        debug('query', `${(t2-t1).toFixed(0).padStart(3, ' ')}ms`, sql.trim().split('\n')[0]+(sql.trim().split('\n').length>1?'...':''), `×${rows.length}`);
+
+        return [ rows, fields ];
     }
 
     /**
@@ -54,7 +61,6 @@ class MysqlDb {
      */
     static async connect() {
         if (!connectionPool) await setupConnectionPool();
-        debug('MysqlDb.connect');
 
         const db = await connectionPool.getConnection();
 
@@ -122,15 +128,19 @@ class MysqlDb {
  * First connection request after app startup will set up connection pool.
  */
 async function setupConnectionPool() {
+    const t1 = performance.now();
+
     const dbConfig = MysqlDb.connectionParams();
     dbConfig.namedPlaceholders = true;
     dbConfig.dateStrings = true;
     connectionPool = mysql.createPool(dbConfig);
-    debug('MysqlDb.setupConnectionPool', `connect to ${dbConfig.host}/${dbConfig.database}`);
 
     // traditional mode ensures not null is respected for unsupplied fields, ensures valid JavaScript dates, etc
     await connectionPool.query('SET SESSION sql_mode = "TRADITIONAL"');
 
+    const t2 = performance.now();
+    debug('connect', `${(t2-t1).toFixed(0).padStart(3, ' ')}ms`, `${dbConfig.host}/${dbConfig.database}`);
+
     // send regular queries in attempt to fix Azure ETIMEDOUT / ECONNRESET issues - github.com/sidorares/node-mysql2/issues/683
     if (heartbeat) {
         setInterval(async () => {