Android anr异常日志安卓anr日志

转载

mob6454cc6d1c0b 2023-07-25 22:30:22

文章标签 Android anr异常日志 java android 主线程 文章分类 Android 移动开发

ANR定义
ANR(Application Not Responding) 应用程序无响应。如果你应用程序在UI线程被阻塞太长时间，就会出现ANR，通常出现ANR，系统会弹出一个提示提示框，让用户知道，该程序正在被阻塞，是否继续等待还是关闭。
ANR类型
出现ANR的一般有以下几种类型：

KeyDispatchTimeout（常见）
input事件在5S内没有处理完成发生了ANR。
logcat日志关键字：Input event dispatching timed out
BroadcastTimeout
前台Broadcast：onReceiver在10S内没有处理完成发生ANR。
后台Broadcast：onReceiver在60s内没有处理完成发生ANR。
logcat日志关键字：Timeout of broadcast BroadcastRecord
ServiceTimeout
前台Service：onCreate，onStart，onBind等生命周期在20s内没有处理完成发生ANR。
后台Service：onCreate，onStart，onBind等生命周期在200s内没有处理完成发生ANR
logcat日志关键字：Timeout executing service
ContentProviderTimeout
ContentProvider 在10S内没有处理完成发生ANR。 logcat日志关键字：timeout publishing content providers
ANR出现的原因

1:主线程频繁进行耗时的IO操作：如数据库读写
2:多线程操作的死锁，主线程被block；
3:主线程被Binder 对端block；
4:System Server中WatchDog出现ANR；
5:service binder的连接达到上线无法和和System Server通信
6:系统资源已耗尽（管道、CPU、IO）
ANR案例分析过程
我们将一步一步分析ANR,这个过程更加理解如何找到问题、分析问题以及解决问题。
一、查看events_log
查看mobilelog文件夹下的events_log,从日志中搜索关键字：am_anr，找到出现ANR的时间点、进程PID、ANR类型。
如日志：
07-20 15:36:36.472 1000 1520 1597 I am_anr : [0,1480,com.xxxx.moblie,952680005,Input dispatching timed out (AppWindowToken{da8f666 token=Token{5501f51 ActivityRecord{15c5c78 u0 com.xxxx.moblie/.ui.MainActivity t3862}}}, Waiting because no window has focus but there is a focused application that may eventually add a window when it finishes starting up.)]
从上面的log我们可以看出：应用com.xxxx.moblie 在07-20 15:36:36.472时间，发生了一次KeyDispatchTimeout类型的ANR，它的进程号是1480. 把关键的信息整理一下：
ANR时间：07-20 15:36:36.472
进程pid：1480
进程名：com.xxxx.moblie
ANR类型：KeyDispatchTimeout
我们已经知道了发生KeyDispatchTimeout的ANR是因为 input事件在5秒内没有处理完成。那么在这个时间07-20 15:36:36.472 的前5秒，也就是（15:36:30 ~15:36:31）时间段左右程序到底做了什么事情？这个简单，因为我们已经知道pid了，再搜索一下pid = 1480的日志.这些日志表示该进程所运行的轨迹，关键的日志如下：

07-20 15:36:29.749 10102  1480  1737 D moblie-Application: [Thread:17329] receive an intent from server, action=com.ttt.push.RECEIVE_MESSAGE
    07-20 15:36:30.136 10102  1480  1737 D moblie-Application: receiving an empty message, drop
    07-20 15:36:35.791 10102  1480  1766 I Adreno  : QUALCOMM build                   : 9c9b012, I92eb381bc9
    07-20 15:36:35.791 10102  1480  1766 I Adreno  : Build Date                       : 12/31/17
    07-20 15:36:35.791 10102  1480  1766 I Adreno  : OpenGL ES Shader Compiler Version: EV031.22.00.01
    07-20 15:36:35.791 10102  1480  1766 I Adreno  : Local Branch                     : 
    07-20 15:36:35.791 10102  1480  1766 I Adreno  : Remote Branch                    : refs/tags/AU_LINUX_ANDROID_LA.UM.6.4.R1.08.00.00.309.049
    07-20 15:36:35.791 10102  1480  1766 I Adreno  : Remote Branch                    : NONE
    07-20 15:36:35.791 10102  1480  1766 I Adreno  : Reconstruct Branch               : NOTHING
    07-20 15:36:35.826 10102  1480  1766 I vndksupport: sphal namespace is not configured for this process. Loading /vendor/lib64/hw/gralloc.msm8998.so from the current namespace instead.
    07-20 15:36:36.682 10102  1480  1480 W ViewRootImpl[MainActivity]: Cancelling event due to no window focus: KeyEvent { action=ACTION_UP, keyCode=KEYCODE_PERIOD, scanCode=0, metaState=0, flags=0x28, repeatCount=0, eventTime=16099429, downTime=16099429, deviceId=-1, source=0x101 }

从上面我们可以知道，在时间 07-20 15:36:29.749 程序收到了一个action消息。

07-20 15:36:29.749 10102 1480 1737 D moblie-Application: [Thread:17329] receive an intent from server, action=com.ttt.push.RECEIVE_MESSAGE。

原来是应用com.xxxx.moblie 收到了一个推送消息（com.ttt.push.RECEIVE_MESSAGE）导致了阻塞，我们再串联一下目前所获取到的信息：在时间07-20 15:36:29.749 应用com.xxxx.moblie收到了一下推送信息action=com.ttt.push.RECEIVE_MESSAGE发生阻塞，5秒后发生了KeyDispatchTimeout的ANR。
虽然知道了是怎么开始的，但是具体原因还没有找到，是不是当时CPU很紧张、各路APP再抢占资源？我们再看看CPU的信息,。搜索关键字关键字： ANR IN

07-20 15:36:58.711  1000  1520  1597 E ActivityManager: ANR in com.xxxx.moblie (com.xxxx.moblie/.ui.MainActivity) (进程名)
07-20 15:36:58.711  1000  1520  1597 E ActivityManager: PID: 1480 (进程pid)
07-20 15:36:58.711  1000  1520  1597 E ActivityManager: Reason: Input dispatching timed out (AppWindowToken{da8f666 token=Token{5501f51 ActivityRecord{15c5c78 u0 com.xxxx.moblie/.ui.MainActivity t3862}}}, Waiting because no window has focus but there is a focused application that may eventually add a window when it finishes starting up.)
07-20 15:36:58.711  1000  1520  1597 E ActivityManager: Load: 0.0 / 0.0 / 0.0 (Load表明是1分钟,5分钟,15分钟CPU的负载)
07-20 15:36:58.711  1000  1520  1597 E ActivityManager: CPU usage from 20ms to 20286ms later (2018-07-20 15:36:36.170 to 2018-07-20 15:36:56.436):
07-20 15:36:58.711  1000  1520  1597 E ActivityManager:   42% 6774/pressure: 41% user + 1.4% kernel / faults: 168 minor
07-20 15:36:58.711  1000  1520  1597 E ActivityManager:   34% 142/kswapd0: 0% user + 34% kernel
07-20 15:36:58.711  1000  1520  1597 E ActivityManager:   31% 1520/system_server: 13% user + 18% kernel / faults: 58724 minor 1585 major
07-20 15:36:58.711  1000  1520  1597 E ActivityManager:   13% 29901/com.ss.android.article.news: 7.7% user + 6% kernel / faults: 56007 minor 2446 major
07-20 15:36:58.711  1000  1520  1597 E ActivityManager:   13% 32638/com.android.quicksearchbox: 9.4% user + 3.8% kernel / faults: 48999 minor 1540 major
07-20 15:36:58.711  1000  1520  1597 E ActivityManager:   11% (CPU的使用率)1480/com.xxxx.moblie: 5.2%(用户态的使用率) user + (内核态的使用率) 6.3% kernel / faults: 76401 minor 2422 major
07-20 15:36:58.711  1000  1520  1597 E ActivityManager:   8.2% 21000/kworker/u16:12: 0% user + 8.2% kernel
07-20 15:36:58.711  1000  1520  1597 E ActivityManager:   0.8% 724/mtd: 0% user + 0.8% kernel / faults: 1561 minor 9 major
07-20 15:36:58.711  1000  1520  1597 E ActivityManager:   8% 29704/kworker/u16:8: 0% user + 8% kernel
07-20 15:36:58.711  1000  1520  1597 E ActivityManager:   7.9% 24391/kworker/u16:18: 0% user + 7.9% kernel
07-20 15:36:58.711  1000  1520  1597 E ActivityManager:   7.1% 30656/kworker/u16:14: 0% user + 7.1% kernel
07-20 15:36:58.711  1000  1520  1597 E ActivityManager:   7.1% 9998/kworker/u16:4: 0% user + 7.1% kernel

我已经在log 中标志了相关的含义。com.xxxx.moblie 占用了11%的CPU，其实这并不算多。现在的手机基本都是多核CPU。假如你的CPU是4核，那么上限是400%，以此类推。
既然不是CPU负载的原因，那么到底是什么原因呢？这时就要看我们的终极大杀器——traces.txt。
二、 traces.txt 日志分析

当APP不响应、响应慢了、或者WatchDog的监视没有得到回应时，系统就会dump出一个traces.txt文件，存放在文件目录:/data/anr/traces.txt，通过traces文件,我们可以拿到线程名、堆栈信息、线程当前状态、binder call等信息。
通过adb命令拿到该文件：adb pull /data/anr/traces.txt
trace: Cmd line:com.xxxx.moblie

"main" prio=5 tid=1 Runnable
  | group="main" sCount=0 dsCount=0 obj=0x73bcc7d0 self=0x7f20814c00
  | sysTid=20176 nice=-10 cgrp=default sched=0/0 handle=0x7f251349b0
  | state=R schedstat=( 0 0 0 ) utm=12 stm=3 core=5 HZ=100
  | stack=0x7fdb75e000-0x7fdb760000 stackSize=8MB
  | held mutexes= "mutator lock"(shared held)
  // java 堆栈调用信息,可以查看调用的关系，定位到具体位置
  at ttt.push.InterceptorProxy.addMiuiApplication(InterceptorProxy.java:77)
  at ttt.push.InterceptorProxy.create(InterceptorProxy.java:59)
  at android.app.Activity.onCreate(Activity.java:1041)
  at miui.app.Activity.onCreate(SourceFile:47)
  at com.xxxx.moblie.ui.b.onCreate(SourceFile:172)
  at com.xxxx.moblie.ui.MainActivity.onCreate(SourceFile:68)
  at android.app.Activity.performCreate(Activity.java:7050)
  at android.app.Instrumentation.callActivityOnCreate(Instrumentation.java:1214)
  at android.app.ActivityThread.performLaunchActivity(ActivityThread.java:2807)
  at android.app.ActivityThread.handleLaunchActivity(ActivityThread.java:2929)
  at android.app.ActivityThread.-wrap11(ActivityThread.java:-1)
  at android.app.ActivityThread$H.handleMessage(ActivityThread.java:1618)
  at android.os.Handler.dispatchMessage(Handler.java:105)
  at android.os.Looper.loop(Looper.java:171)
  at android.app.ActivityThread.main(ActivityThread.java:6699)
  at java.lang.reflect.Method.invoke(Native method)
  at com.android.internal.os.Zygote$MethodAndArgsCaller.run(Zygote.java:246)
  at com.android.internal.os.ZygoteInit.main(ZygoteInit.java:783)

我详细解析一下traces.txt里面的一些字段，看看它到底能给我们提供什么信息.
main：main标识是主线程，如果是线程，那么命名成“Thread-X”的格式,x表示线程id,逐步递增。
prio：线程优先级,默认是5
tid：tid不是线程的id，是线程唯一标识ID
group：是线程组名称
sCount：该线程被挂起的次数
dsCount：是线程被调试器挂起的次数
obj：对象地址
self：该线程Native的地址
sysTid：是线程号(主线程的线程号和进程号相同)
nice：是线程的调度优先级
sched：分别标志了线程的调度策略和优先级
cgrp：调度归属组
handle：线程处理函数的地址。
state：是调度状态
schedstat：从 /proc/[pid]/task/[tid]/schedstat读出，三个值分别表示线程在cpu上执行的时间、线程的等待时间和线程执行的时间片长度，不支持这项信息的三个值都是0；
utm：是线程用户态下使用的时间值(单位是jiffies）
stm：是内核态下的调度时间值
core：是最后执行这个线程的cpu核的序号。

Java的堆栈信息是我们最关心的，它能够定位到具体位置。从上面的traces,我们可以判断ttt.push.InterceptorProxy.addMiuiApplicationInterceptorProxy.java:77 导致了com.xxxx.moblie发生了ANR。这时候可以对着源码查看，找到出问题，并且解决它。
总结一下这分析流程：首先我们搜索am_anr，找到出现ANR的时间点、进程PID、ANR类型、然后再找搜索PID，找前5秒左右的日志。过滤ANR IN 查看CPU信息，接着查看traces.txt，找到java的堆栈信息定位代码位置，最后查看源码，分析与解决问题。这个过程基本能找到发生ANR的来龙去脉。

ANR 案例整理
一、主线程被其他线程lock，导致死锁

waiting on <0x1cd570> (a android.os.MessageQueue)

DALVIK THREADS:
"main" prio=5 tid=3 TIMED_WAIT
  | group="main" sCount=1 dsCount=0 s=0 obj=0x400143a8
  | sysTid=691 nice=0 sched=0/0 handle=-1091117924
  at java.lang.Object.wait(Native Method)
  - waiting on <0x1cd570> (a android.os.MessageQueue)
  at java.lang.Object.wait(Object.java:195)
  at android.os.MessageQueue.next(MessageQueue.java:144)
  at android.os.Looper.loop(Looper.java:110)
  at android.app.ActivityThread.main(ActivityThread.java:3742)
  at java.lang.reflect.Method.invokeNative(Native Method)
  at java.lang.reflect.Method.invoke(Method.java:515)
  at com.android.internal.os.ZygoteInit$MethodAndArgsCaller.run(ZygoteInit.java:739)
  at com.android.internal.os.ZygoteInit.main(ZygoteInit.java:497)
  at dalvik.system.NativeStart.main(Native Method)
 
"Binder Thread #3" prio=5 tid=15 NATIVE
  | group="main" sCount=1 dsCount=0 s=0 obj=0x434e7758
  | sysTid=734 nice=0 sched=0/0 handle=1733632
  at dalvik.system.NativeStart.run(Native Method)
 
"Binder Thread #2" prio=5 tid=13 NATIVE
  | group="main" sCount=1 dsCount=0 s=0 obj=0x1cd570
  | sysTid=696 nice=0 sched=0/0 handle=1369840
  at dalvik.system.NativeStart.run(Native Method)
 
"Binder Thread #1" prio=5 tid=11 NATIVE
  | group="main" sCount=1 dsCount=0 s=0 obj=0x433aca10
  | sysTid=695 nice=0 sched=0/0 handle=1367448
  at dalvik.system.NativeStart.run(Native Method)
 
----- end 691 -----

二、主线程做耗时的操作：比如数据库读写。

"main" prio=5 tid=1 Native
  | group="main" sCount=1 dsCount=0 flags=1 obj=0x7340a3a0 self=0xb0a4f000
  | sysTid=762 nice=-2 cgrp=default sched=0/0 handle=0xb48bd4a4
  | state=S schedstat=( 2154417152 308150910 5791 ) utm=165 stm=50 core=1 HZ=100
  | stack=0xbe45e000-0xbe460000 stackSize=8MB
  | held mutexes=
  kernel: (couldn't read /proc/self/task/762/stack)
  native: #00 pc 000486cc  /system/lib/libc.so (__ioctl+8)
  native: #01 pc 0001d09f  /system/lib/libc.so (ioctl+38)
  native: #02 pc 0001000b  /system/lib/libhwbinder.so (android::hardware::IPCThreadState::talkWithDriver(bool)+170)
  native: #03 pc 00010a89  /system/lib/libhwbinder.so (android::hardware::IPCThreadState::waitForResponse(android::hardware::Parcel*, int*)+236)
  native: #04 pc 0000e4cd  /system/lib/libhwbinder.so (android::hardware::BpHwBinder::transact(unsigned int, android::hardware::Parcel const&, android::hardware::Parcel*, unsigned int, std::__1::function<void (android::hardware::Parcel&)>)+36)
  native: #05 pc 00069559  /system/lib/android.hardware.gnss@1.0.so (android::hardware::gnss::V1_0::BpHwGnss::_hidl_getExtensionAGnss(android::hardware::IInterface*, android::hardware::details::HidlInstrumentor*)+136)
  native: #06 pc 0006b829  /system/lib/vendor.sprd.hardware.gnss@1.0.so (vendor::sprd::hardware::gnss::V1_0::BpHwGnssExt::getExtensionAGnss()+10)
  native: #07 pc 00048c95  /system/lib/libandroid_servers.so (???)
  native: #08 pc 00023ddf  /system/framework/oat/arm/services.odex (???)
  at com.android.server.location.GnssLocationProvider.class_init_native(Native method)
  at com.android.server.location.GnssLocationProvider.<clinit>(GnssLocationProvider.java:2737)
  at com.android.server.LocationManagerService.loadProvidersLocked(LocationManagerService.java:619)
  at com.android.server.LocationManagerService.systemRunning(LocationManagerService.java:371)
  - locked <0x013d057d> (a java.lang.Object)
  at com.android.server.SystemServer.lambda$-com_android_server_SystemServer_79161(SystemServer.java:1855)
  at com.android.server.-$Lambda$T7cKu_OKm_Fk2kBNthmo_uUJTSo$1.$m$0(unavailable:-1)
  at com.android.server.-$Lambda$T7cKu_OKm_Fk2kBNthmo_uUJTSo$1.run(unavailable:-1)
  at com.android.server.am.ActivityManagerService.systemReady(ActivityManagerService.java:14557)
  at com.android.server.am.ActivityManagerServiceEx.systemReady(ActivityManagerServiceEx.java:270)
  at com.android.server.SystemServer.startOtherServices(SystemServer.java:1748)
  at com.android.server.SystemServer.run(SystemServer.java:404)
  at com.android.server.SystemServer.main(SystemServer.java:280)
  at java.lang.reflect.Method.invoke(Native method)
  at com.android.internal.os.RuntimeInit$MethodAndArgsCaller.run(RuntimeInit.java:449)
  at com.android.internal.os.ZygoteInit.main(ZygoteInit.java:787)

三、binder数据量过大

07-21 04:43:21.573  1000  1488 12756 E Binder  : Unreasonably large binder reply buffer: on android.content.pm.BaseParceledListSlice$1@770c74f calling 1 size 388568 (data: 1, 32, 7274595)
07-21 04:43:21.573  1000  1488 12756 E Binder  : android.util.Log$TerribleFailure: Unreasonably large binder reply buffer: on android.content.pm.BaseParceledListSlice$1@770c74f calling 1 size 388568 (data: 1, 32, 7274595)
07-21 04:43:21.607  1000  1488  2951 E Binder  : Unreasonably large binder reply buffer: on android.content.pm.BaseParceledListSlice$1@770c74f calling 1 size 211848 (data: 1, 23, 7274595)
07-21 04:43:21.607  1000  1488  2951 E Binder  : android.util.Log$TerribleFailure: Unreasonably large binder reply buffer: on android.content.pm.BaseParceledListSlice$1@770c74f calling 1 size 211848 (data: 1, 23, 7274595)
07-21 04:43:21.662  1000  1488  6258 E Binder  : Unreasonably large binder reply buffer: on android.content.pm.BaseParceledListSlice$1@770c74f calling 1 size 259300 (data: 1, 33, 7274595)

四、binder 通信失败

07-21 06:04:35.580 <6>[32837.690321] binder: 1698:2362 transaction failed 29189/-3, size 100-0 line 3042
07-21 06:04:35.594 <6>[32837.704042] binder: 1765:4071 transaction failed 29189/-3, size 76-0 line 3042
07-21 06:04:35.899 <6>[32838.009132] binder: 1765:4067 transaction failed 29189/-3, size 224-8 line 3042
07-21 06:04:36.018 <6>[32838.128903] binder: 1765:2397 transaction failed 29189/-22, size 348-0 line 2916

五、案例分析

//点击一个按钮后延时操作，会报ANR
  public void onANR(View view) {
        try {
            Thread.sleep(1000000);
        } catch (InterruptedException e) {
            e.printStackTrace();
        }
    }

执行命令：adb shell logcat -s ActivityManager

ANR in com.zqc.testdemo (com.zqc.testdemo/.MainActivity)
04-27 17:19:59.229   691   705 E ActivityManager: PID: 4423
04-27 17:19:59.229   691   705 E ActivityManager: Reason: Input dispatching timed out (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: 22.  Wait queue head age: 10507.2ms.)
04-27 17:19:59.229   691   705 E ActivityManager: Load: 10.56 / 10.95 / 5.73
04-27 17:19:59.229   691   705 E ActivityManager: CPU usage from 1ms to 24521ms later (2020-04-27 17:19:34.209 to 2020-04-27 17:19:58.729):
04-27 17:19:59.229   691   705 E ActivityManager:   34% 691/system_server: 31% user + 3.4% kernel / faults: 11109 minor 283 major
04-27 17:19:59.229   691   705 E ActivityManager:   28% 247/android.hardware.camera.provider@2.4-service: 20% user + 7.8% kernel / faults: 3869 minor 3 major
04-27 17:19:59.229   691   705 E ActivityManager:   23% 1354/com.txznet.txz: 21% user + 1.6% kernel / faults: 15174 minor 1128 major
04-27 17:19:59.229   691   705 E ActivityManager:   18% 1843/com.mapgoo.diruite: 17% user + 1.5% kernel / faults: 10041 minor 26 major
04-27 17:19:59.229   691   705 E ActivityManager:   15% 1367/com.zqc.camera: 12% user + 3.4% kernel / faults: 74195 minor 102 major
04-27 17:19:59.229   691   705 E ActivityManager:   14% 484/adbd: 4.6% user + 9.9% kernel / faults: 34367 minor
04-27 17:19:59.229   691   705 E ActivityManager:   9% 216/logd: 3.5% user + 5.4% kernel / faults: 1918 minor 42 major
04-27 17:19:59.229   691   705 E ActivityManager:   8.4% 437/mediaserver: 3.5% user + 4.9% kernel / faults: 18665 minor 8 major
04-27 17:19:59.229   691   705 E ActivityManager:   8% 64/kswapd0: 0% user + 8% kernel
04-27 17:19:59.229   691   705 E ActivityManager:   7.3% 1399/com.hdsc.edog: 3% user + 4.3% kernel / faults: 2812 minor 176 major
04-27 17:19:59.229   691   705 E ActivityManager:   7% 443/media.codec: 3.4% user + 3.6% kernel / faults: 4241 minor 41 major
04-27 17:19:59.229   691   705 E ActivityManager:   7% 1825/com.autonavi.amapautolite: 5.9% user + 1.1% kernel / faults: 7901 minor 797 major
04-27 17:19:59.229   691   705 E ActivityManager:   6.8% 1//init: 3.7% user + 3% kernel / faults: 348 minor
04-27 17:19:59.229   691   705 E ActivityManager:   6.7% 218/hwservicemanager: 5% user + 1.7% kernel / faults: 11845 minor
04-27 17:19:59.229   691   705 E ActivityManager:   5.8% 275/surfaceflinger: 3.4% user + 2.4% kernel / faults: 2570 minor 21 major
04-27 17:19:59.229   691   705 E ActivityManager:   4.7% 426/cameraserver: 2.5% user + 2.2% kernel / faults: 2898 minor 15 major
04-27 17:19:59.229   691   705 E ActivityManager:   4.3% 882/com.android.phone: 3.8% user + 0.4% kernel / faults: 5443 minor 167 major
04-27 17:19:59.229   691   705 E ActivityManager:   3.9% 913/com.android.systemui: 3.1% user + 0.7% kernel / faults: 6000 minor 100 major
04-27 17:19:59.229   691   705 E ActivityManager:   3.7% 3448/logcat: 2.1% user + 1.5% kernel / faults: 116 minor 2 major
04-27 17:19:59.229   691   705 E ActivityManager:   3.1% 3222/com.autonavi.amapautolite:locationservice: 2.8% user + 0.3% kernel / faults: 5277 minor 110 major
04-27 17:19:59.229   691   705 E ActivityManager:   3% 1658/isp0_bin: 0% user + 3% kernel
04-27 17:19:59.229   691   705 E ActivityManager:   3% 1413/com.car.tencent: 2.7% user + 0.3% kernel / faults: 5478 minor 104 major
04-27 17:19:59.229   691   705 E ActivityManager:   2.2% 254/android.hardware.graphics.composer@2.1-service: 1.2% user + 0.9% kernel / faults: 322 minor
04-27 17:19:59.229   691   705 E ActivityManager:   1.7% 178/kworker/u8:3: 0% user + 1.7% kernel
04-27 17:19:59.229   691   705 E ActivityManager:   1.5% 448/vendor.sprd.hardware.gnss@1.0-service: 1.4% user + 0.1% kernel / faults: 334 minor
04-27 17:19:59.229   691   705 E ActivityManager:   1.3% 1301/com.zqc.functioncore: 1.2% user + 0.1% kernel / faults: 3703 minor 61 major
04-27 17:19:59.229   691   705 E ActivityManager:   1.3% 245/android.hardware.audio@2.0-service: 0.2% user + 1% kernel / faults: 263 minor 27 major
04-27 17:19:59.229   691   705 E ActivityManager:   1.3% 3458/logcat: 0.3% user + 0.9% kernel / faults: 129 minor
04-27 17:19:59.229   691   705 E ActivityManager:   1.2% 1428/com.sprd.customizedNet: 1% user + 0.1% kernel / faults: 1585 minor 290 major
04-27 17:19:59.229   691   705 E ActivityManager:   1.1% 425/audioserver: 0.3% user + 0.8% kernel / faults: 842 minor 82 major
04-27 17:19:59.229   691   705 E ActivityManager:   1% 1476/com.android.modemnotifier: 0.8% user + 0.1% kernel / faults: 1609 minor 233 major
04-27 17:19:59.229   691   705 E ActivityManager:   1% 45/cfinteractive: 0% user + 1% kernel
04-27 17:19:59.229   691   705 E ActivityManager:   0.9% 141/kworker/u8:2: 0% user + 0.9% kernel
04-27 17:19:59.229   691   705 E ActivityManager:   0.8% 1445/cn.kuwo.kwmusiccar: 0.7% user + 0.1% kernel / faults: 1537 minor 307 major
04-27 17:19:59.229   691   705 E ActivityManager:   0.8% 148/mmcqd/0: 0% user + 0.8% kernel
04-27 17:19:59.229   691   705 E ActivityManager:   0.8% 1382/com.spreadtrum.vce: 0.7% user + 0.1% kernel / faults: 1618 minor 280 major
04-27 17:19:59.229   691   705 E ActivityManager:   0.8% 1461/com.zxbluelet: 0.6% user + 0.1% kernel / faults: 1552 minor 273 major
04-27 17:19:59.229   691   705 E ActivityManager:   0.8% 4423/com.zqc.testdemo: 0.5% user + 0.2% kernel / faults: 1481 minor 474 major
04-27 17:19:59.229   691   705 E ActivityManager:   0.6% 1340/com.zqc.screensaver: 0.5% user + 0.1% kernel / faults: 1525 minor 346 major
04-27 17:19:59.229   691   705 E ActivityManager:   0.6% 258/android.hardware.sensors@1.0-service: 0.2% user + 0.3% kernel / faults: 1087 minor
04-27 17:19:59.229   691   705 E ActivityManager:   0.5% 30/irq/23-70800000: 0% user + 0.5% kernel
04-27 17:19:59.229   691   705 E ActivityManager:   0.5% 122/gsp-core[0]: 0% user + 0.5% kernel
04-27 17:19:59.229   691   705 E ActivityManager:   0.5% 2947/com.redstone.ota.ui: 0.3% user + 0.1% kernel / faults: 1435 minor 1044 major
04-27 17:19:59.229   691   705 E ActivityManager:   0.4% 6/kworker/u8:0: 0% user + 0.4% kernel
04-27 17:19:59.229   691   705 E ActivityManager:   0.4% 99/sprd-adf-dev: 0% user + 0.4% kernel
04-27 17:19:59.229   691   705 E ActivityManager:   0% 126/kworker/u8:1: 0% user + 0% kernel
04-27 17:19:59.229   691   705 E ActivityManager:   0.3% 184/mmcqd/1: 0% user + 0.3% kernel
04-27 17:19:59.229   691   705 E ActivityManager:   0.3% 217/servicemanager: 0.1% user + 0.2% kernel / faults: 404 minor 1 major
04-27 17:19:59.229   691   705 E ActivityManager:   0.2% 411/kworker/u9:3: 0% user + 0.2% kernel
04-27 17:19:59.229   691   705 E ActivityManager:   0.2% 7/rcu_preempt: 0% use
04-27 17:20:00.595   691  1474 W ActivityManager: Unable to start service Intent { pkg=com.mapgoo.media.dvrx cmp=com.mapgoo.media.dvrx/.service.Daemon } U=0: not found



04-27 17:20:14.562   691  1842 W ActivityManager: Unbind failed: could not find connection for android.os.BinderProxy@37e22fe
04-27 17:20:18.312   691  1491 W ActivityManager: Unable to start service Intent { cmp=com.autonavi.minimap/com.amap.api.service.AMapService (has extras) } U=0: not found
04-27 17:20:20.571   691   706 W ActivityManager:   Force finishing activity com.zqc.testdemo/.MainActivity
04-27 17:20:20.642   691   706 I ActivityManager: Killing 4423:com.zqc.testdemo/u0a66 (adj 0): user request after error
04-27 17:20:21.174   691   713 W ActivityManager: setHasOverlayUi called on unknown pid: 4423

ANR日志

----- pid 4423 at 2020-04-27 17:19:37 -----
Cmd line: com.wq.testdemo
/13216:user/release-keys'
ABI: 'arm'
Build type: optimized
Zygote loaded classes=5038 post zygote classes=439
Intern table: 12481 strong; 399 weak
JNI: CheckJNI is on; globals=502 (plus 25 weak)
Libraries: /system/lib/libandroid.so /system/lib/libcompiler_rt.so /system/lib/libjavacrypto.so /system/lib/libjnigraphics.so /system/lib/libmedia_jni.so /system/lib/libsoundpool.so /system/lib/libwebviewchromium_loader.so libjavacore.so libopenjdk.so (9)
Heap: 22% free, 1423KB/1837KB; 58760 objects
Dumping cumulative Gc timings
Start Dumping histograms for 3 iterations for concurrent copying
ProcessMarkStack:	Sum: 141.836ms 99% C.I. 21.138ms-87.738ms Avg: 47.278ms Max: 87.738ms
ScanImmuneSpaces:	Sum: 137.615ms 99% C.I. 1.905ms-123.198ms Avg: 45.871ms Max: 123.198ms
MarkingPhase:	Sum: 54.627ms 99% C.I. 0.048ms-54.507ms Avg: 18.209ms Max: 54.507ms
VisitConcurrentRoots:	Sum: 37.792ms 99% C.I. 1.636ms-24.881ms Avg: 12.597ms Max: 24.881ms
SweepAllocSpace:	Sum: 9.365ms 99% C.I. 0.013ms-9.339ms Avg: 3.121ms Max: 9.339ms
SweepSystemWeaks:	Sum: 9.072ms 99% C.I. 0.091ms-8.887ms Avg: 3.024ms Max: 8.887ms
ReclaimPhase:	Sum: 4.870ms 99% C.I. 0.024ms-4.817ms Avg: 1.623ms Max: 4.817ms
ClearFromSpace:	Sum: 4.292ms 99% C.I. 0.140ms-3.946ms Avg: 1.430ms Max: 3.981ms
FlipOtherThreads:	Sum: 1.242ms 99% C.I. 84us-988us Avg: 414us Max: 988us
FlipThreadRoots:	Sum: 1.225ms 99% C.I. 4us-1213us Avg: 408.333us Max: 1213us
ThreadListFlip:	Sum: 775us 99% C.I. 29us-702us Avg: 258.333us Max: 702us
ProcessReferences:	Sum: 674us 99% C.I. 2us-623us Avg: 112.333us Max: 623us
GrayAllDirtyImmuneObjects:	Sum: 443us 99% C.I. 101us-218us Avg: 147.666us Max: 218us
RecordFree:	Sum: 298us 99% C.I. 85us-115us Avg: 99.333us Max: 115us
EnqueueFinalizerReferences:	Sum: 255us 99% C.I. 50us-140us Avg: 85us Max: 140us
InitializePhase:	Sum: 205us 99% C.I. 37us-121us Avg: 68.333us Max: 121us
MarkZygoteLargeObjects:	Sum: 182us 99% C.I. 49us-80us Avg: 60.666us Max: 80us
VisitNonThreadRoots:	Sum: 140us 99% C.I. 41us-52us Avg: 46.666us Max: 52us
EmptyRBMarkBitStack:	Sum: 109us 99% C.I. 28us-44us Avg: 36.333us Max: 44us
MarkStackAsLive:	Sum: 79us 99% C.I. 16us-43us Avg: 26.333us Max: 43us
ResumeRunnableThreads:	Sum: 73us 99% C.I. 11us-37us Avg: 24.333us Max: 37us
SweepLargeObjects:	Sum: 71us 99% C.I. 22us-25us Avg: 23.666us Max: 25us
ForwardSoftReferences:	Sum: 69us 99% C.I. 18us-32us Avg: 23us Max: 32us
ClearRegionSpaceCards:	Sum: 61us 99% C.I. 12us-26us Avg: 20.333us Max: 26us
SwapBitmaps:	Sum: 54us 99% C.I. 16us-20us Avg: 18us Max: 20us
(Paused)SetFromSpace:	Sum: 39us 99% C.I. 6us-27us Avg: 13us Max: 27us
(Paused)GrayAllNewlyDirtyImmuneObjects:	Sum: 33us 99% C.I. 10us-13us Avg: 11us Max: 13us
(Paused)FlipCallback:	Sum: 18us 99% C.I. 4us-9us Avg: 6us Max: 9us
ResumeOtherThreads:	Sum: 15us 99% C.I. 2us-9us Avg: 5us Max: 9us
Sweep:	Sum: 11us 99% C.I. 3us-5us Avg: 3.666us Max: 5us
(Paused)ClearCards:	Sum: 6us 99% C.I. 2us-2us Avg: 2us Max: 2us
UnBindBitmaps:	Sum: 5us 99% C.I. 1us-2us Avg: 1.666us Max: 2us
Done Dumping histograms
concurrent copying paused:	Sum: 843us 99% C.I. 44us-719us Avg: 281us Max: 719us
concurrent copying total time: 405.551ms mean time: 135.183ms
concurrent copying freed: 9873 objects with total size 4MB
concurrent copying throughput: 24377.8/s / 11MB/s
Cumulative bytes moved 15506032
Cumulative objects moved 260366
Total time spent in GC: 405.551ms
Mean GC size throughput: 11MB/s
Mean GC object throughput: 24344.7 objects/s
Total number of allocations 68633
Total bytes allocated 6MB
Total bytes freed 4MB
Free memory 414KB
Free memory until GC 414KB
Free memory until OOME 126MB
Total memory 1837KB
Max memory 128MB
Zygote space size 2MB
Total mutator paused time: 843us
Total time waiting for GC to complete: 6.808us
Total GC count: 3
Total GC time: 405.551ms
Total blocking GC count: 0
Total blocking GC time: 0
Histogram of GC count per 10000 ms: 1:1
Histogram of blocking GC count per 10000 ms: 0:1
Registered native bytes allocated: 281707
/system/framework/boot.oat: speed
/system/framework/boot-core-libart.oat: speed
/system/framework/boot-conscrypt.oat: speed
/system/framework/boot-okhttp.oat: speed
/system/framework/boot-bouncycastle.oat: speed
/system/framework/boot-apache-xml.oat: speed
/system/framework/boot-legacy-test.oat: speed
/system/framework/boot-ext.oat: speed
/system/framework/boot-framework.oat: speed
/system/framework/boot-telephony-common.oat: speed
/system/framework/boot-voip-common.oat: speed
/system/framework/boot-ims-common.oat: speed
/system/framework/boot-org.apache.http.legacy.boot.oat: speed
/system/framework/boot-android.hidl.base-V1.0-java.oat: speed
/system/framework/boot-android.hidl.manager-V1.0-java.oat: speed
/system/framework/boot-radio_interactor_common.oat: speed
Current JIT code cache size: 9KB
Current JIT data cache size: 11KB
Current JIT capacity: 64KB
Current number of JIT code cache entries: 26
Total number of JIT compilations: 26
Total number of JIT compilations for on stack replacement: 0
Total number of JIT code cache collections: 0
Memory used for stack maps: Avg: 135B Max: 832B Min: 24B
Memory used for compiled code: Avg: 354B Max: 2988B Min: 2B
Memory used for profiling info: Avg: 123B Max: 1240B Min: 16B
Start Dumping histograms for 26 iterations for JIT timings
Compiling:	Sum: 1.165s 99% C.I. 1.115ms-198.155ms Avg: 44.823ms Max: 198.155ms
TrimMaps:	Sum: 5.764ms 99% C.I. 18us-4228us Avg: 221.692us Max: 4733us
Done Dumping histograms
Memory used for compilation: Avg: 71KB Max: 435KB Min: 15KB
ProfileSaver total_bytes_written=0
ProfileSaver total_number_of_writes=0
ProfileSaver total_number_of_code_cache_queries=0
ProfileSaver total_number_of_skipped_writes=0
ProfileSaver total_number_of_failed_writes=0
ProfileSaver total_ms_of_sleep=5000
ProfileSaver total_ms_of_work=0
ProfileSaver max_number_profile_entries_cached=0
ProfileSaver total_number_of_hot_spikes=0
ProfileSaver total_number_of_wake_ups=0

suspend all histogram:	Sum: 1.099ms 99% C.I. 5us-660.160us Avg: 91.583us Max: 678us
DALVIK THREADS (16):
"Signal Catcher" daemon prio=5 tid=3 Runnable
  | group="system" sCount=0 dsCount=0 flags=0 obj=0x12e406a8 self=0xb16cb200
  | sysTid=4429 nice=0 cgrp=default sched=0/0 handle=0xa81d4970
  | state=R schedstat=( 57331698 43635573 258 ) utm=2 stm=3 core=2 HZ=100
  | stack=0xa80da000-0xa80dc000 stackSize=1006KB
  | held mutexes= "mutator lock"(shared held)
  native: #00 pc 002ecd57  /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 00380045  /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 0037c57f  /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 00394511  /system/lib/libart.so (art::DumpCheckpoint::Run(art::Thread*)+684)
  native: #04 pc 0038e02f  /system/lib/libart.so (art::ThreadList::RunCheckpoint(art::Closure*, art::Closure*)+322)
  native: #05 pc 0038db1f  /system/lib/libart.so (art::ThreadList::Dump(std::__1::basic_ostream<char, std::__1::char_traits<char>>&, bool)+542)
  native: #06 pc 0038d831  /system/lib/libart.so (art::ThreadList::DumpForSigQuit(std::__1::basic_ostream<char, std::__1::char_traits<char>>&)+648)
  native: #07 pc 0036aac3  /system/lib/libart.so (art::Runtime::DumpForSigQuit(std::__1::basic_ostream<char, std::__1::char_traits<char>>&)+122)
  native: #08 pc 003720c5  /system/lib/libart.so (art::SignalCatcher::HandleSigQuit()+1276)
  native: #09 pc 0037104d  /system/lib/libart.so (art::SignalCatcher::Run(void*)+240)
  native: #10 pc 00046f7b  /system/lib/libc.so (__pthread_start(void*)+22)
  native: #11 pc 0001a2a7  /system/lib/libc.so (__start_thread+32)
  (no managed stack frames)

"main" prio=5 tid=1 Sleeping
  | group="main" sCount=1 dsCount=0 flags=1 obj=0xec01358 self=0xb16ca000
  | sysTid=4423 nice=-10 cgrp=default sched=0/0 handle=0xb556a4a4
  | state=S schedstat=( 1520964430 721498577 1834 ) utm=124 stm=28 core=2 HZ=100
  | stack=0xbe5df000-0xbe5e1000 stackSize=8MB
  | held mutexes=
  at java.lang.Thread.sleep(Native method)
 - sleeping on <0x0a0eedce> (a java.lang.Object)
  at java.lang.Thread.sleep(Thread.java:373)
 - locked <0x0a0eedce> (a java.lang.Object)
  at java.lang.Thread.sleep(Thread.java:314)
  at com.wq.testdemo.MainActivity.onANR(MainActivity.java:18)
  at java.lang.reflect.Method.invoke(Native method)
  at androidx.appcompat.app.AppCompatViewInflater$DeclaredOnClickListener.onClick(AppCompatViewInflater.java:397)
  at android.view.View.performClick(View.java:6311)
  at android.view.View$PerformClick.run(View.java:24829)
  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.app.ActivityThread.main(ActivityThread.java:6752)
  at java.lang.reflect.Method.invoke(Native method)
  at com.android.internal.os.RuntimeInit$MethodAndArgsCaller.run(RuntimeInit.java:449)
  at com.android.internal.os.ZygoteInit.main(ZygoteInit.java:807)

system server ANR 一种分析方法 – Android JVM异常重启简析

找到SYSTEM server的PID，一般在logcat中会有这么一句
System server process 2094 has been created； 2094就是你需要的PID
根据pid去搜索写入anr的地方，比如log中应该会有下面这些log：

05-10 11:10:02.360 I/Process ( 2094): Sending signal. PID: 2094 SIG: 3 这里发了SIGQUIT ----向system server进程发quit信号，这里是“果”
    05-10 11:10:02.360 I/dalvikvm( 2094): threadid=4: reacting to signal 3
    05-10 11:10:02.420 I/dalvikvm( 2094): Wrote stack traces to '/data/anr/traces.txt'            
    之后也一定会有类似的kill log：
    05-10 11:10:34.860 I/Process ( 2094): Sending signal. PID: 2094 SIG: 9
    05-10 11:10:34.860 W/Watchdog( 2094): *** WATCHDOG KILLING SYSTEM PROCESS: null    ----  这里发出了kill 
   至于ANR的“因”，继续在log中往上寻找，也一定能有类似的语句：
    05-10 11:09:37.980 W/ActivityManager( 2094): Timeout of broadcast BroadcastRecord{2b1a7f48 android.intent.action.SCREEN_OFF} --这里就是"因"SCREEN_OFFtimeout
    05-10 11:09:37.980 W/ActivityManager( 2094): Receiverduring timeout: BroadcastFilter{2b161a08 ReceiverList{2b1619d0 2094 system/1000 local:2b130420}}

本文章为转载内容，我们尊重原作者对文章享有的著作权。如有内容错误或侵权问题，欢迎原作者联系我们进行内容更正或删除文章。