记录ANR产生的原因及其定位分析

ANR概述

ANR是Android中一个独有的概念，全称是Application Not Responding(应用程序无响应)。

ANR的直观体验是用户在操作APP的过程中，感觉界面卡顿，比如按下某个按钮，打开某个页面等，当卡顿超过一定时间(一般是5秒)时就会出现ANR对话框。

这时查看Logcat，一般可以发现ANR以及traces.txt字样。

ANR产生原因

只有当应用程序的UI线程响应超时才会引起ANR，超时产生原因一般有两种：

当前事件没有机会得到处理，例如UI线程正在响应另外一个事件，当前事件由于某种原因被阻塞了。

当前的事件正在处理，但由于耗时太长没能及时完成。

根据ANR产生的原因不同，超时时间也不尽相同，从本质上讲，产生ANR的原因有三种，大致可以对应到Android中四大组件的三个(Activity/View、BroadcastReceiver和Service)。

KeyDispatchTimeout 最常见的一种类型，原因是View的按键事件或者触摸事件在特定的时间(5秒)内无法得到响应。

BroadcastTimeout 原因是BroadcastReceiver的onReceive()函数运行在主线程中，在特定的时间(10秒)内无法完成处理。

ServiceTimeout 比较少出现的一种类型，原因是Service的各个生命周期函数在特定时间(20秒)内无法完成处理。

典型的ANR问题场景应用程序UI线程存在耗时操作，例如在UI线程中进行网络请求，数据库操作或者文件操作等，可能会导致UI线程无法及时处理用户输入等。当然在Android4.0之后，如果在UI线程中进行网络操作，将会抛出NetworkOnMainThreadException异常

应用程序的UI线程等待子线程释放某个锁，从而无法处理用户输入。

耗时的动画需要大量的计算工作，可能导致CPU负载过重。

ANR日志分析

获取ANR产生的trace文件

ANR产生时, 系统会生成一个traces.txt的文件放在/data/anr/下. 可以通过adb命令将其导出到本地:

1adb pull data/anr/traces.txt .

分析traces.txt1

2

3

4

5

6

7

8

9

10

11

12

13

14

15

16

17

18

19

20

21

22

23

24

25

26

27

28

29

30

31

32

33

34

35

36

37

38

39

40

41

42

43

44

45

46

47

48

49

50

51

52

53

54

55

56

57

58

59

60

61

62

63

64

65

66

67

68

69

70

71

72

73

74

75

76

77

78

79

80

81

82

83

84

85

86

87

88

89

90

91

92

93

94

95

96

97

98

99

100

101

102

103

104

105

106

107

108

109

110

111

112

113

114

115

116

117

118

119

120

121

122

123

124

125----- pid 7163 at 2017-01-20 19:01:00 -----

Cmd line: com.test.getapppackage

Build fingerprint: 'HUAWEI/GRA-UL00/HWGRA:6.0/HUAWEIGRA-UL00/C00B370:user/release-keys'

ABI: 'arm64'

Build type: optimized

Zygote loaded classes=4071 post zygote classes=425

Intern table: 56221 strong; 27 weak

JNI: CheckJNI is on; globals=310 (plus 365 weak)

Libraries: /system/lib64/libandroid.so /system/lib64/libcompiler_rt.so /system/lib64/libfm_jni.so /system/lib64/libhwdeviceinfo.so /system/lib64/libhwtheme_jni.so /system/lib64/libjavacrypto.so /system/lib64/libjnigraphics.so /system/lib64/libmedia_jni.so /system/lib64/libwebviewchromium_loader.so libjavacore.so (10)

Heap: 10% free, 17MB/19MB; 35084 objects

Dumping cumulative Gc timings

Start Dumping histograms for 1 iterations for partial concurrent mark sweep

SweepMallocSpace:Sum: 2.697ms 99% C.I. 0.020ms-2.673ms Avg: 1.348ms Max: 2.677ms

MarkConcurrentRoots:Sum: 2.144ms 99% C.I. 0.069ms-2.075ms Avg: 1.072ms Max: 2.075ms

UpdateAndMarkImageModUnionTable:Sum: 2.139ms 99% C.I. 2.139ms-2.139ms Avg: 2.139ms Max: 2.139ms

ProcessMarkStack:Sum: 1.188ms 99% C.I. 5us-1173us Avg: 396us Max: 1173us

SweepSystemWeaks:Sum: 947us 99% C.I. 947us-947us Avg: 947us Max: 947us

MarkAllocStackAsLive:Sum: 641us 99% C.I. 641us-641us Avg: 641us Max: 641us

UpdateAndMarkZygoteModUnionTable:Sum: 421us 99% C.I. 421us-421us Avg: 421us Max: 421us

MarkRootsCheckpoint:Sum: 400us 99% C.I. 138us-262us Avg: 200us Max: 262us

ImageModUnionClearCards:Sum: 120us 99% C.I. 38us-82us Avg: 60us Max: 82us

ReMarkRoots:Sum: 105us 99% C.I. 105us-105us Avg: 105us Max: 105us

ScanGrayAllocSpaceObjects:Sum: 74us 99% C.I. 3us-71us Avg: 37us Max: 71us

FinishPhase:Sum: 68us 99% C.I. 68us-68us Avg: 68us Max: 68us

MarkNonThreadRoots:Sum: 47us 99% C.I. 20us-27us Avg: 23.500us Max: 27us

SwapBitmaps:Sum: 41us 99% C.I. 41us-41us Avg: 41us Max: 41us

ZygoteModUnionClearCards:Sum: 36us 99% C.I. 9us-27us Avg: 18us Max: 27us

AllocSpaceClearCards:Sum: 34us 99% C.I. 0.250us-18us Avg: 8.500us Max: 18us

ScanGrayImageSpaceObjects:Sum: 30us 99% C.I. 30us-30us Avg: 30us Max: 30us

(Paused)ScanGrayImageSpaceObjects:Sum: 29us 99% C.I. 29us-29us Avg: 29us Max: 29us

(Paused)PausePhase:Sum: 24us 99% C.I. 24us-24us Avg: 24us Max: 24us

MarkingPhase:Sum: 22us 99% C.I. 22us-22us Avg: 22us Max: 22us

(Paused)ScanGrayAllocSpaceObjects:Sum: 13us 99% C.I. 0.250us-13us Avg: 6.500us Max: 13us

RevokeAllThreadLocalAllocationStacks:Sum: 11us 99% C.I. 11us-11us Avg: 11us Max: 11us

InitializePhase:Sum: 10us 99% C.I. 10us-10us Avg: 10us Max: 10us

EnqueueFinalizerReferences:Sum: 9us 99% C.I. 9us-9us Avg: 9us Max: 9us

PreCleanCards:Sum: 6us 99% C.I. 6us-6us Avg: 6us Max: 6us

ScanGrayZygoteSpaceObjects:Sum: 5us 99% C.I. 5us-5us Avg: 5us Max: 5us

(Paused)ScanGrayZygoteSpaceObjects:Sum: 4us 99% C.I. 4us-4us Avg: 4us Max: 4us

BindBitmaps:Sum: 3us 99% C.I. 3us-3us Avg: 3us Max: 3us

MarkRoots:Sum: 2us 99% C.I. 2us-2us Avg: 2us Max: 2us

SwapStacks:Sum: 1us 99% C.I. 1us-1us Avg: 1us Max: 1us

(Paused)ProcessMarkStack:Sum: 0 99% C.I. 0ns-0ns Avg: 0ns Max: 0ns

Done Dumping histograms

partial concurrent mark sweep paused:Sum: 818us 99% C.I. 818us-818us Avg: 818us Max: 818us

partial concurrent mark sweep total time: 11.323ms mean time: 11.323ms

partial concurrent mark sweep freed: 12553 objects with total size 679KB

partial concurrent mark sweep throughput: 1.14118e+06/s / 60MB/s

Total time spent in GC: 11.323ms

Mean GC size throughput: 58MB/s

Mean GC object throughput: 1.10863e+06 objects/s

Total number of allocations 47637

Total bytes allocated 17MB

Total bytes freed 679KB

Free memory 1963KB

Free memory until GC 1963KB

Free memory until OOME 238MB

Total memory 19MB

Max memory 256MB

Zygote space size 1528KB

Total mutator paused time: 818us

Total time waiting for GC to complete: 3.125us

Total GC count: 1

Total GC time: 11.323ms

Total blocking GC count: 0

Total blocking GC time: 0

suspend all histogram:Sum: 7.287ms 99% C.I. 1us-3310.080us Avg: 142.882us Max: 4197us

DALVIK THREADS (18):

"Signal Catcher" daemon prio=5 tid=2 Runnable

| group="system" sCount=0 dsCount=0 obj=0x12cc00a0 self=0x55a19bf650

| sysTid=7168 nice=0 cgrp=top_visible sched=0/0 handle=0x7f7866e450

| state=R schedstat=( 1491568 160160 7 ) utm=0 stm=0 core=2 HZ=100

| stack=0x7f78572000-0x7f78574000 stackSize=1013KB

| held mutexes= "mutator lock"(shared held)

(no managed stack frames)

//由此可看出是由于主线程sleep阻塞导致后面线程在waiting中无法执行

"main" prio=5 tid=1 Sleeping

| group="main" sCount=1 dsCount=0 obj=0x753d4df0 self=0x559fdab9d0

| sysTid=7163 nice=-1 cgrp=top_visible sched=0/0 handle=0x7f7d54f000

| state=S schedstat=( 653285568 12361024 238 ) utm=51 stm=14 core=2 HZ=100

| stack=0x7fd73ba000-0x7fd73bc000 stackSize=8MB

| held mutexes=

at java.lang.Thread.sleep!(Native method)

- sleeping on <0x03cd324f> (a java.lang.Object)

at java.lang.Thread.sleep(Thread.java:1046)

- locked <0x03cd324f> (a java.lang.Object)

at java.lang.Thread.sleep(Thread.java:1000)

at com.test.getapppackage.WsYunIntentActivity$1.onClick(WsYunIntentActivity.java:35)

at android.view.View.performClick(View.java:5264)

at android.view.View$PerformClick.run(View.java:21297)

at android.os.Handler.handleCallback(Handler.java:743)

at android.os.Handler.dispatchMessage(Handler.java:95)

at android.os.Looper.loop(Looper.java:150)

at android.app.ActivityThread.main(ActivityThread.java:5621)

at java.lang.reflect.Method.invoke!(Native method)

at com.android.internal.os.ZygoteInit$MethodAndArgsCaller.run(ZygoteInit.java:794)

at com.android.internal.os.ZygoteInit.main(ZygoteInit.java:684)

"JDWP" daemon prio=5 tid=3 WaitingInMainDebuggerLoop

| group="system" sCount=1 dsCount=0 obj=0x12cc30a0 self=0x559fda58a0

| sysTid=7169 nice=0 cgrp=top_visible sched=0/0 handle=0x7f78568450

| state=S schedstat=( 45619808 1392976 40 ) utm=3 stm=1 core=0 HZ=100

| stack=0x7f7846c000-0x7f7846e000 stackSize=1013KB

| held mutexes=

kernel: __switch_to+0x74/0x8c

kernel: poll_schedule_timeout+0x58/0xe4

kernel: do_select+0x3e0/0x510

kernel: core_sys_select+0x1a4/0x2f8

kernel: SyS_pselect6+0x234/0x258

kernel: cpu_switch_to+0x48/0x4c

(no managed stack frames)

"ReferenceQueueDaemon" daemon prio=5 tid=4 Waiting

| group="system" sCount=1 dsCount=0 obj=0x12cbbb80 self=0x55a19867c0

| sysTid=7170 nice=0 cgrp=top_visible sched=0/0 handle=0x7f78460450

| state=S schedstat=( 526240 565968 9 ) utm=0 stm=0 core=5 HZ=100

| stack=0x7f7835e000-0x7f78360000 stackSize=1037KB

| held mutexes=

at java.lang.Object.wait!(Native method)

- waiting on <0x0bccaddc> (a java.lang.Class)

at java.lang.Daemons$ReferenceQueueDaemon.run(Daemons.java:147)

- locked <0x0bccaddc> (a java.lang.Class)

at java.lang.Thread.run(Thread.java:833)

前面两行表明ANR发生的进程pid, 时间, 以及进程名字(包名).

后面跟着的堆栈中可以跟踪到产生anr的地方

线程有很多状态，了解这些状态的意义对分析ANR的原因是有帮助的，总结如下

Thread.java中定义的状态

Thread.cpp中定义的状态

说明

TERMINATED

ZOMBIE

线程死亡，终止运行

RUNNABLE

RUNNING/RUNNABLE

线程可运行或正在运行

TIMED_WAITING

TIMED_WAIT

执行了带有超时参数的wait、sleep或join函数

BLOCKED

MONITOR

线程阻塞，等待获取对象锁

WAITING

WAIT

执行了无超时参数的wait函数

NEW

INITIALIZING

新建，正在初始化，为其分配资源

NEW

STARTING

新建，正在启动

RUNNABLE

NATIVE

正在执行JNI本地函数

WAITING

VMWAIT

正在等待VM资源

RUNNABLE

SUSPENDED

线程暂停，通常是由于GC或debug被暂停

UNKNOWN

未知状态

如何避免ANR

不要在主线程(UI线程)里面做繁重的操作。

主线程阻塞的

开辟单独的子线程来处理耗时阻塞事务。

CPU满负荷, I/O阻塞的

I/O阻塞一般来说就是文件读写或数据库操作执行在主线程了, 也可以通过开辟子线程的方式异步执行。

内存不够用的

增大VM内存, 使用largeHeap属性。

哪些地方是执行在主线程的Activity的所有生命周期回调都是执行在主线程的。

Service默认是执行在主线程的。

BroadcastReceiver的onReceive回调是执行在主线程的。

没有使用子线程的looper的Handler的handleMessage, post(Runnable)是执行在主线程的。

AsyncTask的回调中除了doInBackground, 其他都是执行在主线程的。

View的post(Runnable)是执行在主线程的。

使用子线程的方式有哪些

避免ANR的方法就是在子线程中执行耗时阻塞操作。

继承Thread1

2

3

4

5

6

7

8

9

10class MyThread extends Thread{

@Override

public void run(){

super.run();

}

}

MyThread m = new MyThread();

m.start();

实现Runnable接口1

2

3

4

5

6

7

8

9class MyThread implements Runnable{

@Override

public void run(){

}

}

MyThread m = new MyThread();

m.run();

使用AsyncTask

Android特有的方式,异步任务

1

2

3

4

5

6

7

8

9

10

11

12

13

14

15

16

17

18

19

20

21

22

23

24

25

26

27

28

29private class DownloadFilesTask extends AsyncTask{

// Do the long-running work in here

// 执行在子线程

protected Long doInBackground(URL... urls){

int count = urls.length;

long totalSize = 0;

for (int i = 0; i < count; i++) {

totalSize += Downloader.downloadFile(urls[i]);

publishProgress((int) ((i / (float) count) * 100));

// Escape early if cancel() is called

if (isCancelled()) break;

}

return totalSize;

}

// This is called each time you call publishProgress()

// 执行在主线程

protected void onProgressUpdate(Integer... progress){

setProgressPercent(progress[0]);

}

// This is called when doInBackground() is finished

// 执行在主线程

protected void onPostExecute(Long result){

showNotification("Downloaded " + result + " bytes");

}

}

new DownloadFilesTask().execute(url1, url2, url3);

HandlerThread

Android中结合Handler和Thread的一种方式。默认情况下Handler是为了解决主线程和工作线程通信设计的。handleMessage是执行在主线程的, 但是如果我给这个Handler传入了子线程的looper, handleMessage就会执行在这个子线程中的。HandlerThread正是这样的一个结合体。

1

2

3

4

5

6

7

8

9

10

11

12

13

14

15

16

17

18

19HandlerThread thread = new HandlerThread("new_thread");

thread.start();

// 取new_thread赋值给ServiceHandler

private ServiceHandler mServiceHandler;

mServiceLooper = thread.getLooper();

mServiceHandler = new ServiceHandler(mServiceLooper);

private final class ServiceHandler extends Handler{

public ServiceHandler(Looper looper){

super(looper);

}

@Override

public void handleMessage(Message msg){

// 此时handleMessage是运行在new_thread这个子线程中了.

}

}

IntentService

Service是运行在主线程的, 然而IntentService是运行在子线程的。实际上IntentService就是实现了一个HandlerThread + ServiceHandler的模式。

1

2

3

4

5

6

7

8

9

10

11

12

13

14

15

16

17

18

19

20

21

22

23

24

25

26

27

28

29

30

31

32

33

34

35

36

37

38

39

40

41

42

43

44

45

46

47

48

49

50

51

52

53

54

55

56

57

58

59

60

61

62

63

64

65

66public abstract class IntentService extends Service{

private volatile Looper mServiceLooper;

@UnsupportedAppUsage

private volatile ServiceHandler mServiceHandler;

private String mName;

private boolean mRedelivery;

private final class ServiceHandler extends Handler{

public ServiceHandler(Looper looper){

super(looper);

}

@Override

public void handleMessage(Message msg){

onHandleIntent((Intent)msg.obj);

stopSelf(msg.arg1);

}

}

public IntentService(String name){

super();

mName = name;

}

public void setIntentRedelivery(boolean enabled){

mRedelivery = enabled;

}

@Override

public void onCreate(){

super.onCreate();

HandlerThread thread = new HandlerThread("IntentService[" + mName + "]");

thread.start();

mServiceLooper = thread.getLooper();

mServiceHandler = new ServiceHandler(mServiceLooper);

}

@Override

public void onStart(@Nullable Intent intent, int startId){

Message msg = mServiceHandler.obtainMessage();

msg.arg1 = startId;

msg.obj = intent;

mServiceHandler.sendMessage(msg);

}

@Override

public int onStartCommand(@Nullable Intent intent, int flags, int startId){

onStart(intent, startId);

return mRedelivery ? START_REDELIVER_INTENT : START_NOT_STICKY;

}

@Override

public void onDestroy(){

mServiceLooper.quit();

}

@Override

@Nullable

public IBinder onBind(Intent intent){

return null;

}

@WorkerThread

protected abstract void onHandleIntent(@Nullable Intent intent);

}

Loader

Android 3.0引入的数据加载器, 可以在Activity/Fragment中使用。支持异步加载数据, 并可监控数据源在数据发生变化时传递新结果.。常用的有CursorLoader, 用来加载数据库数据。

1

2

3

4

5

6

7

8

9

10

11

12

13

14

15

16

17

18

19

20

21

22

23

24

25

26

27

28

29

30

31

32

33// Prepare the loader. Either re-connect with an existing one,

// or start a new one.

getLoaderManager().initLoader(0, null, this);

public Loader onCreateLoader(int id, Bundle args){

// This is called when a new Loader needs to be created. This

// sample only has one Loader, so we don't care about the ID.

// First, pick the base URI to use depending on whether we are

// currently filtering.

Uri baseUri;

if (mCurFilter != null) {

baseUri = Uri.withAppendedPath(Contacts.CONTENT_FILTER_URI,

Uri.encode(mCurFilter));

} else {

baseUri = Contacts.CONTENT_URI;

}

// Now create and return a CursorLoader that will take care of

// creating a Cursor for the data being displayed.

String select = "((" + Contacts.DISPLAY_NAME + " NOTNULL) AND ("

+ Contacts.HAS_PHONE_NUMBER + "=1) AND ("

+ Contacts.DISPLAY_NAME + " != '' ))";

return new CursorLoader(getActivity(), baseUri,

CONTACTS_SUMMARY_PROJECTION, select, null,

Contacts.DISPLAY_NAME + " COLLATE LOCALIZED ASC");

}

public void onLoadFinished(Loader loader, Cursor data){

// Swap the new cursor in. (The framework will take care of closing the

// old cursor once we return.)

mAdapter.swapCursor(data);

}

注：使用Thread和HandlerThread时, 为了使效果更好, 建议设置Thread的优先级偏低一点:

1Process.setThreadPriority(THREAD_PRIORITY_BACKGROUND);

因为如果没有做任何优先级设置的话, 你创建的Thread默认和UI Thread是具有同样的优先级的,同样的优先级的Thread, CPU调度上还是可能会阻塞掉你的UI Thread, 导致ANR的。

ANR 检测

StrictMode

严格模式StrictMode是Android SDK提供的一个用来检测代码中是否存在违规操作的工具类，StrictMode主要检测两大类问题。

线程策略ThreadPolicydetectCustomSlowCalls: 检测自定义耗时操作。

detectDiskReads: 检测是否存在磁盘读取操作。

detectDiskWrites: 检测是否存在磁盘写入操作。

detectNetWork: 检测是否存在网络操作。

虚拟机策略VmPolicydetectActivityLeaks: 检测是否存在Activity泄漏。

detectLeakedClosableObjects: 检测是否存在未关闭的Closable对象泄漏。

detectLeakedSqlLiteObjects: 检测是否存在Sqlite对象泄漏。

setClassInstanceLimit: 检测类实例个数是否超过限制。

可以看到，其中ThreadPolicy可以用来检测可能存在的主线程耗时操作，解决这些检测到问题能搞减少应用发生ANR的概率。

注意：只能在Debug模式下使用它。

在应用初始化的地方，例如Application或者MainActivity类的onCreate方法中执行如下代码即可：

1

2

3

4

5

6

7

8

9

10@Override

protected void onCreate(Bundle savedInstanceState){

if (BuildConfig.DEBUG) {

//开启线程模式所有检测策略

StrictMode.setThreadPolicy(new StrictMode.ThreadPolicy.Builder().detectAll().penaltyLog().build());

//开启虚拟机模式所有检测策略

StrictMode.setVmPolicy(new VmPolicy.Builder().detectAll().penaltyLog().build());

}

super.onCreate(savedInstanceState);

}

上面的初始化代码调用penaltyLog表示在Logcat中打印日志。

BlockCanary

BlockCanary是一个非入侵式的性能监控函数库，它的用法和LeakCanary类似，只不过后者监控应用内存泄漏，而前者用来监控应用主线程卡顿。

它的基本原理是利用主线程的消息队列处理机制，通过对比消息分发开始和结束时间点来判断是否超过设定时间。

在build.gradle中添加依赖

1

2

3

4

5

6

7dependencies {

compile 'com.github.moduth:blockcanary-android:1.2.1'

//仅在debug包启用BlockCanary进行卡顿监控和提示

debugCompile 'com.github.moduth:blockcanary-android:1.2.1'

releaseCompile 'com.github.moduth:blockcanary-no-op:1.2.1'

}

1

2

3

4

5

6

7

8

9

10

11public class DemoApplication extends Application{

@Override

public void onCreate(){

//在主进程初始化调用

BlockCanary.install(this, new AppBlockCanaryContext()).start();

}

}

public class AppBlockCanaryContext extends BlockCanaryContext{

//实现各种上下文，包括应用标识符，用户uid，网络类型，卡慢判断阈值，Log保存位置等

}