Android ANR log trace日誌文件分析

 

 

版權聲明：本文爲博主原創文章，遵循 CC 4.0 BY-SA 版權協議，轉載請附上原文出處連接和本聲明。

本文連接： https://blog.csdn.net/qq_25804863/article/details/49111005

• 什麼是ANR?

  ANR:Application Not Responding，即應用無響應

• ANR日誌Trace文件獲取

  系統生成的Trace文件保存在data/anr,能夠用過命令adb pull data/anr/取出

  traces.txt只保留最後一次ANR的信息,Android系統有個DropBox功能功能,它能記錄系統出現的crash錯誤.所以保留有發生過的ANR的信息.(log路徑:/data/system/dropbox)

  獲取系統crash log: adb shell dumpsys dropbox --print >>log.txt

1.  
   Trace文件怎麼生成的?
2.  
   當 APP(包括系統APP和用戶APP)進程出現ANR、應用響應慢或WatchDog的監視沒有獲得回饋時,
3.  
   系統會 dump此時的top進程,進程中Thread的運行狀態就都dump到這個Trace文件中了.

• 致使ANR的常見幾種狀況:

  1：Input dispatching timed out(5 seconds) 按鍵或觸摸事件處理超時(通常是UI主線程作了耗時的操做,這類ANR最多見)

  2：BroadcastTimeout(10 seconds) 廣播的分發和處理超時(通常是onReceiver執行時間過長)

  3：ServiceTimeout(20 seconds) Service的啓動和執行超時

  另外還有ProviderTimeout和WatchDog等致使的ANR.還有當系統內存或CPU資源不足時容易出現ANR,通常這種狀況會有lowmemorykill的log打印.

  應用ANR產生的時候,ActivityManagerService的appNotResponding方法就會被調用,而後在/data/anr/traces.txt文件中寫入ANR相關信息.

1.  
   final void appNotResponding(ProcessRecord app, ActivityRecord activity,
2.  
   ActivityRecord parent, boolean aboveSystem, final String annotation) {
3.  
   // ... ...
4.  
   if (MONITOR_CPU_USAGE) {
5.  
   updateCpuStatsNow(); // 更新CPU使用率
6.  
   }
7.  
   // ... ...
8.  
   final ProcessCpuTracker processCpuTracker = new ProcessCpuTracker(true);
9.  
   // dumpStackTraces是輸出traces文件的函數
10.  
    File tracesFile = dumpStackTraces( true, firstPids, processCpuTracker, lastPids,
11.  
    NATIVE_STACKS_OF_INTEREST);
12.  
     
13.  
    String cpuInfo = null;
14.  
    if (MONITOR_CPU_USAGE) {
15.  
    updateCpuStatsNow(); // 再次更新CPU信息
16.  
    synchronized (mProcessCpuTracker) {
17.  
    // 輸出ANR發生前一段時間內的CPU使用率
18.  
    cpuInfo = mProcessCpuTracker.printCurrentState(anrTime);
19.  
    }
20.  
    info.append(processCpuTracker.printCurrentLoad());
21.  
    info.append(cpuInfo);
22.  
    }
23.  
    // 輸出ANR發生後一段時間內的CPU使用率
24.  
    info.append(processCpuTracker.printCurrentState(anrTime));
25.  
     
26.  
    Slog.e(TAG, info.toString());
27.  
    if (tracesFile == null) {
28.  
    // There is no trace file, so dump (only) the alleged culprit's threads to the log
29.  
    Process.sendSignal(app.pid, Process.SIGNAL_QUIT);
30.  
    }
31.  
    // 將ANR信息同時輸出到DropBox中
32.  
    addErrorToDropBox( "anr", app, app.processName, activity, parent, annotation,
33.  
    cpuInfo, tracesFile, null);
34.  
    // ... ...
35.  
    synchronized (this) {
36.  
    // 顯示ANR提示對話框
37.  
    // Bring up the infamous App Not Responding dialog
38.  
    Message msg = Message.obtain();
39.  
    HashMap<String, Object> map = new HashMap<String, Object>();
40.  
    msg.what = SHOW_NOT_RESPONDING_MSG;
41.  
    msg.obj = map;
42.  
    msg.arg1 = aboveSystem ? 1 : 0;
43.  
    map.put( "app", app);
44.  
    if (activity != null) {
45.  
    map.put( "activity", activity);
46.  
    }
47.  
    mUiHandler.sendMessage(msg);
48.  
    }
49.  
    }

避免ANR?

1. UI線程儘可能只作跟UI相關的工做

2. 耗時的工做（好比數據庫操做，I/O，鏈接網絡或者別的有可能阻礙UI線程的操做）把它放入單獨的線程處理

3. 儘可能用Handler來處理UIthread和別的thread之間的交互

分析ANR的Log:

出現ANR的log以下:

1.  
   06-22 10:37:46.204 3547 3604 E ActivityManager: ANR in org.code:MessengerService // ANR出現的進程包名
2.  
    
3.  
   E ActivityManager: PID: 17027 // ANR進程ID
4.  
    
5.  
   E ActivityManager: Reason: executing service org.code/.ipc.MessengerService //致使ANR的緣由
6.  
    
7.  
   E ActivityManager: Load: 8.31 / 8.12 / 8.47
8.  
    
9.  
   E ActivityManager: CPU usage from 0ms to 6462ms later: //CPU在ANR發生後的使用狀況
10.  
     
11.  
    E ActivityManager: 61% 3547/system_server: 21% user + 39% kernel / faults: 13302 minor 2 major
12.  
     
13.  
    E ActivityManager: 0.2% 475/debuggerd: 0% user + 0.1% kernel / faults: 6086 minor 1 major
14.  
     
15.  
    E ActivityManager: 10% 5742/com.android.phone: 5.1% user + 5.1% kernel / faults: 7597 minor
16.  
     
17.  
    E ActivityManager: 6.9% 5342/com.android.systemui: 2.1% user + 4.8% kernel / faults: 4158 minor
18.  
     
19.  
    E ActivityManager: 0.1% 477/debuggerd64: 0% user + 0.1% kernel / faults: 4013 minor
20.  
     
21.  
    E ActivityManager: 5.7% 16313/org.code: 3.2% user + 2.4% kernel / faults: 2412 minor
22.  
     
23.  
    E ActivityManager: 3.7% 17027/org.code:MessengerService: 1.7% user + 2% kernel / faults: 2571 minor 6 major
24.  
     
25.  
    E ActivityManager: 2.6% 306/cfinteractive: 0% user + 2.6% kernel
26.  
    ... ...
27.  
    E ActivityManager: + 0% 17168/kworker/0:1: 0% user + 0% kernel
28.  
     
29.  
    E ActivityManager: 0% TOTAL: 0% user + 0% kernel + 0% softirq // CUP佔用狀況
30.  
     
31.  
    E ActivityManager: CPU usage from 5628ms to 6183ms later:
32.  
     
33.  
    E ActivityManager: 42% 3547/system_server: 17% user + 24% kernel / faults: 11 minor
34.  
     
35.  
    E ActivityManager: 12% 3604/ActivityManager: 1.7% user + 10% kernel
36.  
     
37.  
    E ActivityManager: 12% 3609/android.display: 8.7% user + 3.5% kernel
38.  
     
39.  
    E ActivityManager: 3.5% 5304/Binder_6: 1.7% user + 1.7% kernel
40.  
     
41.  
    E ActivityManager: 3.5% 5721/Binder_A: 1.7% user + 1.7% kernel
42.  
     
43.  
    E ActivityManager: 3.5% 5746/Binder_C: 3.5% user + 0% kernel
44.  
     
45.  
    E ActivityManager: 1.7% 3599/Binder_1: 0% user + 1.7% kernel
46.  
     
47.  
    E ActivityManager: 1.7% 3600/Binder_2: 0% user + 1.7% kernel
48.  
     
49.  
    I ActivityManager: Killing 17027:org.code:MessengerService/u0a85 (adj 1): bg anr
50.  
     
51.  
    I art : Wrote stack traces to '/data/anr/traces.txt' //art這個TAG打印對traces操做的信息
52.  
     
53.  
    D GraphicsStats: Buffer count: 9
54.  
     
55.  
    W ActivityManager: Scheduling restart of crashed service org.code/.ipc.MessengerService in 1000ms
56.  
     

log打印了ANR的基本信息,咱們能夠分析CPU使用率推測ANR發生的時候設備在作什麼工做;若是CPU使用率很高,接近100%,多是在進行大規模的計算更多是陷入死循環;若是CUP使用率很低,說明主線程被阻塞了,而且當IOwait很高,多是主線程在等待I/O操做的完成.

對於ANR只是分析Log很難知道問題所在,咱們還須要經過Trace文件分析stack調用狀況.

1.  
    
2.  
   ----- pid 17027 at 2017-06-22 10:37:39 ----- // ANR出現的進程pid和時間(和上述log中pid一致)
3.  
   Cmd line: org.code:MessengerService // ANR出現的進程名
4.  
   Build fingerprint: 'Homecare/qucii8976v3_64:6.0.1/pansen06141150:eng/test-keys' // 下面記錄系統版本,內存等狀態信息
5.  
   ABI: 'arm64'
6.  
   Build type: optimized
7.  
   Zygote loaded classes= 6576 post zygote classes=13
8.  
   Intern table: 13780 strong; 17 weak
9.  
   JNI: CheckJNI is on; globals= 283 (plus 158 weak)
10.  
    Libraries: /system/lib64/libandroid.so /system/lib64/libcompiler_rt.so /system/lib64/libjavacrypto.so /system/lib64/libjnigraphics.so /system/lib64/libmedia_jni.so /system/lib64/libwebviewchromium_loader.so libjavacore.so ( 7)
11.  
    Heap: 29% free, 8MB/12MB; 75731 objects
12.  
    Dumping cumulative Gc timings
13.  
    Total number of allocations 75731
14.  
    Total bytes allocated 8MB
15.  
    Total bytes freed 0B
16.  
    Free memory 3MB
17.  
    Free memory until GC 3MB
18.  
    Free memory until OOME 183MB
19.  
    Total memory 12MB
20.  
    Max memory 192MB
21.  
    Zygote space size 3MB
22.  
    Total mutator paused time: 0
23.  
    Total time waiting for GC to complete: 0
24.  
    Total GC count: 0
25.  
    Total GC time: 0
26.  
    Total blocking GC count: 0
27.  
    Total blocking GC time: 0
28.  
     
29.  
    suspend all histogram: Sum: 76us 99% C.I. 0.100us-28us Avg: 7.600us Max: 28us
30.  
    DALVIK THREADS ( 15):
31.  
    // Signal Catcher是記錄traces信息的線程
32.  
    // Signal Catche(線程名)、(daemon)表示守護進程、prio(線程優先級,默認是5)、tid(線程惟一標識ID)、Runnable(線程當前狀態)
33.  
    "Signal Catcher" daemon prio=5 tid=3 Runnable
34.  
    //線程組名稱、suspendCount、debugSuspendCount、線程的Java對象地址、線程的Native對象地址
35.  
    | group= "system" sCount=0 dsCount=0 obj=0x12d8f0a0 self=0x5598ae55d0
36.  
    //sysTid是線程號(主線程的線程號和進程號相同)
37.  
    | sysTid= 17033 nice=0 cgrp=default sched=0/0 handle=0x7fb2350450
38.  
    | state=R schedstat=( 4348125 172343 3 ) utm=0 stm=0 core=1 HZ=100
39.  
    | stack= 0x7fb2254000-0x7fb2256000 stackSize=1013KB
40.  
    | held mutexes= "mutator lock"(shared held)
41.  
    native: #00 pc 0000000000489e28 /system/lib64/libart.so (art::DumpNativeStack(std::__1::basic_ostream<char, std::__1::char_traits<char> >&, int, char const*, art::ArtMethod*, void*)+236)
42.  
    native: #01 pc 0000000000458fe8 /system/lib64/libart.so (art::Thread::Dump(std::__1::basic_ostream<char, std::__1::char_traits<char> >&) const+220)
43.  
    native: #02 pc 0000000000465bc8 /system/lib64/libart.so (art::DumpCheckpoint::Run(art::Thread*)+688)
44.  
    native: #03 pc 0000000000466ae0 /system/lib64/libart.so (art::ThreadList::RunCheckpoint(art::Closure*)+276)
45.  
    native: #04 pc 000000000046719c /system/lib64/libart.so (art::ThreadList::Dump(std::__1::basic_ostream<char, std::__1::char_traits<char> >&)+188)
46.  
    native: #05 pc 0000000000467a84 /system/lib64/libart.so (art::ThreadList::DumpForSigQuit(std::__1::basic_ostream<char, std::__1::char_traits<char> >&)+492)
47.  
    native: #06 pc 0000000000431194 /system/lib64/libart.so (art::Runtime::DumpForSigQuit(std::__1::basic_ostream<char, std::__1::char_traits<char> >&)+96)
48.  
    native: #07 pc 000000000043e604 /system/lib64/libart.so (art::SignalCatcher::HandleSigQuit()+1256)
49.  
    native: #08 pc 000000000043f214 /system/lib64/libart.so (art::SignalCatcher::Run(void*)+452)
50.  
    native: #09 pc 0000000000068714 /system/lib64/libc.so (__pthread_start(void*)+52)
51.  
    native: #10 pc 000000000001c604 /system/lib64/libc.so (__start_thread+16)
52.  
    (no managed stack frames)
53.  
     
54.  
    //main(線程名)、prio(線程優先級,默認是5)、tid(線程惟一標識ID)、Sleeping(線程當前狀態)
55.  
    "main" prio=5 tid=1 Sleeping
56.  
    | group= "main" sCount=1 dsCount=0 obj=0x73132d10 self=0x5598a5f5e0
57.  
    //sysTid是線程號(主線程的線程號和進程號相同)
58.  
    | sysTid= 17027 nice=0 cgrp=default sched=0/0 handle=0x7fb6db6fe8
59.  
    | state=S schedstat=( 420582038 5862546 143 ) utm=24 stm=18 core=6 HZ=100
60.  
    | stack= 0x7fefba3000-0x7fefba5000 stackSize=8MB
61.  
    | held mutexes=
62.  
    // java 堆棧調用信息(這裏可查看致使ANR的代碼調用流程)(分析ANR最重要的信息)
63.  
    at java.lang.Thread.sleep!(Native method)
64.  
    - sleeping on < 0x0c60f3c7> (a java.lang.Object)
65.  
    at java.lang.Thread.sleep(Thread.java: 1031)
66.  
    - locked < 0x0c60f3c7> (a java.lang.Object) // 鎖住對象0x0c60f3c7
67.  
    at java.lang.Thread.sleep(Thread.java: 985)
68.  
    at android.os.SystemClock.sleep(SystemClock.java: 120)
69.  
    at org.code.ipc.MessengerService.onCreate(MessengerService.java: 63) //致使ANR的代碼
70.  
    at android.app.ActivityThread.handleCreateService(ActivityThread.java: 2877)
71.  
    at android.app.ActivityThread.access$ 1900(ActivityThread.java:150)
72.  
    at android.app.ActivityThread$H.handleMessage(ActivityThread.java: 1427)
73.  
    at android.os.Handler.dispatchMessage(Handler.java: 102)
74.  
    at android.os.Looper.loop(Looper.java: 148)
75.  
    at android.app.ActivityThread.main(ActivityThread.java: 5417)
76.  
    at java.lang.reflect.Method.invoke!(Native method)
77.  
    at com.android.internal.os.ZygoteInit$MethodAndArgsCaller.run(ZygoteInit.java: 726)
78.  
    at com.android.internal.os.ZygoteInit.main(ZygoteInit.java: 616)

在log中顯示的pid在traces文件中與之對應,trace log中會打印當前全部線程的堆棧信息,通常咱們主要關注main線程的堆棧(也有分析其餘線程的狀況,經過分析ANR發生時系統狀態推測出設備正在進行操做)

而這裏而後經過查看堆棧調用信息分析ANR的代碼.上述ANR實際上在org.code.ipc.MessengerService.onCreate中63行調用SystemClock.sleep(10000)代碼致使的;這是比較簡單ANR示例.

以上僅爲解決ANR問題提供一個思路,具體問題還須要根據實際狀況具體分析

---

線程狀態的分類: java中定義的線程狀態:

1.  
   // libcore/libart/src/main/java/java/lang/Thread.java
2.  
   /**
3.  
   * A representation of a thread's state. A given thread may only be in one
4.  
   * state at a time.
5.  
   */
6.  
   public enum State {
7.  
   /**
8.  
   * The thread has been created, but has never been started.
9.  
   */
10.  
    NEW,
11.  
    /**
12.  
    * The thread may be run.
13.  
    */
14.  
    RUNNABLE,
15.  
    /**
16.  
    * The thread is blocked and waiting for a lock.
17.  
    */
18.  
    BLOCKED,
19.  
    /**
20.  
    * The thread is waiting.
21.  
    */
22.  
    WAITING,
23.  
    /**
24.  
    * The thread is waiting for a specified amount of time.
25.  
    */
26.  
    TIMED_WAITING,
27.  
    /**
28.  
    * The thread has been terminated.
29.  
    */
30.  
    TERMINATED
31.  
    }

C代碼中定義的線程狀態:

1.  
   / / /art/runtime/thread_state.h
2.  
   enum ThreadState {
3.  
   // Thread.State JDWP state
4.  
   kTerminated = 66, // TERMINATED TS_ZOMBIE Thread.run has returned, but Thread* still around
5.  
   kRunnable, // RUNNABLE TS_RUNNING runnable
6.  
   kTimedWaiting, // TIMED_WAITING TS_WAIT in Object.wait() with a timeout
7.  
   kSleeping, // TIMED_WAITING TS_SLEEPING in Thread.sleep()
8.  
   kBlocked, // BLOCKED TS_MONITOR blocked on a monitor
9.  
   kWaiting, // WAITING TS_WAIT in Object.wait()
10.  
    kWaitingForGcToComplete, // WAITING TS_WAIT blocked waiting for GC
11.  
    kWaitingForCheckPointsToRun, // WAITING TS_WAIT GC waiting for checkpoints to run
12.  
    kWaitingPerformingGc, // WAITING TS_WAIT performing GC
13.  
    kWaitingForDebuggerSend, // WAITING TS_WAIT blocked waiting for events to be sent
14.  
    kWaitingForDebuggerToAttach, // WAITING TS_WAIT blocked waiting for debugger to attach
15.  
    kWaitingInMainDebuggerLoop, // WAITING TS_WAIT blocking/reading/processing debugger events
16.  
    kWaitingForDebuggerSuspension, // WAITING TS_WAIT waiting for debugger suspend all
17.  
    kWaitingForJniOnLoad, // WAITING TS_WAIT waiting for execution of dlopen and JNI on load code
18.  
    kWaitingForSignalCatcherOutput, // WAITING TS_WAIT waiting for signal catcher IO to complete
19.  
    kWaitingInMainSignalCatcherLoop, // WAITING TS_WAIT blocking/reading/processing signals
20.  
    kWaitingForDeoptimization, // WAITING TS_WAIT waiting for deoptimization suspend all
21.  
    kWaitingForMethodTracingStart, // WAITING TS_WAIT waiting for method tracing to start
22.  
    kWaitingForVisitObjects, // WAITING TS_WAIT waiting for visiting objects
23.  
    kWaitingForGetObjectsAllocated, // WAITING TS_WAIT waiting for getting the number of allocated objects
24.  
    kStarting, // NEW TS_WAIT native thread started, not yet ready to run managed code
25.  
    kNative, // RUNNABLE TS_RUNNING running in a JNI native method
26.  
    kSuspended, // RUNNABLE TS_RUNNING suspended by GC or debugger
27.  
    };

二者能夠看出在C代碼中定義更爲詳細,Traces中顯示的線程狀態都是C代碼定義的.咱們能夠經過查看線程狀態對應的信息分析ANR問題.

如: TimedWaiting對應的線程狀態是TIMED_WAITING

kTimedWaiting, // TIMED_WAITING TS_WAIT in Object.wait() with a timeout 執行了無超時參數的wait函數

kSleeping, // TIMED_WAITING TS_SLEEPING in Thread.sleep() 執行了帶有超時參數的sleep函數

1.  
   ZOMBIE 線程死亡，終止運行
2.  
   RUNNING/RUNNABLE 線程可運行或正在運行
3.  
   TIMED_WAIT 執行了帶有超時參數的 wait、sleep或join函數
4.  
   MONITOR 線程阻塞，等待獲取對象鎖
5.  
   WAIT 執行了無超時參數的 wait函數
6.  
   INITIALIZING 新建，正在初始化，爲其分配資源
7.  
   STARTING 新建，正在啓動
8.  
   NATIVE 正在執行JNI本地函數
9.  
   VMWAIT 正在等待VM資源
10.  
    SUSPENDED 線程暫停，一般是因爲GC或debug被暫停