Как читать отчеты об ошибках

Ошибки – это неизбежная часть разработки, а отчеты об ошибках помогают выявлять и устранять проблемы. Все версии Android поддерживают создание отчетов об ошибках с помощью Android Debug Bridge (adb). В Android 4.2 и более поздних версиях есть параметр для разработчиков, позволяющий создавать отчеты об ошибках и отправлять их по электронной почте, через Диск и т. д.

Отчеты об ошибках Android содержат данные dumpsys, dumpstate и logcat в текстовом формате (TXT), что позволяет легко искать в них нужную информацию. В следующих разделах описаны компоненты отчета об ошибке, распространенные проблемы, а также полезные советы и команды grep для поиска журналов, связанных с этими ошибками. В большинстве разделов также есть примеры grepкоманд и результатов и/или dumpsysрезультатов.

logcat

Журнал logcat представляет собой дамп всей информации logcat в виде строк. Раздел system зарезервирован для фреймворка и имеет более длинную историю, чем main, в котором хранится все остальное. Обычно каждая строка начинается с timestamp UID PID TID log-level, хотя в более старых версиях Android UID может не быть.

Как посмотреть журнал событий

Этот журнал содержит строковые представления сообщений журнала в двоичном формате. Он менее шумный, чем журнал logcat, но и читать его немного сложнее. При просмотре журналов событий вы можете искать в этом разделе определенный идентификатор процесса (PID), чтобы узнать, что делал процесс. Основной формат: timestamp PID TID log-level log-tag tag-values.

Доступны следующие уровни:

  • V: подробный
  • D: отладка
  • I: информация
  • W – предупреждение.
  • E: ошибка

 

Другие полезные теги журнала событий можно найти в файле /services/core/java/com/android/server/EventLogTags.logtags.

Ошибки ANR и взаимоблокировки

Отчеты об ошибках помогают определить, что вызывает ошибки ANR и блокировки.

Как определить, какие приложения не отвечают

Если приложение не отвечает в течение определенного времени (обычно из-за блокировки или занятости основного потока), система завершает процесс и сохраняет дамп стека в /data/anr. Чтобы найти причину ошибки ANR, выполните поиск по строке am_anr в двоичном журнале событий.

Вы также можете найти в журнале logcat строку ANR in, в которой содержится дополнительная информация о том, какие процессы использовали ресурсы ЦП во время ошибки ANR.

Как найти трассировки стека

Часто можно найти трассировки стека, соответствующие ошибке ANR. Убедитесь, что временная метка и PID в трассировке ВМ совпадают с данными ANR, которые вы исследуете, а затем проверьте основной поток процесса. Примечания

  • Основной поток сообщает только о том, что он делал в момент возникновения ошибки ANR. Это может не соответствовать истинной причине ошибки. (Стек в отчете об ошибке может быть невиновен. Что-то другое могло быть заблокировано в течение длительного времени, но не настолько долго, чтобы вызвать ANR, а затем разблокироваться.)
  • Может существовать несколько наборов трассировок стека (VM TRACES JUST NOW и VM TRACES AT LAST ANR). Убедитесь, что вы просматриваете нужный раздел.

Поиск взаимоблокировок

В большинстве случаев взаимоблокировки сначала проявляются как ошибки ANR, поскольку потоки зависают. Если взаимная блокировка затронет системный сервер, сторожевой таймер в конечном итоге остановит его, что приведет к появлению в журнале записи, похожей на следующую: WATCHDOG KILLING SYSTEM PROCESS. С точки зрения пользователя, устройство перезагружается, хотя технически это перезапуск среды выполнения, а не настоящая перезагрузка.

  • При перезапуске среды выполнения системный сервер отключается и перезапускается. Пользователь видит анимацию загрузки.
  • При перезагрузке происходит сбой ядра, и пользователь видит логотип Google при загрузке устройства.

Чтобы найти взаимные блокировки, проверьте разделы трассировки виртуальной машины на наличие шаблона, в котором поток А ожидает что-то, удерживаемое потоком Б, который, в свою очередь, ожидает что-то, удерживаемое потоком А.

Объекты activity

Действие – это компонент приложения, который предоставляет экран, с помощью которого пользователи взаимодействуют с приложением, например набирают номер, делают фото, отправляют электронное письмо и т. д. С точки зрения отчета об ошибке действие – это одно конкретное действие, которое может выполнить пользователь. Поэтому очень важно найти действие, которое было в фокусе во время сбоя. Действия (через ActivityManager) запускают процессы, поэтому поиск всех остановок и запусков процесса для определенного действия также может помочь в устранении неполадок.

Как посмотреть действия в фокусе

Чтобы посмотреть историю действий, связанных с фокусировкой, выполните поиск по значку am_focused_activity.

Начало просмотра

Чтобы посмотреть историю запусков процессов, выполните поиск по запросу Start proc.

определять, происходит ли перегрузка устройства;

Чтобы определить, перегружено ли устройство, проверьте, наблюдается ли аномальное увеличение активности в период времени между am_proc_died и am_proc_start.

Память

Поскольку у устройств Android часто ограничен объем физической памяти, управление оперативным запоминающим устройством (ОЗУ) имеет решающее значение. Отчеты об ошибках содержат несколько индикаторов нехватки памяти, а также дамп состояния, в котором представлен снимок памяти.

Как определить, что на устройстве мало памяти

Нехватка памяти может привести к сбою системы, поскольку она завершает некоторые процессы, чтобы освободить память, но продолжает запускать другие процессы. Чтобы посмотреть подтверждающие доказательства нехватки памяти, проверьте, есть ли в журнале двоичных событий записи am_proc_died и am_proc_start.

Кроме того, из-за нехватки памяти может замедлиться переключение между задачами и стать невозможным возврат к предыдущей задаче (поскольку она была завершена). Если программа запуска была закрыта, она перезапускается, когда пользователь нажимает кнопку главного экрана, и в журналах показывается, что программа запуска перезагружает свой контент.

Просмотр исторических показателей

Запись am_low_memory в двоичном журнале событий указывает на то, что последний кешированный процесс был завершен. После этого система начнет завершать службы.

Как посмотреть индикаторы пробуксовки

Другие индикаторы пробуксовки системы (подкачка страниц, прямое освобождение памяти и т. д.) включают kswapd, kworker и mmcqd, потребляющие циклы. (Учтите, что сбор отчета об ошибке может повлиять на показатели перегрузки.)

Журналы ANR могут содержать аналогичные данные о памяти.

Получите снимок памяти

Снимок памяти – это дамп состояния, в котором перечислены запущенные процессы Java и нативные процессы (подробнее о просмотре общего объема выделенной памяти…). Учитывайте, что снимок отражает состояние системы только в определенный момент времени. До этого система могла работать лучше или хуже.

Трансляции

Приложения создают широковещательные передачи, чтобы отправлять события в текущем приложении или в другое приложение. Широковещательные приемники подписываются на определенные сообщения (с помощью фильтров), что позволяет им прослушивать широковещательные рассылки и отвечать на них. Отчеты об ошибках содержат информацию об отправленных и неотправленных широковещательных сообщениях, а также данные dumpsys обо всех приемниках, которые прослушивают определенное широковещательное сообщение.

Как посмотреть историю трансляций

В разделе "История трансляций" перечислены уже отправленные трансляции в обратном хронологическом порядке.

В разделе Сводка приводится обзор последних 300 трансляций в фоновом режиме и последних 300 трансляций в фоновом режиме.

В разделе detail содержится полная информация о последних 50 трансляциях на переднем плане и последних 50 трансляциях в фоновом режиме, а также о получателях каждой трансляции. Приемники, у которых:

  • Записи BroadcastFilter регистрируются во время выполнения и отправляются только уже запущенным процессам.
  • Записи ResolveInfo регистрируются через записи манифеста. ActivityManager запускает процесс для каждого ResolveInfo, если он ещё не запущен.

Просмотр активных трансляций

Активные рассылки ещё не отправлены. Если в очереди много трансляций, значит система не успевает их обрабатывать.

Посмотреть слушателей трансляции

Чтобы посмотреть список получателей, ожидающих трансляцию, проверьте таблицу Receiver Resolver в dumpsys activity broadcasts. В следующем примере показаны все приемники, которые прослушивают USER_PRESENT.

Отслеживание конфликтов

Регистрация конфликтов монитора иногда указывает на фактический конфликт монитора, но чаще всего свидетельствует о том, что система настолько загружена, что все работает медленнее. В системном журнале или журнале событий могут появляться записи о длительных событиях мониторинга, зарегистрированных ART.

В системном журнале:

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

В журнале событий:

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]

Фоновая компиляция

Компиляция может быть дорогостоящей и нагружать устройство.

Компиляция может выполняться в фоновом режиме, когда скачиваются обновления из Google Play. В этом случае сообщения из приложения Google Play (finsky) и installd будут показываться раньше сообщений dex2oat.

Компиляция также может выполняться в фоновом режиме, когда приложение загружает DEX-файл, который ещё не был скомпилирован. В этом случае вы не увидите журналы finsky или installd.

Сюжет

Чтобы понять, как возникла проблема, что произошло и как отреагировала система, нужна точная хронология событий. Вы можете использовать информацию из отчета об ошибке, чтобы синхронизировать временные шкалы в нескольких журналах и определить точную временную метку отчета об ошибке.

Как синхронизировать временные шкалы

Отчет об ошибке содержит несколько параллельных временных шкал: системный журнал, журнал событий, журнал ядра и несколько специализированных временных шкал для трансляций, статистики батареи и т. д. К сожалению, временные шкалы часто составляются с использованием разных временных баз.

Временные метки системного журнала и журнала событий указаны в том же часовом поясе, что и у пользователя (как и большинство других временных меток). Например, когда пользователь нажимает кнопку главного экрана, в системном журнале появляется следующая запись:

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

Для одного и того же действия в журнале событий будет указано:

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

В журналах ядра (dmesg) используется другая временная база. Временные метки в них указываются в секундах с момента завершения работы загрузчика. Чтобы зарегистрировать этот временной интервал для других временных интервалов, найдите сообщения suspend exit и suspend entry:

<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

Поскольку в журналах ядра может не быть времени, когда устройство находится в спящем режиме, вам следует регистрировать журнал по частям между сообщениями о входе и выходе из спящего режима. Кроме того, в журналах ядра используется часовой пояс UTC, поэтому их нужно привести к часовому поясу пользователя.

Как определить время создания отчета об ошибке

Чтобы узнать, когда был создан отчет об ошибке, сначала проверьте системный журнал (Logcat) на устройстве dumpstate: begin:

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

Затем проверьте временные метки в журнале ядра (dmesg) для сообщения Starting service 'bugreport':

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

Сопоставьте два события, учитывая предостережения, упомянутые в разделе Синхронизация временных шкал. После запуска отчета об ошибке происходит много событий, но большинство из них не очень полезны, так как создание отчета об ошибке существенно загружает систему.

Питание

Журнал событий содержит статус питания экрана, где 0 – экран выключен, 1 – экран включен, 2 – блокировка экрана снята.

Отчеты об ошибках также содержат статистику блокировок пробуждения – механизма, который разработчики приложений используют, чтобы указать, что их приложению необходимо, чтобы устройство оставалось включенным. (Подробнее о запрете блокировки читайте в статьях PowerManager.WakeLock и Как не допустить отключения ЦП.)

В статистике суммарной продолжительности запрета блокировки отслеживается только время, в течение которого запрет блокировки действительно не позволял устройству перейти в спящий режим, и не учитывается время, когда экран был включен. Кроме того, если одновременно удерживается несколько запретов блокировки, время их действия распределяется между ними.

Чтобы наглядно представить состояние батареи, используйте Battery Historian – инструмент Google с открытым исходным кодом, который анализирует потребителей заряда батареи с помощью файлов bugreport Android.

Пакеты

В разделе DUMP OF SERVICE package указаны версии приложений и другая полезная информация.

Процессы

Отчеты об ошибках содержат огромное количество данных о процессах, включая время запуска и остановки, продолжительность выполнения, связанные сервисы, оценку oom_adj и т. д. Подробную информацию о том, как Android управляет процессами, можно найти в статье Процессы и потоки.

Как определить время выполнения процесса

В разделе procstats содержится полная статистика о том, как долго выполняются процессы и связанные с ними сервисы. Чтобы быстро получить сводку, понятную человеку, выполните поиск по значку AGGREGATED OVER, чтобы посмотреть данные за последние три или 24 часа, а затем по значку Summary:, чтобы увидеть список процессов, время их выполнения с разными приоритетами и использование ОЗУ в формате "минимальное–среднее–максимальное значение PSS/минимальное–среднее–максимальное значение USS".

Причины, по которым выполняется процесс

В разделе dumpsys activity processes перечислены все запущенные процессы, упорядоченные по оценке oom_adj. Android указывает важность процесса, присваивая ему значение oom_adj, которое может динамически обновляться с помощью ActivityManager. Выходные данные похожи на снимок памяти, но содержат дополнительную информацию о том, что вызывает выполнение процесса. В приведенном ниже примере записи, выделенные полужирным шрифтом, указывают, что процесс gms.persistent выполняется с приоритетом vis (видимый), поскольку системный процесс связан с его NetworkLocationService.

Сканирование

Чтобы определить, какие приложения выполняют слишком много сканирований Bluetooth с низким энергопотреблением (BLE), выполните следующие действия:

  • Найдите сообщения в журнале для BluetoothLeScanner: 
    $ grep 'BluetoothLeScanner' ~/downloads/bugreport.txt
07-28 15:55:19.090 24840 24851 D BluetoothLeScanner: onClientRegistered() - status=0 clientIf=5
  • Найдите PID в сообщениях журнала. В этом примере "24840" и "24851" – это PID (идентификатор процесса) и TID (идентификатор потока).
  • Найдите приложение, связанное с идентификатором процесса: 
    PID #24840: ProcessRecord{4fe996a 24840:com.badapp/u0a105}

    В этом примере название пакета – com.badapp.

  • Найдите название пакета в Google Play, чтобы определить приложение, которое вызывает проблему: https://play.google.com/store/apps/details?id=com.badapp.

Примечание. На устройствах с Android 7.0 система собирает данные о сканировании BLE и связывает эти действия с приложением, которое их инициировало. Подробнее о поиске Bluetooth-устройств и Low Energy (LE)…