Odex引起的开机概率性异常

最新推荐文章于 2024-04-24 18:15:37 发布

W歹匕示申W

最新推荐文章于 2024-04-24 18:15:37 发布

阅读量4.2k

点赞数

分类专栏： LOG查看

LOG查看专栏收录该内容

4 篇文章 0 订阅

订阅专栏

Odex引起的开机概率性异常

1.开机黑屏（整个界面都是黑的，长按power键可以出现提示框，过一段时间可以恢复-大概3到10分钟，或者重启后恢复）[编辑]问题描述

2.开机进入待机界面不可用（只有状态栏可见，剩下界面为黑色看不到正常桌面，长按power键可以出现提示框，重启后恢复）

3.开机可以正常显示待机界面，但是点击设置或者拨号盘或者信息菜单无所用，无法正常进入，过几分钟可以恢复。

4.开机进入待机闪屏（灭屏亮屏之间切换），过一段时间可以恢复-大概3到10分钟，或者重启后恢复）

[编辑]故障复现

由于问题发生现象比较多，但复现步骤是一样的，且从复现抓取的log包含的信息来推断是同一问题，应根本原因一致：

1.格式化下载软件；

2.开机，点击信息/设置/拨号盘主菜单。

3.重启（或者拔电重开机），点击信息/设置/拨号盘主菜单；重复操作至少3次。

4.重复步骤123，保留复现时候的开机adb log备用。

备注：恢复出厂设置有时候也会出现。

[编辑]原因分析

[编辑]检查log中的异常信息

检查问题复现抓取的开机log发现很多的错误信息，大量的service died, 并导致了虚拟机重启：

11-12 10:57:51.493 D/AndroidRuntime( 3805): Shutting down VM

11-12 10:57:51.496 E/AndroidRuntime( 3805): *** FATAL EXCEPTION IN SYSTEM PROCESS: main

11-12 10:57:51.496 E/AndroidRuntime( 3805): java.lang.RuntimeException: Unable to instantiate service com.qualcomm.location.nlp.NlpProxyService: java.lang.ClassNotFoundException: Didn't find class "com.qualcomm.location.nlp.NlpProxyService" on path: DexPathList[[zip file "/system/framework/com.android.location.provider.jar", zip file "/system/priv-app/com.qualcomm.location/com.qualcomm.location.apk"],nativeLibraryDirectories=[/vendor/lib, /system/lib]]

11-12 10:57:51.496 E/AndroidRuntime( 3805): at android.app.ActivityThread.handleCreateService(ActivityThread.java:2746)

11-12 10:57:51.496 E/AndroidRuntime( 3805): at android.app.ActivityThread.access$1800(ActivityThread.java:151)

11-12 10:57:51.496 E/AndroidRuntime( 3805): at android.app.ActivityThread$H.handleMessage(ActivityThread.java:1386)

11-12 10:57:51.533 I/Process ( 3805): Sending signal. PID: 3805 SIG: 9

11-12 10:57:51.566 E/JavaBinder( 4526): !!! FAILED BINDER TRANSACTION !!!

11-12 10:57:51.587 I/ServiceManager( 256): service 'audio' died

11-12 10:57:51.590 V/AudioFlinger( 3639): 3805 died, releasing its sessions

11-12 10:57:51.590 E/AndroidRuntime( 4293): FATAL EXCEPTION: main

11-12 10:57:51.590 E/AndroidRuntime( 4293): Process: com.android.inputmethod.latin, PID: 4293

11-12 10:57:51.590 E/AndroidRuntime( 4293): java.lang.RuntimeException: Unable to create service com.android.inputmethod.latin.LatinIME: java.lang.RuntimeException: android.os.DeadObjectException

11-12 10:57:51.590 E/AndroidRuntime( 4293): at android.app.ActivityThread.handleCreateService(ActivityThread.java:2771)

11-12 10:57:51.590 E/AndroidRuntime( 4293): at android.app.ActivityThread.access$1800(ActivityThread.java:151)

11-12 10:57:51.590 E/AndroidRuntime( 4293): at android.app.ActivityThread$H.handleMessage(ActivityThread.java:1386)

11-12 10:57:51.587 W/Sensors ( 4470): sensorservice died [0xb8b26020]

11-12 10:57:51.587 I/ServiceManager( 256): service 'serial' died

11-12 10:57:51.587 I/ServiceManager( 256): service 'usb' died 11-12 10:57:51.591 I/Process ( 4293): Sending signal. PID: 4293 SIG: 9

11-12 10:57:51.596 I/ServiceManager( 256): service 'commontime_management' died

11-12 10:57:51.596 I/ServiceManager( 256): service 'restrictions' died

11-12 10:57:51.596 I/ServiceManager( 256): service 'dreams' died

11-12 10:57:51.596 I/ServiceManager( 256): service 'batterystats' died

11-12 10:57:51.771 D/AndroidRuntime( 4588): Shutting down VM

11-12 10:57:51.772 E/AndroidRuntime( 4588): FATAL EXCEPTION: main

11-12 10:57:51.772 E/AndroidRuntime( 4588): Process: android.process.acore, PID: 4588

11-12 10:57:51.772 E/AndroidRuntime( 4588): java.lang.RuntimeException: Unable to get provider com.android.providers.contacts.CallLogProvider: java.lang.NullPointerException: Attempt to invoke interface method 'boolean android.os.IUserManager.hasUserRestriction(java.lang.String, int)' on a null object reference

11-12 10:57:51.772 E/AndroidRuntime( 4588): at android.app.ActivityThread.installProvider(ActivityThread.java:5002)

11-12 11:55:23.923 E/AndroidRuntime( 4654): Suppressed: java.io.IOException: Failed to open oat file from dex location '/system/priv-app/Settings/Settings.apk'

看到这么多错误信息，至少可以断定是framework层以下出了问题，很有可能是boot或者驱动部分的问题，由于问题是概率发生的，所以首先怀疑是不是分区或者flash出了问题。

[编辑]对Flash EMMC进行检查分析

1.使用QMESA/QDUTT工具进行检测，硬件和软件的检测结果都显示正常;

2.由于项目兼容了不同的flash，对不同的flash进行的对比压力验证，结果是都能复现问题；

3.这些flash在其他高通项目上都有量产，且兼容是高通本身做好的；

结论：基本排除flash EMMC的问题。

[编辑]对分区设置排除分析

因我们对分区做过修改，故全部将其还原，保持driver only的版本进行验证，结果问题还是可以复现；

结论：跟分区也没有关系

[编辑]通过开机log分析上层的异常

1. 分析过程中发现出现问题最多的是Launcher，Settings，Dialer，Message，SystemUi几个应用，现象都是开机点击应用报停，log中的直接错误信息都是odex文件找不到：

Caused by: java.io.IOException: Failed to open oat file from /system/priv-app/Telecom/arm/Telecom.odex (error Failed to open oat filename for reading: No such file or directory) (no dalvik_cache availible) and relocation failed.

从log也可以看出,系统有重启, 并有执行dex2oat 重新生成dex文件,而重启后问题就恢复正常了，所以很有可能是apk或jar的dex文件发生了错误引起的.

2. 检查发生问题时的apk对应/data/dalvik-cache/arm目录下的出错的 dex文件，再将重启后恢复正常的dex文件分别pull出来进行对比，发现出问题时的dex文件只有0字节，而工程中WITH_DEXPREOPT 宏并没有开启，那么系统应该在第一次开机的时候会生成dex文件，这也是第一次开机慢的原因，但为什么会是0字节呢？

3.同时发现log中还报了很多类似下面的错误信息：

11-09 19:45:19.758 E/AndroidRuntime(24503): Caused by: java.io.IOException: Failed to remove obsolete file from /data/dalvik-cache/arm/system@priv-app@Launcher3@Launcher3.apk@classes.dex when searching for dex file /system/priv-app/Launcher3/Launcher3.apk: Permission denied

故我们需要在调用流程上面加log来获取更多的信息分析，在LINUX/android/art/runtime/class_linker.cc中

函数的调用的关键节点上我们都添加了相应的log

log检查结果显示odex_checksum_verified & cache_checksum_verified are 0,导致PatchAndRetrieveOat函数不会被调用到，进而ret值为null，所以才会报出上面的log错误信息。

4.接着添加log检查整个调用过程，调用流程如下：

5.找到在打开oatFile文件时报出错误异常：

11-20 11:49:06.369 E/AndroidRuntime( 3204): Caused by: java.io.IOException: File size of 0 bytes not large enough to contain ELF header of 52 bytes: '/data/dalvik-cache/arm/system@priv-app@Settings@Settings.apk@classes.dex'

对应的文件代码：

std::unique_ptr<OatFile> odex_oat_file(OatFile::Open(odex_filename, odex_filename, nullptr, nullptr, executable, &odex_error_msg));

结论：从上面的log跟踪和pull出来的dex文件结果显示一致，都是dex文件为0字节导致了后面的异常。问题还是回到了dex文件为什么会成为了0字节？那就是dex文件开机生成的过程出现了异常。

接下来需要做的就是检查这个流程是否有加特殊动作，之前我们版本的driver only版本也是可以复现问题的，所以基本锁定在高通的修改上面。

6.其他重要信息：

1.我们关注到了了另一个重要的信息是高通的这个版本在未打开预编译优化（ WITH_DEXPREOPT）的情况下，首次开机的速度要比之前的8939平台快很多，这看起来不合常理，8909理论上应该比8939慢；

2. 驱动的同事做了一个对应MSM8909.LA.1.1.c7的driver only版本，经过多次压力测试，并没有复现问题；

结论：我们怀疑是dex还没完全生成系统就开机了，且基本肯定高通在升级版本的时候对这个流程做了特殊优化。

7.比较两个版本MSM8909.LA.1.1.c7-011337109-STD.PROD-1 与 MSM8909.LA.1.2-01234-STD.PROD-2的相关文件差异：

发现了如下修改，经过验证确实是该修改引起的：