android调试方法-强烈推荐.docx

Android系统debug经验总结姓名：_胡清河_部门：_智能驱动_日期：_2012.11.17_修订历史记录日期版本说明作者2012-11-19V1.0胡清河目录一 引言.3二 常用查看系统状态和内存命令.3三 ANR7四 CRASH.12五 Memory Analyer定位内存泄漏.14六 动态库死机调试方法.14七 Oops问题的调试和定位.17一 引言Android系统是以linux内核为基础的一个框架，其实本质上就是一个linux操作系统，所以掌握linux系统对分析和调试android一些死机和重启问题致关重要，下面是本人常用的一些分析方法，和大家共享. 一起进步，享受美好生活，是我们每天所追求的.二 常用查看系统状态和内存命令1. cat/proc/meminfo查看系统内存信息，剩余内存 = MemFree + Buffers + CachedAndroid系统中杀程序的这个刽子手被称作LowMemory Killer，它是在Linux内核中实现的。这里它实现了一个机制，由程序的重要性来决定杀谁。通俗来说，谁不干活，先杀谁。Android将程序的重要性分成以下几类，按照重要性依次降低的顺序，可分为以下几种进程：名称Oom_adj解释Foreground app0前台程序Visible app1用户可见的程序Secondary app2后台服务，比如播放音乐Hidden app7后台被隐藏的程序Conent app14Content provider提供进程Empty app15空进程其中每个程序都会有一个oom_adj值，这个值越小，程序越重要，被杀的可能性越低。系统将根据剩余内存依次杀掉oom_odj高的进程来回收内存。有时候杀进程太频繁会引起ANR，因为杀进程引起的进程调度，进程上下文切换是需要很大开销的.2. Procrank查看系统中各进程内存占用情况 VSS - Virtual Set Size 虚拟耗用内存（包含共享库占用的内存） RSS - Resident Set Size 实际使用物理内存（包含共享库占用的内存） PSS - Proportional Set Size 实际使用的物理内存（比例分配共享库占用的内存） USS - Unique Set Size 进程独自占用的物理内存（不包含共享库占用的内存）一般来说内存占用大小有如下规律：VSS = RSS = PSS = USSUSS才是进程真正占用内存的大小.定位某个应用内存泄漏时可用此命令观察。另外一个常用的命令是dumpsys dumpsys meminfo dump所有进程占用内存详细信息dumpsys meminfo d pid dump某个进程占用内存详细信息3. top可以查看进程或线程cpu占用率排名。用这个命令可以很快发现系统中是否存在死循环，cpu占用率高的进程/线程，快速定位到发生问题地方。top -m 12 查看cpu占用率前12的进程top -t m 12 查看cpu占用率前12的线程4. vmstatvmstat是一个查看虚拟内存（Virtual Memory）使用状况的工具，使用vmstat命令可以得到关于进程、内存、内存分页、堵塞IO、traps，上下文切换数及CPU活动的信息. 用这个命令可以观察底层中断是否正常，比如在触摸屏按下的时候，应该会产生大量中断，看这个数目是否和正常时一样。Vmstat d 1 ，每隔一秒种打印出系统信息，包括以下信息：进程r: 运行队列中进程数量b: 等待IO的进程数量Memory(内存)：swpd: 使用虚拟内存大小free: 可用内存大小buff: 用作缓冲的内存大小 swap cache: 用作缓存的内存大小si: 每秒从交换区写到内存的大小so: 每秒写入交换区的内存大小IO:(现在的Linux版本块的大小为1024bytes)bi: 每秒读取的块数 bo: 每秒写入的块数in: 每秒中断数，包括时钟中断。系统cs: 每秒上下文切换数。CPU(以百分比表示)：us: 用户进程执行时间(user time)sy: 系统进程执行时间(system time)id: 空闲时间(包括IO等待时间) wa: 等待IO时间5. df查看系统磁盘分析信息，从下面可以看出当前手机的data分区，系统分区，和SD卡分区等信息，一般我们比较关注的是data分区的剩余容量，当data分区写满时很有可能会导致很多问题，如定屏，虚拟机重启，彩信发不出去等莫名其妙的问题。所以一般在分析问题时，必须确保data空间剩余容量足够.6. am am start n 包名/.activity名，启动设置中的Settings Acitivity.这条命令很有用，可以测试系统中的AMS,WMS, PMS是否工作正常。我们经常碰到开机后launcher启动失败的问题，就可以用am start n com.android.launcher/.Launcher2来定位究竟是系统服务问题还是launcher本身的问题.三 ANR1. ANR是什么？ANR:Application Not Responding，即应用无响应，如下图.2. ANR的类型ANR一般有三种类型：2.1：KeyDispatchTimeout(5 seconds) -主要类型按键或触摸事件在特定时间内无响应2.2：BroadcastTimeout(10 seconds)BroadcastReceiver在特定时间内无法处理完成2.3：ServiceTimeout(20 seconds) -小概率类型Service在特定的时间内无法处理完成3. 主要类型KeyDispatchTimeoutAkey or touch eventwas not dispatched within the specified time（按键或触摸事件在特定时间内无响应）具体的超时时间的定义在framework下的ActivityManagerService.java/ How long we wait until we timeout on key dispatching./ +MediaTek 2012-02-14/ Extend KeyDispatchingTimeout for time needed to perform a call stack pre-dump at 5 second. Static final int KEY_DISPATCHING_TIMEOUT = 8*1000;/ -MediaTek 2012-02-144. 为什么会超时超时时间的计数一般是从按键分发给app开始。超时的原因一般有两种：4.1 当前的事件没有机会得到处理（即UI线程正在处理前一个事件，没有及时的完成或者looper被某种原因阻塞住了）4.2 当前的事件正在处理，但没有及时完成5. 如何避免KeyDispatchTimeout5.1：UI线程尽量只做跟UI相关的工作5.2：耗时的工作（比如数据库操作，I/O，连接网络或者别的有可能阻碍UI线程的操作）把它放入单独的线程处理5.3：尽量用Handler来处理UIthread和别的thread之间的交互5. UI线程UI线程主要包括如下6.1 Activity:onCreate(), onResume(), onDestroy(), onKeyDown(), onClick(),etc6.2 AsyncTask: onPreExecute(), onProgressUpdate(), onPostExecute(), onCancel,etc6.3 Mainthread handler: handleMessage(), post*(runnable r), etc7. 如何去分析ANR04-01 13:12:11.572 I/InputDispatcher( 220): Application is not responding:Window2b263310com.android.email/com.android.email.activity.SplitScreenActivitypaused=false.5009.8ms since event, 5009.5ms since waitstarted04-0113:12:11.572 I/WindowManager( 220): Input event dispatching timedout sending tocom.android.email/com.android.email.activity.SplitScreenActivity04-01 13:12:14.123 I/Process( 220): Sending signal. PID: 21404 SIG: 3-发生ANR的时间和生成trace.txt的时间04-01 13:12:14.123 I/dalvikvm(21404):threadid=4: reacting to signal 304-0113:12:15.872 E/ActivityManager( 220): ANR in com.android.email(com.android.email/.activity.SplitScreenActivity)04-0113:12:15.872 E/ActivityManager( 220): Reason:keyDispatchingTimedOut04-0113:12:15.872 E/ActivityManager( 220): Load: 8.68 / 8.37 / 8.5304-0113:12:15.872 E/ActivityManager( 220):CPUusage from 4361ms to 699ms ago-CPU在ANR发生前的使用情况04-0113:12:15.872 E/ActivityManager( 220): 5.5%21404/com.android.email: 1.3% user + 4.1% kernel / faults: 10 minor04-0113:12:15.872 E/ActivityManager( 220): 4.3%220/system_server: 2.7% user + 1.5% kernel / faults: 11 minor 2 major04-0113:12:15.872 E/ActivityManager( 220): 0.9%52/spi_qsd.0: 0% user + 0.9% kernel04-0113:12:15.872 E/ActivityManager( 220): 0.5%65/irq/170-cyttsp-: 0% user + 0.5% kernel04-0113:12:15.872 E/ActivityManager( 220): 0.5%296/com.android.systemui: 0.5% user + 0% kernel04-0113:12:15.872 E/ActivityManager( 220): 100%TOTAL: 4.8% user + 7.6% kernel + 87% iowait04-0113:12:15.872 E/ActivityManager( 220):CPUusage from 3697ms to 4223ms later:04-0113:12:15.872 E/ActivityManager( 220): 25%21404/com.android.email: 25% user + 0% kernel / faults:191 minor04-0113:12:15.872 E/ActivityManager( 220): 16% 21603/_eas(par.hakan: 16% user + 0% kernel04-0113:12:15.872 E/ActivityManager( 220): 7.2% 21406/GC: 7.2% user + 0% kernel04-0113:12:15.872 E/ActivityManager( 220): 1.8% 21409/Compiler: 1.8% user + 0% kernel04-0113:12:15.872 E/ActivityManager( 220): 5.5%220/system_server: 0% user + 5.5% kernel / faults: 1 minor04-0113:12:15.872 E/ActivityManager( 220): 5.5% 263/InputDispatcher: 0% user + 5.5% kernel04-0113:12:15.872 E/ActivityManager( 220): 32%TOTAL: 28% user + 3.7% kernel从LOG可以看出ANR的类型，CPU的使用情况，如果CPU使用量接近100%，说明当前设备很忙，有可能cpu太忙导致当前主线程ANR，如果CPU使用量很少，说明主线程被BLOCK了，或是线程死锁如果IOwait很高，说明ANR有可能是主线程在进行I/O操作造成的除了看LOG，解决ANR还得需要trace.txt文件，一般在发生ANR的时候会在/data/anr下生成，此外，也可以通过kill 3 pid，这样也会生成traces.txt文件.案例1：线程死锁block, 线程1, 12, 77都处于monitor状态，且互相占有了资源没有释放，导致线程死锁。DALVIK THREADS:(mutexes: tll=0 tsl=0 tscl=0 ghl=0)main prio=5 tid=1 MONITOR | group=main sCount=1 dsCount=0 obj=0x40e584c0 self=0xf759e8 | sysTid=254 nice=0 sched=0/0 cgrp=default handle=1074836852 | schedstat=(34399773681 50728 ) utm=1115 stm=355 core=0 at android.server.BluetoothService.setScanMode(BluetoothService.java:793)- waiting to lock (a android.server.BluetoothService) held by tid=77 (Binder Thread #9) at android.bluetooth.IBluetooth$Stub.onTransact(IBluetooth.java:133) at android.os.Binder.execTransact(Binder.java:338) at com.android.server.SystemServer.init1(Native Method) at com.android.server.SystemServer.main(SystemServer.java:970) at java.lang.reflect.Method.invokeNative(Native Method) at java.lang.reflect.Method.invoke(Method.java:511) at ernal.os.ZygoteInit$MethodAndArgsCaller.run(ZygoteInit.java:809) at ernal.os.ZygoteInit.main(ZygoteInit.java:576) at dalvik.system.NativeStart.main(Native Method)线程77Binder Thread #9 prio=5 tid=77 MONITOR | group=main sCount=1 dsCount=0 obj=0x42571cf8 self=0x158d4f8 | sysTid=863 nice=0 sched=0/0 cgrp=default handle=22762336 | schedstat=(37792082157 47443 ) utm=1166 stm=320 core=1 at android.server.BluetoothDeviceProperties.getProperty(BluetoothDeviceProperties.java:115) - waiting to lock (a java.util.HashMap) held by tid=12 (android.server.ServerThread) at android.server.BluetoothService.getRemoteClass(BluetoothService.java:1272) at android.bluetooth.IBluetooth$Stub.onTransact(IBluetooth.java:335) at android.os.Binder.execTransact(Binder.java:338) at dalvik.system.NativeStart.run(Native Method)android.server.ServerThread prio=5 tid=12 MONITOR | group=main sCount=1 dsCount=0 obj=0x417ef4d8 self=0x129ebd0 | sysTid=269 nice=-2 sched=0/0 cgrp=default handle=19248400 | schedstat=( 22032655436 55428321116 95250 ) utm=1698 stm=505 core=0 at android.server.BluetoothService.updateDeviceServiceChannelCache(BluetoothService.java:1550)- waiting to lock (a android.server.BluetoothService) held by tid=77 (Binder Thread #9) at android.server.BluetoothDeviceProperties.addProperties(BluetoothDeviceProperties.java:80) at android.server.BluetoothDeviceProperties.updateCache(BluetoothDeviceProperties.java:136) at android.server.BluetoothDeviceProperties.getProperty(BluetoothDeviceProperties.java:123) at android.server.BluetoothService.getUuidFromCache(BluetoothService.java:1297) at android.server.BluetoothService.getRemoteUuids(BluetoothService.java:1292) at android.server.BluetoothA2dpService.onBluetoothEnable(BluetoothA2dpService.java:341) at android.server.BluetoothA2dpService.access$400(BluetoothA2dpService.java:55) at android.server.BluetoothA2dpService$1.onReceive(BluetoothA2dpService.java:161) at android.app.LoadedApk$ReceiverDispatcher$Args.run(LoadedApk.java:746) at android.os.Handler.handleCallback(Handler.java:605) at android.os.Handler.dispatchMessage(Handler.java:92) at android.os.Looper.loop(Looper.java:137) at com.android.server.ServerThread.run(SystemServer.java:906)案例2：主线程在等待下条消息进入消息队列，消息队列堵塞，主线程ANRCmdline: com.android.emailDALVIK THREADS:(mutexes: tll=0tsl=0 tscl=0 ghl=0 hwl=0 hwll=0)main prio=5 tid=1NATIVE| group=main sCount=1 dsCount=0obj=0x2aad2248 self=0xcf70 | sysTid=21404 nice=0 sched=0/0cgrp=fopen-error:2 handle=1876218976atandroid.os.MessageQueue.nativePollOnce(Native Method) atandroid.os.MessageQueue.next(MessageQueue.java:119) atandroid.os.Looper.loop(Looper.java:110)at android.app.ActivityThread.main(ActivityThread.java:3688) at java.lang.reflect.Method.invokeNative(Native Method) atjava.lang.reflect.Method.invoke(Method.java:507)ernal.os.ZygoteInit$MethodAndArgsCaller.run(ZygoteInit.java:866) at ernal.os.ZygoteInit.main(ZygoteInit.java:624) at dalvik.system.NativeStart.main(Native Method)案例3：IOWait很高，说明当前系统在忙于I/O，如读写文件等Process:com.android.emailActivity:com.android.email/.activity.MessageViewSubject:keyDispatchingTimedOutCPU usage from 2550ms to -2814ms ago:5%187/system_server: 3.5% user + 1.4% kernel / faults: 86 minor 20major4.4% 1134/com.android.email: 0.7% user + 3.7% kernel /faults: 38 minor 19 major4% 372/com.android.eventstream: 0.7%user + 3.3% kernel / faults: 6 minor1.1% 272/com.android.phone:0.9% user + 0.1% kernel / faults: 33 minor0.9%252/com.android.systemui: 0.9% user + 0% kernel0%409/com.android.eventstream.telephonyplugin: 0% user + 0% kernel /faults: 2 minor0.1% 632/com.android.devicemonitor: 0.1% user + 0%kernel100%TOTAL: 6.9% user + 8.2% kernel +84%iowait8. 线程状态THREAD_RUNNING = 1, /* RUNNABLE or running now */THREAD_TIMED_WAIT = 2, /* TIMED_WAITING in Object.wait() */THREAD_MONITOR = 3, /* BLOCKED on a monitor */THREAD_WAIT = 4, /* WAITING in Object.wait() */THREAD_INITIALIZING= 5, /* allocated, not yet running */THREAD_STARTING = 6, /* started, not yet on thread list */THREAD_NATIVE = 7, /* off in a JNI native method */THREAD_VMWAIT = 8, /* waiting on a VM resource */THREAD_SUSPENDED = 9, /* suspended, usually by GC or debugger */9. ANR调查和解决措施9.1 分析logcat日志，找到ANR堆栈9.2 通过traces.txt看线程状态, 是否死锁9.3 查看系统信息，vmstat, cpu占用率，9.4 剩余内存等是否正常，如低内存可能触发系统杀进程导致大量进程调度和切换.9.5 尽量不要再UI线程干重活，数据库操作，网络连接等，主线程尽可能少干事情9.6 通过post MSG处理主线程消息9.7 不要申明过多的变量以免GC太频繁四Crash当应用进程发生错误，如空指针，缺少资源等而导致运行失败，并弹出crash对话框。定位crash也比较简单，一般在logcat日志中，搜索crash或exception，就能找到crash时的系统信息和堆栈等，根据堆栈很快就能知道到底是哪个函数出问题.从一下日志可以看出，发生crash是在com.android.settings/com.android.settings.DateTimeSettings，Caused by: java.lang.NullPointerException信息表示空指针引起crashE/AndroidRuntime(14883): FATAL EXCEPTION: mainE/AndroidRuntime(14883): java.lang.RuntimeException: Unable to resume activity com.android.settings/com.android.settings.DateTimeSettings: java.lang.NullPointerExceptionE/AndroidRuntime(14883): at android.app.ActivityThread.performResumeActivity(ActivityThread.java:2226)E/AndroidRuntime(14883): at android.app.ActivityThread.handleResumeActivity(ActivityThread.java:2241)E/AndroidRuntime(14883): at android.app.ActivityThread.handleLaunchActivity(ActivityThread.java:1774)E/AndroidRuntime(14883): at android.app.ActivityThread.access$1500(ActivityThread.java:155)E/AndroidRuntime(14883): at android.app.ActivityThread$H.handleMessage(ActivityThread.java:999)E/AndroidRuntime(14883): at android.os.Handler.dispatchMessage(Handler.java:130)E/AndroidRuntime(14883): at android.os.Looper.loop(SourceFile:351)E/AndroidRuntime(14883): at android.app.ActivityThread.main(ActivityThread.java:3826)E/AndroidRuntime(14883): at java.lang.reflect.Method.invokeNative(Native Method)E/AndroidRuntime(14883): at java.lang.reflect.Method.invoke(Method.java:538)E/AndroidRuntime(14883): at ernal.os.ZygoteInit$MethodAndArgsCaller.run(ZygoteInit.java:969)E/AndroidRuntime(14883): at ernal.os.ZygoteInit.main(ZygoteInit.java:727)E/AndroidRuntime(14883): at dalvik.system.NativeStart.main(Native Method)E/AndroidRuntime(14883): Caused by: java.lang.NullPointerExceptionE/AndroidRuntime(14883): at com.android.settings.DateTimeSettings.onResume(DateTimeSettings.java:179)E/AndroidRuntime(14883): at android.app.Instrumentation.callActivityOnResume(Instrumentation.java:1189)E/AndroidRuntime(14883): at android.app.Activity.performResume(Activity.java:3930)E/AndroidRuntime(14883): at android.app.ActivityThread.performResumeActivity(ActivityThread.java:2216)E/AndroidRuntime(14883): . 12 more五Memory Analyzer定位内存泄漏略.六动态库死机调试方法为了演示的目的，我在libsensors的open_sensors_device中故意制造了一个crash：static int open_sensors_device(const struct hw_module_t* module, const char* name, struct hw_device_t* device) int status = -EINVAL; /if our sensor system is ready,commented next line /return status; char* ptr = 0; *ptr =0; / .这里ptr指向0地址，但后面却往这个0地址写0，因此会crash。crash时，logcat可以看到android打印的backtrace：I/SystemServer( 1046): Sensor ServiceI/DEBUG ( 971): * * * * * * * * * * * * * * * *I/DEBUG ( 971): Build fingerprint: Questers/kylin/kylin/aspen168:2.2.1/FRG83/builder.20110307.131914:user/release-keysI/DEBUG ( 971): pid: 1046, tid: 1059 system_server I/DEBUG ( 971): signal 11 (SIGSEGV), fault addr 00000000I/DEBUG ( 971): r0 8150218c r1 81501250 r2 ae205500 r3 00000000I/DEBUG ( 971): r4 ae203d5b r5 8150210c r6 43891f6c r7 42084eb0I/DEBUG ( 971): r8 4a570b80 r9 42084ea8 10 42084e94 fp 0011f3e0I/DEBUG ( 971): ip a7f0110c sp 4a570b50 lr ae203247 pc 815009ba cpsr a0000030I/DEBUG ( 971): #00 pc 000009ba /system/lib/hw/sensors.default.soI/DEBUG ( 971): #01 pc 00003244 /system/lib/libandroid_servers.soI/DEBUG ( 971): #02 pc 00011cf4 /system/lib/libdvm.soI/DEBUG ( 971): #03 pc 0003f194 /system/lib/libdvm.soI/DEBUG ( 971): #04 pc 00016cb8 /system/lib/libdvm.soI/DEBUG ( 971): #05 pc 0001d604 /system/lib/libdvm.soI/DEBUG ( 971): #06 pc 0001c49c /system/lib/libdvm.soI/DEBUG ( 971): #07 pc 00055374 /system/lib/libdvm.soI/DEBUG ( 971): #08 pc 0005558a /system/lib/libdvm.soI/DEBUG ( 971): #09 pc 00049672 /system/lib/libdvm.soI/DEBUG ( 971): #10 pc 000113fc /system/lib/libc.soI/DEBUG ( 971): #11 pc 00010ee0 /system/lib/libc.soI/DEBUG ( 971): I/DEBUG ( 971): code around pc:I/DEBUG ( 971): 81500998 600b189b 46c04770 00001772 fffffef4 I/DEBUG ( 971): 815009a8 4d2bb5f0 492b1c0c b083447d 90012300 I/DEBUG ( 971): 815009b8 701b1869 1c161c20 efa8f7ff d11f1e07 I/DEBUG ( 971): 815009c8 f7ff205c 2100ef62 1c04225c ef92f7ff I/DEBUG ( 971): 815009d8 21014821 6562424a 60676020 4a20491f I/DEBUG ( 971): I/DEBUG ( 971): code around lr:I/DEBUG ( 971): ae203224 b082480e 1820447c f7fea901 2800eaf6 I/DEBUG ( 971): ae203234 9801d10f 4a0b490a 18616943 681b18a2 I/DEBUG ( 971): ae203244 28004798 9801d105 1d034669 47a06fdc I/DEBUG ( 971): ae203254 2000e000 bd10b002 00001ee8 ffffec3f I/DEBUG ( 971): ae203264 ffffec47 000003ec 4e3db5f0 4c3d1c05 I/DEBUG ( 971): I/DEBUG ( 971): stack:I/DEBUG ( 971): 4a570b10 4a570b80 I/DEBUG ( 971): 4a570b14 42084e74 I/DEBUG ( 971): 4a570b18 0027be10 heapI/DEBUG ( 971): 4a570b1c 0011f3e0 heapI/DEBUG ( 971): 4a570b20 00000001 I/DEBUG ( 971): 4a570b24 00000007 I/DEBUG ( 971): 4a570b28 00000000 I/DEBUG ( 971): 4a570b2c 00000000 I/DEBUG ( 971): 4a570b30 420ce5c0 /dev/ashmem/dalvik-LinearAlloc (deleted)I/DEBUG ( 971): 4a570b34 0011f3e0 heapI/DEBUG ( 971): 4a570b38 0027be10 heapI/DEBUG ( 971): 4a570b3c 422962b0 /dev/ashmem/dalvik-LinearAlloc (deleted)I/DEBUG ( 971): 4a570b40 4a570bb0 I/DEBUG ( 971): 4a570b44 000000d0 I/DEB