$ kill -l
1) SIGHUP 2) SIGINT 3) SIGQUIT 4) SIGILL
5) SIGTRAP 6) SIGABRT 7) SIGBUS 8) SIGFPE
9) SIGKILL 10) SIGUSR1 11) SIGSEGV 12) SIGUSR2
13) SIGPIPE 14) SIGALRM 15) SIGTERM 17) SIGCHLD
18) SIGCONT 19) SIGSTOP 20) SIGTSTP 21) SIGTTIN
22) SIGTTOU 23) SIGURG 24) SIGXCPU 25) SIGXFSZ
26) SIGVTALRM 27) SIGPROF 28) SIGWINCH29) SIGIO
30) SIGPWR 31) SIGSYS 34) SIGRTMIN35) SIGRTMIN+1
36) SIGRTMIN+2 37) SIGRTMIN+3 38) SIGRTMIN+4 39) SIGRTMIN+5
40) SIGRTMIN+6 41) SIGRTMIN+7 42) SIGRTMIN+8 43) SIGRTMIN+9
44) SIGRTMIN+10 45) SIGRTMIN+11 46) SIGRTMIN+12 47) SIGRTMIN+13
48) SIGRTMIN+14 49) SIGRTMIN+15 50) SIGRTMAX-14 51) SIGRTMAX-13
52) SIGRTMAX-12 53) SIGRTMAX-11 54) SIGRTMAX-10 55) SIGRTMAX-9
56) SIGRTMAX-8 57) SIGRTMAX-7 58) SIGRTMAX-6 59) SIGRTMAX-5
60) SIGRTMAX-4 61) SIGRTMAX-3 62) SIGRTMAX-2 63) SIGRTMAX-1
64) SIGRTMAX
首先,让我们看一看AndroidLog的格式。下面这段log是以所谓的long格式打印出来的。从前面Logcat的介绍中可以知道,long格式会把时间,标签等作为单独的一行显示。[ 12-09 21:39:35.510 396: 416 I/ActivityManager ]
Start procnet.coollet.infzmreader:umengService_v1 for service
net.coollet.infzmreader/com.umeng.message.
UmengService:pid=21745 uid=10039 gids={50039, 3003, 1015,1028}
[ 12-09 21:39:35.518 21745:21745I/dalvikvm ]
Turning on JNI app bug workarounds fortarget SDK version 8...
[ 12-09 21:39:35.611 21745:21745D/AgooService ]
onCreate()
我们以第一行为例:12-09 是日期,21:39:35.510是时间396是进程号,416是线程号;I代表log优先级,ActivityManager是log标签。
在应用开发中,这些信息的作用可能不是很大。但是在系统开发中,这些都是很重要的辅助信息。开发工程师分析的log很多都是由测试工程师抓取的,所以可能有些log根本就不是当时出错的log。如果出现这种情况,无论你怎么分析都不太可能得出正确的结论。如何能最大限度的避免这种情况呢?笔者就要求测试工程师报bug时必须填上bug发生的时间。这样结合log里的时间戳信息就能大致判断是否是发生错误时的log。而且根据测试工程师提供的bug发生时间点,开发工程师可以在长长的log信息中快速的定位错误的位置,缩小分析的范围。
同时我们也要注意,时间信息在log分析中可能被错误的使用。例如:在分析多线程相关的问题时,我们有时需要根据两段不同线程中log语句执行的先后顺序来判断错误发生的原因,但是我们不能以两段log在log文件中出现的先后做为判断的条件,这是因为在小段时间内两个线程输出log的先后是随机的,log打印的先后顺序并不完全等同于执行的顺序。那么我们是否能以log的时间戳来判断呢?同样是不可以,因为这个时间戳实际上是系统打印输出log时的时间,并不是调用log函数时的时间。遇到这种情况唯一的办法是在输出log前,调用系统时间函数获取当时时间,然后再通过log信息打印输出。这样虽然麻烦一点,但是只有这样取得的时间才是可靠的,才能做为我们判断的依据。
另外一种误用log中时间戳的情况是用它来分析程序的性能。一个有多年工作经验的工程师拿着他的性能分析结果给笔者看,但是笔者对这份和实际情况相差很远的报告表示怀疑,于是询问这位工程师是如何得出结论的。他的回答让笔者很惊讶,他计算所采用的数据就是log信息前面的时间戳。前面我们已经讲过,log前面时间戳和调用log函数的时间并不相同,这是由于系统缓冲log信息引起的,而且这两个时间的时间差并不固定。所以用log信息前附带的时间戳来计算两段log间代码的性能会有比较大的误差。正确的方法还是上面提到的:在程序中获取系统时间然后打印输出,利用我们打印的时间来计算所花费的时间。
了解了时间,我们再谈谈进程Id和线程Id,它们也是分析log时很重要的依据。我们看到的log文件,不同进程的log信息实际上是混杂在一起输出的,这给我们分析log带来了很大的麻烦。有时即使是一个函数内的两条相邻的log,也会出现不同进程的log交替输出的情况,也就是A进程的第一条log后面跟着的是B进程的第二条log,对于这样的组合如果不细心分析,就很容易得出错误的结论。这时一定要仔细看log前面的进程Id,把相同Id的log放到一起看。
不同进程的log有这样的问题,不同的线程输出的log当然也存在着相同的问题。Logcat加上-vthread就能打印出线程Id。但是有一点也要引起注意,就是Android的线程Id和我们平时所讲的Linux线程Id并不完全等同。首先,在Android系统中,C++层使用的Linux获取线程Id的函数gettid()是不能得到线程Id的,调用gettid()实际上返回的是进程Id。作为替代,我们可以调用pthread_self()得到一个唯一的值来标示当前的native线程。Android也提供了一个函数androidGetThreaId()来获取线程Id,这个函数实际上就是在调用pthread_self函数。但是在Java层线程Id又是另外一个值,Java层的线程Id是通过调用Thread的getId方法得到的,这个方法的返回值实际上来自Android在每个进程的java层中维护的一个全局变量,所以这个值和C++层所获得的值并不相同。这也是我们分析log时要注意的问题,如果是Java层线程Id,一般值会比较小,几百左右;如果是C++层的线程,值会比较大。在前里面的log样本中,就能很容易的看出,第一条log是Jave层输出的log,第二条是native层输出的。明白了这些,我们在分析log时就不要看见两段log前面的线程Id不相同就得出是两个不同线程log的简单结论,还要注意Jave层和native层的区别,这样才能防止被误导。
AndroidLog的优先级在打印输出时会被转换成V,I,D,W,E等简单的字符标记。在做系统log分析时,我们很难把一个log文件从头看到尾,都是利用搜索工具来查找出错的标记。比如搜索“E/”来看看有没有指示错误的log。所以如果参与系统开发的每个工程师都能遵守Android定义的优先级含义来输出log,这会让我们繁重的log分析工作变得相对轻松些。
Android比较常见的严重问题有两大类,一是程序发生崩溃;二是产生了ANR。程序崩溃和ANR既可能发生在java层,也可能发生在native层。如果问题发生在java层,出错的原因一般比较容易定位。如果是native层的问题,在很多情况下,解决问题就不是那么的容易了。我们先看一个java层的崩溃例子:
I/ActivityManager( 396): Start proccom.test.crash for activity com.test.crash/.MainActivity:
pid=1760 uid=10065 gids={50065, 1028}
D/AndroidRuntime( 1760): Shutting downVM
W/dalvikvm( 1760): threadid=1: threadexiting with uncaught exception(group=0x40c38930)
E/AndroidRuntime( 1760): FATALEXCEPTION: main
E/AndroidRuntime( 1760):java.lang.RuntimeException: Unable to start activityComponentInfo
{com.test.crash/com.test.crash.MainActivity}:java.lang.NullPointerException
E/AndroidRuntime( 1760): atandroid.app.ActivityThread.performLaunchActivity(ActivityThread.java:2180)
E/AndroidRuntime( 1760): atandroid.app.ActivityThread.handleLaunchActivity(ActivityThread.java:2230)
E/AndroidRuntime( 1760): atandroid.app.ActivityThread.access$600(ActivityThread.java:141)
E/AndroidRuntime( 1760): atandroid.app.ActivityThread$H.handleMessage(ActivityThread.java:1234)
E/AndroidRuntime( 1760): atandroid.os.Handler.dispatchMessage(Handler.java:99)
E/AndroidRuntime( 1760): atandroid.os.Looper.loop(Looper.java:137)
E/AndroidRuntime( 1760): atandroid.app.ActivityThread.main(ActivityThread.java:5050)
E/AndroidRuntime( 1760): atjava.lang.reflect.Method.invokeNative(NativeMethod)
E/AndroidRuntime( 1760): atjava.lang.reflect.Method.invoke(Method.java:511)
E/AndroidRuntime( 1760): atcom.android.internal.os.ZygoteInit$MethodAndArgsCaller.run
(ZygoteInit.java:793)
E/AndroidRuntime( 1760): atcom.android.internal.os.ZygoteInit.main(ZygoteInit.java:560)
E/AndroidRuntime( 1760): atdalvik.system.NativeStart.main(NativeMethod)
E/AndroidRuntime( 1760): Caused by:java.lang.NullPointerException
E/AndroidRuntime( 1760): atcom.test.crash.MainActivity.setViewText(MainActivity.java:29)
E/AndroidRuntime( 1760): atcom.test.crash.MainActivity.onCreate(MainActivity.java:17)
E/AndroidRuntime( 1760): atandroid.app.Activity.performCreate(Activity.java:5104)
E/AndroidRuntime( 1760): atandroid.app.Instrumentation.callActivityOnCreate(Instrumentation.java:1080)
E/AndroidRuntime( 1760): atandroid.app.ActivityThread.performLaunchActivity(ActivityThread.java:2144)
E/AndroidRuntime( 1760): ... 11more
I/Process ( 1760): Sending signal.PID: 1760 SIG: 9
W/ActivityManager( 396): Force finishing activitycom.test.crash/.MainActivity
Jave层的代码发生crash问题时,系统往往会打印出很详细的出错信息。比如上面这个例子,不但给出了出错的原因,还有出错的文件和行数。根据这些信息,我们会很容易的定位问题所在。native层的crash虽然也有栈log信息输出,但是就不那么容易看懂了。下面我们再看一个native层crash的例子:
F/libc ( 2102): Fatal signal 11 (SIGSEGV) at 0x00000000 (code=1), thread2102 (testapp)
D/dalvikvm(26630):GC_FOR_ALLOC freed 604K, 11% free 11980K/13368K, paused 36ms, total36ms
I/dalvikvm-heap(26630):Grow heap (frag case) to 11.831MB for 102416-byteallocation
D/dalvikvm(26630):GC_FOR_ALLOC freed 1K, 11% free 12078K/13472K, paused 34ms, total34ms
I/DEBUG ( 127):*** *** *** *** *** *** *** *** *** *** *** *** *** *** ******
I/DEBUG ( 127):Build fingerprint:
'Android/full_maguro/maguro:4.2.2/JDQ39/eng.liuchao.20130619.201255:userdebug/test-keys'
I/DEBUG ( 127):Revision: '9'
I/DEBUG ( 127):pid: 2102, tid: 2102, name: testapp >>>./testapp <<<
I/DEBUG ( 127):signal 11 (SIGSEGV), code 1 (SEGV_MAPERR), fault addr00000000
I/DEBUG ( 127): r0 00000020 r173696874 r2 400ff520 r300000000
I/DEBUG ( 127): r4 400ff469 r5beb4ab24 r6 00000001 r7beb4ab2c
I/DEBUG ( 127): r8 00000000 r900000000 sl 00000000 fpbeb4ab1c
I/DEBUG ( 127): ip 4009b5dc spbeb4aae8 lr 400ff46f pc400ff45e cpsr 60000030
I/DEBUG ( 127): d0 000000004108dae8 d1 4108ced84108cec8
I/DEBUG ( 127): d2 4108cef84108cee8 d3 4108cf184108cf08
I/DEBUG ( 127): d4 4108c5a84108c598 d5 4108ca084108c5b8
I/DEBUG ( 127): d6 4108ce684108ce58 d7 4108ce884108ce78
I/DEBUG ( 127): d8 0000000000000000 d9 0000000000000000
I/DEBUG ( 127): d10 0000000000000000 d110000000000000000
I/DEBUG ( 127): d120000000000000000 d130000000000000000
I/DEBUG ( 127): d14 0000000000000000 d150000000000000000
I/DEBUG ( 127): d16 c1dcf7c087fec8b4 d173f50624dd2f1a9fc
I/DEBUG ( 127): d18 41c7b1ac89800000 d190000000000000000
I/DEBUG ( 127): d20 0000000000000000 d210000000000000000
I/DEBUG ( 127): d22 0000000000000000 d230000000000000000
I/DEBUG ( 127): d24 0000000000000000 d250000000000000000
I/DEBUG ( 127): d26 0000000000000000 d270000000000000000
I/DEBUG ( 127): d28 0000000000000000 d290000000000000000
I/DEBUG ( 127): d30 0000000000000000 d310000000000000000
I/DEBUG ( 127): scr 00000010
I/DEBUG ( 127):
I/DEBUG ( 127):backtrace:
I/DEBUG ( 127): #00 pc0000045e /system/bin/testapp
I/DEBUG ( 127): #01 pc0000046b /system/bin/testapp
I/DEBUG ( 127): #02 pc0001271f /system/lib/libc.so (__libc_init+38)
I/DEBUG ( 127): #03 pc00000400 /system/bin/testapp
I/DEBUG ( 127):
I/DEBUG ( 127):stack:
I/DEBUG ( 127): beb4aaa8 000000c8
I/DEBUG ( 127): beb4aaac 00000000
I/DEBUG ( 127): beb4aab0 00000000
I/DEBUG ( 127): beb4aab4 401cbee0 /system/bin/linker
I/DEBUG ( 127): beb4aab8 00001000
I/DEBUG ( 127): beb4aabc 4020191d /system/lib/libc.so (__libc_fini)
I/DEBUG ( 127): beb4aac0 4020191d /system/lib/libc.so (__libc_fini)
I/DEBUG ( 127): beb4aac4 40100eac /system/bin/testapp
I/DEBUG ( 127): beb4aac8 00000000
I/DEBUG ( 127): beb4aacc 400ff469 /system/bin/testapp
I/DEBUG ( 127): beb4aad0 beb4ab24 [stack]
I/DEBUG ( 127): beb4aad4 00000001
I/DEBUG ( 127): beb4aad8 beb4ab2c [stack]
I/DEBUG ( 127): beb4aadc 00000000
I/DEBUG ( 127): beb4aae0 df0027ad
I/DEBUG ( 127): beb4aae4 00000000
I/DEBUG ( 127): #00 beb4aae8 00000000
I/DEBUG ( 127): ........ ........
I/DEBUG ( 127): #01 beb4aae8 00000000
I/DEBUG ( 127): beb4aaec 401e9721 /system/lib/libc.so (__libc_init+40)
I/DEBUG ( 127): #02 beb4aaf0 beb4ab08 [stack]
I/DEBUG ( 127): beb4aaf4 00000000
I/DEBUG ( 127): beb4aaf8 00000000
I/DEBUG ( 127): beb4aafc 00000000
I/DEBUG ( 127): beb4ab00 00000000
I/DEBUG ( 127): beb4ab04 400ff404 /system/bin/testapp
I/DEBUG ( 127):
这个log就不那么容易懂了,但是还是能从中看出很多信息,让我们一起来学习如何分析这种log。首先看下面这行:
pid: 2102, tid: 2102,name: testapp >>>./testapp <<<
从这一行我们可以知道crash进程的pid和tid,前文我们已经提到过,Android调用gettid函数得到的实际是进程Id号,所以这里的pid和tid相同。知道进程号后我们可以往前翻翻log,看看该进程最后一次打印的log是什么,这样能缩小一点范围。
接下来内容是进程名和启动参数。再接下来的一行比较重要了,它告诉了我们从系统角度看,出错的原因:
signal 11 (SIGSEGV), code 1(SEGV_MAPERR), fault addr 00000000
signal11是Linux定义的信号之一,含义是Invalidmemory reference,无效的内存引用。加上后面的“faultaddr 00000000”我们基本可以判定这是一个空指针导致的crash。当然这是笔者为了讲解而特地制造的一个Crash的例子,比较容易判断,大部分实际的例子可能就没有那么容易了。
再接下来的log打印出了cpu的所有寄存器的信息和堆栈的信息,这里面最重要的是从堆栈中得到的backtrace信息:
I/DEBUG ( 127):backtrace:
I/DEBUG ( 127): #00 pc0000045e /system/bin/testapp
I/DEBUG ( 127): #01 pc0000046b /system/bin/testapp
I/DEBUG ( 127): #02 pc0001271f /system/lib/libc.so (__libc_init+38)
I/DEBUG ( 127): #03 pc00000400 /system/bin/testapp
因为实际的运行系统里没有符号信息,所以打印出的log里看不出文件名和行数。这就需要我们借助编译时留下的符号信息表来翻译了。Android提供了一个工具可以来做这种翻译工作:arm-eabi-addr2line,位于prebuilts/gcc/linux-x86/arm/arm-eabi-4.6/bin目录下。用法很简单:
#./arm-eabi-addr2line -f -eout/target/product/hammerhead/symbols/system/bin/testapp0x0000045e
参数-f表示打印函数名;参数-e表示带符号表的模块路径;最后是要转换的地址。这条命令在笔者的编译环境中得到的结果是:
memcpy /home/rd/compile/android-4.4_r1.2/bionic/libc/include/string.h:108
剩余三个地址翻译如下:
main /home/rd/compile/android-4.4_r1.2/packages/apps/testapp/app_main.cpp:38
out_vformat /home/rd/compile/android-4.4_r1.2/bionic/libc/bionic/libc_logging.cpp:361
_start libgcc2.c:0
利用这些信息我们很快就能定位问题了。不过这样手动一条一条的翻译比较麻烦,笔者使用的是从网上找到的一个脚本,可以一次翻译所有的行,有需要的读者可以在网上找一找。
了解了如何分析普通的Log文件,下面让我们再看看如何分析ANR的Log文件。
欢迎分享,转载请注明来源:内存溢出
评论列表(0条)