Usando ftrace

ftrace é uma ferramenta de depuração para entender o que está acontecendo dentro do kernel do Linux. As seções a seguir detalham a funcionalidade básica do ftrace, o uso do ftrace com o atrace (que captura eventos do kernel) e o ftrace dinâmico.

Para obter detalhes sobre a funcionalidade avançada do ftrace que não está disponível no systrace, consulte a documentação do ftrace em <kernel tree>/Documentation/trace/ftrace.txt .

Capturando eventos do kernel com atrace

atrace ( frameworks/native/cmds/atrace ) usa ftrace para capturar eventos do kernel. Por sua vez, systrace.py (ou run_systrace.py em versões posteriores do Catapult ) usa adb para executar atrace no dispositivo. atrac faz o seguinte:

  • Configura o rastreamento de modo de usuário definindo uma propriedade ( debug.atrace.tags.enableflags ).
  • Habilita a funcionalidade desejada do ftrace gravando nos nós sysfs do ftrace apropriados. No entanto, como o ftrace suporta mais recursos, você mesmo pode definir alguns nós sysfs e usar o atrace.

Com exceção do rastreamento de tempo de inicialização, use atrace para definir a propriedade com o valor apropriado. A propriedade é uma máscara de bits e não há uma boa maneira de determinar os valores corretos além de observar o cabeçalho apropriado (que pode mudar entre as versões do Android).

Ativando eventos ftrace

Os nós sysfs do ftrace estão em /sys/kernel/tracing e os eventos de rastreamento são divididos em categorias em /sys/kernel/tracing/events .

Para habilitar eventos por categoria, use:

echo 1 > /sys/kernel/tracing/events/irq/enable

Para habilitar eventos por evento, use:

echo 1 > /sys/kernel/tracing/events/sched/sched_wakeup/enable

Se eventos extras foram habilitados gravando em nós sysfs, eles não serão redefinidos pelo atrace. Um padrão comum para a ativação do dispositivo Qualcomm é habilitar os pontos de kgsl (GPU) e mdss (pipeline de exibição) e, em seguida, usar atrace ou systrace :

adb shell "echo 1 > /sys/kernel/tracing/events/mdss/enable"
adb shell "echo 1 > /sys/kernel/tracing/events/kgsl/enable"
./systrace.py sched freq idle am wm gfx view binder_driver irq workq ss sync -t 10 -b 96000 -o full_trace.html

Você também pode usar o ftrace sem atrace ou systrace, o que é útil quando você deseja rastreamentos somente do kernel (ou se você teve tempo para escrever manualmente a propriedade de rastreamento do modo de usuário). Para executar apenas ftrace:

  1. Defina o tamanho do buffer para um valor grande o suficiente para seu rastreamento:
    echo 96000 > /sys/kernel/tracing/buffer_size_kb
    
  2. Habilitar rastreamento:
    echo 1 > /sys/kernel/tracing/tracing_on
    
  3. Execute seu teste e desative o rastreamento:
    echo 0 > /sys/kernel/tracing/tracing_on
    
  4. Despeje o rastreamento:
    cat /sys/kernel/tracing/trace > /data/local/tmp/trace_output
    

O trace_output fornece o rastreamento em forma de texto. Para visualizá-lo usando o Catapult, obtenha o repositório do Catapult no GitHub e execute trace2html:

catapult/tracing/bin/trace2html ~/path/to/trace_file

Por padrão, isso grava trace_file.html no mesmo diretório.

Eventos correlacionados

Muitas vezes, é útil examinar a visualização da Catapult e o log do ftrace simultaneamente; por exemplo, alguns eventos ftrace (especialmente os específicos do fornecedor) não são visualizados pelo Catapult. No entanto, os carimbos de data/hora do Catapult são relativos ao primeiro evento no rastreamento ou a um carimbo de data/hora específico despejado pelo atrace, enquanto os carimbos de data/hora brutos do ftrace são baseados em uma fonte de relógio absoluta específica no kernel do Linux.

Para encontrar um determinado evento ftrace de um evento Catapult:

  1. Abra o log bruto do ftrace. Os rastreamentos em versões recentes do systrace são compactados por padrão:
    • Se você capturou seu systrace com --no-compress , isso está no arquivo html na seção que começa com BEGIN TRACE.
    • Caso contrário, execute o html2trace na árvore do Catapult ( tracing/bin/html2trace ) para descompactar o rastreamento.
  2. Encontre o carimbo de data/hora relativo na visualização do Catapult.
  3. Encontre uma linha no início do rastreamento contendo tracing_mark_sync . Deve ser algo assim:
    <5134>-5134  (-----) [003] ...1    68.104349: tracing_mark_write: trace_event_clock_sync: parent_ts=68.104286
    

    Se essa linha não existir (ou se você usou ftrace sem atrace), os tempos serão relativos ao primeiro evento no log do ftrace.
    1. Adicione o carimbo de data/hora relativo (em milissegundos) ao valor em parent_ts (em segundos).
    2. Procure o novo carimbo de data/hora.

Essas etapas devem colocá-lo no (ou pelo menos muito próximo) do evento.

Usando ftrace dinâmico

Quando o systrace e o ftrace padrão são insuficientes, há um último recurso disponível: dynamic ftrace . O ftrace dinâmico envolve a reescrita do código do kernel após a inicialização e, como resultado, não está disponível em kernels de produção por motivos de segurança. No entanto, cada bug de desempenho difícil em 2015 e 2016 foi causado pela raiz usando o ftrace dinâmico. É especialmente poderoso para depurar sonos ininterruptos porque você pode obter um rastreamento de pilha no kernel toda vez que atingir a função que aciona o sono ininterrupto. Você também pode depurar seções com interrupções e preempções desabilitadas, o que pode ser muito útil para provar problemas.

Para ativar o ftrace dinâmico, edite o defconfig do seu kernel:

  1. Remova CONFIG_STRICT_MEMORY_RWX (se estiver presente). Se você estiver em 3.18 ou mais recente e arm64, não está lá.
  2. Adicione o seguinte: CONFIG_DYNAMIC_FTRACE=y, CONFIG_FUNCTION_TRACER=y, CONFIG_IRQSOFF_TRACER=y, CONFIG_FUNCTION_PROFILER=y e CONFIG_PREEMPT_TRACER=y
  3. Reconstrua e inicialize o novo kernel.
  4. Execute o seguinte para verificar os rastreadores disponíveis:
    cat /sys/kernel/tracing/available_tracers
    
  5. Confirme se o comando retorna function , irqsoff , preemptoff e preemptirqsoff .
  6. Execute o seguinte para garantir que o ftrace dinâmico esteja funcionando:
    cat /sys/kernel/tracing/available_filter_functions | grep <a function you care about>
    

Depois de concluir essas etapas, você terá o ftrace dinâmico, o criador de perfil de função, o criador de perfil irqsoff e o criador de perfil preemptoff disponíveis. É altamente recomendável ler a documentação do ftrace sobre esses tópicos antes de usá-los, pois eles são poderosos, mas complexos. irqsoff e preemptoff são úteis principalmente para confirmar que os drivers podem estar deixando interrupções ou preempção desativadas por muito tempo.

O criador de perfil de função é a melhor opção para problemas de desempenho e geralmente é usado para descobrir onde uma função está sendo chamada.


Se os dados do criador de perfil de função não forem específicos o suficiente, você poderá combinar pontos de rastreamento ftrace com o criador de perfil de função. Os eventos ftrace podem ser habilitados exatamente da mesma maneira que de costume, e eles serão intercalados com seu rastreamento. Isso é ótimo se houver um sono longo e ininterrupto ocasional em uma função específica que você deseja depurar: defina o filtro ftrace para a função desejada, habilite pontos de rastreamento, faça um rastreamento. Você pode analisar o rastreamento resultante com trace2html , encontrar o evento desejado e obter rastreamentos de pilha próximos no rastreamento bruto.

Usando lockstat

Às vezes, ftrace não é suficiente e você realmente precisa depurar o que parece ser uma contenção de bloqueio do kernel. Há mais uma opção de kernel que vale a pena tentar: CONFIG_LOCK_STAT . Este é um último recurso, pois é extremamente difícil trabalhar em dispositivos Android porque infla o tamanho do kernel além do que a maioria dos dispositivos pode suportar.

No entanto, o lockstat usa a infraestrutura de bloqueio de depuração, que é útil para muitos outros aplicativos. Todos os que trabalham na ativação do dispositivo devem descobrir uma maneira de fazer com que essa opção funcione em todos os dispositivos, porque haverá um momento em que você pensará "Se ao menos eu pudesse ativar LOCK_STAT , eu poderia confirmar ou refutar isso como o problema em cinco minutos em vez de cinco dias."


Se você pode inicializar um kernel com a opção de configuração, o rastreamento de bloqueio é semelhante ao ftrace:

  1. Ativar rastreamento:
    echo 1 > /proc/sys/kernel/lock_stat
    
  2. Execute seu teste.
  3. Desativar rastreamento:
    echo 0 > /proc/sys/kernel/lock_stat
    
  4. Despeje seu rastreamento:
    cat /proc/lock_stat > /data/local/tmp/lock_stat
    

Para obter ajuda na interpretação da saída resultante, consulte a documentação do lockstat em <kernel>/Documentation/locking/lockstat.txt .

Usando pontos de rastreamento do fornecedor

Use os pontos de rastreamento upstream primeiro, mas às vezes você precisará usar os pontos de rastreamento do fornecedor:

  { "gfx",        "Graphics",         ATRACE_TAG_GRAPHICS, {
        { OPT,      "events/mdss/enable" },
        { OPT,      "events/sde/enable" },
        { OPT,      "events/mali_systrace/enable" },
    } },

Os pontos de rastreamento são extensíveis pelo serviço HAL, permitindo que você adicione pontos/categorias de rastreamento específicos do dispositivo. Os pontos de rastreamento são integrados ao aplicativo de rastreamento do sistema perfetto, atrace/systrace e no dispositivo.

As APIs para implementar tracepoints/categorias são:

  • listCategories() gera (vec<TracingCategory> categorias);
  • enableCategories(vec<string> categorias) gera (status status);
  • disableAllCategories() gera (status status);
Para obter mais informações, consulte a definição HAL e a implementação padrão no AOSP :