Auditoría de rendimiento de un read-case lento

1. La auditoría de rendimiento como escenario

Cuando un desarrollador dice «el catálogo va lento», suena más o menos como «me duele... bueno, en alguna parte». En cierto modo es verdad, pero tratar algo así solo se puede con un emplasto de llantén sobre el portátil. La auditoría de rendimiento en la capa de persistencia comienza con una idea muy terrenal: no optimizamos un sistema abstracto, sino un read-case concreto que se pueda repetir igual dos veces seguidas y obtener un resultado comparable.

Si intenta «acelerar todo en general», se ahogará instantáneamente en el ruido: diferentes consultas, diferentes parámetros, diferentes cachés, diferentes límites de transacción, calentamiento, tareas en segundo plano, migraciones, consultas automáticas de Hibernate, etc. Por lo tanto, nuestro estilo de hoy es casi aburrido. Fijamos un caso de uso, tomamos una línea base, clasificamos el problema por SQL y estadísticas, seleccionamos una palanca de cambio y preparamos una ejecución repetida correcta. Eso es todo. Sin magia: solo perseverancia y números.

Para retener esta idea, es útil recordar una fórmula simple del día:

Caso de uso → línea base → síntoma SQL → confirmación por estadísticas → EXPLAIN (si es necesario) → un cambio

Y ahora ya podemos hablar del «esquema de auditoría» como un procedimiento real, no como una inspiración.

2. Paso 0: fijar un read-case y sus parámetros

Antes de mirar el SQL, es natural querer «mejorar algo» de inmediato. Pero si no fija el escenario, estará optimizando no el sistema, sino sus propias emociones. En este paso hacemos lo que normalmente se omite: elegir un read-case, determinar sus parámetros (filtros, ordenación, tamaño de página) y decidir dónde está su límite transaccional. Esto convierte un «va lento aleatorio» en un experimento repetible.

En Commerce Persistence Lab, los candidatos convenientes para un read-case de este tipo son, por ejemplo, «la página de productos activos en el panel de administración» o «la lista de pedidos nuevos para procesar». Es importante que sea solo lectura, sin efectos de negocio, y que se ejecute siempre igual: el mismo estado, el mismo pageSize, la misma ordenación.

A menudo sugiero a los estudiantes que etiqueten mentalmente el read-case como un caso de prueba, aunque todavía no estén escribiendo el test:

«CatalogPage: status=ACTIVE, sort=name, pageSize=50»

Esto ayuda a no divagar.

Técnicamente también nos conviene garantizar el mismo entorno: el mismo perfil de logs (sql-trace, stats), el mismo conjunto de datos (preferiblemente no «ayer se sembró, hoy es otro») y preferiblemente la misma lógica de transacción. En nuestro proyecto tenemos open-in-view=false, por lo que el read-case debe vivir en el servicio/query-service (y no ser un recorrido aleatorio de entidades en algún lugar «después de la transacción»).

Un pequeño ejemplo de «fijar la entrada» en código (sin filosofía, solo para mostrar el estilo):

import java.util.UUID;

/**
 * Parámetros de un read-case fijado: así el escenario se vuelve repetible.
 * Idea: misma entrada → mediciones comparables "antes/después".
 */
public record CatalogPageRequest(
    UUID auditRunId, // Identificador de la ejecución: útil para correlacionar logs/métricas
    int pageSize,    // Fijamos el tamaño de página para no "mejorar" el tiempo por casualidad
    String sort      // La ordenación a menudo influye en el plan de consulta y el coste de ORDER BY
) {}

El sentido de este objeto no es que «haga falta un record». El sentido es que el escenario adquiere límites y parámetros, y por lo tanto se puede ejecutar de manera idéntica.

3. Paso 1: línea base (tiempo, estadísticas, SQL)

Una vez elegido el escenario base, dan ganas de meterse directamente con JOIN FETCH o los índices. Pero la línea base es un ancla; sin ella luego no sabrá si ha mejorado o simplemente tuvo suerte con el calentamiento. Aquí es importante reconocer una verdad incómoda: el tiempo por sí solo es un mal diagnóstico, porque no explica la causa. Por eso tomamos la línea base como una «tripleta»: duración mínima, estadísticas y forma SQL.

A nivel de código es útil tener una pequeña utilidad que ejecute el caso de uso, tome el tiempo y lea el mismo conjunto de métricas. Así la línea base, la comprobación de la hipótesis y la ejecución repetida hablan el mismo idioma: elapsedMs, queryCount, prepareStatementCount, entityLoadCount, collectionFetchCount, flushCount.

Ejemplo de una «captura» simple (sin fanatismo, 8-9 líneas para que se vea la idea):

import org.hibernate.stat.Statistics;

/**
 * Captura de métricas clave para comparar ejecuciones "antes/después" no a nivel de sensaciones.
 */
public record AuditSnapshot(
    long elapsedMs,              // Tiempo de ejecución del caso de uso (orientación gruesa pero necesaria)
    long queryCount,             // Cuántas ejecuciones basadas en consultas pasaron por Hibernate
    long prepareStatementCount,  // Cuántos PreparedStatement de JDBC se necesitaron realmente
    long entityLoadCount,        // Cuántas entidades se cargaron (puede revelar sobrecarga)
    long collectionFetchCount,   // Cuántas veces se cargaron colecciones (a menudo signo de N+1)
    long flushCount              // Cuántos flush ocurrieron en "lectura" (sospechoso para un read-case)
) {
    public static AuditSnapshot from(Statistics st, long elapsedMs) {
        // Tomamos el mismo conjunto de contadores para la línea base y la ejecución repetida.
        return new AuditSnapshot(
            elapsedMs,
            st.getQueryExecutionCount(),
            st.getPrepareStatementCount(),
            st.getEntityLoadCount(),
            st.getCollectionFetchCount(),
            st.getFlushCount()
        );
    }
}

Ahora podemos hacer «una ejecución» del escenario. Observe que no se intenta ser JMH: no necesitamos un microbenchmark perfecto, necesitamos un diagnóstico reproducible.

import org.hibernate.stat.Statistics;

public AuditSnapshot run(Statistics st, Runnable useCase) {
    // Es importante restablecer los contadores, de lo contrario las ejecuciones se "acumulan" y mienten.
    st.clear();

    long started = System.nanoTime();
    // Aquí se ejecuta el read-case fijado (la misma entrada).
    useCase.run();
    long elapsedMs = (System.nanoTime() - started) / 1_000_000;

    // Tomamos la instantánea inmediatamente después de la ejecución para que la línea base y el después se comparen por los mismos campos.
    return AuditSnapshot.from(st, elapsedMs);
}

Paralelamente a esto, activa el trace de SQL (como comentamos en la lección 1) para ver la forma de las consultas. Y así obtiene una línea base del tipo: «240 ms, 18 consultas, 120 cargas de entidades, 30 recuperaciones de colecciones, flushCount=0». Eso ya no es «lento», es algo concreto.

4. Paso 2: clasificar el problema por SQL

Cuando abre el log de SQL, el cerebro del desarrollador a menudo se comporta como un gato con un puntero láser: la atención salta de línea en línea, el ojo se engancha en temibles left outer join, la mano se estira para cambiar anotaciones. En este paso hacemos lo contrario: leemos el log de forma estructurada para determinar el tipo de problema. Y solo después elegimos la herramienta de corrección, no al revés.

En la realidad, normalmente nos encontramos con cuatro «argumentos característicos».

El primer argumento: SELECT repetitivos de la misma forma con diferentes parámetros. Se ve como una consulta raíz y luego muchas consultas del tipo select ... from product_details where product_id=? o select ... from order_item where order_id=?. A menudo es un N+1, o una «carga perezosa en bucle», o un @BatchSize pequeño podría ayudar, o se necesita un plan de recuperación para el caso de uso concreto.

El segundo argumento: una sola consulta, pero muy amplia: muchos JOIN, muchas columnas, muchas filas debido a to-many. En los logs parece «una sola consulta», pero en realidad está arrastrando un conjunto de resultados enorme, duplicando datos en filas y haciendo una lectura costosa para una lista simple. Es un caso típico en el que hay que pensar en una proyección/modelo de lectura, no alegrarse de «oh, solo una consulta».

El tercer argumento: en el read-case aparecen de repente UPDATE o flush antes de la consulta. Esto significa que en algún lugar ha mutado una entidad gestionada (quizás incluso accidentalmente: trim(), cambio de campo, modificación de un embeddable, o un setter con efecto secundario). Este escenario rompe la idea de que «la lectura debe ser lectura», y además a menudo estropea el tiempo y crea carga innecesaria en la base de datos.

El cuarto argumento: hay pocas consultas, pero una consulta concreta es pesada: los filtros y las ordenaciones obligan a PostgreSQL a realizar un escaneo costoso, ordenación, join con un plan desfavorable. Es el momento en que el EXPLAIN de la lección 3 se vuelve realmente útil, y la conversación sobre el índice deja de ser abstracta.

Para retener esto en la cabeza, es útil tener una pequeña «tabla de síntomas» — no como dogma, sino como chuleta para el pensamiento:

Observe: en esta tabla no hay ningún punto que diga «la culpa es de Hibernate». Hibernate, por supuesto, puede ser un excelente chivo expiatorio, pero en realidad solo ejecuta fielmente lo que le pedimos (a veces incluso demasiado fielmente).

5. Paso 3: comprobar la hipótesis con las estadísticas

El log de SQL muestra la forma del problema, pero a veces nos engañamos fácilmente a nosotros mismos. Por ejemplo, parece que hay «pocas» consultas, pero en realidad son 60, solo que están mezcladas. O parece que el N+1 ha desaparecido, pero las colecciones todavía se están cargando. En este paso utilizamos las Statistics como un «informe seco de contable»: no discute, solo registra la cantidad de eventos.

La idea es simple: después de haber clasificado el problema visualmente, observa los contadores correspondientes. Si sospechaba de selects secundarios repetitivos, entonces prepareStatementCount suele aumentar rápidamente, y collectionFetchCount y/o entityLoadCount a menudo se disparan junto con él. queryExecutionCount también es útil como señal rápida, pero no sustituye a estos contadores ni al trace SQL en sí. Si sospechaba de un SELECT amplio, puede que haya pocas consultas, pero entityLoadCount será inesperadamente grande (ha cargado un montón de entidades que ni siquiera necesitaba), y a veces verá que debajo del capó se materializaron colecciones.

Si sospechaba que «por alguna razón hubo un flush», entonces flushCount de repente será mayor que cero, aunque «solo estaba leyendo». Este es un contador muy útil precisamente para read-cases, porque saca a la luz rápidamente una «lectura sucia con efectos secundarios».

Mini-ejemplo de «leer los contadores como diagnóstico», sin código largo:

import org.hibernate.stat.Statistics;

public String quickDiagnosis(Statistics st) {
    // Cadena corta para el log/consola: disciplina, porque son "números", no sensaciones.
    return "queryCount=" + st.getQueryExecutionCount()
        + ", prepareStatementCount=" + st.getPrepareStatementCount()
        + ", entityLoadCount=" + st.getEntityLoadCount()
        + ", collectionFetchCount=" + st.getCollectionFetchCount()
        + ", flushCount=" + st.getFlushCount();
}

En el ciclo de auditoría real no se limita a una sola línea, pero incluso un «informe resumido» así ya disciplina: en lugar de «parece que ha mejorado» aparece «las consultas cayeron de 18 a 2, las colecciones de 30 a 0».

6. Paso 4: encontrar la consulta dominante

Un error muy común en la optimización es arreglar lo primero que se ve. Es como tratar un resfriado midiendo la temperatura en el codo: hay números, pero poca utilidad. En la auditoría de rendimiento necesitamos la fuente de coste dominante: la consulta o el patrón de consultas que realmente determina la carga y el tiempo del escenario. Este paso a menudo ahorra la mayor parte del tiempo, porque deja de optimizar «todo un poco» y comienza a optimizar «lo más caro».

Para encontrar el SQL dominante, suele bastar con dos técnicas. La primera es un comentario en la consulta (si utiliza la API de Hibernate a través de Session) para encontrar fácilmente el bloque SQL en el log. La segunda es simplemente disciplina: toma la consulta raíz de su caso de uso y mira qué viene después.

Ejemplo con comentario (ahora es solo diagnóstico, no arquitectura):

import org.hibernate.Session;

// Obtenemos la Session de Hibernate para añadir un comentario SQL y encontrar más fácilmente la consulta en el trace.
Session session = entityManager.unwrap(Session.class);

return session.createQuery("from Product p where p.status = :s", Product.class)
    .setComment("audit: catalog-page") // Este comentario aparecerá en el SQL como /* ... */.
    .setParameter("s", ProductStatus.ACTIVE) // Fijamos el parámetro: el estado es parte del escenario.
    .setMaxResults(50) // Fijamos el tamaño de página: de lo contrario la comparación "antes/después" no es válida.
    .getResultList();

Luego, en el trace SQL, encuentra el bloque con /* audit: catalog-page */ y lo analiza por completo: consulta raíz, selects secundarios, cargas de colecciones, escrituras inesperadas. En este paso es importante no dispersarse: si en el escenario hay 18 consultas, a menudo 15 de ellas serán de la «misma familia», y esa familia es el objetivo principal.

Si la consulta es única pero pesada, entonces la «consulta dominante» es obvia. Entonces pasa a EXPLAIN (como comentamos en la lección anterior) ya para el SQL concreto, no para «la idea de la consulta».

7. Paso 5: elegir una palanca

En esta etapa, el principiante suele sentir el deseo de hacerlo todo a la vez: JOIN FETCH, proyección, índice, @BatchSize, y «además activemos el caché». Es normal, porque al cerebro le gusta la sensación de actividad. Pero la auditoría de ingeniería funciona de otra manera: en un ciclo cambiamos un solo factor, de lo contrario no entenderá qué funcionó (y si funcionó).

Para elegir la palanca, basta con hacerse una pregunta muy práctica: «¿Dónde se genera exactamente el coste?» Si el coste se genera por la cantidad de consultas, la primera palanca suele ser el plan de recuperación o la reducción del modelo de lectura. Si el coste se genera por la anchura de los datos (sobrecarga), la primera palanca suele ser la proyección. Si el coste se genera por el plan de la BD (escaneo, ordenación), entonces tiene sentido hablar de índice o reescribir el filtro/ordenación.

Mostraré algunos mini-ejemplos de «una palanca, un paso», sin profundizar en el tema de fetching (ya se trató antes), pero para que se vea cómo queda en el código.

Si el problema parece un N+1 en to-one/to-many, la primera palanca puede ser un método de lectura separado con EntityGraph:

import org.springframework.data.jpa.repository.EntityGraph;
import org.springframework.data.jpa.repository.JpaRepository;

public interface PurchaseOrderRepository extends JpaRepository<PurchaseOrder, Long> {

    // EntityGraph define el plan de recuperación para un read-case concreto:
    //     traemos customer e items de una sola vez para no sufrir N+1 en relaciones perezosas.
    @EntityGraph(attributePaths = {"customer", "items"})
    java.util.List<PurchaseOrder> findTop20ByStatusOrderByCreatedAtDesc(OrderStatus status);
}

Si el problema es que está arrastrando un grafo de entidades para una lista, la primera palanca suele ser la proyección (reducir el modelo de lectura):

import java.util.List;

// Proyección en lugar de entidades: tomamos solo lo que necesita la lista (id/sku/name).
//     Esto reduce la sobrecarga y a menudo disminuye el coste de materialización.
List<ProductRow> rows = entityManager.createQuery("""
    select new com.example.commerce.catalog.dto.ProductRow(p.id, p.sku, p.name)
    from Product p
    where p.status = :status
    order by p.name
    """, ProductRow.class)
    .setParameter("status", ProductStatus.ACTIVE) // El parámetro fija el escenario (la línea base es comparable).
    .getResultList();

Si el problema es que el read-case de repente «escribe», la palanca no será el fetch ni el índice, sino eliminar la mutación o poner la lectura en modo de solo lectura (para la pureza del experimento):

import java.util.List;

// La sugerencia de solo lectura ayuda a no perder tiempo en dirty checking y reduce el riesgo de flush "en la lectura".
List<Product> products = entityManager.createQuery("""
    select p from Product p where p.status = :status
    """, Product.class)
    .setParameter("status", ProductStatus.ACTIVE) // Los mismos parámetros — el mismo punto de comparación.
    .setHint("org.hibernate.readOnly", true) // Subrayamos que este caso de uso debe ser una lectura limpia.
    .getResultList();

Y si ve que la consulta en sí es pesada (pocas consultas, pero tarda mucho), entonces la palanca es EXPLAIN (y luego, los índices). Aquí es importante: no «optimizamos con índices en el vacío», vinculamos el índice con el SQL concreto:

explain
select p.id, p.sku, p.name
from product p
where p.status = 'ACTIVE'
order by p.name

Estos ejemplos son deliberadamente cortos, porque la idea clave no está en la sintaxis. La idea clave es: primero diagnosticó el tipo de problema, luego eligió una palanca, y solo entonces hizo un cambio.

8. Paso 6: ejecución repetida

Después de un cambio, dan muchas ganas de escribir triunfalmente en el chat del equipo: «He acelerado el catálogo en un 73%». Conténgase. En este paso, nuestra tarea es preparar una ejecución repetida correcta: la misma entrada, el mismo conjunto de datos, el mismo orden de acciones, los mismos perfiles de log activados. Ahora no se trata de declarar la victoria de forma bonita, sino de asegurar que la comparación tenga sentido.

Técnicamente, esto implica varias cosas aburridas pero obligatorias: de nuevo statistics.clear(), el mismo pageSize, la misma ordenación, el mismo estado. Si midió «la lista de pedidos NEW», vuelve a medir NEW, no de repente PAID. Si tomó el trace SQL en un escenario, vuelve a encontrar en el log exactamente ese escenario (y es muy útil si tiene un comentario). Si hizo EXPLAIN, lo hace para la misma plantilla SQL, no para «una aproximadamente parecida».

Y un punto importante para la psique del desarrollador: si después del cambio las métricas no mejoraron, no es un fracaso. Simplemente significa que la hipótesis era débil o que no estaba tratando la fuente de coste dominante. En la auditoría de rendimiento, esto es una parte normal del proceso: «comprobamos → no funcionó → volvemos al paso 4».

9. Errores típicos en la auditoría de un read-case

Al final, quiero recopilar los «rastrillos» más comunes precisamente en torno al procedimiento de auditoría, no en torno a herramientas concretas. Estos errores son desagradables porque puede hacer un EntityGraph correcto o una proyección correcta, y aún así no entender si ayudó, porque el experimento en sí estaba mal planteado. Por lo tanto, este bloque trata sobre disciplina y reproducibilidad, no sobre anotaciones.

Error n.º 1: auditoría sin línea base.
Si no ha fijado el «antes», entonces el «después» se convierte en una obra literaria. Parece más rápido, parece más lento, «en mi máquina era así». Las estadísticas de Hibernate y una medición mínima del tiempo no son para la belleza, sino para que cualquier cambio se pueda comparar con el estado original en las mismas condiciones.

Error n.º 2: cambiar tres cosas a la vez y alegrarse por una.
Es muy tentador reescribir la consulta, añadir JOIN FETCH y aplicar un índice al mismo tiempo. Luego no sabe qué dio el efecto y qué se puede dejar de forma segura. En el ciclo de auditoría educativo cambiamos un factor de forma deliberada para que la relación «cambio → efecto» sea demostrable, no intuitiva.

Error n.º 3: optimizar «la consulta más bonita» en lugar de la más cara.
A veces el desarrollador arregla la consulta raíz porque es grande y da miedo, pero el coste real está en 50 selects secundarios repetitivos. O al revés: lucha heroicamente contra el N+1, pero en realidad una consulta monstruo con un SELECT amplio y una ordenación por un campo no indexado consume el 95% del tiempo. La fuente de coste dominante es más importante que la estética.

Error n.º 4: ignorar el flushCount en un read-case.
Un read-case que de repente hace un flush a menudo significa que está mutando una entidad gestionada dentro de la lectura. Puede ser casi imperceptible en el código, pero muy visible en el SQL. Si no mira el flushCount, puede estar buscando «malos índices» donde el problema es un update accidental.

Error n.º 5: discutir con la base de datos sin EXPLAIN.
A veces ocurre al revés: está seguro de que la consulta «debería volar» porque «es simple», pero PostgreSQL elige un plan en el que hace un seq scan y ordenación en memoria/disco. En ese momento, cualquier conversación de «añadamos una anotación» termina. Se necesita un plan de ejecución, porque explica el coste de un SQL concreto en una BD concreta.