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
- Cuándo los contadores no bastan
- strace: las llamadas al sistema una por una
- El obstáculo que tú mismo pusiste: ptrace_scope
- ltrace y el nivel de las bibliotecas
- perf: perfilado por muestreo
- Gráficos de llama
- eBPF: instrumentar el kernel en producción
- Las herramientas de bpfcc y qué pregunta responde cada una
- Tabla de decisión: qué herramienta para qué pregunta
- 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:
- Síntoma medido. «La aplicación tarda 400 ms en responder; la línea base dice 40 ms.» No «va lenta».
- Hipótesis descartadas con contadores. ¿CPU? ¿Disco? ¿Memoria? ¿Red? Es gratis y elimina la mayoría de los casos.
- 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) = 33Cada 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:
| 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 totalEsto 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.confEl 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
stracesin-e trace=ni-csobre 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
straceconSIGKILLpuede quedar detenido. Sal siempre conCtrl+C, que hace undetachlimpio. - Para producción,
perf tracey 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 permittedNo 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:
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 = 1Para 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í.
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 elapsedCó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.svgEl 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.svgY 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, ...) = 412Misma 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:
- 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.
- Se compila a código nativo con un JIT, así que se ejecuta a velocidad de kernel.
- 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.
Y aquí aparece el segundo sysctl de 06-06 con consecuencias:
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
389Confirmado 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,4GiCPU 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 cycle12,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 88210418,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;"
100Ahí 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.servicePaso 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: 0De 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. stracesin-e trace=ni-cen 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 -ccon el tiempo total del proceso.% timees 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
straceconSIGKILL. Puede dejar el proceso trazado detenido. Sal conCtrl+C. - Interpretar todos los
ENOENTcomo errores. Un arranque normal genera decenas al buscar bibliotecas y locales. Filtra el ruido antes de concluir. - Bajar
ptrace_scopey olvidar restaurarlo. Deja abierta la lectura de memoria entre procesos del mismo usuario, y con ella los secretos. Usasudo, o un script contrap. - Fiarse de la media de latencia.
iostatpuede dar 1 ms de media mientras el 1 % de las operaciones tarda 500 ms.biolatency-bpfccmuestra 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 cifradoCon 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 -5La interpretación, que es lo que se pide:
CPUs utilizedcerca de 1,00 yprofile-bpfccmostrando 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/cpuinfoy se resuelve activandohost-passthroughen la configuración de la VM (lo verás en 07-04) o cambiando el cifrado de LUKS.CPUs utilizedbajo yoffcputimemostrando espera en E/S: el cuello es el disco. Entoncesbiolatency -Ddice si la latencia ya viene desda, y el siguiente paso esext4slower-bpfccpara ver qué operaciones concretas tardan.- Cambios de contexto muy altos con ambos bajos: contención entre
resticy otro proceso.runqlat-bpfcclo 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-dataUn 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 -20Las decisiones de diseño que hacen que este script sea usable en producción y no un peligro:
MainPIDen lugar depgrep.systemctl show -p MainPIDda el proceso que systemd considera principal.pgrep -f tramontanapodría coger el propio script, ungrep, o un proceso de otro release.- El orden de los pasos es el de coste creciente, y
straceva último. Si el problema se ve en el paso 2, ya tienes la respuesta antes de pagar nada. sudoparastrace, nunca tocarptrace_scope. Es la salida A de la lección, y es la única aceptable en un script que puede ejecutar cualquiera.timeoutobligatorio enstrace, con|| trueporque el código 124 detimeoutes el resultado esperado, no un fallo. Sin esto,set -eabortaría el script justo antes de escribir las conclusiones.- Degradación elegante. Si
perfo 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. - Un
mktemp -dcontrap, según 04-06: no deja residuos ni al interrumpirse. - 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 = 0Qué se gana. Poder ejecutar
strace,gdbyperfcontra procesos del mismo usuario sinsudo. En la práctica esto ahorra escribir cuatro caracteres, porque ensrv-tramontanala aplicación corre comosvc-tramontanay nosotros comooperador: conptrace_scope = 0seguiríamos necesitandosudo, 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.
ptracepermite 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.confy ciframos consystemd-credsprecisamente 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 queauditdregistre 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.
- Usar
sudo. Es la respuesta correcta el 95 % de las veces.CAP_SYS_PTRACEignora la restricción de Yama, queda registrado enauth.log—lo que es una ventaja, no un inconveniente— y no cambia la postura del sistema. Coste: cinco caracteres.- Usar eBPF, que es mejor herramienta.
perf trace,tcplife-bpfcc,biolatency-bpfcc,offcputime-bpfccybpftraceno usanptraceen absoluto, así queptrace_scopeno 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.- 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:Retomando las capabilities de 05-02. Sigue siendo un aumento de superficie —cualquiera que pueda ejecutar$ sudo setcap cap_sys_ptrace+ep /usr/bin/stracestracepodrá 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.- 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 necesitandosudo— 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 aprenderbpfcc-toolsybpftrace, que además nos permitirán diagnosticar en producción y con carga, algo questraceno permite en ningún caso.Añado dos notas para el runbook: el valor
1está documentado en/etc/sysctl.d/60-endurecimiento.confcon 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 ysudo 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
- ¿Qué es Linux?
- Historia de Linux
- Distribuciones de Linux
- Instalando Linux
- Primer Contacto con el Sistema
- Estructura del Sistema de Archivos de Linux
Módulo 2: Comandos Básicos de Linux
- Introducción a la Línea de Comandos
- Obtener Ayuda y Documentación del Sistema
- Navegando el Sistema de Archivos
- Operaciones con Archivos y Directorios
- Visualización y Edición de Archivos
- Enlaces Duros y Simbólicos
- Permisos y Propiedad de Archivos
Módulo 3: Habilidades Avanzadas en la Línea de Comandos
- El Entorno del Shell: Variables, Alias e Historial
- Uso de Comodines y Expresiones Regulares
- Búsqueda de Archivos y Contenido: find, locate y grep
- Tuberías y Redirección
- Procesamiento de Texto: cut, sort, uniq, sed y awk
- Gestión de Procesos
- Programación de Tareas con Cron
- Comandos de Redes
Módulo 4: Scripting en Shell
- Introducción al Scripting en Shell
- Variables y Tipos de Datos
- Entrada, Salida y Argumentos de un Script
- Estructuras de Control
- Funciones y Librerías
- Depuración y Manejo de Errores
- Scripts de Producción: Buenas Prácticas
Módulo 5: Administración del Sistema
- Gestión de Usuarios y Grupos
- sudo y Permisos Especiales
- Gestión de Paquetes
- Gestión de Discos
- systemd y la Gestión de Servicios
- Registros del Sistema: journald y syslog
- Monitoreo del Sistema y Optimización del Rendimiento
- Respaldo y Restauración
Módulo 6: Redes y Seguridad
- Configuración de Redes
- SSH y Acceso Remoto
- Firewall y Seguridad Perimetral
- Sistemas de Detección de Intrusos
- Gestión de Secretos y Certificados TLS
- Asegurando Sistemas Linux
Módulo 7: Temas Avanzados
- El Proceso de Arranque y la Recuperación del Sistema
- Diagnóstico Avanzado: strace, perf y eBPF
- Optimización del Kernel de Linux
- Virtualización con Linux
- Contenedores de Linux y Docker
- Automatización con Ansible
- Alta Disponibilidad y Balanceo de Carga
