OpenTelemetry en Spring Boot 3: cuando el log dice OK y el trace muestra el problema

Hay una pregunta que me hice muchas veces debuggeando sistemas backend: ¿la request tardó porque la DB fue lenta, porque el downstream nos clavó, o porque algún loop interno disparó 60 queries para traer 60 registros? El log dice duration_ms=340 y status=200. Eso es todo. Empezás a adivinar.

Ese momento de incertidumbre fue el origen de este laboratorio. No para medir overhead de OpenTelemetry, no para comparar Jaeger contra Tempo, sino para responder algo más concreto: ¿qué señales perdés cuando solo tenés logs buenos, y qué aparece cuando sumás un trace?

El repo está en github.com/JuanTorchia/opentelemetry-spring-boot-lab, commit c12ea4e848dc431c8bbd324318399172302fe053, tag editorial-final-diagnosis-comparison-v2.

El setup: un laboratorio que produce evidencia, no benchmarks

El stack es Spring Boot 3.5.7, Java 21, PostgreSQL 16, OpenTelemetry API 1.43.0, OpenTelemetry Java Agent 2.9.0 y Jaeger all-in-one. Todo levanta con Docker Compose. Para reproducirlo:

# Smoke rápido con dataset pequeño (1k tasks)
.\scripts\run-lab.ps1 -Mode smoke -Size small

# Corrida editorial completa (50k tasks, 200 requests, warmup 20, concurrencia 8)
.\scripts\run-lab.ps1 -Mode editorial -Size editorial -Runs 3 -Requests 200 -Warmup 20 -Concurrency 8

El runner levanta Compose, descarga el agente en tools/, empaqueta el jar, seedea Postgres con tablas sintéticas (organizations, users, projects, tasks, comments), ejecuta los escenarios, consulta Jaeger por traceId y regenera los reportes en results/.

Jaeger fue elegido por simplicidad local: una imagen, UI web, API REST para consultar traces por traceId. Tempo también es válido, pero necesita más piezas para una demo editorial local. No es una recomendación de stack productivo.

El dataset editorial tiene 50.000 tasks. El small tiene 1.000. La diferencia importa para que el N+1 produzca fan-out visible y no una diferencia de microsegundos que desaparece en el ruido.

La decisión de instrumentación que más me importa

El pom.xml tiene opentelemetry-api como dependencia de compilación, pero el agente llega en runtime. Eso significa que HTTP server, HTTP client y JDBC se instrumentan automáticamente sin tocar el código de negocio.

Los spans manuales se usan solo para etapas de negocio que el agente no puede inferir:

// LabService.java — span manual para marcar intención de negocio
Span span = tracer.spanBuilder("business.n_plus_one.load_tasks_then_comments").startSpan();
try (var ignored = span.makeCurrent()) {
    // primero trae tasks, luego hace una query por cada una
    List<Map<String, Object>> tasks = jdbcTemplate.queryForList(
        "select t.id, t.title, u.display_name as assignee from tasks t "
        + "join users u on u.id = t.assignee_id order by t.id limit ?",
        limit);
    for (Map<String, Object> task : tasks) {
        Long taskId = ((Number) task.get("id")).longValue();
        // esta query se repite por cada task → fan-out
        Integer comments = jdbcTemplate.queryForObject(
            "select count(*) from comments where task_id = ?",
            Integer.class, taskId);
        // ...
    }
    span.setAttribute("lab.n_plus_one.expected_extra_queries", enriched.size());
} finally {
    span.end();
}

Esa mezcla es más honesta para el post: auto-instrumentación para infraestructura, spans manuales para explicar intención. Si hubiera usado solo spans manuales, el lab requeriría código específico de observabilidad en cada capa. Si hubiera confiado solo en el agente, los spans de negocio serían invisibles.

El logback-spring.xml inyecta traceId y spanId en cada línea de log:

<!-- logback-spring.xml -->
<pattern>%d{yyyy-MM-dd'T'HH:mm:ss.SSSXXX} %-5level traceId=%X{trace_id:-none} spanId=%X{span_id:-none} %logger{36} - %msg%n</pattern>

Eso es lo que conecta ambos mundos. Un log con traceId te permite saltar directo al trace en Jaeger. Sin eso, logs y traces son islas.

La matriz que resume el diagnóstico

Esta tabla no intenta coronar una herramienta. Resume qué señales quedan disponibles para diagnosticar. El dato fuerte no es que un número sea universal: es que el N+1 deja una forma muy distinta al caso optimizado, y esa forma no aparece en un log plano sin activar SQL debug.

Lo que revelan los seis escenarios

El laboratorio tiene seis endpoints: baseline, n-plus-one, optimized, downstream-slow, mixed y partial-error. Cada uno produce señales diferentes que el runner consolida en results/comparison.md y results/diagnosis-comparison.md.

El hallazgo que más me interesa defender:

N+1 vs optimized: ambos devuelven el mismo shape de respuesta. El log de ambos dice status=200. La diferencia está en el trace: n-plus-one genera un promedio de 63,38 spans por request en la corrida editorial; optimized genera 3,04. Eso no es un claim de performance universal, es una señal diagnóstica. Con solo los logs, sin activar SQL debug, la diferencia es ambigua. Con el trace, el fan-out DB es visible sin configuración extra.

Downstream-slow: el p95 está en 374 ms, muy cerca del delay configurado de 300 ms. Los logs muestran la duración total y el traceId. Lo que no muestran es dónde se fue ese tiempo: ¿fue DB? ¿fue el downstream? ¿fue transformación en memoria? El trace lo separa: el span HTTP client del downstream domina la jerarquía. La DB local aparece como span secundario de duración baja.

Mixed: aquí es donde los logs planos fallan más. Tres etapas compiten (DB, downstream, transformación) y ninguna es dominante de forma obvia. El p95 llega a 395 ms. El trace muestra la distribución temporal por etapa. El log solo dice que tardó.

Partial-error: el endpoint responde con HTTP 206 (partial content). El log registra el traceId, el status y el tipo de error. El trace va más lejos: el span del downstream está marcado con error, anidado bajo una request que técnicamente respondió. Logs y trace no se reemplazan acá, se complementan. El log avisa y permite correlacionar. El trace ubica el error en la jerarquía causal.

La captura que cambió el diagnóstico

En Jaeger, n-plus-one no se ve como una request apenas más lenta. Se ve como una request con fan-out DB: muchos spans repetidos bajo una misma operación de negocio.

El caso optimizado, en cambio, mantiene una forma compacta. No necesito mirar el código para sospechar que el problema del caso anterior no era "Postgres lento" en abstracto, sino el shape de queries.

El caso de error parcial también vale por otra razón: la request puede responder, pero el span del downstream queda marcado con error. Ese matiz es justo donde logs y traces se complementan: el log avisa, el trace ubica.

El límite honesto de las métricas

Los campos *_vs_root_pct en results/diagnosis-comparison.md son porcentajes acumulados de duración de spans exportados por Jaeger. Pueden superar el 100% cuando hay spans anidados, pares cliente/servidor o solapamiento. El campo duration_denominator_type indica qué se usó como denominador: root_span, http_request_span o largest_observed_span si la traza quedó ambigua.

No son overhead. No son distribución exacta del tiempo real de la request. Son señales diagnósticas acumuladas. Usarlas como si fueran porcentajes de CPU sería un error de interpretación que este lab no intenta fomentar.

De la misma forma, diagnosis_confidence_* es una clasificación editorial codificada en ScenarioDiagnosis.java, no una métrica medida automáticamente. Para N+1, diagnosisConfidenceLogs es low y diagnosisConfidenceTrace es high. Eso refleja que sin SQL debug, el log es ambiguo. No es un benchmark universal de qué herramienta es mejor.

Mi postura: qué acepto y qué no compro

Acepto que OpenTelemetry con el Java Agent es una forma razonable de agregar visibilidad estructural a una app Spring Boot 3 sin ensuciar el código de negocio. La auto-instrumentación de JDBC y HTTP client funciona bien para escenarios comunes.

No compro la narrativa de que los traces reemplazan los logs. El RequestCompletionLoggingFilter del lab es un filtro Servlet que registra cada request completada con escenario, método, path, status y duración. Esos logs son operativamente útiles aunque Jaeger no esté disponible. El traceId en el log es el puente, no el reemplazo.

Tampoco compro que Jaeger sea la única opción válida. Se eligió porque levanta con una imagen y tiene UI web lista. Tempo, Zipkin o cualquier backend compatible con OTLP resolverían el mismo problema en este contexto.

El trade-off honesto es este: la auto-instrumentación reduce trabajo accidental pero agrega un agente en el classpath que exporta datos en background. En un laboratorio local eso es trivial. En producción, el overhead del agente depende de la carga, la configuración del exporter y el sampling. Este lab no mide eso, y sería engañoso afirmar que sí.

Qué hacer con esto

Si ya tenés logs estructurados en producción con traceId y spanId, el paso siguiente no es reemplazar nada. Es agregar el backend de traces y conectar ambos mundos. El lab muestra que la auto-instrumentación de Spring Boot 3 con el Java Agent es suficiente para los escenarios comunes, y que los spans manuales tienen sentido solo cuando querés nombrar intención de negocio que el agente no puede inferir.

Si estás evaluando si vale la pena el esfuerzo: el caso donde más claramente lo justifica no es el baseline sano. Es el escenario mixto o el N+1, donde los logs te dan un número y el trace te da una forma. La diferencia entre adivinar y diagnosticar.

Después de este lab, mi regla queda así: logs para saber qué pasó; traces para entender cómo pasó. Si el log plano te da solo duración total, todavía no tenés una explicación. Tenés una pista.