赞
踩
关于异常
异常?
异常就是一种程序中没有预料到的问题,既然是没有预料到的,就可能不在原有逻辑处理范围内,脱离了代码控制,软件可能会出现各种奇怪的现象。比如:android系统常见异常现象有应用无响应、应用停止运行、冻屏、重启、死机等,这些异常系统有统一的异常处理机制,出现异常系统就会执行相应的操作,最终有相应的现象体现出来。另外,一些不在预料之中的界面显示问题,操作问题,运行卡顿问题等也可以归于异常,只不过这种异常是人为逻辑缺陷,对系统来说是正常的,但这些缺陷在异常现象中占比却相当大,直接体现出软件的质量。
架构决定逻辑,逻辑决定异常多少
异常重要性
都说ISO比android系统好,iphone手机比android手机好,为什么呢?其实最基本原因就是ISO系统稳定性和体验做得好,很少出现异常,使用一段时间后运行还是很稳健,且它的界面、操作、运行速度等体验也做的非常好,所以才被大家认可。
异常关系一个软件的稳定性
缺陷关系一个软件的性能和体验
打造精品,追求卓越,对软件开发人员来说就是追求零异常、零缺陷。我们做的软件,负责的模块应用质量怎么样,是不是精品都是通过异常数量和缺陷数量来体现的。这篇文档主要讲的是log分析,属于事后处理,处理的是用户的抱怨和不满,处理的是我们开发时埋下的雷或未挖掘出的雷,是被动的。所以,更重要的是软件量产前开发工作中,怎样去减少异常和缺陷,保证软件质量。
(公司战略,对研发部门要求)
异常分类
Android是一个庞大而复杂的系统,涉及多种语言,所以其异常也很复杂。根据android系统架构层次,我们也把android异常层次化,分为JE、NE、KE、EE、其他类别
l JE (Java layer exception) 一般是在应用层和框架层发生的异常,通常是由Java代码,XML代码引起的。比如各种RuntimeException, ANR(Application Not Responding)、SWT(Software Watchdog Timeout)等
l NE (Native layer exception) 发生在Linux用户空间的异常,通常是由C/C++代码和库文件引起的。比如内核发出的NE信号(SIGILL、 SIGABRT、 SIGBUS等)
l KE (Kernel layer execption) 通常指内核故障或内核错误,由于在内核模式下出错,这类异常是非常严重的,往往会导致重启、死机或无法开机等
l EE (External (Modem) exception) 从名字看就能猜到Modem这一部分是比较特殊的,独立的。Modem有自己的内存空间和代码,为手机通讯提供服务,一旦这一部分发生异常,需要MDlog,此log需用AEE-LogVie工具解析,解析是需要对应版本的数据文件,具体使用可参考《GAT_User_Guide(Customer).pdf》文档
l 其他 除了以上类型外,还有些异常可能没有明显的类别,例如一些由硬件引起的异常
Android系统架构图
异常复现和日志打印
异常复现
解决异常的关键之一就是复现异常。比如,对于偶现异常,如果能要找到必现路径,那问题就变得容易多了。解决异常问题首先要了解异常,清楚异常怎么发生的,什么条件下发生的。下面是异常复现需要注意的地方。
异常复现注意点:
l 仔细阅读异常描述,弄清楚异常产生步骤、异常概率、异常预置条件,并预判属于哪一类异常
l 复现前,确认是否打LOG,如果是偶现问题,务必开启此异常类型需要LOG
l 根据描述复现异常,如果是偶现问题,注意条件,尽量找出异常必现路径
l 如果没有复现异常,和异常信息提供人沟通,再次复现
客户报的异常可能是正常的
日志打印
解决异常的关键之二就是抓取有效的LOG。比如,ANR异常必须抓取bugreport或trace.txt文件,NE异常必须抓取aee_exp, EE异常必须抓取MDLog。根据不同异常类型抓取不同LOG,有针对性的分析。下面是异常日志打印需要注意的地方。
一份错误的LOG是分析问题的, 发生了异常,没有抓到正确的LOG, 就可能浪费掉一次补救机会
异常打印注意点:
l 抓LOG前,清除SD卡和内部存储里原有的LOG文件,减少不必要的LOG带来的分析困扰
l 抓log前,设置好异常产生的预置条件,特别是需要对比的异常,确保预置条件一样
l 根据异常类型,打开必须的LOG。任何异常,mtklog都是必要的,重启、死机异常,尽量多抓LOG
l 抓LOG后,记录下异常出现的手机显示时间,必要时截图,连同异常描述一起备注在log里
异常分析之ANR
ANR种类
l Key Dispatch Timeout (8s)
No response to an input event(e.g. key press, screen touch) within 8 seconds
l Broadcast Timeout
A BroadcastReceiver hasn’t finished executing within setting seconds
BROADCAST_FG_TIMEOUT: 10s
BROADCAST_BG_TIMEOUT: 60s
l Service Timeout (20s)
Request service failed within 20 seconds
按键或广播等事件在特定时间内未响应,这里特定时间在系统里设定的,各平台可能不一样,上面的时间是KK平台默认超时时间,一般定义在ActivityManagerService.java类中,如:
static final int KEY_DISPATCHING_TIMEOUT = 5*1000
ANR产生原因
l 应用进程有一个主线程(main thread)和一个信息队列(main message queue)main thead == activity thread
l 主线程负责处理像Draw、Listen、receive等UI事件
l 主线程负责从消息队列中取出信息并分发它
l 主线程在完成当前信息处理之前,不会再取信息队列中的信息
l 如果主线程在处理当前信息时卡住,没有及时分发,ANR就会出现
如何避免ANR
l UI线程尽量只做跟UI相关的工作
l 耗时的工作(比如数据库操作,I/O,连接网络或者别的有可能阻碍UI线程的操作)把它放入单独的线程处理
l 尽量用Handler来处理UI thread和别的thread之间的交互
ANR分析需要的LOG
l MTKlog,主要是其中的Aee_exp和MobileLog
l Trace.txt文件(data/anr目录下)或者bugreport日志(使用adb bugreport > bugreport.txt或者GAT工具输出)
ANR分析流程
由于ANR类型多,触发ANR的条件也多,且LOG中没有像RuntimeException异常那样有明显的关键字Fatal来准确定位问题点,所以,ANR分析相对比较麻烦点,但是只要有完整的LOG,按照方法去分析还是很快的。下图是MTK分析ANR的流程图,通过ANR触发类型一步一步查找排除
MTK分析ANR的流程图
l 首先,检查log中是否有ANR信息
events_log
00:28:19.999 544 564 I am_anr : [0,3003,com.example.test,11058758,keyDispatchingTimedOut]
main_log 或 Sys_log
00:28:31.193 544 564 E ANRManager: ANR in com.example.test (com.example.test/.MainActivity)
traces.txt
----- pid 3003 at 2013-06-01 00:28:20 -----
Cmd line: com.example.test
JNI: CheckJNI is off; workarounds are off; pins=0; globals=147
DALVIK THREADS:
(mutexes: tll=0 tsl=0 tscl=0 ghl=0)
"main" prio=5 tid=1 SUSPENDED
| group="main" sCount=1 dsCount=0 obj=0x40d5ea18 self=0x40d4e0d8
| sysTid=3003 nice=0 sched=0/0 cgrp=apps handle=1074645084
| state=S schedstat=( 16757266877 27764681051 104147 ) utm=1184 stm=491 core=0
#00 pc 0002746c /system/lib/libc.so (__futex_syscall3+8)
#01 pc 0000f694 /system/lib/libc.so (__pthread_cond_timedwait_relative+48)
………
#12 pc 00020580 [stack]
at libcore.io.Posix.strerror(Native Method)
at libcore.io.ForwardingOs.strerror(ForwardingOs.java:128)
at libcore.io.ErrnoException.getMessage(ErrnoException.java:52)
at java.lang.Throwable.getLocalizedMessage(Throwable.java:187)
at java.lang.Throwable.toString(Throwable.java:361)
at java.lang.Throwable.printStackTrace(Throwable.java:321)
at java.lang.Throwable.printStackTrace(Throwable.java:355)
at java.lang.Throwable.printStackTrace(Throwable.java:288)
at java.lang.Throwable.printStackTrace(Throwable.java:236)
at com.example.test.MainActivity.monitorANR(MainActivity.java:200)
at com.example.test.MainActivity$1.handleMessage(MainActivity.java:38)
at android.os.Handler.dispatchMessage(Handler.java:107)
at android.os.Looper.loop(Looper.java:194)
l 如果定位不到信息点,再看看CUP使用情况
main_log
06-01 00:28:31.193 544 564 E ANRManager: ANR in com.example.test (com.example.test/.MainActivity)
06-01 00:28:31.193 544 564 E ANRManager: Reason: keyDispatchingTimedOut
06-01 00:28:31.193 544 564 E ANRManager: Load: 10.5 / 11.94 / 6.06
06-01 00:28:31.193 544 564 E ANRManager: Android time :[2013-06-01 00:28:31.176] [454.712]
06-01 00:28:31.193 544 564 E ANRManager: CPU usage from 0ms to 11736ms later:
06-01 00:28:31.193 544 564 E ANRManager: 34% 3003/com.example.test: 26% user + 8.4% kernel / faults: 708 minor 10 major
06-01 00:28:31.193 544 564 E ANRManager: 32% 3018/logcat: 10% user + 21% kernel / faults: 4143 minor
06-01 00:28:31.193 544 564 E ANRManager: 23% 379/mobile_log_d: 8.7% user + 14% kernel / faults: 10 minor 1 major
06-01 00:28:31.193 544 564 E ANRManager: 19% 171/adbd: 1.7% user + 17% kernel / faults: 423 minor
06-01 00:28:31.193 544 564 E ANRManager: 18% 544/system_server: 8.5% user + 9.8% kernel / faults: 899 minor 2 major
06-01 00:28:31.193 544 564 E ANRManager: 14% 132/mobile_log_d: 1.7% user + 13% kernel
……
06-01 00:28:31.193 544 564 E ANRManager: 96% TOTAL: 36% user + 60% kernel + 0% iowait
从CPU使用率可以看出
如果CPU使用量接近100%,说明当前设备很忙(内存不足,循环处理等)
如果CPU使用量很少,说明主线程被BLOCK了(Activity超过5秒等)
如果IOwait很高,说明ANR有可能是主线程在进行I/O操作造成的(数据库操作、文件操作、网络操作等)
l 根据CPU使用情况,在main_log和event_log中查找有用信息
main_log
l 结合log看代码,找到原因
为了让ANR出现,在onClick里面用了while(true),不断的文件读写,报错不断打印(不要这样打log)
等待锁引起的ANR
l events_log
22:05:22.819934 732 755 I am_anr : [0,24992,com.example.test,8961606,Input dispatching timed out (Waiting because the touched window has not finished processing the input events that were previously delivered to it.)
l main_log或 Sys_log
01-01 22:05:22.857387 732 755 E ANRManager: ANR in com.example.test (com.example.test/.MainActivity)
01-01 22:05:22.857387 732 755 E ANRManager: Reason: Input dispatching timed out (Waiting because the touched window has not finished processing the input events that were previously delivered to it.)
l traces.txt
----- pid 29364 at 2014-01-01 22:05:22 ----- Cmd line: com.example.test
JNI: CheckJNI is off; workarounds are off; pins=0; globals=263
DALVIK THREADS: (mutexes: tll=0 tsl=0 tscl=0 ghl=0)
"main" prio=5 tid=1 MONITOR | group="main" sCount=1 dsCount=0 obj=0x419cede0 self=0x419bd8a8
| sysTid=29364 nice=0 sched=0/0 cgrp=apps handle=1074139524
| state=S schedstat=( 265882702 297191749 665 ) utm=19 stm=7 core=0
at com.example.test.MainActivity$ANRBroadcast.onReceive(MainActivity.java:~120)
- waiting to lock <0x41edc968> (a java.lang.Object) held by tid=11 (Thread-720) at android.app.LoadedApk$ReceiverDispatcher$Args.run(LoadedApk.java:798) at android.os.Handler.handleCallback(Handler.java:808)
l 对应代码
异常分析之OOM
OOM产生原因
Android应用内存管理机制是在Java内存管理机制基础上改进的,所以造成OOM的原因两者差不多,即所有对象都在堆上分配空间,堆是有大小限制的,当分配的对象不能被回收仍然占据堆空间,新分配的对象不能获取足够的堆空间时,就会OOM。为什么会这样呢?这就是GC不足的地方,GC只能回收自己记录(有向树)里面不可达的对象,对可达对象认为是有用的,不会被回收。但是可达对象并非一定是有用对象,他们可能是废弃对象(死对象、冗余对象、电灯泡,僵尸),但却无法被GC回收,占据着进程堆空间,下面是网上的一个对象实例化简图
各种OOM情景
l 资源对象没有回收,如cursor,bitmap等
通常关闭Cursor的方法:
Cursor cursor = mDownloadManager.query(new Query());
try {
if (cursor.moveToFirst()) {
do {
int index = cursor.getColumnIndex(DownloadManager.COLUMN_ID);
long downloadId = cursor.getLong(index);
ids.add(downloadId);
} while (cursor.moveToNext());
}
} finally {
cursor.close();
}
另外,在adapter中使用cursor时,需在cursor改变的时候先关闭原来的cursor, 但通常我们都是用android提供的CursorAdapter,其changeCursor函数会将原来的Cursor释放掉,并替换为新的Cursor,所以你不用担心原来的Cursor没有被关闭。
l 注册没有对应的去注册,如各种监听
l 生命周期问题引起的无法回收,如果static、线程等
l 其他
所有发生OOM情景最终都可以认为是对象没有被回收,如,cursor没有close(),bitmap没有recycle(),监听没有unregister…()等等都是因为对象没有被回收,GC认为这些对象是可达的、正在使用的,导致这些应该被回收的对象不能被回收,最终造成OOM。
大多数的回收方法,如close()、recycle()、unregister…(),其实都是把不再使用的对象置为null,这样GC就能回收原来对象所占空间。所以在编程的时候,对全局变量,特别是容器之类的对象和status 修饰对象,要关注其生命周期,不再需要就及时置为null或调用相应的回收方法
OOM LOG分析
发生OOM异常后,如果仅仅只有mtklog,只能从Log中知道发生了OOM,但怎么发生的却看不出来,所以通常需要OOM分析工具,下面以MAT工具为例
在eclipse中,监视你需要分析OOM的进程,某种规律下,发现进程内存一直在涨,抓取hprof文件:
这里的某种规律,是指某种操作下,不断重复就会出现OOM。经常导致OOM的操作有来回切换界面、回来滑动list、不断的点击某个按钮等,这些操作都是不断更新界面,不断的生产对象,生产的对象导致堆空间越来越大,最终发生OOM
DDMS dump 出来的hprof文件需要经过SDK下hprof-conv(位于sdk/tools下)转换后才能被MAT工具使用
hprof-conv xxx.hprof d:/xxxold.hprof
然后使用MAT工具打开
1. Cache泄漏
多次插拔耳机后,发现内存一直在涨:
发现一个静态变量 sAnimators,此为怀疑的地方,查看代码,加点log,编译调试:
Log.d("CWW", "sAnimators.size() = " + sAnimators.size());
可以看出,插拔耳机操作后,sAnimators.size一直会增大。
处理方法:防止缓存过大,可以设置上限,也可以定期清理下!
对内存敏感的应用,防止缓存过大,除了设置上限外,同时使用SoftReference,当内存吃紧时可以回收缓存,这预防编程的一个技巧,但是使用SoftReference时,注意对null情况的处理,因为获取对象可能已经被回收,获取返回就null
2. 线程未释放导致的泄漏
后台播放音乐,不停切换主题,最后Launcher OOM
如下图,5个AppsCustomizePagedView实例,明显泄漏了:
已经看到被CircleProgress.java的MyTimerTask持有:
再看代码,修改后,调试内存,正常:
这样改内存泄露解决了, 但是后面引入了新的功能问题, 重新修改了。所以修改类似问题时多小心,确认生命周期已经完成后再执行回收
结束语:
这些问题大多是比较难解的问题,大部分都是随机的,往往都是很难复现的,找出规律是很重要的!
另外,内存泄露不容易发现,一些轻微的泄露,可能要使用一个月才能发现,所以对自己的模块,要自己去检查有没有OOM,可以下班时挂上monkey,有时候是能跑出来的
从OOM联想到性能问题,性能问题很多是界面刷新、对象生命周期、冗余操作、不必要的线程等引起的……
异常分析之SWT
认识SWT
SWT是指Android Watchdog Timeout,应用层看门狗超时,通常我们说的WDT(Watchdog Timeout)是HWT,硬件看门狗超时。应用层Watchdog主要实现是在frameworks/base/services/java/com/android/server/Watchdog.java里,其实现原理看看这个类就知道,主要逻辑是:
1. Watchdog是单例模式,监控系统几个比较重要的Service,如:MountService、ActivityManagerService、InputManagerService等,这些Service在启动时通过调用Watchdog.getInstance().addMonitor(this); 加入到Watchdog的监控列表中
2. 在SystemServer的 ServerThread线程中,初始化watchdog并启动它
3. Watchdog线程向ServerThread线程发送一个MONITOR message,同时将mCompleted标志位置为false
4. 然后Watchdog线程Sleep 60秒(不包含系统睡眠的时间),如果mCompleted标志位不为true,则认为发生watchdog超时,之后Android就会重启.
5. ServerThread收到这个消息后会依次执行之前每个Service Object的monitor()函数,当执行完后会将mCompleted标志位置为true.
SWT LOG分析
SWT也是一种ANR,普通ANR是某个AP的主线程在一段时间内没有做完某件事情;SWT是SystemServer进程的ServerThread线程在一段时间内没有做完某件事情。所以SWT的分析方法和ANR分析方法是一样的,只是现象不一样,发生SWT手机会重启
分析方法:
1. 从eventlog中以watchdog为关键字搜索,记录下这个时刻。
2. 然后分析所有Service Object的monitor()为何在这个时刻之前1分钟内没有做完。具体信息主要查找log文件有sys_log和mtklog\aee_exp\db.fatal.00.SWT\db.fatal.00.SWT.dbg.DEC
3. 后面具体的分析方法和ANR一样
重启死机
重启
从异常分类来看,重启异常大多数和NE、KE和硬件问题有关,JE方面引起重启死机大多是和系统进程有关,如system_process进程发生了Crash、SWT、JVM Error,AP应用一般是不会引起重启死机的,但偶尔也会
72平台上,发送短信内容为‘==’时会重启
虽然是Mms引起的,但最终也是System_process挂掉了,导致重启
重启异常分析步骤(JE):
1. 确认异常类型(用QAAT跑一下做初步判断,如果是NE、KE让驱动人员帮忙解决)
2. 找到第一时间发生错误的地方,因为后面的错误多半是因为前面错误引起的,那就没有意义
3. 根据JE类型,结合对应工具分析LOG
死机
这里说的死机就是冻屏,停留在一个界面没反应。死机问题很少遇到,且大多不是一个用层问题,下面简单说下可能造成死机的原因和分析需要信息
死机可能原因:
1. 输入系统或者输入驱动问题
2. 系统逻辑问题或阻塞
3. Surfacefinger问题
4. 显示系统或LCM驱动问题
相关信息和抓log:
1. 确认adb是否可用
2. 抓取bugreport,adb bugreport > d:/bugreport.txt
3. 抓取dumpstate信息,adb shell dumpstate > d:/dumpstate.txt
4. 抓取CPU信息,adb shell top –t –m 5 > d:/cpu.txt
5. 确认是否可以拨打电话,adb shell am start –a android.intent.action.CALL tel:10086(看界面是否能够更新)
6. 查看按键和触屏报点,adb shell getevent
7. 抓取Surfacefinger进程信息,先adb shell ps –p找出pid,然后使用adb shell rtt –f bt –p pid > rtt.txt
LOG相关工具
MTK提供了多种抓取和查看LOG的工具, 如:mtklogger,GAT,Catcher,LogView,QAAT等,这些工具在文档《MediaTek_Logging_SOP.pdf》中都有描述
Mtklogger:
Mtklogger是抓取log的apk,整合了ModemLog,MobileLog,NetworkLog and SystemLogger,在工程模式操作就可以打相关log了。
GAT:
基于SDK调试开发的GUI工具,新增了Log Recoder,Debug Configuration Setting,DBpuller,adb command,Process Information view,Profiling Tools,LogView,Plug-in Script。是调试和抓log的神器,使用说明阅读文档《GAT_User_Guide(Customer).pdf》
工具获取路径(以W1444版本为例):
\\192.168.1.75\rd\MTK_TOOL\AndroidTool\W1444\W1444_full.zip\Debugging Tools (Binary)\GAT
Catcher:
是抓取和解析ModemLog的PC端工具,我们经常使用来查看ModemLog,使用说明阅读文档《Catcher_User_Manual_for_Customer.pdf》
工具获取路径:
\\192.168.1.75\rd\MTK_TOOL\AndroidTool\W1444\W1444_full.zip\Catcher
LogView:
可以查看APlog,Taglog,MTKlog,但最常用的是用来查看NE时产生的AEE DB文件里的log,具体使用参考《GAT_User_Guide(Customer).pdf》
工具获取路径:
此工具已集成到GAT
QAAT:
快速分析log的工具,涵盖错误类型较广,很多地方都可以用,其实他的原理就是过滤关键字,把各种类型的错误过滤出来,是一个分析LOG非常便捷的工具,具体使用参考《MediaTek_Logging_SOP.pdf》
工具获取路径:
附件或者\\192.168.1.75\rd\MTK_TOOL\AndroidTool
Copyright © 2003-2013 www.wpsshop.cn 版权所有,并保留所有权利。