BUG实例分析二：卡死在开机动画界面
目录 |
一、现象
开机时一直卡在开机动画界面，动画一直在循环播放，将手机重启也无济于事。
二、准备分析材料
由于之前出现过类似现象的问题，换eng版的lk后恢复正常，故第一反应是抓串口log，抓出来一看，没啥异常，还是要adb log才行。
于是让同事通过AT命令打开手机的adb调试，开始用adb抓取log
==>其实从现象来看，既然开机动画已经在滚动，明显就已经进入到kernel里了，只是之前换lk的现象有干扰，才抓取串口log，从本质上来看直接抓取adb log分析即可
三、开始分析
抓到logcat一看，傻眼了，没有Fatal Exception，但其他Exception还真是不少啊，到底会不会引起系统起不来呢？
系统起不来有两种情况：
1、系统核心进程，如system_server，在运行时遇到错误，如空指针，导致上层重启；
2、系统的某个核心进程直接卡在某个函数里了，如 binder调用，此时系统虽不会重启，但却一直无法完成开机。
如果是情况一，则一般抓取logcat和kernel log，查找Exception便可，此时如有多个Exception，难点就会在于判别哪个Exception才是导致问题的终结所在，这时就可以用对比的方法，找一个最近可以开机的版本，同样抓取一份log，针对每个Exception进行对比，不一样的很可以就是问题的根本原因了。
而如果是情况二，则最有用的就是anr文件了，此时可以使用dumpstate来获取相关信息，通过分析各进程中各线程的当前状态可以方便地看出问题，当然前提是要对这些进程的依赖关系比较了解。
现在看来，是属于第2种情况，一是因为没有看到Fatal Exception；二是system_server的pid不曾变化(adb 也不会中断)。
那就开始dumpstate看各线程状态吧？！
可这么多线程，能不能减少一些工作量呢？
那就行看logcat吧，看到什么时候开始出现问题，最后找到system_server在addService时，跑到这里就基本没log输出了：
01-02 08:05:49.854 I/SystemServer( 515): Country Detector
01-02 08:05:49.854 I/SystemServer( 515): Search Service
01-02 08:05:49.856 I/SystemServer( 515): Search Engine Service
01-02 08:05:49.857 I/SystemServer( 515): DropBox Service
01-02 08:05:49.857 I/SystemServer( 515): Wallpaper Service
01-02 08:05:49.867 V/WallpaperService( 515): WallpaperService startup
01-02 08:05:49.869 V/WallpaperService( 515): loadSettingsLocked
01-02 08:05:49.869 W/WallpaperService( 515): no current wallpaper -- first boot?
01-02 08:05:49.870 I/SystemServer( 515): Audio Service
01-02 08:05:50.439 D/BatteryService( 515): mBatteryVoltage=3951
01-02 08:05:57.119 D/BatteryService( 515): mBatteryVoltage=3975
01-02 08:06:00.000 I/AlarmManager( 515): reset poweroff alarm none
01-02 08:06:00.000 V/ActivityManager( 515): Broadcast: Intent { act=android.intent.action.TIME_TICK flg=0x40000014 (has extras) } ordered=true userid=-1
01-02 08:06:00.001 D/PowerManagerService( 515): acquireWakeLockInternal: lock=1107310128, flags=0x1, tag="AlarmManager", ws={WorkSource: uids=[1000]}, uid=1000, pid=515
01-02 08:06:04.186 D/BatteryService( 515): mBatteryVoltage=3965
查看代码：
try {
Slog.i(TAG, "DropBox Service");
ServiceManager.addService(Context.DROPBOX_SERVICE,
new DropBoxManagerService(context, new File("/data/system/dropbox")));
} catch (Throwable e) {
reportWtf("starting DropBoxManagerService", e);
}
if (context.getResources().getBoolean(
com.android.internal.R.bool.config_enableWallpaperService)) {
try {
Slog.i(TAG, "Wallpaper Service");
if (!headless) {
wallpaper = new WallpaperManagerService(context);
ServiceManager.addService(Context.WALLPAPER_SERVICE, wallpaper);
}
} catch (Throwable e) {
reportWtf("starting Wallpaper Service", e);
}
}
if (!"0".equals(SystemProperties.get("system_init.startaudioservice"))) {
try {
Slog.i(TAG, "Audio Service");
ServiceManager.addService(Context.AUDIO_SERVICE, new AudioService(context));
} catch (Throwable e) {
reportWtf("starting Audio Service", e);
}
}
嗯，正对应！
开始在dumpstate中查看system_server中相关anr，因为上面这里明显有创建 AudioService，所以在堆栈路径中必然包含 AudioService.java这个文件，有了这两个关键字就很好办了:
"android.server.ServerThread" prio=5 tid=13 NATIVE | group="main" sCount=1 dsCount=0 obj=0x41a5ea58 self=0x5bccc888 | sysTid=540 nice=-2 sched=0/0 cgrp=apps handle=1540112656 | state=S schedstat=( 3563176107 205595162 5622 ) utm=303 stm=53 core=0 #00 pc 0002066c /system/lib/libc.so (__ioctl+8) #01 pc 00040b90 /system/lib/libc.so (ioctl+28) #02 pc 00016b59 /system/lib/libbinder.so (android::IPCThreadState::talkWithDriver(bool)+132) #03 pc 00017055 /system/lib/libbinder.so (android::IPCThreadState::waitForResponse(android::Parcel*, int*)+44) #04 pc 0001726f /system/lib/libbinder.so (android::IPCThreadState::transact(int, unsigned int, android::Parcel const&, android::Parcel*, unsigned int)+114) #05 pc 00014a3b /system/lib/libbinder.so (android::BpBinder::transact(unsigned int, android::Parcel const&, android::Parcel*, unsigned int)+34) #06 pc 0004c341 /system/lib/libmedia.so #07 pc 00052177 /system/lib/libmedia.so (android::AudioSystem::get_audio_flinger()+422) #08 pc 000529b3 /system/lib/libmedia.so (android::AudioSystem::isMicrophoneMuted(bool*)+4) #09 pc 0007d5f9 /system/lib/libandroid_runtime.so #10 pc 0001e4d0 /system/lib/libdvm.so (dvmPlatformInvoke+112) #11 pc 0004dd21 /system/lib/libdvm.so (dvmCallJNIMethod(unsigned int const*, JValue*, Method const*, Thread*)+500) #12 pc 000278a0 /system/lib/libdvm.so #13 pc 0002b7fc /system/lib/libdvm.so (dvmInterpret(Thread*, Method const*, JValue*)+180) #14 pc 00060fe1 /system/lib/libdvm.so (dvmCallMethodV(Thread*, Method const*, Object*, bool, JValue*, std::__va_list)+272) #15 pc 0006100b /system/lib/libdvm.so (dvmCallMethod(Thread*, Method const*, Object*, JValue*, ...)+20) #16 pc 00055685 /system/lib/libdvm.so #17 pc 0000e058 /system/lib/libc.so (__thread_entry+72) at android.media.AudioSystem.isMicrophoneMuted(Native Method) at android.media.AudioSystem.setErrorCallback(AudioSystem.java:187) at android.media.AudioService.<init>(AudioService.java:599) at com.android.server.ServerThread.run(SystemServer.java:766)
可以看到是卡在了 AudioSystem::isMicrophoneMuted 这个函数中，而原因则是使用了binder通信，通信的Bn端没有回复，Bn端是AudioSystem::get_audio_flinger -> "media.audio_flinger"
获取不到这个服务，那应该是这个服务没起来，于是继续查看 "media.audio_flinger"，这个服务是运行在 mediaserver中的，查看其线程各堆栈：
Cmd line: /system/bin/mediaserver KERNEL SPACE BACKTRACE, sysTid=143 [<ffffffff>] 0xffffffff from [<c061565c>] __schedule+0x374/0x6e4 [<c06152f4>] __schedule+0xc/0x6e4 from [<c0615b24>] schedule+0x38/0x78 [<c0615af8>] schedule+0xc/0x78 from [<c0613d44>] schedule_timeout+0x154/0x208 [<c0613bfc>] schedule_timeout+0xc/0x208 from [<c04a504c>] mt_deal_result+0x4ec/0x594 [<c04a4b6c>] mt_deal_result+0xc/0x594 from [<c04a5984>] mt_i2c_transfer+0x82c/0xb9c [<c04a5164>] mt_i2c_transfer+0xc/0xb9c from [<c02f60e8>] i2c_transfer+0xbc/0x10c [<c02f6038>] i2c_transfer+0xc/0x10c from [<c02f66d0>] i2c_master_recv+0x58/0x68 [<c02f6684>] i2c_master_recv+0xc/0x68 from [<c03a564c>] tfa9887_i2c_read_block+0xd4/0x108 [<c03a5584>] tfa9887_i2c_read_block+0xc/0x108 from [<c03a5ac0>] tfa9887_read+0x4c/0xe8 [<c03a5a80>] tfa9887_read+0xc/0xe8 from [<c01047c4>] vfs_read+0xac/0x13c [<c0104724>] vfs_read+0xc/0x13c from [<c0104898>] sys_read+0x44/0x70 [<c0104860>] sys_read+0xc/0x70 from [<c000e500>] ret_fast_syscall+0x0/0x30 [<ffffffff>] from [<ffffffff>] "mediaserver" sysTid=143 #00 pc 0002041c /system/lib/libc.so (read+12) #01 pc 00006e07 /system/lib/libtfa9887.so (lxI2cWriteRead+138) #02 pc 0000568f /system/lib/libtfa9887.so (i2cExecuteRS+86) #03 pc 000057ed /system/lib/libtfa9887.so (NXP_I2C_WriteRead+88) #04 pc 00002dfb /system/lib/libtfa9887.so (Tfa98xx_ReadRegister16+62) #05 pc 0000501f /system/lib/libtfa9887.so (Iqoo_Tfa9887_init+406) #06 pc 0004951c /system/lib/libaudio.primary.default.so (android::AudioMTKHardware::HardwareInit(bool)+772) #07 pc 00049670 /system/lib/libaudio.primary.default.so (android::AudioMTKHardware::AudioMTKHardware()+44) #08 pc 00026368 /system/lib/libaudio.primary.default.so (android_audio_legacy::AudioHardwareInterface::create()+212) #09 pc 00026e2c /system/lib/libaudio.primary.default.so #10 pc 00036ce9 /system/lib/libaudioflinger.so (android::AudioFlinger::loadHwModule_l(char const*)+120) #11 pc 00036ea7 /system/lib/libaudioflinger.so (android::AudioFlinger::loadHwModule(char const*)+26) #12 pc 00046e8b /system/lib/libaudioflinger.so #13 pc 0001449d /system/lib/hw/audio_policy.default.so (android_audio_legacy::AudioPolicyCompatClient::loadHwModule(char const*)+8) #14 pc 0001a26f /system/lib/hw/audio_policy.default.so android_audio_legacy::AudioMTKPolicyManager::AudioMTKPolicyManager(android_audio_legacy::AudioPolicyClientInterface*)+1498) #15 pc 00014a45 /system/lib/hw/audio_policy.default.so (createAudioPolicyManager+16) #16 pc 00014977 /system/lib/hw/audio_policy.default.so #17 pc 000467b9 /system/lib/libaudioflinger.so (android::AudioPolicyService::AudioPolicyService()+292) #18 pc 00000bcb /system/bin/mediaserver #19 pc 00000c43 /system/bin/mediaserver #20 pc 0001bd98 /system/lib/libc.so (__libc_init+64) #21 pc 00000a58 /system/bin/mediaserver
==>很明确是卡在 lxI2cWriteRead函数中了
四、总结
第一步：通过现象，总体上确定是上层在不断重启还是卡住
第二步：通过logcat，快速定位到系统大概卡在什么地方显得很重要，这里明确后就有地方下手，接下来就基本是体力活了。
五、真相
呵呵，这一节是现在才加上的。原因很简单，那就是现在，00:16分才把这个问题彻底解决了。
第三节中得出结论：“很明确是卡在 lxI2cWriteRead函数中了”，其实不准确。
虽然从堆栈上看，是每次在dumpstate时都是这样的，但得出这样结果的直接原因是每次在dumpsate mediaserver这个进程信息时，线程143都是通过 lxI2cWriteRead -> tfa9887_i2c_read_block -> mt_deal_result -> schedule_timeout 运行或暂停在 __schedule函数上面。然而，这并不是说就是一定卡在这个函数上面！这非常重要！！！虽然可能之前很多时候遇到的情况都是卡死在相应的函数中了，但不能说一定都是这样！而现在这个就是一个很好例子：
while ( (status & XXXX_STATUS_SWS) == XXXX_STATUS_SWS)
{
err = XXXX_ReadRegister16(handle, XXXX_STATUSREG, &status);
}
如上，真实现象是在这个while循环中一直获取不到设想的状态，出现了死循环！而 mt_deal_result函数中又有调用调度函数 schedule_timeout，所以这个线程98%以上的时间就都是在 __schedule函数中了。
六、再次总结
由于第三节存在一定程度上的判断失误，所以曾经有一小段时间都固执地认为 I2C出问题了，于是用了几个小时尝试启用新线程来规避这类异常；
直到机器莫名其妙地恢复正常后才又真正开始尝试去查看对比手机上层log，了解这个驱动代码的流程及逻辑，到后面找到手机恢复的原因，再次加入log并定位后终于解决了这个问题！
