Log slow Blink database queries

bskylink/src/cache/safelinkClient.ts

@@ -98,13 +98,15 @@ export class SafelinkClient {
     url: string,
     pattern: ToolsOzoneSafelinkDefs.PatternType,
   ): Promise<SafelinkRule> {
-    return db.db
-      .selectFrom('safelink_rule')
-      .selectAll()
-      .where('url', '=', url)
-      .where('pattern', '=', pattern)
-      .orderBy('createdAt', 'desc')
-      .executeTakeFirstOrThrow()
+    return db.observeQuery(`resolve_safelink_${pattern}_rule`, () =>
+      db.db
+        .selectFrom('safelink_rule')
+        .selectAll()
+        .where('url', '=', url)
+        .where('pattern', '=', pattern)
+        .orderBy('createdAt', 'desc')
+        .executeTakeFirstOrThrow(),
+    )
   }
 
   private async addRule(db: Database, rule: SafelinkRule) {

bskylink/src/db/index.ts

@@ -1,4 +1,5 @@
 import assert from 'assert'
+import {performance} from 'node:perf_hooks'
 import {
   Kysely,
   type KyselyPlugin,
@@ -101,6 +102,27 @@ export class Database {
     return this.db.isTransaction
   }
 
+  async observeQuery<T>(operation: string, query: () => Promise<T>): Promise<T> {
+    const startedAt = performance.now()
+    try {
+      return await query()
+    } finally {
+      const durationMs = Math.round(performance.now() - startedAt)
+      if (durationMs >= 1000) {
+        log.warn(
+          {
+            durationMs,
+            operation,
+            poolIdleConnections: this.cfg.pool.idleCount,
+            poolTotalConnections: this.cfg.pool.totalCount,
+            poolWaitingRequests: this.cfg.pool.waitingCount,
+          },
+          'slow database query',
+        )
+      }
+    }
+  }
+
   assertTransaction() {
     assert(this.isTransaction, 'Transaction required')
   }

bskylink/src/routes/shortLink.ts

@@ -16,11 +16,13 @@ export default function (ctx: AppContext, app: Express) {
         typeof linkId === 'string',
         'express guarantees id parameter is a string',
       )
-      const found = await ctx.db.db
-        .selectFrom('link')
-        .selectAll()
-        .where('id', '=', linkId)
-        .executeTakeFirst()
+      const found = await ctx.db.observeQuery('resolve_short_link', () =>
+        ctx.db.db
+          .selectFrom('link')
+          .selectAll()
+          .where('id', '=', linkId)
+          .executeTakeFirst(),
+      )
       if (!found) {
         // potentially broken or mistyped link
         res.setHeader('Cache-Control', 'no-store')