[]Android ANR analysis solution

A: what is ANR

ANR:Application Not Responding, The application of non response

Two: the type of ANR

There are three types of ANR:

1. KeyDispatchTimeout(5 seconds) The main types of buttons or touch events -- no response within a specified time.

2. BroadcastTimeout(10 seconds) --BroadcastReceiver cannot complete the processing within a specified time.

3. ServiceTimeout(20 seconds) Small probability of type Service cannot process completed within the specified time

Three: KeyDispatchTimeout

Akey or touch event was not dispatched within the specified time (button or the touch event no response in a particular period of time)

The definition of a specific timeout in under framework ActivityManagerService.java

//How long we wait until we timeout on key dispatching.

staticfinal int KEY_DISPATCHING_TIMEOUT = 5*1000

Four: why will timeout.?

Count timeout is generally to app began distributing from the key. Overtime two general reasons:

(1)Current events have no chance of getting treatment (i.e. UI thread is processing before an event, not timely completed or looper is somehow blocked)

(2)The event is being processed, but was not completed in time

Five: how to avoid KeyDispatchTimeout

1 the UI thread to do only with UI related work

2 time consuming work (operations such as database operation, I/O, connect to the network or the other may hinder the UI thread) put it into the thread processing alone

3 try to use Handler to handle the interaction between UIthread and other thread

Six: the UI thread

Said so much UI thread, which belongs to the UI thread.?

The UI thread mainly include the following:

1. Activity:onCreate(), onResume(), onDestroy(), onKeyDown(), onClick(),etc

2. AsyncTask: onPreExecute(), onProgressUpdate(), onPostExecute(), onCancel,etc

3. Mainthread handler: handleMessage(), post*(runnable r), etc

4. other

Seven: how to analysis ANR

Look at the LOG:

04-01 13:12:11.572 I/InputDispatcher( 220): Application is not responding:Window{2b263310com.android.email/com.android.email.activity.SplitScreenActivitypaused=false}. 5009.8ms since event, 5009.5ms since waitstarted 04-0113:12:11.572 I/WindowManager( 220): Input event dispatching timedout sending tocom.android.email/com.android.email.activity.SplitScreenActivity 04-01 13:12:14.123 I/Process( 220): Sending signal. PID: 21404 SIG: 3---HappenANRTime and generationtrace.txtTime 04-01 13:12:14.123 I/dalvikvm(21404):threadid=4: reacting to signal 3 …… 04-0113:12:15.872 E/ActivityManager( 220): ANR in com.android.email(com.android.email/.activity.SplitScreenActivity) 04-0113:12:15.872 E/ActivityManager( 220): Reason:keyDispatchingTimedOut 04-0113:12:15.872 E/ActivityManager( 220): Load: 8.68 / 8.37 / 8.53 04-0113:12:15.872 E/ActivityManager( 220): CPUusage from 4361ms to 699ms ago ----CPUIn theANRUse before 04-0113:12:15.872 E/ActivityManager( 220): 5.5%21404/com.android.email: 1.3% user + 4.1% kernel / faults: 10 minor 04-0113:12:15.872 E/ActivityManager( 220): 4.3%220/system_server: 2.7% user + 1.5% kernel / faults: 11 minor 2 major 04-0113:12:15.872 E/ActivityManager( 220): 0.9%52/spi_qsd.0: 0% user + 0.9% kernel 04-0113:12:15.872 E/ActivityManager( 220): 0.5%65/irq/170-cyttsp-: 0% user + 0.5% kernel 04-0113:12:15.872 E/ActivityManager( 220): 0.5%296/com.android.systemui: 0.5% user + 0% kernel 04-0113:12:15.872 E/ActivityManager( 220): 100%TOTAL: 4.8% user + 7.6% kernel + 87% iowait 04-0113:12:15.872 E/ActivityManager( 220): CPUusage from 3697ms to 4223ms later:-- ANRAfter theCPUThe use of 04-0113:12:15.872 E/ActivityManager( 220): 25%21404/com.android.email: 25% user + 0% kernel / faults: 191 minor 04-0113:12:15.872 E/ActivityManager( 220): 16% 21603/__eas(par.hakan: 16% user + 0% kernel 04-0113:12:15.872 E/ActivityManager( 220): 7.2% 21406/GC: 7.2% user + 0% kernel 04-0113:12:15.872 E/ActivityManager( 220): 1.8% 21409/Compiler: 1.8% user + 0% kernel 04-0113:12:15.872 E/ActivityManager( 220): 5.5%220/system_server: 0% user + 5.5% kernel / faults: 1 minor 04-0113:12:15.872 E/ActivityManager( 220): 5.5% 263/InputDispatcher: 0% user + 5.5% kernel 04-0113:12:15.872 E/ActivityManager( 220): 32%TOTAL: 28% user + 3.7% kernel

As can be seen from the LOG type of ANR, CPU usage, if the usage of CPU is close to 100%, indicating the current device is busy, there may be CPU starvation resulted in ANR

If the CPU amount used few, that the main thread is BLOCK.

If IOwait is high, indicating that ANR may be the main thread in the I/O operation by

In addition to LOG, ANR also needs to have the trace.txt file,

How to get? Can be obtained by the following command

$chmod 777 /data/anr

$rm /data/anr/traces.txt

$ps

$kill -3 PID

adbpull data/anr/traces.txt ./mytraces.txt
From the trace.txt file, see the most of the information is as follows:

-----pid 21404 at 2011-04-01 13:12:14 ----- Cmdline: com.android.email DALVIK THREADS: (mutexes: tll=0tsl=0 tscl=0 ghl=0 hwl=0 hwll=0) "main" prio=5 tid=1NATIVE | group="main" sCount=1 dsCount=0obj=0x2aad2248 self=0xcf70 | sysTid=21404 nice=0 sched=0/0cgrp=[fopen-error:2] handle=1876218976 atandroid.os.MessageQueue.nativePollOnce(Native Method) atandroid.os.MessageQueue.next(MessageQueue.java:119) atandroid.os.Looper.loop(Looper.java:110) at android.app.ActivityThread.main(ActivityThread.java:3688) at java.lang.reflect.Method.invokeNative(Native Method) atjava.lang.reflect.Method.invoke(Method.java:507) atcom.android.internal.os.ZygoteInit$MethodAndArgsCaller.run(ZygoteInit.java:866) at com.android.internal.os.ZygoteInit.main(ZygoteInit.java:624) at dalvik.system.NativeStart.main(Native Method)


That the main thread is waiting for the next message into the message queue

Eight: Thread state

ThreadState (defined at “dalvik/vm/thread.h “)

   THREAD_UNDEFINED = -1, /* makes enum compatible with int32_t */

   THREAD_ZOMBIE = 0, /* TERMINATED */

   THREAD_RUNNING = 1, /* RUNNABLE or running now */

   THREAD_TIMED_WAIT = 2, /* TIMED_WAITING in Object.wait() */

   THREAD_MONITOR = 3, /* BLOCKED on a monitor */

   THREAD_WAIT = 4, /* WAITING in Object.wait() */

   THREAD_INITIALIZING= 5, /* allocated, not yet running */

   THREAD_STARTING = 6, /* started, not yet on thread list */

   THREAD_NATIVE = 7, /* off in a JNI native method */

   THREAD_VMWAIT = 8, /* waiting on a VM resource */

   THREAD_SUSPENDED = 9, /* suspended, usually by GC or debugger */

Nine: how to investigate and resolve ANR

1 first analysis log

2 from the trace.txt file call stack.

3 see code

4 check the ANR origin(iowait?block?memoryleak?)

Case ten:

Case 1: key words: ContentResolver in AsyncTask onPostExecute, high iowait

Process:com.android.email Activity:com.android.email/.activity.MessageView Subject:keyDispatchingTimedOut CPU usage from 2550ms to -2814ms ago: 5%187/system_server: 3.5% user + 1.4% kernel / faults: 86 minor 20major 4.4% 1134/com.android.email: 0.7% user + 3.7% kernel /faults: 38 minor 19 major 4% 372/com.android.eventstream: 0.7%user + 3.3% kernel / faults: 6 minor 1.1% 272/com.android.phone:0.9% user + 0.1% kernel / faults: 33 minor 0.9%252/com.android.systemui: 0.9% user + 0% kernel 0%409/com.android.eventstream.telephonyplugin: 0% user + 0% kernel /faults: 2 minor 0.1% 632/com.android.devicemonitor: 0.1% user + 0%kernel 100%TOTAL: 6.9% user + 8.2% kernel +84%iowait -----pid 1134 at 2010-12-17 17:46:51 ----- Cmd line:com.android.email DALVIK THREADS: (mutexes: tll=0 tsl=0tscl=0 ghl=0 hwl=0 hwll=0) "main" prio=5 tid=1 WAIT |group="main" sCount=1 dsCount=0 obj=0x2aaca180self=0xcf20 | sysTid=1134 nice=0 sched=0/0 cgrp=[fopen-error:2]handle=1876218976 at java.lang.Object.wait(Native Method) -waiting on <0x2aaca218> (a java.lang.VMThread) atjava.lang.Thread.parkFor(Thread.java:1424) atjava.lang.LangAccessImpl.parkFor(LangAccessImpl.java:48) atsun.misc.Unsafe.park(Unsafe.java:337) atjava.util.concurrent.locks.LockSupport.park(LockSupport.java:157) atjava.util.concurrent.locks.AbstractQueuedSynchronizer.parkAndCheckInterrupt(AbstractQueuedSynchronizer.java:808) atjava.util.concurrent.locks.AbstractQueuedSynchronizer.acquireQueued(AbstractQueuedSynchronizer.java:841) atjava.util.concurrent.locks.AbstractQueuedSynchronizer.acquire(AbstractQueuedSynchronizer.java:1171) atjava.util.concurrent.locks.ReentrantLock$FairSync.lock(ReentrantLock.java:200) atjava.util.concurrent.locks.ReentrantLock.lock(ReentrantLock.java:261) atandroid.database.sqlite.SQLiteDatabase.lock(SQLiteDatabase.java:378) atandroid.database.sqlite.SQLiteCursor.<init>(SQLiteCursor.java:222) atandroid.database.sqlite.SQLiteDirectCursorDriver.query(SQLiteDirectCursorDriver.java:53) atandroid.database.sqlite.SQLiteDatabase.rawQueryWithFactory(SQLiteDatabase.java:1356) atandroid.database.sqlite.SQLiteDatabase.queryWithFactory(SQLiteDatabase.java:1235) atandroid.database.sqlite.SQLiteDatabase.query(SQLiteDatabase.java:1189) atandroid.database.sqlite.SQLiteDatabase.query(SQLiteDatabase.java:1271) atcom.android.email.provider.EmailProvider.query(EmailProvider.java:1098) atandroid.content.ContentProvider$Transport.query(ContentProvider.java:187) atandroid.content.ContentResolver.query(ContentResolver.java:268) atcom.android.email.provider.EmailContent$Message.restoreMessageWithId(EmailContent.java:648) atcom.android.email.Controller.setMessageRead(Controller.java:658) atcom.android.email.activity.MessageView.onMarkAsRead(MessageView.java:700) atcom.android.email.activity.MessageView.access$2500(MessageView.java:98) atcom.android.email.activity.MessageView$LoadBodyTask.onPostExecute(MessageView.java:1290) atcom.android.email.activity.MessageView$LoadBodyTask.onPostExecute(MessageView.java:1255) atandroid.os.AsyncTask.finish(AsyncTask.java:417) atandroid.os.AsyncTask.access$300(AsyncTask.java:127) atandroid.os.AsyncTask$InternalHandler.handleMessage(AsyncTask.java:429) atandroid.os.Handler.dispatchMessage(Handler.java:99) atandroid.os.Looper.loop(Looper.java:123) atandroid.app.ActivityThread.main(ActivityThread.java:3652) atjava.lang.reflect.Method.invokeNative(Native Method) atjava.lang.reflect.Method.invoke(Method.java:507) atcom.android.internal.os.ZygoteIn

Reason: IOWait is very high, the current system with I/O, so the database operation is blocked

Original:

final Message message=Message.restoreMessageWithId(mProviderContext,messageId); if(message==null){ return; } Account account=Account.restoreAccountWithId(mProviderContext,message.mAccountKey); if(account==null){ return;//isMessagingController returns false for null, but let's make itclear. } if(isMessagingController(account)){ new Thread(){ @Override public void run(){ mLegacyController.processPendingActions(message.mAccountKey); }}.start(); }

After the solution:


newThread() { finalMessagemessage=Message.restoreMessageWithId(mProviderContext,messageId); if(message==null){ return; } Accountaccount=Account.restoreAccountWithId(mProviderContext,message.mAccountKey); if(account==null){ return;//isMessagingController returns false for null, but let's make itclear. } if(isMessagingController(account)) { mLegacyController.processPendingActions(message.mAccountKey); } }.start();

About AsyncTask:http://developer.android.com/reference/android/os/AsyncTask.html


Case 2: Keywords: network data read and write on the UI thread

ANRin process: com.android.mediascape:PhotoViewer (last incom.android.mediascape:PhotoViewer) Annotation:keyDispatchingTimedOut CPU usage: Load: 6.74 / 6.89 / 6.12 CPUusage from 8254ms to 3224ms ago: ovider.webmedia: 4% = 4% user +0% kernel / faults: 68 minor system_server: 2% = 1% user + 0%kernel / faults: 18 minor re-initialized>: 0% = 0% user + 0%kernel / faults: 50 minor events/0: 0% = 0% user + 0%kernel TOTAL:7% = 6% user + 1% kernel DALVIKTHREADS: ""main"" prio=5 tid=3 NATIVE |group=""main"" sCount=1 dsCount=0 s=Yobj=0x4001b240 self=0xbda8 | sysTid=2579 nice=0 sched=0/0cgrp=unknown handle=-1343993184 atorg.apache.harmony.luni.platform.OSNetworkSystem.receiveStreamImpl(NativeMethod) atorg.apache.harmony.luni.platform.OSNetworkSystem.receiveStream(OSNetworkSystem.java:478) atorg.apache.harmony.luni.net.PlainSocketImpl.read(PlainSocketImpl.java:565) atorg.apache.harmony.luni.net.SocketInputStream.read(SocketInputStream.java:87) atorg.apache.harmony.luni.internal.net.www.protocol.http.HttpURLConnection$LimitedInputStream.read(HttpURLConnection.java:303) atjava.io.InputStream.read(InputStream.java:133) atjava.io.BufferedInputStream.fillbuf(BufferedInputStream.java:157) atjava.io.BufferedInputStream.read(BufferedInputStream.java:346) atandroid.graphics.BitmapFactory.nativeDecodeStream(Native Method) atandroid.graphics.BitmapFactory.decodeStream(BitmapFactory.java:459) atcom.android.mediascape.activity.PhotoViewerActivity.getPreviewImage(PhotoViewerActivity.java:4465) atcom.android.mediascape.activity.PhotoViewerActivity.dispPreview(PhotoViewerActivity.java:4406) atcom.android.mediascape.activity.PhotoViewerActivity.access$6500(PhotoViewerActivity.java:125) atcom.android.mediascape.activity.PhotoViewerActivity$33$1.run(PhotoViewerActivity.java:4558) atandroid.os.Handler.handleCallback(Handler.java:587) atandroid.os.Handler.dispatchMessage(Handler.java:92) atandroid.os.Looper.loop(Looper.java:123) atandroid.app.ActivityThread.main(ActivityThread.java:4370) atjava.lang.reflect.Method.invokeNative(Native Method) atjava.lang.reflect.Method.invoke(Method.java:521) atcom.android.internal.os.ZygoteInit$MethodAndArgsCaller.run(ZygoteInit.java:868) atcom.android.internal.os.ZygoteInit.main(ZygoteInit.java:626) atdalvik.system.NativeStart.main(Native Method)

A network connection, in the design of the time can be set to timeout at a time or in a separate thread to handle.

Questions about Handler, can refer to: http://developer.android.com/reference/android/os/Handler.html

   

Case 3: Keyword: Memoryleak/Thread leak

11-1621:41:42.560 I/ActivityManager( 1190): ANR in process:android.process.acore (last in android.process.acore) 11-1621:41:42.560 I/ActivityManager( 1190): Annotation:keyDispatchingTimedOut 11-16 21:41:42.560 I/ActivityManager(1190): CPU usage: 11-16 21:41:42.560 I/ActivityManager( 1190):Load: 11.5 / 11.1 / 11.09 11-16 21:41:42.560 I/ActivityManager(1190): CPU usage from 9046ms to 4018ms ago: 11-16 21:41:42.560I/ActivityManager( 1190): d.process.acore:98%= 97% user + 0% kernel / faults: 1134 minor 11-16 21:41:42.560I/ActivityManager( 1190): system_server: 0% = 0% user + 0% kernel /faults: 1 minor 11-16 21:41:42.560 I/ActivityManager( 1190): adbd:0% = 0% user + 0% kernel 11-16 21:41:42.560 I/ActivityManager(1190): logcat: 0% = 0% user + 0% kernel 11-16 21:41:42.560I/ActivityManager( 1190): TOTAL:100% = 98% user + 1% kernel Cmdline: android.process.acore DALVIK THREADS: "main"prio=5 tid=3 VMWAIT |group="main" sCount=1 dsCount=0 s=N obj=0x40026240self=0xbda8 | sysTid=1815 nice=0 sched=0/0 cgrp=unknownhandle=-1344001376 atdalvik.system.VMRuntime.trackExternalAllocation(NativeMethod) atandroid.graphics.Bitmap.nativeCreate(Native Method) atandroid.graphics.Bitmap.createBitmap(Bitmap.java:468) atandroid.view.View.buildDrawingCache(View.java:6324) atandroid.view.View.getDrawingCache(View.java:6178) atandroid.view.ViewGroup.drawChild(ViewGroup.java:1541) …… atcom.android.internal.policy.impl.PhoneWindow$DecorView.draw(PhoneWindow.java:1830) atandroid.view.ViewRoot.draw(ViewRoot.java:1349) atandroid.view.ViewRoot.performTraversals(ViewRoot.java:1114) atandroid.view.ViewRoot.handleMessage(ViewRoot.java:1633) atandroid.os.Handler.dispatchMessage(Handler.java:99) atandroid.os.Looper.loop(Looper.java:123) atandroid.app.ActivityThread.main(ActivityThread.java:4370) atjava.lang.reflect.Method.invokeNative(Native Method) atjava.lang.reflect.Method.invoke(Method.java:521) atcom.android.internal.os.ZygoteInit$MethodAndArgsCaller.run(ZygoteInit.java:868) atcom.android.internal.os.ZygoteInit.main(ZygoteInit.java:626) atdalvik.system.NativeStart.main(Native Method) "Thread-408"prio=5 tid=329 WAIT |group="main" sCount=1 dsCount=0 s=N obj=0x46910d40self=0xcd0548 | sysTid=10602 nice=0 sched=0/0 cgrp=unknownhandle=15470792 at java.lang.Object.wait(Native Method) -waiting on <0x468cd420> (a java.lang.Object) atjava.lang.Object.wait(Object.java:288) atcom.android.dialer.CallLogContentHelper$UiUpdaterExecutor$1.run(CallLogContentHelper.java:289) atjava.lang.Thread.run(Thread.java:1096)

Analysis:

atdalvik.system.VMRuntime.trackExternalAllocation(NativeMethod)Insufficient memory to create block in bitmap

   **MEMINFO in pid 1360 [android.process.acore] **

           native dalvik other total

           size: 17036 23111 N/A 40147

           allocated: 16484 20675 N/A 37159

           free: 296 2436 N/A 2732

Solution: if the machine's memory, you can modify the virtual machine's memory is 36M or more, but it is best to review code, see what memory is not released

Posted by Kristine at November 24, 2013 - 3:36 AM