天天看点

ANR超时种类及产生原因ANR产生原因及分类死锁

ANR产生原因及分类

ANR的产生需要同时满足三个条件

1.主线程:只有应用程序进程的主线程响应超时才会产生ANR; 

2.超时时间:产生ANR的上下文不同,超时时间也不同,但只要超过这个时间上限没有响应就会产生ANR;

3.输入事件/特定操作:输入事件是指按键、触屏等设备输入事件,特定操作是指BroadcastReceiver和Service的生命周期中的各个函数调用。

产生ANR的上下文不同,导致ANR原因也不同,主要有以下三种情况:

· 应用进程的主线程对输入事件在5s内没有处理完毕; 

· 应用进程的主线程在执行BroadcastRecevier的onReceive函数时10s/60s内没有处理完毕; 

在ActivityManagerService.java中前台广播(10秒)和后台广播(60秒)超时时间

// How long we allow a receiver to run before giving up on it.
    static final int BROADCAST_FG_TIMEOUT = 10*1000;
    static final int BROADCAST_BG_TIMEOUT = 60*1000;
           

· 应用进程的主线程在执行Service的各个生命周期函数时20s/200s内没有处理完毕;

在ActiveServices.java后台服务超时(200秒) 和前台服务超时(20秒)的超时时间

// How long we wait for a service to finish executing.
    static final int SERVICE_TIMEOUT = 20*1000;

    // How long we wait for a service to finish executing.
    static final int SERVICE_BACKGROUND_TIMEOUT = SERVICE_TIMEOUT * 10;
           

AMS在发生ANR时,会按以下格式将ANR信息记录到logcat日志中:

ActivityManager: ANR in [Process Name]([short component name])

ActivityManager: PID: [Application Pid]

ActivityManager: Reason: [Annotation]

ActivityManager: Parent: [short component name of parent]

[Process CPU state] 

其中的Reason信息可以给出ANR产生原因的一些详细信息,

·输入事件处理引起的ANR,提示信息格式为:“Inputdispatching timed out [anr reason]”

·Service处理引起的ANR,提示信息格式为:“Executingservice [Package name]/[Short class name]”

·Broadcast处理引起的ANR,提示信息格式为:“Broadcast of [Intent focused byBroadcast receiver]”

其中的Process CPU state 信息格式如下:

ActivityManager: Load: [Load1] / [Load5] / [Load15]

ActivityManager: CPU usage from [上次采样与现在的时间差] ms to [当前采样与现在的时间差] ms ago/later:

ActivityManager: [总的CPU时间占用率]% [PID]/[Process Name]: [用户CPU时间占用率]% user + [系统CPU时间占用率]% kernel + [IO等待CPU时间占用率]% iowait + [硬中断CPU时间占用率]% irq + [软中断CPU时间占用率]% softirq / faults: [次要页错误/主要页错误] minor/major

ActivityManager: .....

ActivityManager: [CPU时间占用率合计统计]

其中Load1, Load5, Load15分别为CPU 1分钟平均任务负载数,5分钟平均任务负载数,15分钟平均任务负载数,平均任务负载数和CPU占用率并没有必然联系,可以作为参考信息。可以通过分析各进程的CPU时间占用率,来判断是否为某些进程长期占用CPU导致该进程无法获取到足够的CPU处理时间,而导致发生ANR。

这里需要重点关注的是Load1,各进程总的CPU时间占用率,用户CPU时间占用率,系统CPU时间占用率,以及iowait CPU时间占用率。

ActivityManagerService的appNotResponding方法在写入logcat日志的同时,还会将ANR时的stack trace信息写入到trace文件。

日志中关于CPU和内存的关键指标含义

CPU的使用时间:读取 /proc/stat

  • user: 用户进程的CPU使用时间
  • nice: 降低过优先级进程的CPU使用时间。Linux进程都有优先级,这个优先级可以进行动态调整,譬如进程初始优先级的值设为10,运行时降低为8,那么,修正值-2就定义为nice。

Android将user和nice这两个时间归类成user

  • sys: 内核进程的CPU使用时间
  • idle: CPU空闲的时间
  • wait: CPU等待IO的时间
  • hw irq: 硬件中断的时间。如果外设(譬如硬盘)出现故障,需要通过硬件终端通知CPU保存现场,发生上下文切换的时间就是CPU的硬件中断时间
  • sw irg: 软件中断的时间。同硬件中断一样,如果软件要求CPU中断,则上下文切换的时间就是CPU的软件中断时间

CPU负载:读取/proc/loadavg

统计最近1分钟,5分钟,15分钟内,CPU的平均活动进程数。 CPU的负载可以比喻成超市收银员负载,如果有1个人正在买单,有2个人在排队,那么该收银员的负载就是3。 在收银员工作时,

不断会有人买单完成,也不断会有人排队,可以在固定的时间间隔内(譬如,每隔5秒)统计一次负载,那么,就可以统计出一段时间内的平均负载。

手机内存:读取/proc/meninfo

内存指标概念

常用的内存调优分析命令:

dumpsys meminfo

procrank

cat /proc/meminfo

free

showmap

vmstat

Item 全称 含义 等价
USS Unique Set Size  进程独自占用的物理内存(不包含共享库占用的内存) 物理内存 进程独占的内存
PSS Proportional Set Size 虚拟耗用内存(包含共享库占用的内存) 物理内存 PSS= USS+ 按比例包含共享库
RSS Resident Set Size 实际使用物理内存(包含共享库占用的内存) 物理内存 RSS= USS+ 包含共享库
VSS Virtual Set Size  虚拟耗用内存(包含共享库占用的内存) 虚拟内存 VSS= RSS+ 未分配实际物理内存

故内存的大小关系:VSS >= RSS >= PSS >= USS

VSS - Virtual Set Size 虚拟耗用内存(包含共享库占用的内存)是单个进程全部可访问的地址空间

RSS - Resident Set Size 实际使用物理内存(包含共享库占用的内存)是单个进程实际占用的内存大小,对于单个共享库, 尽管无论多少个进程使用,实际该共享库只会被装入内存一次。

PSS - Proportional Set Size 实际使用的物理内存(比例分配共享库占用的内存)

USS - Unique Set Size 进程独自占用的物理内存(不包含共享库占用的内存)USS 是一个非常非常有用的数字, 因为它揭示了运行一个特定进程的真实的内存增量大小。如果进程被终止, USS 就是实际被返还给系统的内存大小。

USS 是针对某个进程开始有可疑内存泄露的情况,进行检测的最佳数字。怀疑某个程序有内存泄露可以查看这个值是否一直有增加

   dumpsys meminfo命令的输出结果分以下4部分:

序列 划分类型 排序 解释
1 process PSS 以进程的PSS从大到小依次排序显示,每行显示一个进程;
2 OOM adj PSS Native/System/Persistent/Foreground/Visible/Perceptible/A Services/Home/B Services/Cached,分别显示每类的进程情况;一般而言,占用内存越多,oom_adj就越大,也就越有可能被选中。OOM异常的时候会根据这个表单从下往上杀掉进程释放内存
3 category PSS 以Dalvik/Native/.art mmap/.dex map等划分的各类进程的总PSS情况
4 total 总内存、剩余内存、可用内存、其他内存

类型一:等待binder调用返回

SYS_BINDER_INFO这个文件查找当前这个线程在和谁通信

----- pid 11406 at 2017-11-09 11:08:26 -----
Cmd line: system_server
suspend all histogram:	Sum: 34.211s 99% C.I. 0.112ms-145.252ms Avg: 3.613ms Max: 721.119ms
DALVIK THREADS (116):
"Signal Catcher" daemon prio=5 tid=2 Runnable

group="system" sCount=0 dsCount=0 obj=0x12c010d0 self=0xa2a8b000
sysTid=11411 nice=0 cgrp=default sched=0/0 handle=0xa6aa6920
state=R schedstat=( 221574139562 21185268985 105795 ) utm=17338 stm=4819 core=0 HZ=100
stack=0xa69aa000-0xa69ac000 stackSize=1014KB
held mutexes= "mutator lock"(shared held)
(no managed stack frames)
"main" prio=5 tid=1 Native

group="main" sCount=1 dsCount=0 obj=0x745a75c8 self=0xa7304400
sysTid=11406 nice=0 cgrp=default sched=0/0 handle=0xaa6ad534
state=S schedstat=( 370737816372 373044335371 779301 ) utm=25895 stm=11178 core=0 HZ=100
stack=0xbe566000-0xbe568000 stackSize=8MB
held mutexes=
at android.media.AudioSystem.setParameters(Native method)
at com.android.server.audio.AudioService$AudioServiceBroadcastReceiver.onReceive(AudioService.java:5596)
at android.app.LoadedApk$ReceiverDispatcher$Args.run(LoadedApk.java:1164)
at android.os.Handler.handleCallback(Handler.java:836)
at android.os.Handler.dispatchMessage(Handler.java:103)
at android.os.Looper.loop(Looper.java:203)
at com.android.server.SystemServer.run(SystemServer.java:421)
at com.android.server.SystemServer.main(SystemServer.java:275)
at java.lang.reflect.Method.invoke!(Native method)
at com.android.internal.os.ZygoteInit$MethodAndArgsCaller.run(ZygoteInit.java:1063)
at com.android.internal.os.ZygoteInit.main(ZygoteInit.java:924)
由上边可以看到是 11406进程 linnux线程 11406 与谁通信 
3.打开SYS_BINDER_INFO文件,搜索 thread 11406 看到如下
proc 11406
thread 11406: l 10
outgoing transaction 197732395: 00000000 from 11406:11406 to 11246:30103 code 13 flags 10 pri 0 r1 node 130786871 size 92:0 data 00000000
代表11406进程的11406linux 线程 与11246进程的 30103 linux线程通信有问题
然后搜索11246进程是谁,搜索如下
----- pid 11246 at 2017-11-09 11:08:28 -----
Cmd line: /system/bin/audioserver
ABI: 'arm'
"audioserver" sysTid=11246
#00 pc 000173f4 /system/lib/libc.so (syscall+28)
#01 pc 00048965 /system/lib/libc.so (ZL33_pthread_mutex_lock_with_timeoutP24pthread_mutex_internal_tbPK8timespec+176)
#02 pc 0000c283 /system/lib/libaudiopolicyservice.so
#03 pc 00093b53 /system/lib/libmedia.so (_ZN7android11AudioSystem14registerEffectEPK19effect_descriptor_sij15audio_session_ti+50)
#04 pc 00031995 /system/lib/libaudioflinger.so
#05 pc 0002e55d /system/lib/libaudioflinger.so
#06 pc 00080b4d /system/lib/libmedia.so (_ZN7android14BnAudioFlinger10onTransactEjRKNS_6ParcelEPS1_j+3268)
#07 pc 000359e3 /system/lib/libbinder.so (_ZN7android7BBinder8transactEjRKNS_6ParcelEPS1_j+70)
#08 pc 0003d19f /system/lib/libbinder.so (_ZN7android14IPCThreadState14executeCommandEi+690)
#09 pc 0003cdf7 /system/lib/libbinder.so (_ZN7android14IPCThreadState20getAndExecuteCommandEv+114)
#10 pc 0003d307 /system/lib/libbinder.so (_ZN7android14IPCThreadState14joinThreadPoolEb+46)
#11 pc 00001873 /system/bin/audioserver
#12 pc 00016c3d /system/lib/libc.so (__libc_init+48)
#13 pc 00001580 /system/bin/audioserver
4.打开SYS_PROCESSES_AND_THREADS文件搜索 audioserver
u:r:audioserver:s0 audioserver 11246 1 65256 2564 1 20 0 0 0 fg futex_wait a90903f8 S 32 /system/bin/audioserver
u:r:audioserver:s0 audioserver 11252 11246 65256 2564 1 4 -16 0 0 fg futex_wait a90903f8 S 32 ApmTone
u:r:audioserver:s0 audioserver 11253 11246 65256 2564 1 4 -16 0 0 fg futex_wait a90903f8 S 32 ApmAudio
u:r:audioserver:s0 audioserver 11254 11246 65256 2564 1 4 -16 0 0 fg futex_wait a90903f8 S 32 ApmOutput
u:r:audioserver:s0 audioserver 11257 11246 65256 2564 2 4 -16 0 0 fg ccci_dev_r a90c389c S 32 CCCIReadThread
u:r:audioserver:s0 audioserver 11261 11246 65256 2564 1 2 -18 0 0 fg futex_wait a90903f8 S 32 AudioOut_D
u:r:audioserver:s0 audioserver 11263 11246 65256 2564 0 -4 -18 3 1 fg futex_wait a90903f8 S 32 FastMixer
u:r:audioserver:s0 audioserver 11264 11246 65256 2564 1 2 -18 0 0 fg futex_wait a90903f8 S 32 AudioOut_15
u:r:audioserver:s0 audioserver 11269 11246 65256 2564 1 4 -16 0 0 fg futex_wait a90903f8 S 32 Binder:11246_1
u:r:audioserver:s0 audioserver 11987 11246 65256 2564 1 20 0 0 0 fg futex_wait a90903f8 S 32 Binder:11246_2
u:r:audioserver:s0 audioserver 16220 11246 65256 2564 1 20 0 0 0 fg futex_wait a90903f8 S 32 Binder:11246_3
u:r:audioserver:s0 audioserver 1646 11246 65256 2564 1 20 0 0 0 fg futex_wait a90903f8 S 32 Binder:11246_4
u:r:audioserver:s0 audioserver 30103 11246 65256 2564 1 20 0 0 0 fg futex_wait a90903f8 S 32 Binder:11246_5
u:r:audioserver:s0 audioserver 30104 11246 65256 2564 2 30 10 0 0 bg futex_wait a90903f8 S 32 Binder:11246_6
u:r:audioserver:s0 audioserver 30327 11246 65256 2564 2 20 0 0 0 fg futex_wait a90903f8 S 32 Binder:11246_7
u:r:audioserver:s0 audioserver 30328 11246 65256 2564 0 20 0 0 0 fg binder_thr a90c284c S 32 Binder:11246_8
u:r:audioserver:s0 audioserver 30966 11246 65256 2564 0 30 10 0 0 bg futex_wait a90903f8 S 32 Binder:11246_9
u:r:audioserver:s0 audioserver 30967 11246 65256 2564 0 20 0 0 0 fg futex_wait a90903f8 S 32 Binder:11246_A
u:r:audioserver:s0 audioserver 514 11246 65256 2564 0 20 0 0 0 fg binder_thr a90c284c S 32 Binder:11246_B
u:r:audioserver:s0 audioserver 515 11246 65256 2564 0 20 0 0 0 fg binder_thr a90c284c S 32 Binder:11246_C
看到u:r:audioserver:s0 audioserver 30103 11246 65256 2564 1 20 0 0 0 fg futex_wait a90903f8 S 32 Binder:11246_5
说明audioserver进程死锁。
           

类型二:主线程等待锁

主线程的CallStack DVM thread Status是Blocked

类型三:IO Wait问题

这种情况一般是和文件操作相关,判断是否是这种情况。IO占比很高,这个时候就需要查看trace日志看当时的callstack,着重看有没有file相关的动作。

[FAQ13684] iowait问题成因及对策

成因:

1. 系统因为io导致进程wait;

2. 数据请求量大;

3. 存储器性能欠佳(TLC的eMMC和SD Card表现明显)

原理:

 Linux 用pdflush进程把数据从缓存页写入硬盘,pdflush写入硬盘看两个参数:

1. 数据在页缓存中是否超出3秒 (default),如果是,标记为脏页缓存;

/proc/sys/vm/dirty_expire_centiseconds

2. 脏页缓存是否达到工作内存的10%(default);

/proc/sys/vm/dirty_background_ratio

以下参数也会影响到pdflush

/proc/sys/vm/dirty_ratio (default 20): global_dirtyable_memory的最大百分比,系统所能拥有的最大脏页缓存的总量。

超过这个值,开启pdflush写入硬盘。如果cache增长快于pdflush,那么整个系统在20%的时候遇到I/O瓶颈,所有的I/O都要等待cache被pdflush进硬盘后才能重新开始。

对于有高度写入操作的系统

dirty_background_ratio: 主要调整参数。如果需要把缓存持续的而不是一下子大量的写入硬盘,降低这个值。

dirty_ratio:第二调整参数。

对策:

如果有大量的写操作,为避免I/O的长时间等待,可以设置:

$ echo 3 > /proc/sys/vm/dirty_background_ratio

$ echo 10 > /proc/sys/vm/dirty_ratio

可以在init.rc中修改,如果user版本(未开mtklog)难以复现,建议不做修改。

因为通过调整内核参数,将写活动的高峰分布成频繁的多次写,每次写入的数据比较少。

以这种方式执行的效率比较低,减少了内核组合写操作的机会。

类型四:主线程作耗时动作

耗时操作造成主线程堵塞

类型五:binder线程被占满

系统对每个process最多分配15个binder线程

这个是谷歌的设计(/frameworks/native/libs/binder/ProcessState.cpp)

#define BINDER_VM_SIZE ((1 * 1024 * 1024) - sysconf(_SC_PAGE_SIZE) * 2)   binder 的 RAM Size 约为 1M

【1024*(1024-8)】

#define DEFAULT_MAX_BINDER_THREADS 15 //支持最大线程数为15 

如果另一个process发送太多重复binder请求,那么就会导致接收端binder线程被占满,从而处理不了其它的binder请求

这本身就是系统的一个限制,如果应用未按照系统的要求来实现对应逻辑,那么就会造成问题。

而系统端是不会(也不建议)通过修改系统行为来兼容应用逻辑,否则更容易造成其它根据系统需求正常编写的应用反而出现不可预料的问题。

判断Binder是否用完,可以在trace中搜索关键字"binder_f",如果搜索到则表示已经用完,然后就要找log其他地方看是谁一直在消耗binder或者是有死锁发生,对于binder用完的前期思路大致如此。

其中15并不代表该线程所能创建的binder线程的最大个数.

只是代表由binder驱动被动请求创建线程的个数,当我们查看binder线程池是否耗尽的时候要区分线程是被动创建的还是主动创建的.分析log的时候搜索关键字requested threads 就能找到被动创建的binder线程数量

以SYS_BINDR_INFO中Proc 3347为例,
proc 3347
context binder
  threads: 16    进程包含的binder线程个数
  requested threads: 0+6/15 是否正在请求创建binder线程中+由binder驱动被动请求创建的binder个数/最大可以被动创建的binder线程个数 
  ready threads 7  空闲的线程个数
  free async space 520192
  nodes: 45   binder服务的个数 
  refs: 74 s 74 w 74  请求服务的个数 强引用个数 弱引用个数 
  buffers: 7
  pages: 1:12:241   活跃的:分配未使用的:未分配的
  pages high watermark: 13
  pending transactions: 0  还没有执行的工作项 
  BC_TRANSACTION: 14309  发起的BC_TRANSACTION请求次数
  BC_REPLY: 42
  BC_FREE_BUFFER: 13023
  BC_INCREFS: 119 请求增加强引用
  BC_ACQUIRE: 119
  BC_RELEASE: 45
  BC_DECREFS: 45
  BC_INCREFS_DONE: 136
  BC_ACQUIRE_DONE: 136
  BC_REGISTER_LOOPER: 6 被动准备的线程 进入就绪状态的次数
  BC_ENTER_LOOPER: 1  主动 
  BC_REQUEST_DEATH_NOTIFICATION: 3
  BC_CLEAR_DEATH_NOTIFICATION: 2
  BR_TRANSACTION: 1367 收到的BR_TRANSACTION请求
  BR_REPLY: 11663  收到的结果(入过每次BC_TRANSACTION都有返回的话是一致的) 
  BR_TRANSACTION_COMPLETE: 14351  TRANSACTION被驱动接收到的次数
  BR_INCREFS: 136
  BR_ACQUIRE: 136
  BR_RELEASE: 91
  BR_DECREFS: 91
  BR_SPAWN_LOOPER: 6
  BR_CLEAR_DEATH_NOTIFICATION_DONE: 2 请求创建binder线程次数
           

binder内存耗尽导致进程被kill的案例

遇到一起SystemUI Crash的案例,原因是因为SystemUI进程的binder内存空间被消耗完毕,导致ActivityManagerService 向SystemUI发送广播的时候发生了RemoteException,进而导致AMS kill掉SystemUI进程。

四大组件和AMS之间的通信都是通过binder,同时,APP层和Framework服务之间的通信大部分也是通过binder,少数的通过Socket与Pipe。 系统为每个进程分配的Binder空间为BINDER_VM_SIZE(1*1024*1024) - (4096 *2)。binder通信分为同步通信和异步通信。client等待service处理完毕之后接着执行称为同步通信;client发送请求之后,立刻返回不等待service处理完毕称之为异步通信。binder用于异步通信分配的内存空间为BINDER_VM_SIZE /2.

如果一个client给一个service端高频率的发送异步消息,而service端来不及处理,就会导致service端的binder异步通信内存空间耗尽。 这时候其他的client给service再发送异步消息的时候由于内存不够就会失败,client端会收到一个异常。AMS给我们的应用发送广播,这种情况下AMS为client, 而我们的应用暂且可以称之为service。

在我们写binder通信代码的时候,特别要注意发送数据的频率和大小,这直接会影响我们代码的健壮性。

类型六:JE或者NE导致ANR

此类问题需查看具体log看分析原因。

Linux 信号机制

信号机制是 Linux 进程间通信的一种重要方式,Linux 信号一方面用于正常的进程间通信和同步,如任务控制(SIGINT, SIGTSTP,SIGKILL, SIGCONT,……);另一方面,它还负责监控系统异常及中断。 当应用程序运行异常时, Linux 内核将产生错误信号并通知当前进程。 当前进程在接收到该错误信号后,可以有三种不同的处理方式。

1. 忽略该信号。

2. 捕捉该信号并执行对应的信号处理函数(signal handler)。

3. 执行该信号的缺省操作(如 SIGTERM, 其缺省操作是终止进程)。

当 Linux 应用程序在执行时发生严重错误,一般会导致程序 crash。其中,Linux 专门提供了一类 crash 信号,在程序接收到此类信号时,缺省操作是将 crash 的现场信息记录到 core 文件,然后终止进程。

Crash信号列表

Signal Description
SIGSEGV Invalid memory reference.
SIGBUS Access to an undefined portion of a memory object.
SIGFPE Arithmetic operation error, like divide by zero.
SIGILL Illegal instruction, like execute garbage or a privileged instruction
SIGSYS Bad system call.
SIGXCPU CPU time limit exceeded.
SIGXFSZ File size limit exceeded. 

signal 7 (SIGBUS)原因有2种:

1.地址未对齐访问(需要自然对齐),比如int类型的指针,必须4字节对齐访问,否则会抛出SIGBUS

2.访问的虚拟地址存在,但是没有对应的物理地址或物理地址内无后备存储器可加载,比如将文件映射到内存中,当访问前文件被删除了,那么访问会导致SIGBUS。Linux平台上执行malloc(),如果没有足够的RAM,Linux不是让malloc()失败返回,

而是向当前进程分发SIGBUS信号。

Linux进程状态 ( Linux Process State Codes)

STATE代码    说明

D    不可中断的睡眠. 通常是处于I/O之中,同步IO在做读或写操作时,cpu不能做其它事情,只能等待,这时进程处于这种状态,如果程序采用异步IO,这种状态应该就很少见到了

R    运行中/可运行. 正处于运行队列中.

S    可中断的睡眠. 等待某事件发生.

T    已停止. 可能是因为shell作业控制或进程正被调试,也可能是进程发生了NE

W    分页中. 不适用于内核2.6.xx及以后的版本.

X    死亡. 再也不会出现.

Z    死/僵尸进程.

<    高优先级任务.

N    低优先级任务.

L    有分页内存被锁定到内存中. 用于实时任务和自定义I/O.

s    会话期首进程.

l    属多线程进程. 就像pthreads那样的克隆线程.

+    处于前台进程组.

类型七:容易出现在Monkey测试下

Zram Swap 

是 Linux 内核中采用时间换空间的一种技术,是把物理内存的一部分划分出来,把不是常用的内存数据压缩后放到zram里, 用到的时候把数据解压出来, 相当于牺牲了一些cpu效率,变相增大了内存。它通过压缩内存(Zram)来作为交换分区,通过压缩比来获取更多可利用的内存空间。

磁盘 swap:是把磁盘的一部分作为内存, 对应用来说完全是透明的,相当与增大了内存, 但是缺点很明显, 当用到swap的时候,速度会变的很慢。

swap分区的作用是当物理内存不足时,会将一部分硬盘当做虚拟内存来使用。

kswapd0:kswapd0进程的作用它是虚拟内存管理中,负责换页的,操作系统每过一定时间就会唤醒kswapd ,看看内存是否紧张,如果不紧张,则睡眠。

kswapd0 占用过高是因为 物理内存不足,使用swap分区与内存换页操作交换数据,导致CPU占用过高。

mmcqd:是与sd卡读取文件有关的进程

死锁

从现在的信息来看,手机发生了ANR后,cpu使用率过高,系统又做dump操作,导出相关的日志信息,进一步造成了系统的卡顿,

AMS持锁长时间得不到,软狗咬死system server,造成的swt问题。

SWT 堆栈信息
Exception Class: SWT
Exception Type: system_server_watchdog
Current Executing Process: 
system_server
Trigger time:[2018-01-01 10:49:20.340251] pid:634
Backtrace: 
Process: system_server
Subject: Blocked in monitor com.android.server.am.ActivityManagerService on foreground thread (android.fg), Blocked in handler on main thread (main), Blocked in handler on ActivityManager (ActivityManager)
Build: XXXX/H3718/XXXX:8.1.0/O11008/A-171225V54:user/release-keys
"android.fg" prio=5 tid=16 Blocked
group="main" sCount=1 dsCount=0 flags=1 obj=0x14603868 self=0xa1f78c00
sysTid=653 nice=0 cgrp=default sched=0/0 handle=0x9717a970
state=S schedstat=( 3635992772 7722759432 14830 ) utm=217 stm=146 core=1 HZ=100
stack=0x97078000-0x9707a000 stackSize=1038KB
held mutexes=
at com.android.server.am.ActivityManagerService.monitor(ActivityManagerService.java:24156)
持锁0x06495b83 8号线程
waiting to lock <0x06495b83> (a com.android.server.am.ActivityManagerService) held by thread 8
at com.android.server.Watchdog$HandlerChecker.run(Watchdog.java:229)
at android.os.Handler.handleCallback(Handler.java:790)
at android.os.Handler.dispatchMessage(Handler.java:99)
at android.os.Looper.loop(Looper.java:164)
at android.os.HandlerThread.run(HandlerThread.java:65)
at com.android.server.ServiceThread.run(ServiceThread.java:46)
"Binder:634_2" prio=5 tid=8 Runnable
group="main" sCount=0 dsCount=0 flags=0 obj=0x14602fe8 self=0xa1f3e600
sysTid=645 nice=-20 cgrp=default sched=0/0 handle=0x9840e970
state=R schedstat=( 206755441243 123539766496 298590 ) utm=16176 stm=4499 core=1 HZ=100
stack=0x98314000-0x98316000 stackSize=1006KB
held mutexes= "mutator lock"(shared held)
native: #00 pc 002e8377 /system/lib/libart.so (art::DumpNativeStack(std::_1::basic_ostream<char, std::_1::char_traits<char>>&, int, BacktraceMap*, char const*, art::ArtMethod*, void*)+130)
native: #01 pc 00379121 /system/lib/libart.so (art::Thread::DumpStack(std::_1::basic_ostream<char, std::_1::char_traits<char>>&, bool, BacktraceMap*, bool) const+204)
native: #02 pc 00375857 /system/lib/libart.so (art::Thread::Dump(std::_1::basic_ostream<char, std::_1::char_traits<char>>&, bool, BacktraceMap*, bool) const+34)
native: #03 pc 0038d1eb /system/lib/libart.so (art::DumpCheckpoint::Run(art::Thread*)+698)
native: #04 pc 00379d01 /system/lib/libart.so (art::Thread::RunCheckpointFunction()+284)
native: #05 pc 003e0317 /system/lib/libart.so (art::JniMethodFastEnd(unsigned int, art::Thread*)+46)
native: #06 pc 00047043 /system/framework/arm/boot.oat (Java_java_lang_String_charAt__I+90)
at java.lang.String.charAt(Native method)
at java.lang.AbstractStringBuilder.append(AbstractStringBuilder.java:550)
at java.lang.StringBuilder.append(StringBuilder.java:176)
at android.content.ComponentName.appendShortClassName(ComponentName.java:173)
at android.content.ComponentName.appendShortString(ComponentName.java:234)
at android.content.ComponentName.flattenToShortString(ComponentName.java:222)
at android.content.Intent.toShortString(Intent.java:9359)
at android.content.Intent.toInsecureString(Intent.java:9277)
at com.android.server.am.BroadcastRecord.dump(BroadcastRecord.java:105)
at com.android.server.am.BroadcastQueue.dumpLocked(BroadcastQueue.java:1695)
at com.android.server.am.ActivityManagerService.dumpBroadcastsLocked(ActivityManagerService.java:16832)
ActivityManagerService.dump 持锁 0x06495b83 没有释放 
at com.android.server.am.ActivityManagerService.dump(ActivityManagerService.java:15770)
bocked <0x06495b83> (a com.android.server.am.ActivityManagerService)
at android.os.Binder.doDump(Binder.java:531)
at android.os.Binder.dump(Binder.java:521)
at android.os.Binder.onTransact(Binder.java:471)
at android.app.IActivityManager$Stub.onTransact(IActivityManager.java:4323)
at com.android.server.am.ActivityManagerService.onTransact(ActivityManagerService.java:3119)
at android.os.Binder.execTransact(Binder.java:697)
at android.os.Binder.doDump(Binder.java:531)
at android.os.Binder.dump(Binder.java:521)
at android.os.Binder.onTransact(Binder.java:471)
at android.app.IActivityManager$Stub.onTransact(IActivityManager.java:4323)
at com.android.server.am.ActivityManagerService.onTransact(ActivityManagerService.java:3119)
at android.os.Binder.execTransact(Binder.java:697)
           

从上面的堆栈来看,系统卡在dump操作过程中,

查看Android Log流水日志,应用发生了ANR,且此时cpu使用率已经很高

01-01 10:47:46.915 634 648 I AnrManager: Reason: executing service com.google.android.apps.messaging/.shared.datamodel.action.ActionJobService
01-01 10:47:46.915 634 648 I AnrManager: Load: 11.44 / 15.26 / 16.63
01-01 10:47:46.915 634 648 I AnrManager: Android time :[2018-01-01 10:47:46.83] [24403.543]
01-01 10:47:46.915 634 648 I AnrManager: CPU usage from 8958ms to 16871ms later (2018-01-01 10:47:32.219 to 2018-01-01 10:47:40.132) with 99% awake:
01-01 10:47:46.915 634 648 I AnrManager: 165% 634/system_server: 113% user + 52% kernel / faults: 8529 minor 714 major
01-01 10:47:59.004 634 648 I AnrManager: ANR in com.eset.ems2.gp (com.eset.ems2.gp/com.eset.ems.gui.MainActivity), time=24403878
01-01 10:47:59.004 634 648 I AnrManager: Reason: Input dispatching timed out (Waiting because no window has focus but there is a focused application that may eventually add a window when it finishes starting up.)
01-01 10:47:59.004 634 648 I AnrManager: Load: 16.67 / 16.19 / 16.9
01-01 10:47:59.004 634 648 I AnrManager: Android time :[2018-01-01 10:47:58.95] [24415.656]
01-01 10:47:59.004 634 648 I AnrManager: CPU usage from 7049ms to 327ms ago (2018-01-01 10:47:40.132 to 2018-01-01 10:47:46.854):
01-01 10:47:59.004 634 648 I AnrManager: 118% 634/system_server: 76% user + 41% kernel / faults: 35929 minor 17223 major
软狗咬死系统服务 
Line 1502: 01-01 10:49:20.347 634 1218 V Watchdog: ** save all info before killnig system server **
Line 1503: 01-01 10:49:20.366 634 25488 V Watchdog: ** start addErrorToDropBox **
查看CPU-INFO的信息,可以看到CPU使用率很高 
Tasks: 1686 total, 22 running,1655 sleeping, 0 stopped, 1 zombie
Mem: 947908k total, 919144k used, 28764k free, 360k buffers
Swap: 710924k total, 350116k used, 360808k free, 229024k cached
400%cpu 209%user 70%nice 353%sys 232%idle 0%iow 0%irq 0%sirq 0%host
           

结论:

从现在的信息来看,手机发生了ANR后,cpu使用率过高,系统dump操作,导出相关的日志信息,进一步加剧了系统的卡顿,

AMS持锁长时间么有释放,触发软狗机制,咬死服务进程,造成的swt问题。