Android ANR-Broadcast Timeout

最新推荐文章于 2024-05-24 17:26:43 发布

laisse

最新推荐文章于 2024-05-24 17:26:43 发布

阅读量1.5w

点赞数 2

分类专栏： Android 文章标签： ANR

本文链接：https://blog.csdn.net/laisse/article/details/47259707

版权

Android 专栏收录该内容

51 篇文章 1 订阅

订阅专栏

Definition

Ordered broadcasts
- Intents sent by Context.sendOrderedBroadcast() are broadcasted to one receiver at a time, regardless of if they are registered by Context.registerReceiver() or AndroidManifest.xml.
- When receivers are delivered one at a time, each receiver’s execution time is restricted by 10 seconds to prevent later receivers’ starvation.
Parallel broadcasts
Intents sent by Context.sendBroadcast() are broadcasted to receivers in an undefined order.
Receivers registered by Context.registerReceiver() are delivered intents at the same time, whereas receivers registered by AndroidManifest.xml are delivered one at a time to reduce overall system’s loading.
Intent flag
FLAG_EXCLUDE_STOPPED_PACKAGES: If set, this intent will NOT match any components in packages that are currently stopped. that means, if the receiver process is stopped now, the receiver process will not bring-up under this flag setting.
FLAG_INCLUDE_STOPPED_PACKAGES: If set, this intent will always match any components in packages that are currently stopped. that means, if the receiver process is stopped now, the receiver process will be bring-up under this flag setting.

Code flow of ANR

这里写图片描述

broadcast Scenario:

Log pattern

Broadcast log pattern

ActivityManager: broadcast

// Parallel broadcasts:
// pid:726 sent a 'BATTERY_CHANGED' intent; it's parallel broadcast and there are 11 receivers for this intent
I ActivityManager: broadcast act=android.intent.action.BATTERY_CHANGED flg=0x60000000 from pid=726, uid=1000,parallel BR:45f90fd,u-1,size=11,replaced=0,order BR:null,size=0,resultTo=null

// Ordered broadcasts:
// pid:726 sent a 'SCREEN_OFF' intent; it's order broadcast and there are 112 receivers for this intent
I ActivityManager: broadcast act=android.intent.action.SCREEN_OFF flg=0x50000000 from pid=726, uid=1000,order BR:3dc1eef7,u-1,size=112,replaced=0

BroadcastQueue: Deliver

// pid:726 sent a 'wifi.SCAN_RESULTS' intent
I ActivityManager: broadcast act=android.net.wifi.SCAN_RESULTS flg=0x4000000 from pid=726, uid=1000,parallel BR:3bfa7c3b,u-1,size=4,replaced=0,order BR:null,size=0,resultTo=null

// there are 4 parallel receivers (search keyword: 3bfa7c3b, it's BroadcastRecord hash-code)
I BroadcastQueue: Deliver non-order [BG] BR@3bfa7c3b BF{11b6236e u0 RL{a579ae9 726 system/1000/u0 c9ca770}} BF{1fbf7533 u0 RL{1f71b4a2 726 system/1000/u0 2a36a06d}} BF{1a300bcb u0 RL{2bf2a69a 2199 com.google.process.location/10029/u0}} BF{271fad82 u0 RL{3f2f70cd 2199 com.google.process.location/10029/u0}}

// BF{11b6236e u0 RL{a579ae9 726 system/1000/u0 c9ca770}}
// BF{1fbf7533 u0 RL{1f71b4a2 726 system/1000/u0 2a36a06d}}
// BF{1a300bcb u0 RL{2bf2a69a 2199 com.google.process.location/10029/u0}}
// BF{271fad82 u0 RL{3f2f70cd 2199 com.google.process.location/10029/u0}}

// pid:-1 sent a 'TIME_TICK' order broadcast, and there are 6 receivers
 726   977 I ActivityManager: broadcast act=android.intent.action.TIME_TICK flg=0x50000004 from pid=-1, uid=1000,order BR:27bfce76,u-1,size=6,replaced=0

// deliver to 1st, system(pid:726) (search keyword: 27bfce76, it's BroadcastRecord hash-code)
 726   755 I BroadcastQueue: Deliver order [FG] BF{284db6ba u0 RL{32477be5 726 system/1000/u0 1fe3bedc}}:BR@27bfce76
 726   726 V Perf    : com.android.server.AlarmManagerService$ClockReceiver@1fe3bedc onReceive:android.intent.action.TIME_TICK, 1ms    // pid:726 onReceive() completed in 1ms

// deliver to 2nd, systemui(pid:1034) (search keyword: 27bfce76, it's BroadcastRecord hash-code)
 726   726 I BroadcastQueue: Deliver order [FG] BF{a586775 u0 RL{1dddeac 1034 com.android.systemui/10052/u0}}:BR@27bfce76
1034  1034 V Perf    : com.htc.lockscreen.keyguard.KeyguardUpdateMonitor$2@620726e onReceive:android.intent.action.TIME_TICK, 0ms    // pid:1034 onReceive() completed in 0ms

// deliver to 3rd, systemui(pid:1034) (search keyword: 27bfce76, it's BroadcastRecord hash-code)
 726  1439 I BroadcastQueue: Deliver order [FG] BF{2f06c36d u0 RL{f4ccf84 1034 com.android.systemui/10052/u0}}:BR@27bfce76
1034  1034 V Perf    : com.htc.lockscreen.util.KeyguardIndicationController$2@cbd28a8 onReceive:android.intent.action.TIME_TICK, 1ms    // pid:1034 onReceive() completed in 1ms

...others...

Broadcast log pattern (MTK)

Pattern 1

// AMS got a request to broadcast intent
01-01 08:09:00.000   670   990 V ActivityManager: Broadcast: Intent { act=android.intent.action.TIME_TICK flg=0x50000014 (has extras) } ordered=true userid=-1 callerApp=null

// AMS schedules to broadcast intent to 1st app (pid:670).
01-01 08:09:00.004   670   716 D BroadcastQueue: BDC-Delivered broadcast: Intent { act=android.intent.action.TIME_TICK flg=0x50000014 (has extras) }, ordered=true, filter=BroadcastFilter{22568769 u0 ReceiverList{2fc975f0 670 system/1000/u0 local:20a67e33}}, receiver=android.app.LoadedApk$ReceiverDispatcher$InnerReceiver@20a67e33
01-01 08:09:00.005   670   670 D ActivityThread: BDC-Calling onReceive: intent=Intent { act=android.intent.action.TIME_TICK flg=0x50000014 (has extras) }, ordered=true, receiver=com.android.server.AlarmManagerService$ClockReceiver@10db41a2, IIntentReceiver=20a67e33    // app (pid:670) received this intent
01-01 08:09:00.006   670   670 D ActivityThread: BDC-Calling finishReceiver: IIntentReceiver=20a67e33    // app (pid:670) finished onReceive
01-01 08:09:00.006   670   670 D ActivityManager: BDC-Finishing receiver: android.app.LoadedApk$ReceiverDispatcher$InnerReceiver@20a67e33    // AMS is notified that application done receiver execution.

// AMS schedules to broadcast intent to 2nd app (pid:1043).
01-01 08:09:00.008   670   670 D BroadcastQueue: BDC-Delivered broadcast: Intent { act=android.intent.action.TIME_TICK flg=0x50000014 (has extras) }, ordered=true, filter=BroadcastFilter{c59798e u0 ReceiverList{19f7f589 1043 com.android.systemui/10015/u0 remote:27b14890}}, receiver=android.os.BinderProxy@27b14890
01-01 08:09:00.011  1043  1043 D ActivityThread: BDC-Calling onReceive: intent=Intent { act=android.intent.action.TIME_TICK flg=0x50000014 (has extras) }, ordered=true, receiver=com.android.keyguard.KeyguardUpdateMonitor$2@2ee2a814, IIntentReceiver=1f9f24a9
01-01 08:09:00.011  1043  1043 D ActivityThread: BDC-Calling finishReceiver: IIntentReceiver=1f9f24a9
01-01 08:09:00.012   670  1792 D ActivityManager: BDC-Finishing receiver: android.os.BinderProxy@27b14890

// AMS schedules to broadcast intent to 3rd app (pid:1990).
01-01 08:09:00.157   670  1456 D BroadcastQueue: BDC-Delivered broadcast: Intent { act=android.intent.action.TIME_TICK flg=0x50000014 (has extras) }, ordered=true, filter=BroadcastFilter{9a85e99 u0 ReceiverList{354c6be0 1990 com.android.launcher/10010/u0 remote:1f84d5e3}}, receiver=android.os.BinderProxy@1f84d5e3
01-01 08:09:00.158  1990  1990 D ActivityThread: BDC-Calling onReceive: intent=Intent { act=android.intent.action.TIME_TICK flg=0x50000014 (has extras) }, ordered=true, receiver=android.widget.AnalogClock$1@3a2ccbae, IIntentReceiver=1ed8a3b8
01-01 08:09:00.161  1990  1990 D ActivityThread: BDC-Calling finishReceiver: IIntentReceiver=1ed8a3b8
01-01 08:09:00.163   670  1456 D ActivityManager: BDC-Finishing receiver: android.os.BinderProxy@1f84d5e3

Pattern 2

// AMS got a request to broadcast intent
01-01 08:08:54.890   670   727 V ActivityManager: Broadcast: Intent { act=android.intent.action.PACKAGE_ADDED dat=package:com.mtk.anrmechanismtesting flg=0x4000010 (has extras) } ordered=false userid=0 callerApp=null

// AMS schedules to broadcast intent to 1st app (pid:3216).
01-01 08:08:54.934   670   716 D BroadcastQueue: BDC-Delivered broadcast: Intent { act=android.intent.action.PACKAGE_ADDED dat=package:com.mtk.anrmechanismtesting flg=0x4000010 cmp=com.android.providers.contacts/.PackageIntentReceiver (has extras) }, ordered=true, app=ProcessRecord{3ae71bea 3216:android.process.acore/u0a2}, receiver=android.os.BinderProxy@2f276aa4
01-01 08:08:54.927  3216  3216 D ActivityThread: BDC-Calling onReceive: intent=Intent { act=android.intent.action.PACKAGE_ADDED dat=package:com.mtk.anrmechanismtesting flg=0x4000010 cmp=com.android.providers.contacts/.PackageIntentReceiver (has extras) }, ordered=true, receiver=com.android.providers.contacts.PackageIntentReceiver@376d9110
01-01 08:08:54.928  3216  3216 D ActivityThread: BDC-RECEIVER handled : 0 / ReceiverData{intent=Intent { act=android.intent.action.PACKAGE_ADDED dat=package:com.mtk.anrmechanismtesting flg=0x4000010 cmp=com.android.providers.contacts/.PackageIntentReceiver (has extras) } packageName=com.android.providers.contacts resultCode=0 resultData=null resultExtras=null}
01-01 08:08:54.937   670  1867 D ActivityManager: BDC-Finishing receiver: android.os.BinderProxy@2f276aa4

// AMS schedules to broadcast intent to 2nd app (pid:2573).
01-01 08:08:54.964   670  1867 D BroadcastQueue: BDC-Delivered broadcast: Intent { act=android.intent.action.PACKAGE_ADDED dat=package:com.mtk.anrmechanismtesting flg=0x4000010 cmp=com.android.gallery3d/.app.PackagesMonitor (has extras) }, ordered=true, app=ProcessRecord{291bb754 2573:com.android.gallery3d/u0a37}, receiver=android.os.BinderProxy@11a0d6fd
01-01 08:08:55.001  2573  2573 D ActivityThread: BDC-Calling onReceive: intent=Intent { act=android.intent.action.PACKAGE_ADDED dat=package:com.mtk.anrmechanismtesting flg=0x4000010 cmp=com.android.gallery3d/.app.PackagesMonitor (has extras) }, ordered=true, receiver=com.android.gallery3d.app.PackagesMonitor@a0f0d6a
01-01 08:08:55.153  2573  2573 D ActivityThread: BDC-RECEIVER handled : 0 / ReceiverData{intent=Intent { act=android.intent.action.PACKAGE_ADDED dat=package:com.mtk.anrmechanismtesting flg=0x4000010 cmp=com.android.gallery3d/.app.PackagesMonitor$AsyncService (has extras) } packageName=com.android.gallery3d resultCode=0 resultData=null resultExtras=null}
01-01 08:08:55.153   670  1867 D ActivityManager: BDC-Finishing receiver: android.os.BinderProxy@11a0d6fd

How to check broadcast timeout

ANR’s timestamp

am_anr @ eventlog
BroadcastQueue: Timeout of broadcast @ devicelog

@device-log
W BroadcastQueue: Timeout of broadcast BroadcastRecord{48ab67c8 u-1 android.net.conn.CONNECTIVITY_CHANGE callingPid=921 callingUid=1000} - receiver=android.os.BinderProxy@488a5c10
W BroadcastQueue: Receiver during timeout: ResolveInfo{48a846c8 com.tencent.mm/.booter.MMReceivers$ConnectionReceiver m=0x108000}
...
E ActivityThread: MSG: Dump looper, process: com.tencent.mm:push
E ActivityThread: MSG: ===== Message History (Most recent to least recent) =====
...
E ActivityManager: ANR in com.tencent.mm:push, time=4391605
E ActivityManager: PID: 32154
E ActivityManager: Reason: Broadcast of Intent { act=android.net.conn.CONNECTIVITY_CHANGE flg=0x4000010 cmp=com.tencent.mm/.booter.MMReceivers$ConnectionReceiver (has extras) }
E ActivityManager: Load: 13.96 / 14.42 / 16.21
E ActivityManager: CPU usage from 10394ms to 0ms ago:

@event-log
I am_anr  : [0,32154,com.tencent.mm:push,9485892,Broadcast of Intent { act=android.net.conn.CONNECTIVITY_CHANGE flg=0x4000010 cmp=com.tencent.mm/.booter.MMReceivers$ConnectionReceiver (has extras) }]

when this broadcast intent deliver

ActivityManager: broadcast: AMS broadcast the intent
BroadcastQueue: Deliver: broadcast deliver the intent to receivers

// AMS broadcast this intent(android.intent.action.SCREEN_ON) at 18:17:50.967; and there are 42 order broadcast receivers
10-30 18:17:50.967   669   690 I ActivityManager: broadcast act=android.intent.action.SCREEN_ON flg=0x50000000 from pid=669, uid=1000,order BR:430eb370,u-1,size=42,replaced=0


// the broadcast record (BR:430eb370) delivered log...
10-30 18:17:50.967   669   768 I BroadcastQueue: Deliver order [FG] BF{41e6c178 u0 RL{41e7a5d0 669 system/1000/u0 local:41e90be8}}:BR@430eb370
10-30 18:17:51.017   669   690 I BroadcastQueue: Deliver order [FG] BF{42485c50 u0 RL{42485bd0 669 system/1000/u0 local:42485a38}}:BR@430eb370
10-30 18:17:51.037   669   690 I BroadcastQueue: Deliver order [FG] BF{4257c788 u0 RL{4257c708 669 system/1000/u0 local:4257c570}}:BR@430eb370
...
10-30 18:18:02.179   669   768 I BroadcastQueue: Deliver order [FG] BF{4437d0f8 u0 RL{42e7ebe0 10322 com.babytree.apps.pregnancy:pushservice/10408/u0 remote:439e4508}}:BR@430eb370
10-30 18:18:02.199   669   768 I BroadcastQueue: Deliver order [FG] BF{437b3030 u0 RL{437ac638 1309 com.funcity.taxi.driver/10412/u0 remote:434d4408}}:BR@430eb370


// broadcast this intent to 'RL{42cf82f0 10322 com.babytree.apps.pregnancy:pushservice/10408/u0 remote:42741340}}' this receiver, after 10sec timeout happened
10-30 18:17:52.169   669  1239 I BroadcastQueue: Deliver order [FG] BF{42cf8370 u0 RL{42cf82f0 10322 com.babytree.apps.pregnancy:pushservice/10408/u0 remote:42741340}}:BR@430eb370
...
10-30 18:18:02.179   669   768 W BroadcastQueue: Timeout of broadcast BroadcastRecord{430eb370 u-1 android.intent.action.SCREEN_ON callingPid=669 callingUid=1000} - receiver=android.os.BinderProxy@42741340

laisse

关注

2
点赞
踩
3

收藏

觉得还不错? 一键收藏
0
评论
Android ANR-Broadcast Timeout

DefinitionOrdered broadcastsIntents sent by Context.sendOrderedBroadcast() are broadcasted to one receiver at a time, regardless of if they are registered by Context.registerReceiver() or AndroidManif
复制链接

扫一扫

专栏目录