perf: add timing logs to api routes, tiles, search, embeddings

Author: onmax

server/middleware/timing.ts

@@ -0,0 +1,9 @@
+import { consola } from 'consola'
+
+export default defineEventHandler((event) => {
+  const start = performance.now()
+  event.node.res.on('finish', () => {
+    const ms = (performance.now() - start).toFixed(0)
+    consola.info(`[perf] ${event.node.req.method} ${event.path} ${ms}ms`)
+  })
+})

server/utils/db-functions.ts

@@ -1,5 +1,6 @@
 import { Buffer } from 'node:buffer'
 
+import { consola } from 'consola'
 import { sql } from 'drizzle-orm'
 
 /**
@@ -8,9 +9,9 @@ import { sql } from 'drizzle-orm'
 export async function getTileMvt(z: number, x: number, y: number): Promise<Buffer> {
   const db = useDrizzle()
 
-  const result = await db.execute(
-    sql`SELECT get_tile_mvt(${z}, ${x}, ${y})`,
-  )
+  const start = performance.now()
+  const result = await db.execute(sql`SELECT get_tile_mvt(${z}, ${x}, ${y})`)
+  consola.info(`[perf] getTileMvt z=${z} x=${x} y=${y} ${(performance.now() - start).toFixed(0)}ms`)
 
   const row = Array.isArray(result) ? result[0] : (result as { rows?: unknown[] })?.rows?.[0]
   const mvtData: unknown = (row as { get_tile_mvt?: unknown })?.get_tile_mvt

server/utils/embeddings.ts

@@ -1,16 +1,22 @@
 import { createOpenAI } from '@ai-sdk/openai'
 import { embed } from 'ai'
+import { consola } from 'consola'
 
 export async function generateEmbeddingCached(value: string): Promise<number[]> {
   const normalizedValue = value.trim().toLowerCase()
   const cacheKey = `embedding:${normalizedValue}`
 
   const cached = await kv.get(cacheKey) as number[] | null
-  if (cached)
+  if (cached) {
+    consola.info('[perf] embedding: cache hit')
     return cached
+  }
 
+  consola.info('[perf] embedding: cache miss, calling OpenAI')
+  const start = performance.now()
   const model = createOpenAI({ apiKey: useRuntimeConfig().openaiApiKey }).embedding('text-embedding-3-small')
   const { embedding } = await embed({ model, value })
+  consola.info(`[perf] embedding: OpenAI ${(performance.now() - start).toFixed(0)}ms`)
 
   await kv.set(cacheKey, embedding as unknown as string)
 

server/utils/search.ts

@@ -106,9 +106,12 @@ export async function searchLocationsBySimilarCategories(
 ): Promise<SearchLocationResponse[]> {
   try {
     const db = useDrizzle()
+    const embStart = performance.now()
     const queryEmbedding = await generateEmbeddingCached(query)
+    logger.info(`[perf] generateEmbedding ${(performance.now() - embStart).toFixed(0)}ms`)
     const { origin, maxDistanceMeters, categories: requiredCategories, fetchLimit, page, limit: pageLimit } = options
 
+    const vecStart = performance.now()
     const vectorMatches = await db.execute(sql`
       SELECT ${tables.categories.id} as id
       FROM ${tables.categories}
@@ -119,6 +122,7 @@ export async function searchLocationsBySimilarCategories(
     `)
 
     let categoryIds = ((vectorMatches as any).rows || []).map((row: any) => row.id as string)
+    logger.info(`[perf] vectorSearch found=${categoryIds.length} ${(performance.now() - vecStart).toFixed(0)}ms`)
 
     if (categoryIds.length === 0)
       categoryIds = pickFallbackCategories(query)
@@ -198,7 +202,10 @@ export async function searchLocationsByCategories(
     ? baseQuery.orderBy(selectFields.distanceMeters)
     : baseQuery.orderBy(sql`${tables.locations.rating} DESC NULLS LAST`)
 
-  return await queryBuilder.limit(limit).offset(offset) as SearchLocationResponse[]
+  const catStart = performance.now()
+  const rows = await queryBuilder.limit(limit).offset(offset) as SearchLocationResponse[]
+  logger.info(`[perf] searchLocationsByCategories count=${rows.length} ${(performance.now() - catStart).toFixed(0)}ms`)
+  return rows
 }
 
 // PostgreSQL's built-in FTS is faster than vector search for exact/prefix matches
@@ -273,5 +280,8 @@ export async function searchLocationsByText(
     ? baseQuery.orderBy(selectFields.distanceMeters)
     : baseQuery
 
-  return await queryBuilder.limit(limit).offset(offset) as SearchLocationResponse[]
+  const txtStart = performance.now()
+  const rows = await queryBuilder.limit(limit).offset(offset) as SearchLocationResponse[]
+  logger.info(`[perf] searchLocationsByText count=${rows.length} ${(performance.now() - txtStart).toFixed(0)}ms`)
+  return rows
 }