Log slow Blink database operations (#11505)

bskylink/src/cache/safelinkClient.ts

@@ -98,13 +98,15 @@ export class SafelinkClient {
     url: string,
     pattern: ToolsOzoneSafelinkDefs.PatternType,
   ): Promise<SafelinkRule> {
-    return db.db
+    return db.observeQuery(`resolve_safelink_${pattern}_rule`, () =>
-      .selectFrom('safelink_rule')
+      db.db
-      .selectAll()
+        .selectFrom('safelink_rule')
-      .where('url', '=', url)
+        .selectAll()
-      .where('pattern', '=', pattern)
+        .where('url', '=', url)
-      .orderBy('createdAt', 'desc')
+        .where('pattern', '=', pattern)
-      .executeTakeFirstOrThrow()
+        .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,
@@ -17,6 +18,8 @@ import {default as migrations} from './migrations/index.js'
 import {DbMigrationProvider} from './migrations/provider.js'
 import {type DbSchema} from './schema.js'
 
+const SLOW_QUERY_THRESHOLD_MS = 1000
+
 export class Database {
   migrator: Migrator
   destroyed = false
@@ -101,6 +104,51 @@ export class Database {
     return this.db.isTransaction
   }
 
+  async observeQuery<T>(
+    operation: string,
+    query: () => Promise<T>,
+  ): Promise<T> {
+    const poolIdleConnectionsAtStart = this.cfg.pool.idleCount
+    const poolTotalConnectionsAtStart = this.cfg.pool.totalCount
+    const poolWaitingRequestsAtStart = this.cfg.pool.waitingCount
+    const startedAt = performance.now()
+    let poolIdleConnectionsAtThreshold: number | undefined
+    let poolTotalConnectionsAtThreshold: number | undefined
+    let poolWaitingRequestsAtThreshold: number | undefined
+    const slowQueryTimer = setTimeout(() => {
+      poolIdleConnectionsAtThreshold = this.cfg.pool.idleCount
+      poolTotalConnectionsAtThreshold = this.cfg.pool.totalCount
+      poolWaitingRequestsAtThreshold = this.cfg.pool.waitingCount
+    }, SLOW_QUERY_THRESHOLD_MS)
+    slowQueryTimer.unref()
+    try {
+      return await query()
+    } finally {
+      clearTimeout(slowQueryTimer)
+      const durationMs = Math.round(performance.now() - startedAt)
+      if (durationMs >= SLOW_QUERY_THRESHOLD_MS) {
+        log.warn(
+          {
+            durationMs,
+            operation,
+            poolIdleConnectionsAtEnd: this.cfg.pool.idleCount,
+            poolIdleConnectionsAtStart,
+            poolIdleConnectionsAtThreshold,
+            poolStateAtThresholdCaptured:
+              poolWaitingRequestsAtThreshold !== undefined,
+            poolTotalConnectionsAtEnd: this.cfg.pool.totalCount,
+            poolTotalConnectionsAtStart,
+            poolTotalConnectionsAtThreshold,
+            poolWaitingRequestsAtEnd: this.cfg.pool.waitingCount,
+            poolWaitingRequestsAtStart,
+            poolWaitingRequestsAtThreshold,
+          },
+          'slow database query',
+        )
+      }
+    }
+  }
+
   assertTransaction() {
     assert(this.isTransaction, 'Transaction required')
   }

bskylink/src/routes/redirect.ts

@@ -8,7 +8,7 @@ import {linkRedirectContents} from '../html/linkRedirectContents.js'
 import {linkWarningContents} from '../html/linkWarningContents.js'
 import {linkWarningLayout} from '../html/linkWarningLayout.js'
 import {redirectLogger} from '../logger.js'
-import {handler} from './util.js'
+import {observedHandler} from './util.js'
 
 const INTERNAL_IP_REGEX = new RegExp(
   '(^127.[0-9]{1,3}.[0-9]{1,3}.[0-9]{1,3}$)|(^10.[0-9]{1,3}.[0-9]{1,3}.[0-9]{1,3}$)|(^172.1[6-9]{1}[0-9]{0,1}.[0-9]{1,3}.[0-9]{1,3}$)|(^172.2[0-9]{1}[0-9]{0,1}.[0-9]{1,3}.[0-9]{1,3}$)|(^172.3[0-1]{1}[0-9]{0,1}.[0-9]{1,3}.[0-9]{1,3}$)|(^192.168.[0-9]{1,3}.[0-9]{1,3}$)|^localhost',
@@ -18,7 +18,7 @@ const INTERNAL_IP_REGEX = new RegExp(
 export default function (ctx: AppContext, app: Express) {
   return app.get(
     '/redirect',
-    handler(async (req, res) => {
+    observedHandler('redirect', async (req, res) => {
       let link = req.query.u
       assert(
         typeof link === 'string',

bskylink/src/routes/shortLink.ts

@@ -4,23 +4,25 @@ import {DAY, SECOND} from '@atproto/common'
 import {Express} from 'express'
 
 import {AppContext} from '../context.js'
-import {handler} from './util.js'
+import {observedHandler} from './util.js'
 
 export default function (ctx: AppContext, app: Express) {
   return app.get(
     '/:linkId',
-    handler(async (req, res) => {
+    observedHandler('short_link', async (req, res) => {
       const linkId = req.params.linkId
       const contentType = req.accepts(['html', 'json'])
       assert(
         typeof linkId === 'string',
         'express guarantees id parameter is a string',
       )
-      const found = await ctx.db.db
+      const found = await ctx.db.observeQuery('resolve_short_link', () =>
-        .selectFrom('link')
+        ctx.db.db
-        .selectAll()
+          .selectFrom('link')
-        .where('id', '=', linkId)
+          .selectAll()
-        .executeTakeFirst()
+          .where('id', '=', linkId)
+          .executeTakeFirst(),
+      )
       if (!found) {
         // potentially broken or mistyped link
         res.setHeader('Cache-Control', 'no-store')

bskylink/src/routes/util.ts

@@ -1,7 +1,11 @@
+import {performance} from 'node:perf_hooks'
+
 import {ErrorRequestHandler, Request, RequestHandler, Response} from 'express'
 
 import {httpLogger} from '../logger.js'
 
+const SLOW_REQUEST_THRESHOLD_MS = 1000
+
 export type Handler = (req: Request, res: Response) => Awaited<void>
 
 export const handler = (runHandler: Handler): RequestHandler => {
@@ -14,6 +18,32 @@ export const handler = (runHandler: Handler): RequestHandler => {
   }
 }
 
+export const observedHandler = (
+  operation: string,
+  runHandler: Handler,
+): RequestHandler => {
+  return handler(async (req, res) => {
+    const startedAt = performance.now()
+    try {
+      await runHandler(req, res)
+    } finally {
+      const durationMs = Math.round(performance.now() - startedAt)
+      if (durationMs >= SLOW_REQUEST_THRESHOLD_MS) {
+        httpLogger.warn(
+          {
+            durationMs,
+            method: req.method,
+            operation,
+            requestTraceId: req.get('x-amzn-trace-id'),
+            statusCode: res.statusCode,
+          },
+          'slow request',
+        )
+      }
+    }
+  })
+}
+
 export const errorHandler: ErrorRequestHandler = (err, _req, res, next) => {
   httpLogger.error({err}, 'request error')
   if (res.headersSent) {