Android ANR log traceログファイル分析
14973 ワード
取得システムcrash log:adb shell dumpsys dropbox--print>>log.txt
Trace ?
APP( APP APP) ANR、 WatchDog ,
dump top , Thread dump Trace .final void appNotResponding(ProcessRecord app, ActivityRecord activity,
ActivityRecord parent, boolean aboveSystem, final String annotation) {
// ... ...
if (MONITOR_CPU_USAGE) {
updateCpuStatsNow(); // CPU
}
// ... ...
final ProcessCpuTracker processCpuTracker = new ProcessCpuTracker(true);
// dumpStackTraces traces
File tracesFile = dumpStackTraces(true, firstPids, processCpuTracker, lastPids,
NATIVE_STACKS_OF_INTEREST);
String cpuInfo = null;
if (MONITOR_CPU_USAGE) {
updateCpuStatsNow(); // CPU
synchronized (mProcessCpuTracker) {
// ANR CPU
cpuInfo = mProcessCpuTracker.printCurrentState(anrTime);
}
info.append(processCpuTracker.printCurrentLoad());
info.append(cpuInfo);
}
// ANR CPU
info.append(processCpuTracker.printCurrentState(anrTime));
Slog.e(TAG, info.toString());
if (tracesFile == null) {
// There is no trace file, so dump (only) the alleged culprit's threads to the log
Process.sendSignal(app.pid, Process.SIGNAL_QUIT);
}
// ANR DropBox
addErrorToDropBox("anr", app, app.processName, activity, parent, annotation,
cpuInfo, tracesFile, null);
// ... ...
synchronized (this) {
// ANR
// Bring up the infamous App Not Responding dialog
Message msg = Message.obtain();
HashMap map = new HashMap();
msg.what = SHOW_NOT_RESPONDING_MSG;
msg.obj = map;
msg.arg1 = aboveSystem ? 1 : 0;
map.put("app", app);
if (activity != null) {
map.put("activity", activity);
}
mUiHandler.sendMessage(msg);
}
}
ANRを避ける?
ANRのログを分析する:
ANRのロゴは以下の通りです.
06-22 10:37:46.204 3547 3604 E ActivityManager: ANR in org.code:MessengerService // ANR
E ActivityManager: PID: 17027 // ANR ID
E ActivityManager: Reason: executing service org.code/.ipc.MessengerService // ANR
E ActivityManager: Load: 8.31 / 8.12 / 8.47
E ActivityManager: CPU usage from 0ms to 6462ms later: //CPU ANR
E ActivityManager: 61% 3547/system_server: 21% user + 39% kernel / faults: 13302 minor 2 major
E ActivityManager: 0.2% 475/debuggerd: 0% user + 0.1% kernel / faults: 6086 minor 1 major
E ActivityManager: 10% 5742/com.android.phone: 5.1% user + 5.1% kernel / faults: 7597 minor
E ActivityManager: 6.9% 5342/com.android.systemui: 2.1% user + 4.8% kernel / faults: 4158 minor
E ActivityManager: 0.1% 477/debuggerd64: 0% user + 0.1% kernel / faults: 4013 minor
E ActivityManager: 5.7% 16313/org.code: 3.2% user + 2.4% kernel / faults: 2412 minor
E ActivityManager: 3.7% 17027/org.code:MessengerService: 1.7% user + 2% kernel / faults: 2571 minor 6 major
E ActivityManager: 2.6% 306/cfinteractive: 0% user + 2.6% kernel
... ...
E ActivityManager: +0% 17168/kworker/0:1: 0% user + 0% kernel
E ActivityManager: 0% TOTAL: 0% user + 0% kernel + 0% softirq // CUP
E ActivityManager: CPU usage from 5628ms to 6183ms later:
E ActivityManager: 42% 3547/system_server: 17% user + 24% kernel / faults: 11 minor
E ActivityManager: 12% 3604/ActivityManager: 1.7% user + 10% kernel
E ActivityManager: 12% 3609/android.display: 8.7% user + 3.5% kernel
E ActivityManager: 3.5% 5304/Binder_6: 1.7% user + 1.7% kernel
E ActivityManager: 3.5% 5721/Binder_A: 1.7% user + 1.7% kernel
E ActivityManager: 3.5% 5746/Binder_C: 3.5% user + 0% kernel
E ActivityManager: 1.7% 3599/Binder_1: 0% user + 1.7% kernel
E ActivityManager: 1.7% 3600/Binder_2: 0% user + 1.7% kernel
I ActivityManager: Killing 17027:org.code:MessengerService/u0a85 (adj 1): bg anr
I art : Wrote stack traces to '/data/anr/traces.txt' //art TAG traces
D GraphicsStats: Buffer count: 9
W ActivityManager: Scheduling restart of crashed service org.code/.ipc.MessengerService in 1000ms
logはANRの基本情報を印刷して、私達はCPUの使用率を分析してANRが発生する時設備がどんな仕事をしているかを推測することができます;CPUの使用率が高く、100%に近い場合は、大規模な計算を行っている可能性があり、デッドサイクルに陥る可能性があります.CUPの使用率が低い場合は、メインスレッドがブロックする、IOwaitが高い場合は、メインスレッドがI/O動作の完了を待っている可能性がある.
ANRがログを分析するだけでは問題点が分かりにくいので、Traceファイルでstack呼び出し状況を分析する必要があります.
----- pid 17027 at 2017-06-22 10:37:39 ----- // ANR pid ( log pid )
Cmd line: org.code:MessengerService // ANR
Build fingerprint: 'Homecare/qucii8976v3_64:6.0.1/pansen06141150:eng/test-keys' // ,
ABI: 'arm64'
Build type: optimized
Zygote loaded classes=6576 post zygote classes=13
Intern table: 13780 strong; 17 weak
JNI: CheckJNI is on; globals=283 (plus 158 weak)
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)
Heap: 29% free, 8MB/12MB; 75731 objects
Dumping cumulative Gc timings
Total number of allocations 75731
Total bytes allocated 8MB
Total bytes freed 0B
Free memory 3MB
Free memory until GC 3MB
Free memory until OOME 183MB
Total memory 12MB
Max memory 192MB
Zygote space size 3MB
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: 76us 99% C.I. 0.100us-28us Avg: 7.600us Max: 28us
DALVIK THREADS (15):
// Signal Catcher traces
// Signal Catche( )、(daemon) 、prio( , 5)、tid( ID)、Runnable( )
"Signal Catcher" daemon prio=5 tid=3 Runnable
// 、suspendCount、debugSuspendCount、 Java 、 Native
| group="system" sCount=0 dsCount=0 obj=0x12d8f0a0 self=0x5598ae55d0
//sysTid ( )
| sysTid=17033 nice=0 cgrp=default sched=0/0 handle=0x7fb2350450
| state=R schedstat=( 4348125 172343 3 ) utm=0 stm=0 core=1 HZ=100
| stack=0x7fb2254000-0x7fb2256000 stackSize=1013KB
| held mutexes= "mutator lock"(shared held)
native: #00 pc 0000000000489e28 /system/lib64/libart.so (art::DumpNativeStack(std::__1::basic_ostream >&, int, char const*, art::ArtMethod*, void*)+236)
native: #01 pc 0000000000458fe8 /system/lib64/libart.so (art::Thread::Dump(std::__1::basic_ostream >&) const+220)
native: #02 pc 0000000000465bc8 /system/lib64/libart.so (art::DumpCheckpoint::Run(art::Thread*)+688)
native: #03 pc 0000000000466ae0 /system/lib64/libart.so (art::ThreadList::RunCheckpoint(art::Closure*)+276)
native: #04 pc 000000000046719c /system/lib64/libart.so (art::ThreadList::Dump(std::__1::basic_ostream >&)+188)
native: #05 pc 0000000000467a84 /system/lib64/libart.so (art::ThreadList::DumpForSigQuit(std::__1::basic_ostream >&)+492)
native: #06 pc 0000000000431194 /system/lib64/libart.so (art::Runtime::DumpForSigQuit(std::__1::basic_ostream >&)+96)
native: #07 pc 000000000043e604 /system/lib64/libart.so (art::SignalCatcher::HandleSigQuit()+1256)
native: #08 pc 000000000043f214 /system/lib64/libart.so (art::SignalCatcher::Run(void*)+452)
native: #09 pc 0000000000068714 /system/lib64/libc.so (__pthread_start(void*)+52)
native: #10 pc 000000000001c604 /system/lib64/libc.so (__start_thread+16)
(no managed stack frames)
//main( )、prio( , 5)、tid( ID)、Sleeping( )
"main" prio=5 tid=1 Sleeping
| group="main" sCount=1 dsCount=0 obj=0x73132d10 self=0x5598a5f5e0
//sysTid ( )
| sysTid=17027 nice=0 cgrp=default sched=0/0 handle=0x7fb6db6fe8
| state=S schedstat=( 420582038 5862546 143 ) utm=24 stm=18 core=6 HZ=100
| stack=0x7fefba3000-0x7fefba5000 stackSize=8MB
| held mutexes=
// java ( ANR )( ANR )
at java.lang.Thread.sleep!(Native method)
- sleeping on <0x0c60f3c7> (a java.lang.Object)
at java.lang.Thread.sleep(Thread.java:1031)
- locked <0x0c60f3c7> (a java.lang.Object) // 0x0c60f3c7
at java.lang.Thread.sleep(Thread.java:985)
at android.os.SystemClock.sleep(SystemClock.java:120)
at org.code.ipc.MessengerService.onCreate(MessengerService.java:63) // ANR
at android.app.ActivityThread.handleCreateService(ActivityThread.java:2877)
at android.app.ActivityThread.access$1900(ActivityThread.java:150)
at android.app.ActivityThread$H.handleMessage(ActivityThread.java:1427)
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)
logに表示されるpidはtracesファイルに対応しており、trace logには現在のすべてのスレッドのスタック情報が印刷されます.一般的にmainスレッドのスタックに注目します(他のスレッドを分析する場合もありますが、ANR発生時のシステム状態を分析することでデバイスが進行中であると推測します).
ここではスタック呼び出し情報を見ることによりANRのコードを解析する.上記ANRは実際にorg.code.ipc.MessengerService.onCreateの63行はSystemClockを呼び出す.sleep(10000)コードによる;比較的単純なANRの例である.
以上はANR問題を解決するために一つの構想を提供しただけで、具体的な問題は実際の状況によって具体的に分析する必要がある.
スレッドステータスの分類:javaで定義されたスレッドステータス:
// libcore/libart/src/main/java/java/lang/Thread.java
/**
* A representation of a thread's state. A given thread may only be in one
* state at a time.
*/
public enum State {
/**
* The thread has been created, but has never been started.
*/
NEW,
/**
* The thread may be run.
*/
RUNNABLE,
/**
* The thread is blocked and waiting for a lock.
*/
BLOCKED,
/**
* The thread is waiting.
*/
WAITING,
/**
* The thread is waiting for a specified amount of time.
*/
TIMED_WAITING,
/**
* The thread has been terminated.
*/
TERMINATED
}
Cコードで定義されたスレッドのステータス:
// /art/runtime/thread_state.h
enum ThreadState {
// Thread.State JDWP state
kTerminated = 66, // TERMINATED TS_ZOMBIE Thread.run has returned, but Thread* still around
kRunnable, // RUNNABLE TS_RUNNING runnable
kTimedWaiting, // TIMED_WAITING TS_WAIT in Object.wait() with a timeout
kSleeping, // TIMED_WAITING TS_SLEEPING in Thread.sleep()
kBlocked, // BLOCKED TS_MONITOR blocked on a monitor
kWaiting, // WAITING TS_WAIT in Object.wait()
kWaitingForGcToComplete, // WAITING TS_WAIT blocked waiting for GC
kWaitingForCheckPointsToRun, // WAITING TS_WAIT GC waiting for checkpoints to run
kWaitingPerformingGc, // WAITING TS_WAIT performing GC
kWaitingForDebuggerSend, // WAITING TS_WAIT blocked waiting for events to be sent
kWaitingForDebuggerToAttach, // WAITING TS_WAIT blocked waiting for debugger to attach
kWaitingInMainDebuggerLoop, // WAITING TS_WAIT blocking/reading/processing debugger events
kWaitingForDebuggerSuspension, // WAITING TS_WAIT waiting for debugger suspend all
kWaitingForJniOnLoad, // WAITING TS_WAIT waiting for execution of dlopen and JNI on load code
kWaitingForSignalCatcherOutput, // WAITING TS_WAIT waiting for signal catcher IO to complete
kWaitingInMainSignalCatcherLoop, // WAITING TS_WAIT blocking/reading/processing signals
kWaitingForDeoptimization, // WAITING TS_WAIT waiting for deoptimization suspend all
kWaitingForMethodTracingStart, // WAITING TS_WAIT waiting for method tracing to start
kWaitingForVisitObjects, // WAITING TS_WAIT waiting for visiting objects
kWaitingForGetObjectsAllocated, // WAITING TS_WAIT waiting for getting the number of allocated objects
kStarting, // NEW TS_WAIT native thread started, not yet ready to run managed code
kNative, // RUNNABLE TS_RUNNING running in a JNI native method
kSuspended, // RUNNABLE TS_RUNNING suspended by GC or debugger
};
両者は、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関数を実行します
ZOMBIE ，
RUNNING/RUNNABLE
TIMED_WAIT wait、sleep join
MONITOR ，
WAIT wait
INITIALIZING ， ，
STARTING ，
NATIVE JNI
VMWAIT VM
SUSPENDED ， GC debug