Improve Blink slow-request diagnostics

bskylink/src/db/index.ts

@@ -18,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
@@ -110,21 +112,36 @@ export class Database {
     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 >= 1000) {
+      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',
         )

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,12 +4,12 @@ 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(

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) {