如何分析Android的Log

首先，讓我們看一看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文件。