android anr探索 anr日志分析

个人理解要解决anr至少要理解anr日志的部分信息明白其中关键参数的意思

在分心anr日志之前我们先了解结果概念：

CPU平均负载：CPU负载是指某一时刻系统中运行队列长度之和加上当前正在CPU上运行的进程数，而CPU平均负载可以理解为一段时间内正在使用和等待使用CPU的活动进程的平均数量。在Linux中“活动进程”是指当前状态为运行或不可中断阻塞的进程。通常所说的负载其实就是指平均负载。

ANR发生之前和之后一段时间的CPU使用率

CPU使用率可以理解为一段时间（记作T）内除CPU空闲时间（记作I）之外的时间与这段时间T的比值，用公式表示可以写为：

CPU使用率= (T – I) / T

而时间段T是两个采样时间点的时间差值。

之所以可以这样计算，是因为Linux内核会把从系统启动开始到当前时刻CPU活动的所有时间信息都记录下来，我们可以通过查看“/proc/stat”文件获取这些信息。主要包括以下几种时间，这些时间都是从系统启动开始计算的，单位都是0.01秒：

user：CPU在用户态的运行时间，不包括nice值为负数的进程运行的时间

nice：CPU在用户态并且nice值为负数的进程运行的时间

system：CPU在内核态运行的时间

idle：CPU空闲时间，不包括iowait时间

iowait：CPU等待I/O操作的时间

irq：CPU硬中断的时间

softirq：CPU软中断的时间

1.理解日志中的信息：

看下面一段日志：

[09:34:37]03-16 09:34:03.815 D/TvosFeatureEventHelper( 2538): _ngbAnyCodeEventListener:KEY_EVENT:KEY_PRESSED Code=40 From: remote_control
[09:34:37]03-16 09:34:03.852 E/ActivityManager( 2092): ANR in in com.txl.demo (在in com.txl.demo这个进程里面发生了anr)
[09:34:37]03-16 09:34:03.852 E/ActivityManager( 2092): PID: 21098 （发生anr的进程id是21098）
[09:34:37]03-16 09:34:03.852 E/ActivityManager( 2092): Reason: executing service com.txt.demo/.message.NewsBroadcastService （发生anr的原因是这个服务执行超时）
[09:34:37]03-16 09:34:03.852 E/ActivityManager( 2092): Load: 12.51 / 13.35 / 13.98  （cpu前1分钟，5分钟，15分钟的平均负载）
[09:34:37]03-16 09:34:03.852 E/ActivityManager( 2092): CPU usage from 54617ms to 0ms ago: (Anr发生前一段时间cpu的使用率)
[09:34:37]03-16 09:34:03.852 E/ActivityManager( 2092): 19% 1616/dvb_middleware: 5.9% user + 13% kernel / faults: 164078 minor
[09:34:37]03-16 09:34:03.852 E/ActivityManager( 2092): 17% 2538/com.txl.demo1: 13% user + 4.2% kernel / faults: 89 minor
[09:34:37]03-16 09:34:03.852 E/ActivityManager( 2092): 7.1% 1617/IVIPService: 2.1% user + 4.9% kernel
[09:34:37]03-16 09:34:03.852 E/ActivityManager( 2092): 4.7% 21098/com.txl.demo: 1.7% user + 2.9% kernel / faults: 22 minor
[09:34:37]03-16 09:34:03.852 E/ActivityManager( 2092): 3.1% 1605/netmanager: 0.7% user + 2.3% kernel / faults: 159 minor
[09:34:37]03-16 09:34:03.852 E/ActivityManager( 2092): 2.8% 1618/PublishService: 0.8% user + 1.9% kernel / faults: 26 minor
[09:34:37]03-16 09:34:03.852 E/ActivityManager( 2092): 2.4% 1596/surfaceflinger: 1.2% user + 1.2% kernel
[09:34:37]03-16 09:34:03.852 E/ActivityManager( 2092): 2% 1778/AoEngineTask: 0% user + 2% kernel
[09:34:37]03-16 09:34:03.852 E/ActivityManager( 2092): 1.8% 2092/system_server: 1.1% user + 0.7% kernel / faults: 415 minor
[09:34:37]03-16 09:34:03.852 E/ActivityManager( 2092): 1.2% 3381/com.txl.demo2: 0.6% user + 0.6% kernel / faults: 44 minor
[09:34:37]03-16 09:34:03.852 E/ActivityManager( 2092): 0.7% 509/HI_VDEC_Task: 0% user + 0.7% kernel
[09:34:37]03-16 09:34:03.852 E/ActivityManager( 2092): 0.6% 508/HI_VPSS_Process: 0% user + 0.6% kernel
[09:34:37]03-16 09:34:03.852 E/ActivityManager( 2092): 0.5% 7/rcu_sched: 0% user + 0.5% kernel
[09:34:37]03-16 09:34:03.852 E/ActivityManager( 2092): 0.4% 1701/VDH_Distributor: 0% user + 0.4% kernel
[09:34:37]03-16 09:34:03.852 E/ActivityManager( 2092): 0.3% 1600/mediaserver: 0.1% user + 0.2% kernel
[09:34:37]03-16 09:34:03.852 E/ActivityManager( 2092): 0.3% 1699/HI_VFMW_VideoDe: 0% user + 0.3% kernel
[09:34:37]03-16 09:34:03.852 E/ActivityManager( 2092): 0.3% 1612/displaysetting: 0% user + 0.2% kernel
[09:34:37]03-16 09:34:03.852 E/ActivityManager( 2092): 0.2% 505/log_udisk_task: 0% user + 0.2% kernel
[09:34:37]03-16 09:34:03.852 E/ActivityManager( 2092): 0.1% 1591/logd: 0% user + 0% kernel / faults: 13 minor
[09:34:37]03-16 09:34:03.852 E/ActivityManager( 2092): 0.1% 20915/kworker/u8:1: 0% user + 0.1% kernel
[09:34:37]03-16 09:34:03.852 E/ActivityManager( 2092): 0.1% 826/mmcqd/0: 0% user + 0.1% kernel
[09:34:37]03-16 09:34:03.852 E/ActivityManager( 2092): 0% 3/ksoftirqd/0: 0% user + 0% kernel
[09:34:37]03-16 09:34:03.852 E/ActivityManager( 2092): 0% 1126/OmxVdecTask: 0% user + 0% kernel
[09:34:37]03-16 09:34:03.852 E/ActivityManager( 2092): 0% 1621/android_ir_user: 0% user + 0% kernel
[09:34:37]03-16 09:34:03.852 E/ActivityManager( 2092): 0% 11/ksoftirqd/1: 0% user + 0% kernel
[09:34:37]03-16 09:34:03.852 E/ActivityManager( 2092): 0% 15/ksoftirqd/2: 0% user + 0% kernel
[09:34:37]03-16 09:34:03.852 E/ActivityManager( 2092): 0% 19/ksoftirqd/3: 0% user + 0% kernel
[09:34:37]03-16 09:34:03.852 E/ActivityManager( 2092): 0% 510/HI_HDMI_kThread: 0% user + 0% kernel
[09:34:37]03-16 09:34:03.852 E/ActivityManager( 2092): 0% 1156/temperature_con: 0% user + 0% kernel
[09:34:37]03-16 09:34:03.852 E/ActivityManager( 2092): 0% 475/kworker/0:1: 0% user + 0% kernel
[09:34:37]03-16 09:34:03.852 E/ActivityManager( 2092): 0% 597/kworker/1:1: 0% user + 0% kernel
[09:34:37]03-16 09:34:03.852 E/ActivityManager( 2092): 0% 781/kworker/3:1: 0% user + 0% kernel
[09:34:37]03-16 09:34:03.852 E/ActivityManager( 2092): 0% 823/cfinteractive: 0% user + 0% kernel
[09:34:37]03-16 09:34:03.852 E/ActivityManager( 2092): 0% 971/usb-otg: 0% user + 0% kernel
[09:34:37]03-16 09:34:03.852 E/ActivityManager( 2092): 0% 1587/jbd2/mmcblk0p24: 0% user + 0% kernel
[09:34:37]03-16 09:34:03.852 E/ActivityManager( 2092): 0% 2454/com.hisilicon.android.inputmethod.remote: 0% user + 0% kernel / faults: 2 minor
[09:34:37]03-16 09:34:03.852 E/ActivityManager( 2092): +0% 21216/logcat: 0% user + 0% kernel
[09:34:37]03-16 09:34:03.852 E/ActivityManager( 2092): 16% TOTAL: 7.4% user + 8.2% kernel + 0% iowait + 0.9% softirq
[09:34:37]03-16 09:34:03.852 E/ActivityManager( 2092): CPU usage from 3659ms to 4204ms later:
[09:34:37]03-16 09:34:03.852 E/ActivityManager( 2092): 11% 1616/dvb_middleware: 3.7% user + 7.4% kernel / faults: 1650 minor
[09:34:37]03-16 09:34:03.852 E/ActivityManager( 2092):  7.4% 2127/dvb_middleware: 1.8% user + 5.5% kernel
[09:34:37]03-16 09:34:03.852 E/ActivityManager( 2092):  1.8% 2077/dvb_middleware: 0% user + 1.8% kernel
[09:34:37]03-16 09:34:03.852 E/ActivityManager( 2092):  1.8% 2744/dvb_middleware: 0% user + 1.8% kernel
[09:34:37]03-16 09:34:03.852 E/ActivityManager( 2092): 11% 2538/com.txl.demo1: 7.5% user + 3.7% kernel / faults: 3 minor
[09:34:37]03-16 09:34:03.852 E/ActivityManager( 2092):  3.7% 2538/or.tvos.browser: 1.8% user + 1.8% kernel
[09:34:37]03-16 09:34:03.852 E/ActivityManager( 2092): 7.4% 2092/system_server: 1.8% user + 5.5% kernel / faults: 8 minor
[09:34:37]03-16 09:34:03.852 E/ActivityManager( 2092):  7.4% 2111/ActivityManager: 1.8% user + 5.5% kernel
[09:34:37]03-16 09:34:03.852 E/ActivityManager( 2092): 5.5% 1617/IVIPService: 1.8% user + 3.7% kernel
[09:34:37]03-16 09:34:03.852 E/ActivityManager( 2092):  3.7% 2595/IVIPService: 1.8% user + 1.8% kernel
[09:34:37]03-16 09:34:03.852 E/ActivityManager( 2092): 2.7% 1591/logd: 1.3% user + 1.3% kernel
[09:34:37]03-16 09:34:03.852 E/ActivityManager( 2092):  1.3% 1634/logd.writer: 1.3% user + 0% kernel
[09:34:37]03-16 09:34:03.852 E/ActivityManager( 2092): 1.2% 508/HI_VPSS_Process: 0% user + 1.2% kernel
[09:34:37]03-16 09:34:03.852 E/ActivityManager( 2092): 1.8% 1596/surfaceflinger: 1.8% user + 0% kernel
[09:34:37]03-16 09:34:03.852 E/ActivityManager( 2092):  1.8% 1813/EventThread: 0% user + 1.8% kernel
[09:34:37]03-16 09:34:03.852 E/ActivityManager( 2092): 1.4% 1778/AoEngineTask: 0% user + 1.4% kernel
[09:34:37]03-16 09:34:03.852 E/ActivityManager( 2092): 1.7% 21098/com.starcor.tvos.settings: 1.7% user + 0% kernel
[09:34:37]03-16 09:34:03.852 E/ActivityManager( 2092): 11% TOTAL: 5.1% user + 6.1% kernel + 0.4% softirq
[09:34:37]03-16 09:34:03.852 I/ActivityManager( 2092): Killing 21098:com.txl.demo/1000 (adj -12): bg anr
[09:34:37]03-16 09:34:03.856 W/libprocessgroup( 2092): failed to open /acct/uid_1000/pid_21098/cgroup.procs: No such file or directory
[09:34:37]03-16 09:34:03.856 W/ActivityManager( 2092): Timeout executing service: ServiceRecord{2ab0fbaa u0 com.txl.demo/.message.NewsBroadcastService}
[09:34:37]03-16 09:34:03.857 I/ActivityManager( 2092): Skipping duplicate ANR: ProcessRecord{262e5071 21098:in com.txl.demo/1000} executing service com.txl.demo/.message.NewsBroadcastService