ftrace: el tracer integrado, function y function_graph

ftrace no es un programa que instalas: es una máquina de trazado compilada dentro del propio kernel, gobernada leyendo y escribiendo archivos de texto en /sys/kernel/tracing. Sin agentes, sin bibliotecas, sin recompilar. Con dos echo enciendes el function tracer y ves el torrente de funciones que el kernel ejecuta; con otro cambias a function_graph y ese torrente se ordena en un árbol de llamadas anidadas, cada una con su duración medida en nanosegundos. Es el sismógrafo del kernel, y aprender a leerlo —y sobre todo a acotarlo— es el corazón de este nivel.

tracefs y current_tracer

Toda la interfaz vive bajo un único directorio. En un kernel actual está montado en /sys/kernel/tracing; si no, se monta a mano.

sudo mount -t tracefs nodev /sys/kernel/tracing
cd /sys/kernel/tracing
cat available_tracers
# timerlat osnoise hwlat blk function_graph wakeup_dl wakeup_rt wakeup function nop

El archivo current_tracer es el interruptor central: contiene el tracer activo, y por defecto vale nop (ninguno). Escribir en él cambia de trazador en caliente; escribir nop lo apaga. Dos archivos más completan el control básico: tracing_on (un 1 o un 0 que pausa y reanuda la escritura sin perder configuración) y trace, que al leerlo vuelca una instantánea del buffer.

echo function > current_tracer      # elegir el trazador de funciones
echo 1 > tracing_on                 # empezar a capturar
cat trace | head                    # mirar el buffer
echo 0 > tracing_on                 # pausar
echo nop > current_tracer           # apagar y limpiar

El function tracer

El function tracer registra cada entrada a función del kernel apoyándose en los ganchos __fentry__ que el compilador insertó. Su salida es una línea por llamada, con un encabezado que documenta las columnas:

# tracer: function
#
#                                _-----=> irqs-off/BH-disabled
#                               / _----=> need-resched
#                              | / _---=> hardirq/softirq
#                              || / _--=> preempt-depth
#                              ||| / _-=> migrate-disable
#                              |||| /     delay
#           TASK-PID     CPU#  |||||   TIMESTAMP  FUNCTION
#              | |         |   |||||      |          |
         sshd-1893    [002] ...1.  4213.998112: tcp_sendmsg <-sock_write_iter
         sshd-1893    [002] ...1.  4213.998114: tcp_sendmsg_locked <-tcp_sendmsg

Cada fila te dice quién ejecutaba (tarea y PID), en qué CPU, en qué contexto (las banderas: interrupciones deshabilitadas, softirq/hardirq, profundidad de preempción), cuándo (marca de tiempo en segundos) y qué función se llamó, con la que la llamó tras el <-. Ese <- que revela al llamante es la mitad del valor del function tracer: no solo ves qué se ejecuta, sino desde dónde.

El problema es el volumen. Trazar todas las funciones del kernel genera millones de líneas por segundo y ralentiza el sistema de forma notable. En bruto casi nunca es lo que quieres: el function tracer se vuelve útil cuando lo acotas, como veremos abajo.

function_graph: anidamiento y tiempos

El trazador function_graph engancha tanto la entrada como la salida de cada función, y con ambos instantes hace dos cosas que el function tracer no puede: dibuja el árbol de llamadas con indentación y mide cuánto tardó cada función, cierres incluidos.

echo function_graph > current_tracer
echo 1 > options/funcgraph-proc     # mostrar tambien la tarea
cat trace

# tracer: function_graph
#
# CPU  DURATION                  FUNCTION CALLS
# |     |   |                     |   |   |   |
 2)               |  __x64_sys_openat() {
 2)               |    do_sys_openat2() {
 2)   0.214 us    |      getname();
 2)               |      do_filp_open() {
 2)               |        path_openat() {
 2) + 18.902 us   |          link_path_walk.part.0();
 2) ! 121.665 us  |        }
 2) ! 142.330 us  |      }
 2) ! 143.001 us  |    }
 2) ! 143.556 us  |  }

La columna DURATION da la latencia real de cada función. Los marcadores a su izquierda saltan a la vista cuando algo va lento: un espacio significa menos de diez microsegundos, + marca más de diez y ! marca más de cien. Un ! junto a path_openat te dice, sin adivinar, dónde se fue el tiempo de tu openat. Puedes limitar la profundidad para no ahogarte en hojas y arrancar el árbol solo desde una función concreta:

echo 3 > max_graph_depth                 # no bajar mas de tres niveles
echo do_sys_openat2 > set_graph_function # el arbol solo cuelga de aqui

Acotar el ámbito con set_ftrace_filter

La diferencia entre un trazado inútil y uno quirúrgico es el filtro de funciones. set_ftrace_filter acepta nombres exactos y comodines, y su complemento set_ftrace_notrace excluye. Como el trazado descansa sobre los nop parcheados, filtrar no solo reduce la salida: reduce el coste, porque el kernel solo reescribe los sitios que pediste.

echo function > current_tracer
echo 'tcp_*' > set_ftrace_filter     # solo funciones de TCP
echo 'tcp_metrics_*' >> set_ftrace_notrace  # menos estas
cat set_ftrace_filter                # ver que quedo activo
echo > set_ftrace_filter             # vaciar: volver a todas

Dos acotaciones más afinan aún más. set_ftrace_pid limita el trazado a un proceso concreto (escribe su PID), y en function_graph, set_graph_function restringe el árbol a las llamadas que nacen de una función dada. Para consumir el flujo en vivo en lugar de una instantánea, se lee trace_pipe, que bloquea hasta que hay datos y los va vaciando —ideal para un cat trace_pipe en una terminal mientras reproduces el problema en otra.