ANR 로그 분석 방법 - /data/anr/traces.txt

ANR 로그 분석 방법 - /data/anr/traces.txt 

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)