From dd173216ed5ddb90a77345f00c8a1a2435b87aa1 Mon Sep 17 00:00:00 2001 From: Fedor Indutny <79877362+indutny-signal@users.noreply.github.com> Date: Mon, 26 Apr 2021 15:01:22 -0700 Subject: [PATCH] sql: speed up fts query, report slow queries --- ts/sql/Client.ts | 37 ++++++++++++++++++++++++++++++++--- ts/sql/Server.ts | 46 ++++++++++++++++++++++++++++++++------------ ts/sql/main.ts | 15 ++++++++++++++- ts/sql/mainWorker.ts | 6 +++++- 4 files changed, 87 insertions(+), 17 deletions(-) diff --git a/ts/sql/Client.ts b/ts/sql/Client.ts index e5ef3aae781..77718cdab62 100644 --- a/ts/sql/Client.ts +++ b/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 | null = null; let shouldUseRendererProcess = true; +const startupQueries = new Map(); // 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 { 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); diff --git a/ts/sql/Server.ts b/ts/sql/Server.ts index 12b6f445810..fe470ffc1be 100644 --- a/ts/sql/Server.ts +++ b/ts/sql/Server.ts @@ -2467,18 +2467,31 @@ async function searchMessages( { limit }: { limit?: number } = {} ): Promise> { 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 = db .prepare( ` SELECT messages.json, snippet(messages_fts, -1, '<>', '<>', '...', 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> { const db = getInstance(); + + // See `searchMessages` for the explanation of the query const rows = db .prepare( ` SELECT messages.json, snippet(messages_fts, -1, '<>', '<>', '...', 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({ diff --git a/ts/sql/main.ts b/ts/sql/main.ts index a114c9a16ff..1d50c2760f7 100644 --- a/ts/sql/main.ts +++ b/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(request: WorkerRequest): Promise { diff --git a/ts/sql/mainWorker.ts b/ts/sql/mainWorker.ts index 466be06e18c..41dcb689dc2 100644 --- a/ts/sql/mainWorker.ts +++ b/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'); }