Android----分析ANR

发表于 | 更新于: | 阅读次数:

一.前言

ANR 是 Android 开发中会遇到的一个经典问题，但是如果不是自己遇到 ANR 并实现解决是很难对 ANR 有深入的体会的，所以本文就产生 ANR 到如何定位做一个详细的记录。

二.产生 ANR

ANR 产生的原因无非就三种，网上也有很多介绍，这里就简单提及：

  • Input dispatching timed out ： Activity 输入分发（即触摸响应超时） 5s
  • Broadcast Timeout：广播 onReceiver 方法执行超时 10 s
  • Service Timeout: 服务的 主线程方法执行超时 20s

简单的总结就是在主线程做超时的任务，下面就模拟一个在主线程休眠引发 ANR 的场景

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
public class MainActivity extends AppCompatActivity {
    @Override
    protected void onCreate(Bundle savedInstanceState) {
        super.onCreate(savedInstanceState);
        setContentView(R.layout.activity_main);
        findViewById(R.id.btn_anr).setOnClickListener(new View.OnClickListener() {
            @Override
            public void onClick(View v) {
                try {
                    Thread.sleep(20_000);
                } catch (InterruptedException e) {
                    e.printStackTrace();
                }
            }
        });
    }
}

当重复点击 Button 的时候就会产生 ANR . 分析 ANR 的途径主要是两个

  • log 日志
  • traces.txt 文件
1.log 日志 分析

查看 ANR log 日志的时候，log 过滤规则不能设置为仅限本应用，可以直接设置为 NO Filters

ANR 的时候会产生如下的红色日志

1
2
3
4
5
6
7
8
9
10
11
12

// log 需要设置过滤规则为 No Filters
03-14 19:52:05.513 1448-1527/? E/ActivityManager:
//ANR 的主线程的组件
ANR in piratehat.appstore (piratehat.appstore/piratehat.httpClient.MainActivity)
//进程的 ID 
PID: 30106
//ANR 的种类和原因，这里是 Input dispatching timed out
 Reason: Input dispatching timed out (piratehat.appstore/piratehat.httpClient.HttpTestActivity, Waiting to send non-key event because the touched window has not finished processing certain input events that were delivered to it over 500.0ms ago.  Wait queue length: 2.  Wait queue head age: 11632.7ms.)
 Load: 2.95 / 2.29 / 2.54
 CPU usage from 51546ms to 0ms ago:
 ...// 省略内核中的一些信息

从 log 日志中就可以看出关于 ANR 的几个信息：

  • 发生 ANR 的主线程的组件
  • 进程的 ID
  • ANR 的种类和原因

有这么几个信息还不足以定位到 ANR 的地方和具体的原因，因此还需要另一种途径，分析 traces.txt 文件

2.traces.txt 文件 分析

发生 ANR 除了有上面的 log 之外，还有下面针对 本应用的 log(可以设置 Show only selected application 查看)

1
//03-14 19:52:01.934 30106-30111/piratehat.appstore I/art: Wrote stack traces to '/data/anr/traces.txt'

每一次产生 ANR 的时候，Android 虚拟机就会 dump 出当前进程所有线程信息并存储到 traces.txt 这个文件。

那么怎么获取到这个文件呢？

网上有很多方式 dump 当前进程的 traces.txt，但是都行不通，最后自己 dump 出所有再去找到自己应用的。
image.png
只要在 Terminal 命令输入窗口输入 adb pull data/anr 即可导出所有的 anr traces.txt 文件夹到 对应的目录下（这里是 AppStore 目录）
然后找到属于自己应用的 traces.txt 文件

这个文件中可能会包含有其他进程的一些信息. 首先知道几个标识

  • PID :进程 ID
  • TID :线程 ID , 1 为 主线程
  • UID :用户 ID , 0 为 root 权限
    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
    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
    126
    127
    128
    129
    130
    131
    132
    133
    134
    135
    136
    137
    138
    139
    140
    141
    142
    143
    144
    145
    146
    147
    148
    149
    150
    151
    152
    153
    154
    155
    156
    157
    158
    159
    160
    161
    162
    163
    164
    165
    166
    167
    168
    169
    170
    171
    172
    173
    174
    175
    176
    177
    178
    179
    180
    181
    182
    183
    184
    185
    186
    187
    188
    189
    190
    191
    192
    193
    194
    195
    196
    197
    198
    199
    200
    201
    202
    203
    204
    205
    206
    207
    208
    209
    210
    211
    212
    213
    214

    ----- pid 30106 at 2019-03-14 19:52:01 -----
    Cmd line: piratehat.appstore
    Build fingerprint: 'Xiaomi/land/land:6.0.1/MMB29M/V9.5.4.0.MALCNFA:user/release-keys'
    ABI: 'arm64'
    Build type: optimized
    Zygote loaded classes=4192 post zygote classes=427
    Intern table: 55033 strong; 16 weak
    JNI: CheckJNI is on; globals=419 (plus 218 weak)
    Libraries: /data/app/piratehat.appstore-2/lib/arm64/libsupportjni.so /system/lib64/libandroid.so /system/lib64/libcompiler_rt.so /system/lib64/libjavacrypto.so /system/lib64/libjnigraphics.so /system/lib64/libmedia_jni.so /system/lib64/libmiuiclassproxy.so /system/lib64/libmiuinative.so /system/lib64/libqti_performance.so /system/lib64/libwebviewchromium_loader.so libjavacore.so (11)

    suspend all histogram:	Sum: 147us 99% C.I. 1us-8us Avg: 3.195us Max: 8us
    DALVIK THREADS (21):
    "Signal Catcher" daemon prio=5 tid=2 Runnable
      | group="system" sCount=0 dsCount=0 obj=0x12cae0a0 self=0x55a1e9ded0
      | sysTid=30111 nice=0 cgrp=default sched=0/0 handle=0x7fa6e82450
      | state=R schedstat=( 22837912 5312140 66 ) utm=2 stm=0 core=4 HZ=100
      | stack=0x7fa6d86000-0x7fa6d88000 stackSize=1013KB
      | held mutexes= "mutator lock"(shared held)
      ....//这里省略一些 信息，下面也是一样
      (no managed stack frames)

    "main" prio=5 tid=1 Sleeping
      | group="main" sCount=1 dsCount=0 obj=0x7542afb8 self=0x55a1dbb930
      | sysTid=30106 nice=0 cgrp=default sched=1073741825/1 handle=0x7fab053fc8
      | state=S schedstat=( 920246246 7424173 385 ) utm=73 stm=19 core=5 HZ=100
      | stack=0x7fc946a000-0x7fc946c000 stackSize=8MB
      | held mutexes=
     

    "JDWP" daemon prio=5 tid=3 WaitingInMainDebuggerLoop
      | group="system" sCount=1 dsCount=0 obj=0x12cb90a0 self=0x55a2088380
      | sysTid=30112 nice=0 cgrp=default sched=0/0 handle=0x7fa6d7c450
      | state=S schedstat=( 2740050 224427 9 ) utm=0 stm=0 core=3 HZ=100
      | stack=0x7fa6c80000-0x7fa6c82000 stackSize=1013KB
      | held mutexes=
     
      
      (no managed stack frames)

    "ReferenceQueueDaemon" daemon prio=5 tid=4 Waiting
      | group="system" sCount=1 dsCount=0 obj=0x12ca94c0 self=0x55a207b6b0
      | sysTid=30113 nice=0 cgrp=default sched=0/0 handle=0x7fa6c74450
      | state=S schedstat=( 730157 66354 11 ) utm=0 stm=0 core=1 HZ=100
      | stack=0x7fa6b72000-0x7fa6b74000 stackSize=1037KB
      | held mutexes=
     

    "FinalizerDaemon" daemon prio=5 tid=5 Waiting
      | group="system" sCount=1 dsCount=0 obj=0x12ca9520 self=0x55a2236170
      | sysTid=30114 nice=0 cgrp=default sched=0/0 handle=0x7fa6b68450
      | state=S schedstat=( 1202655 63333 14 ) utm=0 stm=0 core=2 HZ=100
      | stack=0x7fa6a66000-0x7fa6a68000 stackSize=1037KB
      | held mutexes=
      

    "FinalizerWatchdogDaemon" daemon prio=5 tid=6 Waiting
      | group="system" sCount=1 dsCount=0 obj=0x12ca9580 self=0x55a22369c0
      | sysTid=30115 nice=0 cgrp=default sched=0/0 handle=0x7fa6a5c450
      | state=S schedstat=( 964737 0 6 ) utm=0 stm=0 core=4 HZ=100
      | stack=0x7fa695a000-0x7fa695c000 stackSize=1037KB
      | held mutexes=
      
    "HeapTaskDaemon" daemon prio=5 tid=7 Blocked
      | group="system" sCount=1 dsCount=0 obj=0x12ca95e0 self=0x55a2237210
      | sysTid=30116 nice=0 cgrp=default sched=0/0 handle=0x7fa6950450
      | state=S schedstat=( 943231 0 7 ) utm=0 stm=0 core=6 HZ=100
      | stack=0x7fa684e000-0x7fa6850000 stackSize=1037KB
      | held mutexes=
     

    "Binder:30106_1" prio=5 tid=8 Native
      | group="main" sCount=1 dsCount=0 obj=0x12cbf0a0 self=0x55a2238a10
      | sysTid=30117 nice=0 cgrp=default sched=0/0 handle=0x7fa6748450
      | state=S schedstat=( 7228229 6658334 40 ) utm=0 stm=0 core=7 HZ=100
      | stack=0x7fa664c000-0x7fa664e000 stackSize=1013KB
      | held mutexes=
     
      (no managed stack frames)

    "Binder:30106_2" prio=5 tid=9 Native
      | group="main" sCount=1 dsCount=0 obj=0x12cc30a0 self=0x55a2239260
      | sysTid=30118 nice=0 cgrp=default sched=0/0 handle=0x7fa6642450
      | state=S schedstat=( 6283645 7792968 39 ) utm=0 stm=0 core=7 HZ=100
      | stack=0x7fa6546000-0x7fa6548000 stackSize=1013KB
      | held mutexes=
     

    "FileObserver" prio=5 tid=10 Native
      | group="main" sCount=1 dsCount=0 obj=0x12ce3340 self=0x55a1f00ba0
      | sysTid=30119 nice=0 cgrp=default sched=0/0 handle=0x7fa21fd450
      | state=S schedstat=( 494896 0 2 ) utm=0 stm=0 core=3 HZ=100
      | stack=0x7fa20fb000-0x7fa20fd000 stackSize=1037KB
      | held mutexes=
     

    "Binder:30106_3" prio=5 tid=11 Native
      | group="main" sCount=1 dsCount=0 obj=0x12d450a0 self=0x55a2249010
      | sysTid=30124 nice=0 cgrp=default sched=0/0 handle=0x7fa20f8450
      | state=S schedstat=( 4480311 4345883 32 ) utm=0 stm=0 core=6 HZ=100
      | stack=0x7fa1ffc000-0x7fa1ffe000 stackSize=1013KB
      | held mutexes=
      
      (no managed stack frames)

    "Binder:30106_4" prio=5 tid=12 Native
      | group="main" sCount=1 dsCount=0 obj=0x12d4c0a0 self=0x55a224a6f0
      | sysTid=30127 nice=0 cgrp=default sched=0/0 handle=0x7fa1ff9450
      | state=S schedstat=( 4391355 18013748 31 ) utm=0 stm=0 core=6 HZ=100
      | stack=0x7fa1efd000-0x7fa1eff000 stackSize=1013KB
      | held mutexes=
     )
      native: #10 pc 000000000001c644  /system/lib64/libc.so (__start_thread+16)
      (no managed stack frames)

    "Binder:30106_5" prio=5 tid=13 Native
      | group="main" sCount=1 dsCount=0 obj=0x12d500a0 self=0x55a224ba60
      | sysTid=30130 nice=0 cgrp=default sched=0/0 handle=0x7f9423e450
      | state=S schedstat=( 3941615 3599219 32 ) utm=0 stm=0 core=7 HZ=100
      | stack=0x7f94142000-0x7f94144000 stackSize=1013KB
      | held mutexes=

      (no managed stack frames)

    "Binder:30106_6" prio=5 tid=14 Native
      | group="main" sCount=1 dsCount=0 obj=0x12cae100 self=0x55a1f013f0
      | sysTid=30151 nice=0 cgrp=default sched=0/0 handle=0x7f93cc3450
      | state=S schedstat=( 3181774 4945416 16 ) utm=0 stm=0 core=5 HZ=100
      | stack=0x7f93bc7000-0x7f93bc9000 stackSize=1013KB
      | held mutexes=
     
      (no managed stack frames)

    "Thread-47826" prio=5 tid=16 Sleeping
      | group="main" sCount=1 dsCount=0 obj=0x12ca91c0 self=0x55a2259ac0
      | sysTid=30156 nice=0 cgrp=default sched=0/0 handle=0x7f938b1450
      | state=S schedstat=( 2956969195 115115680 18859 ) utm=207 stm=88 core=5 HZ=100
      | stack=0x7f937af000-0x7f937b1000 stackSize=1037KB
      | held mutexes=
     
    "Studio:VmStats" prio=5 tid=17 TimedWaiting
      | group="main" sCount=1 dsCount=0 obj=0x12ca9220 self=0x55a2263f80
      | sysTid=30157 nice=0 cgrp=default sched=0/0 handle=0x7f937a5450
      | state=S schedstat=( 2314347878 48209793 7588 ) utm=203 stm=28 core=4 HZ=100
      | stack=0x7f936a3000-0x7f936a5000 stackSize=1037KB
      | held mutexes=
      
      

    "RenderThread" prio=5 tid=19 Native
      | group="main" sCount=1 dsCount=0 obj=0x12f6a0a0 self=0x55a1eb9dd0
      | sysTid=30161 nice=-4 cgrp=default sched=1073741825/1 handle=0x7f9354f450
      | state=S schedstat=( 301889746 26133758 324 ) utm=16 stm=14 core=6 HZ=100
      | stack=0x7f93453000-0x7f93455000 stackSize=1013KB
      
      (no managed stack frames)

    "hwuiTask1" prio=5 tid=20 Native
      | group="main" sCount=1 dsCount=0 obj=0x12f830a0 self=0x55a24701a0
      | sysTid=30162 nice=-2 cgrp=default sched=0/0 handle=0x7f933a9450
      | state=S schedstat=( 10214478 14752295 67 ) utm=1 stm=0 core=7 HZ=100
      | stack=0x7f932ad000-0x7f932af000 stackSize=1013KB
      | held mutexes=


    "hwuiTask2" prio=5 tid=21 Native
      | group="main" sCount=1 dsCount=0 obj=0x12f870a0 self=0x55a246d420
      | sysTid=30163 nice=-2 cgrp=default sched=0/0 handle=0x7f932a5450
      | state=S schedstat=( 834375 116302 6 ) utm=0 stm=0 core=2 HZ=100
      | stack=0x7f931a9000-0x7f931ab000 stackSize=1013KB
      | held mutexes=

     
      (no managed stack frames)

    "Studio:Agent" prio=5 (not attached)
      | sysTid=30148 nice=0 cgrp=default
      | state=S schedstat=( 7029339016 4208610113 69915 ) utm=214 stm=488 core=7 HZ=100
     

    "Studio:Heartbea" prio=5 (not attached)
      | sysTid=30153 nice=0 cgrp=default
      | state=S schedstat=( 6660169473 4244203001 68400 ) utm=238 stm=428 core=6 HZ=100
     

    ----- end 30106 -----

    ----- pid 2256 at 2019-03-14 19:52:02 -----
    Cmd line: com.fingerprints.serviceext

    ----- end 2256 -----

    ----- pid 2378 at 2019-03-14 19:52:01 -----
    Cmd line: com.android.phone

    ----- end 2378 -----


    ----- pid 443 at 2019-03-14 19:52:02 -----
    Cmd line: /system/bin/surfaceflinger
    ABI: 'arm64'

    "surfaceflinger" sysTid=443
      #00 pc 0000000000069c54  /system/lib64/libc.so (__epoll_pwait+8)
      #01 pc 000000000001cca4  /system/lib64/libc.so (epoll_pwait+32)
      #02 pc 000000000001be88  /system/lib64/libutils.so (_ZN7android6Looper9pollInnerEi+144)
      #03 pc 000000000001c268  /system/lib64/libutils.so (_ZN7android6Looper8pollOnceEiPiS1_PPv+80)
      #04 pc 000000000002d6d4  /system/lib64/libsurfaceflinger.so
      #05 pc 0000000000030c48  /system/lib64/libsurfaceflinger.so (_ZN7android14SurfaceFlinger3runEv+20)
      #06 pc 0000000000001190  /system/bin/surfaceflinger
      #07 pc 000000000001976c  /system/lib64/libc.so (__libc_init+100)
      #08 pc 0000000000000fcc  /system/bin/surfaceflinger

    "Binder:443_1" sysTid=507

从上面的信息可以看到一个 traces.txt 包含了多个进程的信息。
每个进程的信息又包含了其有的线程的信息，比如上面最后一个就是 surfaceflinger 进程的信息。

那么如何找到自己的应用的进程呢？
因为每个进程都有自己的进程 ID ,(即 PID )，而在第一种 log 日志分析中已经知道我们的进程 ID 为 30106 ，因此全局搜索 30106 可以找到属于我们进程的 信息。

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
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
----- pid 30106 at 2019-03-14 19:52:01 -----
Cmd line: piratehat.appstore
Build fingerprint: 'Xiaomi/land/land:6.0.1/MMB29M/V9.5.4.0.MALCNFA:user/release-keys'
ABI: 'arm64'
Build type: optimized
Zygote loaded classes=4192 post zygote classes=427
Intern table: 55033 strong; 16 weak
JNI: CheckJNI is on; globals=419 (plus 218 weak)
Libraries: /data/app/piratehat.appstore-2/lib/arm64/libsupportjni.so /system/lib64/libandroid.so /system/lib64/libcompiler_rt.so /system/lib64/libjavacrypto.so /system/lib64/libjnigraphics.so /system/lib64/libmedia_jni.so /system/lib64/libmiuiclassproxy.so /system/lib64/libmiuinative.so /system/lib64/libqti_performance.so /system/lib64/libwebviewchromium_loader.so libjavacore.so (11)

suspend all histogram:	Sum: 147us 99% C.I. 1us-8us Avg: 3.195us Max: 8us
DALVIK THREADS (21):
"Signal Catcher" daemon prio=5 tid=2 Runnable
  | group="system" sCount=0 dsCount=0 obj=0x12cae0a0 self=0x55a1e9ded0
  | sysTid=30111 nice=0 cgrp=default sched=0/0 handle=0x7fa6e82450
  | state=R schedstat=( 22837912 5312140 66 ) utm=2 stm=0 core=4 HZ=100
  | stack=0x7fa6d86000-0x7fa6d88000 stackSize=1013KB
  | held mutexes= "mutator lock"(shared held)
  ....//这里省略一些 信息，下面也是一样
  (no managed stack frames)

// “main” ：线程名字
// prio ： 线程优先级
// tid ：线程
"main" prio=5 tid=1 Sleeping
  | group="main" sCount=1 dsCount=0 obj=0x7542afb8 self=0x55a1dbb930
  | sysTid=30106 nice=0 cgrp=default sched=1073741825/1 handle=0x7fab053fc8
  | state=S schedstat=( 920246246 7424173 385 ) utm=73 stm=19 core=5 HZ=100
  | stack=0x7fc946a000-0x7fc946c000 stackSize=8MB
  | held mutexes=
 
//这是一个守护线程
"JDWP" daemon prio=5 tid=3 WaitingInMainDebuggerLoop
  ...
  (no managed stack frames)
//这是一个守护线程
"ReferenceQueueDaemon" daemon prio=5 tid=4 Waiting
  ... 
 
//这是一个守护线程
"FinalizerDaemon" daemon prio=5 tid=5 Waiting
  ...
  
//这是一个守护线程
"FinalizerWatchdogDaemon" daemon prio=5 tid=6 Waiting
 ...
  //这是一个守护线程
"HeapTaskDaemon" daemon prio=5 tid=7 Blocked
 ...
 
//这是一个 Binder 线程
"Binder:30106_1" prio=5 tid=8 Native
  ...
 
  (no managed stack frames)
//这是一个 Binder 线程
"Binder:30106_2" prio=5 tid=9 Native
  ...
 

"FileObserver" prio=5 tid=10 Native
  ...
//这是一个 Binder 线程
"Binder:30106_3" prio=5 tid=11 Native
  ...
  (no managed stack frames)
//这是一个 Binder 线程
"Binder:30106_4" prio=5 tid=12 Native
  ...
//这是一个 Binder 线程
"Binder:30106_5" prio=5 tid=13 Native
  ...

  (no managed stack frames)
//这是一个 Binder 线程
"Binder:30106_6" prio=5 tid=14 Native
  ...

"Thread-47826" prio=5 tid=16 Sleeping
   ...
 
"Studio:VmStats" prio=5 tid=17 TimedWaiting
  ...
  

"RenderThread" prio=5 tid=19 Native
  ...

"hwuiTask1" prio=5 tid=20 Native
  ...


"hwuiTask2" prio=5 tid=21 Native
  ...

 
  (no managed stack frames)

"Studio:Agent" prio=5 (not attached)
  ...

"Studio:Heartbea" prio=5 (not attached)
  ...
 

----- end 30106 -----

因为发生 ANR 的情况是在主线程中，所以 tid = 1 ,看主线程中的信息的

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
"main" prio=5 tid=1 Sleeping
  | group="main" sCount=1 dsCount=0 obj=0x7542afb8 self=0x55a1dbb930
  | sysTid=30106 nice=0 cgrp=default sched=1073741825/1 handle=0x7fab053fc8
  | state=S schedstat=( 920246246 7424173 385 ) utm=73 stm=19 core=5 HZ=100
  | stack=0x7fc946a000-0x7fc946c000 stackSize=8MB
  | held mutexes=
    at java.lang.Thread.sleep!(Native method)
  - sleeping on <0x0735c84c> (a java.lang.Object)
  at java.lang.Thread.sleep(Thread.java:1031)
  - locked <0x0735c84c> (a java.lang.Object)
  at java.lang.Thread.sleep(Thread.java:985)
  at piratehat.httpClient.HttpTestActivity$1.onClick(HttpTestActivity.java:27)
  at android.view.View.performClick(View.java:5215)
  at android.view.View$PerformClick.run(View.java:21193)
  at android.os.Handler.handleCallback(Handler.java:742)
  at android.os.Handler.dispatchMessage(Handler.java:95)
  at android.os.Looper.loop(Looper.java:157)
  at android.app.ActivityThread.main(ActivityThread.java:5571)
  at java.lang.reflect.Method.invoke!(Native method)
  at com.android.internal.os.ZygoteInit$MethodAndArgsCaller.run(ZygoteInit.java:745)
  at com.android.internal.os.ZygoteInit.main(ZygoteInit.java:635)

就可以看到主线程中 ANR 的原因是因为 调用了 Sleep 方法，具体在 onClick 方法中，至此就找到了 ANR 的位置。

0%