From cc26e5a09036b46810df76f75a5edaf5a03697c7 Mon Sep 17 00:00:00 2001 From: Austin McKinley <54160+amckinley@users.noreply.github.com> Date: Wed, 19 Aug 2026 12:38:48 -0700 Subject: [PATCH] Log slow Blink database operations (#11505) --- bskylink/src/cache/safelinkClient.ts | 16 ++++++---- bskylink/src/db/index.ts | 48 ++++++++++++++++++++++++++++ bskylink/src/routes/redirect.ts | 4 +-- bskylink/src/routes/shortLink.ts | 16 ++++++---- bskylink/src/routes/util.ts | 30 +++++++++++++++++ 5 files changed, 98 insertions(+), 16 deletions(-) diff --git a/bskylink/src/cache/safelinkClient.ts b/bskylink/src/cache/safelinkClient.ts index d0f16e72c1..c48b49ddc4 100644 --- a/bskylink/src/cache/safelinkClient.ts +++ b/bskylink/src/cache/safelinkClient.ts @@ -98,13 +98,15 @@ export class SafelinkClient { url: string, pattern: ToolsOzoneSafelinkDefs.PatternType, ): Promise { - 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) { diff --git a/bskylink/src/db/index.ts b/bskylink/src/db/index.ts index d335f80146..1e9e644561 100644 --- a/bskylink/src/db/index.ts +++ b/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( + operation: string, + query: () => Promise, + ): Promise { + 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') } 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 276aae1ca1..f78228fef2 100644 --- a/bskylink/src/routes/shortLink.ts +++ b/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 - .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') 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) {