Android ANR Solution case (internal information)

When the ANR occurs , you first need to view the log information and the trace file (the system will be /data/anr/ generated under directory Trace files ) Analyze the cause of ANR . The following analysis does not solve all the ANRencountered, but the program itself causes the ANR problem basically can find the reason.

LogInformation Analysis

04-01 13:12:11.572 I/inputdispatcher (): application is not responding:window{2b263310com.android.email/ Com.android.email.activity.splitscreenactivitypaused=false}. 5009.8ms since event, 5009.5ms since waitstarted--anr at the interface 04-0113:12:11.572 I/windowmanager: Input Event Dispatch ing timedout sendingtocom.android.email/com.android.email.activity.splitscreenactivity--can see the type of ANR (Keydispatchtimeout (5 Seconds), broadcasttimeout (seconds), servicetimeout (seconds)) 04-01 13:12:14.123 i/process (): Sending signal. pid:21404 sig:3---Generate trace.txt time 04-01 13:12:14.123 I/DALVIKVM (21404): threadid=4:reacting to signal 3 ... 04-0113:12:15.872 E/activitymanager: ANR in Com.android.email (com.android.email/.activity. splitscreenactivity) 04-0113:12:15.872 E/activitymanager (): reason:keydispatchingtimedout04-0113:12:15.872 E/ Activitymanager: load:8.68/8.37/8.5304-0113:12:15.872 e/activitymanager: CPUUsage from 4361ms to 699ms ago ----CPU usage before ANR occurs 04-0113:12:15.872E/activitymanager: 5.5!404/com.android.email:1.3% user + 4.1% kernel/faults:10 minor04-0113:12:15.872 E/Activity  Manager: 4.3 "0/system_server:2.7% user + 1.5% kernel/faults:11 minor 2 major04-0113:12:15.872 e/activitymanager ( ): 0.9r/spi_qsd.0:0% user + 0.9% kernel04-0113:12:15.872 e/activitymanager: 0.5e/irq/170-cyttsp-: 0% user + 0.5 % kernel04-0113:12:15.872 E/activitymanager (UP): 0.5) 6/com.android.systemui:0.5% user + 0% kernel04-0113:12:15.872 E/ Activitymanager: 100%total:4.8% user + 7.6% kernel + 87% iowait04-0113:12:15.872 E/activitymanager (UP): CPUusage F Rom 3697ms to 4223ms later:--ANR CPU Usage 04-0113:12:15.872 e/activitymanager: 25!404/com.android.email:25% user + 0 % kernel/faults:191 minor04-0113:12:15.872 E/activitymanager (UP): 16% 21603/__eas (par.hakan:16% user + 0% kernel04-0  113:12:15.872 E/activitymanager: 7.2% 21406/gc:7.2% user + 0% kernel04-0113:12:15.872 e/activitymanager (220): 1.8% 21409/compiler:1.8% User + 0% kernel04-0113:12:15.872 E/activitymanager (+): 5.5 "0/system_server:0% user + 5.5% kernel/faults:1 minor04-0113 : 12:15.872 e/activitymanager: 5.5% 263/inputdispatcher:0% user + 5.5% kernel04-0113:12:15.872 E/ActivityManager (2 ): 32%total:28% user + 3.7% kernel

From LOG You can see the type of ANR ,CPU usage, if the CPU usage is close to 100%, indicating that the current device is busy, there may be CPU starvation caused by the ANR

If the CPU usage is small, the main thread is BLOCK

If the iowait is High, it is possible that the ANR is the main thread that caused the I/o operation

In addition to looking at LOG, to resolve the ANR also need to trace.txt file,

Trace File Analysis

PID 21404 at 2011-04-0113:12:14-----Cmdline:com.android.emailDALVIK THREADS: (mutexes:tll=0tsl=0 tscl=0 ghl=0 hwl=0 HWL l=0) "Main" prio=5 tid=1native--Indicates the thread state (/?dalvik/?vm/?  thread.h0042 enum Threadstatus {0043 thread_undefined =-1,/* makes enum compatible with int32_t */0045/* These match up With JDWP values */0046 Thread_zombie = 0,/* TERMINATED */0047 thread_running = 1,/* RUNNABLE or RUNNING now */0048 THR ead_timed_wait = 2,/* timed_waiting in object.wait () */0049 thread_monitor = 3,/* BLOCKED on a MONITOR */0050 Thread_wai  T = 4,/* Waiting in object.wait () */0051/* non-jdwp states */0052 thread_initializing = 5,/* allocated, not yet running */0053 thread_starting = 6,/* started, not yet on THREAD list */0054 thread_native = 7,/* off in a JNI NATIVE method */ 0055 thread_vmwait = 8,/* Waiting on a VM resource */0056 thread_suspended = 9,/* SUSPENDED, usually by GC or debugger * /0057};) | group= "main" Scount=1 dscount=0obj=0x2aad2248 self=0xcf70| systid=21404 Nice=0 SchEd=0/0cgrp=[fopen-error:2] Handle=1876218976atandroid.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)

Indicates that the main thread is waiting for the next message to enter the message queue

We can clearly parse the meaning of the thread information in the trace file :

1. The first line is a fixed head , indicating that the following are the currently running DVM thread :"DALVIK THREADS:"

2. The second line outputs the values of the various thread mutexes in the process. (The role of the specific mutex is stated separately in the Dalvik thread chapter)

3. The third line of output is the name of the thread ("main"), Thread priority ("prio=5"), thread ID( " tid=1") and the type of thread ("NATIVE")

Case

Case 1: Keywords : contentresolver in asynctask onpostexecute, High iowait

Process:com.android.emailactivity:com.android.email/.activity. MESSAGEVIEWSUBJECT:KEYDISPATCHINGTIMEDOUTCPU usage from 2550ms to-2814ms ago:57/system_server:3.5% user + 1.4% kernel/ Faults:86 minor 20major4.4% 1134/com.android.email:0.7% user + 3.7% kernel/faults:38 minor-major4% 372/com.android. Eventstream:0.7%user + 3.3% kernel/faults:6 minor1.1% 272/com.android.phone:0.9% user + 0.1% kernel/faults:33 minor 0.9%2/com.android.systemui:0.9% user + 0% kernel[email protected]/com.android.eventstream.telephonyplugin:0% User + 0% kernel/faults:2 minor0.1% 632/com.android.devicemonitor:0.1% user + 0%kernel100%total:6.9% user + 8.2% Kerne L +84%iowait PID 1134 at 2010-12-17 17:46:51-----Cmd line:com.android.emailDALVIK 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=1876218976at 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

Cause: Theiowait is high, indicating that the current system is busy with I/O, so database operations are blocked

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

Anrin Process:com.android.mediascape:PhotoViewer (last Incom.android.mediascape:PhotoViewer) Annotation: Keydispatchingtimedoutcpu usage:load:6.74/6.89/6.12cpuusage from 8254ms to 3224ms ago:ovider.webmedia:4% = 4% user + 0% kernel/faults:68 minorsystem_server:2% = 1% user + 0%kernel/faults:18 minorre-initialized>: 0% = 0% user + 0% Kernel/faults:50 minorevents/0:0% = 0% user + 0%kerneltotal:7% = 6% user + 1% kerneldalvikthreads: "" 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=- 1343993184atorg.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)

With respect to the network connection, you can set a timeout time or put it on a separate thread when designing.

For Handler questions, refer to: http://developer.android.com/reference/android/os/Handler.html

Case 3: 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:keydispatchingtimedout11-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.0911-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 minor11-16 21:41:42.560i/activitymanager (1190): system_server:0% = 0% user + 0% Kernel/faults: 1 minor11-16 21:41:42.560 I/activitymanager (1190): adbd:0% = 0% user + 0% kernel11-16 21:41:42.560 I/ActivityManager (1190 ): logcat:0% = 0% user + 0% kernel11-16 21:41:42.560i/activitymanager (1190): total:100% = 98% user + 1% kernelcmdline:a Ndroid.process.acoreDALVIK 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=-1344001376atdalvik.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=15470792at 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 causes block to create bitmap on *meminfo in PID 1360 [Android.process.acore] *native Dalvik other totalsize:17036 23111 N/a 40147all ocated:16484 20675 N/a 37159free:296 2436 N/a 2732

WORKAROUND: If the machine's memory family can modify the virtual machine's memory to 36M or greater, it is best to review the code to see which memory is not released

Android ANR Solution case (internal information)