MOBILE-3971 core: Track database query performance

scripts/print-performance-measures.js

@@ -40,6 +40,7 @@ for (const file of files) {
         styling: [],
         blocking: [],
         longTasks: [],
+        database: [],
         networking: [],
     };
     performanceMeasures[performanceMeasure.name].duration.push(performanceMeasure.duration);
@@ -47,17 +48,19 @@ for (const file of files) {
     performanceMeasures[performanceMeasure.name].styling.push(performanceMeasure.styling);
     performanceMeasures[performanceMeasure.name].blocking.push(performanceMeasure.blocking);
     performanceMeasures[performanceMeasure.name].longTasks.push(performanceMeasure.longTasks);
+    performanceMeasures[performanceMeasure.name].database.push(performanceMeasure.database);
     performanceMeasures[performanceMeasure.name].networking.push(performanceMeasure.networking);
 }
 
 // Calculate averages
-for (const [name, { duration, scripting, styling, blocking, longTasks, networking }] of Object.entries(performanceMeasures)) {
+for (const [name, { duration, scripting, styling, blocking, longTasks, database, networking }] of Object.entries(performanceMeasures)) {
     const totalRuns = duration.length;
     const averageDuration = Math.round(duration.reduce((total, duration) => total + duration) / totalRuns);
     const averageScripting = Math.round(scripting.reduce((total, scripting) => total + scripting) / totalRuns);
     const averageStyling = Math.round(styling.reduce((total, styling) => total + styling) / totalRuns);
     const averageBlocking = Math.round(blocking.reduce((total, blocking) => total + blocking) / totalRuns);
     const averageLongTasks = Math.round(longTasks.reduce((total, longTasks) => total + longTasks) / totalRuns);
+    const averageDatabase = Math.round(database.reduce((total, database) => total + database) / totalRuns);
     const averageNetworking = Math.round(networking.reduce((total, networking) => total + networking) / totalRuns);
 
     performanceMeasures[name] = {
@@ -66,6 +69,7 @@ for (const [name, { duration, scripting, styling, blocking, longTasks, networkin
         'Styling': `${averageStyling}ms`,
         'Blocking': `${averageBlocking}ms`,
         '# Network requests': averageNetworking,
+        '# DB Queries': averageDatabase,
         '# Long Tasks': averageLongTasks,
         '# runs': totalRuns,
     };

src/core/classes/sqlitedb.ts

@@ -16,6 +16,7 @@ import { SQLiteObject } from '@ionic-native/sqlite/ngx';
 
 import { SQLite, Platform } from '@singletons';
 import { CoreError } from '@classes/errors/error';
+import { CoreDB } from '@services/db';
 
 type SQLiteDBColumnType = 'INTEGER' | 'REAL' | 'TEXT' | 'BLOB';
 
@@ -813,16 +814,19 @@ export class SQLiteDB {
      * Initialize the database.
      */
     init(): void {
-        this.promise = Platform.ready()
-            .then(() => SQLite.create({
-                name: this.name,
-                location: 'default',
-            }))
-            .then((db: SQLiteObject) => {
-                this.db = db;
+        this.promise = this.createDatabase().then(db => {
+            if (CoreDB.loggingEnabled()) {
+                const spies = this.getDatabaseSpies(db);
 
-                return;
-            });
+                db = new Proxy(db, {
+                    get: (target, property, receiver) => spies[property] ?? Reflect.get(target, property, receiver),
+                });
+            }
+
+            this.db = db;
+
+            return;
+        });
     }
 
     /**
@@ -1147,6 +1151,50 @@ export class SQLiteDB {
         return { sql, params };
     }
 
+    /**
+     * Open a database connection.
+     *
+     * @returns Database.
+     */
+    protected async createDatabase(): Promise<SQLiteObject> {
+        await Platform.ready();
+
+        return SQLite.create({ name: this.name, location: 'default' });
+    }
+
+    /**
+     * Get database spy methods to intercept database calls and track logging information.
+     *
+     * @param db Database to spy.
+     * @returns Spy methods.
+     */
+    protected getDatabaseSpies(db: SQLiteObject): Partial<SQLiteObject> {
+        return {
+            executeSql(statement, params) {
+                const start = performance.now();
+
+                return db.executeSql(statement, params).then(result => {
+                    CoreDB.logQuery(statement, performance.now() - start, params);
+
+                    return result;
+                });
+            },
+            sqlBatch(statements) {
+                const start = performance.now();
+
+                return db.sqlBatch(statements).then(result => {
+                    const sql = Array.isArray(statements)
+                        ? statements.join(' | ')
+                        : String(statements);
+
+                    CoreDB.logQuery(sql, performance.now() - start);
+
+                    return result;
+                });
+            },
+        };
+    }
+
 }
 
 export type SQLiteDBRecordValues = {

src/core/features/emulator/classes/sqlitedb.ts

@@ -15,6 +15,8 @@
 /* tslint:disable:no-console */
 
 import { SQLiteDB } from '@classes/sqlitedb';
+import { DbTransaction, SQLiteObject } from '@ionic-native/sqlite/ngx';
+import { CoreDB } from '@services/db';
 
 /**
  * Class to mock the interaction with the SQLite database.
@@ -158,16 +160,6 @@ export class SQLiteDBMock extends SQLiteDB {
         });
     }
 
-    /**
-     * Initialize the database.
-     */
-    init(): void {
-        // This DB is for desktop apps, so use a big size to be sure it isn't filled.
-        // eslint-disable-next-line @typescript-eslint/no-explicit-any
-        this.db = (<any> window).openDatabase(this.name, '1.0', this.name, 500 * 1024 * 1024);
-        this.promise = Promise.resolve();
-    }
-
     /**
      * Open the database. Only needed if it was closed before, a database is automatically opened when created.
      *
@@ -178,4 +170,40 @@ export class SQLiteDBMock extends SQLiteDB {
         return Promise.resolve();
     }
 
+    /**
+     * @inheritdoc
+     */
+    protected async createDatabase(): Promise<SQLiteObject> {
+        // This DB is for desktop apps, so use a big size to be sure it isn't filled.
+        return (window as unknown as WebSQLWindow).openDatabase(this.name, '1.0', this.name, 500 * 1024 * 1024);
+    }
+
+    /**
+     * @inheritdoc
+     */
+    protected getDatabaseSpies(db: SQLiteObject): Partial<SQLiteObject> {
+        return {
+            transaction: (callback) => db.transaction((transaction) => {
+                const transactionSpy: DbTransaction = {
+                    executeSql(sql, params, success, error) {
+                        const start = performance.now();
+                        const resolve = callback => (...args) => {
+                            CoreDB.logQuery(sql, performance.now() - start, params);
+
+                            return callback(...args);
+                        };
+
+                        return transaction.executeSql(sql, params, resolve(success), resolve(error));
+                    },
+                };
+
+                return callback(transactionSpy);
+            }),
+        };
+    }
+
+}
+
+interface WebSQLWindow extends Window {
+    openDatabase(name: string, version: string, displayName: string, estimatedSize: number): SQLiteObject;
 }

src/core/initializers/prepare-automated-tests.ts

@@ -16,12 +16,14 @@ import { ApplicationRef, NgZone as NgZoneService } from '@angular/core';
 import { CorePushNotifications, CorePushNotificationsProvider } from '@features/pushnotifications/services/pushnotifications';
 import { CoreApp, CoreAppProvider } from '@services/app';
 import { CoreCronDelegate, CoreCronDelegateService } from '@services/cron';
+import { CoreDB, CoreDbProvider } from '@services/db';
 import { CoreCustomURLSchemes, CoreCustomURLSchemesProvider } from '@services/urlschemes';
 import { Application, NgZone } from '@singletons';
 
 type AutomatedTestsWindow = Window & {
     appRef?: ApplicationRef;
     appProvider?: CoreAppProvider;
+    dbProvider?: CoreDbProvider;
     cronProvider?: CoreCronDelegateService;
     ngZone?: NgZoneService;
     pushNotifications?: CorePushNotificationsProvider;
@@ -31,6 +33,7 @@ type AutomatedTestsWindow = Window & {
 function initializeAutomatedTestsWindow(window: AutomatedTestsWindow) {
     window.appRef = Application.instance;
     window.appProvider = CoreApp.instance;
+    window.dbProvider = CoreDB.instance;
     window.cronProvider = CoreCronDelegate.instance;
     window.ngZone = NgZone.instance;
     window.pushNotifications = CorePushNotifications.instance;

src/core/services/db.ts

@@ -17,6 +17,7 @@ import { Injectable } from '@angular/core';
 import { SQLiteDB } from '@classes/sqlitedb';
 import { SQLiteDBMock } from '@features/emulator/classes/sqlitedb';
 import { makeSingleton, SQLite, Platform } from '@singletons';
+import { CoreAppProvider } from './app';
 
 /**
  * This service allows interacting with the local database to store and retrieve data.
@@ -24,8 +25,29 @@ import { makeSingleton, SQLite, Platform } from '@singletons';
 @Injectable({ providedIn: 'root' })
 export class CoreDbProvider {
 
+    queryLogs: CoreDbQueryLog[] = [];
+
     protected dbInstances: {[name: string]: SQLiteDB} = {};
 
+    /**
+     * Check whether database queries should be logged.
+     *
+     * @returns Whether queries should be logged.
+     */
+    loggingEnabled(): boolean {
+        return CoreAppProvider.isAutomated();
+    }
+
+    /**
+     * Log a query.
+     *
+     * @param sql Query SQL.
+     * @param params Query parameters.
+     */
+    logQuery(sql: string, duration: number, params?: unknown[]): void {
+        this.queryLogs.push({ sql, duration, params });
+    }
+
     /**
      * Get or create a database object.
      *
@@ -81,3 +103,12 @@ export class CoreDbProvider {
 }
 
 export const CoreDB = makeSingleton(CoreDbProvider);
+
+/**
+ * Database query log entry.
+ */
+export interface CoreDbQueryLog {
+    sql: string;
+    duration: number;
+    params?: unknown[];
+}

tests/behat/classes/performance_measure.php

@@ -58,6 +58,16 @@ class performance_measure implements behat_app_listener {
      */
      public $blocking;
 
+    /**
+     * @var int
+     */
+    public $databaseStart;
+
+    /**
+     * @var int
+     */
+    public $database;
+
     /**
      * @var int
      */
@@ -90,6 +100,7 @@ class performance_measure implements behat_app_listener {
         $this->start = $this->now();
 
         $this->observeLongTasks();
+        $this->startDatabaseCount();
 
         $this->behatAppUnsubscribe = behat_app::listen($this);
     }
@@ -107,6 +118,7 @@ class performance_measure implements behat_app_listener {
 
         $this->analyseDuration();
         $this->analyseLongTasks();
+        $this->analyseDatabaseUsage();
         $this->analysePerformanceLogs();
     }
 
@@ -131,6 +143,7 @@ class performance_measure implements behat_app_listener {
             'styling' => $this->styling,
             'blocking' => $this->blocking,
             'longTasks' => count($this->longTasks),
+            'database' => $this->database,
             'networking' => $this->networking,
         ];
 
@@ -181,6 +194,17 @@ class performance_measure implements behat_app_listener {
         ");
     }
 
+    /**
+     * Record how many database queries have been logged so far.
+     */
+    private function startDatabaseCount(): void {
+        try {
+            $this->databaseStart = $this->driver->evaluateScript('dbProvider.queryLogs.length') ?? 0;
+        } catch (Exception $e) {
+            $this->databaseStart = 0;
+        }
+    }
+
     /**
      * Flush Performance observer.
      */
@@ -228,6 +252,13 @@ class performance_measure implements behat_app_listener {
         $this->blocking = $blocking;
     }
 
+    /**
+     * Analyse database usage.
+     */
+    private function analyseDatabaseUsage(): void {
+        $this->database = $this->driver->evaluateScript('dbProvider.queryLogs.length') - $this->databaseStart;
+    }
+
     /**
      * Analyse performance logs.
      */