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.

• Activar y desactivar tracers escribiendo en current_tracer dentro de tracefs.
• Leer la salida del function tracer: tarea, CPU, banderas de contexto y marca de tiempo.
• Usar function_graph para ver anidamiento de llamadas y la duración de cada una.
• Acotar el ámbito con set_ftrace_filter para que el coste del trazado sea manejable.

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/tracingcd /sys/kernel/tracingcat 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 funcionesecho 1 > tracing_on                 # empezar a capturarcat trace | head                    # mirar el bufferecho 0 > tracing_on                 # pausarecho 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_tracerecho 1 > options/funcgraph-proc     # mostrar tambien la tareacat 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 nivelesecho 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_tracerecho 'tcp_*' > set_ftrace_filter     # solo funciones de TCPecho 'tcp_metrics_*' >> set_ftrace_notrace  # menos estascat set_ftrace_filter                # ver que quedo activoecho > 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.

function

Una línea por llamada, con el llamante tras el <-. Barato de activar, brutal de volumen. Ideal acotado a un puñado de funciones para ver quién llama a quién.

function_graph

Engancha entrada y salida: dibuja el árbol de llamadas y mide la duración de cada nodo. Más caro, pero convierte la traza en un perfil de latencia con coordenadas.

Filtra antes de encender en producción

Activar el function tracer sin filtro en una máquina cargada puede multiplicar por varias veces el tiempo de CPU y llenar el buffer en milisegundos. La secuencia segura es siempre la misma: primero escribe set_ftrace_filter con el subconjunto que te interesa, luego echo function en current_tracer, y solo entonces tracing_on.

function_graph convierte el tiempo en topografía

Piensa en lo que function_graph hace de verdad, porque es más profundo que una lista con sangría. El function tracer te da una secuencia: una función tras otra, un río de nombres en orden temporal. function_graph toma ese río unidimensional y lo levanta a dos dimensiones, porque captura no solo cuándo entra el kernel en una función sino cuándo sale. Y con esos dos instantes reconstruye algo que en el código fuente estaba implícito y en la ejecución se había perdido: la estructura de árbol de la llamada, el hecho de que path_openat vive dentro de do_filp_open que vive dentro de do_sys_openat2. La sangría no es cosmética; es la pila de llamadas materializada en el tiempo. Y una vez tienes el árbol, la duración deja de ser un número suelto y se vuelve atribuible: cuando ves un ! de ciento veintiún microsegundos en un nodo cuyos hijos suman ciento veinte, sabes que el tiempo se fue en los hijos y no en el nodo; cuando el nodo tarda mucho más que la suma de sus hijos, el tiempo se fue en él mismo, entre llamada y llamada, quizás esperando un lock. Esa aritmética —tiempo del padre menos suma de los hijos igual a tiempo propio— es el arte del profiling, y function_graph te la sirve gratis. Has convertido una traza en un mapa topográfico donde la latencia tiene coordenadas.

Perfila un openat con function_graph

1. Monta tracefs si hace falta y confirma con available_tracers que tu kernel trae function y function_graph.
2. Filtra con set_ftrace_filter a las funciones de VFS (vfs_*) y traza un cat /etc/hostname con el function tracer; localiza el <- que revela quién llamó a vfs_read.
3. Cambia a function_graph, fija set_graph_function en do_sys_openat2 y max_graph_depth en 5, y encuentra el nodo con el marcador ! de mayor latencia.
4. Explica, usando la resta tiempo-propio, si esa latencia está en el nodo o en sus descendientes.
5. Razona por qué vaciar set_ftrace_filter con echo > no solo cambia la salida sino también el coste en CPU del trazado.