Usar ftrace

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

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

Capturar eventos do kernel com o atrace

o atrace (frameworks/native/cmds/atrace) usa ftrace para capturar eventos do kernel. Por sua vez, o systrace.py (ou run_systrace.py em versões posteriores do Catapult) usa o adb. para executar o atrace no dispositivo. O 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 no nós do ftrace. No entanto, como o ftrace é compatível com mais recursos, você pode definir alguns nós do sysfs e, em seguida, use o atrace.

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

Ativar eventos ftrace

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

Para ativar eventos por categoria, use: 

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

Para ativar eventos por evento, use: 

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

Se eventos extras tiverem sido ativados ao gravar nos nós sysfs, eles não podem ser redefinidos pelo atrace. Um padrão comum para a exibição do dispositivo Qualcomm é ativar kgsl (GPU) e mdss (pipeline de exibição) e depois 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, que são útil quando você quer traces somente do kernel (ou se você se esforçou para escrever a propriedade de rastreamento do modo de usuário manualmente). Para executar apenas ftrace:

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

O trace_output fornece o trace em forma de texto. Para visualizá-lo usando Catapult, pegue a Catapult repositório (em inglês) do GitHub e execute trace2html:

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

Por padrão, isso grava trace_file.html na mesma diretório.

Correlacionar eventos

A visualização da Catapult e do ftrace pode ser útil registrar simultaneamente; por exemplo, alguns eventos ftrace (especialmente específicos do fornecedor não são visualizados pela Catapult. No entanto, os carimbos de data/hora da Catapult são em relação ao primeiro evento no trace ou a um carimbo de data/hora específico despejados pelo atrace, enquanto os carimbos de data/hora de ftrace brutos são baseados em um determinado origem absoluta do relógio no kernel do Linux.

Para encontrar um determinado evento ftrace em um evento do Catapult:

  1. Abra o registro ftrace bruto. Os traces em versões recentes do Systrace são compactado por padrão:
    • Se você capturou o Systrace com --no-compress, ele está o arquivo html na seção que começa com BEGIN TRACE.
    • Caso contrário, execute o html2trace na Catapult árvore (tracing/bin/html2trace) para descompactar o rastro.
  2. Encontre o carimbo de data/hora relativo na visualização do Catapult.
  3. Encontrar uma linha no início do trace que contenha tracing_mark_sync: O código será semelhante a este: 
    <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ê tiver usado ftrace sem atrace), os tempos serão relativos a partir do primeiro evento no registro do ftrace.
    1. Adicione o carimbo de data/hora relativo (em milissegundos) ao valor em parent_ts (em segundos).
    2. Pesquise o novo carimbo de data/hora.

Essas etapas devem colocar você no evento (ou pelo menos muito próximo dele).

Usar ftrace dinâmico

Quando o Systrace e o ftrace padrão não são suficientes, há uma última recurso disponível: ftrace dinâmico O ftrace dinâmico envolve reescrever do código do kernel após a inicialização e, por isso, não fica disponível na produção os kernels por motivos de segurança. No entanto, todos os bugs de desempenho difíceis A causa raiz de 2015 e 2016 foi o uso de ftrace dinâmico. É especialmente eficiente para depurar períodos de inatividade ininterruptos porque você pode conseguir um stack trace no kernel toda vez que você clica na função que aciona a suspensão ininterrupta. Também é possível depurar seções com interrupções e preempções desativadas, o que pode ser muito úteis 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 usando a versão 3.18 ou mais recente e arm64, 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. Recrie e inicialize o novo kernel.
  4. Execute o seguinte comando 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 comando para garantir o funcionamento do ftrace dinâmico: 
    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 Profiler irqsoff e o criador de perfil preemptoff estão disponíveis. Nós forçamos recomendamos a leitura da documentação do ftrace sobre esses tópicos antes de usar porque são poderosos, mas complexos. irqsoff e preemptoff são, principalmente, útil para confirmar se os motoristas estão deixando para trás desativada por muito tempo.

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

Nesse problema, usar um Pixel XL para tirar uma foto HDR+ e imediatamente girava o visor sempre que ficava instável. Usamos o criador de perfil de função para e depurar o problema em menos de uma hora. Para acompanhar o exemplo, fazer o download do arquivo zip dos rastros (que também incluir outros traces mencionados nesta seção), descompacte o arquivo e abra o trace_30898724.html no navegador.

O rastro mostra várias linhas de execução bloqueadas no processo do servidor da câmera suspensão ininterrupta às ion_client_destroy. Esse é um sistema função de íon, mas não deve ser chamado com muita frequência porque é provável que os abrangem muitas alocações. Inicialmente, a culpa estava no código Hexagon Halide, que era um dos culpados (criava um novo cliente para cada alocação de íons e destruíram aquele cliente quando a alocação foi liberada, o que era muito caro). Migração para um único cliente de íons para todo o Hexágono alocações melhoraram a situação, mas a instabilidade não foi corrigida.

Agora, precisamos saber quem está ligando para ion_client_destroy, então é hora de usar o criador de perfil de função:

  1. Como as funções às vezes são renomeadas pelo compilador, confirme ion_client_destroy está lá usando: 
    cat /sys/kernel/tracing/available_filter_functions | grep ion_client_destroy
  2. Depois de confirmar que está lá, use-o como o filtro ftrace: 
    echo ion_client_destroy > /sys/kernel/tracing/set_ftrace_filter
  3. Ative o criador de perfil de função: 
    echo function > /sys/kernel/tracing/current_tracer
  4. Ative os stack traces 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 receba o trace: 
    cat /sys/kernel/tracing/trace > /data/local/tmp/trace
  8. Abra o rastro para encontrar vários stack traces: 
        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 de íons, podemos ver que ion_client_destroy está recebendo spam pelo fechamento de uma função do espaço do usuário um fd para /dev/ion, não um driver de kernel aleatório. Ao pesquisar no Base de código do Android para \"/dev/ion\", encontramos vários drivers de fornecedores fazer a mesma coisa que o driver Hexagon e abrir/fechar /dev/ion (criando e destruindo um novo cliente iônico) toda vez que ele precisam de uma nova alocação de íons. Alterar para usar um único cliente ion durante o ciclo de vida do processo corrigiu o bug.

Se os dados do criador de perfil de função não forem específicos o suficiente, será possível combinar tracepoints ftrace com o criador de perfil de função. Os eventos ftrace podem ser ativados exatamente da mesma forma que de costume, e eles serão intercalados com seu rastro. Isso é ótimo quando há um sono longo e ininterrupto ocasional em um horário específico que você quer depurar: defina o filtro ftrace para a função desejada ativar tracepoints, capturar trace. É possível analisar o rastro resultante com trace2html, encontre o evento que você quer e acesse stack traces próximos no rastreamento bruto.

Usar bloqueio estatístico

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

No entanto, o lockstat usa o valor de infraestrutura de bloqueio, o que é útil para muitos outros apps. Todos ao trabalhar na exibição do dispositivo deve descobrir uma maneira de fazer essa opção funcionar. em todos os dispositivos, porque haverá momento em que você pensará "Se eu pudesse ativar o LOCK_STAT, poderia confirmar ou refutar isso como o problema em cinco minutos em vez de cinco dias".

Nesse problema, a linha de execução SCHED_FIFO parou quando todos os núcleos estavam no máximo carregado com threads não-SCHED_FIFO. Tínhamos rastros mostrando um bloqueio significativo contenção de um fd em aplicativos de RV, mas não conseguimos identificar facilmente o fd em uso. Para acompanhar o exemplo, faça o download do arquivo de traces (que também inclui outros traces mencionados neste ), descompacte o arquivo e abra o arquivo trace_30905547.html no navegador.

Nossa hipótese era que o próprio ftrace fosse a fonte da contenção de bloqueio, quando um de baixa prioridade começaria a gravar no pipe ftrace e depois ou interrompida antes de liberar o bloqueio. Esse é o pior cenário foi exacerbado por um conjunto de linhas de execução de prioridade extremamente baixa gravando no marcador ftrace junto com algumas linhas de execução de prioridade mais alta girando nas CPUs para para simular um dispositivo completamente carregado.

Como não foi possível usar o ftrace para depuração, temos LOCK_STAT funcionando e desativou todos os outros rastreamentos do app. Os resultados mostraram que o bloqueio contenção na verdade foi de ftrace porque nenhuma contenção apareceu em o trace de bloqueio quando o ftrace não estava em execução.

Se for possível inicializar um kernel com a opção de configuração, o rastreamento de bloqueio será semelhante à ftrace:

  1. Ative o rastreamento: 
    echo 1 > /proc/sys/kernel/lock_stat
  2. Execute o teste.
  3. Desative o rastreamento: 
    echo 0 > /proc/sys/kernel/lock_stat
  4. Despeje seu rastro: 
    cat /proc/lock_stat > /data/local/tmp/lock_stat

Se precisar de ajuda para interpretar a saída resultante, consulte a documentação da lockstat em <kernel>/Documentation/locking/lockstat.txt.

Usar tracepoints do fornecedor

Use os tracepoints upstream primeiro, mas às vezes você vai precisar usar os tracepoints 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 adicionar rastros específicos do dispositivo pontos/categorias. Os pontos de rastreamento são integrados ao perfetto, atrace/systrace e sistemas no dispositivo app de rastreamento padrão.

As APIs para implementar pontos de rastreamento/categorias são:

  • listCategories()generates (vec<TracingCategory>>);
  • enableCategories(vec<string>>) gera (status de status);
  • desativaAllCategories() gera (status de status);
. Para mais informações, consulte a definição da HAL e a implementação padrão em AOSP: