안드로이드 개발을 하다보면 간단히 Stacktrace로 버그를 찾아내어 수정할 수 있는 경우도 많지만, 알 수 없는 문제로 고생하는 경우도 많다. 그럴 경우 다양한 경로로 해당 원인을 분석하기 위해 노력해야 하는데, 그러한 노력의 일환으로 dumpstate 로그를 추출하여 확인하는 것이 있다. 공식적인 명칭으로는 버그리포트 혹은 버그신고 로그라고 한다.
일반적인 개발 용어로는 덤프로그가 조금 더 익숙하여 이 포스팅에서는 이렇게 용어를 기록하였다.
로그 추출하기
당연하겠지만, 우선 디바이스를 디버깅 연결한다. 그러면 아래와 같이 기기가 잘 연결되어 있을 것이다.(아래와 같은 경우는 무선디버깅으로 연결할 경우 나오는 내용이다.)
그리고 다음과 같이 커맨드 명령을 입력해준다. 그렇게하면 현 시점 기준으로 버그리포트를 위한 파일이, 입력한 이름의 zip 파일로 생성된다. 생성되는데 걸리는 시간은 고사양폰 기준으로 보더라도 약 3분정도는 걸리는 것 같다.
adb bugreport [파일이름]
나오는 파일의 구성은 대략 아래와 같으며, 특징으로는 메인이 되는 로그파일을 보면 용량이 수십메가 이상은 된다는 점이다.
위에서 bugreport-* 형식으로 되어있는 파일을 선택하면 되며, Android OS 버전에 따라서는 파일 이름이 다른 형식으로 나올 수 있지만, 용량이 수십메가쯤 되는 파일을 선택하면, 내부에는 비슷한 내용으로 구성되어 있을 것이기 때문에 어렵지 않게 찾을 수 있을 것이다.
로그 읽기
해당 파일을 Visual Studio Code와 같이 텍스트 에디터로 열면 된다.
이 문서에서 모든 부분을 언급할 수는 없겠지만, 참고가 될만한 부분을 기록하자면 다음과 같다.
시스템 로그
logcat 로그는 모든 logcat 정보의 문자열 기반 덤프이다. system 부분은 프레임워크를 위해 예약되었으며, 다른 모든 부분을 포함하는 main보다 더 긴 기록을 갖는다. 각 행은 일반적으로
timestamp UID PID TID log-level TAG text순으로 되어있지만, 버전에 따라서는 UID가 없을 수도 있다.
아래의 예시의 내용에서처럼 'SYSTEM LOG'를 키워드로 검색하면 바로 쉽게 찾을 수 있다. 혹은 system과 main 파트를 찾고 싶다면, 해당 부분도 마찬가지로 각각 beginning of system과 beginning of main으로 검색하면 된다.
------ SYSTEM LOG (logcat -v threadtime -d *:v) ------
--------- beginning of system
Blah
Blah
Blah
--------- beginning of main
Blah
Blah
Blah
이벤트 로그
이벤트로그는 바이너리 형식 로그 메시지의 문자열 표현이 포함될 수 있다. 이 로그는 logcat 로그보다 노이즈는 적지만 더 읽기가 어려울 수 있다. 기본형식은
timestamp PID TID log-level log-tag tag-values처럼 되어 있다. (V: 상세, D: 디버그, I: 정보, W: 경고, E: 에러)
아래는 그 예시이며, 동일하게 EVENT LOG를 키워드로 찾기 쉽다.
------ EVENT LOG (logcat -b events -v threadtime -d *:v) ------
09-28 13:47:34.179 785 5113 I am_proc_bound: [0,23054,com.google.android.gms.unstable]
09-28 13:47:34.777 785 1975 I am_proc_start: [0,23134,10032,com.android.chrome,broadcast,com.android.chrome/org.chromium.chrome.browser.precache.PrecacheServiceLauncher]
09-28 13:47:34.806 785 2764 I am_proc_bound: [0,23134,com.android.chrome]
...ANR(Application Not Responding) 찾기
일반적으로 차단되었거나 사용량이 많은 기본 쓰레드로 인해 앱이 특정 시간내에 응답하지 않는다면, 시스템은 프로세스를 종료하고 스택을 /data/anr로 덤프한다. am_anr을 검색하면 찾을 수 있다. 다만, 이 로그는 모든 경우에 찾을 수 있는 것은 아니기 때문에 해당되는 경우가 아니라면 없을 수 있다. 아래는 나올 경우 예시이다.
grep "am_anr" bugreport-2015-10-01-18-13-48.txt
10-01 18:12:49.599 4600 4614 I am_anr : [0,29761,com.google.android.youtube,953695941,executing service com.google.android.youtube/com.google.android.apps.youtube.app.offline.transfer.OfflineTransferService]
10-01 18:14:10.211 4600 4614 I am_anr : [0,30363,com.google.android.apps.plus,953728580,executing service com.google.android.apps.plus/com.google.android.apps.photos.service.PhotosService]
ANR이 검색되었고, 해당되는 경우라면 아래와 같이 CPU를 사용하고 있는 것들에 대한 정보를 추가로 찾을 수 있다.
grep "ANR in" bugreport-2015-10-01-18-13-48.txt
10-01 18:13:11.984 4600 4614 E ActivityManager: ANR in com.google.android.youtube
10-01 18:14:31.720 4600 4614 E ActivityManager: ANR in com.google.android.apps.plus
10-01 18:14:31.720 4600 4614 E ActivityManager: PID: 30363
10-01 18:14:31.720 4600 4614 E ActivityManager: Reason: executing service com.google.android.apps.plus/com.google.android.apps.photos.service.PhotosService
10-01 18:14:31.720 4600 4614 E ActivityManager: Load: 35.27 / 23.9 / 16.18
10-01 18:14:31.720 4600 4614 E ActivityManager: CPU usage from 16ms to 21868ms later:
10-01 18:14:31.720 4600 4614 E ActivityManager: 74% 3361/mm-qcamera-daemon: 62% user + 12% kernel / faults: 15276 minor 10 major
10-01 18:14:31.720 4600 4614 E ActivityManager: 41% 4600/system_server: 18% user + 23% kernel / faults: 18597 minor 309 major
10-01 18:14:31.720 4600 4614 E ActivityManager: 32% 27420/com.google.android.GoogleCamera: 24% user + 7.8% kernel / faults: 48374 minor 338 major
10-01 18:14:31.720 4600 4614 E ActivityManager: 16% 130/kswapd0: 0% user + 16% kernel
10-01 18:14:31.720 4600 4614 E ActivityManager: 15% 283/mmcqd/0: 0% user + 15% kernel
...
10-01 18:14:31.720 4600 4614 E ActivityManager: 0.1% 27248/irq/503-synapti: 0%
10-01 18:14:31.721 4600 4614 I ActivityManager: Killing 30363:com.google.android.apps.plus/u0a206 (adj 0): bg anr
만약 나오지 않을 경우 아래와 같은 내용이 포함되어 있을 수 있다.
------ 0.025s was the duration of 'VM TRACES JUST NOW' ------
*** NO ANRs to dump in /data/anr/
종종 ANR에 대응하는 stacktrace를 찾을 수도 있다. VM 트레이스에서 timestamp와 조사중인 ANR사이에 PID가 일치하는지 확인 한 후, 프로세스의 기본 쓰레드를 확인한다. 참고로 기본쓰레드는 ANR 발생시에 실행하고 있던 작업만 알려주는 것이므로 이는 ANR의 실제 원인일수도 있으며, 아닐 수도 있다. 또한 2개 이상의 stacktrace 세트가 있을 수 있으니 현재 보고있는 섹션이 맞는지 확인을 잘 해야 한다. 나온다면 아래와 같을 것이다.
------ VM TRACES AT LAST ANR (/data/anr/traces.txt: 2015-10-01 18:14:41) ------
----- pid 30363 at 2015-10-01 18:14:11 -----
Cmd line: com.google.android.apps.plus
Build fingerprint: 'google/angler/angler:6.0/MDA89D/2294819:userdebug/dev-keys'
ABI: 'arm'
Build type: optimized
Zygote loaded classes=3978 post zygote classes=27
Intern table: 45068 strong; 21 weak
JNI: CheckJNI is off; globals=283 (plus 360 weak)
Libraries: /system/lib/libandroid.so /system/lib/libcompiler_rt.so /system/lib/libjavacrypto.so /system/lib/libjnigraphics.so /system/lib/libmedia_jni.so /system/lib/libwebviewchromium_loader.so libjavacore.so (7)
Heap: 29% free, 21MB/30MB; 32251 objects
Dumping cumulative Gc timings
Total number of allocations 32251
Total bytes allocated 21MB
Total bytes freed 0B
....
....
"main" prio=5 tid=1 Suspended
| group="main" sCount=1 dsCount=0 obj=0x747552a0 self=0xf5376500
| sysTid=30363 nice=0 cgrp=default sched=0/0 handle=0xf74feb34
| state=S schedstat=( 331107086 164153349 851 ) utm=6 stm=27 core=3 HZ=100
| stack=0xff00f000-0xff011000 stackSize=8MB
| held mutexes=
kernel: __switch_to+0x7c/0x88
kernel: futex_wait_queue_me+0xd4/0x130
kernel: futex_wait+0xf0/0x1f4
kernel: do_futex+0xcc/0x8f4
kernel: compat_SyS_futex+0xd0/0x14c
kernel: cpu_switch_to+0x48/0x4c
native: #00 pc 000175e8 /system/lib/libc.so (syscall+28)
native: #01 pc 000f5ced /system/lib/libart.so (art::ConditionVariable::Wait(art::Thread*)+80)
native: #02 pc 00335353 /system/lib/libart.so (art::Thread::FullSuspendCheck()+838)
native: #03 pc 0011d3a7 /system/lib/libart.so (art::ClassLinker::LoadClassMembers(art::Thread*, art::DexFile const&, unsigned char const*, art::Handle<art::mirror::Class>, art::OatFile::OatClass const*)+746)
native: #04 pc 0011d81d /system/lib/libart.so (art::ClassLinker::LoadClass(art::Thread*, art::DexFile const&, art::DexFile::ClassDef const&, art::Handle<art::mirror::Class>)+88)
native: #05 pc 00132059 /system/lib/libart.so (art::ClassLinker::DefineClass(art::Thread*, char const*, unsigned int, art::Handle<art::mirror::ClassLoader>, art::DexFile const&, art::DexFile::ClassDef const&)+320)
native: #06 pc 001326c1 /system/lib/libart.so (art::ClassLinker::FindClassInPathClassLoader(art::ScopedObjectAccessAlreadyRunnable&, art::Thread*, char const*, unsigned int, art::Handle<art::mirror::ClassLoader>, art::mirror::Class**)+688)
native: #07 pc 002cb1a1 /system/lib/libart.so (art::VMClassLoader_findLoadedClass(_JNIEnv*, _jclass*, _jobject*, _jstring*)+264)
native: #08 pc 002847fd /data/dalvik-cache/arm/system@framework@boot.oat (Java_java_lang_VMClassLoader_findLoadedClass__Ljava_lang_ClassLoader_2Ljava_lang_String_2+112)
at java.lang.VMClassLoader.findLoadedClass!(Native method)
at java.lang.ClassLoader.findLoadedClass(ClassLoader.java:362)
참고로 교착상태 발생시에는 다음과 같은 로그가 나올 수 있다. 다음 로그의 특징으로는 Blocked로 기록된 부분과, waiting to lock 혹은 locked라고 표현된 부분들이다.
"Binder_B" prio=5 tid=73 Blocked
| group="main" sCount=1 dsCount=0 obj=0x13faa0a0 self=0x95e24800
| sysTid=2016 nice=0 cgrp=default sched=0/0 handle=0x8b68d930
| state=S schedstat=( 9351576559 4141431119 16920 ) utm=819 stm=116 core=1 HZ=100
| stack=0x8b591000-0x8b593000 stackSize=1014KB
| held mutexes=
at com.android.server.pm.UserManagerService.exists(UserManagerService.java:387)
- waiting to lock <0x025f9b02> (a android.util.ArrayMap) held by thread 20
at com.android.server.pm.PackageManagerService.getApplicationInfo(PackageManagerService.java:2848)
at com.android.server.AppOpsService.getOpsRawLocked(AppOpsService.java:881)
at com.android.server.AppOpsService.getOpsLocked(AppOpsService.java:856)
at com.android.server.AppOpsService.noteOperationUnchecked(AppOpsService.java:719)
- locked <0x0231885a> (a com.android.server.AppOpsService)
at com.android.server.AppOpsService.noteOperation(AppOpsService.java:713)
at com.android.server.AppOpsService$2.getMountMode(AppOpsService.java:260)
at com.android.server.MountService$MountServiceInternalImpl.getExternalStorageMountMode(MountService.java:3416)
at com.android.server.am.ActivityManagerService.startProcessLocked(ActivityManagerService.java:3228)
Activity 찾기
집중이 된 Activity를 찾고 싶다면 'am_focused_activity'를 검색한다.
또한 프로세스의 시작을 찾고싶다면, 'Start proc'을 찾으면 된다.
또한 기기가 쓰래싱(메모리 접근시 페이지 폴트 발생으로 CPU 이용률이 급격히 낮아지는 현상)이 발생하는 지 알아보려면 'am_proc_died'와 'am_proc_start' 주변에서 Activity가 비정상적으로 증가했는지 확인해보는것이 좋다. 아래와 같은 것이 예시가 될 것이다.
grep -e "am_proc_died" -e "am_proc_start" bugreport-2015-10-01-18-13-48.txt
10-01 18:07:06.494 4600 9696 I am_proc_died: [0,20074,com.android.musicfx]
10-01 18:07:06.555 4600 6606 I am_proc_died: [0,31166,com.concur.breeze]
10-01 18:07:06.566 4600 14112 I am_proc_died: [0,18812,com.google.android.apps.fitness]
10-01 18:07:07.018 4600 7513 I am_proc_start: [0,20361,10113,com.sony.playmemories.mobile,broadcast,com.sony.playmemories.mobile/.service.StartupReceiver]
10-01 18:07:07.357 4600 4614 I am_proc_start: [0,20381,10056,com.google.android.talk,service,com.google.android.talk/com.google.android.libraries.hangouts.video.CallService]
10-01 18:07:07.784 4600 4612 I am_proc_start: [0,20402,10190,com.andcreate.app.trafficmonitor:loopback_measure_serivce,service,com.andcreate.app.trafficmonitor/.loopback.LoopbackMeasureService]
10-01 18:07:10.753 4600 5997 I am_proc_start: [0,20450,10097,com.amazon.mShop.android.shopping,broadcast,com.amazon.mShop.android.shopping/com.amazon.identity.auth.device.storage.LambortishClock$ChangeTimestampsBroadcastReceiver]
메모리 관련 찾기
물리적 메모리가 제한적인 경우가 많으므로, RAM 관리가 매우 중요하다. 일단 메모리 부족을 식별하기 위해서는 앞에서 언급했던 내용처럼 'am_proc_died와 'am_proc_start' 항목이 얼마나 몰려있는지 확인하면 된다.
바이너리 이벤트 로그의 'am_low_memory' 항목은 마지막으로 캐시된 프로세스가 종료되었다는 의미이다. 그래서 이것이 발생되면, 이후에는 아래의 예시처럼 시스템이 서비스를 종료하기 시작한다.
grep "am_low_memory" bugreport-2015-10-01-18-13-48.txt
10-01 18:11:02.219 4600 7513 I am_low_memory: 41
10-01 18:12:18.526 4600 14112 I am_low_memory: 39
10-01 18:12:18.874 4600 7514 I am_low_memory: 38
10-01 18:12:22.570 4600 14112 I am_low_memory: 40
10-01 18:12:34.811 4600 20319 I am_low_memory: 43
쓰래싱 지표를 보기 위해서는 먼저 'CPU INFO' 항목을 찾는다. 이곳에서 'kswapd', 'kworker', 'mmcqd' 소비 주기가 있다. 이러한 부분들이 쓰래싱 지표에 영향을 미칠 수 있다.
------ CPU INFO (top -b -n 1 -H -s 6 -o pid,tid,user,pr,ni,%cpu,s,virt,res,pcy,cmd,name) ------
Threads: 3856 total, 1 running, 3855 sleeping, 0 stopped, 0 zombie
Mem: 3665264K total, 3558544K used, 106720K free, 1888256 buffers
Swap: 2097148K total, 988104K used, 1109044K free, 1049220K cached
800%cpu 22%user 0%nice 79%sys 693%idle 0%iow 3%irq 2%sirq 0%host
PID TID USER PR NI[%CPU]S VIRT RES PCY CMD NAME
13618 13618 shell 0 -20 62.0 R 10G 5.3M fg top top
53 53 root 20 0 13.7 S 0 0 fg rcuop/5 [rcuop/5]
145 145 root 20 0 8.6 S 0 0 fg kswapd0 [kswapd0]
8962 8962 u0_a80 20 0 3.4 S 15G 144M bg oid.apps.photos com.google.android.apps.photos
1543 1833 system 20 0 3.4 S 16G 344M fg WifiHandlerThre system_server
11782 11782 root 20 0 1.7 S 0 0 fg kworker/5:0 [kworker/5:0]
7576 7576 root 20 0 1.7 S 0 0 fg kworker/u16:16 [kworker/u16:16]
2332 8144 radio 20 0 1.7 S 14G 60M fg Binder:2332_E com.android.phone
ANR로그에서도 마찬가지로 유사항 스냅샷을 제공하기도 한다. 아래는 그 예시이다.
10-03 17:19:59.959 1963 1976 E ActivityManager: ANR in com.google.android.apps.magazines
10-03 17:19:59.959 1963 1976 E ActivityManager: PID: 18819
10-03 17:19:59.959 1963 1976 E ActivityManager: Reason: Broadcast of Intent { act=android.net.conn.CONNECTIVITY_CHANGE flg=0x4000010 cmp=com.google.android.apps.magazines/com.google.apps.dots.android.newsstand.appwidget.NewsWidgetProvider (has extras) }
10-03 17:19:59.959 1963 1976 E ActivityManager: Load: 19.19 / 14.76 / 12.03
10-03 17:19:59.959 1963 1976 E ActivityManager: CPU usage from 0ms to 11463ms later:
10-03 17:19:59.959 1963 1976 E ActivityManager: 54% 15229/kworker/0:2: 0% user + 54% kernel
10-03 17:19:59.959 1963 1976 E ActivityManager: 38% 1963/system_server: 14% user + 23% kernel / faults: 17152 minor 1073 major
10-03 17:19:59.959 1963 1976 E ActivityManager: 11% 120/mmcqd/1: 0% user + 11% kernel
10-03 17:19:59.959 1963 1976 E ActivityManager: 10% 2737/com.android.systemui: 4.7% user + 5.6% kernel / faults: 7211 minor 149 major
10-03 17:19:59.959 1963 1976 E ActivityManager: 0.2% 1451/debuggerd: 0% user + 0.2% kernel / faults: 15211 minor 147 major
10-03 17:19:59.959 1963 1976 E ActivityManager: 8.7% 6162/com.twofortyfouram.locale: 4% user + 4.7% kernel / faults: 4924 minor 260 major
10
메모리 스냅샷은 'Total PSS by OOM adjustment' 키워드로 찾을 수 있다. 메모리 관련 이슈가 있을 경우에도 유용할 것이니 이 경우 잘 체크해두면 좋다. 이 경우의 예시는 아래와 같다.
Total PSS by OOM adjustment:
431,259K: Native ( 234,451K in swap)
91,045K: surfaceflinger (pid 708) ( 6,816K in swap)
23,345K: android.hardware.camera.provider@2.4-service_64 (pid 1018) ( 22,968K in swap)
22,548K: zygote64 (pid 1000) ( 19,257K in swap)
19,873K: statsd (pid 999) ( 4,176K in swap)
17,325K: webview_zygote (pid 2129) ( 16,988K in swap)
15,500K: zygote (pid 1001) ( 13,706K in swap)
13,595K: android.hardware.neuralnetworks@1.3-service-qti (pid 1030) ( 13,140K in swap)
12,629K: vendor.google.wifi_ext@1.0-service-vendor (pid 1054) ( 760K in swap)
12,092K: android.hardware.graphics.composer@2.3-service (pid 711) ( 9,360K in swap)
......
230,472K: System ( 13,416K in swap)
230,472K: system (pid 1543) ( 13,416K in swap)
305,654K: Persistent ( 95,467K in swap)
150,911K: com.android.systemui (pid 2007) ( 26,589K in swap)
38,804K: com.android.phone (pid 2332) ( 14,817K in swap)
27,076K: .dataservices (pid 2253) ( 20,123K in swap)
20,836K: com.android.networkstack.process (pid 2216) ( 9,492K in swap)
......
1,077,948K: Cached ( 427,776K in swap)
158,075K: com.google.android.apps.photos (pid 8962 / activities) ( 80,550K in swap)
117,726K: com.google.android.googlequicksearchbox:search (pid 22446) ( 44,295K in swap)
64,743K: com.android.chrome (pid 26348) ( 25,630K in swap)
60,803K: com.google.android.apps.youtube.music (pid 11588) ( 2,805K in swap)
58,289K: com.google.android.gm (pid 27354) ( 11,327K in swap)이 정보로 현재 메모리 상태를 파악하는 데 도움이 될 것이다.
- 프로세스가 얼마나 오랫동안 실행하는지 이해하거나
- 프로세스가 현재 실행되고 있는 이유를 이해하기 위해서는
다른 부분의 섹션을 추가로 참고해야 하는데, 해당 부분은 다음 포스팅에 기록할 예정이다.
출처
- 버그 신고캡처 및 읽기: https://developer.android.com/studio/debug/bug-report?hl=ko
- 버그신고 읽기: https://source.android.com/setup/contribute/read-bug-reports?hl=ko#anrs-deadlocks
'[Developer] > Android' 카테고리의 다른 글
| Android Studio 2020.3.1 Arctic Fox Stable 업데이트 정리 (0) | 2021.07.31 |
|---|---|
| Android Dumpstate 로그 추출 및 분석(2/2) (0) | 2021.07.13 |
| [개발 팁] adb 디버깅 무선 연결하기 - Android 11 이상 (6) | 2021.04.26 |
| [번역] 단위테스트를 위한 안드로이드 모의 서버 (0) | 2020.07.27 |
| Android Studio 3.5 주요 변화점 (0) | 2019.08.21 |
댓글