Android ANR bugreport log分析

Posted 2023-03-23 LXB-89

最近工作中频繁遇到设备ANR问题，而且是概率性的那种，于是决定花点时间找找规律复现分析下
说道这里，抓日志是问题解决的最有效途径，这里不得不说一下 bugreport log,其实网上关于它的分析方法有很多，在此仅仅是为了记录下bugreport 日志分析的过程和小技巧
希望对大家有所帮助。

1.抓取bugreport 日志（不指定，默认为当前目录）
- adb bugreport ..
- bugreport  anr 目录

2.bugreport log 分析
拿到log，首先要了解下log 抓取到的系统基本信息，主要包括 内存，CPU ，进程队列 ，虚拟内存 ， 垃圾回收等信息

2022-04-20 18:15:20.674 870-970/? E/ActivityManager: Aborting stack trace dump (current extra pid=3061); deadline exceeded.
2022-04-20 18:15:20.675 870-970/? I/AnrManager: dumpStackTraces end!
2022-04-20 18:15:20.738 870-970/? I/AnrManager: ANR in 包名 (包名/.ui.activity.MainActivity), time=342068
    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: 2.  Wait queue head age: 6459.2ms.)
    Load: 26.27 / 18.54 / 8.44
    android time :[2022-04-20 18:15:20.67] [363.181]
    CPU usage from 162797ms to 4885ms ago (2022-04-20 18:12:16.765 to 2022-04-20 18:14:54.677):
      48% 870/system_server: 20% user + 27% kernel / faults: 32190 minor
      17% 312/exe_cq/0: 0% user + 17% kernel
      11% 1691/net.forclass.guard: 2.2% user + 9.2% kernel / faults: 9288 minor
      10% 314/mmcqd/0: 0% user + 10% kernel
      10% 864/WantJoinFireWall: 1.2% user + 9% kernel / faults: 1 minor
      8.8% 635/jbd2/dm-2-8: 0% user + 8.8% kernel
      7.6% 491/surfaceflinger: 4.7% user + 2.9% kernel / faults: 774 minor 2 major
      6% 460/android.hardware.graphics.composer@2.1-service: 2.1% user + 3.9% kernel / faults: 14495 minor
      5.5% 681/netd: 1.6% user + 3.9% kernel / faults: 950 minor 3 major
      3.7% 1107/com.android.settings: 3.1% user + 0.5% kernel / faults: 18086 minor 5224 major
      3.5% 689/android.hardware.sensors@2.0-service-mediatek: 1.5% user + 2% kernel
      2.7% 1030/com.android.systemui: 1.7% user + 1% kernel / faults: 894 minor 22 major
      1.2% 1284/com.google.android.inputmethod.pinyin: 1.1% user + 0.1% kernel / faults: 8048 minor 43 major
      1.3% 204/chre_kthread: 0% user + 1.3% kernel
      1.1% 3061/com.estrongs.android.pop: 0.8% user + 0.3% kernel / faults: 5525 minor 164 major
      0.7% 249/kworker/4:1: 0% user + 0.7% kernel / faults: 67 minor
      0.7% 597/kworker/1:2: 0% user + 0.7% kernel / faults: 25 minor
      0.6% 243/kworker/5:1: 0% user + 0.6% kernel / faults: 61 minor
      0.6% 449/android.hardware.audio@5.0-service-mediatek: 0.3% user + 0.3% kernel / faults: 1040 minor
      0.3% 321/kworker/0:2: 0% user + 0.3% kernel / faults: 34 minor
      0.5% 231/WJFirewallTask: 0% user + 0.5% kernel
      0.5% 102/kworker/2:1: 0% user + 0.5% kernel / faults: 24 minor
      0.5% 240/kworker/0:1: 0% user + 0.5% kernel
      0.5% 7/rcu_preempt: 0% user + 0.5% kernel
      0.4% 323/kworker/6:1H: 0% user + 0.4% kernel
      0.4% 606/kworker/u16:16: 0% user + 0.4% kernel
      0.4% 608/kworker/u16:18: 0% user + 0.4% kernel
      0.4% 333/kworker/7:1H: 0% user + 0.4% kernel
      0.4% 276/ipi_cpu_dvfs_rt: 0% user + 0.4% kernel
      0.4% 332/kworker/5:1H: 0% user + 0.4% kernel
      0.4% 609/kworker/u16:19: 0% user + 0.4% kernel
      0.3% 607/kworker/u16:17: 0% user + 0.3% kernel
      0.3% 322/kworker/4:1H: 0% user + 0.3% kernel
      0.3% 359/logd: 0.1% user + 0.1% kernel / faults: 74 minor 11 major
      0.3% 300/kworker/6:1: 0% user + 0.3% kernel
      0.2% 610/kworker/u16:20: 0% user + 0.2% kernel
      0.1% 604/kworker/u16:14: 0% user + 0.1% kernel
      0.2% 2792/com.ibox.calculators: 0.1% user + 0.1% kernel / faults: 630 minor 1 major
      0.2% 195/pbm: 0% user + 0.2% kernel
      0.2% 46/kworker/7:0: 0% user + 0.2% kernel
      0.1% 41/kworker/6:0: 0% user + 0.1% kernel / faults: 45 minor
      0.2% 477/audioserver: 0.1% user + 0% kernel / faults: 208 minor 2 major
      0.2% 601/kworker/u16:11: 0% user + 0.2% kernel
      0.1% 688/media.codec: 0.1% user + 0% kernel / faults: 6308 minor
      0.1% 470/vendor.mediatek.hardware.mtkpower@1.0-service: 0% user + 0.1% kernel / faults: 1 minor
      0% 582/kworker/7:2: 0% user + 0% kernel / faults: 56 minor
      0.1% 347/ueventd: 0.1% user + 0% kernel / faults: 202 minor 9 major
      0.1% 1145/com.android.phone: 0.1% user + 0% kernel / faults: 702 minor 196 major
      0.1% 2931/com.ckl.fcfilemanager: 0% user + 0% kernel / faults: 698 minor 464 major
      0% 605/kworker/u16:15: 0% user + 0% kernel
      0.1% 1/init: 0% user + 0% kernel / faults: 202 minor 21 major
      0.1% 260/disp_idlemgr: 0% user + 0.1% kernel
      0% 267/present_fence_w: 0% user + 0% kernel
      0% 499/fuelgauged: 0% user + 0% kernel / faults: 1 minor
      0% 1716/com.amap.android.location: 0% user + 0% kernel / faults: 235 minor
      0% 110/ion_mm_heap: 0% user + 0% kernel
      0% 687/wificond: 0% user + 0% kernel / faults: 148 minor
2022-04-20 18:15:20.739 870-970/? I/AnrManager: dumpAnrDebugInfo end: AnrDumpRecord 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: 2.  Wait queue head age: 6459.2ms.) ProcessRecord883191b 3908:包名/u0a97 IsCompleted:true IsCancelled:false , isAsyncDump = false , isSilentANR = false
2022-04-20 18:15:20.739 870-901/? I/AnrManager: dumpAnrDebugInfoLocked: AnrDumpRecord 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: 2.  Wait queue head age: 6459.2ms.) ProcessRecord883191b 3908:包名/u0a97 IsCompleted:true IsCancelled:false , isAsyncDump = true, isSilentANR = false
2022-04-20 18:15:20.739 870-901/? I/AnrManager: dumpAnrDebugInfo end: AnrDumpRecord 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: 2.  Wait queue head age: 6459.2ms.) ProcessRecord883191b 3908:包名/u0a97 IsCompleted:true IsCancelled:false , isAsyncDump = true , isSilentANR = false
2022-04-20 18:15:20.740 870-970/? I/AnrManager: addErrorToDropBox app = ProcessRecord883191b 3908:包名/u0a97 processName = 包名 activityShortComponentName = 包名/.ui.activity.MainActivity parentShortComponentName = 包名/.ui.activity.MainActivity parentProcess = ProcessRecord883191b 3908:包名/u0a97 annotation = 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: 2.  Wait queue head age: 6459.2ms.) mTracesFile = /data/anr/anr_2022-04-20-18-15-00-174
2022-04-20 18:15:20.742 870-970/? I/AnrManager:  controller = null
2022-04-20 18:15:20.743 870-970/? I/InputDispatcher: Dropped event because it is stale.
2022-04-20 18:15:20.743 870-885/? W/Looper: Slow dispatch took 2581ms android.fg h=android.os.Handler c=com.android.server.Watchdog$HandlerChecker@bd2bd25 m=0
2022-04-20 18:15:20.757 870-970/? I/chatty: uid=1000(system) InputDispatcher identical 90 lines
2022-04-20 18:15:20.757 870-970/? I/InputDispatcher: Dropped event because it is stale.
2022-04-20 18:15:20.759 870-4081/? I/DropBoxManagerService: add tag=system_app_anr isTagEnabled=true flags=0x2
2022-04-20 18:15:20.784 870-4081/? W/AES: Exception Log handling...
2022-04-20 18:15:20.788 460-460/? I/hwcomposer: [HWC] (0) displayGetActiveConfig config:0  
2022-04-20 18:15:20.801 491-491/? I/BufferQueueProducer: [FramebufferSurface](this:0x76bc693800,id:0,api:1,p:491,c:491) queueBuffer: fps=0.17 dur=5951.50 max=5951.50 min=5951.50
2022-04-20 18:15:20.802 460-460/? I/hwcomposer: [HWCDisplay] [Display_0 (type:1)] fps:0.168050,dur:5950.61,max:5950.61,min:5950.61  
2022-04-20 18:15:20.803 491-973/? I/BufferQueue: [unnamed-491-34](this:0x76b8b3b000,id:34,api:0,p:-1,c:-1) BufferQueue core=(491:/system/bin/surfaceflinger)
2022-04-20 18:15:20.804 491-973/? I/BufferQueueConsumer: [unnamed-491-34](this:0x76b8b3b000,id:34,api:0,p:-1,c:491) connect(C): consumer=(491:/system/bin/surfaceflinger) controlledByApp=false
2022-04-20 18:15:20.804 491-973/? I/BufferQueueConsumer: [unnamed-491-34](this:0x76b8b3b000,id:34,api:0,p:-1,c:491) setConsumerName: unnamed-491-34
2022-04-20 18:15:20.804 491-973/? I/BufferQueueConsumer: [Application Not Responding: 包名#0](this:0x76b8b3b000,id:34,api:0,p:-1,c:491) setConsumerName: Application Not Responding: 包名#0
2022-04-20 18:15:20.804 491-973/? I/BufferQueueConsumer: [Application Not Responding: 包名#0](this:0x76b8b3b000,id:34,api:0,p:-1,c:491) setDefaultBufferSize: width=960 height=391
2022-04-20 18:15:20.807 870-886/? E/GraphicExt: GraphicExtModuleLoader::CreateGraphicExtInstance false
2022-04-20 18:15:20.835 870-4081/? W/AES: skip for Exp level 0
2022-04-20 18:15:20.836 491-973/? I/BufferQueueProducer: [Application Not Responding: 包名#0](this:0x76b8b3b000,id:34,api:1,p:870,c:491) connect(P): api=1 producer=(870:system_server) producerControlledByApp=false
2022-04-20 18:15:20.839 870-983/? E/WifiVendorHal: getWifiLinkLayerStats_1_3_Internal(l.927) failed .code = ERROR_NOT_SUPPORTED, .description = 
2022-04-20 18:15:20.905 870-886/? W/Looper: Slow dispatch took 110ms android.ui h=android.view.Choreographer$FrameHandler c=android.view.Choreographer$FrameDisplayEventReceiver@67bf45a m=0
2022-04-20 18:15:21.980 870-870/? I/DeviceIdleController: updateChargingLocked: charging=true
2022-04-20 18:15:21.980 870-870/? I/DeviceIdleController: becomeActiveLocked, reason=charging, changeLightIdle=true
2022-04-20 18:15:21.986 460-460/? I/hwcomposer: [HWC] (0) displayGetActiveConfig config:0  
2022-04-20 18:15:22.012 491-973/? I/BufferQueueProducer: [StatusBar#0](this:0x76b8b36800,id:4,api:1,p:1030,c:491) queueBuffer: fps=0.14 dur=7173.60 max=7173.60 min=7173.60
2022-04-20 18:15:22.013 1030-1030/? I/QSTileHost: QSTileHost QSSTATUS =0--VEGASTATUS = 0

日志很清晰了，顺藤摸瓜找到anr具体位置就行，不过这个过程可能会不会太顺利，一步一步来就能找到根源

分析日志小技巧
- anr 搜 "ANR in"
- Reason: Input dispatching timed out
-Load: 
-"mian" / tid= / sysTid=

系统cpu负荷分析

3.内存占比分析

Total PSS by process:

查看系统是否低内存（MemFree 和 MemAvailable 的值会很小）
adb shell cat proc/meminfo
adb查看应用程序内存使用情况
adb shell dumpsys meminfo <package_name>
了解更多，请参阅以下链接
https://www.jianshu.com/p/6b1c16e23987
https://www.proyy.com/7006950034935660574.html

4.死锁分析

 

 分析结果：tid=26 Blocked 该线程当前阻塞 - waiting to lock <0x0ff86ecf>，发现在等待的锁被  tid=52 Native  线程持有...

 5.更多ANR 问题分析
请参阅如下文章：
ANR问题浅析
ANR问题分析的一般套路  
负载Load分析
BugReport 辅助分析利器 ChkBugReportB​​​​​​

Anroid BugReport 异常快速排查手册