Rastreando o kernel Linux com ftrace

- por Sergio Prado

Categorias: ftrace Tags: ,

Tracing é uma técnica bastante útil para encontrar erros em software, e o ftrace é um framework de tracing integrado ao kernel Linux.

Mas antes de estudarmos sobre o ftrace, vamos falar de tracing.

O que é tracing?

Tracing ou rastreamento de código é um log especializado capaz de registrar informações sobre o fluxo de execução de um programa.

Sabe quando você coloca mensagens de debug no código? Você está rastreando o programa com seu próprio “sistema de rastreamento”. As mensagens de debug adicionadas ao código são pontos de rastreamento estáticos e seu “sistema de rastreamento” pode enviar as mensagens de debug para a saída padrão do programa ou para um arquivo de log.

Bom, isso funciona. Mas não escala. Sempre que desejar rastrear parte do programa, você precisará adicionar novas mensagens de debug e recompilar o código. E você não tem muito controle sobre a impressão das mensagens. E se você quiser salvá-las para análise posterior? E se você quiser filtrar as mensagens? E o código ficará uma bagunça, com muitas mensagens de debug. Será necessário ter muito cuidado para não comitar nenhum código com mensagens de debug.

O fato é que na maioria das vezes não precisamos adicionar mensagens de debug no código, porque já existem ferramentas e frameworks de tracing que podem fazer isso automaticamente por nós!

É aí que entra o ftrace…

O que é o ftrace?

O Ftrace é um framework de tracing do kernel Linux. Ele foi adicionado ao kernel em 2008 e evoluiu bastante desde então.

Ftrace significa function tracer e basicamente permite monitorar e registrar o fluxo de execução das funções do kernel. Foi criado por Steven Rostedt, derivado de duas outras ferramentas chamadas latency tracer do Ingo Molnar e logdev do próprio Steven Rostedt.

Com o ftrace, podemos realmente ver o que o kernel está fazendo. Podemos rastrear as chamadas de função e aprender muito sobre como o kernel funciona. Podemos descobrir quais funções do kernel são chamadas quando executamos uma aplicação em espaço de usuário.

Podemos medir o tempo de execução das funções e descobrir gargalos e problemas de desempenho. Podemos identificar travamentos no espaço do kernel. Podemos medir o tempo necessário para executar uma tarefa de tempo real e descobrir problemas de latência. Podemos medir o consumo de pilha em espaço de kernel e descobrir possíveis estouros de pilha. É uma ferramenta extremamente útil para monitorar e encontrar bugs no kernel!

Mas como ele funciona? Magia negra? Talvez um pouco. :-)

Como o ftrace funciona?

Existem dois principais tipos de implementação de tracing: estático e dinâmico.

Tracing estático é implementado através de pontos de rastreamento estáticos adicionados ao código-fonte. Possuem baixa carga de processamento, porém o código rastreado é limitado e definido em tempo de compilação.

Tracing dinâmico é implementado através pontos de rastreamento dinâmicos injetados no código (normalmente através de interrupção de software), permitindo definir em tempo de execução o código a ser rastreado. Possui uma certa carga de processamento, mas a abrangência do código-fonte a ser rastreado é bem maior.

O ftrace utiliza uma combinação de tracing estático (rastreamento de funções, rastreamento de eventos, etc.) e tracing dinâmico (kprobes, uprobes, etc).

Para rastrear as chamadas de função, o ftrace irá compilar o kernel com a opção -pg do GCC.

Quando o kernel é compilado com -pg, serão adicionadas algumas instruções da máquina no início de cada função (que não seja inline) do kernel, redirecionando a execução para os plugins de tracing do ftrace.

A código em Assembly abaixo é o prólogo da função gpiod_set_value do kernel compilado com tracing habilitado. A chamada __ gnu_mcount_nc na linha 10 foi adicionada pelo GCC e será utilizada pelo ftrace para instrumentação (essa é a mesma técnica utilizada pelo gprof para analisar a performance de aplicações em espaço de usuário).

1
2
3
4
5
6
7
8
9
10
11
12
$ arm-linux-gdb -q vmlinux
Reading symbols from vmlinux...done.
(gdb) disassemble /m gpiod_set_value
Dump of assembler code for function gpiod_set_value:
3133    {
   0xc03a83ac <+0>:     mov     r12, sp
   0xc03a83b0 <+4>:     push    {r4, r5, r11, r12, lr, pc}
   0xc03a83b4 <+8>:     sub     r11, r12, #4
   0xc03a83b8 <+12>:    push    {lr}            ; (str lr, [sp, #-4]!)
   0xc03a83bc <+16>:    bl      0xc001b420 <__gnu_mcount_nc>
   0xc03a83c0 <+20>:    mov     r5, r1
   0xc03a83c8 <+28>:    mov     r4, r0

O Ftrace também é capaz de rastrear eventos (trace events) do kernel.

Trace events são pontos de rastreamento estáticos adicionados pelos desenvolvedores para monitorar os subsistemas do kernel, como o escalonador de tarefas, gerenciamento de energia, tratamento de interrupções, camada de rede, GPIO, etc. Basta procurar por funções começando com trace_ no código-fonte do kernel Linux e você encontrará vários locais onde os trace events são utilizados:

$ grep -R trace_ drivers/gpio/*
drivers/gpio/gpiolib.c: trace_gpio_direction(desc_to_gpio(desc), 1, status);
drivers/gpio/gpiolib.c: trace_gpio_value(desc_to_gpio(desc), 0, val);
drivers/gpio/gpiolib.c: trace_gpio_direction(desc_to_gpio(desc), 0, ret);
drivers/gpio/gpiolib.c: trace_gpio_value(desc_to_gpio(desc), 1, value);
drivers/gpio/gpiolib.c:                 trace_gpio_value(desc_to_gpio(desc), 1, value);
drivers/gpio/gpiolib.c: trace_gpio_direction(desc_to_gpio(desc), value, err);
drivers/gpio/gpiolib.c: trace_gpio_direction(desc_to_gpio(desc), !value, err);
drivers/gpio/gpiolib.c: trace_gpio_value(desc_to_gpio(desc), 0, value);
drivers/gpio/gpiolib.c:                 trace_gpio_value(desc_to_gpio(desc), 0, value);

Mas como interagimos com o ftrace?

Quando o tracing é ativado, todos os dados de rastreamento coletados serão armazenados pelo ftrace em um buffer circular em memória.

Existe um sistema de arquivos virtual chamado tracefs (geralmente montado em /sys/kernel/tracing) para interfacear com o ftrace. Através deste sistema de arquivos, podemos configurar o ftrace e coletar os dados de rastreamento.

O fato da interface ser através de operações em arquivos é uma característica interessante do ftrace, já que é possível utilizar ferramentas simples como echo e cat para rastrear o kernel Linux!

Como então usar o ftrace?

Primeiro devemos habilitar o ftrace no kernel (opção CONFIG_FTRACE), incluindo todas as funcionalidades que planejamos utilizar. Esta é a tela de configuração do kernel versão 4.18 com a maioria das opções do ftrace habilitadas:

ftrace menuconfig

Com o ftrace habilitado, podemos montar o sistema de arquivos virtual tracefs:

# mount -t tracefs tracefs /sys/kernel/tracing

E esta é a interface de arquivos provida pelo ftrace:

# ls /sys/kernel/tracing/
README                      set_ftrace_filter
available_events            set_ftrace_notrace
available_filter_functions  set_ftrace_pid
available_tracers           set_graph_function
buffer_size_kb              set_graph_notrace
buffer_total_size_kb        snapshot
current_tracer              stack_max_size
dyn_ftrace_total_info       stack_trace
enabled_functions           stack_trace_filter
events                      timestamp_mode
free_buffer                 trace
function_profile_enabled    trace_clock
hwlat_detector              trace_marker
instances                   trace_marker_raw
max_graph_depth             trace_options
options                     trace_pipe
per_cpu                     trace_stat
printk_formats              tracing_cpumask
saved_cmdlines              tracing_max_latency
saved_cmdlines_size         tracing_on
saved_tgids                 tracing_thresh
set_event                   uprobe_events
set_event_pid               uprobe_profile

Podemos exibir a lista de tracers disponíveis:

# cat available_tracers
hwlat   blk      function_graph   wakeup_dl   wakeup_rt 
wakeup  irqsoff  function         nop

Existem tracers de função (function, function_graph), tracers de latência (wakeup_dl, wakeup_rt, irqsoff, wakeup, hwlat), tracers de I/O (blk), etc.

Para habilitar um tracer, precisamos escrever seu nome no arquivo current_tracer:

# echo function > current_tracer

Depois podemos ler o buffer de tracing através dos arquivos trace ou trace_pipe:

# cat trace
# tracer: function
#
#                              _-----=> irqs-off
#                             / _----=> need-resched
#                            | / _---=> hardirq/softirq
#                            || / _--=> preempt-depth
#                            ||| /     delay
#           TASK-PID   CPU#  ||||    TIMESTAMP  FUNCTION
#              | |       |   ||||       |         |
          <idle>-0     [001] d...    23.695208: _raw_spin_lock_irqsave <-hrtimer_next_event_wi...
          <idle>-0     [001] d...    23.695209: __hrtimer_next_event_base <-hrtimer_next_event...
          <idle>-0     [001] d...    23.695210: __next_base <-__hrtimer_next_event_base
          <idle>-0     [001] d...    23.695211: __hrtimer_next_event_base <-hrtimer_next_event...
          <idle>-0     [001] d...    23.695212: __next_base <-__hrtimer_next_event_base
          <idle>-0     [001] d...    23.695213: __next_base <-__hrtimer_next_event_base
          <idle>-0     [001] d...    23.695214: _raw_spin_unlock_irqrestore <-hrtimer_next_eve...
          <idle>-0     [001] d...    23.695215: get_iowait_load <-menu_select
          <idle>-0     [001] d...    23.695217: tick_nohz_tick_stopped <-menu_select
          <idle>-0     [001] d...    23.695218: tick_nohz_idle_stop_tick <-do_idle
          <idle>-0     [001] d...    23.695219: rcu_idle_enter <-do_idle
          <idle>-0     [001] d...    23.695220: call_cpuidle <-do_idle
          <idle>-0     [001] d...    23.695221: cpuidle_enter <-call_cpuidle

O function_graph é um tracer de funções alternativo que rastreia não apenas a entrada da função, mas também também seu retorno, permitindo criar um gráfico de chamada de função em um estilo parecido com a linguagem C, incluindo informações sobre o tempo de execução de cada função.

# echo function_graph > current_tracer
 
# cat trace
# tracer: function_graph
#
# CPU  DURATION                  FUNCTION CALLS
# |     |   |                     |   |   |   |
 0)   1.000 us    |                } /* idle_cpu */
 0)               |                tick_nohz_irq_exit() {
 0)               |                  ktime_get() {
 0)   1.000 us    |                    clocksource_mmio_readl_up();
 0)   7.666 us    |                  }
 0) + 14.000 us   |                }
 0)               |                rcu_irq_exit() {
 0)   1.334 us    |                  rcu_nmi_exit();
 0)   7.667 us    |                }
 0) ! 556.000 us  |              } /* irq_exit */
 0) # 1187.667 us |            } /* __handle_domain_irq */
 0) # 1194.333 us |          } /* gic_handle_irq */
 0)   <========== |
 0) # 8197.333 us |        } /* cpuidle_enter_state */
 0) # 8205.334 us |      } /* cpuidle_enter */

A quantidade de dados gerados pelo tracing pode ser muito grande, por isso existem diversas opções de filtro no ftrace. Por exemplo, podemos configurar um filtro para rastrear apenas um pequeno grupo de funções do kernel, ou então filtrar por PID e rastrear apenas funções do kernel executadas por um processo específico do sistema.

No exemplo abaixo, estamos rastreando apenas as funções que começam com snvs, correspondentes ao driver de RTC da NXP:

# echo "snvs*" > set_ftrace_filter
# echo function > current_tracer
# cat trace_pipe
      Binder_3-836   [000] ...1  5890.663049: snvs_rtc_set_time <-rtc_set_time
      Binder_3-836   [000] ...1  5890.663063: snvs_rtc_enable <-snvs_rtc_set_time
      Binder_3-836   [000] ...1  5890.663106: snvs_rtc_enable <-snvs_rtc_set_time
   kworker/0:0-2128  [000] ...1  5890.663215: snvs_rtc_read_time <-__rtc_read_time

Podemos também ativar o tracing de eventos específicos do kernel, como escalonamento de tarefas, acesso a GPIOs ou chamadas de sistema. No exemplo abaixo, estamos rastreando apenas eventos de GPIO:

# echo 1 > events/gpio/enable
# cat trace_pipe
         mmcqd/2-103   [000] d..2   778.002889: gpio_value: 73 get 0
         mmcqd/2-103   [000] d..2   778.002910: gpio_value: 73 get 0
         mmcqd/2-103   [000] d..2   778.007575: gpio_value: 73 get 0
         mmcqd/2-103   [000] d..2   778.013398: gpio_value: 73 get 0

Também podemos utilizar o ftrace para medir latências em espaço de kernel (latência com as interrupções desabilitadas, latência para executar um processo de tempo-real, etc).

É bom poder usar ferramentas simples como cat e echo para rastrear o kernel Linux. Mas, às vezes, precisamos escrever em vários arquivos diferentes para configurar uma sessão de tracing. Nesse caso, a ferramenta trace-cmd pode ajudar.

A ferramenta trace-cmd

trace-cmd é uma ferramenta de linha de comando criada por Steven Rostedt que serve de interface para o ftrace.

É um front-end para o sistema de arquivos tracefs e pode ser usada para configurar o ftrace, ler o buffer de tracing e salvar os dados em um arquivo (trace.dat por padrão) para análise posterior.

# trace-cmd
 
trace-cmd version 2.6.1
 
usage:
  trace-cmd [COMMAND] ...
 
  commands:
     record - record a trace into a trace.dat file
     start - start tracing without recording into a file
     extract - extract a trace from the kernel
     stop - stop the kernel from recording trace data
     restart - restart the kernel trace data recording
     show - show the contents of the kernel tracing buffer
     reset - disable all kernel tracing and clear the trace buffers
     report - read out the trace stored in a trace.dat file
     stream - Start tracing and read the output directly
     profile - Start profiling and read the output directly
     hist - show a historgram of the trace.dat information
     stat - show the status of the running tracing (ftrace) system
     split - parse a trace.dat file into smaller file(s)
     options - list the plugin options available for trace-cmd report
     listen - listen on a network socket for trace clients
     list - list the available events, plugins or options
     restore - restore a crashed record
     snapshot - take snapshot of running trace
     stack - output, enable or disable kernel stack tracing
     check-events - parse trace event formats

Por exemplo, o comando abaixo irá iniciar um tracing de função:

# trace-cmd start -p function

O comando abaixo irá rastrear os eventos de GPIO:

# trace-cmd start -e gpio

Podemos também, com um único comando, rastrear um processo específico e armazenar o resultado em um arquivo:

# trace-cmd record -p function -F ls /
  plugin 'function'
CPU0 data recorded at offset=0x30d000
    737280 bytes in size
CPU1 data recorded at offset=0x3c1000
    0 bytes in size
 
# ls trace.dat
trace.dat

E depois exibir o resultado do tracing com o comando report:

# trace-cmd report
CPU 1 is empty
cpus=2
              ls-175   [000]    43.359618: function:             mutex_unlock <-- rb_simple_write
              ls-175   [000]    43.359624: function:             __fsnotify_parent <-- vfs_write
              ls-175   [000]    43.359625: function:             fsnotify <-- vfs_write
              ls-175   [000]    43.359627: function:             __sb_end_write <-- vfs_write

Ou podemos abrir o arquivo com o KernelShark.

KernelShark

O KernelShark é uma ferramenta gráfica que serve de front-end para o arquivo trace.dat gerado pelo trace-cmd.

kernelshark

A ferramenta possui duas áreas principais de visualização.

A metade superior é uma exibição gráfica dos dados (por CPU ou tarefa). Você pode aumentar ou diminuir o zoom em um determinado local para ver os detalhes dos eventos em um período específico de tempo.

A metade inferior é uma exibição de lista de eventos de tracing, com opções de filtro para ajudar a analisar os dados de rastreamento.

Mais informações sobre a ferramenta estão disponíveis na documentação do KernelShark.

Estudamos aqui o trace-cmd e o KernelShark, mas muitas outras ferramentas usam o ftrace atualmente, incluindo o perf e implementações de kernel live patching.

Para saber mais, leia a documentação de tracing do kernel e a documentação do ftrace.

Também há palestras muito boas do Steven Rostedt no YouTube, dentre elas Understanding the Linux Kernel via Ftrace, See what your computer is doing with Ftrace utilities, Learning the Linux Kernel with tracing e ftrace: Where modifying a running kernel all started.

Embora este artigo não explore o ftrace em detalhes, ele serve de base para artigos futuros em que explorarei o ftrace para medir latências e identificar diferentes tipos de problemas no kernel Linux.

Happy tracing!

Sergio Prado

Navegue
Creative Commons Este trabalho de Sergio Prado é licenciado pelo
Creative Commons BY-NC-SA 3.0.