2014. 5. 19. 20:33ㆍPrograming/Debugging
1. ANR이란?
Application Not Responding (ANR)의 줄임말로 어플리케이션이 일정시간 동안 응답이 없을 경우 발생하는 현상을 말합니다.
무한루프가 돌거나 UI 쓰레드에서 오래 걸리는 작업을 할 경우 발생하는 다이얼로그가 바로 ANR dialog입니다.
ANR이 발생하면 안드로이드 파일 시스템에 data/anr/ 위치에 traces.txt라는 ANR발생 시점의 프로세스 상태에 관한 로그가 기록됩니다.
이건 모든 안드로이드 폰 공통이지만 안타깝게도 루트권한에서만 접근이 가능합니다.
보통은 synchronized가 걸려서 독점하고 있거나 혹은 생각없이 sleep을 처리해서 발생할 가능성이 큽니다.
traces.txt에 held by라는 단어가 핵심포인트가 됩니다.
2. Thread 상태
A. java
NEW - 스레드가 생성되었지만 아직 실행되지 않은 상태
RUNNABLE - 현재 CPU를 점유하고 작업을 수행 중인 상태. 운영체제의 자원 분배로 인해 WAITING 상태가 될 수도 있다.
BLOCKED - Monitor를 획득하기 위해 다른 스레드가 락을 해제하기를 기다리는 상태
WAITING - wait() 메서드, join() 메서드, park() 메서드 등를 이용해 대기하고 있는 상태
TIMED_WAITING - sleep() 메서드, wait() 메서드, join() 메서드, park() 메서드 등을 이용해 대기하고 있는 상태.
B. 안드로이드
running - executing application code(실행중)
sleeping - called Thread.sleep()
monitor - waiting to acquire a monitor lock(다른 쓰레드가 작업을 마치기를 기다리는 중)
wait - in Object.wait()
native - executing native code
vmwait - waiting on a VM resource
zombie - thread is in the process of dying
init - thread is initializing (you shouldn't see this)
starting - thread is about to start (you shouldn't see this either)
3. Thread Method
sleep(long millis) : 지정된 밀리세컨드 동안 스레드를 쉬게함.
join(long millis) : 이스레드가 종료될 때까지 지정된 밀리세컨드 동안 대기한다.
yield() : 다른 스레드가 실행될 수 있도록 현재 스레드를 대기시킨다.
wait(long timeout) : notify(), 혹은 notifyAll() 메소드가 호출되거나 지정된 밀리세컨드 시간이 경과될때까지 대기한다.
notify() : 이 객체의 모니터상에서 기다리고 있는 하나의 스레드를 깨운다.
notifyAll() : 이 객체의 모니터상에서 기다리고 있는 모든 스레드를 깨운다.
4. Log 분석
Thread Name : 스레드의 고유 이름.
Priority : 스레드의 우선순위(Priority)
Thread ID: 스레드의 ID. 해당 정보를 이용해 스레드의 CPU 사용, 메모리 사용 등 유용한 정보를 얻을 수 있다.
Thread State: 스레드의 상태.
nice : 스레드 할당 시간.
Thread Call Stack: 스레드의 콜스택(Call Stack) 정보.
----- pid 1947 at 2014-05-12 10:16:11 -----
Cmd line: com.android.phone
JNI: CheckJNI is off; workarounds are off; pins=3; globals=478
DALVIK THREADS:
(mutexes: tll=0 tsl=0 tscl=0 ghl=0)
"main" prio=5 tid=1 MONITOR
| group="main" sCount=1 dsCount=0 obj=0x419f1e58 self=0x4190a908
| sysTid=1947 nice=0 sched=0/0 cgrp=apps handle=1074721108
| state=S schedstat=( 7162132792 15881334947 14355 ) utm=576 stm=140 core=1
at com.android.internal.telephony.IccPhoneBookInterfaceManager$1.handleMessage(IccPhoneBookInterfaceManager.java:~222)
- waiting to lock <0x422043a8> (a java.lang.Object) held by tid=31 (Binder_3)
at android.os.Handler.dispatchMessage(Handler.java:102)
at android.os.Looper.loop(Looper.java:136)
at android.app.ActivityThread.main(ActivityThread.java:5103)
at java.lang.reflect.Method.invokeNative(Native Method)
at java.lang.reflect.Method.invoke(Method.java:515)
at com.android.internal.os.ZygoteInit$MethodAndArgsCaller.run(ZygoteInit.java:789)
at com.android.internal.os.ZygoteInit.main(ZygoteInit.java:605)
at dalvik.system.NativeStart.main(Native Method)
5. 예제
Dalvik Threads Dump를 확인해 보면,
Main Group가 MONITOR로 다른 Thread가 작업을 마치기를 기다리고 있는 상태임을 확인 할 수 있습니다.
"held by tid=31 (Binder_3)"를 통해 작업이 진행이 되고 있는 Thread가 Binder_3 임을 알 수 있습니다.
"main" prio=5 tid=1 MONITOR
| group="main" sCount=1 dsCount=0 obj=0x419f1e58 self=0x4190a908
| sysTid=1947 nice=0 sched=0/0 cgrp=apps handle=1074721108
| state=S schedstat=( 7162132792 15881334947 14355 ) utm=576 stm=140 core=1
at com.android.internal.telephony.IccPhoneBookInterfaceManager$1.handleMessage(IccPhoneBookInterfaceManager.java:~222)
- waiting to lock <0x422043a8> (a java.lang.Object) held by tid=31 (Binder_3)
at android.os.Handler.dispatchMessage(Handler.java:102)
at android.os.Looper.loop(Looper.java:136)
at android.app.ActivityThread.main(ActivityThread.java:5103)
at java.lang.reflect.Method.invokeNative(Native Method)
at java.lang.reflect.Method.invoke(Method.java:515)
at com.android.internal.os.ZygoteInit$MethodAndArgsCaller.run(ZygoteInit.java:789)
at com.android.internal.os.ZygoteInit.main(ZygoteInit.java:605)
at dalvik.system.NativeStart.main(Native Method)
Thread ID 31인 Binder_3로 가보니, readRecordSize의 wait() 부분이 문제가 되는 것을 알 수 있습니다.
"Binder_3" prio=5 tid=31 WAIT
| group="main" sCount=1 dsCount=0 obj=0x422aed20 self=0x57765c38
| sysTid=2307 nice=0 sched=0/0 cgrp=apps handle=1467347920
| state=S schedstat=( 185606198 603088469 908 ) utm=9 stm=9 core=1
at java.lang.Object.wait(Native Method)
- waiting on <0x420f6e38> (a java.lang.Object)
at java.lang.Object.wait(Object.java:364)
at com.android.internal.telephony.gsm.UsimPhoneBookManager.readRecordSize(UsimPhoneBookManager.java:927)
at com.android.internal.telephony.gsm.UsimPhoneBookManager.loadEfFilesFromUsim(UsimPhoneBookManager.java:269)
at com.android.internal.telephony.uicc.AdnRecordCache.requestLoadAllAdnLike(AdnRecordCache.java:529)
at com.android.internal.telephony.IccPhoneBookInterfaceManager.getAdnRecordsInEf(IccPhoneBookInterfaceManager.java:693)
at com.android.internal.telephony.IccPhoneBookInterfaceManagerProxy.getAdnRecordsInEf(IccPhoneBookInterfaceManagerProxy.java:192)
at com.android.internal.telephony.IccProvider.loadFromEf(IccProvider.java:689)
at com.android.internal.telephony.IccProvider.query(IccProvider.java:231)
at android.content.ContentProvider.query(ContentProvider.java:904)
at android.content.ContentProvider$Transport.query(ContentProvider.java:234)
at android.content.ContentProviderNative.onTransact(ContentProviderNative.java:112)
at android.os.Binder.execTransact(Binder.java:407)
at dalvik.system.NativeStart.run(Native Method)