Android log常用分析方法

logcat

event log

这种log framework层常常使用，通过类似EventLog.writeEvent()写log，这种log被保存在/system/etc/event-log-tags，如果要看这种log，通过类似logcat -b events -v threadtime这种方式打印出来，输出的格式类似于下面：

02-18 12:29:22.625   451   467 I am_create_task: [0,116]02-18 12:29:22.625   451   467 I am_create_activity: [0,114895309,116,com.xd.ro.roapk/com.xindong.RODevelop.UnitySavePicActivity,android.intent.action.MAIN,NULL,NULL,270532608]02-18 12:29:22.626   451   467 I wm_task_created: [116,1]02-18 12:29:22.626   451   467 I wm_task_moved: [116,1,0]

它的格式就是

timestamp PID TID log-level log-tag tag-values

每个log-tag都能在framework下的源代码中找到，如上面的am_create_task，它的tag是在frameworks/base/services/core/java/com/android/server/am/EventLogTags.logtags定义的。某种程度上说，要检查event log，必须去找这些EventLogTags.logtags，才能清楚知道是啥意思。

ANR

应用在一定时间内由于主线程阻塞而没做出相应，系统将会杀死这个进程并且dump栈信息到/data/anr目录中。

检查ANR log需要两种类型的log，需要event log/logcat和/data/anr下的log。
event log的意思就是上节说的event log，logcat就是我们常常用logcat后面不加-b打印出来的log，这两种log主要是为了找出发生ANR的进程号和发生ARN时的类信息，没有现成的例子，拿网上的例子做个说明。

如果是event log，搜索“am_anr”关键字：

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]

如果是logcat log，搜索关键字“ANR”:

10-01 18:13:11.984  4600  4614 E ActivityManager: ANR in com.google.android.youtube10-01 18:14:31.720  4600  4614 E ActivityManager: ANR in com.google.android.apps.plus10-01 18:14:31.720  4600  4614 E ActivityManager: PID: 3036310-01 18:14:31.720  4600  4614 E ActivityManager: Reason: executing service com.google.android.apps.plus/com.google.android.apps.photos.service.PhotosService10-01 18:14:31.720  4600  4614 E ActivityManager: Load: 35.27 / 23.9 / 16.1810-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 major10-01 18:14:31.720  4600  4614 E ActivityManager:   41% 4600/system_server: 18% user + 23% kernel / faults: 18597 minor 309 major10-01 18:14:31.720  4600  4614 E ActivityManager:   32% 27420/com.google.android.GoogleCamera: 24% user + 7.8% kernel / faults: 48374 minor 338 major10-01 18:14:31.720  4600  4614 E ActivityManager:   16% 130/kswapd0: 0% user + 16% kernel10-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

通过这两种log都能看出进程30363在执行com.google.android.apps.plus/com.google.android.apps.photos.service.PhotosService时发生了ANR，event log更加简明，不过需要对着EventLogTags.logtags文件看，logcat更加易懂写。看自己的喜好吧。

接着需要看/data/anr下traces.txt文件的栈信息了，看栈信息的主要注意事项就是要确保该traces.txt是对应ANR的文件，因为系统可能发生了多次ARN，/data/anr路径下可能有多个文件，接着我们要找到发生ANR进程的栈信息：

----- pid 30363 at 2015-10-01 18:14:11 -----Cmd line: com.google.android.apps.plusBuild fingerprint: 'google/angler/angler:6.0/MDA89D/2294819:userdebug/dev-keys'ABI: 'arm'Build type: optimizedZygote loaded classes=3978 post zygote classes=27Intern table: 45068 strong; 21 weakJNI: 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 objectsDumping cumulative Gc timingsTotal number of allocations 32251Total bytes allocated 21MBTotal bytes freed 0BFree memory 9MBFree memory until GC 9MBFree memory until OOME 490MBTotal memory 30MBMax memory 512MBZygote space size 1260KBTotal mutator paused time: 0Total time waiting for GC to complete: 0Total GC count: 0Total GC time: 0Total blocking GC count: 0Total blocking GC time: 0suspend all histogram:  Sum: 119.728ms 99% C.I. 0.010ms-107.765ms Avg: 5.442ms Max: 119.562msDALVIK 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@[e-mail] (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的形式出现，但如果是对于system server进程，看门狗会要死system server进程，从而导致系统重启，而且这种情况会有类似“WATCHDOG KILLING SYSTEM PROCESS”这种log出现。

检查这种问题，需要检查VM的log，这是logcat就不行了，抓dumpstate的log吧，然后搜索“held by thread”关键字，然后一点一点细致的检查，如下面网上的log：

"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)

线程73要的锁被线程20持有，而线程20申请的锁被线程73持有。

Activities

看焦点activity

关键字am_focused_activity

进程启动历史

关键字Start proc

确认设备是否抖动

关键字am_proc_died和am_proc_start，检查是否在短时间内出现了大量的这样的log