refactor(logger): non-debug query profiling

Use less precise query profiling (script based, rather than sql
server based). Re-enables slow query warning, and reduces
overhead when ui is enabled.

Author: thelindat

src/database/rawExecute.ts

@@ -1,9 +1,10 @@
-import { logError, profileBatchStatements, runProfiler } from '../logger';
+import { logError, logQuery, profileBatchStatements, runProfiler } from '../logger';
 import { CFXCallback, CFXParameters, QueryType } from '../types';
 import { parseResponse } from '../utils/parseResponse';
 import { executeType, parseExecute } from '../utils/parseExecute';
 import { getPoolConnection } from './connection';
 import { setCallback } from '../utils/setCallback';
+import { performance } from 'perf_hooks';
 
 export const rawExecute = async (
   invokingResource: string,
@@ -44,6 +45,7 @@ export const rawExecute = async (
         }
       }
 
+      const startTime = !hasProfiler && performance.now();
       const [result] = await connection.execute(query, values);
 
       if (cb) {
@@ -56,6 +58,8 @@ export const rawExecute = async (
 
       if (hasProfiler && ((index > 0 && index % 100 === 0) || index === parametersLength - 1)) {
         await profileBatchStatements(connection, invokingResource, query, parameters, index < 100 ? 0 : index);
+      } else if (startTime) {
+        logQuery(invokingResource, query, performance.now() - startTime, values);
       }
     }
 

src/database/rawQuery.ts

@@ -6,6 +6,7 @@ import type { CFXCallback, CFXParameters } from '../types';
 import type { QueryType } from '../types';
 import { getPoolConnection } from './connection';
 import { RowDataPacket } from 'mysql2';
+import { performance } from 'perf_hooks';
 
 export const rawQuery = async (
   type: QueryType,
@@ -28,14 +29,17 @@ export const rawQuery = async (
 
   try {
     const hasProfiler = await runProfiler(connection, invokingResource);
+    const startTime = !hasProfiler && performance.now();
     const [result] = await connection.query(query, parameters);
 
     if (hasProfiler) {
       const [profiler] = <RowDataPacket[]>(
         await connection.query('SELECT FORMAT(SUM(DURATION) * 1000, 4) AS `duration` FROM INFORMATION_SCHEMA.PROFILING')
       );
 
-      if (profiler[0]) logQuery(invokingResource, query, profiler[0].duration, parameters);
+      if (profiler[0]) logQuery(invokingResource, query, parseFloat(profiler[0].duration), parameters);
+    } else if (startTime) {
+      logQuery(invokingResource, query, performance.now() - startTime, parameters);
     }
 
     if (cb)

src/database/rawTransaction.ts

@@ -1,8 +1,9 @@
 import { getPoolConnection } from './connection';
-import { logError, profileBatchStatements, runProfiler } from '../logger';
+import { logError, logQuery, profileBatchStatements, runProfiler } from '../logger';
 import { CFXCallback, CFXParameters, TransactionQuery } from '../types';
 import { parseTransaction } from '../utils/parseTransaction';
 import { setCallback } from '../utils/setCallback';
+import { performance } from 'perf_hooks';
 
 const transactionError = (queries: { query: string; params?: CFXParameters }[], parameters: CFXParameters) => {
   `${queries.map((query) => `${query.query} ${JSON.stringify(query.params || [])}`).join('\n')}\n${JSON.stringify(
@@ -39,11 +40,13 @@ export const rawTransaction = async (
 
     for (let i = 0; i < transactionsLength; i++) {
       const transaction = transactions[i];
-
+      const startTime = !hasProfiler && performance.now();
       await connection.query(transaction.query, transaction.params);
 
       if (hasProfiler && ((i > 0 && i % 100 === 0) || i === transactionsLength - 1)) {
         await profileBatchStatements(connection, invokingResource, transactions, null, i < 100 ? 0 : i);
+      } else if (startTime) {
+        logQuery(invokingResource, transaction.query, performance.now() - startTime, transaction.params);
       }
     }
 

src/logger/index.ts

@@ -10,9 +10,11 @@ export function logError(
   err: any,
   query?: string,
   parameters?: CFXParameters,
-  includeParameters?: boolean,
+  includeParameters?: boolean
 ) {
-  const message = `${invokingResource} was unable to execute a query!${query ? `\n${`Query: ${query}`}` : ''}${includeParameters ? `\n${JSON.stringify(parameters)}` : ''}\n${err.message}`;
+  const message = `${invokingResource} was unable to execute a query!${query ? `\n${`Query: ${query}`}` : ''}${
+    includeParameters ? `\n${JSON.stringify(parameters)}` : ''
+  }\n${err.message}`;
 
   TriggerEvent('oxmysql:error', {
     query: query,
@@ -34,9 +36,13 @@ export const profilerStatements = [
   'SET profiling = 1',
 ];
 
+/**
+ * Executes MySQL queries to fetch accurate query profiling results when `mysql_debug` is enabled.
+ */
 export async function runProfiler(connection: PoolConnection, invokingResource: string) {
-  if (!mysql_debug && !mysql_ui) return;
-  if (!mysql_ui && mysql_debug && Array.isArray(mysql_debug) && !mysql_debug.includes(invokingResource)) return;
+  if (!mysql_debug) return;
+
+  if (Array.isArray(mysql_debug) && !mysql_debug.includes(invokingResource)) return;
 
   for (const statement of profilerStatements) await connection.query(statement);
 
@@ -62,12 +68,13 @@ export async function profileBatchStatements(
 
   if (typeof query === 'string' && parameters)
     for (let i = 0; i < profiler.length; i++) {
-      logQuery(invokingResource, query, profiler[i].duration, parameters[offset + i]);
+      logQuery(invokingResource, query, parseFloat(profiler[i].duration), parameters[offset + i]);
     }
   else if (typeof query === 'object')
     for (let i = 0; i < profiler.length; i++) {
       const transaction = query[offset + i];
-      if (transaction) logQuery(invokingResource, transaction.query, profiler[i].duration, transaction.params);
+      if (transaction)
+        logQuery(invokingResource, transaction.query, parseFloat(profiler[i].duration), transaction.params);
       else break;
     }
 }
@@ -86,17 +93,15 @@ const logStorage: QueryLog = {};
 export const logQuery = (
   invokingResource: string,
   query: string,
-  executionTime: string | number,
+  executionTime: number,
   parameters?: CFXParameters
 ) => {
-  executionTime = parseFloat(executionTime as string);
-
   if (
     executionTime >= mysql_slow_query_warning ||
     (mysql_debug && (!Array.isArray(mysql_debug) || mysql_debug.includes(invokingResource)))
   ) {
     console.log(
-      `${dbVersion} ^3${invokingResource} took ${executionTime}ms to execute a query!\n${query}${
+      `${dbVersion} ^3${invokingResource} took ${executionTime.toFixed(4)}ms to execute a query!\n${query}${
         parameters ? ` ${JSON.stringify(parameters)}` : ''
       }^0`
     );