Android Log分析

最新推荐文章于 2023-05-23 14:58:19 发布

VIP文章快马夜小刀

最新推荐文章于 2023-05-23 14:58:19 发布

阅读量4.1k

点赞数 2

分类专栏： Android 文章标签： android bug

本文链接：https://blog.csdn.net/wfeii/article/details/56501747

版权

Bug在任何类型的开发中都会存在的，而Bug报告又是定位问题，解决问题的关键。

Bug报告中包含的内容：

logcat文件以文字形式存储所有的log信息
- main 包含了所有的log
- system log 存储framework相关的log
- event log 进程的正在做的事情
dumpsys获取系统运行状态的信息，通过adb shell 可以获取想要的系统信息，内存使用情况的信息等等
- Activity Manager的状态 - dumpsys activity
- Package信息 - dumpsys package
- 内存使用情况 - dumpsys meminfo
- 进程一段时间内的内存使用情况 - dumpsys procstats
- 界面相关的状态 - dumpsys gfxinfo
dumpstate 系统运行状态的信息

常用命令：
adb shell bugreport 获取logcat信息，dumpsys信息，dumpstate信息
adb shell logcat -v threadtime -d 获取logcat文件
adb shell logcat -b events -v threadtime -d 获取events log
adb shell logcat -b main -v threadtime -d 获取main log
adb shell dumpsys 获取系统信息。
adb shell dumpstate 获取系统状态信息，dumpstate包含dumpsys

下面的部分会细化bug报告中的各部分，描述一个问题给出相关技巧和使用grep来查找相关的log

LogCat

logcat文件以文字形式存储了所有了的日志信息，system 部分存储了framework的相关log，而 main 包含了所有log。每行log都以 timestamp PID(Process ID) TID(Thread ID) log-level 开头。

\------ SYSTEM LOG (logcat -v threadtime -d *:v) ------
--------- beginning of system  
Blah  
Blah  
Blah  

--------- beginning of main  
Blah   
Blah  
Blah

阅读event log

event log 里面包含了文字形式的二进格式的log信息，它比logcat里面的信息简洁但是更难理解。当阅读event log的时候，我们应该搜索特定的PID来看进程做了什么，格式为timestamp PID TID log-level log-tag tag-values.

log等级包括：
- V: verbose
- D: debug
- I: information
- W: warning
- E: error

------ 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]  
...

对于Event log标签更详细的信息,可以阅读Event log tags

ANR和死锁

log能帮助我们找到导致ANR错误和死锁原因。

识别无响应的APP

当应用一段时间无响应的时候，通常是由于主线程阻塞了或者是主线程做的事太多。系统会kill掉应用并且把相关的堆栈信息存储在/data/anr目录下。
可以使用grep am_anr在event log找到原因：

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]

或者在logcat中使用grep ANR来搜索，搜索结果将会包含ANR有关CPU使用的信息。

查找堆栈信息

我们经常可以发现对应的ANR的堆栈信息，确保时间和进程ID匹配正在调查的ANR。然后检查进程的主线的相关堆栈信息。

需要牢记的:

主线程只是说明线程ANR的时候正在做什么，但是不一定是造成ANR的原因（堆栈信息可能是无辜的，有些事可能卡顿了主线程一段时间但是不足以构成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