Android App에서 종종 ANR이 발생되어 원인분석을 했다.
증상
Receiver 에서 Broadcast 를 수신받지 못한 후 ANR 발생
adb logcat -v threadtime -b events
06-17 12:07:05.067 3800 3826 I am_broadcast_discard_app: [0,536238391,android.intent.action.PACKAGE_ADDED,7,ResolveInfo {45fc40d com.???.???/.packages.PackageReceiver m=0x208000}]
06-17 12:07:05.127 3800 3826 I am_proc_start: [0,28839,1000,com.!!!.!!!,broadcast,com.!!!.!!!/.receiver.AppInstallReceiver]
06-17 12:07:05.167 3800 3826 I am_anr : [0,0,com.???.???,8961605,Broadcast of Intent { act=android.intent.action.PACKAGE_ADDED dat=package:com.@@@.@@@ flg=0x4000010 (has extras) }]
/data/anr/traces.txt (ANR 이 발생되면 디바이스에 해당 파일이 생성된다.)
...
"ActivityManager" prio=5 tid=17 TimedWaiting
| group="main" sCount=1 dsCount=0 obj=0x131c3ba0 self=0x7fa70ba800
| sysTid=3826 nice=-2 cgrp=default sched=0/0 handle=0x7f9b52f900
| state=S schedstat=( 0 0 0 ) utm=779 stm=841 core=3 HZ=100
| stack=0x7f906e8000-0x7f906ea000 stackSize=1036KB
| held mutexes=
at java.lang.Object.wait!(Native method)
- waiting on <0x0d0c5110> (a com.android.server.am.ActivityManagerService$6)
at java.lang.Object.wait(Object.java:422)
at com.android.server.am.ActivityManagerService.dumpStackTraces(ActivityManagerService.java:7145)
- locked <0x0d0c5110> (a com.android.server.am.ActivityManagerService$6)
at com.android.server.am.ActivityManagerService.dumpStackTraces(ActivityManagerService.java:7122)
at com.android.server.am.ActivityManagerService.appNotResponding(ActivityManagerService.java:7373)
at com.android.server.am.BroadcastQueue$AppNotResponding.run(BroadcastQueue.java:217)
at android.os.Handler.handleCallback(Handler.java:739)
at android.os.Handler.dispatchMessage(Handler.java:95)
at android.os.Looper.loop(Looper.java:145)
at android.os.HandlerThread.run(HandlerThread.java:61)
at com.android.server.ServiceThread.run(ServiceThread.java:46)
...
https://android.googlesource.com/platform/frameworks/base/+/483f3b06ea84440a082e21b68ec2c2e54046f5a6/services/java/com/android/server/am/BroadcastQueue.java
final void broadcastTimeoutLocked(boolean fromMsg) {
if (fromMsg) {
mPendingBroadcastTimeoutMessage = false;
}
if (mOrderedBroadcasts.size() == 0) {
return;
}
long now = SystemClock.uptimeMillis();
BroadcastRecord r = mOrderedBroadcasts.get(0);
if (fromMsg) {
if (mService.mDidDexOpt) {
// Delay timeouts until dexopt finishes.
mService.mDidDexOpt = false;
long timeoutTime = SystemClock.uptimeMillis() + mTimeoutPeriod;
setBroadcastTimeoutLocked(timeoutTime);
return;
}
if (!mService.mProcessesReady) {
// Only process broadcast timeouts if the system is ready. That way
// PRE_BOOT_COMPLETED broadcasts can't timeout as they are intended
// to do heavy lifting for system up.
return;
}
long timeoutTime = r.receiverTime + mTimeoutPeriod;
if (timeoutTime > now) {
// We can observe premature timeouts because we do not cancel and reset the
// broadcast timeout message after each receiver finishes. Instead, we set up
// an initial timeout then kick it down the road a little further as needed
// when it expires.
if (DEBUG_BROADCAST) Slog.v(TAG,
"Premature timeout ["
+ mQueueName + "] @ " + now + ": resetting BROADCAST_TIMEOUT_MSG for "
+ timeoutTime);
setBroadcastTimeoutLocked(timeoutTime);
return;
}
}
Slog.w(TAG, "Timeout of broadcast " + r + " - receiver=" + r.receiver
+ ", started " + (now - r.receiverTime) + "ms ago");
r.receiverTime = now;
r.anrCount++;
// Current receiver has passed its expiration date.
if (r.nextReceiver <= 0) {
Slog.w(TAG, "Timeout on receiver with nextReceiver <= 0");
return;
}
ProcessRecord app = null;
String anrMessage = null;
Object curReceiver = r.receivers.get(r.nextReceiver-1);
Slog.w(TAG, "Receiver during timeout: " + curReceiver);
logBroadcastReceiverDiscardLocked(r);
if (curReceiver instanceof BroadcastFilter) {
BroadcastFilter bf = (BroadcastFilter)curReceiver;
if (bf.receiverList.pid != 0
&& bf.receiverList.pid != ActivityManagerService.MY_PID) {
synchronized (mService.mPidsSelfLocked) {
app = mService.mPidsSelfLocked.get(
bf.receiverList.pid);
}
}
} else {
app = r.curApp;
}
if (app != null) {
anrMessage = "Broadcast of " + r.intent.toString();
}
if (mPendingBroadcast == r) {
mPendingBroadcast = null;
}
// Move on to the next receiver.
finishReceiverLocked(r, r.resultCode, r.resultData,
r.resultExtras, r.resultAbort, true);
scheduleBroadcastsLocked();
if (anrMessage != null) {
// Post the ANR to the handler since we do not want to process ANRs while
// potentially holding our lock.
mHandler.post(new AppNotResponding(app, anrMessage));
}
}
am_broadcast_discard_app 이라는 로그는 Broadcast를 정상적으로 수신 할 수 없는 경우에 발생이 된다고 한다. (본문 하단의 추가내용 확인)
(
http://stackoverflow.com/questions/28675002/broadcast-receiver-being-discarded)
traces.txt 파일을 통해 ANR 원인에 대한 스택을 보면 BroadcastQueue$AppNotResponding Class 에서 ANR 관련 tracesFile 을 생성한다.
최초 BroadcastQueue Class의 broadcastTimeoutLocked Method 에서 AppNotResponding 을 수행시키는데 Broadcast 가 발생했음에도 시간내에 처리되지 않으면 ANR을 발생시키는 것으로 보인다.
위의 이슈로 인해 제조사에 문의를 했다.
제조사에서 온 답변은 다음과 같다.
(메일의 내용을 그대로 담을 수 없어 내용을 조금 수정했다.)
======================================
해당 App에서 App 다운로드시 백그라운드에서 다른 이름의 여러 패키지들이 연속적으로 다운로드 되어지면서, android.intent.action.PACKAGE_ADDED 가 너무 많이 전달됨에 따라 Broadcast처리에 로드가 걸려 안드로이드에서 발생시킨 ANR로 보입니다.
최근 프레임워크에서 관련하여 PACKAGE _ADDED Broadcast가 무분별하게 전달되지 않도록 하는 수정이 있었습니다. 이 수정이 반영된 이후의 바이너리에선 아직 재현된 이슈가 없습니다.
======================================
=============================
2015.07.12 내용 추가
2주 뒤에 위와 같은 이슈가 발생이 되어 android.intent.action.PACKAGE_ADDED 가 짧은 시간에 많이 발생이 되는경우 ANR이 발생되는 증상이 발생 되었다.
onReceive 메소드 내부의 로직을 확인결과 시간이 오래 걸릴 수 있는 로직이 발견되었다.
짧은 시간에 broadcast가 많이 발생 시 문제가 될 수 있기에 Thread 처리를 하여 수정을 했다.
이후 해당 문제로 ANR 발생되는 일이 아직 발생하지 않았다.
