From 5c9a3b59613ff5ea75c94249f672e0a49a313889 Mon Sep 17 00:00:00 2001 From: Ralf Kistner Date: Tue, 16 Jul 2024 14:35:32 +0200 Subject: [PATCH 1/2] Log profiling output to the console. --- .../adapters/wa-sqlite/WASQLiteDBAdapter.ts | 57 ++++++++++++++++++- 1 file changed, 55 insertions(+), 2 deletions(-) diff --git a/packages/web/src/db/adapters/wa-sqlite/WASQLiteDBAdapter.ts b/packages/web/src/db/adapters/wa-sqlite/WASQLiteDBAdapter.ts index 0fc1b81a7..1360a2e3a 100644 --- a/packages/web/src/db/adapters/wa-sqlite/WASQLiteDBAdapter.ts +++ b/packages/web/src/db/adapters/wa-sqlite/WASQLiteDBAdapter.ts @@ -53,10 +53,53 @@ export class WASQLiteDBAdapter extends BaseObserver implement const start = performance.now(); try { const r = await originalExecute(sql, bindings); - performance.measure(`SQL: ${sql}`, { start }); + const end = performance.now(); + const message = `[SQL] ${sql}`; + performance.measure(message, { start, end }); + const duration = end - start; + if (duration >= 10) { + if (duration >= 50) { + const rw = await originalExecute(`EXPLAIN QUERY PLAN ${sql}`, bindings); + const explain = rw.rows?._array ?? []; + if (explain.length > 0) { + const emessage = explain.map((r) => ` ${r.detail}`).join('\n'); + + console.log( + '%c[SQL] %c%s %c%s\n%c%s\n%c%s', + 'color: grey', + durationStyle(duration), + `[${duration.toFixed(1)}ms]`, + 'color: grey', + sql, + 'color: blue', + '[EXPLAIN QUERY PLAN]', + 'color: grey', + emessage + ); + } else { + console.log( + '%c[SQL] %c%s %c%s', + 'color: grey', + durationStyle(duration), + `[${duration.toFixed(1)}ms]`, + 'color: grey', + sql + ); + } + } else { + console.log( + '%c[SQL] %c%s %c%s', + 'color: grey', + durationStyle(duration), + `[${duration.toFixed(1)}ms]`, + 'color: grey', + sql + ); + } + } return r; } catch (e: any) { - performance.measure(`SQL ERROR: ${e.message} | ${sql}`, { start }); + performance.measure(`[SQL] [ERROR: ${e.message}] ${sql}`, { start }); throw e; } }; @@ -263,3 +306,13 @@ export class WASQLiteDBAdapter extends BaseObserver implement }; } } + +function durationStyle(duration: number) { + if (duration < 30) { + return 'color: grey'; + } else if (duration < 300) { + return 'color: blue'; + } else { + return 'color: red'; + } +} From 65a814df9ee2602be867c35b444abce60bebb527 Mon Sep 17 00:00:00 2001 From: Ralf Kistner Date: Tue, 16 Jul 2024 15:06:20 +0200 Subject: [PATCH 2/2] Use groupCollapsed for query profiling output. --- .../adapters/wa-sqlite/WASQLiteDBAdapter.ts | 66 +++++++------------ 1 file changed, 24 insertions(+), 42 deletions(-) diff --git a/packages/web/src/db/adapters/wa-sqlite/WASQLiteDBAdapter.ts b/packages/web/src/db/adapters/wa-sqlite/WASQLiteDBAdapter.ts index 1360a2e3a..d26dd4727 100644 --- a/packages/web/src/db/adapters/wa-sqlite/WASQLiteDBAdapter.ts +++ b/packages/web/src/db/adapters/wa-sqlite/WASQLiteDBAdapter.ts @@ -54,48 +54,30 @@ export class WASQLiteDBAdapter extends BaseObserver implement try { const r = await originalExecute(sql, bindings); const end = performance.now(); - const message = `[SQL] ${sql}`; - performance.measure(message, { start, end }); + performance.measure(`[SQL] ${sql}`, { start, end }); const duration = end - start; if (duration >= 10) { - if (duration >= 50) { - const rw = await originalExecute(`EXPLAIN QUERY PLAN ${sql}`, bindings); - const explain = rw.rows?._array ?? []; - if (explain.length > 0) { - const emessage = explain.map((r) => ` ${r.detail}`).join('\n'); - - console.log( - '%c[SQL] %c%s %c%s\n%c%s\n%c%s', - 'color: grey', - durationStyle(duration), - `[${duration.toFixed(1)}ms]`, - 'color: grey', - sql, - 'color: blue', - '[EXPLAIN QUERY PLAN]', - 'color: grey', - emessage - ); - } else { - console.log( - '%c[SQL] %c%s %c%s', - 'color: grey', - durationStyle(duration), - `[${duration.toFixed(1)}ms]`, - 'color: grey', - sql - ); - } - } else { - console.log( - '%c[SQL] %c%s %c%s', - 'color: grey', - durationStyle(duration), - `[${duration.toFixed(1)}ms]`, - 'color: grey', - sql - ); + const rw = await originalExecute(`EXPLAIN QUERY PLAN ${sql}`, bindings); + const explain = rw.rows?._array ?? []; + const sqlMessage = sql.trim(); + const newline = sqlMessage.indexOf('\n'); + const firstLine = newline >= 0 ? sqlMessage.substring(0, newline) + '...' : sqlMessage; + console.groupCollapsed( + '%c[SQL] %c%s %c%s', + 'color: grey; font-weight: normal', + durationStyle(duration), + `[${duration.toFixed(1)}ms]`, + 'color: grey; font-weight: normal', + firstLine + ); + if (newline >= 0) { + console.log('%c%s', 'color: grey', sqlMessage); } + if (explain.length > 0) { + const emessage = explain.map((r) => ` ${r.detail}`).join('\n'); + console.log('%c%s\n%c%s', 'color: blue', '[EXPLAIN QUERY PLAN]', 'color: grey', emessage); + } + console.groupEnd(); } return r; } catch (e: any) { @@ -309,10 +291,10 @@ export class WASQLiteDBAdapter extends BaseObserver implement function durationStyle(duration: number) { if (duration < 30) { - return 'color: grey'; + return 'color: grey; font-weight: normal'; } else if (duration < 300) { - return 'color: blue'; + return 'color: blue; font-weight: normal'; } else { - return 'color: red'; + return 'color: red; font-weight: normal'; } }