En el Módulo 5 aprendiste a medir. El método USE, vmstat, iostat, free, sar y pidstat te dicen cuánto: la CPU está al 80 %, el disco tiene 22 ms de latencia de escritura, quedan 300 MB de memoria disponible. Con eso resolviste el incidente de la web lenta por las mañanas, porque los contadores señalaban a la E/S y la E/S tenía un culpable identificable.

Pero hay una clase de problema para la que los contadores no sirven: cuando todos están en verde y el servicio va mal de todas formas. La CPU ociosa, el disco tranquilo, la memoria de sobra, y la aplicación tardando diez veces más de lo que debería. En ese punto la pregunta deja de ser cuánto y pasa a ser qué está haciendo exactamente este proceso, y para responderla hacen falta herramientas que no midan agregados, sino que observen eventos individuales.

Esta lección te da tres, en orden creciente de sofisticación y decreciente de coste: strace para ver las llamadas al sistema una por una, perf para perfilar dónde se consumen los ciclos de verdad, y eBPF para instrumentar el kernel en producción sin penalización apreciable. Y te vas a encontrar de frente con una consecuencia de tu propio trabajo del Módulo 6.

Contenido

  1. Cuándo los contadores no bastan
  2. strace: las llamadas al sistema una por una
  3. El obstáculo que tú mismo pusiste: ptrace_scope
  4. ltrace y el nivel de las bibliotecas
  5. perf: perfilado por muestreo
  6. Gráficos de llama
  7. eBPF: instrumentar el kernel en producción
  8. Las herramientas de bpfcc y qué pregunta responde cada una
  9. Tabla de decisión: qué herramienta para qué pregunta
  10. Caso Tramontana: de 400 ms a 40 ms

Cuándo los contadores no bastan

La diferencia entre las dos familias de herramientas es la unidad de observación:

Contadores (M5) Trazado y perfilado (esta lección)
Qué observan Agregados y medias en un intervalo Eventos individuales
Ejemplos vmstat, iostat, free, sar strace, perf, bpftrace
Coste Despreciable; se dejan corriendo siempre De despreciable a prohibitivo
Responden a Cuánto, dónde Qué, por qué
Punto ciego Lo que no está en la media Necesitan una hipótesis previa

Ese último punto es importante y ordena toda la lección: las herramientas de trazado no sustituyen a los contadores, los continúan. Se usan cuando ya tienes una hipótesis que quieres confirmar o refutar. Lanzar strace sobre un proceso sin saber qué buscas produce cien mil líneas ilegibles y ralentiza el servicio.

La metodología, entonces, tiene tres pasos y el orden no es negociable:

  1. Síntoma medido. «La aplicación tarda 400 ms en responder; la línea base dice 40 ms.» No «va lenta».
  2. Hipótesis descartadas con contadores. ¿CPU? ¿Disco? ¿Memoria? ¿Red? Es gratis y elimina la mayoría de los casos.
  3. Medición dirigida con la herramienta adecuada. Una hipótesis concreta, una herramienta, una respuesta.

strace: las llamadas al sistema una por una

Recuerda las capas del Módulo 1: hardware → kernel → llamadas al sistema → shell y bibliotecas → aplicaciones. Una llamada al sistema es la única forma que tiene un programa de pedirle algo al kernel: abrir un fichero, leer de un socket, reservar memoria, esperar. Todo lo que un proceso hace de cara al exterior pasa por ahí.

strace intercepta esas llamadas y las imprime. Es literalmente ver la conversación entre el programa y el kernel.

$ sudo apt install strace

# Lo mas simple: trazar un comando desde el principio
$ strace -f ls /opt/tramontana 2>&1 | head -12
execve("/usr/bin/ls", ["ls", "/opt/tramontana"], 0x7ffd1c4a2b18 /* 24 vars */) = 0
brk(NULL)                               = 0x5f8c1a2f4000
access("/etc/ld.so.preload", R_OK)      = -1 ENOENT (No such file or directory)
openat(AT_FDCWD, "/etc/ld.so.cache", O_RDONLY|O_CLOEXEC) = 3
newfstatat(3, {st_mode=S_IFREG|0644, st_size=71234, ...}, 0) = 0
mmap(NULL, 71234, PROT_READ, MAP_PRIVATE, 3, 0) = 0x7f2a1c4b0000
close(3)                                = 0
openat(AT_FDCWD, "/lib/x86_64-linux-gnu/libselinux.so.1", O_RDONLY|O_CLOEXEC) = 3
...
openat(AT_FDCWD, "/opt/tramontana", O_RDONLY|O_NONBLOCK|O_CLOEXEC|O_DIRECTORY) = 3
getdents64(3, 0x5f8c1a2f5b40 /* 5 entries */, 32768) = 160
write(1, "app  HISTORIAL  releases  shared\n", 33) = 33

Cada línea tiene la misma estructura: nombre de la llamada, argumentos entre paréntesis, y el valor devuelto tras el =. Si el valor es negativo, aparece el nombre simbólico del error (ENOENT, EACCES, EAGAIN) y su descripción. Esa tercera parte es donde suele estar la respuesta.

Fíjate en la línea de /etc/ld.so.preload: devuelve ENOENT. No es un error, es normal —ese fichero rara vez existe—, y esto ilustra algo que hay que interiorizar: strace muestra muchísimos errores esperados. Saber cuáles son normales es la mitad del oficio.

Las opciones que se usan de verdad

Opción Qué hace Cuándo
-f Sigue los procesos e hilos hijos Casi siempre; sin ella pierdes la mitad
-p PID Se adjunta a un proceso ya en marcha Diagnóstico en producción
-e trace=<lista> Solo las llamadas indicadas Imprescindible para no ahogarte
-c Solo el resumen estadístico al final El primer paso, casi siempre
-T Añade el tiempo que tardó cada llamada Cuando buscas latencia
-tt Marca de tiempo con microsegundos Correlacionar con logs
-s N Longitud máxima de las cadenas (por defecto 32) -s 200 para ver rutas y datos completos
-o fichero Escribe a fichero en lugar de stderr Sesiones largas
-y Muestra la ruta de cada descriptor de fichero Muy útil con sockets y ficheros
-k Muestra la pila de llamadas Cuando necesitas saber quién llamó

Los grupos de -e trace= ahorran memorizar nombres:

$ strace -c -e trace=%file ls /opt/tramontana >/dev/null
Grupo Incluye
%file Todas las que reciben un nombre de fichero (openat, stat, unlink…)
%desc Operaciones sobre descriptores (read, write, close, poll…)
%network socket, connect, accept, send, recv…
%process fork, execve, wait, exit…
%memory mmap, brk, munmap…
%signal Señales

El resumen estadístico: por dónde empezar siempre

$ sudo strace -f -c -p 4318
strace: Process 4318 attached with 4 threads
^Cstrace: Process 4318 detached
% time     seconds  usecs/call     calls    errors syscall
------ ----------- ----------- --------- --------- ----------------
 89.14    2.417882        8062       300           connect
  6.02    0.163291         272       600           sendto
  3.11    0.084372         140       602           recvfrom
  0.98    0.026573          44       604           epoll_wait
  0.41    0.011118          18       617           futex
  0.34    0.009229          15       602        12 read
------ ----------- ----------- --------- --------- ----------------
100.00    2.712465                  3325        12 total

Esto es el primer paso de cualquier diagnóstico con strace, y por una razón práctica: cabe en una pantalla y dice inmediatamente dónde se va el tiempo. Aquí el 89 % del tiempo está en connect, con 300 llamadas a 8 ms cada una. Eso es una pista enorme: el proceso está abriendo conexiones nuevas constantemente y cada una cuesta 8 milisegundos.

Las columnas: % time es la proporción del tiempo total dentro de llamadas al sistema (no del tiempo total del proceso: si el programa quema CPU en su propio código, aquí no se ve); usecs/call es la media por llamada; errors cuenta los retornos con error.

El caso clásico: «no encuentra su fichero de configuración»

El uso más rentable de strace, y el que hay que tener memorizado. Un programa falla diciendo que no encuentra un fichero, y tú estás seguro de que el fichero existe:

$ sudo -u svc-tramontana /opt/tramontana/app/tramontana --config /etc/tramontana/app.conf
error: no se pudo cargar la configuracion

$ ls -l /etc/tramontana/app.conf
-rw-r----- 1 root tramontana 341 ago 18 12:04 /etc/tramontana/app.conf

El fichero está. La pregunta es qué está buscando el programa realmente:

$ sudo -u svc-tramontana strace -f -e trace=openat,newfstatat -s 200 \
    /opt/tramontana/app/tramontana --config /etc/tramontana/app.conf 2>&1 \
    | grep -E 'ENOENT|EACCES' | grep -v 'lib\|locale\|gconv'
openat(AT_FDCWD, "/etc/tramontana/app.conf.local", O_RDONLY) = -1 ENOENT (No such file or directory)
openat(AT_FDCWD, "/etc/tramontana/secretos/db_password", O_RDONLY) = -1 EACCES (Permission denied)

Ahí está, y no era lo que parecía. El fichero de configuración se abre bien; el .local que no existe es opcional. El error real es EACCES sobre el fichero de la credencial: el programa lo busca en /etc/tramontana/secretos/db_password, pero desde 06-05 la credencial la entrega systemd en $CREDENTIALS_DIRECTORY, y ejecutado a mano esa variable no existe. El programa funciona correctamente bajo systemd y falla ejecutado directamente.

Ese es el patrón general y por eso vale la pena memorizarlo:

# La linea que resuelve la mitad de los "no encuentra el fichero"
$ strace -f -e trace=%file <comando> 2>&1 | grep -E 'ENOENT|EACCES'

El coste, dicho claramente

strace funciona con ptrace, que detiene el proceso en cada llamada al sistema, transfiere el control al trazador, y lo reanuda. Eso significa dos cambios de contexto por llamada.

Carga del proceso Ralentización típica con strace
Intensivo en CPU, pocas llamadas ×1,2 – ×2
Mixto ×5 – ×20
Intensivo en E/S, muchas llamadas ×50 – ×100

Un proceso que hace 50.000 llamadas por segundo puede volverse cien veces más lento. Las consecuencias operativas:

  • Nunca strace sin -e trace= ni -c sobre un proceso de producción con carga. Si tienes que hacerlo, hazlo con un límite de tiempo: timeout 5 strace -f -c -p PID.
  • Un proceso al que estás adjuntado y matas strace con SIGKILL puede quedar detenido. Sal siempre con Ctrl+C, que hace un detach limpio.
  • Para producción, perf trace y eBPF hacen lo mismo con un coste una o dos órdenes de magnitud menor. Es la razón de que existan.

El obstáculo que tú mismo pusiste: ptrace_scope

Intenta adjuntarte al proceso de la aplicación como tu usuario:

$ pgrep -u svc-tramontana tramontana
4318
$ strace -p 4318
strace: attach: ptrace(PTRACE_SEIZE, 4318): Operation not permitted

No es un fallo. Es el kernel.yama.ptrace_scope = 1 que pusiste en /etc/sysctl.d/60-endurecimiento.conf en 06-06, y que aquel día venía con un aviso escrito al lado precisamente por esto:

$ sysctl kernel.yama.ptrace_scope
kernel.yama.ptrace_scope = 1

Los cuatro valores posibles:

Valor Quién puede trazar a quién
0 Cualquier proceso puede trazar a cualquier otro del mismo usuario
1 Solo a descendientes directos (el valor que pusiste)
2 Solo procesos con CAP_SYS_PTRACE (es decir, root)
3 Nadie, ni root. Irreversible hasta reiniciar

Y por qué la medida es correcta, que es la parte que hay que entender y no solo sortear: con ptrace_scope = 0, un proceso comprometido puede leer toda la memoria de cualquier otro proceso del mismo usuario. Eso incluye la credencial de la base de datos que tanto trabajo costó cifrar en 06-05: está en claro en la memoria del proceso que la usa. Un atacante que consiga ejecutar código como svc-tramontana en un proceso cualquiera podría extraerla del proceso de la aplicación sin tocar ningún fichero. El valor 1 cierra exactamente esa vía.

Las dos salidas legítimas:

# Salida A: usar sudo. CAP_SYS_PTRACE ignora la restriccion de Yama.
$ sudo strace -f -c -p 4318
# funciona
# Salida B: bajarlo temporalmente. Solo si necesitas trazar SIN privilegios,
# que es raro. Y SIEMPRE con la vuelta atras garantizada.
$ sudo sysctl -w kernel.yama.ptrace_scope=0
kernel.yama.ptrace_scope = 0
$ strace -f -c -p 4318 ; sudo sysctl -w kernel.yama.ptrace_scope=1
kernel.yama.ptrace_scope = 1

Para la salida B, la forma disciplinada es un script con trap, aplicando lo de 04-06, porque un Ctrl+C a mitad dejaría el sistema con la protección desactivada:

$ cat ~/scripts/trazar_temporal.sh
#!/usr/bin/env bash
# trazar_temporal.sh - Baja ptrace_scope, ejecuta el trazado, y lo restaura
#                      SIEMPRE, incluso si se interrumpe.
# Uso: trazar_temporal.sh <pid>
set -euo pipefail

readonly SCRIPT_DIR="$(cd "$(dirname "${BASH_SOURCE[0]}")" && pwd)"
# shellcheck source=lib/comunes.sh
source "${SCRIPT_DIR}/lib/comunes.sh"

readonly ETIQUETA_LOG="trazar-temporal"

restaurar() {
    sudo sysctl -q -w kernel.yama.ptrace_scope="$VALOR_ORIGINAL"
    log "ptrace_scope restaurado a $VALOR_ORIGINAL"
}

main() {
    local pid="${1:?uso: trazar_temporal.sh <pid>}"
    es_numero "$pid" || morir 64 "el pid debe ser un numero: $pid"
    requiere_comando strace

    VALOR_ORIGINAL="$(sysctl -n kernel.yama.ptrace_scope)"
    readonly VALOR_ORIGINAL
    trap restaurar EXIT INT TERM

    log "bajando ptrace_scope temporalmente (era $VALOR_ORIGINAL)"
    sudo sysctl -q -w kernel.yama.ptrace_scope=0

    timeout 10 strace -f -c -p "$pid" || true
}

main "$@"

En la práctica, la salida A —sudo— es la correcta el 95 % de las veces. La salida B solo tiene sentido con herramientas que no funcionan bien bajo sudo, y en un servidor de producción la respuesta honesta es que no se baja ptrace_scope: se usa eBPF, que no necesita ptrace en absoluto. Es otro argumento a favor de la tercera sección de esta lección.

ltrace y el nivel de las bibliotecas

strace ve la frontera entre el programa y el kernel. Hay otra frontera, un nivel más arriba: entre el programa y las bibliotecas compartidas que usa.

$ sudo apt install ltrace
$ ltrace -e 'malloc+free' ./programa 2>&1 | head -5
programa->malloc(1024)                        = 0x5f8c1a2f5000
programa->malloc(4096)                        = 0x5f8c1a2f5410
programa->free(0x5f8c1a2f5000)                = <void>

Es útil para entender el comportamiento de un programa propio —fugas de memoria, uso de una biblioteca criptográfica, llamadas a libcurl— pero tiene dos límites serios: solo ve llamadas a bibliotecas dinámicas (un binario estático es opaco), y su coste es aún mayor que el de strace. En la práctica se usa poco, y en un servidor casi nunca. strace para la frontera con el kernel, perf para el interior del proceso.

perf: perfilado por muestreo

perf es la herramienta de rendimiento del propio kernel de Linux, y opera con un modelo radicalmente distinto:

Trazado (strace) Muestreo (perf)
Método Intercepta todos los eventos Toma una foto N veces por segundo
Precisión Exacta Estadística, pero suficiente
Coste ×10 – ×100 1 – 5 %
Ve el código propio del proceso No Sí
Apto para producción No Sí

La diferencia clave es la penúltima fila. strace no puede decirte nada de un proceso que quema CPU en su propio bucle, porque ahí no hay llamadas al sistema. perf sí.

$ sudo apt install linux-tools-common linux-tools-$(uname -r)
$ perf --version
perf version 6.8.12

En una VM, algunos contadores de hardware no están disponibles porque el hipervisor no los expone. Los eventos de software (task-clock, context-switches, page-faults) sí funcionan siempre.

perf stat: la foto de eficiencia

$ sudo perf stat -p 4318 -- sleep 10

 Performance counter stats for process id '4318':

          1.284,17 msec task-clock                #    0,128 CPUs utilized
             3.412      context-switches          #    2,657 K/sec
                48      cpu-migrations            #   37,378 /sec
             1.204     page-faults                #    0,938 K/sec
     3.108.442.190      cycles                    #    2,421 GHz
     1.882.104.556      instructions              #    0,61  insn per cycle
       412.887.204      branches                  #  321,52 M/sec
        18.442.109      branch-misses             #    4,47% of all branches
       104.882.441      cache-references          #   81,68 M/sec
        41.204.882      cache-misses              #   39,28% of all cache refs

      10,002841 seconds time elapsed

Cómo leer esto, línea por línea, porque cada una responde a una pregunta distinta:

Métrica Qué significa Valor de referencia
CPUs utilized Fracción de un núcleo consumida 0,128: el proceso está prácticamente ocioso
context-switches Veces que dejó la CPU Alto + CPU baja = está esperando algo
insn per cycle (IPC) Instrucciones por ciclo: la eficiencia real >1 bueno; <0,5 el procesador espera memoria
branch-misses Predicciones de salto falladas <5 % normal; >10 % código muy ramificado
cache-misses Accesos que fueron a RAM <10 % bueno; >30 % problema de localidad

Y la conclusión de esta medición concreta: 0,128 CPU utilizadas. El proceso no está trabajando, está esperando. Los 3.412 cambios de contexto en 10 segundos lo confirman: entra y sale de la CPU constantemente porque se bloquea. Con esto queda descartada la CPU como causa del problema de latencia, que era el objetivo del paso 2 de la metodología.

El IPC de 0,61 y el 39 % de fallos de caché son mediocres, pero irrelevantes aquí: con el proceso al 12,8 % de un núcleo, mejorar su eficiencia de CPU no cambiaría la latencia.

perf top y perf record

# En vivo: que funciones consumen CPU ahora mismo, en todo el sistema
$ sudo perf top --sort comm,dso
Samples: 84K of event 'cpu-clock:pppH', 4000 Hz
  18,42%  postgres         postgres
  11,04%  tramontana       tramontana
   8,87%  swapper          [kernel.kallsyms]
   4,12%  tramontana       libssl.so.3
# Grabar con pilas de llamadas (-g) durante 30 segundos
$ sudo perf record -F 99 -g -p 4318 -- sleep 30
[ perf record: Woken up 3 times to write data ]
[ perf record: Captured and wrote 1,842 MB perf.data (2841 samples) ]

$ sudo perf report --stdio --sort overhead,symbol | head -14
# Overhead  Symbol
    64,12%  [k] __x64_sys_connect
    18,44%  [k] tcp_v4_connect
     6,02%  [.] tramontana_db_conectar
     3,18%  [.] SSL_connect
     1,84%  [k] finish_task_switch

-F 99 fija la frecuencia de muestreo en 99 Hz. Es una convención con motivo: usar 100 Hz corre el riesgo de sincronizarse con eventos periódicos del sistema que también son de 100 Hz, y sesgar la muestra. Un número primo cercano lo evita.

Las marcas [k] y [.] distinguen el espacio de kernel del de usuario. Aquí el 82 % del tiempo de CPU está en connect y tcp_v4_connect, ambos en el kernel, y tramontana_db_conectar aparece en el espacio de usuario. Tres herramientas distintas apuntando al mismo sitio: el proceso se pasa la vida abriendo conexiones.

Gráficos de llama

Un perf report con pilas de llamadas es difícil de leer porque la información es jerárquica y la salida es plana. El gráfico de llama (flame graph) resuelve eso visualmente, y se ha convertido en el estándar del área.

Cómo se lee, que es lo que hay que aprender:

  • El eje horizontal NO es tiempo. Es la agrupación alfabética de las pilas. La anchura de un bloque es la proporción de muestras en las que esa función estaba en la pila.
  • El eje vertical es la profundidad de la pila. Abajo el punto de entrada, arriba la función que estaba ejecutándose en ese instante.
  • Lo que buscas son mesetas anchas, especialmente en la parte alta: una función ancha arriba es una función donde el proceso pasa mucho tiempo realmente ejecutando. Una función ancha abajo con muchas torres finas encima es solo un punto de paso.
$ git clone --depth 1 https://github.com/brendangregg/FlameGraph ~/FlameGraph
$ sudo perf record -F 99 -g -p 4318 -- sleep 30
$ sudo perf script > salida.perf
$ ~/FlameGraph/stackcollapse-perf.pl salida.perf > salida.folded
$ ~/FlameGraph/flamegraph.pl salida.folded > llama-tramontana.svg

El resultado es un SVG interactivo: se abre en un navegador, se puede hacer clic para ampliar una rama y buscar por nombre de función.

Existe una variante muy útil que casi nadie conoce: el gráfico de llama fuera de CPU (off-CPU). El normal muestra dónde se consume CPU; el de fuera de CPU muestra dónde el proceso está bloqueado esperando. Para un problema de latencia como el nuestro —proceso al 12 % de CPU— el segundo es mucho más informativo, y se construye con eBPF en lugar de con perf:

$ sudo offcputime-bpfcc -df -p 4318 30 > fuera-cpu.folded
$ ~/FlameGraph/flamegraph.pl --title "Fuera de CPU" --countname us \
    fuera-cpu.folded > llama-espera.svg

Y perf trace, que merece una mención porque resuelve el problema de coste de strace:

$ sudo perf trace -p 4318 --duration 5 2>&1 | head -6
     0,000 ( 8,412 ms): tramontana/4318 connect(fd: 12, uservaddr: 10.0.2.15:5432) = 0
     8,441 ( 0,182 ms): tramontana/4318 sendto(fd: 12, buff: 0x7f2a..., len: 96) = 96
     8,712 ( 6,204 ms): tramontana/4318 recvfrom(fd: 12, ...) = 412

Misma información que strace -T, con un coste mucho menor porque usa la infraestructura de eventos del kernel en lugar de ptrace — y, de paso, no le afecta ptrace_scope.

eBPF: instrumentar el kernel en producción

eBPF es el cambio más importante en la observabilidad de Linux de la última década. La idea: permitir cargar programas propios dentro del kernel, que se ejecutan cuando ocurre un evento, con tres garantías que lo hacen seguro:

  1. Un verificador analiza el programa antes de cargarlo y rechaza todo lo que pueda colgar el kernel: bucles no acotados, accesos a memoria arbitraria, llamadas no permitidas.
  2. Se compila a código nativo con un JIT, así que se ejecuta a velocidad de kernel.
  3. No puede bloquear ni modificar el flujo del kernel; solo observar y agregar.

Por qué eso lo cambia todo: antes, para saber la latencia de cada operación de disco tenías que elegir entre un contador agregado (iostat, que da la media y oculta la cola) o trazar todo (strace, prohibitivo). Con eBPF puedes calcular el histograma completo dentro del kernel y sacar solo el resultado. El coste es de fracciones de porcentaje.

$ sudo apt install bpfcc-tools bpftrace linux-headers-$(uname -r)

Y aquí aparece el segundo sysctl de 06-06 con consecuencias:

$ sysctl kernel.unprivileged_bpf_disabled
kernel.unprivileged_bpf_disabled = 1

Esto impide que un usuario sin privilegios cargue programas eBPF, y es correcto: el subsistema BPF ha tenido vulnerabilidades de escalada de privilegios, y su superficie es grande. La consecuencia práctica es que todas las herramientas de esta sección se ejecutan con sudo, que es exactamente lo que quieres en un servidor.

bpftrace: una línea, una respuesta

bpftrace es un lenguaje de una línea para eBPF, con sintaxis inspirada en awk —que ya conoces del Módulo 3—: evento { acción }.

# 1. Contar llamadas al sistema por proceso durante 10 segundos
$ sudo timeout 10 bpftrace -e '
    tracepoint:raw_syscalls:sys_enter { @[comm] = count(); }'
Attaching 1 probe...
@[systemd-journal]: 412
@[postgres]: 8841
@[tramontana]: 33204

# 2. Latencia de las llamadas connect(), en histograma
$ sudo timeout 30 bpftrace -e '
    tracepoint:syscalls:sys_enter_connect { @inicio[tid] = nsecs; }
    tracepoint:syscalls:sys_exit_connect  /@inicio[tid]/ {
        @us = hist((nsecs - @inicio[tid]) / 1000);
        delete(@inicio[tid]);
    }'
@us:
[1, 2)                 4 |@                                    |
[2, 4)                12 |@@@@                                 |
[4, 8)               142 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@|
[8, 16)              128 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@   |
[16, 32)              14 |@@@@                                 |

# 3. Que ficheros abre un proceso concreto, en vivo
$ sudo bpftrace -e '
    tracepoint:syscalls:sys_enter_openat /comm == "tramontana"/ {
        printf("%s -> %s\n", comm, str(args->filename));
    }'

# 4. Cuantos bytes escribe cada proceso en disco
$ sudo timeout 20 bpftrace -e '
    tracepoint:block:block_rq_issue { @bytes[comm] = sum(args->bytes); }'

El histograma del ejemplo 2 es la clase de información que ninguna otra herramienta da fácilmente: 300 llamadas a connect, con la masa entre 4 y 16 microsegundos... espera. Ese histograma dice microsegundos, y strace -c decía 8 milisegundos por llamada. La discrepancia es la pista: la llamada connect al kernel es rápida; el tiempo se va en otra parte del proceso de conexión. Volveremos a esto en el caso práctico.

Fíjate en la mecánica del ejemplo 2, porque es el patrón de medición de latencia con eBPF: guardar nsecs en un mapa indexado por tid en la entrada, restar en la salida, y agregar con hist(). El cálculo entero ocurre dentro del kernel; lo único que sale al espacio de usuario es el histograma final.

Las herramientas de bpfcc y qué pregunta responde cada una

bpfcc-tools instala unas ciento cincuenta herramientas ya escritas. Estas son las que se usan de verdad:

Herramienta Pregunta que responde
execsnoop-bpfcc ¿Qué procesos se están lanzando? (procesos efímeros que ps no ve)
opensnoop-bpfcc ¿Qué ficheros se abren, y cuáles fallan?
biolatency-bpfcc ¿Cuál es la distribución de latencia de disco, no la media?
biosnoop-bpfcc ¿Qué proceso hace cada operación de disco?
tcpconnect-bpfcc ¿Quién abre conexiones salientes, y a dónde?
tcpaccept-bpfcc ¿Quién se conecta a mis servicios?
tcpretrans-bpfcc ¿Hay retransmisiones TCP? (problema de red real)
tcplife-bpfcc ¿Cuánto duran las conexiones y cuántos bytes mueven?
runqlat-bpfcc ¿Cuánto esperan los procesos en la cola de la CPU?
cachestat-bpfcc ¿Cuál es la tasa de acierto de la caché de página?
ext4slower-bpfcc ¿Qué operaciones de sistema de ficheros tardan más de N ms?
profile-bpfcc Perfilado por muestreo, alternativa a perf record
offcputime-bpfcc ¿Dónde está bloqueado esperando el proceso?
funclatency-bpfcc ¿Cuánto tarda una función concreta del kernel?

Dos de ellas merecen un comentario por lo que aportan sobre los contadores clásicos:

# biolatency: la DISTRIBUCION, no la media. Una media de 5 ms puede ocultar
# que el 1% de las operaciones tarda 500 ms, y ese 1% es el que se nota.
$ sudo biolatency-bpfcc -m 30 1
     msecs               : count     distribution
         0 -> 1          : 8412     |****************************************|
         2 -> 3          : 1204     |*****                                   |
         4 -> 7          :  412     |*                                       |
         8 -> 15         :   88     |                                        |
        16 -> 31         :   12     |                                        |
       256 -> 511        :    3     |                                        |

Esos tres eventos de 256-511 ms no aparecen en ninguna media. Si coinciden con las peticiones lentas, son la causa.

# runqlat: cuanto esperan los procesos para entrar en la CPU.
# Es la respuesta a "la CPU no esta saturada pero todo va lento".
$ sudo runqlat-bpfcc 10 1
     usecs               : count     distribution
         0 -> 1          : 12841    |****************************************|
         2 -> 3          :  2104    |******                                  |
         4 -> 7          :   412    |*                                       |

Tabla de decisión: qué herramienta para qué pregunta

La tabla que resume la lección y a la que volver cuando tengas un problema delante:

Pregunta Herramienta Coste
¿Está saturado algún recurso? vmstat, iostat, free, sar (M5) Nulo
¿Por qué falló el servicio? journalctl -u <unidad> (M5) Nulo
¿Qué fichero busca y no encuentra? strace -e trace=%file | grep ENOENT Alto, breve
¿Dónde se va el tiempo de un proceso? strace -f -c (primero), luego perf Alto / bajo
¿Cuánto tarda cada llamada? strace -T o perf trace Alto / bajo
¿Qué función consume CPU? perf top, perf record -g + gráfico de llama Bajo
¿Es eficiente el código (IPC, caché)? perf stat Nulo
¿Dónde está bloqueado esperando? offcputime-bpfcc + gráfico de llama Bajo
¿Cuál es la distribución de latencia de disco? biolatency-bpfcc Muy bajo
¿Quién abre conexiones y a dónde? tcpconnect-bpfcc, tcplife-bpfcc Muy bajo
¿Hay procesos efímeros que no veo? execsnoop-bpfcc Muy bajo
¿Espera para entrar en la CPU? runqlat-bpfcc Muy bajo
Algo muy específico del kernel bpftrace a medida Muy bajo
¿Por qué se cayó el proceso? gdb sobre el volcado, coredumpctl N/A

Y la regla de orden: contadores → perf stat → eBPF → strace. De menor a mayor coste, y strace en último lugar precisamente porque es el más caro. La intuición contraria —empezar por strace porque es el más conocido— es la que produce diagnósticos que degradan el servicio que intentan arreglar.

Una nota sobre volcados: si el problema es una caída, no una lentitud, la herramienta es otra. Recuerda que en 06-06 pusiste * hard core 0 en limits.conf para que los volcados no expusieran secretos; para depurar una caída habría que revertirlo temporalmente, y coredumpctl de systemd es la vía moderna.

Caso Tramontana: de 400 ms a 40 ms

revision_salud.sh empieza a devolver 1. La línea base de 05-07 dice que la aplicación responde en 40 ms; ahora tarda 400.

Paso 1: el síntoma, medido

$ for i in {1..5}; do
      curl -s -o /dev/null -w '%{time_total}\n' http://127.0.0.1:8080/casas
  done
0,412844
0,398201
0,421077
0,404118
0,397882

$ grep -c 'ms=[0-9]\{3,\}' /var/log/tramontana/acceso.log
389

Confirmado y reproducible: ~400 ms, no un pico aislado.

Paso 2: descartar con contadores (gratis)

$ vmstat 2 5
procs -----------memory---------- ---swap-- -----io---- -system-- ------cpu-----
 r  b   swpd   free   buff  cache   si   so    bi    bo   in   cs us sy id wa st
 0  0      0 1284412 104882 1841204   0    0     0    12  412  882  3  2 95  0  0
 0  0      0 1284188 104882 1841204   0    0     0     8  388  841  2  2 96  0  0

$ iostat -xz 2 3 | grep -A2 'Device'
Device   r/s   rkB/s  w/s   wkB/s   r_await  w_await  aqu-sz  %util
sda     0,50    8,00  2,00   16,00     0,42     0,88    0,01   0,40

$ free -h | head -2
               total        used        free      shared  buff/cache   available
Mem:           3,8Gi       1,2Gi       1,3Gi        12Mi       1,4Gi       2,4Gi

CPU al 95 % ociosa, disco al 0,4 % de utilización, 2,4 GB de memoria disponible. Ningún recurso está saturado. Este es exactamente el escenario que anunciaba el cierre de 07-01: los contadores en verde y el servicio mal.

Paso 3: perf stat confirma que espera, no trabaja

$ sudo perf stat -p $(pgrep -u svc-tramontana -f tramontana) -- sleep 10 2>&1 | \
      grep -E 'CPUs utilized|context-switches|insn per cycle'
          1.284,17 msec task-clock                #    0,128 CPUs utilized
             3.412      context-switches          #    2,657 K/sec
     1.882.104.556      instructions              #    0,61  insn per cycle

12,8 % de un núcleo y 3.412 cambios de contexto. El proceso se bloquea constantemente. La hipótesis pasa a ser: está esperando a algo externo. Los candidatos son disco (descartado por iostat) y red — es decir, PostgreSQL.

Paso 4: strace -c localiza el tiempo

Con sudo, por el ptrace_scope, y con límite de tiempo por el coste:

$ sudo timeout 10 strace -f -c -p $(pgrep -u svc-tramontana -f tramontana)
% time     seconds  usecs/call     calls    errors syscall
------ ----------- ----------- --------- --------- ----------------
 89.14    2.417882        8062       300           connect
  6.02    0.163291         272       600           sendto
  3.11    0.084372         140       602           recvfrom
------ ----------- ----------- --------- --------- ----------------

300 llamadas a connect en 10 segundos, a 8 ms cada una. Con ~75 peticiones en ese intervalo, salen unas 4 conexiones nuevas por petición. Una aplicación con un grupo de conexiones no debería abrir ninguna.

Paso 5: eBPF encuentra la causa real

Aquí es donde la discrepancia que dejamos pendiente se resuelve:

$ sudo timeout 20 tcplife-bpfcc
PID   COMM        LADDR      LPORT RADDR      RPORT TX_KB RX_KB MS
4318  tramontana  10.0.2.15  48812 10.0.2.15   5432     1     3 8.42
4318  tramontana  10.0.2.15  48814 10.0.2.15   5432     1     2 8.11
4318  tramontana  10.0.2.15  48816 10.0.2.15   5432     1     4 8.38
[... 297 lineas mas ...]

Trescientas conexiones a PostgreSQL, cada una de 8 ms de vida y unos pocos KB. Se abren, hacen una consulta y se cierran. Eso es un grupo de conexiones que no funciona.

Y el histograma explica los 8 ms, que la llamada connect sola no justificaba:

$ sudo timeout 30 bpftrace -e '
    tracepoint:syscalls:sys_enter_connect /comm == "tramontana"/ { @i[tid] = nsecs; }
    tracepoint:syscalls:sys_exit_connect  /@i[tid]/ {
        @us_syscall = hist((nsecs - @i[tid]) / 1000); delete(@i[tid]); }'
@us_syscall:
[4, 8)               142 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@|
[8, 16)              128 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@    |

La llamada al sistema tarda microsegundos. Los 8 milisegundos que veía strace incluyen todo lo que rodea a la conexión: el establecimiento TCP, y sobre todo la autenticación y el arranque de sesión de PostgreSQL. perf report ya lo insinuaba con SSL_connect en la pila.

$ sudo timeout 20 offcputime-bpfcc -p 4318 -f | sort -k2 -rn | head -3
tramontana;db_conectar;SSL_connect;read;schedule 18412042
tramontana;db_consultar;read;schedule 1204882
tramontana;epoll_wait;schedule 882104

18,4 de 20 segundos bloqueado dentro de db_conectar. Confirmado desde una cuarta herramienta independiente.

Paso 6: la causa raíz y la corrección

La pieza que faltaba es un dato que ya tenías. Recuerda el incidente de 05-07: errores.log con conexiones_activas=200 y db_timeout. Entonces se resolvió la saturación de E/S, pero el max_conexiones=200 quedó ahí:

$ grep -E 'max_conexiones|pool' /etc/tramontana/app.conf
max_conexiones=200

$ sudo -u postgres psql -tAc "SHOW max_connections;"
100

Ahí está la causa raíz, y es de configuración, no de código: la aplicación cree que puede tener 200 conexiones, PostgreSQL solo acepta 100. Cuando el grupo intenta crecer más allá de 100, las conexiones nuevas son rechazadas, la aplicación desiste del grupo y abre conexiones directas por petición, y cada una cuesta 8 ms de establecimiento y autenticación.

# Corregir: el grupo por debajo del limite real, con margen para el resto
$ sudo cp -p /etc/tramontana/app.conf /etc/tramontana/app.conf.bak-$(date +%F)
$ sudo chattr -i /etc/tramontana/app.conf
$ sudo sed -i.bak-$(date +%F) 's/^max_conexiones=200$/max_conexiones=80/' \
      /etc/tramontana/app.conf
$ sudo chattr +i /etc/tramontana/app.conf
$ sudo diff -u /etc/tramontana/app.conf.bak-$(date +%F) /etc/tramontana/app.conf
@@ -5,7 +5,7 @@
-max_conexiones=200
+max_conexiones=80
$ sudo systemctl restart tramontana.service

Paso 7: medir después

$ for i in {1..5}; do
      curl -s -o /dev/null -w '%{time_total}\n' http://127.0.0.1:8080/casas
  done
0,041882
0,038204
0,042118
0,039877
0,040412

$ sudo timeout 20 tcplife-bpfcc | wc -l
81

$ sudo timeout 10 strace -f -c -p $(pgrep -u svc-tramontana -f tramontana) 2>&1 | \
      grep -E 'connect|total'
  0.42    0.000841          10        80           connect
100.00    0.198442                  1841        12 total

$ ~/scripts/revision_salud.sh; echo "estado: $?"
estado: 0

De 400 ms a 40 ms. De 300 conexiones cada 10 segundos a 80 en total, que es el tamaño del grupo estableciéndose una vez. Y revision_salud.sh vuelve a 0.

Lo que hace válido este diagnóstico no es ninguna herramienta en particular, sino la convergencia de cinco mediciones independientes —perf stat, strace -c, tcplife, bpftrace y offcputime— señalando el mismo punto, más una hipótesis final verificada por comparación antes/después. Y la nota para el runbook: cambiar un límite en un lado de una relación cliente-servidor sin comprobar el otro lado es el error que provocó esto, y ocurrió hace tres módulos.

Errores Comunes y Consejos

  • Empezar por strace. Es la herramienta más conocida y la más cara. El orden es contadores → perf stat → eBPF → strace.
  • strace sin -e trace= ni -c en producción. Cien mil líneas ilegibles y un servicio cien veces más lento. Si tienes que trazar en producción, timeout 5 strace -f -c -p PID.
  • Olvidar -f. Sin seguir hijos e hilos, en una aplicación multihilo pierdes casi todo.
  • Confundir el tiempo de strace -c con el tiempo total del proceso. % time es la proporción dentro de llamadas al sistema. Si el programa quema CPU en su código, ahí no aparece: para eso está perf.
  • Matar strace con SIGKILL. Puede dejar el proceso trazado detenido. Sal con Ctrl+C.
  • Interpretar todos los ENOENT como errores. Un arranque normal genera decenas al buscar bibliotecas y locales. Filtra el ruido antes de concluir.
  • Bajar ptrace_scope y olvidar restaurarlo. Deja abierta la lectura de memoria entre procesos del mismo usuario, y con ella los secretos. Usa sudo, o un script con trap.
  • Fiarse de la media de latencia. iostat puede dar 1 ms de media mientras el 1 % de las operaciones tarda 500 ms. biolatency-bpfcc muestra la distribución, y la cola es lo que el usuario nota.
  • Muestrear a 100 Hz. Puede sincronizarse con eventos periódicos del sistema y sesgar la muestra. Usa un primo cercano: -F 99.
  • Buscar el problema de latencia en un gráfico de llama normal. El de CPU muestra dónde se consume; para un proceso que espera necesitas el de fuera de CPU (offcputime-bpfcc).
  • Concluir con una sola herramienta. Este caso se resolvió con cinco mediciones convergentes. Una sola habría dado una respuesta plausible y probablemente incompleta.
  • Consejo de método. Guarda las mediciones del diagnóstico junto a la línea base de 05-07: qué medías, con qué comando, y el valor normal. La próxima vez, el paso 2 son treinta segundos en lugar de veinte minutos.

Ejercicios

Ejercicio 1

respaldo_tramontana.sh tardaba 40 minutos y ahora tarda 3 horas, lo que hace que la copia de las 02:30 no termine antes del pico de la mañana — el incidente de 05-07 otra vez. iostat muestra el disco al 45 % de utilización, muy lejos de la saturación. Diseña el procedimiento de diagnóstico indicando qué herramienta usarías en cada paso y por qué, sabiendo que la copia usa restic sobre un volumen cifrado con LUKS.

Ejercicio 2

Escribe un script diagnostico_latencia.sh que, dado el nombre de un servicio de systemd, ejecute automáticamente los pasos 2, 3 y 4 de la metodología —contadores, perf stat y strace -c— y produzca un informe legible. Debe respetar las convenciones del curso, gestionar el ptrace_scope de forma segura, y no dejar residuos.

Ejercicio 3

Un compañero propone poner kernel.yama.ptrace_scope = 0 de forma permanente «porque así podemos diagnosticar sin sudo». Redacta la respuesta técnica: qué se gana, qué se pierde exactamente, y qué alternativa propones.

Soluciones

Solución 1

La clave del enunciado es «45 % de utilización», que descarta la saturación pero no descarta la latencia: son dos cosas distintas y confundirlas es el error habitual. Un disco al 45 % puede tener una cola de peticiones lentas.

# Paso 1. El sintoma, medido y comparado con la linea base
$ sudo journalctl -u tramontana-respaldo.service --since "7 days ago" \
    | grep -E 'Started|Finished|Succeeded'
$ systemd-analyze --no-pager verify tramontana-respaldo.service
# Y la fuente directa: cuanto tarda cada ejecucion
$ sudo systemctl show tramontana-respaldo.service -p ExecMainStartTimestamp \
    -p ExecMainExitTimestamp
# Paso 2. Contadores, gratis, mientras la copia corre.
# Lo que se busca aqui: %util NO es el indicador; w_await y aqu-sz si.
$ iostat -xz 5 6
Device   r/s   rkB/s  w/s   wkB/s  r_await  w_await  aqu-sz  %util
dm-1     2,00   32,0  84,0  1024,0    1,12    38,42    3,21   45,10
$ vmstat 5 6      # mirar la columna 'wa' y la 'b' (procesos bloqueados)
$ mpstat -P ALL 5 3   # buscar un nucleo al 100% en 'sy': senal de cifrado

Con w_await de 38 ms y %util del 45 %, ya hay una anomalía: hay latencia sin saturación, lo que apunta a operaciones individualmente lentas o a un cuello en algún punto de la pila.

# Paso 3. Distribucion, no media. Es LA herramienta para este sintoma.
$ sudo biolatency-bpfcc -D 60 1
# -D separa por dispositivo: permite ver si el problema esta en dm-1 (LUKS)
# o en sda (el disco fisico de debajo)

Y aquí está el razonamiento específico del ejercicio: /srv/tramontana/backups es un volumen LUKS sobre LVM sobre sda. Son tres capas, y la latencia hay que atribuirla a una:

Dispositivo Capa Si la latencia está aquí…
sda Disco físico El problema es el almacenamiento; no es cosa de la copia
vg-datos/lv-backups LVM Poco probable; LVM añade muy poco
dm-1 (backups-cifrado) LUKS El cifrado es el cuello de botella
# Paso 4. Confirmar si el cifrado es el cuello: la operacion consume CPU
# de kernel en los hilos de kcryptd.
$ sudo timeout 30 profile-bpfcc -f 30 | grep -iE 'crypt|aes' | head -5
$ ps -eLo comm,pcpu | grep -E 'kcryptd|restic' | sort -k2 -rn | head -5
$ cryptsetup luksDump /dev/vg-datos/lv-backups | grep -E 'Cipher|PBKDF'

# Y comprobar si el hardware acelera AES. Si no, el cifrado va por software
# y es entre 5 y 10 veces mas lento.
$ grep -o -m1 aes /proc/cpuinfo || echo "SIN aceleracion AES-NI"
# Paso 5. Descartar que sea restic y no el cifrado. Un proceso puede ir
# lento por E/S o por CPU, y hay que saber cual.
$ sudo perf stat -p $(pgrep -f 'restic backup') -- sleep 20 2>&1 \
    | grep -E 'CPUs utilized|context-switches'
$ sudo timeout 30 offcputime-bpfcc -p $(pgrep -f 'restic backup') -f \
    | sort -k2 -rn | head -5

La interpretación, que es lo que se pide:

  • CPUs utilized cerca de 1,00 y profile-bpfcc mostrando funciones de AES: el cuello es el cifrado por software. Causas posibles: la VM no expone AES-NI al huésped, o la CPU no lo tiene. Se comprueba con /proc/cpuinfo y se resuelve activando host-passthrough en la configuración de la VM (lo verás en 07-04) o cambiando el cifrado de LUKS.
  • CPUs utilized bajo y offcputime mostrando espera en E/S: el cuello es el disco. Entonces biolatency -D dice si la latencia ya viene de sda, y el siguiente paso es ext4slower-bpfcc para ver qué operaciones concretas tardan.
  • Cambios de contexto muy altos con ambos bajos: contención entre restic y otro proceso. runqlat-bpfcc lo confirmaría.

Y dos hipótesis alternativas que hay que descartar antes de tocar nada, porque son más probables que un problema de hardware:

# a) Ha crecido el volumen de datos? Una copia mas grande tarda mas.
$ sudo restic -r /srv/tramontana/backups/restic stats latest
$ du -sh /opt/tramontana/releases/*/ /home/operador/datos/

# b) Se ha degradado la deduplicacion, o falta un prune?
$ sudo restic -r /srv/tramontana/backups/restic snapshots | wc -l
$ sudo restic -r /srv/tramontana/backups/restic stats --mode raw-data

Un repositorio de restic sin forget --prune acumula datos y ralentiza cada operación. Si la retención GFS 14/8/12 dejó de ejecutarse, esa es la explicación más simple — y comprobarla es gratis. Antes de diagnosticar el hardware, descarta lo aburrido.

Nota final de método: el ionice que se puso en 05-07 sigue aplicándose y es correcto que el proceso ceda E/S. Pero si la copia ya no cabe en su ventana, ionice deja de ser suficiente y hay que atacar la causa, no el síntoma.

Solución 2

$ cat ~/scripts/diagnostico_latencia.sh
#!/usr/bin/env bash
# diagnostico_latencia.sh - Diagnostico guiado de latencia de un servicio.
#   Ejecuta los pasos 2, 3 y 4 de la metodologia: contadores, perf stat y
#   strace -c, y produce un informe legible.
# Uso: diagnostico_latencia.sh [-d segundos] [-o fichero] <unidad.service>
# Salida: 0 informe generado | 64 uso incorrecto | 69 falta una herramienta
set -euo pipefail

readonly SCRIPT_DIR="$(cd "$(dirname "${BASH_SOURCE[0]}")" && pwd)"
# shellcheck source=lib/comunes.sh
source "${SCRIPT_DIR}/lib/comunes.sh"

readonly ETIQUETA_LOG="diagnostico-latencia"
readonly DURACION_POR_DEFECTO=10

uso() {
    sed -n '2,6s/^# \?//p' "$0"
}

seccion() {
    printf '\n===== %s =====\n\n' "$1" >>"$INFORME"
}

main() {
    local duracion="${TRAMONTANA_DIAG_DURACION:-$DURACION_POR_DEFECTO}"
    local salida=""

    while getopts ":d:o:h" opcion; do
        case "$opcion" in
            d) duracion="$OPTARG" ;;
            o) salida="$OPTARG" ;;
            h) uso; return 0 ;;
            *) uso >&2; morir 64 "opcion no valida: -$OPTARG" ;;
        esac
    done
    shift $((OPTIND - 1))

    local unidad="${1:-}"
    [[ -n "$unidad" ]] || { uso >&2; morir 64 "falta la unidad de systemd"; }
    es_numero "$duracion" || morir 64 "la duracion debe ser un numero"

    requiere_comando systemctl
    requiere_comando vmstat
    requiere_comando iostat

    # Un solo temporal, limpiado por trap: convencion de 04-06
    local tmp
    tmp="$(mktemp -d)"
    INFORME="${salida:-${tmp}/informe.txt}"
    readonly INFORME
    trap 'rm -rf "$tmp"' EXIT

    # El PID principal es la fuente de verdad; pgrep podria coger otro proceso
    local pid
    pid="$(systemctl show "$unidad" -p MainPID --value)"
    [[ "$pid" =~ ^[0-9]+$ && "$pid" -gt 0 ]] \
        || morir 69 "la unidad $unidad no tiene un proceso principal activo"

    log "diagnosticando $unidad (PID $pid) durante ${duracion}s"

    {
        printf 'INFORME DE DIAGNOSTICO DE LATENCIA\n'
        printf 'Unidad:    %s\n' "$unidad"
        printf 'PID:       %s\n' "$pid"
        printf 'Maquina:   %s\n' "$(hostname)"
        printf 'Duracion:  %ss\n' "$duracion"
    } >"$INFORME"

    # ---- Paso 2: contadores. Coste nulo, se ejecuta siempre. ----
    seccion "PASO 2 - CONTADORES (metodo USE)"
    {
        printf '# CPU y memoria (vmstat)\n'
        vmstat 2 3
        printf '\n# Disco (iostat -xz)\n'
        iostat -xz 2 2 | sed -n '/Device/,$p'
        printf '\n# Memoria (free -h)\n'
        free -h
        printf '\n# Sockets del proceso (ss)\n'
        ss -tanp 2>/dev/null | grep -F "pid=${pid}," || printf '(ninguno)\n'
    } >>"$INFORME" 2>&1

    # ---- Paso 3: perf stat. Coste ~nulo, requiere root. ----
    seccion "PASO 3 - PERF STAT (trabaja o espera?)"
    if command -v perf >/dev/null 2>&1; then
        sudo perf stat -p "$pid" -- sleep "$duracion" >>"$INFORME" 2>&1 || \
            printf '(perf stat fallo: contadores no disponibles en esta VM?)\n' >>"$INFORME"
    else
        printf '(perf no instalado: apt install linux-tools-%s)\n' "$(uname -r)" >>"$INFORME"
    fi

    # ---- Paso 4: strace -c. COSTOSO: siempre con timeout y solo el resumen. ----
    seccion "PASO 4 - STRACE -c (donde se va el tiempo de syscalls)"
    printf 'ATENCION: strace ralentiza el proceso. Solo resumen, con limite.\n\n' >>"$INFORME"
    if command -v strace >/dev/null 2>&1; then
        # Con sudo: ignora ptrace_scope sin tocar el sysctl (ver 06-06).
        # || true porque timeout devuelve 124 al cortar, y eso es lo esperado.
        sudo timeout "$duracion" strace -f -c -p "$pid" >>"$INFORME" 2>&1 || true
    else
        printf '(strace no instalado)\n' >>"$INFORME"
    fi

    # ---- Extra: eBPF si esta disponible. Coste muy bajo. ----
    if command -v tcplife-bpfcc >/dev/null 2>&1; then
        seccion "EXTRA - CONEXIONES (tcplife)"
        sudo timeout "$duracion" tcplife-bpfcc 2>/dev/null \
            | awk -v p="$pid" 'NR==1 || $1==p' >>"$INFORME" || true
    fi

    seccion "SIGUIENTE PASO SUGERIDO"
    {
        printf 'Si CPUs utilized es ALTO  -> perf record -g + grafico de llama\n'
        printf 'Si CPUs utilized es BAJO  -> offcputime-bpfcc (esta bloqueado)\n'
        printf 'Si domina connect/sendto  -> tcplife-bpfcc, tcpconnect-bpfcc\n'
        printf 'Si domina read/write      -> biolatency-bpfcc, ext4slower-bpfcc\n'
    } >>"$INFORME"

    if [[ -n "$salida" ]]; then
        log "informe escrito en $salida"
    else
        cat "$INFORME"
    fi
}

main "$@"
$ chmod +x ~/scripts/diagnostico_latencia.sh
$ shellcheck ~/scripts/diagnostico_latencia.sh && echo "sin avisos"
sin avisos
$ ~/scripts/diagnostico_latencia.sh -d 5 tramontana.service | head -20

Las decisiones de diseño que hacen que este script sea usable en producción y no un peligro:

  1. MainPID en lugar de pgrep. systemctl show -p MainPID da el proceso que systemd considera principal. pgrep -f tramontana podría coger el propio script, un grep, o un proceso de otro release.
  2. El orden de los pasos es el de coste creciente, y strace va último. Si el problema se ve en el paso 2, ya tienes la respuesta antes de pagar nada.
  3. sudo para strace, nunca tocar ptrace_scope. Es la salida A de la lección, y es la única aceptable en un script que puede ejecutar cualquiera.
  4. timeout obligatorio en strace, con || true porque el código 124 de timeout es el resultado esperado, no un fallo. Sin esto, set -e abortaría el script justo antes de escribir las conclusiones.
  5. Degradación elegante. Si perf o eBPF no están, el informe lo dice y continúa. Un script de diagnóstico que falla porque falta una herramienta opcional es inútil precisamente cuando más lo necesitas.
  6. Un mktemp -d con trap, según 04-06: no deja residuos ni al interrumpirse.
  7. La sección final orienta el paso siguiente. El script automatiza los pasos mecánicos; la interpretación sigue siendo humana, y darle al operador el árbol de decisión es más útil que intentar concluir automáticamente.

Solución 3

Respuesta técnica: propuesta de fijar kernel.yama.ptrace_scope = 0

Qué se gana. Poder ejecutar strace, gdb y perf contra procesos del mismo usuario sin sudo. En la práctica esto ahorra escribir cuatro caracteres, porque en srv-tramontana la aplicación corre como svc-tramontana y nosotros como operador: con ptrace_scope = 0 seguiríamos necesitando sudo, ya que el valor 0 solo permite trazar procesos del propio usuario. El beneficio real de la propuesta, en nuestro caso concreto, es cero.

Qué se pierde, exactamente. ptrace permite leer y escribir toda la memoria de otro proceso. La memoria del proceso de la aplicación contiene, en claro y necesariamente:

  • La contraseña de la base de datos, que en 06-05 sacamos de app.conf y ciframos con systemd-creds precisamente para que no fuera legible.
  • La clave privada TLS, si el proceso la carga.
  • Los datos personales de huéspedes de las peticiones en curso.

Con ptrace_scope = 0, cualquier proceso comprometido que se ejecute como el mismo usuario puede extraer todo eso sin tocar ningún fichero: sin escrituras que AIDE detecte, sin accesos que auditd registre en las rutas que vigilamos, y sin dejar rastro en los registros. Es decir, anularía en la práctica el trabajo de dos lecciones enteras del módulo anterior.

Concretando sobre nuestro modelo de amenazas de 06-06: la segunda amenaza por probabilidad es la credencial filtrada, y la cuarta el abuso de acceso legítimo. Esta propuesta abre una vía directa para ambas y no cierra ninguna.

Alternativas, en orden de preferencia.

  1. Usar sudo. Es la respuesta correcta el 95 % de las veces. CAP_SYS_PTRACE ignora la restricción de Yama, queda registrado en auth.log —lo que es una ventaja, no un inconveniente— y no cambia la postura del sistema. Coste: cinco caracteres.
  2. Usar eBPF, que es mejor herramienta. perf trace, tcplife-bpfcc, biolatency-bpfcc, offcputime-bpfcc y bpftrace no usan ptrace en absoluto, así que ptrace_scope no les afecta. Y son entre diez y cien veces más baratas, lo que las hace las únicas realmente aptas para producción. Si la motivación de fondo es «diagnosticar con comodidad», esta es la respuesta técnica, no bajar una protección.
  3. Si de verdad hace falta trazar sin privilegios, existe una vía intermedia: dar CAP_SYS_PTRACE únicamente al binario de diagnóstico, en lugar de abrir el sistema entero:
    $ sudo setcap cap_sys_ptrace+ep /usr/bin/strace
    
    Retomando las capabilities de 05-02. Sigue siendo un aumento de superficie —cualquiera que pueda ejecutar strace podrá trazar—, pero acotado a un binario en lugar de a todo el sistema. Aun así no lo recomiendo aquí: no resuelve nuestro caso real (usuarios distintos) y añade un binario privilegiado que auditar.
  4. Bajarlo temporalmente, solo durante una sesión de diagnóstico, con restauración garantizada por trap (~/scripts/trazar_temporal.sh). Aceptable en el laboratorio; en producción es innecesario dado el punto 2.

Recomendación. Mantener kernel.yama.ptrace_scope = 1. La propuesta no aporta ningún beneficio en nuestra configuración —seguiríamos necesitando sudo— y abre una vía de extracción de credenciales y datos personales que no deja rastro. Si el problema de fondo es la fricción al diagnosticar, la solución es instalar y aprender bpfcc-tools y bpftrace, que además nos permitirán diagnosticar en producción y con carga, algo que strace no permite en ningún caso.

Añado dos notas para el runbook: el valor 1 está documentado en /etc/sysctl.d/60-endurecimiento.conf con un comentario que ya advertía de este efecto secundario; y conviene registrar aquí que el diagnóstico del incidente de latencia de esta semana se resolvió íntegramente con eBPF y sudo strace, sin necesidad de tocar el parámetro.

Conclusión

Ya sabes mirar dentro de un proceso en marcha. Tienes tres familias de herramientas y —lo más importante— el criterio para elegir entre ellas: los contadores del Módulo 5 responden a cuánto y son gratis, perf stat dice si un proceso trabaja o espera con un coste despreciable, eBPF instrumenta el kernel en producción con histogramas que revelan las colas que las medias ocultan, y strace da la respuesta exacta a costa de ralentizar el proceso hasta cien veces. El orden contadores → perf stat → eBPF → strace es la lección práctica que hay que llevarse, junto con la línea que resuelve la mitad de los misterios de configuración: strace -e trace=%file | grep ENOENT.

Has resuelto un caso completo siguiendo la metodología: síntoma medido y reproducible, hipótesis descartadas con contadores gratuitos, y cinco mediciones independientes convergiendo en la misma causa —un max_conexiones=200 contra un max_connections=100, un desajuste que llevaba tres módulos ahí— con la corrección verificada de 400 ms a 40 ms. Y te has topado con la consecuencia de tu propio endurecimiento: el ptrace_scope = 1 que impide trazar sin privilegios, que resulta que está bien porque la memoria de un proceso contiene en claro exactamente los secretos que tanto trabajo costó cifrar. Que la solución correcta a esa fricción sea usar eBPF, y no bajar la protección, es la clase de decisión que distingue a un administrador de alguien que sigue recetas.

Fíjate en un detalle de este diagnóstico que orienta lo que viene: la causa era un valor de configuración, y lo encontraste comparando dos lados de una misma relación. Ese es el terreno de la siguiente lección, con una diferencia importante: aquí el valor estaba en la aplicación, y ahora vas a tocar los del kernel. En la lección 07-03: Optimización del Kernel de Linux aprenderás a ajustar sysctl por rendimiento —no por seguridad, que ya lo hiciste en 06-06—: la memoria virtual con swappiness y los umbrales de páginas sucias, la red con somaxconn y el control de congestión BBR, los límites de ficheros y procesos, el planificador de E/S y por qué un NVMe quiere none, y las páginas enormes transparentes que toda base de datos pide desactivar. Verás también los módulos del kernel, dkms, y una respuesta honesta a si compilar el kernel tiene sentido en un servidor de producción. Y lo harás con la regla que gobierna todo el asunto y que esta lección ya te ha enseñado a aplicar: no se ajusta lo que no se ha medido, un solo cambio a la vez, y medir antes y después. Recuerda que el somaxconn por defecto sigue ahí, y que aquel errores.log con conexiones_activas=200 tenía más de una causa.

Curso de Linux: De Principiante a Administrador de Sistemas

Módulo 1: Introducción a Linux

Módulo 2: Comandos Básicos de Linux

Módulo 3: Habilidades Avanzadas en la Línea de Comandos

Módulo 4: Scripting en Shell

Módulo 5: Administración del Sistema

Módulo 6: Redes y Seguridad

Módulo 7: Temas Avanzados

Módulo 8: Proyectos Prácticos

© Copyright 2026. Todos los derechos reservados