Usando ftrace

ftrace é uma ferramenta de depuração para entender o que está acontecendo dentro do kernel Linux. As seções a seguir detalham a funcionalidade básica do ftrace, o uso do ftrace com 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. atrace faz o seguinte:

  • Configura o rastreamento do modo de usuário definindo uma propriedade ( debug.atrace.tags.enableflags ).
  • Ativa 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, utilize 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).

Habilitando eventos ftrace

Os nós ftrace sysfs 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 por gravação em nós sysfs, eles não serão redefinidos pelo atrace. Um padrão comum para a ativação de dispositivos Qualcomm é ativar pontos de rastreamento 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 ftrace sem atrace ou systrace, o que é útil quando você deseja rastreamentos somente do kernel (ou se você reservou um tempo para escrever a propriedade de rastreamento do modo de usuário manualmente). Para executar apenas o ftrace:

  1. Defina o tamanho do buffer para um valor grande o suficiente para o 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. Descarte o rastreamento:
    cat /sys/kernel/tracing/trace > /data/local/tmp/trace_output

O trace_output fornece o rastreamento em formato de texto. Para visualizá-lo usando Catapult, obtenha o repositório 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.

Correlacionando eventos

Muitas vezes é útil observar a visualização do 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 nas 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 html2trace da árvore Catapult ( tracing/bin/html2trace ) para descompactar o rastreamento.
  2. Encontre o carimbo de data/hora relativo na visualização da Catapulta.
  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 esta linha não existir (ou se você usou ftrace sem atrace), então 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 evento (ou pelo menos muito próximo dele).

Usando ftrace dinâmico

Quando o systrace e o ftrace padrão são insuficientes, há um último recurso disponível: o ftrace dinâmico . 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 nos kernels de produção por motivos de segurança. No entanto, cada bug difícil de desempenho em 2015 e 2016 foi causado pela raiz usando o ftrace dinâmico. É especialmente poderoso para depurar suspensões ininterruptas porque você pode obter um rastreamento de pilha no kernel toda vez que você pressiona a função que aciona a suspensão ininterrupta. Você também pode depurar seções com interrupções e preempções desabilitadas, o que pode ser muito útil para comprovar 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 no 3.18 ou mais recente e no arm64, ele não estará 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. Recomendamos fortemente a leitura da documentação do ftrace sobre esses tópicos antes de usá-los, pois são poderosos, mas complexos. irqsoff e preemptoff são úteis principalmente para confirmar que os drivers podem estar deixando interrupções ou preempções desligadas por muito tempo.

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

Nesta edição, usar um Pixel XL para tirar uma foto HDR + e girar imediatamente o visor sempre causava erros. Usamos o function profiler para depurar o problema em menos de uma hora. Para acompanhar o exemplo, baixe o arquivo zip de rastreamentos (que também inclui outros rastreamentos mencionados nesta seção), descompacte o arquivo e abra o arquivo trace_30898724.html em seu navegador.

O rastreamento mostra vários threads no processo cameraserver bloqueados em suspensão ininterrupta em ion_client_destroy . Essa é uma função cara, mas deve ser chamada com pouca frequência porque os clientes Ion devem abranger muitas alocações. Inicialmente, a culpa recaiu sobre o código Hexagon em Halide, que era de fato um dos culpados (ele criava um novo cliente para cada alocação de íons e destruía esse cliente quando a alocação era liberada, o que era muito caro). Mudar para um único cliente de íons para todas as alocações da Hexagon melhorou a situação, mas o problema não foi corrigido.

Neste ponto precisamos saber quem está chamando ion_client_destroy , então é hora de usar a função profiler:

  1. Como as funções às vezes são renomeadas pelo compilador, confirme a presença de ion_client_destroy usando:
    cat /sys/kernel/tracing/available_filter_functions | grep ion_client_destroy
  2. Depois de confirmar que está lá, use-o como filtro ftrace:
    echo ion_client_destroy > /sys/kernel/tracing/set_ftrace_filter
  3. Ative o perfilador de função:
    echo function > /sys/kernel/tracing/current_tracer
  4. Ative rastreamentos de pilha sempre que uma função de filtro for chamada:
    echo func_stack_trace > /sys/kernel/tracing/trace_options
  5. Aumente o tamanho do buffer:
    echo 64000 > /sys/kernel/tracing/buffer_size_kb
  6. Ative o rastreamento:
    echo 1 > /sys/kernel/tracing/trace_on
  7. Execute o teste e obtenha o rastreamento:
    cat /sys/kernel/tracing/trace > /data/local/tmp/trace
  8. Visualize o rastreamento para ver muitos rastreamentos de pilha:
        cameraserver-643   [003] ...1    94.192991: ion_client_destroy <-ion_release
    cameraserver-643   [003] ...1    94.192997: <stack trace>
 => ftrace_ops_no_ops
 => ftrace_graph_call
 => ion_client_destroy
 => ion_release
 => __fput
 => ____fput
 => task_work_run
 => do_notify_resume
 => work_pending

Com base na inspeção do driver ion, podemos ver que ion_client_destroy está recebendo spam por uma função de espaço do usuário fechando um fd para /dev/ion , não por um driver de kernel aleatório. Ao pesquisar na base de código do Android por \"/dev/ion\" , encontramos vários drivers de fornecedores fazendo a mesma coisa que o driver Hexagon e abrindo/fechando /dev/ion (criando e destruindo um novo cliente ion) toda vez que precisam de um nova alocação de íons. Alterá-los para usar um único cliente Ion durante a vida útil do processo corrigiu o bug.

Se os dados do function profiler não forem específicos o suficiente, você poderá combinar tracepoints ftrace com o function profiler. Os eventos ftrace podem ser habilitados exatamente da mesma maneira que de costume e serão intercalados com o seu rastreamento. Isso é ótimo se houver uma suspensão longa e ininterrupta 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, o 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 é o último recurso, pois é extremamente difícil trabalhar em dispositivos Android porque aumenta 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 que trabalham na configuração de dispositivos devem descobrir uma maneira de fazer com que essa opção funcione em todos os dispositivos, porque chegará um momento em que você pensará "Se eu pudesse ativar LOCK_STAT , poderia confirmar ou refutar isso como o problema em cinco minutos, em vez de cinco dias."

Neste problema, o encadeamento SCHED_FIFO travou quando todos os núcleos estavam com carga máxima com encadeamentos não SCHED_FIFO. Tivemos rastros mostrando contenção de bloqueio significativa em um fd em aplicativos de VR, mas não conseguimos identificar facilmente o fd em uso. Para acompanhar o exemplo, baixe o arquivo zip de rastreamentos (que também inclui outros rastreamentos mencionados nesta seção), descompacte o arquivo e abra o arquivo trace_30905547.html em seu navegador.

Nossa hipótese era que o próprio ftrace era a fonte da contenção de bloqueio, quando um thread de baixa prioridade começava a gravar no canal ftrace e era interrompido antes que pudesse liberar o bloqueio. Este é o pior cenário que foi exacerbado por uma mistura de threads de prioridade extremamente baixa gravando no marcador ftrace junto com alguns threads de prioridade mais alta girando em CPUs para simular um dispositivo completamente carregado.

Como não pudemos usar o ftrace para depurar, colocamos LOCK_STAT funcionando e desativamos todos os outros rastreamentos do aplicativo. Os resultados mostraram que a contenção de bloqueio era na verdade do ftrace porque nenhuma contenção aparecia no rastreamento de bloqueio quando o ftrace não estava em execução.

Se você puder inicializar um kernel com a opção config, o rastreamento de bloqueio será semelhante ao ftrace:

  1. Habilitar rastreamento:
    echo 1 > /proc/sys/kernel/lock_stat
  2. Execute seu teste.
  3. Desativar rastreamento:
    echo 0 > /proc/sys/kernel/lock_stat
  4. Descarte 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 de fornecedor

Use tracepoints upstream primeiro, mas às vezes você precisará usar tracepoints de fornecedores:

  { "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 adicionar pontos/categorias de rastreamento específicos do dispositivo. Tracepoints são integrados com perfetto, atrace/systrace e aplicativo de rastreamento de sistema no dispositivo.

As APIs para implementação de tracepoints/categorias são:

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