Android ANR问题分析

感兴趣可以加QQ群85486140，大家一起交流相互学习下！
备注：展讯平台

###案例分析：
####1.等待锁引起的ANR问题
现在遇到一个Monkey跑出来的Camera bug.
#####1).找出ANR发生的时间
一般情况下，拿到测试提供的log之后，需要在trace目录下打开ANR log文件(这里有可能有很多anr日志文件，找到和你有关的就行，如果没有和你有关系的，请转给对应的模块owner)。如下是我在分析该bug时的anr日志文件：

-rwxrwxrwx 1 root root 1439284 Jul 25 06:35 0001.20120101-115416.856.anr*
-rwxrwxrwx 1 root root 820120 Jul 25 06:35 0001.20120102-000727.046.tombstone*
-rwxrwxrwx 1 root root 2318604 Jul 25 06:35 0002.20120101-153245.085.anr*
-rwxrwxrwx 1 root root 2296634 Jul 25 06:35 0003.20120101-153252.049.anr*
-rwxrwxrwx 1 root root 1715999 Jul 25 06:35 0004.20120101-153335.657.anr*

查找后发现Camera的anr日志就是第一个，打开后可以发现开头的地方就是camera应用anr了，可以发现发生anr的时间是在2012-01-01 03:54:11发生的。

ylog.anr 000 [ cat /data/ylog/traces.txt.ylog ] [01-01 11:54:16.966]-
----- pid 22910 at 2012-01-01 03:54:11 -----
Cmd line: com.android.camera2

#####2).初步定位问题发生的原因
在anr日志文件中搜索Blocked关键字（可能有很多Blocked关键字，但是要找到和Camera有关系的那个）

“pool-2-thread-6” prio=5 tid=21 Blocked
| group=“main” sCount=1 dsCount=0 obj=0x12c0aa60 self=0x754f7dac00
| sysTid=22940 nice=10 cgrp=bg_non_interactive sched=0/0 handle=0x753f532450
| state=S schedstat=( 38854895 3200374253 296 ) utm=2 stm=1 core=0 HZ=100
| stack=0x753f430000-0x753f432000 stackSize=1037KB
| held mutexes=
at android.hardware.camera2.CameraManager.getCameraIdList(CameraManager.java:98)

• waiting to lock <0x07410fc0> (a java.lang.Object) held by thread 24//这个地方我们明显可以看到,这个地方在等一个锁，而且是被24号线程锁住的。那我们去24号线程看一下（这里一定要非常注意锁的地址是0x07410fc0，你也可以直接搜索这个地址，找到使用这个锁的地方）。
  at com.android.ex.camera2.portability.AndroidCamera2AgentImpl.updateCameraDevices(AndroidCamera2AgentImpl.java:122)
  at com.android.ex.camera2.portability.AndroidCamera2AgentImpl.(AndroidCamera2AgentImpl.java:112)
  at com.android.ex.camera2.portability.SprdAndroidCamera2AgentImpl.(SprdAndroidCamera2AgentImpl.java:38)
  at com.android.ex.camera2.portability.CameraAgentFactory.getAndroidCameraAgent(CameraAgentFactory.java:129)
• locked <0x080064f9> (a java.lang.Class<com.android.ex.camera2.portability.CameraAgentFactory>)
  at com.android.camera.CameraActivity$14.run(CameraActivity.java:2305)atjava.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1133)atjava.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:607)
  at java.lang.Thread.run(Thread.java:761)

下面的tid=24 表明这就是24号线程，这个时候我们可以看到，正在进行进程间通信。

“Camera2 Handler Thread” prio=5 tid=24 Native
| group=“main” sCount=1 dsCount=0 obj=0x12c194c0 self=0x753c8c2400
| sysTid=2352 nice=0 cgrp=default sched=0/0 handle=0x753ef1c450
| state=S schedstat=( 2330078 16381808 6 ) utm=0 stm=0 core=0 HZ=100
| stack=0x753ee1a000-0x753ee1c000 stackSize=1037KB
| held mutexes=
kernel: __switch_to+0xb0/0xe4
kernel: binder_thread_read+0xa84/0x107c
kernel: binder_ioctl_write_read+0x1fc/0x318
kernel: binder_ioctl+0x47c/0x72c
kernel: do_vfs_ioctl+0x36c/0x594
kernel: SyS_ioctl+0x90/0xa4
kernel: el0_svc_naked+0x24/0x28
native: #00 pc 000000000006a398 /system/lib64/libc.so (__ioctl+4)
native: #01 pc 000000000001f848 /system/lib64/libc.so (ioctl+144)
native: #02 pc 0000000000053f30 /system/lib64/libbinder.so (_ZN7android14IPCThreadState14talkWithDriverEb+260)
native: #03 pc 0000000000054cf4 /system/lib64/libbinder.so (_ZN7android14IPCThreadState15waitForResponseEPNS_6ParcelEPi+352)
native: #04 pc 0000000000049d38 /system/lib64/libbinder.so (_ZN7android8BpBinder8transactEjRKNS_6ParcelEPS1_j+72)
native: #05 pc 00000000000f9474 /system/lib64/libandroid_runtime.so (???)
native: #06 pc 0000000001039fe8 /data/dalvik-cache/arm64/system@framework@boot.oat (Java_android_os_BinderProxy_transactNative__ILandroid_os_Parcel_2Landroid_os_Parcel_2I+196)
at android.os.BinderProxy.transactNative(Native method)
at android.os.BinderProxy.transact(Binder.java:641)
at android.hardware.ICameraService$Stub$Proxy.connectDevice(ICameraService.java:323)
at android.hardware.camera2.CameraManager.openCameraDeviceUserAsync(CameraManager.java:347)

• locked <0x07410fc0> (a java.lang.Object)
  //这里可以看到在CameraManager.java文件的中锁住了这个锁(后面只是打出了函数调用的行数，并不是具体的行数)，根据函数调用栈可以发现，这个地方正在打开Camera。那么我们去看看这个地方到底在干嘛呢。
  at android.hardware.camera2.CameraManager.openCamera(CameraManager.java:478)
  at com.android.ex.camera2.portability.AndroidCamera2AgentImpl$Camera2Handler.handleMessage(AndroidCamera2AgentImpl.java:302)atcom.android.ex.camera2.portability.SprdAndroidCamera2AgentImpl$SprdCamera2Handler.handleMessage(SprdAndroidCamera2AgentImpl.java:222)
  at android.os.Handler.dispatchMessage(Handler.java:102)
  at android.os.Looper.loop(Looper.java:154)
  at android.os.HandlerThread.run(HandlerThread.java:61)

#####3).源码追踪
frameworks/base/core/java/android/hardware/camera2/CameraManager.java
下面可以看到这段代码是在synchronized中包含的，可以知道，这个时候已经将该段互斥代码锁住了，这里
已经锁住了mLock这个锁。

289    private CameraDevice openCameraDeviceUserAsync(String cameraId,
290            CameraDevice.StateCallback callback, Handler handler)
291            throws CameraAccessException {
292        CameraCharacteristics characteristics = getCameraCharacteristics(cameraId);
   synchronized (mLock) {
339                if (supportsCamera2ApiLocked(cameraId)) {
340                    // Use cameraservice's cameradeviceclient implementation for HAL3.2+ devices
341                    ICameraService cameraService =
                       CameraManagerGlobal.get().getCameraService();
342                    if (cameraService == null) {
343                        throw new ServiceSpecificException(
344                            ICameraService.ERROR_DISCONNECTED,
345                            "Camera service is currently unavailable");
346                    }
347                    cameraUser = cameraService.connectDevice(callbacks, id,
348                            mContext.getOpPackageName(), USE_CALLING_UID);
....
  }

导致这个原因就是上一次CloseCamera没有成功，上一次的CameraClient对象仍然驻留在CameraServie 中，CameraService就会提示有多个客户端使用Camera，所以就一直OpenCamera不成功，导致这个线程一直持有mLock这个锁，当其它线程执行这段代码就只有等待锁的份了。
  所以应该分析的问题是，底层为什么没有成功关闭Camera，然后分析问题是不是你的，不是就要流转到其它组。

####2.系统性能引起的ANR问题

####3.UI主线程耗时操作引起的ANR问题

上面部分待后续遇到了再来完善。