From cc9ebd4c3ca97199d832ac22d1bd400554ee7867 Mon Sep 17 00:00:00 2001 From: Austin McKinley Date: Wed, 19 Aug 2026 11:43:23 -0700 Subject: [PATCH] Improve Blink slow-request diagnostics --- bskylink/src/db/index.ts | 19 ++++++++++++++++++- bskylink/src/routes/redirect.ts | 4 ++-- bskylink/src/routes/shortLink.ts | 4 ++-- bskylink/src/routes/util.ts | 30 ++++++++++++++++++++++++++++++ 4 files changed, 52 insertions(+), 5 deletions(-) diff --git a/bskylink/src/db/index.ts b/bskylink/src/db/index.ts index 97f07857a9..1e9e644561 100644 --- a/bskylink/src/db/index.ts +++ b/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', ) diff --git a/bskylink/src/routes/redirect.ts b/bskylink/src/routes/redirect.ts index a49f9c401e..ed1e32f9bc 100644 --- a/bskylink/src/routes/redirect.ts +++ b/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', diff --git a/bskylink/src/routes/shortLink.ts b/bskylink/src/routes/shortLink.ts index 35f48f99ae..f78228fef2 100644 --- a/bskylink/src/routes/shortLink.ts +++ b/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( diff --git a/bskylink/src/routes/util.ts b/bskylink/src/routes/util.ts index bcac64b01d..b8ac18071a 100644 --- a/bskylink/src/routes/util.ts +++ b/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 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) {