阅读错误报告

无论是任何类型的开发工作,出错都在所难免,而错误报告对于找出和解决问题至关重要。Android 的所有版本都支持通过 Android 调试桥 (adb) 获取错误报告;Android 4.2 及更高版本提供了一个开发者选项,供开发者获取错误报告以及通过电子邮件、云端硬盘等分享报告。

Android 错误报告中包含文本 (.txt) 格式的 dumpsysdumpstatelogcat 数据,以便您轻松搜索特定内容。以下各部分详细说明了错误报告的组成部分、介绍了常见问题,并提供了关于查找与这些错误相关的日志的实用提示和 grep 命令。大多数部分中还包括 grep 命令及输出和/或 dumpsys 输出方面的示例。

Logcat

logcat 日志是所有 logcat 信息的转储,并采用字符串形式。system(系统)部分专门用于记录框架方面的信息,与包含所有其他内容的 main(主要内容)部分相比,该部分包含更长时间内的记录。每行都以 timestamp PID TID log-level 开头。

查看事件日志

该日志中包含将二进制格式转换成了字符串形式的日志消息。它比 logcat 日志要清晰明了,但也有些难以阅读。在查看事件日志时,您可以在这一部分中搜索特定进程 ID (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 执行 grep 命令。

您也可以为 logcat 日志(其中包含关于发生 ANR 时是什么在占用 CPU 的更多信息)中的 ANR in 执行 grep 命令。

查找堆栈跟踪

通常您可以找到与 ANR 对应的堆栈跟踪。请确保 VM 跟踪上的时间戳和 PID 与您正在调查的 ANR 相符,然后再检查进程的主线程。请注意:

  • 主线程只能让您了解发生 ANR 时它在做什么,这可能是导致 ANR 的真正原因,也可能不是。(错误报告中的堆栈可能是无辜的;可能有其他线程在恢复正常之前粘滞了很长时间,但不足以导致 ANR。)
  • 可能存在多组堆栈跟踪(VM TRACES JUST NOWVM TRACES AT LAST ANR)。请确保您查看的是正确的部分。

查找死锁

由于线程出现粘滞,死锁往往首先表现为 ANR。如果系统服务器发生死锁,监控程序最终会将其终止,从而导致日志中出现类似以下的条目:WATCHDOG KILLING SYSTEM PROCESS。对于用户来说,他们看到的是设备重新启动,但从技术上来讲这是运行时重启,而不是真正的设备重新启动。

  • 运行时重启时,系统服务器已死机并会重启,并且用户会看到设备返回到显示启动动画。
  • 在设备重新启动时,内核已崩溃,并且用户会看到设备返回到显示 Google 启动徽标。

要查找死锁,请检查 VM 跟踪部分中是否存在以下模式:线程 A 在等待线程 B 占用的某些资源,而线程 B 也在等待线程 A 占用的某些资源。

Activity

Activity 是一种应用组件,可为用户提供一个可交互的屏幕,用来执行某些操作(例如拨号、拍照、发送电子邮件等)。从错误报告的角度来看,Activity 是用户可以执行的一项明确具体的操作,这使得查找在崩溃期间处于聚焦状态的 Activity 变得非常重要。Activity 通过 ActivityManager 运行进程,因此找出指定 Activity 的所有进程停止和启动事件也有助于进行问题排查。

查看处于聚焦状态的 Activity

要查看记录的处于聚焦状态的 Activity,请搜索 am_focused_activity

查看进程启动事件

要查看记录的进程启动事件,请搜索 Start proc

设备是否发生系统颠簸?

要确定设备是否发生系统颠簸,请检查在 am_proc_diedam_proc_start 前后的短时间内是否出现活动异常增多的情况。

内存

由于 Android 设备的物理内存通常都存在限制,因此管理随机存取存储器 (RAM) 至关重要。错误报告中包含一些用于指示内存不足的指标以及一个提供内存快照的 dumpstate。

发现内存不足的情况

内存不足可能会导致系统发生颠簸,这是因为虽然内存不足时系统会终止某些进程来释放内存,但又会继续启动其他进程。要查看内存不足的确凿证据,请检查二进制事件日志中 am_proc_diedam_proc_start 条目的密集程度。

内存不足还可能会减慢任务切换速度,并且可能会阻止进行返回尝试(因为用户尝试返回到的任务已被终止)。如果启动器被终止,它会在用户触摸主屏幕按钮时重启,并且日志中会显示启动器重新加载其内容。

查看历史指标

二进制事件日志中的 am_low_memory 条目表示最后一个缓存的进程已终止。在此之后,系统开始终止各项服务。

查看系统颠簸指标

关于系统颠簸(分页、直接回收等)的其他指标包括 kswapdkworkermmcqd 消耗的 CPU 周期。(请注意,收集错误报告可能会影响系统颠簸指标。)

ANR 日志可以提供类似的内存快照。

获取内存快照

内存快照是一种 dumpstate,其中会列出正在运行的 Java 进程和本机进程(有关详情,请参阅查看整体内存分配)。请注意,快照仅提供特定时刻的状态;在此快照之前,系统的状况可能更好,也可能更糟。

广播

应用会生成广播,以便在当前应用内发送事件或向其他应用发送事件。广播接收方可以通过过滤器订阅特定消息,以便收听和响应广播。错误报告中包含已发送广播和未发送广播的相关信息,以及关于收听特定广播的所有接收方的 dumpsys。

查看历史广播

历史广播是指已发送的广播,按时间逆序排列。

summary(摘要)部分用于提供最近 300 个前台广播和最近 300 个后台广播的概况。

detail(详情)部分包含最近 50 条前台广播和最近 50 条后台广播的完整信息,以及每个广播的接收方。其中:

  • 具有 BroadcastFilter 条目的接收方是在运行时注册的,并且只会被发送到已在运行的进程。
  • 具有 ResolveInfo 条目的接收方是通过清单条目注册的。ActivityManager 会为每个 ResolveInfo 启动相应进程(如果相应进程尚未在运行)。

查看待发送的广播

待发送的广播是指尚未发送的广播。如果队列中存在大量广播,则意味着系统无法足够快地发送广播来跟上进度。

查看广播监听器

要查看监听某条广播的接收方列表,请查看 dumpsys activity broadcasts 中的 Receiver Resolver Table。以下示例显示了监听 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 文件时,编译也可能会在后台进行。在这种情况下,您将看不到 finskyinstalld 日志记录。

概况

要呈现问题概况(问题是如何开始的、发生了什么、系统是如何应对的),需要一个固定的事件时间轴。您可以利用错误报告中的信息来同步多个日志中的时间轴并确定错误报告的确切时间戳。

同步时间轴

错误报告反映的是多个并行时间轴(系统日志、事件日志、内核日志,以及针对广播、电池统计信息等的多个专用时间轴)。遗憾的是,系统通常会使用不同的时间基准来报告不同的时间轴。

系统日志时间戳和事件日志时间戳采用用户所用的时区(与大多数其他时间戳一样)。例如,当用户点按主屏幕按钮时,系统日志会报告以下内容:

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使 CPU 保持运行状态。)

唤醒锁定总时长统计信息跟踪唤醒锁定实际负责使设备保持唤醒状态的时间,包括屏幕处于开启状态的时间。此外,如果同时持有多个唤醒锁定,系统会在它们之间分配唤醒锁定时长。

如需直观呈现电源状态方面的更多帮助,请使用 Battery Historian(一种 Google 开放源代码工具,能够利用 Android 错误报告文件分析电池消耗进程)。

软件包

“DUMP OF SERVICE”软件包中包含应用版本信息(以及其他实用信息)。

进程

错误报告中含有大量进程数据,包括启动和停止时间、运行时时长、相关服务、oom_adj 得分等。要详细了解 Android 如何管理进程,请参阅进程和线程

确定进程运行时

procstats 部分包含有关进程及相关服务已运行时长的完整统计信息。要快速获得便于用户阅读的摘要,请搜索 AGGREGATED OVER 以查看最近 3 个小时或 24 个小时的数据,然后搜索 Summary: 以查看进程列表、这些进程已以各种优先级运行的时长,以及它们使用 RAM 的情况(格式为“最小-平均-最大 PSS”/“最小-平均-最大 USS”)。

某个进程为什么正在运行?

dumpsys activity processes 部分会列出当前正在运行的所有进程,并按 oom_adj 得分排序(Android 通过为进程分配 oom_adj 值来表明进程的重要性,该值可由 ActivityManager 动态更新)。这种输出类似于内存快照的输出,但包含有关是什么导致进程运行的更多信息。在以下示例中,以粗体显示的条目表明 gms.persistent 进程正在以 vis(可见)优先级运行,因为该系统进程已经与其 NetworkLocationService 绑定。

扫描

您可以按照以下步骤来确定过度执行蓝牙低功耗 (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(进程 ID)和 TID(线程 ID)。
  • 找到与该 PID 关联的应用:
    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 扫描数据,并会将这些活动与初始应用相关联。有关详情,请参阅低功耗 (LE) 和蓝牙扫描