• Android异常分析(转)


     

    关于异常

    异常?

    异常就是一种程序中没有预料到的问题,既然是没有预料到的,就可能不在原有逻辑处理范围内,脱离了代码控制,软件可能会出现各种奇怪的现象。比如: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 其他 除了以上类型外,还有些异常可能没有明显的类别,例如一些由硬件引起的异常

    clip_image002

    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触发类型一步一步查找排除

    clip_image004

    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

    clip_image005----- 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

    clip_image007

    l 结合log看代码,找到原因

    clip_image009

    为了让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 对应代码

    clip_image011

    异常分析之OOM

    OOM产生原因

    Android应用内存管理机制是在Java内存管理机制基础上改进的,所以造成OOM的原因两者差不多,即所有对象都在堆上分配空间,堆是有大小限制的,当分配的对象不能被回收仍然占据堆空间,新分配的对象不能获取足够的堆空间时,就会OOM。为什么会这样呢?这就是GC不足的地方,GC只能回收自己记录(有向树)里面不可达的对象,对可达对象认为是有用的,不会被回收。但是可达对象并非一定是有用对象,他们可能是废弃对象(死对象、冗余对象、电灯泡,僵尸),但却无法被GC回收,占据着进程堆空间,下面是网上的一个对象实例化简图

    clip_image013

    各种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

    clip_image015

    clip_image017

    DDMS dump 出来的hprof文件需要经过SDK下hprof-conv(位于sdk/tools下)转换后才能被MAT工具使用

    hprof-conv xxx.hprof d:/xxxold.hprof

    然后使用MAT工具打开

    1. Cache泄漏

    多次插拔耳机后,发现内存一直在涨:

    clip_image019点击Details进入下面页面

    clip_image021 点击Patch To GC Root

    clip_image023发现一个静态变量 sAnimators,此为怀疑的地方,查看代码,加点log,编译调试:

    Log.d("CWW", "sAnimators.size() = " + sAnimators.size());

    可以看出,插拔耳机操作后,sAnimators.size一直会增大。

    处理方法:防止缓存过大,可以设置上限,也可以定期清理下!

    clip_image025

    clip_image027

    对内存敏感的应用,防止缓存过大,除了设置上限外,同时使用SoftReference,当内存吃紧时可以回收缓存,这预防编程的一个技巧,但是使用SoftReference时,注意对null情况的处理,因为获取对象可能已经被回收,获取返回就null

    2. 线程未释放导致的泄漏

    后台播放音乐,不停切换主题,最后Launcher OOM

    如下图,5个AppsCustomizePagedView实例,明显泄漏了:

    clip_image029点击clip_image031,选中一个实例,Path To GC Roots:

    clip_image033 已经看到被CircleProgress.java的MyTimerTask持有:clip_image035

    再看代码,修改后,调试内存,正常:

    clip_image037

    这样改内存泄露解决了, 但是后面引入了新的功能问题, 重新修改了。所以修改类似问题时多小心,确认生命周期已经完成后再执行回收

    结束语:

    这些问题大多是比较难解的问题,大部分都是随机的,往往都是很难复现的,找出规律是很重要的!

    另外,内存泄露不容易发现,一些轻微的泄露,可能要使用一个月才能发现,所以对自己的模块,要自己去检查有没有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并启动它

    clip_image039

    3. Watchdog线程向ServerThread线程发送一个MONITOR message,同时将mCompleted标志位置为false

    clip_image041

    4. 然后Watchdog线程Sleep 60秒(不包含系统睡眠的时间),如果mCompleted标志位不为true,则认为发生watchdog超时,之后Android就会重启.

    5. ServerThread收到这个消息后会依次执行之前每个Service Object的monitor()函数,当执行完后会将mCompleted标志位置为true.

    clip_image043

    SWT LOG分析

    SWT也是一种ANR,普通ANR是某个AP的主线程在一段时间内没有做完某件事情;SWT是SystemServer进程的ServerThread线程在一段时间内没有做完某件事情。所以SWT的分析方法和ANR分析方法是一样的,只是现象不一样,发生SWT手机会重启

    分析方法:

    1. 从eventlog中以watchdog为关键字搜索,记录下这个时刻。

    clip_image045

    2. 然后分析所有Service Object的monitor()为何在这个时刻之前1分钟内没有做完。具体信息主要查找log文件有sys_log和mtklogaee_expdb.fatal.00.SWTdb.fatal.00.SWT.dbg.DEC

    3. 后面具体的分析方法和ANR一样

    重启死机

    重启

    从异常分类来看,重启异常大多数和NE、KE和硬件问题有关,JE方面引起重启死机大多是和系统进程有关,如system_process进程发生了Crash、SWT、JVM Error,AP应用一般是不会引起重启死机的,但偶尔也会

    72平台上,发送短信内容为‘==’时会重启

    clip_image047

    虽然是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》中都有描述

    clip_image049

    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 dMTK_TOOLAndroidToolW1444W1444_full.zipDebugging Tools (Binary)GAT

    Catcher

    是抓取和解析ModemLog的PC端工具,我们经常使用来查看ModemLog,使用说明阅读文档《Catcher_User_Manual_for_Customer.pdf》

    工具获取路径:

    \192.168.1.75 dMTK_TOOLAndroidToolW1444W1444_full.zipCatcher

    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 dMTK_TOOLAndroidTool

    clip_image051

  • 相关阅读:
    Centos LNMP 安装日记
    记录一次开源工单系统
    搭建Lvs负载均衡群集
    使用yum配置lnmp环境(CentOS7.6)
    AWK的介绍学习
    Shell应用之网卡流量监测
    【NLP】RNN、LSTM、GRU
    【机器学习】Softmax及求导
    【PyTorch】使用中注意事项
    【实作】CNN-人脸表情识别
  • 原文地址:https://www.cnblogs.com/xiyuan2016/p/6740623.html
Copyright © 2020-2023  润新知