Translate

2015년 7월 5일 일요일

[Android] BroadcastReceiver 의 am_broadcast_discard_app 이슈



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 발생되는 일이 아직 발생하지 않았다.


댓글 없음 :

댓글 쓰기