Entender o Systrace

O Systrace é a principal ferramenta para analisar o desempenho de dispositivos Android. No entanto, é um wrapper para outras ferramentas. É o wrapper do lado do host em torno do atrace, o executável do lado do dispositivo que controla o espaço do usuário. o rastreamento e configura o ftrace, e o principal mecanismo de rastreamento no Linux grão O Systrace usa o atrace para ativar o rastreamento, lê o buffer ftrace e contém tudo em um visualizador de HTML independente. Embora os kernels mais recentes tenham suporte para o Filtro de Pacote Berkeley Enhanced (eBPF) do Linux, a documentação a seguir pertence ao kernel 3.18 (sem eFPF), já que foi usado no modelo Pixel/Pixel XG)

O Systrace é de propriedade das equipes do Google Android e do Google Chrome e é de código aberto como parte Projeto Catapult (em inglês). Em 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 pelo atrace. contém funcionalidades avançadas que são essenciais para a depuração do desempenho para solucionar problemas fáceis e de produção. (Esses recursos exigem acesso raiz e geralmente um novo kernel.)

Executar Systrace

Ao depurar a instabilidade 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 combinados com os tracepoints adicionais necessários para GPU e exibição atividade de pipeline, isso permite rastrear a entrada do usuário até o frame exibidos na tela. Defina o tamanho do buffer como um valor grande para evitar perdas porque, sem um buffer grande, algumas CPUs não contêm eventos em algum ponto do rastro).

Ao usar o Systrace, tenha em mente que cada evento é é acionada 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 ftrace que registra as alterações de hardware. Isso significa que, se você quiser saber por que uma fronteira de exibição mudou de estado, possam ver o que estava sendo executado na CPU no ponto exato da transição (algo executado na CPU acionou essa alteração no registro). Isso é a base da análise de desempenho com o Systrace.

Exemplo: frame de trabalho

Este exemplo descreve um Systrace para um pipeline de interface normal. Para acompanhar Com o exemplo, faça o download do arquivo ZIP de traces. (que também inclui outros traces mencionados nesta seção), descompacte o arquivo. e abra o arquivo systrace_tutorial.html no navegador. Aviso que o Systrace é um arquivo grande. a menos que você use o Systrace funcionar, esse é provavelmente um rastro muito maior, com muito mais informações do que você que você já viu em um único trace.

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

1. O EventThread no SurfaceFlinger ativa a linha de execução de interface do app, sinalizando que é hora de para renderizar um novo frame.
2. O app renderiza um frame na linha de execução de IU, RenderThread e hwuiTasks, usando CPU e os recursos da GPU. Essa é a maior parte da capacidade gasta para a 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. Um segundo EventThread no SurfaceFlinger ativa o SurfaceFlinger para acionar composição e exibição. Se o SurfaceFlinger determinar que não há trabalho para ser feito, ele volta a ser suspenso.
5. O SurfaceFlinger gerencia a composição usando hardware/composição de hardware (HWC, na sigla em inglês) Composer 2 (HWC2) ou GL. Composição HWC/HWC2 é mais rápida e com baixo consumo de energia, mas tem limitações dependendo do sistema de um chip (SoC). Esse processo geralmente leva de 4 a 6 ms, mas pode se sobrepor à etapa 2 porque o Android e apps em buffer triplo. Embora os aplicativos sempre tenham buffer triplo, há pode ter apenas um frame pendente aguardando no SurfaceFlinger, o que faz com que ele apareça é idêntico ao armazenamento em buffer duplo.
6. O SurfaceFlinger envia a saída final para ser exibida com um driver do fornecedor e voltar ao modo de suspensão, aguardando a ativação do EventThread.

Vamos analisar o frame a partir de 15.409 ms:

.

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

• Cinza. Dormindo.
• Azul. Executável (ele pode ser executado, mas o programador não já o escolheu para ser executado).
• Verde. Em execução (o programador acha que é em execução).
• Vermelho. Suspensão ininterrupta (geralmente em suspensão em uma fechadura) no kernel). Pode indicar a carga de E/S. Extremamente útil para depuração problemas de desempenho.
• Laranja. Suspensão ininterrupta devido ao carregamento de E/S.

Para conferir o motivo da suspensão ininterrupta (disponível no sched_blocked_reason tracepoint), selecione o ininterrupto vermelho uma fração de sono.

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

.

A figura 2 mostra que a linha de execução de interface de TouchLatency foi ativada pelo tid 6843, que corresponde a EventThread. O thread de IU é ativado, renderiza um frame e enfileira. para o SurfaceFlinger consumir.

.

Se a tag binder_driver estiver ativada em um trace, será possível selecionar um de vinculação para consultar informações sobre todos os processos envolvidos nessa transação.

.

A Figura 4 mostra que, em 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 consulte rowBuffer em ambos os lados da transação do binder.

Durante o rowBuffer no lado do SurfaceFlinger, o número de objetos frames da latência de toque vai de 1 para 2.

.

A figura 5 mostra o armazenamento em buffer triplo, em que há dois frames concluídos e o aplicativo está prestes a começar a renderizar um terceiro. Isso ocorre porque já descartamos alguns frames, então o app mantém dois frames pendentes em vez de um para tentar evitar mais frames perdidos.

Logo depois, a linha de execução principal do SurfaceFlinger é despertada por um segundo EventThread para ele pode gerar o frame pendente mais antigo na tela:

.

O SurfaceFlinger primeiro trava o buffer pendente mais antigo, o que faz com que o que a contagem pendente de buffers 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 mdss. Por isso, talvez eles não sejam incluídos no seu SoC.

.

Em seguida, mdss_fb0 é ativado na CPU 0. mdss_fb0 é o linha de execução do kernel do pipeline de exibição para enviar um frame renderizado para a tela. A mdss_fb0 aparece como a própria linha no rastro (role a tela para baixo até visualização).

mdss_fb0 acorda, corre brevemente, entra em suspensão ininterrupta, e depois acorda novamente.

Exemplo: frame que não funciona

Esse exemplo descreve um Systrace usado para depurar a instabilidade do Pixel/Pixel XL. Para acompanhe o exemplo, faça o download do arquivo de traces, o que inclui outros traces mencionados neste ), descompacte o arquivo e abra o arquivo systrace_tutorial.html no navegador.

Ao abrir o Systrace, você verá algo assim:

.

Ao procurar instabilidade, verifique a linha FrameMissed em SurfaceFlinger. A FrameMissed é uma melhoria da qualidade de vida oferecida pela HWC2. Ao visualizar Systrace para outros dispositivos, a linha "FrameMissed" poderá não estar presente se o dispositivo não usa HWC2. Em qualquer caso, o FrameMissed está correlacionado ao SurfaceFlinger sem um dos ambientes de execução extremamente regulares e uma contagem de buffers pendentes inalterados para o aplicativo (com.prefabulated.touchlatency) em uma vsync.

.

A figura 11 mostra um frame perdido a 15598,29&nbps;ms. O SurfaceFlinger acordou brevemente às intervalo de vsync e voltaram a entrar no modo de suspensão sem fazer nada, o que significa O SurfaceFlinger determinou que não valia a pena tentar enviar um frame para a tela. de novo. Por quê?

Para entender como o pipeline quebrou para este frame, primeiro revise o exemplo de frame de trabalho acima para conferir como um pipeline de interface normal aparece no Systrace. Quando estiver tudo pronto, volte ao frame perdido e trabalhe para trás. Note que O SurfaceFlinger acorda e adormece imediatamente. Ao visualizar o número de quadros pendentes do TouchLatency, há dois frames (uma boa pista descobrir o que está acontecendo).

.

Como temos frames no SurfaceFlinger, isso não é um problema do app. Além disso, O SurfaceFlinger está sendo ativado no horário correto, então não é um SurfaceFlinger problema. Se o SurfaceFlinger e o app parecerem normais, provavelmente é problema com o driver.

Como os tracepoints mdss e sync estão ativados, podemos obter informações sobre os limites (compartilhados entre o driver de exibição e SurfaceFlinger) que controlam quando os frames são enviados à tela. Esses limites estão listados em mdss_fb0_retire, que indica quando um frame está na tela. Essas cercas são fornecidas parte da categoria de trace sync. Quais limites correspondem eventos específicos no SurfaceFlinger depende do SOC e da pilha de drivers. trabalhar com o fornecedor do SOC para entender o significado das categorias de cerca vestígios.

A Figura 13 mostra um frame que foi exibido por 33 ms, não 16,7 ms como esperado. Na metade dessa fração, o frame deveria ter sido substituído por um novo. mas não eram. Visualize o frame anterior e procure o que quiser.

.

A Figura 14 mostra 14,482 ms por frame. O segmento de dois frames corrompido era de 33,6 ms, o que é parecido com o esperado para dois frames (renderizamos a 60 Hz, 16,7 ms por frame, que é bem próximo). Mas 14,482 ms não é algo próximo de 16,7 ms, sugerindo que há algo de errado com o display.

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

.

Uma fila de trabalho contém __vsync_retire_work_handler, que é em execução quando o limite muda. Na origem do kernel, é possível notar que ele faz parte do driver de exibição. Parece estar no nível crítico para o pipeline de exibição, por isso ele precisa ser executado o mais rápido possível. Está executável por cerca de 70 nós (não há um longo atraso na programação), mas é uma fila de trabalho e talvez não sejam programados com precisão.

Verifique o frame anterior para determinar se isso contribuiu; às vezes instável 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 transforma branco quando é selecionado, mas as estatísticas contam a história: 2,3 ms do programador o atraso de parte do caminho crítico do pipeline de exibição é ruim. Antes de continuar, corrija o atraso que, ao mover esta parte do caminho crítico do pipeline de exibição de uma fila de trabalho (que é executada como um linha de execução de CFS SCHED_OTHER) para um SCHED_FIFO dedicado Kthread. Esta função precisa de garantias de tempo que as filas de trabalho não podem (e não tem a intenção de fornecer.

Esse é o motivo da instabilidade? É difícil dizer de forma conclusiva. Fora de casos de fácil diagnóstico, como contenção de bloqueio do kernel, causando problemas de exibição para suspensão, os rastros geralmente não especificam o problema. Essa instabilidade pode ter sido a causa da queda de frame? Com certeza. A os tempos de cerca devem ser de 16,7 ms, mas não estão próximos disso nos frames que levam ao frame descartado. Considerando o acoplamento rígido entre o pipeline de exibição é possível que a instabilidade no tempo da cerca tenha causado uma queda frame.

Neste exemplo, a solução envolvia a conversão __vsync_retire_work_handler de uma fila de trabalho para uma Kthread. Isso resultou em melhorias significativas na instabilidade e na redução da instabilidade teste de bola saltitante. Os rastros subsequentes mostram tempos de cerca que passam muito próximos a 16,7 ms.