初见问题(2015-09-25)
2015-09-25:产品灰度第一天灰度结果:Crash率9.08%,主要是如下两个Crash所导致
TOP1: java.lang.NoClassDefFoundError
堆栈还原: java.lang.NoClassDefFoundError: com/example/assistant/activity/BaseActivity java.lang.Class.newInstanceImpl(Native Method) java.lang.Class.newInstance(Class.java:1319) android.app.Instrumentation.newActivity(Instrumentation.java:1056) android.app.ActivityThread.performLaunchActivity(ActivityThread.java:1984) android.app.ActivityThread.handleLaunchActivity(ActivityThread.java:2094) android.app.ActivityThread.access$600(ActivityThread.java:134) android.app.ActivityThread$H.handleMessage(ActivityThread.java:1202) android.os.Handler.dispatchMessage(Handler.java:99) android.os.Looper.loop(Looper.java:137) android.app.ActivityThread.main(ActivityThread.java:4791) java.lang.reflect.Method.invokeNative(Native Method) java.lang.reflect.Method.invoke(Method.java:511) com.android.internal.os.ZygoteInit$MethodAndArgsCaller.run(ZygoteInit.java:766) com.android.internal.os.ZygoteInit.main(ZygoteInit.java:533) dalvik.system.NativeStart.main(Native Method)
TOP2: java.lang.RuntimeException/java.lang.ClassNotFoundException
堆栈还原:堆栈还原:堆栈还原:堆栈还原:堆栈还原:堆栈还原:堆栈还原:堆栈还原:堆栈还原:堆栈还原:堆栈还原:堆栈还原:堆栈还原:堆栈还原:堆栈还原:堆栈还原:堆栈还原:堆栈还原:堆栈还原:堆栈还原:堆栈还原:堆栈还原:堆栈还原:堆栈还原:堆栈还原:堆栈还原:堆栈还原:堆栈还原:堆栈还原:堆栈还原:堆栈还原:堆栈还原:堆栈还原:堆栈还原:堆栈还原:堆栈还原:堆栈还原:堆栈还原:堆栈还原:堆栈还原: java.lang.RuntimeException: Unable to instantiate activity ComponentInfo{com.example.android.downloader/com.example.assistant.activity.SpaceCleanActivity}: java.lang.ClassNotFoundException: Didn’t find class “com.example.assistant.activity.SpaceCleanActivity” on path: DexPathList[[zip file “/data/app/com.example.android.downloader-1.apk”, zip file “/data/data/com.example.android.downloader/app_dex/extlibs.1.jar”],nativeLibraryDirectories=[/data/app-lib/com.example.android.downloader-1, /vendor/lib, /system/lib]] android.app.ActivityThread.performLaunchActivity(ActivityThread.java:2274) android.app.ActivityThread.handleLaunchActivity(ActivityThread.java:2417) android.app.ActivityThread.access$800(ActivityThread.java:151) android.app.ActivityThread$H.handleMessage(ActivityThread.java:1342) android.os.Handler.dispatchMessage(Handler.java:110) android.os.Looper.loop(Looper.java:193) android.app.ActivityThread.main(ActivityThread.java:5322) java.lang.reflect.Method.invokeNative(Native Method) java.lang.reflect.Method.invoke(Method.java:515) com.android.internal.os.ZygoteInit$MethodAndArgsCaller.run(ZygoteInit.java:829) com.android.internal.os.ZygoteInit.main(ZygoteInit.java:645) dalvik.system.NativeStart.main(Native Method) cause by: java.lang.ClassNotFoundException: Didn’t find class “com.example.assistant.activity.SpaceCleanActivity” on path: DexPathList[[zip file “/data/app/com.example.android.downloader-1.apk”, zip file “/data/data/com.example.android.downloader/app_dex/extlibs.1.jar”],nativeLibraryDirectories=[/data/app-lib/com.example.android.downloader-1, /vendor/lib, /system/lib]] dalvik.system.BaseDexClassLoader.findClass(BaseDexClassLoader.java:56) java.lang.ClassLoader.loadClass(ClassLoader.java:497) java.lang.ClassLoader.loadClass(ClassLoader.java:457) android.app.Instrumentation.newActivity(Instrumentation.java:1061) android.app.ActivityThread.performLaunchActivity(ActivityThread.java:2265) android.app.ActivityThread.handleLaunchActivity(ActivityThread.java:2417) android.app.ActivityThread.access$800(ActivityThread.java:151) android.app.ActivityThread$H.handleMessage(ActivityThread.java:1342) android.os.Handler.dispatchMessage(Handler.java:110) android.os.Looper.loop(Looper.java:193) android.app.ActivityThread.main(ActivityThread.java:5322) java.lang.reflect.Method.invokeNative(Native Method) java.lang.reflect.Method.invoke(Method.java:515) com.android.internal.os.ZygoteInit$MethodAndArgsCaller.run(ZygoteInit.java:829) com.android.internal.os.ZygoteInit.main(ZygoteInit.java:645) dalvik.system.NativeStart.main(Native Method)
线索
- java.lang.NoClassDefFoundError: com/example/assistant/activity/BaseActivity
- java.lang.ClassNotFoundException: Didn’t find class “com.example.assistant.activity.SpaceCleanActivity”
联想
这两个Crash问题在灰度版本中首次发现,恰好该灰度版本有新加入的dex分包功能,于是dex分包合情合理的成了头号怀疑对象,但是Check分包方案后有如下疑问:
- Crash栈中的BaseActivity和SpaceCleanActivity在主dex中
- 这两个Crash在测试中不可复现
按常理,在主dex中的类,并不会出现NoClassDefFoundError/ClassNotFoundException这种Crash,不过谨慎起见我们还是对分包方案进行了一翻研究,也做了一些微调,并做了小量灰度,然而并没有效果
意外发现Crash与dex分包无关(2015-09-28)
2015-09-28: 在经过几次分包方案调整后依然不见效果,项目时间紧迫,为了尽快暴露其它Crash,我们尝试先针对android 3.0以上用户灰度一个不带分包方案的版本, 2015-09-29: 发现不带dex分包方案的灰度版本中依然出现之前的 TOP1&TOP2 Crash
重新审视问题,搜集更多线索
经过新版本的灰度结果,发现TOP1&TOP2的Crash与分包毫无关系,之前一直研究的方向是错误的,所以我们把再次关注问题本身,深入研究问题,查找到了更多的线索
Bugly抓取的自定义日志内容:
Bugly抓取的系统日志内容:
如上图,我们得到以下线索
- 程序是运行了一段较长的时间才Crash的 appliationCreateTime:2015-09-29 21:23:33 crashTime:2015-09-29 22:49:58
- Crash发生时,没有进入过任何activity contact:991327—,NotAdd—
- Crash发生时,都伴随有如下错误信息 09-29 22:49:57.948 I/dalvikvm( 4203): Rejecting re-init on previously-failed class Lcom/example/assistant/activity/BaseActivity; v=0x0 09-29 22:49:57.948 W/dalvikvm( 4203): Class init failed in newInstance call (Lcom/example/pangu/activity/AppDetailActivityV5;) 09-29 22:49:57.948 D/AndroidRuntime( 4203): Shutting down VM 09-29 22:49:57.948 W/dalvikvm( 4203): threadid=1: thread exiting with uncaught exception (group=0x40f852a0) 09-29 22:49:57.948 W/System.err( 4203): java.lang.NoClassDefFoundError: com/example/assistant/activity/BaseActivity
分析
推论:
- 线索1+线索3 -> Crash发生的前提条件:程序在后台运行了一段时间,且BaseActivity类之前初始化失败过
- 线索2+线索3 -> Crash的触发操作:第一次创建Activity对象(BaseActivity是所有Activity的基类)
结论:根本原因在于推论1:“BaseActivity类之前初始化失败过”。顺着这个方向,我们查了BaseActivity.java文件svn的提交记录,近期并没有修改。
偶然发现重要线索
BaseActivity.java类近期无修改,且常规测试也不能重现BaseActivity类初始化失败的场景,问题再次陷入僵局。幸好,在RDM异常上报平台逐个查看logcat信息的过程中,我们在第4页找到了一个关键的日志信息 log.txt
我们分别来看看对应关键地方的代码
- com.example.nucleus.manager.spaceclean.SpaceScanManager.y(ProGuard:709)
- com.example.assistant.activity.BaseActivity.<clinit>(ProGuard:750)
- 再来看看SpaceCleanActivity.isActivityInfront
问答分析
问:为什么ExceptionInInitializerError这个关键性的log信息如此难找? 答:log.txt抓取的是程序挂掉瞬间的logcat信息,因为输出这个关键log信息的地方并不会导致程序挂掉,所以只有在很极端的情况(ExceptionInInitializerError和NoClassDefFoundError同时发生)下,才有可能抓到这个关键信息
问:为什么这个关键地方SpaceScanManager.y(ProGuard:709)的ExceptionInInitializerError异常没有导致程序挂掉? 答:因为在调用的地方异常被try/catch住了
// 幸亏此处还有tr.printStackTrace();,否者任何加载失败的蛛丝马迹都将不复存在
制造场景重现Crash
知道了Crash发生的原理,很简单的就能制造场景重现Crash,代码如下:
结果: 第一处被catch住的java.lang.ExceptionInInitializerError异常
第二处没有catch的java.lang.NoClassDefFoundError异常
解决
知道了根因,解决就简单了,直接上解决方法
- 将静态变量isActivityInfront从SpaceCleanActivity移至SpaceScanManager(非BaseActivity子类,不会导致在非主线程中加载BaseActivity类)
- 修复BaseActivity中存在的潜在风险,将静态成员
2015-09-30: 问题解决啦,国庆的3倍也顺利逃过啦
灰度验证
吸取之前的教训,这次我们同时灰度了两个包,对比dex分包所带来的问题:
验证结果:9112和9113版本Crash率均在预期的范围内(0.5%左右),且无TOP1&TOP2 Crash
总结
- 惯性思维思考问题容易陷入盲区
- 相信证据,当证据和常识相违背时,给证据多一点信任,深入分析其根因
- 当解决问题遇到瓶颈时,不要忘记重新审视问题本身,挖掘每一条细微的线索,并认真对待
- 关于NoClassDefFoundError Crash的技术总结:
- 使用java类的静态变量时,会触发类的加载操作,类加载过程会初始化类的所有静态变量,如果静态变量初始化失败,将导致类加载失败,并抛出java.lang.ExceptionInInitializerError异常
- 若类加载java.lang.ExceptionInInitializerError异常被try/catch住,下次new类对象时将产生java.lang.NoClassDefFoundError异常
- 谨慎使用try/catch,try/catch很容易掩盖事故的第一现场。try/catch处,至少要将catch到的异常进行输出throwable.printStackTrace();,否则第一现场不光会被掩盖,而且找不到任何蛛丝马迹