Entender o Systrace

O systrace é a principal ferramenta para analisar o desempenho do dispositivo Android. No entanto, ele é realmente um wrapper para outras ferramentas. Ele é o wrapper do lado do host em torno do atrace, o executável do lado do dispositivo que controla o rastreamento do espaço do usuário e configura o ftrace, além do mecanismo de rastreamento principal no kernel do Linux. O systrace usa o atrace para ativar o rastreamento, depois lê o buffer do ftrace e o agrupa em um visualizador HTML independente. Embora kernels mais recentes tenham suporte ao filtro de pacote Berkeley estendido (eBPF) do Linux, a documentação a seguir se refere ao kernel 3.18 (sem eFPF), que foi usado no Pixel/Pixel XL.

O systrace é propriedade das equipes do Google Android e do Google Chrome e é de código aberto como parte do projeto Catapult. Além do systrace, o Catapult inclui outros utilitários úteis. Por exemplo, o ftrace tem mais recursos do que os que podem ser ativados diretamente pelo systrace ou atrace e contém algumas funcionalidades avançadas que são essenciais para depurar problemas de performance. Esses recursos exigem acesso à raiz e, geralmente, um novo kernel.

Executar systrace

Ao depurar jitter no Pixel/Pixel XL, comece com o seguinte comando:

./systrace.py sched freq idle am wm gfx view sync binder_driver irq workq input -b 96000

Quando combinado com os pontos de rastreamento adicionais necessários para a atividade de pipeline de GPU e exibição, isso permite rastrear da entrada do usuário até o frame exibido na tela. Defina o tamanho do buffer como algo grande para evitar a perda de eventos. Isso acontece porque, sem um buffer grande, algumas CPUs não contêm eventos após alguns pontos no trace.

Ao analisar o systrace, lembre-se de que cada evento é acionado por algo na CPU.

Como o systrace é criado com base no ftrace e o ftrace é executado na CPU, algo na CPU precisa gravar o buffer do ftrace que registra as mudanças de hardware. Isso significa que, se você quiser saber por que uma cerca de exibição mudou de estado, é possível conferir o que estava sendo executado na CPU no momento exato da transição (algo executado na CPU acionou essa mudança no registro). Esse conceito é a base da análise de desempenho usando o systrace.

Exemplo: quadro de trabalho

Este exemplo descreve um systrace para um pipeline de interface normal. Para acompanhar o exemplo, faça o download do arquivo ZIP de rastros (que também inclui outros rastros mencionados nesta seção), descompacte o arquivo e abra o arquivo systrace_tutorial.html no navegador. Esse systrace é um arquivo grande. A menos que você use o systrace no seu trabalho diário, ele provavelmente é um rastro muito maior com muito mais informações do que você já conheceu em um único rastro.

Para uma carga de trabalho consistente e periódica, como TouchLatency, o pipeline da interface contém o seguinte:

1. A EventThread no SurfaceFlinger ativa a linha de execução da interface do app, sinalizando que é hora de renderizar um novo frame.
2. O app renderiza um frame na linha de execução de interface, RenderThread e hwuiTasks, usando recursos de CPU e GPU. Esse é o maior gasto de capacidade da interface.
3. O app envia o frame renderizado para o SurfaceFlinger usando um binder e, em seguida, o SurfaceFlinger entra no modo de suspensão.
4. Uma segunda linha de execução de evento no SurfaceFlinger ativa o SurfaceFlinger para acionar a composição e mostrar a saída. Se o SurfaceFlinger determinar que não há trabalho a ser feito, ele volta a dormir.
5. O SurfaceFlinger processa a composição usando o Hardware Composer (HWC)/Hardware Composer 2 (HWC2) ou o GL. A composição HWC/HWC2 é mais rápida e consome menos energia, mas tem limitações dependendo do sistema em um chip (SoC). Isso geralmente leva cerca de 4 a 6 ms, mas pode se sobrepor à etapa 2 porque os apps Android são sempre armazenados em buffer triplo. Embora os apps sempre tenham buffer triplo, pode haver apenas um frame pendente aguardando no SurfaceFlinger, o que faz com que ele pareça idêntico ao buffer duplo.
6. O SurfaceFlinger envia a saída final para exibição com um driver do fornecedor e volta a dormir, aguardando a ativação do EventThread.

Vamos analisar o frame que começa em 15409 ms:

A Figura 1 é um frame normal cercado por frames normais, então é um bom ponto de partida para entender como o pipeline da interface funciona. A linha de encadeamento da interface para TouchLatency inclui cores diferentes em momentos diferentes. As barras indicam diferentes estados da linha de execução:

• Cinza. Dormir.
• Azul. Runnable (pode ser executado, mas o programador ainda não o escolheu para execução).
• Verde. Em execução ativa (o programador acha que está em execução).
• Vermelho. Sono ininterrupto (geralmente em um bloqueio no kernel). Pode indicar carga de E/S. Extremamente útil para depurar problemas de desempenho.
• Laranja. Modo de suspensão ininterrupto devido à carga de E/S.

Para conferir o motivo do modo de suspensão ininterruptível (disponível no ponto de rastreamento sched_blocked_reason), selecione o segmento de suspensão ininterruptível vermelho.

Enquanto a EventThread está em execução, a linha de execução de interface para TouchLatency se torna executável. Para saber o que ativou o sensor, clique na seção azul.

A Figura 2 mostra que a linha de execução da interface TouchLatency foi ativada pelo tid 6843, que corresponde a EventThread. A linha de execução da interface é ativada, renderiza um frame e o enfileira para que o SurfaceFlinger o consuma.

Se a tag binder_driver estiver ativada em um rastro, você poderá selecionar uma transação de vinculação para conferir informações sobre todos os processos envolvidos nessa transação.

A Figura 4 mostra que, em 15.423,65 ms, o Binder:6832_1 no SurfaceFlinger fica executável devido à tid 9579, que é a RenderThread do TouchLatency. Você também pode ver queueBuffer em ambos os lados da transação de vinculação.

Durante o queueBuffer no lado do SurfaceFlinger, o número de frames pendentes de TouchLatency passa de 1 para 2.

A Figura 5 mostra o buffer triplo, em que há dois frames concluídos e o app está prestes a renderizar um terceiro. Isso acontece porque já descartamos alguns frames. Portanto, o app mantém dois frames pendentes em vez de um para tentar evitar outros frames descartados.

Logo depois, a linha de execução principal do SurfaceFlinger é ativada por uma segunda linha de execução de evento para poder exibir o frame pendente mais antigo na tela:

O SurfaceFlinger primeiro fixa o buffer pendente mais antigo, o que faz com que a contagem de buffers pendentes diminua de 2 para 1.

Depois de travar o buffer, o SurfaceFlinger configura a composição e envia o frame final para a tela. Algumas dessas seções são ativadas como parte do ponto de rastreamento mdss, portanto, elas podem não ser incluídas no SoC.

Em seguida, mdss_fb0 é ativado na CPU 0. mdss_fb0 é a linha de exibição do kernel para a saída de um frame renderizado para a tela. Podemos ver mdss_fb0 como uma linha própria no trace (role para baixo para visualizar).

O mdss_fb0 é ativado, é executado brevemente, entra em suspensão ininterrupta e é ativado novamente.

Exemplo: frame inativo

Este exemplo descreve um systrace usado para depurar o jitter do Pixel/Pixel XL. Para seguir o exemplo, faça o download do arquivo ZIP de rastros (que inclui outros rastros mencionados nesta seção), descompacte o arquivo e abra o arquivo systrace_tutorial.html no navegador.

Ao abrir o systrace, você vai encontrar algo como:

Ao procurar por instabilidade, verifique a linha "FrameMissed" em "SurfaceFlinger". O frame perdido é uma melhoria na qualidade de vida fornecida pelo HWC2. Ao visualizar o systrace para outros dispositivos, a linha "FrameMissed" pode não estar presente se o dispositivo não usar o HWC2. Em ambos os casos, o FrameMissed está correlacionado com o SurfaceFlinger perdendo um dos runtimes extremamente regulares e uma contagem de buffer pendente inalterada para o app (com.prefabulated.touchlatency) em um vsync.

A Figura 11 mostra um frame perdido em 15598,29&nbps;ms. O SurfaceFlinger foi ativado brevemente no intervalo de vsync e voltou a dormir sem fazer nenhum trabalho, o que significa que o SurfaceFlinger determinou que não valia a pena tentar enviar um frame para a tela novamente. Por quê?

Para entender como o pipeline foi dividido para esse frame, primeiro revise o exemplo de frame de trabalho acima para ver como um pipeline de interface normal aparece no systrace. Quando estiver tudo pronto, volte ao frame perdido e volte atrás. Observe que o SurfaceFlinger é ativado e entra no modo de suspensão imediatamente. Ao conferir o número de frames pendentes do TouchLatency, há dois frames (uma boa pista para descobrir o que está acontecendo).

Como temos frames no SurfaceFlinger, não é um problema do app. Além disso, o SurfaceFlinger está sendo ativado no momento certo, então não é um problema do SurfaceFlinger. Se o SurfaceFlinger e o app parecerem normais, provavelmente é um problema de driver.

Como os pontos de trace mdss e sync estão ativados, é possível receber informações sobre as cercas (compartilhadas entre o driver de exibição e o SurfaceFlinger) que controlam quando os frames são enviados para a tela. Essas cercas são listadas em mdss_fb0_retire, que denotam quando um frame está na tela. Essas cercas são fornecidas como parte da categoria de rastreamento sync. Quais cercas correspondem a eventos específicos no SurfaceFlinger dependem do SOC e da pilha de drivers. Portanto, trabalhe com o fornecedor do SOC para entender o significado das categorias de cerca nos rastreamentos.

A Figura 13 mostra um frame que foi exibido por 33 ms, e não 16,7 ms, como esperado. Na metade desse intervalo, esse frame deveria ter sido substituído por um novo, mas não foi. Confira o frame anterior e procure por algo.

A Figura 14 mostra 14,482 ms por frame. O segmento de dois frames quebrado foi de 33,6 ms, o que é aproximadamente o que esperaríamos para dois frames (renderizamos a 60 Hz, 16,7 ms por frame, que é próximo). No entanto, 14,482 ms não está nem perto de 16,7 ms, o que sugere que algo está muito errado com o pipe de exibição.

Investigue exatamente onde a cerca termina para determinar o que a controla.

Um workqueue contém __vsync_retire_work_handler, que é executado quando a cerca muda. Analisando a origem do kernel, é possível ver que ele faz parte do driver de exibição. Ele parece estar no caminho crítico do pipeline de exibição, então precisa ser executado o mais rápido possível. Ele pode ser executado por cerca de 70 us (não é um atraso de programação longo), mas é um trabalho em lote e pode não ser programado com precisão.

Verifique o frame anterior para determinar se ele contribuiu. Às vezes, o jitter pode se acumular ao longo do tempo e acabar causando um prazo perdido.

A linha executável no kworker não fica visível porque o visualizador a torna branca quando ela é selecionada, mas as estatísticas contam a história: 2,3 ms de atraso do programador para parte do caminho crítico do pipeline de exibição é ruim. Antes de continuar, corrija o atraso movendo essa parte do caminho crítico do pipeline de exibição de um workqueue (que é executado como uma linha de execução SCHED_OTHER CFS) para uma SCHED_FIFO kthread dedicada. Essa função precisa de garantias de tempo que as filas de trabalho não podem (e não devem) fornecer.

É esse o motivo do problema? É difícil dizer com certeza. Fora de casos fáceis de diagnosticar, como a contenção de bloqueio do kernel que faz com que as linhas críticas da exibição entrem em suspensão, os rastros geralmente não especificam o problema. Esse jitter pode ter sido a causa da perda de frame? Com certeza. Os tempos de cerca devem ser de 16,7 ms, mas não estão nem perto disso nos frames que levam ao frame descartado. Considerando a forte acoplamento do pipeline de exibição, é possível que o jitter em torno dos tempos de cerca tenha resultado em um frame perdido.

Neste exemplo, a solução envolveu a conversão de __vsync_retire_work_handler de um workqueue para uma kthread dedicada. Isso resultou em melhorias perceptíveis no jitter e reduziu o jank no teste da bola saltitante. Os rastros seguintes mostram tempos de cerca que ficam muito próximos de 16,7 ms.