systrace é a principal ferramenta para analisar o desempenho de dispositivos Android. No entanto, é realmente um invólucro de outras ferramentas. É o wrapper do lado do host em torno de atrace , o executável do lado do dispositivo que controla o rastreamento do espaço do usuário e configura ftrace , e o mecanismo de rastreamento primário no kernel do Linux. systrace usa atrace para ativar o rastreamento, depois lê o buffer ftrace e agrupa tudo em um visualizador HTML independente. (Embora os kernels mais recentes tenham suporte para Linux Enhanced Berkeley Packet Filter (eBPF), a documentação a seguir refere-se ao kernel 3.18 (sem eFPF), pois foi o que foi usado no Pixel/Pixel XL.)
systrace é 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 possui 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 requerem acesso root e muitas vezes um novo kernel.)
Executando o 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 a GPU e a atividade do pipeline de exibição, isso permite 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 do 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 do 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). Este conceito é a base da análise de desempenho usando o systrace.
Exemplo: Estrutura de trabalho
Este exemplo descreve um systrace para um pipeline de UI 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 o systrace em seu trabalho diário, este é 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 periódica e consistente, como TouchLatency, o pipeline de UI contém o seguinte:
- EventThread no SurfaceFlinger ativa o thread de UI do aplicativo, sinalizando que é hora de renderizar um novo quadro.
- O aplicativo renderiza um quadro em thread de UI, RenderThread e hwuiTasks, usando recursos de CPU e GPU. Esta é a maior parte da capacidade gasta para a IU.
- 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 desperta 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 voltará a dormir.
- SurfaceFlinger lida com composição usando Hardware Composer (HWC)/Hardware Composer 2 (HWC2) ou GL. A composição HWC/HWC2 é mais rápida e de 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 sempre têm buffer triplo. (Embora os aplicativos sejam sempre com buffer triplo, pode haver apenas um quadro pendente aguardando no SurfaceFlinger, o que faz com que pareça idêntico ao buffer duplo.)
- 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 15.409 ms:
A Figura 1 é um quadro normal cercado por quadros normais, portanto é um bom ponto de partida para entender como funciona o pipeline da UI. A linha de thread da UI para TouchLatency inclui cores diferentes em momentos diferentes. As barras indicam estados diferentes para o thread:
- Cinza . Dormindo.
- Azul. Executável (poderia ser executado, mas o agendador ainda não o escolheu para execução).
- Verde. Em execução ativa (o agendador pensa que está em execução).
- 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 do sono ininterrupto (disponível no tracepoint sched_blocked_reason ), selecione a fatia vermelha do sono ininterrupto.
Enquanto EventThread está em execução, o thread de UI para TouchLatency torna-se executável. Para ver o que o acordou, clique na seção azul.
A Figura 2 mostra que o thread da interface do usuário TouchLatency foi ativado pelo tid 6843, que corresponde a EventThread. O thread da UI é ativado, renderiza um quadro e o coloca na fila para o consumo do SurfaceFlinger.
Se a tag binder_driver estiver ativada em um rastreio, 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, aos 15.423,65 ms, Binder:6832_1 no SurfaceFlinger se torna executável por causa do tid 9579, que é o RenderThread do TouchLatency. Você também pode ver queueBuffer em ambos os lados da transação do fichário.
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 perdidos.
Logo depois, o thread principal do SurfaceFlinger é ativado por um segundo EventThread para que possa enviar o quadro pendente mais antigo para o display:
O SurfaceFlinger primeiro trava o buffer pendente mais antigo, o que faz com que a contagem do 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 tracepoint mdss , portanto, podem não estar incluídas no seu SoC.)
Em seguida, mdss_fb0 desperta na CPU 0. mdss_fb0 é o thread do kernel do pipeline de exibição para enviar 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 depois acorda novamente.
Exemplo: quadro não funcional
Este exemplo descreve um systrace usado para depurar o jitter do 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 instabilidade, verifique a linha FrameMissed em SurfaceFlinger. FrameMissed é uma melhoria de qualidade de vida fornecida pelo HWC2. Ao visualizar o systrace para outros dispositivos, a linha FrameMissed poderá não estar presente se o dispositivo não usar HWC2. Em ambos os casos, FrameMissed está correlacionado com o SurfaceFlinger perdendo 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 15.598,29 ms. SurfaceFlinger acordou brevemente no intervalo vsync e voltou a dormir sem fazer nenhum trabalho, o que significa que SurfaceFlinger determinou que não valia a pena tentar enviar um quadro para a tela novamente. Por que?
Para entender como o pipeline foi interrompido para esse quadro, primeiro revise o exemplo do quadro de trabalho acima para ver como um pipeline de UI normal aparece no systrace. Quando estiver pronto, retorne ao quadro perdido e trabalhe de trás para frente. Observe que o SurfaceFlinger acorda e adormece imediatamente. 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 frames no SurfaceFlinger, não é um problema do 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 sync estão habilitados, podemos obter informações sobre as cercas (compartilhadas entre o driver de vídeo e o SurfaceFlinger) que controlam quando os quadros são enviados para o vídeo. Essas cercas estão listadas em mdss_fb0_retire , o que indica quando um quadro está na tela. Essas cercas são fornecidas como parte da categoria de rastreamento sync . Quais limites correspondem a eventos específicos no SurfaceFlinger dependem do seu SOC e da pilha de drivers, portanto, trabalhe com seu fornecedor de SOC para entender o significado das categorias de limites em seus rastreamentos.
A Figura 13 mostra um quadro que foi exibido por 33 ms, e não 16,7 ms como esperado. No meio dessa fatia, aquele quadro deveria ter sido substituído por um novo, mas não foi. Visualize 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 esperaríamos 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 display pipe.
Investigue exatamente onde termina essa cerca para determinar o que a controla.
Uma fila de trabalho contém __vsync_retire_work_handler , que está em execução quando o fence muda. Olhando através da fonte do kernel, você pode ver que ele faz 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 por cerca de 70 nós (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, a instabilidade pode aumentar com o tempo e, eventualmente, causar perda de prazo.
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 CFS SCHED_OTHER ) para um kthread SCHED_FIFO dedicado. Esta função precisa de garantias de tempo que as filas de trabalho não podem (e não pretendem) fornecer.
É esse o motivo da brincadeira? É difícil dizer de forma conclusiva. Fora de casos fáceis de diagnosticar, como contenção de bloqueio de kernel que faz com que threads críticos para exibição sejam suspensos, os rastreamentos geralmente não especificam o problema. Esse tremor poderia ter sido a causa da queda do quadro? Absolutamente. Os tempos de cerca deveriam ser de 16,7 ms, mas não chegam nem perto disso nos quadros que antecedem o quadro eliminado. Dado o quão fortemente acoplado está o pipeline de exibição, é possível que a instabilidade em torno dos tempos da cerca tenha resultado na perda de um quadro.
Neste exemplo, a solução envolveu a conversão de __vsync_retire_work_handler de uma fila de trabalho em um kthread dedicado. Isso resultou em melhorias perceptíveis no jitter e na redução do jitter no teste da bola quicando. Os rastreamentos subsequentes mostram tempos de cerca que oscilam muito próximos de 16,7 ms.