Prisma Query Logging y PostgreSQL: dónde termina el ORM y empieza la base

#spanish #espanol #typescript #postgres

Activaste log: ['query'] en el cliente de Prisma, viste la consola llenarse de SELECTs con sus parámetros, y ahí quedó la investigación. El endpoint sigue lento. El log te dice qué SQL se ejecutó, pero no te dice si ese SQL usó un índice, si esperó un lock, o si el problema es la query en sí o la conexión que la ejecuta. Esa distancia entre "veo la query" y "entiendo por qué tarda" es el tema de este post.

Mi tesis es simple y no es nueva, pero acá casi nadie la aplica con disciplina: el query logging de Prisma sirve para encontrar patrones — queries N+1, SQL inesperado, parámetros raros — pero no reemplaza instrumentar PostgreSQL cuando el problema es de rendimiento real. Son dos capas distintas, resuelven preguntas distintas, y mezclarlas es la razón por la que tanta gente mira logs durante media hora sin llegar a ninguna conclusión.

Prisma query logging PostgreSQL: qué resuelve el log del ORM

La documentación oficial de Prisma sobre logging es clara sobre el alcance: el sistema de logs te permite suscribirte a eventos query, info, warn y error del cliente, y cada evento de tipo query incluye el SQL generado, los parámetros y la duración total de esa llamada. Eso es todo lo que promete. No dice nada de planes de ejecución, no dice nada de locks, no dice nada de qué pasa dentro de PostgreSQL cuando recibe esa query.

Configurarlo es así:

// prisma-client.ts — logging basico con niveles
import { PrismaClient } from '@prisma/client'

const prisma = new PrismaClient({
  log: [
    { level: 'query', emit: 'event' },
    { level: 'warn', emit: 'stdout' },
    { level: 'error', emit: 'stdout' },
  ],
})

prisma.$on('query', (evento) => {
  console.log('SQL:', evento.query)
  console.log('Parametros:', evento.params)
  console.log('Duracion (ms):', evento.duration)
})

Con esto ya tenés lo que la doc promete: SQL exacto, parámetros, duración total del round trip. Es suficiente para responder preguntas de tipo ORM: ¿Prisma está generando un JOIN que no esperabas? ¿Este findMany con include anidado dispara 40 queries en vez de una? ¿Un middleware está ejecutando algo dos veces? Ese tipo de preguntas las resuelve el log solo, sin tocar la base.

Lo que NO resuelve — y la doc tampoco lo promete, hay que ser justo con la fuente — es por qué una query puntual tarda 800ms en vez de 8ms. Eso vive del otro lado.

Dónde se equivoca la gente: usar el log como si fuera un profiler de base

La receta común es: activo el log, veo que una query tarda mucho, la copio, la corro a mano en el cliente SQL, ahí anda "rápido" porque la tabla está cacheada en el plan o porque el volumen de datos en ese momento es distinto, y cierro el ticket diciendo "se resolvió solo". Tres meses después vuelve a pasar. Lo vi pasar más de una vez en tickets que se reabren solos: nadie mintió, nadie fue negligente, simplemente se confundió la capa.

El costo oculto es que el número de duración que reporta Prisma incluye el viaje completo: serialización de parámetros, tiempo de red hacia PostgreSQL, tiempo de ejecución en la base, y deserialización del resultado en el cliente TypeScript. Si el pool de conexiones está saturado o hay latencia de red, ese número sube sin que la query en sí tenga ningún problema. El log te da un total, no un desglose.

Contraejemplo típico: una query que en el log muestra 300ms de duración puede ser una query de 2ms en PostgreSQL que esperó 298ms para conseguir una conexión del pool. Si el diagnóstico se queda en "esta query es lenta, hay que optimizarla", el problema real — configuración de pool, número de conexiones concurrentes, timeout mal seteado — sigue sin tocarse.

flowchart LR
  A[Request llega] --> B[Prisma pide conexion al pool]
  B --> C{Pool disponible?}
  C -->|no, espera| D[Tiempo de espera se suma al log]
  C -->|si| E[PostgreSQL ejecuta la query]
  E --> F[Prisma deserializa resultado]
  D --> E
  F --> G[Log reporta duracion total]

El diagrama muestra por qué el número del log mezcla cosas que conviene separar antes de tocar código.

Checklist de decisión: cuándo alcanza el log y cuándo mirar PostgreSQL

Esto es lo que uso como criterio de corte antes de invertir tiempo en cualquiera de los dos lados:

Alcanza con el log de Prisma cuando:

La sospecha es sobre qué SQL genera el ORM (queries N+1, includes que explotan, selects innecesarios).
El problema aparece siempre, con cualquier volumen de datos, en cualquier ambiente.
Podés reproducirlo con una llamada aislada y ver el SQL exacto en la consola.
La pregunta es "¿esto hace lo que yo creo que hace?" y no "¿esto es rápido?".

Hay que mirar PostgreSQL directamente cuando:

Una query específica tarda distinto según el momento del día o el volumen de datos.
El log muestra duraciones altas pero el SQL, corrido a mano, "anda bien" — ahí el problema no es la query.
Sospechás de locks, contención, o queries concurrentes pisándose.
Necesitás saber si un índice se está usando o no — eso lo dice EXPLAIN ANALYZE, no el log del ORM.

Herramientas de PostgreSQL que entran en esta segunda categoría: EXPLAIN (ANALYZE, BUFFERS) sobre la query exacta que capturaste en el log, la extensión pg_stat_statements para ver acumulados reales de ejecución en el tiempo, y pg_stat_activity para ver qué está corriendo ahora mismo y si hay algo bloqueado. Ninguna de estas la reemplaza Prisma, y está bien que sea así — no es su trabajo.

Qué mirar primero, en orden: log de Prisma para confirmar el SQL exacto → correrlo con EXPLAIN ANALYZE para ver el plan real → si el plan es razonable pero el log sigue mostrando tiempos altos, sospechar del pool de conexiones antes que de la query.

Lo incómodo de este criterio es que obliga a soltar la primera hipótesis. Cuesta más aceptar "no es la query, es el pool" que quedarte reescribiendo el SELECT una vez más, porque tocar la query da la sensación de estar avanzando aunque no cambie nada. Este mismo criterio de "separar la capa que generó el problema de la capa donde se manifiesta" es el mismo tipo de pregunta que me hago cuando evalúo si vale la pena sumar una dependencia nueva al proyecto — ver cómo evaluar una librería antes de meterla en producción — o cuando el compilador de TypeScript marca un error que en realidad viene de un tipo mal definido más arriba, como escribí en strict null checks en producción. No es la misma herramienta ni el mismo bug, pero la pregunta de fondo —¿dónde nació esto realmente?— se repite en cualquier capa del stack.

Límites: lo que esta evidencia no permite concluir

Ni la documentación de Prisma ni este post dan una cifra de cuánto overhead agrega el logging en sí, ni un número de "a partir de tantas queries por segundo conviene instrumentar la base". Cualquier claim de ese tipo necesitaría un experimento reproducible con carga controlada, y no lo tengo — y prefiero no inventarlo.

Tampoco se puede concluir, solo con el log de Prisma, si un índice falta, si una tabla necesita particionado, o si el problema es de diseño de esquema. Esas conclusiones requieren mirar el plan de ejecución real de PostgreSQL, no el reporte del cliente.

Y una aclaración honesta sobre la fuente: la doc de Prisma no compara su logging contra herramientas de observabilidad de base de datos ni sugiere que sea un sustituto. El límite que planteo en este post es mío, no algo que la doc contradiga ni respalde explícitamente — es una lectura de lo que el log promete versus lo que no promete.

Mi postura y el próximo paso

Uso el log de Prisma para todo lo que es forma del SQL: confirmar que el ORM generó lo que esperaba, cazar N+1 antes de que lleguen a un ambiente con datos reales, revisar que un include no esté trayendo relaciones de más. Para eso es rápido y no necesita nada extra.

En el momento en que la pregunta cambia de "¿qué SQL es?" a "¿por qué tarda?", cierro la consola del log y abro EXPLAIN ANALYZE. Mezclar las dos preguntas en la misma herramienta es lo que hace que la gente se quede mirando logs sin avanzar, y es la trampa más fácil de caer porque las dos preguntas usan el mismo texto de SQL en pantalla.

Si estás evaluando meter observabilidad más seria al stack — logs estructurados, métricas de pool, tracing — vale la misma lógica que aplico cuando incorporo cualquier pieza nueva al backend: primero entender qué capa resuelve, después decidir si hace falta. Ese mismo filtro lo usé evaluando un modelo externo en el pipeline de código — DeepSeek API en TypeScript — antes de sumarlo: separar lo que la herramienta promete de lo que uno quiere que prometa evita bastante frustración después.

Si tenés que elegir una sola cosa para hoy: la próxima vez que el log te muestre una query "lenta", antes de tocar el SQL, corré esa misma query con EXPLAIN ANALYZE aislada. Si el plan sale limpio y rápido, el problema no está en la query — está en algo que el log nunca te iba a mostrar.

FAQ

¿El log de Prisma muestra el plan de ejecución de la query?
No. Muestra el SQL generado, los parámetros y la duración total del round trip. El plan de ejecución hay que pedirlo aparte con EXPLAIN ANALYZE directamente en PostgreSQL.

¿Activar log: ['query'] en producción tiene costo?
Agrega overhead de serialización y logging por cada query, sobre todo si el nivel emitido es stdout en vez de event con un handler liviano. La doc oficial no da una cifra exacta de ese costo, así que conviene medirlo en el ambiente propio antes de asumir que es despreciable.

¿Puedo usar el log de Prisma para detectar queries N+1?
Sí, es uno de los usos más directos: si un findMany con relaciones dispara decenas de queries individuales en el log, ahí está el N+1. Es justamente el tipo de pregunta que el log resuelve bien porque es sobre forma de SQL, no sobre rendimiento de la base.

¿pg_stat_statements reemplaza al logging de Prisma?
No lo reemplaza, lo complementa. pg_stat_statements acumula estadísticas reales de ejecución dentro de PostgreSQL a lo largo del tiempo; el log de Prisma te da la vista puntual de cada llamada desde el cliente. Sirven para preguntas distintas.

¿Por qué una query que el log marca como lenta corre rápido si la ejecuto a mano?
Porque el número del log incluye tiempo de red y espera de conexión del pool, no solo ejecución en la base. Si corrés la query aislada en un cliente SQL, te salteás esa espera y ves solo el tiempo real de PostgreSQL.

¿Sirve el logging de Prisma para diagnosticar locks o contención?
No directamente. Para eso hay que mirar pg_stat_activity en PostgreSQL, que muestra qué sesiones están corriendo y si alguna está bloqueada esperando a otra. El log de Prisma no tiene visibilidad de eso.

Fuente original: Prisma logging docs

Este artículo fue publicado originalmente en juanchi.dev