binder ANR案例

1.分析event_log，确定发生anr的进程和时间点
例：11-13 14:32:05.085  1091  1116 I am_anr  : 
[0,25453,com.google.android.gms.persistent,-1194836411,Broadcast of Intent { act=android.intent.action.SCREEN_OFF flg=0x50000010 }]
2.分析traces文件
例：
"main" prio=5 tid=1 Native
  | group="main" sCount=1 dsCount=0 obj=0x756188c8 self=0xb3004400
  | sysTid=25453 nice=0 cgrp=bg_non_interactive sched=0/0 handle=0xb63ba534
  | state=S schedstat=( 1644024933 1944634424 4080 ) utm=131 stm=33 core=3 HZ=100
  | stack=0xbe48c000-0xbe48e000 stackSize=8MB
  | held mutexes=
  at android.os.BinderProxy.transactNative(Native method)
  at android.os.BinderProxy.transact(Binder.java:622)
  at android.app.ActivityManagerProxy.getContentProvider(ActivityManagerNative.java:4440)
  at android.app.ActivityThread.acquireProvider(ActivityThread.java:5597)
  at android.app.ContextImpl$ApplicationContentResolver.acquireUnstableProvider(ContextImpl.java:2256)
  at android.content.ContentResolver.acquireUnstableProvider(ContentResolver.java:1566)
  at android.content.ContentResolver.query(ContentResolver.java:521)
  at android.content.ContentResolver.query(ContentResolver.java:479)

 

确定ContentProvider的跨进程通信，看binder_info

3. 分析binder_info
Line 73:     outgoing transaction 2071602: 00000000 from 25453:25453 to 1091:1920 code 1d flags 10 pri 0 r1 node 1727 size 164:4 data 00000000
Line 135:     incoming transaction 2071602: 00000000 from 25453:25453 to 1091:1920 code 1d flags 10 pri 0 r1 node 1727 size 164:4 data 00000000


可以看出当前进程25453正在等待1091进程的1920线程执行操作


4.再回过头来分析traces
----- pid 1091 at 2017-11-13 14:32:05 -----
Cmd line: system_server
Build fingerprint: 'Infinix/X557A1/X557:7.0/NRD90M/X557-H807AD-N-171110V163:user/release-keys'
......
"Binder:1091_B" prio=5 tid=92 Waiting
  | group="main" sCount=1 dsCount=0 obj=0x13701d30 self=0x9da93400
  | sysTid=1920 nice=0 cgrp=default sched=0/0 handle=0x93d75920
  | state=S schedstat=( 12242993141 11246346684 32557 ) utm=832 stm=392 core=3 HZ=100
  | stack=0x93c79000-0x93c7b000 stackSize=1014KB
  | held mutexes=
  at java.lang.Object.wait!(Native method)
  - waiting on <0x0b69f197> (a com.android.server.am.ContentProviderRecord)
  at com.android.server.am.ActivityManagerService.getContentProviderImpl(ActivityManagerService.java:11904)
  - locked <0x0b69f197> (a com.android.server.am.ContentProviderRecord)
  at com.android.server.am.ActivityManagerService.getContentProvider(ActivityManagerService.java:11976)
  at android.app.ActivityManagerNative.onTransact(ActivityManagerNative.java:980)
  at com.android.server.am.ActivityManagerService.onTransact(ActivityManagerService.java:3016)
  at android.os.Binder.execTransact(Binder.java:570)