systrace é a principal ferramenta para analisar o desempenho do dispositivo Android. No entanto, é realmente um wrapper em torno de outras ferramentas. É 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 , e o mecanismo de rastreamento primário no kernel do Linux. O systrace usa o atrace para habilitar o rastreamento, depois lê o buffer do ftrace e o envolve em um visualizador HTML independente. (Embora os kernels mais novos tenham suporte para o Linux Enhanced Berkeley Packet Filter (eBPF), a documentação a seguir pertence ao kernel 3.18 (sem eFPF), pois é o que foi usado no Pixel/Pixel XL.)
systrace é de propriedade das equipes Google Android e 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 podem ser habilitados diretamente pelo systrace ou atrace e contém algumas funcionalidades avançadas que são críticas para depurar problemas de desempenho. (Esses recursos exigem acesso root e geralmente um novo kernel.)
Executando systrace
Ao depurar o 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 GPU e atividade de pipeline de exibição, isso oferece a capacidade de rastrear desde a entrada do usuário até o quadro exibido na tela. Defina o tamanho do buffer para algo grande para evitar a perda de eventos (porque sem um buffer grande algumas CPUs não contêm eventos após algum ponto no rastreamento).
Ao passar pelo systrace, lembre-se de que todo evento é acionado por algo na CPU .
Como o systrace é construído sobre o ftrace e o ftrace é executado na CPU, algo na CPU deve gravar o buffer ftrace que registra as alterações de hardware. Isso significa que, se você estiver curioso para saber por que uma cerca de exibição mudou de estado, poderá ver o que estava sendo executado na CPU no ponto exato de sua transição (algo em execução na CPU acionou essa alteração no log). 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 do usuário normal. 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 systrace_tutorial.html em seu navegador. Esteja avisado que este systrace é um arquivo grande; a menos que você use systrace em seu trabalho diário, esse é provavelmente um rastreamento muito maior com muito mais informações do que você já viu em um único rastreamento antes.
Para uma carga de trabalho consistente e periódica, como TouchLatency, o pipeline de IU contém o seguinte:
- EventThread no SurfaceFlinger ativa o thread de interface do usuário do aplicativo, sinalizando que é hora de renderizar um novo quadro.
- O aplicativo renderiza um quadro no thread da interface do usuário, RenderThread e hwuiTasks, usando recursos de CPU e GPU. Essa é a maior parte da capacidade gasta para a interface do usuário.
- O aplicativo envia o quadro renderizado para o SurfaceFlinger usando um fichário e, em seguida, o SurfaceFlinger entra em suspensão.
- Um segundo EventThread no SurfaceFlinger ativa o SurfaceFlinger para acionar a composição e exibir a saída. Se o SurfaceFlinger determinar que não há trabalho a ser feito, ele volta a dormir.
- O SurfaceFlinger manipula a composição usando o Hardware Composer (HWC)/Hardware Composer 2 (HWC2) ou GL. A composição HWC/HWC2 é mais rápida e com menor consumo de energia, mas tem limitações dependendo do sistema em um chip (SoC). Isso geralmente leva de 4 a 6 ms, mas pode se sobrepor à etapa 2 porque os aplicativos Android são sempre triplos em buffer. (Enquanto os aplicativos são sempre armazenados em buffer triplo, pode haver apenas um quadro pendente aguardando no SurfaceFlinger, o que faz com que pareça idêntico ao buffer duplo.)
- O SurfaceFlinger despacha a saída final para exibição com um driver do fornecedor e volta a dormir, aguardando a ativação do EventThread.
Vamos percorrer o quadro começando em 15409 ms:
A Figura 1 é um quadro normal cercado por quadros normais, portanto, é um bom ponto de partida para entender como o pipeline da interface do usuário funciona. A linha de thread da interface do usuário para TouchLatency inclui cores diferentes em momentos diferentes. As barras denotam diferentes estados para o thread:
- Cinza . Dormindo.
- Azul. Executável (pode ser executado, mas o agendador ainda não o escolheu para ser executado).
- Verde. Ativamente rodando (o agendador pensa que está rodando).
- Vermelho. Sono ininterrupto (geralmente dormindo em um bloqueio no kernel). Pode ser indicativo de carga de E/S. Extremamente útil para depurar problemas de desempenho.
- Laranja. Suspensão ininterrupta devido à carga de E/S.
Para visualizar o motivo da suspensão ininterrupta (disponível no sched_blocked_reason ), selecione a fatia vermelha de suspensão ininterrupta.
Enquanto EventThread está em execução, o thread de interface do usuário para TouchLatency torna-se executável. Para ver o que o despertou, clique na seção azul.
A Figura 2 mostra que o thread de interface do usuário TouchLatency foi ativado pelo tid 6843, que corresponde a EventThread. O thread de interface do usuário é ativado, renderiza um quadro e o enfileira para o SurfaceFlinger consumir.
Se a tag binder_driver estiver habilitada em um rastreamento, você poderá selecionar uma transação do binder para visualizar informações sobre todos os processos envolvidos nessa transação.
A Figura 4 mostra que, a 15.423,65 ms Binder:6832_1 no SurfaceFlinger se torna executável devido ao tid 9579, que é o RenderThread do TouchLatency. Você também pode ver queueBuffer em ambos os lados da transação do binder.
Durante o queueBuffer no lado do SurfaceFlinger, o número de quadros pendentes do TouchLatency vai de 1 a 2.
A Figura 5 mostra o buffer triplo, onde há dois quadros concluídos e o aplicativo está prestes a começar a renderizar um terceiro. Isso ocorre porque já descartamos alguns quadros, então o aplicativo mantém dois quadros pendentes em vez de um para tentar evitar mais quadros descartados.
Logo depois, o thread principal do SurfaceFlinger é ativado por um segundo EventThread para que ele possa enviar o quadro pendente mais antigo para a tela:
O SurfaceFlinger primeiro trava o buffer pendente mais antigo, o que faz com que a contagem de buffer pendente diminua de 2 para 1.
Depois de travar o buffer, o SurfaceFlinger configura a composição e envia o quadro final para a exibição. (Algumas dessas seções são habilitadas como parte do mdss , portanto, elas podem não ser incluídas em seu SoC.)
Em seguida, mdss_fb0 ativado na CPU 0. mdss_fb0 é o thread do kernel do pipeline de exibição para a saída de um quadro renderizado para a exibição. Podemos ver mdss_fb0 como sua própria linha no rastreamento (role para baixo para visualizar).
mdss_fb0 acorda, é executado brevemente, entra em suspensão ininterrupta e, em seguida, acorda novamente.
Exemplo: estrutura não funcional
Este exemplo descreve um systrace usado para depurar o jitter Pixel/Pixel XL. Para acompanhar o exemplo, baixe o arquivo zip de rastreamentos (que inclui outros rastreamentos mencionados nesta seção), descompacte o arquivo e abra o arquivo systrace_tutorial.html em seu navegador.
Ao abrir o systrace, você verá algo assim:
Ao procurar por jank, verifique a linha FrameMissed em SurfaceFlinger. FrameMissed é uma melhoria de qualidade de vida fornecida pelo HWC2. Ao visualizar systrace para outros dispositivos, a linha FrameMissed pode não estar presente se o dispositivo não usar HWC2. Em ambos os casos, FrameMissed está correlacionado com SurfaceFlinger faltando um de seus tempos de execução extremamente regulares e uma contagem de buffer pendente inalterada para o aplicativo ( com.prefabulated.touchlatency ) em um vsync.
A Figura 11 mostra um quadro perdido em 15598,29&nbps;ms. O SurfaceFlinger acordou brevemente no intervalo do 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 quadro para a tela novamente. Por quê?
Para entender como o pipeline foi dividido para esse quadro, primeiro revise o exemplo do quadro de trabalho acima para ver como um pipeline de IU normal aparece no systrace. Quando estiver pronto, retorne ao quadro perdido e trabalhe para trás. Observe que o SurfaceFlinger acorda e imediatamente adormece. Ao visualizar o número de quadros pendentes do TouchLatency, há dois quadros (uma boa pista para ajudar a descobrir o que está acontecendo).
Como temos quadros no SurfaceFlinger, não é um problema de aplicativo. Além disso, o SurfaceFlinger está despertando na hora correta, portanto, não é um problema do SurfaceFlinger. Se o SurfaceFlinger e o aplicativo parecerem normais, provavelmente é um problema de driver.
Como os pontos de rastreamento mdss e de sync estão habilitados, podemos obter informações sobre as cercas (compartilhadas entre o driver de exibição e o SurfaceFlinger) que controlam quando os quadros são enviados para a exibição. Essas cercas estão listadas em mdss_fb0_retire , que indica quando um quadro está na tela. Essas cercas são fornecidas como parte da categoria de rastreamento de sync . Quais fences correspondem a eventos específicos no SurfaceFlinger depende do seu SOC e pilha de driver, então trabalhe com seu fornecedor SOC para entender o significado das categorias de fence em seus rastreamentos.
A Figura 13 mostra um quadro que foi exibido por 33 ms, não 16,7 ms como esperado. No meio dessa fatia, esse quadro deveria ter sido substituído por um novo, mas não foi. Veja o quadro anterior e procure por qualquer coisa.
A Figura 14 mostra 14,482 ms por quadro. O segmento quebrado de dois quadros foi de 33,6 ms, que é aproximadamente o que esperávamos para dois quadros (renderizamos a 60 Hz, 16,7 ms por quadro, o que é próximo). Mas 14,482 ms não chega nem perto de 16,7 ms, sugerindo que algo está muito errado com o tubo de exibição.
Investigue exatamente onde essa cerca termina para determinar o que a controla.
Uma fila de trabalho contém __vsync_retire_work_handler , que está em execução quando a cerca é alterada. Olhando através da fonte do kernel, você pode ver que é parte do driver de vídeo. Parece estar no caminho crítico para o pipeline de exibição, portanto, deve ser executado o mais rápido possível. É executável para 70 nós ou mais (não é um longo atraso de agendamento), mas é uma fila de trabalho e pode não ser agendado com precisão.
Verifique o quadro anterior para determinar se isso contribuiu; às vezes, o jitter pode aumentar com o tempo e, eventualmente, causar um prazo perdido.
A linha executável no kworker não é visível porque o visualizador a torna branca quando é selecionada, mas as estatísticas contam a história: 2,3 ms de atraso do agendador para parte do caminho crítico do pipeline de exibição é ruim . Antes de continuar, corrija o atraso movendo esta parte do caminho crítico do pipeline de exibição de uma fila de trabalho (que é executada como um thread SCHED_OTHER CFS) para um SCHED_FIFO SCHED_FIFO dedicado. Essa função precisa de garantias de tempo que as filas de trabalho não podem (e não pretendem) fornecer.
Será este o motivo do engasgo? É difícil dizer de forma conclusiva. Fora dos casos fáceis de diagnosticar, como a contenção de bloqueio do kernel, causando a suspensão de threads críticos de exibição, os rastreamentos geralmente não especificam o problema. Esse jitter poderia ter sido a causa da queda do quadro? Absolutamente. Os tempos de cerca devem ser de 16,7 ms, mas não estão nem perto disso nos quadros que levam ao quadro descartado. Dado o quão fortemente acoplado é o pipeline de exibição, é possível que o jitter em torno dos tempos da cerca tenha resultado em um quadro perdido.
Neste exemplo, a solução envolveu converter __vsync_retire_work_handler de uma fila de trabalho para um kthread dedicado. Isso resultou em melhorias perceptíveis no jitter e na redução do jank no teste da bola quicando. Traços subsequentes mostram tempos de cerca que pairam muito perto de 16,7 ms.