sql: speed up fts query, report slow queries

ts/sql/Client.ts

@@ -68,6 +68,8 @@ if (ipcRenderer && ipcRenderer.setMaxListeners) {
 
 const DATABASE_UPDATE_TIMEOUT = 2 * 60 * 1000; // two minutes
 
+const MIN_TRACE_DURATION = 10;
+
 const SQL_CHANNEL_KEY = 'sql-channel';
 const ERASE_SQL_KEY = 'erase-sql-key';
 const ERASE_ATTACHMENTS_KEY = 'erase-attachments';
@@ -90,6 +92,7 @@ let _shuttingDown = false;
 let _shutdownCallback: Function | null = null;
 let _shutdownPromise: Promise<any> | null = null;
 let shouldUseRendererProcess = true;
+const startupQueries = new Map<string, number>();
 
 // Because we can't force this module to conform to an interface, we narrow our exports
 //   to this one default export, which does conform to the interface.
@@ -255,6 +258,18 @@ async function goBackToMainProcess(): Promise<void> {
   window.log.info('data.goBackToMainProcess: switching to main process');
 
   shouldUseRendererProcess = false;
+
+  // Print query statistics for whole startup
+  const entries = Array.from(startupQueries.entries());
+  startupQueries.clear();
+
+  // Sort by decreasing duration
+  entries
+    .sort((a, b) => b[1] - a[1])
+    .filter(([_, duration]) => duration > MIN_TRACE_DURATION)
+    .forEach(([query, duration]) => {
+      window.log.info(`startup query: ${query} ${duration}ms`);
+    });
 }
 
 const channelsAsUnknown = fromPairs(
@@ -361,8 +376,7 @@ function _updateJob(id: number, data: ClientJobUpdateType) {
     resolve: (value: any) => {
       _removeJob(id);
       const end = Date.now();
-      const delta = end - start;
-      if (delta > 10 || _DEBUG) {
+      if (_DEBUG) {
         window.log.info(
           `SQL channel job ${id} (${fnName}) succeeded in ${end - start}ms`
         );
@@ -452,10 +466,27 @@ function makeChannel(fnName: string) {
     // UI from locking up whenever we do costly db operations.
     if (shouldUseRendererProcess) {
       const serverFnName = fnName as keyof ServerInterface;
+      const start = Date.now();
+
       // Ignoring this error TS2556: Expected 3 arguments, but got 0 or more.
       // eslint-disable-next-line @typescript-eslint/ban-ts-comment
       // @ts-ignore
-      return Server[serverFnName](...args);
+      const result = Server[serverFnName](...args);
+
+      const duration = Date.now() - start;
+
+      startupQueries.set(
+        serverFnName,
+        (startupQueries.get(serverFnName) || 0) + duration
+      );
+
+      if (duration > MIN_TRACE_DURATION || _DEBUG) {
+        window.log.info(
+          `Renderer SQL channel job (${fnName}) succeeded in ${duration}ms`
+        );
+      }
+
+      return result;
     }
 
     const jobId = _makeJob(fnName);

ts/sql/Server.ts

@@ -2467,18 +2467,31 @@ async function searchMessages(
   { limit }: { limit?: number } = {}
 ): Promise<Array<SearchResultMessageType>> {
   const db = getInstance();
+
+  // sqlite queries with a join on a virtual table (like FTS5) are de-optimized
+  // and can't use indices for ordering results. Instead an in-memory index of
+  // the join rows is sorted on the fly. The sorting becomes substantially
+  // slower when there are large columns in the in-memory index (like
+  // `messages.json`) so we do a query without them and then fetch large columns
+  // separately without using `ORDER BY` and `LIMIT`.
   const rows: Array<SearchResultMessageType> = db
     .prepare<Query>(
       `
       SELECT
         messages.json,
         snippet(messages_fts, -1, '<<left>>', '<<right>>', '...', 10) as snippet
-      FROM messages_fts
-      INNER JOIN messages on messages_fts.rowid = messages.rowid
-      WHERE
-        messages_fts match $query
-      ORDER BY messages.received_at DESC, messages.sent_at DESC
-      LIMIT $limit;
+      FROM
+        (SELECT
+          messages.rowid
+        FROM messages_fts
+        INNER JOIN messages ON messages_fts.rowid = messages.rowid
+        WHERE
+          messages_fts MATCH $query
+        ORDER BY messages.received_at DESC, messages.sent_at DESC
+        LIMIT $limit) AS results
+      INNER JOIN messages ON messages.rowid = results.rowid
+      INNER JOIN messages_fts ON messages_fts.rowid = results.rowid
+      WHERE messages_fts MATCH $query;
       `
     )
     .all({
@@ -2495,19 +2508,28 @@ async function searchMessagesInConversation(
   { limit }: { limit?: number } = {}
 ): Promise<Array<SearchResultMessageType>> {
   const db = getInstance();
+
+  // See `searchMessages` for the explanation of the query
   const rows = db
     .prepare<Query>(
       `
       SELECT
         messages.json,
         snippet(messages_fts, -1, '<<left>>', '<<right>>', '...', 10) as snippet
-      FROM messages_fts
-      INNER JOIN messages on messages_fts.rowid = messages.rowid
+      FROM
+        (SELECT
+          messages.rowid
+        FROM messages_fts
+        INNER JOIN messages ON messages_fts.rowid = messages.rowid
+        WHERE
+          messages_fts MATCH $query
+        ORDER BY messages.received_at DESC, messages.sent_at DESC
+        LIMIT $limit) AS results
+      INNER JOIN messages ON messages.rowid = results.rowid
+      INNER JOIN messages_fts ON messages_fts.rowid = results.rowid
       WHERE
-        messages_fts match $query AND
-        messages.conversationId = $conversationId
-      ORDER BY messages.received_at DESC, messages.sent_at DESC
-      LIMIT $limit;
+        messages_fts MATCH $query AND
+        messages.conversationId = $conversationId;
       `
     )
     .all({

ts/sql/main.ts

@@ -1,10 +1,13 @@
 // Copyright 2021 Signal Messenger, LLC
 // SPDX-License-Identifier: AGPL-3.0-only
 
+/* eslint-disable no-console */
+
 import { join } from 'path';
 import { Worker } from 'worker_threads';
 
 const ASAR_PATTERN = /app\.asar$/;
+const MIN_TRACE_DURATION = 10;
 
 export type InitializeOptions = {
   readonly configDir: string;
@@ -124,7 +127,17 @@ export class MainSQL {
       throw new Error('Not initialized');
     }
 
-    return this.send({ type: 'sqlCall', method, args });
+    const { result, duration } = await this.send({
+      type: 'sqlCall',
+      method,
+      args,
+    });
+
+    if (duration > MIN_TRACE_DURATION) {
+      console.log(`ts/sql/main: slow query ${method} duration=${duration}ms`);
+    }
+
+    return result;
   }
 
   private async send<Response>(request: WorkerRequest): Promise<Response> {

ts/sql/mainWorker.ts

@@ -46,7 +46,11 @@ port.on('message', async ({ seq, request }: WrappedWorkerRequest) => {
         throw new Error(`Invalid sql method: ${method}`);
       }
 
-      respond(seq, undefined, await method.apply(db, request.args));
+      const start = Date.now();
+      const result = await method.apply(db, request.args);
+      const end = Date.now();
+
+      respond(seq, undefined, { result, duration: end - start });
     } else {
       throw new Error('Unexpected request type');
     }