Lendo relatórios de bugs

Bugs são uma realidade em qualquer tipo de desenvolvimento – e relatórios de bugs são críticos para identificar e resolver problemas. Todas as versões do Android suportam a captura de relatórios de bugs com o Android Debug Bridge (adb) ; As versões do Android 4.2 e superiores oferecem suporte a uma opção de desenvolvedor para receber relatórios de bugs e compartilhar por e-mail, Drive, etc.

Os relatórios de bugs do Android contêm dumpsys , dumpstate e logcat em formato de texto (.txt), permitindo que você pesquise conteúdo específico com facilidade. As seções a seguir detalham os componentes do relatório de bugs, descrevem problemas comuns e fornecem dicas úteis e comandos grep para localizar logs associados a esses bugs. A maioria das seções também inclui exemplos de comando e saída grep e/ou saída dumpsys .

Logcat

O log do logcat é um dump baseado em string de todas as informações do logcat . A parte do sistema é reservada para o framework e tem um histórico mais longo que o main , que contém todo o resto. Cada linha normalmente começa com timestamp UID PID TID log-level , embora o UID possa não estar listado em versões mais antigas do Android.

Visualizando o log de eventos

Este log contém representações de string de mensagens de log em formato binário. É menos barulhento que o log do logcat , mas também um pouco mais difícil de ler. Ao visualizar logs de eventos, você pode pesquisar nesta seção o ID de processo específico (PID) para ver o que um processo está fazendo. O formato básico é: timestamp PID TID log-level log-tag tag-values .

Os níveis de log incluem o seguinte:

  • V: verboso
  • D: depurar
  • eu: informações
  • W: aviso
  • E: erro

Para outras tags de log de eventos úteis, consulte /services/core/java/com/android/server/EventLogTags.logtags .

ANRs e impasses

Os relatórios de bugs podem ajudá-lo a identificar o que está causando erros de ANR (Application Not Responding) e eventos de impasse.

Identificando aplicativos que não respondem

Quando um aplicativo não responde dentro de um determinado tempo, geralmente devido a um encadeamento principal bloqueado ou ocupado, o sistema encerra o processo e despeja a pilha em /data/anr . Para descobrir o culpado por trás de um ANR, use grep para am_anr no log de eventos binários.

Você também pode grep para ANR in log do logcat , que contém mais informações sobre o que estava usando a CPU no momento do ANR.

Encontrar rastreamentos de pilha

Muitas vezes, você pode encontrar rastreamentos de pilha que correspondem a um ANR. Verifique se o carimbo de data/hora e o PID nos rastreamentos de VM correspondem ao ANR que você está investigando e, em seguida, verifique o encadeamento principal do processo. Tenha em mente:

  • O encadeamento principal informa apenas o que o encadeamento estava fazendo no momento do ANR, o que pode ou não corresponder à verdadeira causa do ANR. (A pilha no relatório de bug pode ser inocente; outra coisa pode ter ficado presa por um longo tempo - mas não o suficiente para ANR - antes de se soltar.)
  • Pode existir mais de um conjunto de rastreamentos de pilha ( VM TRACES JUST NOW e VM TRACES AT LAST ANR ). Verifique se você está visualizando a seção correta.

Encontrando impasses

Os deadlocks geralmente aparecem primeiro como ANRs porque os encadeamentos estão ficando presos. Se o deadlock atingir o servidor do sistema, o watchdog acabará por matá-lo, levando a uma entrada no log semelhante a: WATCHDOG KILLING SYSTEM PROCESS . Do ponto de vista do usuário, o dispositivo é reinicializado, embora tecnicamente seja uma reinicialização em tempo de execução, e não uma reinicialização verdadeira.

  • Em uma reinicialização em tempo de execução , o servidor do sistema é interrompido e reiniciado; o usuário vê o dispositivo retornar à animação de inicialização.
  • Em uma reinicialização , o kernel travou; o usuário vê o dispositivo retornar ao logotipo de inicialização do Google.

Para encontrar deadlocks, verifique as seções de rastreamentos de VM para um padrão de thread A aguardando algo retido pelo thread B, que por sua vez está aguardando algo retido pelo thread A.

Atividades

Uma Activity é um componente de aplicativo que fornece uma tela com a qual os usuários interagem para fazer algo como discar um número, tirar uma foto, enviar um e-mail, etc. Do ponto de vista do relatório de bug, uma atividade é uma coisa única e focada que um usuário pode fazer , o que torna muito importante localizar a atividade que estava em foco durante uma falha. As atividades (via ActivityManager) executam processos, portanto, localizar todas as paradas e inícios de processo para uma determinada atividade também pode ajudar na solução de problemas.

Visualizando atividades focadas

Para visualizar um histórico de atividades focadas, procure am_focused_activity .

O processo de visualização é iniciado

Para visualizar um histórico de inícios de processo, procure por Start proc .

O aparelho está travando?

Para determinar se o dispositivo está em thrashing , verifique se há um aumento anormal na atividade em torno am_proc_died e am_proc_start em um curto período de tempo.

Memória

Como os dispositivos Android geralmente têm memória física restrita, o gerenciamento da memória de acesso aleatório (RAM) é fundamental. Os relatórios de bugs contêm vários indicadores de pouca memória, bem como um estado de despejo que fornece um instantâneo de memória.

Identificando memória baixa

A falta de memória pode fazer com que o sistema trave, pois mata alguns processos para liberar memória, mas continua a iniciar outros processos. Para ver evidências corroborantes de pouca memória, verifique as concentrações das entradas am_proc_died e am_proc_start no log de eventos binários.

A memória baixa também pode retardar a troca de tarefas e frustrar as tentativas de retorno (porque a tarefa para a qual o usuário estava tentando retornar foi encerrada). Se o lançador foi morto, ele será reiniciado quando o usuário tocar no botão home e os logs mostrarão que o lançador recarregou seu conteúdo.

Como visualizar indicadores históricos

A entrada am_low_memory no log de eventos binário indica que o último processo armazenado em cache foi interrompido. Depois disso, o sistema começa a matar os serviços.

Como visualizar indicadores de thrashing

Outros indicadores de thrashing do sistema (paginação, recuperação direta, etc.) incluem ciclos de consumo kswapd , kworker e mmcqd . (Lembre-se de que o relatório de bug que está sendo coletado pode influenciar os indicadores de thrashing.)

Os logs ANR podem fornecer um instantâneo de memória semelhante.

Obtendo um instantâneo de memória

O instantâneo de memória é um estado de despejo que lista os processos Java e nativos em execução (para obter detalhes, consulte Visualizando as alocações gerais de memória ). Lembre-se de que o instantâneo fornece apenas o estado em um momento específico; o sistema pode estar em melhor (ou pior) forma antes do instantâneo.

Transmissões

Os aplicativos geram broadcasts para enviar eventos dentro do aplicativo atual ou para outro aplicativo. Os receptores de transmissão assinam mensagens específicas (por meio de filtros), permitindo que escutem e respondam a uma transmissão. Os relatórios de bugs contêm informações sobre transmissões enviadas e não enviadas, bem como um dumpsys de todos os receptores que estão ouvindo uma transmissão específica.

Como visualizar transmissões históricas

As transmissões históricas são aquelas que já foram enviadas, listadas em ordem cronológica inversa.

A seção de resumo é uma visão geral das últimas 300 transmissões em primeiro plano e das últimas 300 transmissões em segundo plano.

A seção de detalhes contém informações completas para as últimas 50 transmissões em primeiro plano e as últimas 50 transmissões em segundo plano, bem como os receptores de cada transmissão. Receptores que possuem:

  • As entradas BroadcastFilter são registradas em tempo de execução e são enviadas apenas para processos já em execução.
  • A entrada ResolveInfo é registrada por meio de entradas de manifesto. O ActivityManager inicia o processo para cada ResolveInfo se ainda não estiver em execução.

Visualizando transmissões ativas

As transmissões ativas são aquelas que ainda não foram enviadas. Um grande número na fila significa que o sistema não pode despachar as transmissões com rapidez suficiente para acompanhar.

Visualizando ouvintes de transmissão

Para visualizar uma lista de receptores que escutam uma transmissão, verifique a Tabela do Resolvedor de Receptor nas dumpsys activity broadcasts . O exemplo a seguir exibe todos os receptores ouvindo USER_PRESENT .

Monitorar contenção

O log de contenção do monitor às vezes pode indicar a contenção real do monitor, mas na maioria das vezes indica que o sistema está tão carregado que tudo ficou mais lento. Você pode ver eventos de monitor longos registrados pelo ART no sistema ou log de eventos.

No registro do sistema:

10-01 18:12:44.343 29761 29914 W art     : Long monitor contention event with owner method=void android.database.sqlite.SQLiteClosable.acquireReference() from SQLiteClosable.java:52 waiters=0 for 3.914s

No log de eventos:

10-01 18:12:44.364 29761 29914 I dvm_lock_sample: [com.google.android.youtube,0,pool-3-thread-9,3914,ScheduledTaskMaster.java,138,SQLiteClosable.java,52,100]

Compilação em segundo plano

A compilação pode ser cara e carregar o dispositivo.

A compilação pode ocorrer em segundo plano durante o download das atualizações da Google Play Store. Nesse caso, as mensagens do aplicativo da Google Play Store ( finsky ) e installd aparecem antes das mensagens dex2oat .

A compilação também pode ocorrer em segundo plano quando um aplicativo está carregando um arquivo dex que ainda não foi compilado. Nesse caso, você não verá o log finsky ou do installd .

Narrativa

Estabelecer a narrativa de um problema (como começou, o que aconteceu, como o sistema reagiu) requer uma linha do tempo sólida de eventos. Você pode usar as informações no relatório de bug para sincronizar linhas do tempo em vários logs e determinar o timestamp exato do relatório de bug.

Sincronizando linhas do tempo

Um relatório de bug reflete várias linhas de tempo paralelas: log do sistema, log de eventos, log do kernel e várias linhas de tempo especializadas para transmissões, estatísticas de bateria, etc. Infelizmente, as linhas de tempo são frequentemente relatadas usando diferentes bases de tempo.

Os carimbos de data/hora do sistema e do log de eventos estão no mesmo fuso horário que o usuário (assim como a maioria dos outros carimbos de data/hora). Por exemplo, quando o usuário toca no botão home, o log do sistema relata:

10-03 17:19:52.939  1963  2071 I ActivityManager: START u0 {act=android.intent.action.MAIN cat=[android.intent.category.HOME] flg=0x10200000 cmp=com.google.android.googlequicksearchbox/com.google.android.launcher.GEL (has extras)} from uid 1000 on display 0

Para a mesma ação, o log de eventos relata:

10-03 17:19:54.279  1963  2071 I am_focused_activity: [0,com.google.android.googlequicksearchbox/com.google.android.launcher.GEL]

Os logs do kernel ( dmesg ) usam uma base de tempo diferente, marcando os itens de log com segundos desde que o bootloader foi concluído. Para registrar esta escala de tempo em outras escalas de tempo, procure por mensagens de saída de suspensão e entrada de suspensão:

<6>[201640.779997] PM: suspend exit 2015-10-03 19:11:06.646094058 UTC
…
<6>[201644.854315] PM: suspend entry 2015-10-03 19:11:10.720416452 UTC

Como os logs do kernel podem não incluir o tempo durante a suspensão, você deve registrar o log por partes entre a entrada de suspensão e as mensagens de saída. Além disso, os logs do kernel usam o fuso horário UTC e devem ser ajustados ao fuso horário do usuário.

Identificando o tempo do relatório de bugs

Para determinar quando um relatório de bug foi obtido, primeiro verifique o log do sistema (Logcat) para o dumpstate: begin :

10-03 17:19:54.322 19398 19398 I dumpstate: begin

Em seguida, verifique os carimbos de data/hora do log do kernel ( dmesg ) para a mensagem Starting service 'bugreport' :

<5>[207064.285315] init: Starting service 'bugreport'...

Trabalhe de trás para frente para correlacionar os dois eventos, tendo em mente as advertências mencionadas em Sincronizando linhas do tempo . Embora haja muita coisa acontecendo após o relatório de bug ser iniciado, a maioria das atividades não é muito útil, pois o ato de obter o relatório de bug carrega o sistema substancialmente.

Poder

O registro de eventos contém o status de energia da tela, onde 0 é a tela desligada, 1 é a tela ligada e 2 é para a proteção do teclado concluída.

Os relatórios de bugs também contêm estatísticas sobre wake locks, um mecanismo usado pelos desenvolvedores de aplicativos para indicar que seus aplicativos precisam manter o dispositivo ligado. (Para obter detalhes sobre wake locks, consulte PowerManager.WakeLock e Keep the CPU on .)

As estatísticas agregadas de duração do wake lock rastreiam apenas o tempo em que um wake lock é realmente responsável por manter o dispositivo acordado e não incluem o tempo com a tela ligada. Além disso, se vários wake locks forem mantidos simultaneamente, o tempo de duração do wake lock será distribuído entre esses wake locks.

Para obter mais ajuda na visualização do status de energia, use o Battery Historian , uma ferramenta de código aberto do Google para analisar os consumidores de bateria usando arquivos de relatório de bugs do Android.

Pacotes

A seção DUMP OF SERVICE package contém versões de aplicativos (e outras informações úteis).

Processos

Os relatórios de bugs contêm uma grande quantidade de dados para processos, incluindo tempo de início e término, duração do tempo de execução, serviços associados, pontuação oom_adj etc. Para obter detalhes sobre como o Android gerencia processos, consulte Processos e threads .

Determinando o tempo de execução do processo

A seção procstats contém estatísticas completas sobre há quanto tempo os processos e serviços associados estão em execução. Para obter um resumo rápido e legível, pesquise AGGREGATED OVER para visualizar dados das últimas três ou 24 horas e, em seguida, pesquise Summary: para visualizar a lista de processos, por quanto tempo esses processos foram executados em várias prioridades e sua RAM uso formatado como min-average-max PSS/min-average-max USS.

Por que um processo está em execução?

A seção dumpsys activity processes lista todos os processos atualmente em execução ordenados pela pontuação oom_adj (o Android indica a importância do processo atribuindo ao processo um valor oom_adj , que pode ser atualizado dinamicamente pelo ActivityManager). A saída é semelhante à de um instantâneo de memória , mas inclui informações adicionais sobre o que está causando a execução do processo. No exemplo abaixo, as entradas em negrito indicam que o processo gms.persistent está sendo executado com prioridade vis (visível) porque o processo do sistema está vinculado ao seu NetworkLocationService .

Varreduras

Use as etapas a seguir para identificar aplicativos que executam verificações excessivas de Bluetooth Low Energy (BLE):

  • Encontre mensagens de log para BluetoothLeScanner :
    $ grep 'BluetoothLeScanner' ~/downloads/bugreport.txt
07-28 15:55:19.090 24840 24851 D BluetoothLeScanner: onClientRegistered() - status=0 clientIf=5
  • Localize o PID nas mensagens de log. Neste exemplo, "24840" e "24851" são PID (ID do processo) e TID (ID do thread).
  • Localize o aplicativo associado ao PID:
    PID #24840: ProcessRecord{4fe996a 24840:com.badapp/u0a105}

    Neste exemplo, o nome do pacote é com.badapp .

  • Procure o nome do pacote no Google Play para identificar o aplicativo responsável: https://play.google.com/store/apps/details?id=com.badapp .

Observação : para dispositivos com Android 7.0, o sistema coleta dados para verificações de BLE e associa essas atividades ao aplicativo inicial. Para obter detalhes, consulte Verificações de baixa energia (LE) e Bluetooth .