赞
踩
应用发生崩溃,如果是生产环境,通常容易找到,如果不是,那就麻烦很多。bug的发生总是那么突如其来,有时候让我们措手不及,现在我就来理一理如何淡定的解决bug;
应用异常退出有两种可能,一种是出现了异常挂掉了,另一种是被系统杀死了。第一种是程序原因,第二种不一定是程序原因,但多数情况下还是应用的原因。
Bug排查的一般步骤:
对于容易复现的bug,我们只需要在我们的程序中假如关键打印就能很容易确定什么时候应用崩溃,如果是现的bug,那就需要通过一些辅助日志来定位了;
不过这也不难,我们在bugreport的txt里面可以通过以下几种方法定位:
1. am_proc_died
有进程被杀时间点及原因包名,则直接搜索
am_proc_died: [0,[0-9]*,xxxx,,xxxx//代表包名
拿到这行log的时间点以及进程pid
eg: 08-19 10:06:55.302 1000 1699 12137 I am_proc_died: [0,9307,com.quark.browser,905,11]
如上栗子:时间点为08-19 10:06:55.302 (搜索时可自行减几毫秒,否则可能搜索不到同时间点的其他log),进程pid为9307
2. ApplicationExitInfo
在bugReport中搜索这个关键字,能找到你的应用及整个应用在最近一段时间内什么时候退出以及退出的原因,比如在我这里:
package: cn.skyruler.app Historical Process Exit for userId=10284 ApplicationExitInfo #0: timestamp=2021-11-23 18:05:14.376 pid=15455 realUid=10284 packageUid=10284 definingUid=10284 user=0 process=cn.xxxx.app reason=5 (APP CRASH(NATIVE)) status=11 importance=100 pss=431MB rss=535MB description=crash state=empty trace=null
如果是java层的崩溃我们可在logcat日志中找到RuntimeException或者crash字样;如果不是,比如上面这种情况,就需要看native的日志;
- 通过java层logcat看是否崩溃(crashHandler或者调试版logcat)
- 如果java层没有任何相关日志打印就从c层看(在bugreport.zip->FS->data->tombstones->对应时间的日志)
logcat中直接搜索lowmemorykiller: Kill ‘com.xxx.aaa’ (pid)
08-19 10:06:55.207 lmkd 954 954 E lowmemorykiller: Kill ‘com.xxx.aaa’ (9307), uid 10248, oom_adj 905 to free 69048kB
08-19 10:06:55.207 lmkd 954 954 I lowmemorykiller: Reclaimed 69048kB, cache(718372kB) and free(314436kB)-reserved(43892kB) below min(765000kB) for oom_adj 900
解读:手机cache 内存为718372kb,低于oom_adj 900这个级别的最低值765000kB,所以lmkd会查杀pid为9307的com.xxx.aaa进程,该进程当前的adj为905(高于900),释放了69048kb;
未有lowmemorykiller打印,但是am_low_memory递减同时,am_proc_died同时打印,且system log中有has died 打印
07-30 22:18:26.746 1000 1718 5108 I ActivityManager: Process com.xiaomi.channel (pid 21963) has died: hvy HVY
07-30 22:18:26.746 1000 1718 5127 I am_low_memory: 68
07-30 22:18:26.746 1000 1718 5108 I am_proc_died: [0,21963,com.xiaomi.channel,400,14]
07-30 22:18:26.803 1000 1718 5127 I am_low_memory: 66
解读:am_low_memory 后面的数字代表当前系统中lru 中进程的数量,数字递减代表有进程被杀,has died 代表非AMS查杀(lmk查杀或信号查杀),hvy HVY代表进程的优先级(进程自查一览表)
在Android 11后引入了新的安全策略,其中谷歌引入了新的api:
流程退出原因api:getHistoricalProcessExitReasons
这个api使我们对私有数据访问和流程退出(主要是crash)的原因更加清晰明了。我们可以通过在bugreport日志文件里面搜索Historical Process Exit for
关键字,就能看到自己的进程被谁杀死。
空进程被杀
这种是说进程已经不活动了被系统杀了,通常这种情况很少,大概是这样的:
08-10 13:32:13.057 1000 1700 1812 I am_kill : [0,2409,com.miui.screenrecorder,955,empty for 1800s]
empty进程数量达到阈值了,会查杀30min内没活跃的进程
08-10 16:00:54.244 1000 1700 1795 I ActivityManager: Killing 20081:com.android.providers.calendar/u0a72 (adj 985): empty #26
系统内empty进程数量达到阈值26(不同手机略有不同)会按时间顺序查杀进程;
进程自己退出
有时候应用退出不一定是因为奔溃,可能是程序员代码没写对或者漏掉了一些环境细节让应用主动退出了。除了看ApplicationExitInfo外我们还能通过logcat看到。
08-13 10:17:04.053 root 689 689 I Zygote : Process 29263 exited cleanly (0)
08-13 10:17:04.056 1000 1692 1805 I libprocessgroup: Successfully killed process cgroup uid 10252 pid 29263 in 122ms
08-13 10:17:03.933 1000 1692 5189 I ActivityManager: Process com.tencent.tmgp.pubgmhd (pid 29263) has died: hvy HVY
被系统进程杀掉
系统app调用forceStopPackage 接口,杀掉我们的应用,我们搜索stop com.xxx.aaa due to from process
03-25 19:34:10.498 26589 29585 I ActivityManager: Killing 14459:com.xiaomi.misubscreenui/1000 (adj 0): stop com.xiaomi.misubscreenui due to from process:com.miui.voiceassist
过渡使用CPU
09-06 18:07:44.445 1000 1651 1798 I am_kill : [0,22157,com.ximalaya.ting.android,900,excessive cpu 16720 during 300044 dur=2221553 limit=2]
09-06 18:07:44.445 1000 1651 1798 I ActivityManager: Killing 22157:com.ximalaya.ting.android/u0a239 (adj 900): excessive cpu 16720 during 300044 dur=2221553 limit=2
09-06 18:07:44.566 root 681 681 I Zygote : Process 22157 exited due to signal 9 (Killed)
上次adj降为Service以下到现在经历2221553 ms,cpu POWER_CHECK_MAX_CPU_4 = 2, 两次检测时间间隔为300044 ms,使用cpu时间为16720ms,超过2%,就会被杀。
进程的线程异常
进程的某个线程发生异常,自己发Signal 9信号给Zygote 杀掉自己
09-07 16:53:03.027 1000 2566 2582 I Process : Sending signal. PID: 2566 SIG: 9
09-07 16:53:03.154 root 681 681 I Zygote : Process 2566 exited due to signal 9 (Killed)
09-07 16:53:03.167 1000 1734 4006 I ActivityManager: Process com.android.systemui (pid 2566) has died: pers PER
installPackageLI/ deletePackageX等
只要是forceStopPackage接口查杀就有可能查杀到关联的进程,如下拨号就是因为与gms关联被杀
08-10 15:59:30.827 1000 1700 1812 I ActivityManager: Force stopping com.google.android.gms appid=10190 user=-1: installPackageLI
08-10 15:59:30.984 1000 1700 1812 I ActivityManager: Killing 3876:com.google.android.dialer/u0a180 (adj -700): stop com.google.android.gms: installPackageLI
Battery Historian是Google提供的用于可视化分析bugreport的一款工具。虽然bugreport的生成非常简单,目录结构也很好理解,但问题是,这个生成的文件非常庞大,包含的信息量也很大,如果逐个排查确实也痛苦,因此Google针对Android5.0(API21)以上的系统开发了一个分析工具Battery Historian来解析bugreport文件,并用web图形的形式展
关于电量的关键信息在DUMP OF SERVICE batterystats
下,我们可以通过这个关键字在文件中找到。Battery Historian这款工具很多人推荐使用别人做好的镜像,也就是使用docker来使用,主要是简单(如果没有docker则需要先安装docker并配置mirror):
docker run -d -p 9999:9999 bhaavan/battery-historian
然后就可以通过9999端口访问了,大概长这样:
但是实际在使用的时候可能并不是很好用,比如我的会经常出现Note: Could not parse aggregated battery stats.
,图标就出不来,这样就不太舒服了。
bathist网址在线bugreport解析
使用bathist最大的好处是省去了我们自己去搭建更新docker环境,相当实用。
即使你成功生成了对应的结果试图,你不会看,那也是白瞎,下面我们来缕一缕怎么看Battery Historian;
Battery Historian 工具提供各种应用和系统行为的系统级可视化结果,以及它们随时间推移与耗电量的相关性。如图 1 所示,此视图可帮助你诊断和识别应用存在的耗电问题。
如图. Battery Historian 显示了影响功耗的系统级事件
该图中特别值得注意的是表示电池电量的黑色水平下降趋势线(在 y 轴上进行测量)。例如,在电池电量线的最开始处,大约早上 6:50 时,该图表显示电量出现较为急剧的下降。
下图 为该部分显示画面的特写图。
Battery Historian 时间轴(大约从早上 6:50 到 7:20)的特写图。
在电池电量线的最开始处,随着电池电量的急剧下降,显示画面上显示有三件事正在发生:CPU 正在运行,应用已获取唤醒锁定,且屏幕已打开。通过这种方式,Battery Historian 可帮助你了解耗电量高时正在发生什么事件。然后,你可以针对应用中的这些行为,研究是否可以进行相关优化。
系统级可视化还可以提供其他线索。例如,如果它显示移动无线装置频繁关闭和开启,则可能有机会通过智能调度 API(如 JobScheduler 或 Firebase Job Dispatcher 等)优化此行为。
系统的数据太多了,看起来头大,如果我们想要看某个特定应用的视图怎么看呢?
除了系统级数据视图提供的宏观数据外,Battery Historian 还提供特定于设备上运行的每个应用的数据表格和部分可视化内容。表格数据包括:
表格提供了关于应用的两个数据维度。首先,你可以查找应用的耗电量与其他应用相比的排名位置。为此,请点击“Tables”下的“Device Power Estimates”表格。本示例研究了一款名为“Pug Power”的虚构应用。下图中研究哪些应用的耗电量最大。
图 中的表格显示,Pug Power 在此设备上的耗电量排名第九,在不属于操作系统的应用中排名第三。这些数据表明此应用需要更深入的研究。
要查找特定应用的数据,在可视化图表左侧下方,在“App Selection”下方的第二个下拉菜单中输入应用的软件包名称。
当你选择特定应用时,以下数据可视化类别将更改为显示具体应用数据,而不是系统级数据:
如果你的应用以不必要的频率执行同步和执行作业,SyncManager 和 JobScheduler 可视化图表会立即突出显示这种情况。这样,它们能快速展露出优化应用行为以提升电池性能的机会。
你还可以再获取具体应用的一条可视化数据,即用户空间唤醒锁定。要将此信息包含在错误报告中,请在终端窗口中输入以下命令:
$ adb shell dumpsys batterystats --enable full-wake-history
注意:从 Android 6.0(API 级别 23)开始,平台包含对应用实施特定优化的低电耗模式功能。例如,无论 JobScheduler 的调度方式如何,低电耗模式都会将作业处理成在简短的维护期间批量进行。
下面两张图 显示了 PugPower 的数据:图 5 显示了具体应用数据的可视化图表,图 6 显示了相应的表格数据。
查看可视化图表并没有发现任何显而易见的问题。JobScheduler 行显示应用没有调度作业。SyncManager 行显示应用尚未执行任何同步操作。
不过,查看表格数据的“唤醒锁定”部分发现,Pug Power 获取了 1 个小时内的唤醒锁定总次数。这种代价高昂的异常行为可能是应用耗电量较高的原因。这条信息有助于开发者专攻优化后可能会大大获益的方面。在这种情况下,为什么应用会获得如此多的唤醒锁定时间,开发者又如何改善这种行为呢?
在很多其他情况下,Battery Historian 也可帮助你找出改善电池行为的机会。例如,Battery Historian 可以显示应用是否具有以下行为:
获取错误报告有三种方式:通过手机的开发者选项生成错误报告/从 Android 模拟器上获取错误报告/使用 adb 获取错误报告;
错误报告包含设备日志、堆栈轨迹和其他诊断信息,可以帮助你查找和修复应用中的错误。你可以通过以下几种方式从设备上获取错误报告:使用设备上的生成错误报告开发者选项、Android 模拟器菜单或开发机器上的 adb bugreport 命令。
如需生成错误报告,你必须在设备上启用开发者选项,以便访问生成错误报告选项。
如需直接从你的设备上获取错误报告,请执行以下操作:
在 Android 模拟器中,你可以使用“Extended controls”窗口中的 File a bug 功能:
如果你只连接了一台设备,则可以使用 adb 获取错误报告,如下所示:
$ adb bugreport E:\Reports\MyBugReports
如果你没有指定错误报告的路径,系统会将其保存到本地目录。
如果你连接了多台设备,则必须使用 -s 选项指定设备。运行以下 adb 命令可获取设备序列号并生成 bug 报告。
$ adb devices
List of devices attached
emulator-5554 device
8XV7N15C31003476 device
$ adb -s 8XV7N15C31003476 bugreport
保存旧版 bug 报告
默认情况下,bug 报告保存在 /bugreports 中,并可使用如下方式查看:
$ adb shell ls /bugreports/
bugreport-foo-bar.xxx.YYYY-MM-DD-HH-MM-SS-dumpstate_log-yyy.txt
bugreport-foo-bar.xxx.YYYY-MM-DD-HH-MM-SS.zip
dumpstate-stats.txt
然后,你可以通过 adb pull 提取 ZIP 文件,如下所示:
$ adb pull /bugreports/bugreport-foo-bar.xxx.YYYY-MM-DD-HH-MM-SS.zip
默认情况下,ZIP 文件称为 bugreport-BUILD_ID-DATE.zip,它可能会包含多个文件,但最重要的文件是 bugreport-BUILD_ID-DATE.txt。此文件就是错误报告,它包含系统服务 (dumpsys)、错误日志 (dumpstate) 和系统消息日志 (logcat) 的诊断输出。系统消息包括设备抛出错误时的堆栈轨迹,以及从所有应用中使用 Log 类写入的消息。
ZIP 文件中有一个 version.txt 元数据文件,其中包含 Android 版本号,而且启用 systrace 后,ZIP 文件中还会包含 systrace.txt 文件。Systrace 工具可以获取并显示应用进程和其他 Android 系统进程的执行时间,从而帮助分析应用的性能。
dumpstate 工具会将文件从设备的文件系统复制到 ZIP 文件的 FS 文件夹下,以便你引用它们。例如,设备中的 /dirA/dirB/fileC 文件会在 ZIP 文件中生成 FS/dirA/dirB/fileC 条目。
无论是任何类型的开发工作,出错都在所难免,而错误报告对于找出和解决问题至关重要。Android 的所有版本都支持通过 Android 调试桥 (adb) 获取错误报告;Android 4.2 及更高版本支持一个旨在获取错误报告以及通过电子邮件、云端硬盘等分享报告的开发者选项。
Android 错误报告中包含文本 (.txt) 格式的 dumpsys、dumpstate 和 logcat 数据,以便你轻松搜索特定内容。以下各部分详细说明了错误报告的组成部分、介绍了常见问题,并提供了关于查找与这些错误相关的日志的实用提示和 grep 命令。大多数部分中还包括 grep 命令及输出和/或 dumpsys 输出方面的示例。
logcat 日志是所有 logcat 信息的转储,并采用字符串形式。system(系统)部分专门用于记录框架方面的信息,与包含所有其他内容的 main(主要内容)部分相比,该部分包含更长时间内的记录。每行都以 timestamp PID TID log-level 开头。
------ SYSTEM LOG (logcat -v threadtime -d *:v) ------
--------- beginning of system
Blah
Blah
Blah
--------- beginning of main
Blah
Blah
Blah
该日志中包含将二进制格式转换成了字符串形式的日志消息。它比 logcat 日志要清晰明了,但也有些难以阅读。在查看事件日志时,你可以在这一部分中搜索特定进程 ID (PID),以查看相应进程一直在做什么。基本格式为:timestamp PID TID log-level log-tag tag-values。
日志级别包括以下几种:
------ EVENT LOG (logcat -b events -v threadtime -d *:v) ------
09-28 13:47:34.179 785 5113 I am_proc_bound: [0,23054,com.google.android.gms.unstable]
09-28 13:47:34.777 785 1975 I am_proc_start: [0,23134,10032,com.android.chrome,broadcast,com.android.chrome/org.chromium.chrome.browser.precache.PrecacheServiceLauncher]
09-28 13:47:34.806 785 2764 I am_proc_bound: [0,23134,com.android.chrome]
...
有关其他实用的事件日志标记,请参阅 /services/core/java/com/android/server/EventLogTags.logtags。
错误报告有助于你找出导致应用无响应 (ANR) 错误和死锁事件的原因。
当某个应用在一定时间内没有响应(通常是由于主线程被阻塞或繁忙)时,系统会终止该进程并将堆栈转储到 /data/anr。要找出 ANR 背后的罪魁祸首,请为二进制事件日志中的 am_anr 执行 grep 命令。
grep "am_anr" bugreport-2015-10-01-18-13-48.txt
10-01 18:12:49.599 4600 4614 I am_anr : [0,29761,com.google.android.youtube,953695941,executing service com.google.android.youtube/com.google.android.apps.youtube.app.offline.transfer.OfflineTransferService]
10-01 18:14:10.211 4600 4614 I am_anr : [0,30363,com.google.android.apps.plus,953728580,executing service com.google.android.apps.plus/com.google.android.apps.photos.service.PhotosService]
你也可以为 logcat 日志(其中包含关于发生 ANR 时是什么在占用 CPU 的更多信息)中的 ANR in 执行 grep 命令。
grep "ANR in" bugreport-2015-10-01-18-13-48.txt
10-01 18:13:11.984 4600 4614 E ActivityManager: ANR in com.google.android.youtube
10-01 18:14:31.720 4600 4614 E ActivityManager: ANR in com.google.android.apps.plus
10-01 18:14:31.720 4600 4614 E ActivityManager: PID: 30363
10-01 18:14:31.720 4600 4614 E ActivityManager: Reason: executing service com.google.android.apps.plus/com.google.android.apps.photos.service.PhotosService
10-01 18:14:31.720 4600 4614 E ActivityManager: Load: 35.27 / 23.9 / 16.18
10-01 18:14:31.720 4600 4614 E ActivityManager: CPU usage from 16ms to 21868ms later:
10-01 18:14:31.720 4600 4614 E ActivityManager: 74% 3361/mm-qcamera-daemon: 62% user + 12% kernel / faults: 15276 minor 10 major
10-01 18:14:31.720 4600 4614 E ActivityManager: 41% 4600/system_server: 18% user + 23% kernel / faults: 18597 minor 309 major
10-01 18:14:31.720 4600 4614 E ActivityManager: 32% 27420/com.google.android.GoogleCamera: 24% user + 7.8% kernel / faults: 48374 minor 338 major
10-01 18:14:31.720 4600 4614 E ActivityManager: 16% 130/kswapd0: 0% user + 16% kernel
10-01 18:14:31.720 4600 4614 E ActivityManager: 15% 283/mmcqd/0: 0% user + 15% kernel
...
10-01 18:14:31.720 4600 4614 E ActivityManager: 0.1% 27248/irq/503-synapti: 0%
10-01 18:14:31.721 4600 4614 I ActivityManager: Killing 30363:com.google.android.apps.plus/u0a206 (adj 0): bg anr
通常你可以找到与 ANR 对应的堆栈跟踪。请确保 VM 跟踪上的时间戳和 PID 与你正在调查的 ANR 相符,然后再检查进程的主线程。请注意:
主线程只能让你了解发生 ANR 时它在做什么,这可能是导致 ANR 的真正原因,也可能不是。(错误报告中的堆栈可能是无辜的;可能有其他线程在恢复正常之前粘滞了很长时间,但不足以导致 ANR。)
可能存在多组堆栈跟踪(VM TRACES JUST NOW 和 VM TRACES AT LAST ANR)。请确保你查看的是正确的部分。
------ VM TRACES AT LAST ANR (/data/anr/traces.txt: 2015-10-01 18:14:41) ------ ----- pid 30363 at 2015-10-01 18:14:11 ----- Cmd line: com.google.android.apps.plus Build fingerprint: 'google/angler/angler:6.0/MDA89D/2294819:userdebug/dev-keys' ABI: 'arm' Build type: optimized Zygote loaded classes=3978 post zygote classes=27 Intern table: 45068 strong; 21 weak JNI: CheckJNI is off; globals=283 (plus 360 weak) Libraries: /system/lib/libandroid.so /system/lib/libcompiler_rt.so /system/lib/libjavacrypto.so /system/lib/libjnigraphics.so /system/lib/libmedia_jni.so /system/lib/libwebviewchromium_loader.so libjavacore.so (7) Heap: 29% free, 21MB/30MB; 32251 objects Dumping cumulative Gc timings Total number of allocations 32251 Total bytes allocated 21MB Total bytes freed 0B Free memory 9MB Free memory until GC 9MB Free memory until OOME 490MB Total memory 30MB Max memory 512MB Zygote space size 1260KB Total mutator paused time: 0 Total time waiting for GC to complete: 0 Total GC count: 0 Total GC time: 0 Total blocking GC count: 0 Total blocking GC time: 0 suspend all histogram: Sum: 119.728ms 99% C.I. 0.010ms-107.765ms Avg: 5.442ms Max: 119.562ms DALVIK THREADS (12): "Signal Catcher" daemon prio=5 tid=2 Runnable | group="system" sCount=0 dsCount=0 obj=0x12c400a0 self=0xef460000 | sysTid=30368 nice=0 cgrp=default sched=0/0 handle=0xf4a69930 | state=R schedstat=( 9021773 5500523 26 ) utm=0 stm=0 core=1 HZ=100 | stack=0xf496d000-0xf496f000 stackSize=1014KB | held mutexes= "mutator lock"(shared held) native: #00 pc 0035a217 /system/lib/libart.so (art::DumpNativeStack(std::__1::basic_ostream<char, std::__1::char_traits<char> >&, int, char const*, art::ArtMethod*, void*)+126) native: #01 pc 0033b03b /system/lib/libart.so (art::Thread::Dump(std::__1::basic_ostream<char, std::__1::char_traits<char> >&) const+138) native: #02 pc 00344701 /system/lib/libart.so (art::DumpCheckpoint::Run(art::Thread*)+424) native: #03 pc 00345265 /system/lib/libart.so (art::ThreadList::RunCheckpoint(art::Closure*)+200) native: #04 pc 00345769 /system/lib/libart.so (art::ThreadList::Dump(std::__1::basic_ostream<char, std::__1::char_traits<char> >&)+124) native: #05 pc 00345e51 /system/lib/libart.so (art::ThreadList::DumpForSigQuit(std::__1::basic_ostream<char, std::__1::char_traits<char> >&)+312) native: #06 pc 0031f829 /system/lib/libart.so (art::Runtime::DumpForSigQuit(std::__1::basic_ostream<char, std::__1::char_traits<char> >&)+68) native: #07 pc 00326831 /system/lib/libart.so (art::SignalCatcher::HandleSigQuit()+896) native: #08 pc 003270a1 /system/lib/libart.so (art::SignalCatcher::Run(void*)+324) native: #09 pc 0003f813 /system/lib/libc.so (__pthread_start(void*)+30) native: #10 pc 00019f75 /system/lib/libc.so (__start_thread+6) (no managed stack frames) "main" prio=5 tid=1 Suspended | group="main" sCount=1 dsCount=0 obj=0x747552a0 self=0xf5376500 | sysTid=30363 nice=0 cgrp=default sched=0/0 handle=0xf74feb34 | state=S schedstat=( 331107086 164153349 851 ) utm=6 stm=27 core=3 HZ=100 | stack=0xff00f000-0xff011000 stackSize=8MB | held mutexes= kernel: __switch_to+0x7c/0x88 kernel: futex_wait_queue_me+0xd4/0x130 kernel: futex_wait+0xf0/0x1f4 kernel: do_futex+0xcc/0x8f4 kernel: compat_SyS_futex+0xd0/0x14c kernel: cpu_switch_to+0x48/0x4c native: #00 pc 000175e8 /system/lib/libc.so (syscall+28) native: #01 pc 000f5ced /system/lib/libart.so (art::ConditionVariable::Wait(art::Thread*)+80) native: #02 pc 00335353 /system/lib/libart.so (art::Thread::FullSuspendCheck()+838) native: #03 pc 0011d3a7 /system/lib/libart.so (art::ClassLinker::LoadClassMembers(art::Thread*, art::DexFile const&, unsigned char const*, art::Handle<art::mirror::Class>, art::OatFile::OatClass const*)+746) native: #04 pc 0011d81d /system/lib/libart.so (art::ClassLinker::LoadClass(art::Thread*, art::DexFile const&, art::DexFile::ClassDef const&, art::Handle<art::mirror::Class>)+88) native: #05 pc 00132059 /system/lib/libart.so (art::ClassLinker::DefineClass(art::Thread*, char const*, unsigned int, art::Handle<art::mirror::ClassLoader>, art::DexFile const&, art::DexFile::ClassDef const&)+320) native: #06 pc 001326c1 /system/lib/libart.so (art::ClassLinker::FindClassInPathClassLoader(art::ScopedObjectAccessAlreadyRunnable&, art::Thread*, char const*, unsigned int, art::Handle<art::mirror::ClassLoader>, art::mirror::Class**)+688) native: #07 pc 002cb1a1 /system/lib/libart.so (art::VMClassLoader_findLoadedClass(_JNIEnv*, _jclass*, _jobject*, _jstring*)+264) native: #08 pc 002847fd /data/dalvik-cache/arm/system@framework@boot.oat (Java_java_lang_VMClassLoader_findLoadedClass__Ljava_lang_ClassLoader_2Ljava_lang_String_2+112) at java.lang.VMClassLoader.findLoadedClass!(Native method) at java.lang.ClassLoader.findLoadedClass(ClassLoader.java:362) at java.lang.ClassLoader.loadClass(ClassLoader.java:499) at java.lang.ClassLoader.loadClass(ClassLoader.java:469) at android.app.ActivityThread.installProvider(ActivityThread.java:5141) at android.app.ActivityThread.installContentProviders(ActivityThread.java:4748) at android.app.ActivityThread.handleBindApplication(ActivityThread.java:4688) at android.app.ActivityThread.-wrap1(ActivityThread.java:-1) at android.app.ActivityThread$H.handleMessage(ActivityThread.java:1405) at android.os.Handler.dispatchMessage(Handler.java:102) at android.os.Looper.loop(Looper.java:148) at android.app.ActivityThread.main(ActivityThread.java:5417) at java.lang.reflect.Method.invoke!(Native method) at com.android.internal.os.ZygoteInit$MethodAndArgsCaller.run(ZygoteInit.java:726) at com.android.internal.os.ZygoteInit.main(ZygoteInit.java:616) ... Stacks for other threads in this process follow ...
由于线程出现粘滞,死锁往往首先表现为 ANR。如果系统服务器发生死锁,监控程序最终会将其终止,从而导致日志中出现类似以下的条目:WATCHDOG KILLING SYSTEM PROCESS。对于用户来说,他们看到的是设备重新启动,但从技术上来讲这是运行时重启,而不是真正的设备重新启动。
在运行时重启时,系统服务器已死机并会重启,并且用户会看到设备返回到显示启动动画。
在设备重新启动时,内核已崩溃,并且用户会看到设备返回到显示 Google 启动徽标。
要查找死锁,请检查 VM 跟踪部分中是否存在以下模式:线程 A 在等待线程 B 占用的某些资源,而线程 B 也在等待线程 A 占用的某些资源。
"Binder_B" prio=5 tid=73 Blocked | group="main" sCount=1 dsCount=0 obj=0x13faa0a0 self=0x95e24800 | sysTid=2016 nice=0 cgrp=default sched=0/0 handle=0x8b68d930 | state=S schedstat=( 9351576559 4141431119 16920 ) utm=819 stm=116 core=1 HZ=100 | stack=0x8b591000-0x8b593000 stackSize=1014KB | held mutexes= at com.android.server.pm.UserManagerService.exists(UserManagerService.java:387) - waiting to lock <0x025f9b02> (a android.util.ArrayMap) held by thread 20 at com.android.server.pm.PackageManagerService.getApplicationInfo(PackageManagerService.java:2848) at com.android.server.AppOpsService.getOpsRawLocked(AppOpsService.java:881) at com.android.server.AppOpsService.getOpsLocked(AppOpsService.java:856) at com.android.server.AppOpsService.noteOperationUnchecked(AppOpsService.java:719) - locked <0x0231885a> (a com.android.server.AppOpsService) at com.android.server.AppOpsService.noteOperation(AppOpsService.java:713) at com.android.server.AppOpsService$2.getMountMode(AppOpsService.java:260) at com.android.server.MountService$MountServiceInternalImpl.getExternalStorageMountMode(MountService.java:3416) at com.android.server.am.ActivityManagerService.startProcessLocked(ActivityManagerService.java:3228) at com.android.server.am.ActivityManagerService.startProcessLocked(ActivityManagerService.java:3170) at com.android.server.am.ActivityManagerService.startProcessLocked(ActivityManagerService.java:3059) at com.android.server.am.BroadcastQueue.processNextBroadcast(BroadcastQueue.java:1070) - locked <0x044d166f> (a com.android.server.am.ActivityManagerService) at com.android.server.am.ActivityManagerService.finishReceiver(ActivityManagerService.java:16950) at android.app.ActivityManagerNative.onTransact(ActivityManagerNative.java:494) at com.android.server.am.ActivityManagerService.onTransact(ActivityManagerService.java:2432) at android.os.Binder.execTransact(Binder.java:453) ... "PackageManager" prio=5 tid=20 Blocked | group="main" sCount=1 dsCount=0 obj=0x1304f4a0 self=0xa7f43900 | sysTid=1300 nice=10 cgrp=bg_non_interactive sched=0/0 handle=0x9fcf9930 | state=S schedstat=( 26190141996 13612154802 44357 ) utm=2410 stm=209 core=2 HZ=100 | stack=0x9fbf7000-0x9fbf9000 stackSize=1038KB | held mutexes= at com.android.server.AppOpsService.noteOperationUnchecked(AppOpsService.java:718) - waiting to lock <0x0231885a> (a com.android.server.AppOpsService) held by thread 73 at com.android.server.AppOpsService.noteOperation(AppOpsService.java:713) at com.android.server.AppOpsService$2.getMountMode(AppOpsService.java:260) at com.android.server.AppOpsService$2.hasExternalStorage(AppOpsService.java:273) at com.android.server.MountService$MountServiceInternalImpl.hasExternalStorage(MountService.java:3431) at com.android.server.MountService.getVolumeList(MountService.java:2609) at android.os.storage.StorageManager.getVolumeList(StorageManager.java:880) at android.os.Environment$UserEnvironment.getExternalDirs(Environment.java:83) at android.os.Environment.isExternalStorageEmulated(Environment.java:708) at com.android.server.pm.PackageManagerService.isExternalMediaAvailable(PackageManagerService.java:9327) at com.android.server.pm.PackageManagerService.startCleaningPackages(PackageManagerService.java:9367) - locked <0x025f9b02> (a android.util.ArrayMap) at com.android.server.pm.PackageManagerService$PackageHandler.doHandleMessage(PackageManagerService.java:1320) at com.android.server.pm.PackageManagerService$PackageHandler.handleMessage(PackageManagerService.java:1122) at android.os.Handler.dispatchMessage(Handler.java:102) at android.os.Looper.loop(Looper.java:148) at android.os.HandlerThread.run(HandlerThread.java:61) at com.android.server.ServiceThread.run(ServiceThread.java:46)
Activity 是一种应用组件,可提供一个屏幕,用户能够通过与该屏幕互动来执行某些操作,例如拨打电话号码、拍照、发送电子邮件,等等。从错误报告的角度来看,一个 Activity 是用户可以执行一项明确具体的操作,这使得查找在崩溃期间处于聚焦状态的 Activity 变得非常重要。Activity 通过 ActivityManager 运行进程,因此找出指定 Activity 的所有进程停止和启动事件也有助于进行问题排查。
要查看记录的处于聚焦状态的 Activity,请搜索 am_focused_activity。
grep "am_focused_activity" bugreport-2015-10-01-18-13-48.txt
10-01 18:10:41.409 4600 14112 I am_focused_activity: [0,com.google.android.GoogleCamera/com.android.camera.CameraActivity]
10-01 18:11:17.313 4600 5687 I am_focused_activity: [0,com.google.android.googlequicksearchbox/com.google.android.launcher.GEL]
10-01 18:11:52.747 4600 14113 I am_focused_activity: [0,com.google.android.GoogleCamera/com.android.camera.CameraActivity]
10-01 18:14:07.762 4600 5687 I am_focused_activity: [0,com.google.android.googlequicksearchbox/com.google.android.launcher.GEL]
要查看记录的进程启动事件,请搜索 Start proc。
grep "Start proc" bugreport-2015-10-01-18-13-48.txt
10-01 18:09:15.309 4600 4612 I ActivityManager: Start proc 24533:com.metago.astro/u0a240 for broadcast com.metago.astro/com.inmobi.commons.analytics.androidsdk.IMAdTrackerReceiver
10-01 18:09:15.687 4600 14112 I ActivityManager: Start proc 24548:com.google.android.apps.fitness/u0a173 for service com.google.android.apps.fitness/.api.services.ActivityUpsamplingService
10-01 18:09:15.777 4600 6604 I ActivityManager: Start proc 24563:cloudtv.hdwidgets/u0a145 for broadcast cloudtv.hdwidgets/cloudtv.switches.SwitchSystemUpdateReceiver
10-01 18:09:20.574 4600 6604 I ActivityManager: Start proc 24617:com.wageworks.ezreceipts/u0a111 for broadcast com.wageworks.ezreceipts/.ui.managers.IntentReceiver
...
要确定设备是否发生系统颠簸,请检查 am_proc_died 和 am_proc_start 前后在短时间内是否出现活动异常增加。
grep -e "am_proc_died" -e "am_proc_start" bugreport-2015-10-01-18-13-48.txt
10-01 18:07:06.494 4600 9696 I am_proc_died: [0,20074,com.android.musicfx]
10-01 18:07:06.555 4600 6606 I am_proc_died: [0,31166,com.concur.breeze]
10-01 18:07:06.566 4600 14112 I am_proc_died: [0,18812,com.google.android.apps.fitness]
10-01 18:07:07.018 4600 7513 I am_proc_start: [0,20361,10113,com.sony.playmemories.mobile,broadcast,com.sony.playmemories.mobile/.service.StartupReceiver]
10-01 18:07:07.357 4600 4614 I am_proc_start: [0,20381,10056,com.google.android.talk,service,com.google.android.talk/com.google.android.libraries.hangouts.video.CallService]
10-01 18:07:07.784 4600 4612 I am_proc_start: [0,20402,10190,com.andcreate.app.trafficmonitor:loopback_measure_serivce,service,com.andcreate.app.trafficmonitor/.loopback.LoopbackMeasureService]
10-01 18:07:10.753 4600 5997 I am_proc_start: [0,20450,10097,com.amazon.mShop.android.shopping,broadcast,com.amazon.mShop.android.shopping/com.amazon.identity.auth.device.storage.LambortishClock$ChangeTimestampsBroadcastReceiver]
10-01 18:07:15.267 4600 6605 I am_proc_start: [0,20539,10173,com.google.android.apps.fitness,service,com.google.android.apps.fitness/.api.services.ActivityUpsamplingService]
10-01 18:07:15.985 4600 4612 I am_proc_start: [0,20568,10022,com.android.musicfx,broadcast,com.android.musicfx/.ControlPanelReceiver]
10-01 18:07:16.315 4600 7512 I am_proc_died: [0,20096,com.google.android.GoogleCamera]
由于 Android 设备的物理内存通常都存在限制,因此管理随机存取存储器 (RAM) 至关重要。错误报告中包含一些用于指示内存不足的指标以及一个提供内存快照的 dumpstate。
内存不足可能会导致系统发生崩溃,这是因为虽然内存不足时系统会终止某些进程来释放内存,但又会继续启动其他进程。要查看内存不足的确凿证据,请检查二进制事件日志中 am_proc_died 和 am_proc_start 条目的密集程度。
内存不足还可能会减慢任务切换速度,并且可能会阻止进行返回尝试(因为用户尝试返回到的任务已被终止)。如果启动器被终止,它会在用户触摸主屏幕按钮时重启,并且日志中会显示启动器重新加载其内容。
查看历史指标
二进制事件日志中的 am_low_memory 条目表示最后一个缓存的进程已终止。在此之后,系统开始终止各项服务。
grep "am_low_memory" bugreport-2015-10-01-18-13-48.txt
10-01 18:11:02.219 4600 7513 I am_low_memory: 41
10-01 18:12:18.526 4600 14112 I am_low_memory: 39
10-01 18:12:18.874 4600 7514 I am_low_memory: 38
10-01 18:12:22.570 4600 14112 I am_low_memory: 40
10-01 18:12:34.811 4600 20319 I am_low_memory: 43
10-01 18:12:37.945 4600 6521 I am_low_memory: 43
10-01 18:12:47.804 4600 14110 I am_low_memory: 43
查看系统颠簸指标
关于系统颠簸(分页、直接回收等)的其他指标包括 kswapd、kworker 和 mmcqd 消耗的 CPU 周期。(请注意,收集错误报告可能会影响系统颠簸指标。)
------ CPU INFO (top -n 1 -d 1 -m 30 -t) ------ User 15%, System 54%, IOW 28%, IRQ 0% User 82 + Nice 2 + Sys 287 + Idle 1 + IOW 152 + IRQ 0 + SIRQ 5 = 529 PID TID PR CPU% S VSS RSS PCY UID Thread Proc 15229 15229 0 19% R 0K 0K fg root kworker/0:2 29512 29517 1 7% D 1173524K 101188K bg u0_a27 Signal Catcher com.google.android.talk 24565 24570 3 6% D 2090920K 145168K fg u0_a22 Signal Catcher com.google.android.googlequicksearchbox:search 19525 19525 2 6% R 3476K 1644K fg shell top top 24957 24962 2 5% R 1706928K 125716K bg u0_a47 Signal Catcher com.google.android.GoogleCamera 19519 19519 3 4% S 0K 0K fg root kworker/3:1 120 120 0 3% S 0K 0K fg root mmcqd/1 18233 18233 1 3% S 0K 0K fg root kworker/1:1 25589 25594 1 2% D 1270476K 75776K fg u0_a8 Signal Catcher com.google.android.gms 19399 19399 2 1% S 0K 0K fg root kworker/2:2 1963 1978 1 0% S 1819100K 125136K fg system android.fg system_server 1963 1981 3 0% S 1819100K 125136K fg system android.display system_server
ANR 日志可以提供类似的内存快照。
10-03 17:19:59.959 1963 1976 E ActivityManager: ANR in com.google.android.apps.magazines 10-03 17:19:59.959 1963 1976 E ActivityManager: PID: 18819 10-03 17:19:59.959 1963 1976 E ActivityManager: Reason: Broadcast of Intent { act=android.net.conn.CONNECTIVITY_CHANGE flg=0x4000010 cmp=com.google.android.apps.magazines/com.google.apps.dots.android.newsstand.appwidget.NewsWidgetProvider (has extras) } 10-03 17:19:59.959 1963 1976 E ActivityManager: Load: 19.19 / 14.76 / 12.03 10-03 17:19:59.959 1963 1976 E ActivityManager: CPU usage from 0ms to 11463ms later: 10-03 17:19:59.959 1963 1976 E ActivityManager: 54% 15229/kworker/0:2: 0% user + 54% kernel 10-03 17:19:59.959 1963 1976 E ActivityManager: 38% 1963/system_server: 14% user + 23% kernel / faults: 17152 minor 1073 major 10-03 17:19:59.959 1963 1976 E ActivityManager: 11% 120/mmcqd/1: 0% user + 11% kernel 10-03 17:19:59.959 1963 1976 E ActivityManager: 10% 2737/com.android.systemui: 4.7% user + 5.6% kernel / faults: 7211 minor 149 major 10-03 17:19:59.959 1963 1976 E ActivityManager: 0.2% 1451/debuggerd: 0% user + 0.2% kernel / faults: 15211 minor 147 major 10-03 17:19:59.959 1963 1976 E ActivityManager: 8.7% 6162/com.twofortyfouram.locale: 4% user + 4.7% kernel / faults: 4924 minor 260 major 10-03 17:19:59.959 1963 1976 E ActivityManager: 6.1% 24565/com.google.android.googlequicksearchbox:search: 2.4% user + 3.7% kernel / faults: 2902 minor 129 major 10-03 17:19:59.959 1963 1976 E ActivityManager: 6% 55/kswapd0: 0% user + 6% kernel 10-03 17:19:59.959 1963 1976 E ActivityManager: 4.9% 18819/com.google.android.apps.magazines: 1.5% user + 3.3% kernel / faults: 10129 minor 986 major 10-03 17:19:59.959 1963 1976 E ActivityManager: 2.8% 18233/kworker/1:1: 0% user + 2.8% kernel 10-03 17:19:59.959 1963 1976 E ActivityManager: 4.2% 3145/com.android.phone: 2% user + 2.2% kernel / faults: 3005 minor 43 major 10-03 17:19:59.959 1963 1976 E ActivityManager: 4.2% 8084/com.android.chrome: 2% user + 2.1% kernel / faults: 4798 minor 380 major 10-03 17:19:59.959 1963 1976 E ActivityManager: 3.4% 182/surfaceflinger: 1.1% user + 2.3% kernel / faults: 842 minor 13 major 10-03 17:19:59.959 1963 1976 E ActivityManager: 3% 18236/kworker/1:2: 0% user + 3% kernel 10-03 17:19:59.959 1963 1976 E ActivityManager: 2.9% 19231/com.android.systemui:screenshot: 0.8% user + 2.1% kernel / faults: 6119 minor 348 major 10-03 17:19:59.959 1963 1976 E ActivityManager: 2.3% 15350/kworker/0:4: 0% user + 2.3% kernel 10-03 17:19:59.959 1963 1976 E ActivityManager: 2.2% 1454/mediaserver: 0% user + 2.2% kernel / faults: 479 minor 6 major 10-03 17:19:59.959 1963 1976 E ActivityManager: 2% 16496/com.android.chrome:sandboxed_process10: 0.1% user + 1.8% kernel / faults: 3610 minor 234 major 10-03 17:19:59.959 1963 1976 E ActivityManager: 1% 3119/com.android.nfc: 0.4% user + 0.5% kernel / faults: 1789 minor 17 major 10-03 17:19:59.959 1963 1976 E ActivityManager: 1.7% 19337/com.jarettmillard.localeconnectiontype:background: 0.1% user + 1.5% kernel / faults: 7854 minor 439 major 10-03 17:19:59.959 1963 1976 E ActivityManager: 0.7% 3066/com.google.android.inputmethod.latin: 0.3% user + 0.3% kernel / faults: 1336 minor 7 major 10-03 17:19:59.959 1963 1976 E ActivityManager: 1% 25589/com.google.android.gms: 0.3% user + 0.6% kernel / faults: 2867 minor 237 major 10-03 17:19:59.959 1963 1976 E ActivityManager: 0.9% 1460/sensors.qcom: 0.5% user + 0.4% kernel / faults: 262 minor 5 major 10-03 17:19:59.959 1963 1976 E ActivityManager: 0.8% 3650/mpdecision: 0% user + 0.8% kernel / faults: 160 minor 1 major 10-03 17:19:59.959 1963 1976 E ActivityManager: 0.1% 3132/com.redbend.vdmc: 0% user + 0% kernel / faults: 1746 minor 5 major
内存快照是一种 dumpstate,其中会列出正在运行的 Java 进程和本机进程(有关详情,请参阅查看整体内存分配)。请注意,快照仅提供特定时刻的状态;在此快照之前,系统的状况可能更好,也可能更糟。
要了解某个进程的运行时长,请参阅进程运行时。
要了解为什么某个进程当前正在运行,请参阅某个进程为什么正在运行?
Total PSS by OOM adjustment: 86752 kB: Native 22645 kB: surfaceflinger (pid 197) 18597 kB: mediaserver (pid 204) ... 136959 kB: System 136959 kB: system (pid 785) 220218 kB: Persistent 138859 kB: com.android.systemui (pid 947 / activities) 39178 kB: com.android.nfc (pid 1636) 28313 kB: com.android.phone (pid 1659) 13868 kB: com.redbend.vdmc (pid 1646) 9534 kB: Persistent Service 9534 kB: com.android.bluetooth (pid 23807) 178604 kB: Foreground 168620 kB: com.google.android.googlequicksearchbox (pid 1675 / activities) 9984 kB: com.google.android.apps.maps (pid 13952) 188286 kB: Visible 85326 kB: com.google.android.wearable.app (pid 1535) 38978 kB: com.google.process.gapps (pid 1510) 31936 kB: com.google.android.gms.persistent (pid 2072) 27950 kB: com.google.android.gms.wearable (pid 1601) 4096 kB: com.google.android.googlequicksearchbox:interactor (pid 1550) 52948 kB: Perceptible 52948 kB: com.google.android.inputmethod.latin (pid 1566) 150851 kB: A Services 81121 kB: com.google.android.gms (pid 1814) 37586 kB: com.google.android.talk (pid 9584) 10949 kB: com.google.android.music:main (pid 4019) 10727 kB: com.motorola.targetnotif (pid 31071) 10468 kB: com.google.android.GoogleCamera (pid 9984) 33298 kB: Previous 33298 kB: com.android.settings (pid 9673 / activities) 165188 kB: B Services 49490 kB: com.facebook.katana (pid 15035) 22483 kB: com.whatsapp (pid 28694) 21308 kB: com.iPass.OpenMobile (pid 5325) 19788 kB: com.google.android.apps.googlevoice (pid 23934) 17399 kB: com.google.android.googlequicksearchbox:search (pid 30359) 9073 kB: com.google.android.apps.youtube.unplugged (pid 21194) 7660 kB: com.iPass.OpenMobile:remote (pid 23754) 7291 kB: com.pujie.wristwear.pujieblack (pid 24240) 7157 kB: com.instagram.android:mqtt (pid 9530) 3539 kB: com.qualcomm.qcrilmsgtunnel (pid 16186) 204324 kB: Cached 43424 kB: com.amazon.mShop.android (pid 13558) 22563 kB: com.google.android.apps.magazines (pid 13844) ... 4298 kB: com.google.android.apps.enterprise.dmagent (pid 13826)
应用会生成广播,以便在当前应用内发送事件或向其他应用发送事件。广播接收方可以通过过滤器订阅特定消息,以便收听和响应广播。错误报告中包含已发送广播和未发送广播的相关信息,以及关于收听特定广播的所有接收方的 dumpsys。
历史广播是指已发送的广播,按时间逆序排列。
summary(摘要)部分用于提供最近 300 个前台广播和最近 300 个后台广播的概况。
Historical broadcasts summary [foreground]:
#0: act=android.intent.action.SCREEN_ON flg=0x50000010
+1ms dispatch +90ms finish
enq=2015-10-29 17:10:51 disp=2015-10-29 17:10:51 fin=2015-10-29 17:10:51
#1: act=android.intent.action.SCREEN_OFF flg=0x50000010
0 dispatch +60ms finish
enq=2015-10-29 17:10:05 disp=2015-10-29 17:10:05 fin=2015-10-29 17:10:05
...
Historical broadcasts summary [background]:
...
detail(详情)部分包含最近 50 个前台广播和最近 50 个后台广播的完整信息,以及每个广播的接收方。
具有 BroadcastRecord 条目的接收方是在运行时注册的,并且只会被发送到已在运行的进程。
具有 ResolveInfo 条目的接收方是通过清单条目注册的。ActivityManager 会为每个 ResolveInfo 启动相应进程(如果相应进程尚未在运行)。
Historical broadcasts [foreground]: ... Historical broadcasts [background]: Historical Broadcast background #0: ... Historical Broadcast background #5: BroadcastRecord{18dbb16 u0 android.intent.action.USER_PRESENT} to user 0 Intent { act=android.intent.action.USER_PRESENT flg=0x24000010 } caller=com.android.systemui 2925:com.android.systemui/u0a27 pid=2925 uid=10027 enqueueClockTime=2015-10-29 17:10:55 dispatchClockTime=2015-10-29 17:10:55 dispatchTime=-2s321ms (0 since enq) finishTime=-2s320ms (+1ms since disp) Receiver #0: BroadcastFilter{8181cc1 u-1 ReceiverList{5d929a8 902 system/1000/u-1 local:eca4dcb}} Receiver #1: BroadcastFilter{6371c97 u-1 ReceiverList{2938b16 902 system/1000/u-1 local:840b831}} ... Receiver #19: BroadcastFilter{93f16b u0 ReceiverList{5c61eba 17016 com.google.android.gm/10079/u0 remote:24083e5}} ... Historical Broadcast background #37: BroadcastRecord{7f6dd6 u0 android.hardware.action.NEW_PICTURE} to user 0 Intent { act=android.hardware.action.NEW_PICTURE dat=content://media/external/images/media/6345 flg=0x10 } caller=com.google.android.GoogleCamera 32734:com.google.android.GoogleCamera/u0a53 pid=32734 uid=10053 enqueueClockTime=2015-10-29 17:09:48 dispatchClockTime=2015-10-29 17:09:49 dispatchTime=-45s720ms (+399ms since enq) finishTime=-45s701ms (+19ms since disp) resultTo=null resultCode=0 resultData=null nextReceiver=4 receiver=null Receiver #0: ResolveInfo{33d2857 com.google.android.gms/com.google.android.libraries.social.mediamonitor.MediaMonitor m=0x608000} priority=0 preferredOrder=0 match=0x608000 specificIndex=-1 isDefault=false ActivityInfo: name=com.google.android.libraries.social.mediamonitor.MediaMonitor packageName=com.google.android.gms enabled=true exported=true processName=com.google.android.gms ... Receiver #1: ResolveInfo{d9edf44 com.google.android.apps.maps/com.google.android.apps.gmm.ugc.clientnotification.StartPhotoTakenNotifierServiceReceiver m=0x608000} priority=0 preferredOrder=0 match=0x608000 specificIndex=-1 isDefault=false ActivityInfo: name=com.google.android.apps.gmm.ugc.clientnotification.StartPhotoTakenNotifierServiceReceiver packageName=com.google.android.apps.maps enabled=true exported=true processName=com.google.android.apps.maps ... Receiver #2: ResolveInfo{743f82d com.google.android.apps.photos/com.google.android.libraries.social.mediamonitor.MediaMonitor m=0x608000} priority=0 preferredOrder=0 match=0x608000 specificIndex=-1 isDefault=false ActivityInfo: name=com.google.android.libraries.social.mediamonitor.MediaMonitor packageName=com.google.android.apps.photos enabled=true exported=true processName=com.google.android.apps.photos ... Receiver #3: ResolveInfo{d5c9162 com.google.android.apps.plus/com.google.android.libraries.social.mediamonitor.MediaMonitor m=0x608000} priority=0 preferredOrder=0 match=0x608000 specificIndex=-1 isDefault=false ActivityInfo: name=com.google.android.libraries.social.mediamonitor.MediaMonitor packageName=com.google.android.apps.plus enabled=true exported=true processName=com.google.android.apps.plus ...
待发送的广播是指尚未发送的广播。如果队列中存在大量广播,则意味着系统无法足够快地发送广播来跟上进度。
Active ordered broadcasts [background]:
Active Ordered Broadcast background #133: // size of queue
...
要查看收听某个广播的接收方列表,请查看 dumpsys activity broadcasts 中的 Receiver Resolver Table。以下示例显示了收听 USER_PRESENT 的所有接收方。
------------------------------------------------------------------------------- ACTIVITY MANAGER BROADCAST STATE (dumpsys activity broadcasts) .. Receiver Resolver Table: Full MIME Types: .. Wild MIME Types: .. Schemes: .. Non-Data Actions: .. android.intent.action.USER_PRESENT: BroadcastFilter{8181cc1 u-1 ReceiverList{5d929a8 902 system/1000/u-1 local:eca4dcb}} BroadcastFilter{6371c97 u-1 ReceiverList{2938b16 902 system/1000/u-1 local:840b831}} BroadcastFilter{320c00 u0 ReceiverList{d3a6283 902 system/1000/u0 local:799c532}} BroadcastFilter{e486048 u0 ReceiverList{36fbaeb 902 system/1000/u0 local:5f51e3a}} BroadcastFilter{22b02 u-1 ReceiverList{b3f744d 902 system/1000/u-1 local:de837e4}} BroadcastFilter{3e989ab u0 ReceiverList{f8deffa 2981 com.google.process.gapps/10012/u0 remote:26bd225}} BroadcastFilter{fb56150 u0 ReceiverList{22b7b13 2925 com.android.systemui/10027/u0 remote:c54a602}} BroadcastFilter{63bbb6 u-1 ReceiverList{ba6c751 3484 com.android.nfc/1027/u-1 remote:5c4a478}} BroadcastFilter{95ad20d u0 ReceiverList{d8374a4 3586 com.google.android.googlequicksearchbox/10029/u0 remote:feb3737}} BroadcastFilter{fdef551 u0 ReceiverList{28ca78 3745 com.google.android.gms.persistent/10012/u0 remote:f23afdb}} BroadcastFilter{9830707 u0 ReceiverList{aabd946 3745 com.google.android.gms.persistent/10012/u0 remote:a4da121}} BroadcastFilter{83c43d2 u0 ReceiverList{d422e5d 3745 com.google.android.gms.persistent/10012/u0 remote:f585034}} BroadcastFilter{8890378 u0 ReceiverList{26d2cdb 3745 com.google.android.gms.persistent/10012/u0 remote:dfa61ea}} BroadcastFilter{7bbb7 u0 ReceiverList{214b2b6 3745 com.google.android.gms.persistent/10012/u0 remote:8353a51}} BroadcastFilter{38d3566 u0 ReceiverList{de859c1 3745 com.google.android.gms.persistent/10012/u0 remote:e003aa8}} BroadcastFilter{3435d9f u0 ReceiverList{6e38b3e 3745 com.google.android.gms.persistent/10012/u0 remote:8dd7ff9}} BroadcastFilter{d0a34bb u0 ReceiverList{5091d4a 3745 com.google.android.gms.persistent/10012/u0 remote:d6d22b5}} BroadcastFilter{d43c416 u0 ReceiverList{51a3531 3745 com.google.android.gms.persistent/10012/u0 remote:d0b9dd8}} BroadcastFilter{aabf36d u0 ReceiverList{a88bf84 3745 com.google.android.gms.persistent/10012/u0 remote:a9d6197}} BroadcastFilter{93f16b u0 ReceiverList{5c61eba 17016 com.google.android.gm/10079/u0 remote:24083e5}} BroadcastFilter{68f794e u0 ReceiverList{4cb1c49 947 com.google.android.googlequicksearchbox:search/10029/u0 remote:251d250}} .. MIME Typed Actions:
显示器争用日志记录有时可以表明实际的显示器争用情况,但通常情况下会表明系统负载过重,从而导致所有进程都变慢了。你可能会在系统日志或事件日志中看到 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]
编译可能会占用大量资源,而且会加重设备负载。
09-14 06:27:05.670 2508 2587 E ActivityManager: CPU usage from 0ms to 5857ms later:
09-14 06:27:05.670 2508 2587 E ActivityManager: 84% 5708/dex2oat: 81% user + 2.3% kernel / faults: 3731 minor 1 major
09-14 06:27:05.670 2508 2587 E ActivityManager: 73% 2508/system_server: 21% user + 51% kernel / faults: 10019 minor 28 major
09-14 06:27:05.670 2508 2587 E ActivityManager: 1% 3935/com.android.phone: 0.3% user + 0.6% kernel / faults: 2684 minor 2 major
下载 Google Play 商店更新时,编译可能会在后台进行。在这种情况下,来自 Google Play 商店应用 (finsky) 和 installd 的消息会显示在 dex2oat 消息之前。
10-07 08:42:33.725 11051 11051 D Finsky : [1] InstallerTask.advanceState: Prepare to patch com.garmin.android.apps.virb (com.garmin.android.apps.virb) from content://downloads/my_downloads/3602 format 2
10-07 08:42:33.752 495 495 I installd: free_cache(48637657) avail 15111192576
…
10-07 08:42:39.998 2497 2567 I PackageManager.DexOptimizer: Running dexopt (dex2oat) on: /data/app/vmdl436577137.tmp/base.apk pkg=com.garmin.android.apps.virb isa=arm vmSafeMode=false debuggable=false oatDir = /data/app/vmdl436577137.tmp/oat bootComplete=true
当某个应用正在加载尚未编译的 dex 文件时,编译也可能会在后台进行。在这种情况下,你将看不到 finsky 或 installd 日志记录。
09-14 07:29:20.433 15736 15736 I dex2oat : /system/bin/dex2oat -j4 --dex-file=/data/user/0/com.facebook.katana/app_secondary_program_dex/program-72cef82b591768306676e10161c886b58b34315a308602be.dex.jar --oat-file=/data/user/0/com.facebook.katana/app_secondary_program_dex_opt/program-72cef82b591768306676e10161c886b58b34315a308602be.dex.dex
...
09-14 07:29:25.102 15736 15736 I dex2oat : dex2oat took 4.669s (threads: 4) arena alloc=7MB java alloc=3MB native alloc=29MB free=4MB
创建问题叙述(如何开始、发生了什么、系统是如何应对的)需要一个固定的事件时间轴。你可以利用错误报告中的信息来同步多个日志中的时间轴并确定错误报告的确切时间戳。
错误报告会反映多个并行时间轴(系统日志、事件日志、内核日志)以及针对广播、电池统计信息等的多个专用时间轴。遗憾的是,系统通常会使用不同的时间基准来报告时间轴。
系统日志时间戳和事件日志时间戳采用用户所用的时区(与大多数其他时间戳一样)。例如,当用户点按主屏幕按钮时,系统日志会报告以下内容:
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 表示已锁屏。
显示示例
grep screen_toggled bugreport-2015-10-18-16-52-22.txt
10-18 15:05:04.383 992 992 I screen_toggled: 1
10-18 15:05:07.010 992 992 I screen_toggled: 0
10-18 15:23:15.063 992 992 I screen_toggled: 1
10-18 15:23:25.684 992 992 I screen_toggled: 0
10-18 15:36:31.623 992 992 I screen_toggled: 1
10-18 15:36:37.660 3283 3283 I screen_toggled: 2
错误报告中还包含关于唤醒锁的统计信息,唤醒锁是应用开发者采用的一种机制,用于表明其应用需要设备保持开启状态。(要详细了解唤醒锁,请参阅 PowerManager.WakeLock 和使 CPU 保持运行状态。)
唤醒锁总时长统计信息仅跟踪唤醒锁实际负责使设备保持唤醒状态的时间,不包括屏幕处于开启状态的时间。此外,如果同时持有多个唤醒锁,系统会在它们之间分配唤醒锁时长。
如需直观呈现电源状态方面的更多帮助,请使用 Battery Historian(一种 Google 开放源代码工具,能够利用 Android 错误报告文件分析电池消耗进程)。
“DUMP OF SERVICE”程序包中包含应用版本(以及其他实用信息)。
显示示例
... Packages: ... Package [com.google.android.gms] (3cf534b): userId=10013 sharedUser=SharedUserSetting{98f3d28 com.google.uid.shared/10013} pkg=Package{b8f6a41 com.google.android.gms} codePath=/system/priv-app/PrebuiltGmsCore resourcePath=/system/priv-app/PrebuiltGmsCore legacyNativeLibraryDir=/system/priv-app/PrebuiltGmsCore/lib primaryCpuAbi=arm64-v8a secondaryCpuAbi=armeabi-v7a versionCode=8186448 targetSdk=23 versionName=8.1.86 (2287566-448) splits=[base] applicationInfo=ApplicationInfo{5158507 com.google.android.gms} flags=[ SYSTEM HAS_CODE ALLOW_CLEAR_USER_DATA ] privateFlags=[ PRIVILEGED ] dataDir=/data/user/0/com.google.android.gms supportsScreens=[small, medium, large, xlarge, resizeable, anyDensity] libraries: com.google.android.gms usesOptionalLibraries: com.android.location.provider com.google.android.ble com.android.media.remotedisplay usesLibraryFiles: /system/framework/com.android.media.remotedisplay.jar /system/framework/com.android.location.provider.jar timeStamp=2015-10-14 15:17:56 firstInstallTime=2015-09-22 14:08:35 lastUpdateTime=2015-10-14 15:17:56 signatures=PackageSignatures{db63be6 [1af63d8]} installPermissionsFixed=true installStatus=1 pkgFlags=[ SYSTEM HAS_CODE ALLOW_CLEAR_USER_DATA ] declared permissions: com.google.android.gms.permission.INTERNAL_BROADCAST: prot=signature, INSTALLED ... com.google.android.gms.permission.CAR_VENDOR_EXTENSION: prot=dangerous, INSTALLED User 0: installed=true hidden=false stopped=false notLaunched=false enabled=0 disabledComponents: com.google.android.gms.icing.service.PowerConnectedReceiver ... com.google.android.gms.icing.proxy.AppsMonitor enabledComponents: com.google.android.gms.mdm.receivers.GmsRegisteredReceiver ... com.google.android.gms.subscribedfeeds.SyncService
错误报告中包含大量的进程数据,例如启动和停止时间、运行时时长、相关服务、oom_adj 得分等。要详细了解 Android 如何管理进程,请参阅进程和线程。
procstats 部分包含有关进程及相关服务已运行时长的完整统计信息。要快速获得便于用户阅读的摘要,请搜索 AGGREGATED OVER 以查看最近 3 个小时或 24 个小时的数据,然后搜索 Summary: 以查看进程列表、这些进程已以各种优先级运行的时长,以及它们使用 RAM 的情况(格式为“最小-平均-最大 PSS”/“最小-平均-最大 USS”)。
------------------------------------------------------------------------------- DUMP OF SERVICE processinfo: ------------------------------------------------------------------------------- DUMP OF SERVICE procstats: COMMITTED STATS FROM 2015-10-19-23-54-56 (checked in): ... COMMITTED STATS FROM 2015-10-20-03-00-00 (checked in): ... CURRENT STATS: ... AGGREGATED OVER LAST 24 HOURS: System memory usage: ... Per-Package Stats: ... Summary: ... * com.google.android.gms.persistent / u0a13 / v8186448: TOTAL: 100% (21MB-27MB-40MB/20MB-24MB-38MB over 597) Top: 51% (22MB-26MB-38MB/21MB-24MB-36MB over 383) Imp Fg: 49% (21MB-27MB-40MB/20MB-25MB-38MB over 214) … Start time: 2015-10-19 09:14:37 Total elapsed time: +1d0h22m7s390ms (partial) libart.so AGGREGATED OVER LAST 3 HOURS: System memory usage: ... Per-Package Stats: ... Summary: * com.google.android.gms.persistent / u0a13 / v8186448: TOTAL: 100% (23MB-27MB-32MB/21MB-25MB-29MB over 111) Top: 61% (23MB-26MB-31MB/21MB-24MB-28MB over 67) Imp Fg: 39% (23MB-28MB-32MB/21MB-26MB-29MB over 44) ... Start time: 2015-10-20 06:49:24 Total elapsed time: +2h46m59s736ms (partial) libart.so
dumpsys activity processes 部分会列出当前正在运行的所有进程,并按 oom_adj 得分排序(Android 通过为进程分配 oom_adj 值来表明进程的重要性,该值可由 ActivityManager 动态更新)。这种输出类似于内存快照的输出,但包含有关是什么导致进程运行的更多信息。在以下示例中,以粗体显示的条目表明 gms.persistent 进程正在以 vis(可见)优先级运行,因为该系统进程已经与其 NetworkLocationService 绑定。
显示示例
你可以按照以下步骤来确定过度执行蓝牙低功耗 (BLE) 扫描的应用:
$ grep 'BluetoothLeScanner' ~/downloads/bugreport.txt
07-28 15:55:19.090 24840 24851 D BluetoothLeScanner: onClientRegistered() - status=0 clientIf=5
PID #24840: ProcessRecord{4fe996a 24840:com.badapp/u0a105}
在此示例中,程序包名称为 com.badapp。
Copyright © 2003-2013 www.wpsshop.cn 版权所有,并保留所有权利。