버그는 모든 개발 유형에서 발생하기 마련이며 버그 신고는 문제를 식별하고 해결하는 데 있어 매우 중요합니다. 모든 Android 버전은 Android 디버그 브리지(adb)를 통한 버그 신고 캡처를 지원합니다. Android 버전 4.2 이상에서는 이메일, 드라이브 등을 통해 버그 신고를 접수하고 공유할 수 있는 개발자 옵션을 지원합니다.
Android 버그 신고에는 dumpsys, dumpstate 및 logcat 데이터가 텍스트(.txt) 형식으로 포함되어 특정 콘텐츠를 쉽게 검색할 수 있습니다. 다음 섹션에서는 버그 신고 구성요소와 일반적인 문제를 자세히 설명하며 버그와 연결된 로그를 찾는 데 필요한 유용한 팁과 grep 명령어를 제공합니다. 대부분의 섹션에는 grep 명령어와 출력 및 dumpsys 출력의 예도 포함됩니다.
Logcat
logcat 로그는 모든 logcat 정보의 문자열 기반 덤프입니다. system 부분은 프레임워크를 위해 예약되었으며 다른 모든 부분을 포함하는 main보다 더 긴 기록을 갖습니다.
각 행은 일반적으로 timestamp UID PID TID log-level로 시작하지만 Android의 이전 버전에서는 UID가 없을 수도 있습니다.
예시 보기
------ SYSTEM LOG (logcat -v threadtime -d *:v) ------
--------- beginning of system
Blah
Blah
Blah
--------- beginning of main
Blah
Blah
Blah
이벤트 로그 보기
이 로그에는 바이너리 형식 로그 메시지의 문자열 표현이 포함됩니다. 이 로그는 logcat 로그보다 노이즈는 적지만 읽기가 더 어렵습니다.
이벤트 로그를 볼 때는 이 섹션에서 구체적인 처리 ID(PID)를 검색하여 프로세스가 무슨 작업을 실행하고 있었는지 확인할 수 있습니다. 기본 형식은 timestamp PID TID log-level log-tag tag-values입니다.
로그 수준에는 다음이 포함됩니다.
- V: 상세 출력
- D: 디버그
- I: 정보
- W: 경고
- E: 오류
예시 보기
------ 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]
...
기타 유용한 이벤트 로그 태그는 /services/core/java/com/android/server/EventLogTags.logtags를 참고하세요.
ANR 및 교착
버그 신고는 애플리케이션 응답 없음(ANR) 및 교착 이벤트의 원인을 식별할 수 있게 도와줍니다.
응답하지 않는 앱 식별
일반적으로 차단되었거나 사용량이 많은 기본 스레드로 인해 애플리케이션이 특정 시간 내에 응답하지 않는다면 시스템은 프로세스를 종료하고 스택을 /data/anr로 덤프합니다. ANR의 원인을 찾으려면 바이너리 이벤트 로그에서 grep 명령어를 사용하여 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를 사용하고 있던 주체에 관한 추가 정보가 포함된 logcat 로그에서 grep 명령어를 사용하여 ANR in을 검색할 수도 있습니다.
예시 보기
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
스택 트레이스 찾기
종종 ANR에 대응하는 스택 트레이스를 찾을 수 있습니다. VM 트레이스에서 타임스탬프와 PID가 조사 중인 ANR과 일치하는지 확인한 후 프로세스의 기본 스레드를 확인합니다. 이때 다음 사항을 유의하세요.
- 기본 스레드는 ANR 발생 시 스레드에서 실행하고 있던 작업만 알려주며 이는 ANR의 실제 원인일 수도 있고 아닐 수도 있습니다. (버그 신고의 스택이 원인이 아닐 수 있습니다. 다른 부분이 ANR을 일으킬 만큼 긴 시간은 아니더라도 장시간 중단되었다가 다시 작동했을 수 있습니다.)
- 2개 이상의 스택 트레이스 세트(
VM TRACES JUST NOW 및 VM TRACES AT LAST ANR)가 존재할 수 있습니다. 올바른 섹션을 보고 있는지 확인하세요.
예시 보기
------ 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
Free memory 9MB
Free memory until GC 9MB
Free memory until OOME 490MB
Total memory 30MB
Max memory 512MB
Zygote space size 1260KB
Total mutator paused time: 0
Total time waiting for GC to complete: 0
Total GC count: 0
Total GC time: 0
Total blocking GC count: 0
Total blocking GC time: 0
suspend all histogram: Sum: 119.728ms 99% C.I. 0.010ms-107.765ms Avg: 5.442ms Max: 119.562ms
DALVIK THREADS (12):
"Signal Catcher" daemon prio=5 tid=2 Runnable
| group="system" sCount=0 dsCount=0 obj=0x12c400a0 self=0xef460000
| sysTid=30368 nice=0 cgrp=default sched=0/0 handle=0xf4a69930
| state=R schedstat=( 9021773 5500523 26 ) utm=0 stm=0 core=1 HZ=100
| stack=0xf496d000-0xf496f000 stackSize=1014KB
| held mutexes= "mutator lock"(shared held)
native: #00 pc 0035a217 /system/lib/libart.so (art::DumpNativeStack(std::__1::basic_ostream<char, std::__1::char_traits<char> >&, int, char const*, art::ArtMethod*, void*)+126)
native: #01 pc 0033b03b /system/lib/libart.so (art::Thread::Dump(std::__1::basic_ostream<char, std::__1::char_traits<char> >&) const+138)
native: #02 pc 00344701 /system/lib/libart.so (art::DumpCheckpoint::Run(art::Thread*)+424)
native: #03 pc 00345265 /system/lib/libart.so (art::ThreadList::RunCheckpoint(art::Closure*)+200)
native: #04 pc 00345769 /system/lib/libart.so (art::ThreadList::Dump(std::__1::basic_ostream<char, std::__1::char_traits<char> >&)+124)
native: #05 pc 00345e51 /system/lib/libart.so (art::ThreadList::DumpForSigQuit(std::__1::basic_ostream<char, std::__1::char_traits<char> >&)+312)
native: #06 pc 0031f829 /system/lib/libart.so (art::Runtime::DumpForSigQuit(std::__1::basic_ostream<char, std::__1::char_traits<char> >&)+68)
native: #07 pc 00326831 /system/lib/libart.so (art::SignalCatcher::HandleSigQuit()+896)
native: #08 pc 003270a1 /system/lib/libart.so (art::SignalCatcher::Run(void*)+324)
native: #09 pc 0003f813 /system/lib/libc.so (__pthread_start(void*)+30)
native: #10 pc 00019f75 /system/lib/libc.so (__start_thread+6)
(no managed stack frames)
"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)
at java.lang.ClassLoader.loadClass(ClassLoader.java:499)
at java.lang.ClassLoader.loadClass(ClassLoader.java:469)
at android.app.ActivityThread.installProvider(ActivityThread.java:5141)
at android.app.ActivityThread.installContentProviders(ActivityThread.java:4748)
at android.app.ActivityThread.handleBindApplication(ActivityThread.java:4688)
at android.app.ActivityThread.-wrap1(ActivityThread.java:-1)
at android.app.ActivityThread$H.handleMessage(ActivityThread.java:1405)
at android.os.Handler.dispatchMessage(Handler.java:102)
at android.os.Looper.loop(Looper.java:148)
at android.app.ActivityThread.main(ActivityThread.java:5417)
at java.lang.reflect.Method.invoke!(Native method)
at com.android.internal.os.ZygoteInit$MethodAndArgsCaller.run(ZygoteInit.java:726)
at com.android.internal.os.ZygoteInit.main(ZygoteInit.java:616)
...
Stacks for other threads in this process follow
...
교착 상태 찾기
교착은 ANR로 먼저 표시될 때가 많으며 이는 스레드가 멈추고 있기 때문입니다. 시스템 서버에서 교착 상태가 발생하면 워치독은 결국 서버를 종료하며 로그에 WATCHDOG KILLING SYSTEM PROCESS와 유사한 항목이 기재됩니다. 사용자 관점에서는 기기 재부팅이지만 기술적으로 이는 실제 재부팅이 아닌 런타임 재시작입니다.
- 런타임 재시작에서는 시스템 서버가 종료되었다가 다시 시작됩니다. 사용자에게는 기기가 부팅 애니메이션으로 돌아오는 모습이 표시됩니다.
- 재부팅은 커널이 비정상 종료되었을 때 일어납니다. 사용자에게는 기기가 Google 부팅 로고로 돌아오는 모습이 표시됩니다.
교착 상태를 찾으려면 스레드 B에서 가지고 있는 무언가를 기다리고 있는 스레드 A의 패턴이 VM 트레이스 섹션에 있는지 확인합니다. 순차적으로 스레드 B도 스레드 A가 가지고 있는 무언가를 기다리고 있습니다.
예시 보기
"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)
at com.android.server.am.ActivityManagerService.startProcessLocked(ActivityManagerService.java:3170)
at com.android.server.am.ActivityManagerService.startProcessLocked(ActivityManagerService.java:3059)
at com.android.server.am.BroadcastQueue.processNextBroadcast(BroadcastQueue.java:1070)
- locked <0x044d166f> (a com.android.server.am.ActivityManagerService)
at com.android.server.am.ActivityManagerService.finishReceiver(ActivityManagerService.java:16950)
at android.app.ActivityManagerNative.onTransact(ActivityManagerNative.java:494)
at com.android.server.am.ActivityManagerService.onTransact(ActivityManagerService.java:2432)
at android.os.Binder.execTransact(Binder.java:453)
...
"PackageManager" prio=5 tid=20 Blocked
| group="main" sCount=1 dsCount=0 obj=0x1304f4a0 self=0xa7f43900
| sysTid=1300 nice=10 cgrp=bg_non_interactive sched=0/0 handle=0x9fcf9930
| state=S schedstat=( 26190141996 13612154802 44357 ) utm=2410 stm=209 core=2 HZ=100
| stack=0x9fbf7000-0x9fbf9000 stackSize=1038KB
| held mutexes=
at com.android.server.AppOpsService.noteOperationUnchecked(AppOpsService.java:718)
- waiting to lock <0x0231885a> (a com.android.server.AppOpsService) held by thread 73
at com.android.server.AppOpsService.noteOperation(AppOpsService.java:713)
at com.android.server.AppOpsService$2.getMountMode(AppOpsService.java:260)
at com.android.server.AppOpsService$2.hasExternalStorage(AppOpsService.java:273)
at com.android.server.MountService$MountServiceInternalImpl.hasExternalStorage(MountService.java:3431)
at com.android.server.MountService.getVolumeList(MountService.java:2609)
at android.os.storage.StorageManager.getVolumeList(StorageManager.java:880)
at android.os.Environment$UserEnvironment.getExternalDirs(Environment.java:83)
at android.os.Environment.isExternalStorageEmulated(Environment.java:708)
at com.android.server.pm.PackageManagerService.isExternalMediaAvailable(PackageManagerService.java:9327)
at com.android.server.pm.PackageManagerService.startCleaningPackages(PackageManagerService.java:9367)
- locked <0x025f9b02> (a android.util.ArrayMap)
at com.android.server.pm.PackageManagerService$PackageHandler.doHandleMessage(PackageManagerService.java:1320)
at com.android.server.pm.PackageManagerService$PackageHandler.handleMessage(PackageManagerService.java:1122)
at android.os.Handler.dispatchMessage(Handler.java:102)
at android.os.Looper.loop(Looper.java:148)
at android.os.HandlerThread.run(HandlerThread.java:61)
at com.android.server.ServiceThread.run(ServiceThread.java:46)
활동
활동은 사용자가 전화 걸기, 사진 찍기, 이메일 보내기 등의 작업을 하도록 상호작용하는 화면을 제공하는 애플리케이션 구성요소입니다. 버그 신고의 관점에서 활동은 사용자가 할 수 있는 단 하나의 집중된 작업이므로 비정상 종료 시 하고 있던 활동을 찾는 것이 매우 중요합니다. ActivityManager를 통한 활동은 프로세스를 실행하므로 활동 프로세스의 모든 중단 및 시작을 찾는 것도 문제해결에 도움을 줄 수 있습니다.
집중적 활동 보기
집중적 활동의 기록을 보려면 am_focused_activity를 검색합니다.
예시 보기
grep "am_focused_activity" bugreport-2015-10-01-18-13-48.txt
10-01 18:10:41.409 4600 14112 I am_focused_activity: [0,com.google.android.GoogleCamera/com.android.camera.CameraActivity]
10-01 18:11:17.313 4600 5687 I am_focused_activity: [0,com.google.android.googlequicksearchbox/com.google.android.launcher.GEL]
10-01 18:11:52.747 4600 14113 I am_focused_activity: [0,com.google.android.GoogleCamera/com.android.camera.CameraActivity]
10-01 18:14:07.762 4600 5687 I am_focused_activity: [0,com.google.android.googlequicksearchbox/com.google.android.launcher.GEL]
프로세스 시작 보기
프로세스 시작 기록을 보려면 Start proc을 검색합니다.
예시 보기
grep "Start proc" bugreport-2015-10-01-18-13-48.txt
10-01 18:09:15.309 4600 4612 I ActivityManager: Start proc 24533:com.metago.astro/u0a240 for broadcast com.metago.astro/com.inmobi.commons.analytics.androidsdk.IMAdTrackerReceiver
10-01 18:09:15.687 4600 14112 I ActivityManager: Start proc 24548:com.google.android.apps.fitness/u0a173 for service com.google.android.apps.fitness/.api.services.ActivityUpsamplingService
10-01 18:09:15.777 4600 6604 I ActivityManager: Start proc 24563:cloudtv.hdwidgets/u0a145 for broadcast cloudtv.hdwidgets/cloudtv.switches.SwitchSystemUpdateReceiver
10-01 18:09:20.574 4600 6604 I ActivityManager: Start proc 24617:com.wageworks.ezreceipts/u0a111 for broadcast com.wageworks.ezreceipts/.ui.managers.IntentReceiver
...
기기 스래싱 여부 파악
기기가 스래싱되는지 알아보려면 짧은 시간 동안 am_proc_died와 am_proc_start 주변에서 활동이 비정상적으로 증가했는지 확인합니다.
예시 보기
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]
10-01 18:07:15.267 4600 6605 I am_proc_start: [0,20539,10173,com.google.android.apps.fitness,service,com.google.android.apps.fitness/.api.services.ActivityUpsamplingService]
10-01 18:07:15.985 4600 4612 I am_proc_start: [0,20568,10022,com.android.musicfx,broadcast,com.android.musicfx/.ControlPanelReceiver]
10-01 18:07:16.315 4600 7512 I am_proc_died: [0,20096,com.google.android.GoogleCamera]
메모리
Android 기기는 물리적 메모리가 제한적인 경우가 많습니다. 따라서 랜덤 액세스 메모리(RAM) 관리가 매우 중요합니다. 버그 신고에는 메모리 부족에 관한 여러 지표, 그리고 메모리 스냅샷을 제공하는 dumpstate가 포함되어 있습니다.
메모리 부족 식별
메모리가 부족하면 시스템이 메모리 확보를 위해 일부 프로세스를 종료하는 동시에 다른 프로세스를 계속해서 시작하는 과정에서 스래싱을 경험할 수 있습니다. 메모리가 부족하다는 증거를 확인하려면 바이너리 이벤트 로그에서 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
10-01 18:12:37.945 4600 6521 I am_low_memory: 43
10-01 18:12:47.804 4600 14110 I am_low_memory: 43
스래싱 지표 보기
시스템 스래싱(페이징, 직접 회수 등)의 다른 표시기로는 kswapd, kworker 및 mmcqd 소비 주기가 있습니다. 수집되고 있는 버그 신고가 스래싱 지표에 영향을 미칠 수 있음을 기억하세요.
예시 보기
------ CPU INFO (top -n 1 -d 1 -m 30 -t) ------
User 15%, System 54%, IOW 28%, IRQ 0%
User 82 + Nice 2 + Sys 287 + Idle 1 + IOW 152 + IRQ 0 + SIRQ 5 = 529
PID TID PR CPU% S VSS RSS PCY UID Thread Proc
15229 15229 0 19% R 0K 0K fg root kworker/0:2
29512 29517 1 7% D 1173524K 101188K bg u0_a27 Signal Catcher com.google.android.talk
24565 24570 3 6% D 2090920K 145168K fg u0_a22 Signal Catcher com.google.android.googlequicksearchbox:search
19525 19525 2 6% R 3476K 1644K fg shell top top
24957 24962 2 5% R 1706928K 125716K bg u0_a47 Signal Catcher com.google.android.GoogleCamera
19519 19519 3 4% S 0K 0K fg root kworker/3:1
120 120 0 3% S 0K 0K fg root mmcqd/1
18233 18233 1 3% S 0K 0K fg root kworker/1:1
25589 25594 1 2% D 1270476K 75776K fg u0_a8 Signal Catcher com.google.android.gms
19399 19399 2 1% S 0K 0K fg root kworker/2:2
1963 1978 1 0% S 1819100K 125136K fg system android.fg system_server
1963 1981 3 0% S 1819100K 125136K fg system android.display system_server
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-03 17:19:59.959 1963 1976 E ActivityManager: 6.1% 24565/com.google.android.googlequicksearchbox:search: 2.4% user + 3.7% kernel / faults: 2902 minor 129 major
10-03 17:19:59.959 1963 1976 E ActivityManager: 6% 55/kswapd0: 0% user + 6% kernel
10-03 17:19:59.959 1963 1976 E ActivityManager: 4.9% 18819/com.google.android.apps.magazines: 1.5% user + 3.3% kernel / faults: 10129 minor 986 major
10-03 17:19:59.959 1963 1976 E ActivityManager: 2.8% 18233/kworker/1:1: 0% user + 2.8% kernel
10-03 17:19:59.959 1963 1976 E ActivityManager: 4.2% 3145/com.android.phone: 2% user + 2.2% kernel / faults: 3005 minor 43 major
10-03 17:19:59.959 1963 1976 E ActivityManager: 4.2% 8084/com.android.chrome: 2% user + 2.1% kernel / faults: 4798 minor 380 major
10-03 17:19:59.959 1963 1976 E ActivityManager: 3.4% 182/surfaceflinger: 1.1% user + 2.3% kernel / faults: 842 minor 13 major
10-03 17:19:59.959 1963 1976 E ActivityManager: 3% 18236/kworker/1:2: 0% user + 3% kernel
10-03 17:19:59.959 1963 1976 E ActivityManager: 2.9% 19231/com.android.systemui:screenshot: 0.8% user + 2.1% kernel / faults: 6119 minor 348 major
10-03 17:19:59.959 1963 1976 E ActivityManager: 2.3% 15350/kworker/0:4: 0% user + 2.3% kernel
10-03 17:19:59.959 1963 1976 E ActivityManager: 2.2% 1454/mediaserver: 0% user + 2.2% kernel / faults: 479 minor 6 major
10-03 17:19:59.959 1963 1976 E ActivityManager: 2% 16496/com.android.chrome:sandboxed_process10: 0.1% user + 1.8% kernel / faults: 3610 minor 234 major
10-03 17:19:59.959 1963 1976 E ActivityManager: 1% 3119/com.android.nfc: 0.4% user + 0.5% kernel / faults: 1789 minor 17 major
10-03 17:19:59.959 1963 1976 E ActivityManager: 1.7% 19337/com.jarettmillard.localeconnectiontype:background: 0.1% user + 1.5% kernel / faults: 7854 minor 439 major
10-03 17:19:59.959 1963 1976 E ActivityManager: 0.7% 3066/com.google.android.inputmethod.latin: 0.3% user + 0.3% kernel / faults: 1336 minor 7 major
10-03 17:19:59.959 1963 1976 E ActivityManager: 1% 25589/com.google.android.gms: 0.3% user + 0.6% kernel / faults: 2867 minor 237 major
10-03 17:19:59.959 1963 1976 E ActivityManager: 0.9% 1460/sensors.qcom: 0.5% user + 0.4% kernel / faults: 262 minor 5 major
10-03 17:19:59.959 1963 1976 E ActivityManager: 0.8% 3650/mpdecision: 0% user + 0.8% kernel / faults: 160 minor 1 major
10-03 17:19:59.959 1963 1976 E ActivityManager: 0.1% 3132/com.redbend.vdmc: 0% user + 0% kernel / faults: 1746 minor 5 major
메모리 스냅샷 가져오기
메모리 스냅샷은 실행 중인 자바 및 네이티브 프로세스를 나열하는 dumpstate입니다. 자세한 내용은 전체 메모리 할당 보기를 참고하세요. 스냅샷은 구체적인 시점의 상태만 제공합니다. 시스템은 스냅샷 전에 상태가 훨씬 좋거나 나빴을 수 있습니다.
예시 보기
Total PSS by OOM adjustment:
86752 kB: Native
22645 kB: surfaceflinger (pid 197)
18597 kB: mediaserver (pid 204)
...
136959 kB: System
136959 kB: system (pid 785)
220218 kB: Persistent
138859 kB: com.android.systemui (pid 947 / activities)
39178 kB: com.android.nfc (pid 1636)
28313 kB: com.android.phone (pid 1659)
13868 kB: com.redbend.vdmc (pid 1646)
9534 kB: Persistent Service
9534 kB: com.android.bluetooth (pid 23807)
178604 kB: Foreground
168620 kB: com.google.android.googlequicksearchbox (pid 1675 / activities)
9984 kB: com.google.android.apps.maps (pid 13952)
188286 kB: Visible
85326 kB: com.google.android.wearable.app (pid 1535)
38978 kB: com.google.process.gapps (pid 1510)
31936 kB: com.google.android.gms.persistent (pid 2072)
27950 kB: com.google.android.gms.wearable (pid 1601)
4096 kB: com.google.android.googlequicksearchbox:interactor (pid 1550)
52948 kB: Perceptible
52948 kB: com.google.android.inputmethod.latin (pid 1566)
150851 kB: A Services
81121 kB: com.google.android.gms (pid 1814)
37586 kB: com.google.android.talk (pid 9584)
10949 kB: com.google.android.music:main (pid 4019)
10727 kB: com.motorola.targetnotif (pid 31071)
10468 kB: com.google.android.GoogleCamera (pid 9984)
33298 kB: Previous
33298 kB: com.android.settings (pid 9673 / activities)
165188 kB: B Services
49490 kB: com.facebook.katana (pid 15035)
22483 kB: com.whatsapp (pid 28694)
21308 kB: com.iPass.OpenMobile (pid 5325)
19788 kB: com.google.android.apps.googlevoice (pid 23934)
17399 kB: com.google.android.googlequicksearchbox:search (pid 30359)
9073 kB: com.google.android.apps.youtube.unplugged (pid 21194)
7660 kB: com.iPass.OpenMobile:remote (pid 23754)
7291 kB: com.pujie.wristwear.pujieblack (pid 24240)
7157 kB: com.instagram.android:mqtt (pid 9530)
3539 kB: com.qualcomm.qcrilmsgtunnel (pid 16186)
204324 kB: Cached
43424 kB: com.amazon.mShop.android (pid 13558)
22563 kB: com.google.android.apps.magazines (pid 13844)
...
4298 kB: com.google.android.apps.enterprise.dmagent (pid 13826)
브로드캐스트
애플리케이션은 브로드캐스트를 생성하여 현재 애플리케이션 내의 이벤트를 전송하거나 다른 애플리케이션으로 보냅니다. Broadcast receiver는 필터를 통해 특정 메시지를 구독하여 브로드캐스트를 수신하고 응답할 수 있도록 지원합니다.
버그 신고에는 전송된 브로드캐스트와 전송되지 않은 브로드캐스트에 관한 정보는 물론 특정 브로드캐스트를 수신 중인 모든 receiver의 dumpsys까지 포함됩니다.
이전 브로드캐스트 보기
이전 브로드캐스트는 이미 전송된 브로드캐스트로서 시간 역순으로 나열됩니다.
요약 섹션은 포그라운드의 마지막 브로드캐스트 300건과 백그라운드의 마지막 브로드캐스트 300건에 관한 개요입니다.
예시 보기
Historical broadcasts summary [foreground]:
#0: act=android.intent.action.SCREEN_ON flg=0x50000010
+1ms dispatch +90ms finish
enq=2015-10-29 17:10:51 disp=2015-10-29 17:10:51 fin=2015-10-29 17:10:51
#1: act=android.intent.action.SCREEN_OFF flg=0x50000010
0 dispatch +60ms finish
enq=2015-10-29 17:10:05 disp=2015-10-29 17:10:05 fin=2015-10-29 17:10:05
...
Historical broadcasts summary [background]:
...
세부정보 섹션에는 포그라운드의 마지막 브로드캐스트 50건과 백그라운드의 마지막 브로드캐스트 50건, 그리고 각 브로드캐스트의 receiver에 관한 모든 정보가 포함됩니다. Receiver는 다음 두 가지로 나뉩니다.
BroadcastFilter 항목은 런타임에 등록되며 이미 실행 중인 프로세스에만 전송됩니다.ResolveInfo 항목은 매니페스트 항목을 통해 등록됩니다. ActivityManager가 아직 실행 중이 아니라면 각 ResolveInfo의 프로세스를 시작합니다.
예시 보기
Historical broadcasts [foreground]:
...
Historical broadcasts [background]:
Historical Broadcast background #0:
...
Historical Broadcast background #5:
BroadcastRecord{18dbb16 u0 android.intent.action.USER_PRESENT} to user 0
Intent { act=android.intent.action.USER_PRESENT flg=0x24000010 }
caller=com.android.systemui 2925:com.android.systemui/u0a27 pid=2925 uid=10027
enqueueClockTime=2015-10-29 17:10:55 dispatchClockTime=2015-10-29 17:10:55
dispatchTime=-2s321ms (0 since enq) finishTime=-2s320ms (+1ms since disp)
Receiver #0: BroadcastFilter{8181cc1 u-1 ReceiverList{5d929a8 902 system/1000/u-1 local:eca4dcb}}
Receiver #1: BroadcastFilter{6371c97 u-1 ReceiverList{2938b16 902 system/1000/u-1 local:840b831}}
...
Receiver #19: BroadcastFilter{93f16b u0 ReceiverList{5c61eba 17016 com.google.android.gm/10079/u0 remote:24083e5}}
...
Historical Broadcast background #37:
BroadcastRecord{7f6dd6 u0 android.hardware.action.NEW_PICTURE} to user 0
Intent { act=android.hardware.action.NEW_PICTURE dat=content://media/external/images/media/6345 flg=0x10 }
caller=com.google.android.GoogleCamera 32734:com.google.android.GoogleCamera/u0a53 pid=32734 uid=10053
enqueueClockTime=2015-10-29 17:09:48 dispatchClockTime=2015-10-29 17:09:49
dispatchTime=-45s720ms (+399ms since enq) finishTime=-45s701ms (+19ms since disp)
resultTo=null resultCode=0 resultData=null
nextReceiver=4 receiver=null
Receiver #0: ResolveInfo{33d2857 com.google.android.gms/com.google.android.libraries.social.mediamonitor.MediaMonitor m=0x608000}
priority=0 preferredOrder=0 match=0x608000 specificIndex=-1 isDefault=false
ActivityInfo:
name=com.google.android.libraries.social.mediamonitor.MediaMonitor
packageName=com.google.android.gms
enabled=true exported=true processName=com.google.android.gms
...
Receiver #1: ResolveInfo{d9edf44 com.google.android.apps.maps/com.google.android.apps.gmm.ugc.clientnotification.StartPhotoTakenNotifierServiceReceiver m=0x608000}
priority=0 preferredOrder=0 match=0x608000 specificIndex=-1 isDefault=false
ActivityInfo:
name=com.google.android.apps.gmm.ugc.clientnotification.StartPhotoTakenNotifierServiceReceiver
packageName=com.google.android.apps.maps
enabled=true exported=true processName=com.google.android.apps.maps
...
Receiver #2: ResolveInfo{743f82d com.google.android.apps.photos/com.google.android.libraries.social.mediamonitor.MediaMonitor m=0x608000}
priority=0 preferredOrder=0 match=0x608000 specificIndex=-1 isDefault=false
ActivityInfo:
name=com.google.android.libraries.social.mediamonitor.MediaMonitor
packageName=com.google.android.apps.photos
enabled=true exported=true processName=com.google.android.apps.photos
...
Receiver #3: ResolveInfo{d5c9162 com.google.android.apps.plus/com.google.android.libraries.social.mediamonitor.MediaMonitor m=0x608000}
priority=0 preferredOrder=0 match=0x608000 specificIndex=-1 isDefault=false
ActivityInfo:
name=com.google.android.libraries.social.mediamonitor.MediaMonitor
packageName=com.google.android.apps.plus
enabled=true exported=true processName=com.google.android.apps.plus
...
활성 브로드캐스트 보기
활성 브로드캐스트는 아직 전송되지 않은 브로드캐스트입니다. 대기열의 숫자가 높으면 시스템이 속도에 맞춰 브로드캐스트를 전송할 수 없음을 의미합니다.
예시 보기
Active ordered broadcasts [background]:
Active Ordered Broadcast background #133: // size of queue
...
브로드캐스트 리스너 보기
브로드캐스트를 수신 중인 수신기의 목록을 보려면 dumpsys activity broadcasts에서 Receiver Resolver Table을 확인하세요. 다음 예는 USER_PRESENT를 수신하는 모든 수신기를 표시합니다.
예시 보기
-------------------------------------------------------------------------------
ACTIVITY MANAGER BROADCAST STATE (dumpsys activity broadcasts)
..
Receiver Resolver Table:
Full MIME Types:
..
Wild MIME Types:
..
Schemes:
..
Non-Data Actions:
..
android.intent.action.USER_PRESENT:
BroadcastFilter{8181cc1 u-1 ReceiverList{5d929a8 902 system/1000/u-1 local:eca4dcb}}
BroadcastFilter{6371c97 u-1 ReceiverList{2938b16 902 system/1000/u-1 local:840b831}}
BroadcastFilter{320c00 u0 ReceiverList{d3a6283 902 system/1000/u0 local:799c532}}
BroadcastFilter{e486048 u0 ReceiverList{36fbaeb 902 system/1000/u0 local:5f51e3a}}
BroadcastFilter{22b02 u-1 ReceiverList{b3f744d 902 system/1000/u-1 local:de837e4}}
BroadcastFilter{3e989ab u0 ReceiverList{f8deffa 2981 com.google.process.gapps/10012/u0 remote:26bd225}}
BroadcastFilter{fb56150 u0 ReceiverList{22b7b13 2925 com.android.systemui/10027/u0 remote:c54a602}}
BroadcastFilter{63bbb6 u-1 ReceiverList{ba6c751 3484 com.android.nfc/1027/u-1 remote:5c4a478}}
BroadcastFilter{95ad20d u0 ReceiverList{d8374a4 3586 com.google.android.googlequicksearchbox/10029/u0 remote:feb3737}}
BroadcastFilter{fdef551 u0 ReceiverList{28ca78 3745 com.google.android.gms.persistent/10012/u0 remote:f23afdb}}
BroadcastFilter{9830707 u0 ReceiverList{aabd946 3745 com.google.android.gms.persistent/10012/u0 remote:a4da121}}
BroadcastFilter{83c43d2 u0 ReceiverList{d422e5d 3745 com.google.android.gms.persistent/10012/u0 remote:f585034}}
BroadcastFilter{8890378 u0 ReceiverList{26d2cdb 3745 com.google.android.gms.persistent/10012/u0 remote:dfa61ea}}
BroadcastFilter{7bbb7 u0 ReceiverList{214b2b6 3745 com.google.android.gms.persistent/10012/u0 remote:8353a51}}
BroadcastFilter{38d3566 u0 ReceiverList{de859c1 3745 com.google.android.gms.persistent/10012/u0 remote:e003aa8}}
BroadcastFilter{3435d9f u0 ReceiverList{6e38b3e 3745 com.google.android.gms.persistent/10012/u0 remote:8dd7ff9}}
BroadcastFilter{d0a34bb u0 ReceiverList{5091d4a 3745 com.google.android.gms.persistent/10012/u0 remote:d6d22b5}}
BroadcastFilter{d43c416 u0 ReceiverList{51a3531 3745 com.google.android.gms.persistent/10012/u0 remote:d0b9dd8}}
BroadcastFilter{aabf36d u0 ReceiverList{a88bf84 3745 com.google.android.gms.persistent/10012/u0 remote:a9d6197}}
BroadcastFilter{93f16b u0 ReceiverList{5c61eba 17016 com.google.android.gm/10079/u0 remote:24083e5}}
BroadcastFilter{68f794e u0 ReceiverList{4cb1c49 947 com.google.android.googlequicksearchbox:search/10029/u0 remote:251d250}}
..
MIME Typed Actions:
모니터 경합
모니터 경합 로깅은 간혹 실제 모니터 경합을 나타낼 수도 있지만 대부분의 경우 시스템 과부하로 인해 모든 것이 둔화되었음을 나타냅니다.
시스템 또는 이벤트 로그에서는 ART에 의해 로깅된 긴 모니터 이벤트를 볼 수도 있습니다.
시스템 로그에서는 다음과 같이 표시됩니다.
10-01 18:12:44.343 29761 29914 W art : Long monitor contention event with owner method=void android.database.sqlite.SQLiteClosable.acquireReference() from SQLiteClosable.java:52 waiters=0 for 3.914s
이벤트 로그에서는 다음과 같이 표시됩니다.
10-01 18:12:44.364 29761 29914 I dvm_lock_sample: [com.google.android.youtube,0,pool-3-thread-9,3914,ScheduledTaskMaster.java,138,SQLiteClosable.java,52,100]
백그라운드 컴파일
컴파일로 기기를 로드할 수 있지만 비용이 높습니다.
예시 보기
09-14 06:27:05.670 2508 2587 E ActivityManager: CPU usage from 0ms to 5857ms later:
09-14 06:27:05.670 2508 2587 E ActivityManager: 84% 5708/dex2oat: 81% user + 2.3% kernel / faults: 3731 minor 1 major
09-14 06:27:05.670 2508 2587 E ActivityManager: 73% 2508/system_server: 21% user + 51% kernel / faults: 10019 minor 28 major
09-14 06:27:05.670 2508 2587 E ActivityManager: 1% 3935/com.android.phone: 0.3% user + 0.6% kernel / faults: 2684 minor 2 major
컴파일은 Google Play 스토어 업데이트가 다운로드되고 있을 때 백그라운드에서 발생할 수 있습니다. 이 경우 Google Play 스토어 앱(finsky)과 installd의 메시지는 dex2oat 메시지 이전에 표시됩니다.
예시 보기
10-07 08:42:33.725 11051 11051 D Finsky : [1] InstallerTask.advanceState: Prepare to patch com.garmin.android.apps.virb (com.garmin.android.apps.virb) from content://downloads/my_downloads/3602 format 2
10-07 08:42:33.752 495 495 I installd: free_cache(48637657) avail 15111192576
…
10-07 08:42:39.998 2497 2567 I PackageManager.DexOptimizer: Running dexopt (dex2oat) on: /data/app/vmdl436577137.tmp/base.apk pkg=com.garmin.android.apps.virb isa=arm vmSafeMode=false debuggable=false oatDir = /data/app/vmdl436577137.tmp/oat bootComplete=true
…
컴파일은 애플리케이션이 아직 컴파일되지 않은 dex 파일을 로드하고 있을 때 백그라운드에서 발생할 수 있습니다. 이 경우 finsky 또는 installd 로깅이 보이지 않습니다.
예시 보기
09-14 07:29:20.433 15736 15736 I dex2oat : /system/bin/dex2oat -j4 --dex-file=/data/user/0/com.facebook.katana/app_secondary_program_dex/program-72cef82b591768306676e10161c886b58b34315a308602be.dex.jar --oat-file=/data/user/0/com.facebook.katana/app_secondary_program_dex_opt/program-72cef82b591768306676e10161c886b58b34315a308602be.dex.dex
...
09-14 07:29:25.102 15736 15736 I dex2oat : dex2oat took 4.669s (threads: 4) arena alloc=7MB java alloc=3MB native alloc=29MB free=4MB
설명
문제 설명(시작 경위, 상황, 시스템 대응 방식)을 수립하려면 확실한 이벤트 타임라인이 필요합니다. 버그 신고의 정보를 사용하여 여러 로그의 타임라인을 동기화하고 버그 신고의 정확한 타임스탬프를 파악할 수 있습니다.
타임라인 동기화
버그 신고는 시스템 로그, 이벤트 로그, 커널 로그, 브로드캐스트와 관련된 여러 특수 타임라인, 배터리 통계 등을 비롯한 여러 병렬 타임라인을 반영합니다. 안타깝게도 타임라인은 다른 시간 베이스를 사용하여 보고될 때가 많습니다.
시스템 및 이벤트 로그 타임스탬프는 다른 대부분의 타임스탬프처럼 사용자와 같은 시간대에 위치합니다. 예를 들어 사용자가 홈 버튼을 탭하면 시스템 로그는 다음을 보고합니다.
10-03 17:19:52.939 1963 2071 I ActivityManager: START u0 {act=android.intent.action.MAIN cat=[android.intent.category.HOME] flg=0x10200000 cmp=com.google.android.googlequicksearchbox/com.google.android.launcher.GEL (has extras)} from uid 1000 on display 0
같은 작업에 관해 이벤트 로그는 다음을 보고합니다.
10-03 17:19:54.279 1963 2071 I am_focused_activity: [0,com.google.android.googlequicksearchbox/com.google.android.launcher.GEL]
커널(dmesg) 로그는 다른 시간 베이스를 사용하여 부트로더가 완료된 이후의 로그 항목을 초 단위로 태그합니다. 이 기간을 다른 기간에 등록하려면 다음과 같이 suspend exit 및 suspend entry 메시지를 검색합니다.
<6>[201640.779997] PM: suspend exit 2015-10-03 19:11:06.646094058 UTC
…
<6>[201644.854315] PM: suspend entry 2015-10-03 19:11:10.720416452 UTC
커널 로그에는 정지 도중의 시간이 포함되어 있지 않을 수 있습니다. 따라서 정지 항목 및 종료 메시지 간의 로그를 따로 등록해야 합니다.
또한 커널 로그는 UTC 시간대를 사용하며 사용자 시간대에 맞게 조정되어야 합니다.
버그 신고 시간 식별
버그 신고가 언제 접수되었는지 알아보려면 먼저 다음과 같이 시스템 로그(Logcat)에서 dumpstate: begin을 확인합니다.
10-03 17:19:54.322 19398 19398 I dumpstate: begin
그다음 Starting service
'bugreport' 메시지의 커널 로그(dmesg) 타임스탬프를 확인합니다.
<5>[207064.285315] init: Starting service 'bugreport'...
역으로 작업하여 두 이벤트 간의 상관 관계를 지정하고, 이때 타임라인 동기화에 언급된 주의사항을 유념해야 합니다. 버그 신고가 시작된 후에는 많은 상황이 발생하지만 대부분의 활동은 크게 유용하지 않습니다. 이는 버그 신고 접수 시 시스템에 상당한 부하가 발생하기 때문입니다.
전원
이벤트 로그에는 화면 전원 상태가 표시됩니다. 0은 화면 꺼짐, 1은 화면 켜짐, 2는 키가드 적용을 의미합니다.
예시 보기
grep screen_toggled bugreport-2015-10-18-16-52-22.txt
10-18 15:05:04.383 992 992 I screen_toggled: 1
10-18 15:05:07.010 992 992 I screen_toggled: 0
10-18 15:23:15.063 992 992 I screen_toggled: 1
10-18 15:23:25.684 992 992 I screen_toggled: 0
10-18 15:36:31.623 992 992 I screen_toggled: 1
10-18 15:36:37.660 3283 3283 I screen_toggled: 2
버그 신고에는 wake lock에 관한 통계도 포함됩니다. 애플리케이션 개발자는 이 메커니즘을 사용하여 애플리케이션이 기기의 켜짐 상태를 유지해야 함을 나타냅니다. (wake lock에 관한 자세한 내용은 PowerManager.WakeLock 및 CPU를 켜진 상태로 유지를 참조하세요.)
집계된 wake lock 지속 시간 통계는 wake lock이 실제로 기기 켜짐 상태에 기여한 시간만 추적하며 화면이 켜진 시간은 포함하지 않습니다. 또한 여러 wake lock이 동시에 사용되는 경우 wake lock 지속 시간이 이러한 여러 wake lock에 걸쳐 분산됩니다.
전원 상태 시각화에 관한 도움이 더 필요한 경우 Battery Historian을 사용하세요. 이 Google 오픈소스 도구는 Android 버그 신고 파일을 사용하여 배터리 소모 요소를 분석합니다.
패키지
DUMP OF SERVICE package 섹션에는 애플리케이션 버전 및 기타 유용한 정보가 포함되어 있습니다.
예시 보기
...
DUMP OF SERVICE package:
...
Packages:
...
Package [com.google.android.gms] (3cf534b):
userId=10013
sharedUser=SharedUserSetting{98f3d28 com.google.uid.shared/10013}
pkg=Package{b8f6a41 com.google.android.gms}
codePath=/system/priv-app/PrebuiltGmsCore
resourcePath=/system/priv-app/PrebuiltGmsCore
legacyNativeLibraryDir=/system/priv-app/PrebuiltGmsCore/lib
primaryCpuAbi=arm64-v8a
secondaryCpuAbi=armeabi-v7a
versionCode=8186448 targetSdk=23
versionName=8.1.86 (2287566-448)
splits=[base]
applicationInfo=ApplicationInfo{5158507 com.google.android.gms}
flags=[ SYSTEM HAS_CODE ALLOW_CLEAR_USER_DATA ]
privateFlags=[ PRIVILEGED ]
dataDir=/data/user/0/com.google.android.gms
supportsScreens=[small, medium, large, xlarge, resizeable, anyDensity]
libraries:
com.google.android.gms
usesOptionalLibraries:
com.android.location.provider
com.google.android.ble
com.android.media.remotedisplay
usesLibraryFiles:
/system/framework/com.android.media.remotedisplay.jar
/system/framework/com.android.location.provider.jar
timeStamp=2015-10-14 15:17:56
firstInstallTime=2015-09-22 14:08:35
lastUpdateTime=2015-10-14 15:17:56
signatures=PackageSignatures{db63be6 [1af63d8]}
installPermissionsFixed=true installStatus=1
pkgFlags=[ SYSTEM HAS_CODE ALLOW_CLEAR_USER_DATA ]
declared permissions:
com.google.android.gms.permission.INTERNAL_BROADCAST: prot=signature, INSTALLED
...
com.google.android.gms.permission.CAR_VENDOR_EXTENSION: prot=dangerous, INSTALLED
User 0: installed=true hidden=false stopped=false notLaunched=false enabled=0
disabledComponents:
com.google.android.gms.icing.service.PowerConnectedReceiver
...
com.google.android.gms.icing.proxy.AppsMonitor
enabledComponents:
com.google.android.gms.mdm.receivers.GmsRegisteredReceiver
...
com.google.android.gms.subscribedfeeds.SyncService
프로세스
버그 신고에는 시작 및 중지 시간, 런타임 길이, 연결된 서비스 및 oom_adj 스코어 등 방대한 양의 프로세스 데이터가 포함됩니다. Android에서 프로세스를 관리하는 방법에 관한 자세한 내용은 프로세스와 스레드를 참고하세요.
프로세스 런타임 파악
procstats 섹션에는 프로세스 및 연결된 서비스가 실행된 기간에 관한 일체의 통계가 포함됩니다. 사람이 읽을 수 있는 빠른 요약을 보려면 AGGREGATED OVER를 검색하여 마지막 세 시간 또는 24시간의 데이터를 확인한 다음 Summary:를 검색하여 프로세스 목록, 이러한 프로세스가 다양한 우선순위에서 실행된 기간 및 최소-평균-최대 PSS/최소-평균-최대 USS 형식으로 표시된 프로세스의 RAM 사용량을 확인합니다.
예시 보기
-------------------------------------------------------------------------------
DUMP OF SERVICE processinfo:
-------------------------------------------------------------------------------
DUMP OF SERVICE procstats:
COMMITTED STATS FROM 2015-10-19-23-54-56 (checked in):
...
COMMITTED STATS FROM 2015-10-20-03-00-00 (checked in):
...
CURRENT STATS:
...
AGGREGATED OVER LAST 24 HOURS:
System memory usage:
...
Per-Package Stats:
...
Summary:
...
* com.google.android.gms.persistent / u0a13 / v8186448:
TOTAL: 100% (21MB-27MB-40MB/20MB-24MB-38MB over 597)
Top: 51% (22MB-26MB-38MB/21MB-24MB-36MB over 383)
Imp Fg: 49% (21MB-27MB-40MB/20MB-25MB-38MB over 214)
…
Start time: 2015-10-19 09:14:37
Total elapsed time: +1d0h22m7s390ms (partial) libart.so
AGGREGATED OVER LAST 3 HOURS:
System memory usage:
...
Per-Package Stats:
...
Summary:
* com.google.android.gms.persistent / u0a13 / v8186448:
TOTAL: 100% (23MB-27MB-32MB/21MB-25MB-29MB over 111)
Top: 61% (23MB-26MB-31MB/21MB-24MB-28MB over 67)
Imp Fg: 39% (23MB-28MB-32MB/21MB-26MB-29MB over 44)
...
Start time: 2015-10-20 06:49:24
Total elapsed time: +2h46m59s736ms (partial) libart.so
프로세스가 실행 중인 이유
dumpsys activity processes 섹션에는 현재 실행 중인 모든 프로세스가 oom_adj 스코어 순으로 나열됩니다(Android는 프로세스에 oom_adj 값을 할당하여 프로세스 중요도를 표시하며 이 값은 ActivityManager에서 동적으로 업데이트할 수 있음). 출력은 메모리 스냅샷의 출력과 유사하지만 프로세스를 실행시킨 주체에 관한 추가 정보를 포함합니다. 아래 예에서 굵게 표시된 항목은 시스템 프로세스가 NetworkLocationService와 결합되어 있기 때문에 우선순위가 vis(공개)인 상태에서 gms.persistent 프로세스가 실행 중임을 나타냅니다.
예시 보기
-------------------------------------------------------------------------------
ACTIVITY MANAGER RUNNING PROCESSES (dumpsys activity processes)
...
Process LRU list (sorted by oom_adj, 34 total, non-act at 14, non-svc at 14):
PERS #33: sys F/ /P trm: 0 902:system/1000 (fixed)
PERS #32: pers F/ /P trm: 0 2925:com.android.systemui/u0a27 (fixed)
PERS #31: pers F/ /P trm: 0 3477:com.quicinc.cne.CNEService/1000 (fixed)
PERS #30: pers F/ /P trm: 0 3484:com.android.nfc/1027 (fixed)
PERS #29: pers F/ /P trm: 0 3502:com.qualcomm.qti.rcsbootstraputil/1001 (fixed)
PERS #28: pers F/ /P trm: 0 3534:com.qualcomm.qti.rcsimsbootstraputil/1001 (fixed)
PERS #27: pers F/ /P trm: 0 3553:com.android.phone/1001 (fixed)
Proc #25: psvc F/ /IF trm: 0 4951:com.android.bluetooth/1002 (service)
com.android.bluetooth/.hfp.HeadsetService<=Proc{902:system/1000}
Proc # 0: fore F/A/T trm: 0 3586:com.google.android.googlequicksearchbox/u0a29 (top-activity)
Proc #26: vis F/ /SB trm: 0 3374:com.google.android.googlequicksearchbox:interactor/u0a29 (service)
com.google.android.googlequicksearchbox/com.google.android.voiceinteraction.GsaVoiceInteractionService<=Proc{902:system/1000}
Proc # 5: vis F/ /T trm: 0 3745:com.google.android.gms.persistent/u0a12 (service)
com.google.android.gms/com.google.android.location.network.NetworkLocationService<=Proc{902:system/1000}
Proc # 3: vis F/ /SB trm: 0 3279:com.google.android.gms/u0a12 (service)
com.google.android.gms/.icing.service.IndexService<=Proc{947:com.google.android.googlequicksearchbox:search/u0a29}
Proc # 2: vis F/ /T trm: 0 947:com.google.android.googlequicksearchbox:search/u0a29 (service)
com.google.android.googlequicksearchbox/com.google.android.sidekick.main.remoteservice.GoogleNowRemoteService<=Proc{3586:com.google.android.googlequicksearchbox/u0a29}
Proc # 1: vis F/ /T trm: 0 2981:com.google.process.gapps/u0a12 (service)
com.google.android.gms/.tapandpay.hce.service.TpHceService<=Proc{3484:com.android.nfc/1027}
Proc #11: prcp B/ /IB trm: 0 3392:com.google.android.inputmethod.latin/u0a64 (service)
com.google.android.inputmethod.latin/com.android.inputmethod.latin.LatinIME<=Proc{902:system/1000}
Proc #24: svc B/ /S trm: 0 27071:com.google.android.music:main/u0a67 (started-services)
Proc #22: svc B/ /S trm: 0 853:com.qualcomm.qcrilmsgtunnel/1001 (started-services)
Proc # 4: prev B/ /LA trm: 0 32734:com.google.android.GoogleCamera/u0a53 (previous)
Proc #23: svcb B/ /S trm: 0 671:com.qualcomm.telephony/1000 (started-services)
Proc #20: cch B/ /CE trm: 0 27659:com.android.providers.calendar/u0a2 (provider)
com.android.providers.calendar/.CalendarProvider2<=Proc{27697:com.google.android.calendar/u0a40}
Proc #13: cch B/ /CE trm: 0 653:com.google.android.gms.wearable/u0a12 (cch-empty)
Proc #10: cch B/ /S trm: 0 4067:com.google.android.talk/u0a62 (cch-started-ui-services)
Proc # 6: cch B/ /CA trm: 0 27697:com.google.android.calendar/u0a40 (cch-act)
Proc # 8: cch+1 B/ /CA trm: 0 25675:com.google.android.apps.genie.geniewidget/u0a81 (cch-act)
Proc #16: cch+2 B/ /CE trm: 0 1272:com.google.android.keep/u0a106 (cch-empty)
Proc #15: cch+2 B/ /CE trm: 0 885:android.process.media/u0a9 (cch-empty)
Proc #14: cch+2 B/ /CE trm: 0 15146:android.process.acore/u0a3 (cch-empty)
Proc # 9: cch+3 B/ /CA trm: 0 17016:com.google.android.gm/u0a79 (cch-act)
Proc #19: cch+4 B/ /CE trm: 0 973:com.google.android.apps.maps/u0a66 (cch-empty)
Proc #18: cch+4 B/ /CE trm: 0 1091:com.google.android.apps.photos/u0a71 (cch-empty)
Proc #17: cch+4 B/ /CE trm: 0 1141:com.google.android.apps.plus/u0a74 (cch-empty)
Proc #12: cch+5 B/ /CA trm: 0 22299:com.google.android.apps.dogfood/u0a105 (cch-act)
Proc #21: cch+6 B/ /CE trm: 0 995:com.google.android.partnersetup/u0a18 (cch-empty)>
검색
과도한 저전력 블루투스(BLE) 검색을 실행 중인 애플리케이션을 식별하려면 다음 단계를 따르세요.
- 다음과 같이
BluetoothLeScanner에 관한 로그 메시지를 찾습니다.
$ grep 'BluetoothLeScanner' ~/downloads/bugreport.txt
07-28 15:55:19.090 24840 24851 D BluetoothLeScanner: onClientRegistered() - status=0 clientIf=5
- 로그 메시지에서 PID를 찾습니다. 이 예에서는 '24840' 및 '24851'이 프로세스 ID(PID) 및 스레드 ID(TID)입니다.
- PID에 연결된 애플리케이션을 찾습니다.
PID #24840: ProcessRecord{4fe996a 24840:com.badapp/u0a105}
이 예에서 패키지 이름은 com.badapp입니다.
- Google Play에서 패키지 이름을 찾아 해당하는 애플리케이션을 식별합니다(https://play.google.com/store/apps/details?id=com.badapp).
참고: Android 7.0을 실행하는 기기에서는 시스템이 BLE 검색 데이터를 수집하고 이러한 활동을 시작 애플리케이션에 연결합니다. 자세한 내용은 저전력(LE) 및 블루투스 검색을 참조하세요.
