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:
- A EventThread no SurfaceFlinger ativa a linha de execução da interface do app, sinalizando que é hora de renderizar um novo frame.
- 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.
- O app envia o frame renderizado para o SurfaceFlinger usando um binder e, em seguida, o SurfaceFlinger entra no modo de suspensão.
- 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.
- 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.
- 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.