Android Issue Analysis Method (illustrated with ANR)

Log generation We all know, we all know through DDMS to see log, but when will produce log file? A log file is typically generated in the following situations.
1, program abnormal exit, uncaused exception
2, program forced shutdown, Force Closed (FC)
3, program no response, Application no Response ( ANR)
4, manually generated.

　　Get a log file, to be divided into several paragraphs to see. The log file is very long and contains more than 10 small pieces of information, but not to be frightened, in fact he consists mainly of three blocks.

1, the system basic information, including memory, CPU, process queue, virtual memory, garbage collection and other information.

------MEMORY INFO (/proc/meminfo)------
------CPU INFO (top-n 1-d 1-m 30-t)------
------Procrank (Procrank)------
------VIRTUAL MEMORY STATS (/proc/vmstat)------
------Vmalloc INFO (/proc/vmallocinfo)------

------MEMORY INFO (/proc/meminfo)------memtotal:347076 Kbmemfree: 56408 kbbuffers:7192 kbcached:104064 kbswapcached:0 kbactive:192592 Kbinac    tive:40548 kbactive (anon): 129040 kbinactive (anon): 1104 kbactive (file): 63552 kbinactive (file): 39444 kbunevictable:7112 kbmlocked:0 kbswaptotal:0 kbswapfree:0 kbdirty              : kbwriteback:0 kbanonpages:129028 kbmapped:73728 Kbshmem: 1148 kbslab:13072 kbsreclaimable:4564 kbsunreclaim:8508 kbkernelstack:3472 Kbpageta bles:12172 kbnfs_unstable:0 kbbounce:0 kbwritebacktmp:0 kbcommitlimit:17 3536 kbcommitted_as:7394524 kbvmalloctotal:319488 kbvmallocused:90752 kbvmallocchunk:181252 KB 

2, time information, is also our main analysis of information.
------Vmalloc INFO (/proc/vmallocinfo)------
------EVENT INFO (/proc/vmallocinfo)------

The format is as follows:

------SYSTEM LOG (logcat-b system-v time-d *:v)------01-15 16:41:43.671 W/packagemanager (2466): Unknown permission C Om.wsomacp.permission.PROVIDER in Package com.android.mms01-15 16:41:43.671 I/activitymanager (2466): Force stopping Package Com.android.mms uid=1009201-15 16:41:43.675 i/usagestats (2466): Something wrong here, didn ' t expect Com.sec.andr Oid.app.twlauncher to be paused01-15 16:41:44.108 I/activitymanager (2466): Start proc Com.sec.android.widgetapp.infoalarm for service Com.sec.android.widgetapp.infoalarm/.engine. dataservice:pid=20634 uid=10005 gids={3003, 1015, 3002}01-15 16:41:44.175 W/activitymanager (2466): Activity pause Timeo UT for historyrecord{48589868 com.sec.android.app.twlauncher/. Launcher}01-15 16:41:50.864 I/keyinputqueue (2466): Input event01-15 16:41:50.866 d/keyinputqueue (2466): Screencapturekeyflag setting 001-15 16:41:50.882 i/powermanagerservice (2466): Ulight 0->7|001-15 16:41:50.882 I/ Powermanagerservice (2466): Setting target 2:cur=0.0 target=70 delta=4.6666665 nominalcurrentvalue=001-15 16:41:50.882 i/powermanagerservice (2466): Scheduling Light Animator!01-15 16:41:51.706 D/powermanagerservice (2466): Enablelightsensor true01-15 16:41:51.929 I/KeyInputQueue (  2466): Input event01-15 16:41:51.933 W/windowmanager (2466): No Focus window, dropping:keyevent{action=0 code=26 repeat=0 Meta=0 scancode=26 Mflags=9}

 3, virtual machine information, Includes process, thread-tracking information, which is a good place to track process and thread-specific points.
------VM traces JUST now (/data/anr (/data/anr /traces.txt: 2011-01-15 16:49:02)------

-----pid 21161 at 2011-01-15 16:49:01-----Cmd line:com.android.mmsDALVIK THREADS: "Main" prio=5 tid=1 NATIVE | group= "main" scount=1 dscount=0 s=n obj=0x4001d8d0 SELF=0XCCC8 | systid=21161 nice=0 sched=0/0 Cgrp=default handle=-1345017808 | schedstat= (4151552996 5342265329 10995) at Android.media.mediaplayer._reset (Native Method) at Android.media.MediaPlay Er.reset (mediaplayer.java:1218) at Android.widget.VideoView.release (videoview.java:499) at ANDROID.WIDGET.VIDEOVIEW.ACCESS$2100 (videoview.java:50) at android.widget.videoview$6.surfacedestroyed ( videoview.java:489) at android.view.SurfaceView.reportSurfaceDestroyed (surfaceview.java:572) at Android.view.SurfaceView.updateWindow (surfaceview.java:476) at Android.view.SurfaceView.onWindowVisibilityChanged (surfaceview.java:206) at Android.view.View.dispatchDetachedFromWindow (view.java:6082) at Android.view.ViewGroup.dispatchDetachedFromWindow (viewgroup.java:1156) at Android.view.ViewGroup.removeAllViewsInLayout (Viewgroup.java:2296) at Android.view.ViewGroup.removeAllViews (viewgroup.java:2254) at Com.android.mms.ui.SlideView.reset ( slideview.java:687) at Com.android.mms.ui.SlideshowPresenter.presentSlide (slideshowpresenter.java:189) at Com.android.mms.ui.slideshowpresenter$3.run (slideshowpresenter.java:531) at Android.os.Handler.handleCallback ( handler.java:587) at Android.os.Handler.dispatchMessage (handler.java:92) at Android.os.Looper.loop (looper.java:123 ) at Android.app.ActivityThread.main (activitythread.java:4627) at Java.lang.reflect.Method.invokeNative (Native Method) at Java.lang.reflect.Method.invoke (method.java:521) at com.android.internal.os.zygoteinit$ Methodandargscaller.run (zygoteinit.java:858) at Com.android.internal.os.ZygoteInit.main (zygoteinit.java:616) at Dalvik.system.NativeStart.main (Native Method)

With less gossip, I summed up the basic steps of observing the log file.

1, if it is anr problem, search "anr" keyword. Quickly navigate to critical event information.
2, if it is forceclosed and other abnormal exit information, search "Fatal" keyword, quickly locate the key event information.
3, after locating the critical event information, if the information is not clear, then search the application package for virtual machine information, view the specific process and thread tracking log, to locate the code.

　　 with this method, there are problems, there is no need to debug breakpoints, direct positioning to the problem, and tried.
below, we start with the ANR error, so we search for invalid information for theANR. log file.

Navigate to the key event information as follows:

01-15 16:49:02.433 E/activitymanager (2466): ANR in Com.android.mms ( Com.android.mms/.ui. slideshowactivity) 01-15 16:49:02.433 E/activitymanager (2466): reason:keydispatchingtimedout01-15 16:49:02.433 E/ Activitymanager (2466): load:0.6/0.61/0.4201-15 16:49:02.433 E/activitymanager (2466): CPU usage from 1337225ms to 57 Ms Ago:01-15 16:49:02.433 E/activitymanager (2466): sensorserver_ya:8% = 0% user + 8% kernel/faults:40 minor ... 01-15 16:49:02.433 E/activitymanager (2466):-com.android.mms:0% = 0% user + 0% kernel01-15 16:49:02.433 E/ActivityManag  ER (2466):-flush-179:8: 0% = 0% user + 0% kernel01-15 16:49:02.433 E/activitymanager (2466): total:25% = 10% user + 14% Kernel + 0% iowait + 0% IRQ + 0% softirq01-15 16:49:02.436 i/(2466): DUMPMESG > "/DATA/LOG/DUMPSTATE_APP_ANR. Log "

We use natural language to describe the log, which is a kind of ability.

01-15 16:49:02.433 E/activitymanager (2466): ANR in Com.android.mms (Com.android.mms/.ui. slideshowactivity)
translation: At 16:49 minutes, 2 seconds, 433 milliseconds, the following error occurred Activitymanager (process number 2466): Com.android.mms package. Ui.slideshowactivity is not responding.

01-15 16:49:02.433 E/activitymanager (2466): Reason:keydispatchingtimedout
translation: Reason, keydispatchingtimeout-key assignment Timeout

01-15 16:49:02.433 E/activitymanager (2466): load:0.6/0.61/0.42
translation: 5 minutes, 10 minutes, the average load in 15 minutes is: 0.6, 0.61, 0.42

　　 Here we probably know what the problem is, combined with our previous operating procedures, we know that the problem is that the button event may not be processed at some point when the button is clicked, causing the timeout to be unresponsive. Now it seems that it is ready to work. We know that activity is handled by heavy dispatchtouchevent (motionevent ev) to handle click-screen events. Then we can go to the clues, a little analysis to find the reason. But is that enough?
　　 In fact, not enough, at least we can not accurately know exactly where the problem is, just speculation, such as this application, I found in the course of a number of IO operations in the main thread, may cause problems, but it is not good to judge exactly which, so we currently have not enough information to grasp.

analyzing the virtual machine information, Search the "Dalvik Thread" keyword to quickly locate the virtual machine information log for this application, as follows:

-----pid 2922 at 2011-01-13 13:51:07-----Cmd line:com.android.mmsDALVIK THREADS: "Main" prio=5 tid=1 NATIVE | group= "main" scount=1 dscount=0 s=n obj=0x4001d8d0 SELF=0XCCC8 | systid=2922 nice=0 sched=0/0 Cgrp=default handle=-1345017808 | schedstat= (3497492306 15312897923 10358) at Android.media.mediaplayer._release (Native Method) at Android.media.MediaP Layer.release (mediaplayer.java:1206) at Android.widget.VideoView.stopPlayback (videoview.java:196) at Com.android.mms.ui.SlideView.stopVideo (slideview.java:640) at Com.android.mms.ui.SlideshowPresenter.presentVideo (slideshowpresenter.java:443) at Com.android.mms.ui.SlideshowPresenter.presentRegionMedia ( slideshowpresenter.java:219) at Com.android.mms.ui.slideshowpresenter$4.run (slideshowpresenter.java:516) at Android.os.Handler.handleCallback (handler.java:587) at Android.os.Handler.dispatchMessage (handler.java:92) at Android.os.Looper.loop (looper.java:123) at Android.app.ActivityThread.main (activitythread.java:4627) at JAva.lang.reflect.Method.invokeNative (Native Method) at Java.lang.reflect.Method.invoke (method.java:521) at Com.android.internal.os.zygoteinit$methodandargscaller.run (zygoteinit.java:858) at Com.android.internal.os.ZygoteInit.main (zygoteinit.java:616) at Dalvik.system.NativeStart.main (Native Method) " Binder Thread #3 "prio=5 tid=11 NATIVE | group= "main" scount=1 dscount=0 s=n obj=0x4837f808 self=0x242280 | systid=3239 nice=0 sched=0/0 Cgrp=default handle=2341032 |   schedstat= (32410506 932842514 164) at Dalvik.system.NativeStart.run (Native Method) "Asyncqueryworker" Prio=5 tid=9 WAIT | group= "main" scount=1 dscount=0 s=n obj=0x482f4b80 self=0x253e10 | systid=3236 nice=0 sched=0/0 Cgrp=default handle=2432120 | schedstat= (3225061 26561350) at java.lang.Object.wait (Native Method)-Waiting on <0x482f4da8> (a android.os. MessageQueue) at java.lang.Object.wait (object.java:288) at Android.os.MessageQueue.next (messagequeue.java:146) at Android.os.Looper.loop (Looper.java: +) at Android.os.HandlerThread.run (handlerthread.java:60) "Thread-9" Prio=5 tid=8 WAIT | group= "main" scount=1 dscount=0 s=n obj=0x4836e2b0 self=0x25af70 | systid=2929 nice=0 sched=0/0 Cgrp=default handle=2370896 | schedstat= (130248 4389035 2) at java.lang.Object.wait (Native Method)-Waiting on <0x4836e240> (a Java.util.Arra Ylist) at java.lang.Object.wait (object.java:288) at Com.android.mms.data.contact$contactscache$taskstack$1.run ( contact.java:488) at Java.lang.Thread.run (thread.java:1096) "Binder Thread #2" prio=5 tid=7 NATIVE | group= "main" scount=1 dscount=0 s=n obj=0x482f8ca0 self=0x130fd0 | systid=2928 nice=0 sched=0/0 Cgrp=default handle=1215968 | schedstat= (40610049 1837703846 195) at Dalvik.system.NativeStart.run (Native Method) "Binder Thread #1" prio=5 tid=6 Nati VE | group= "main" scount=1 dscount=0 s=n obj=0x482f4a78 self=0x128a50 | systid=2927 nice=0 sched=0/0 Cgrp=default handle=1201352 | schedstat= (40928066 928867585) at Dalvik.system.NatIvestart.run (Native Method) "Compiler" daemon prio=5 tid=5 vmwait | Group= "System" scount=1 dscount=0 s=n obj=0x482f1348 self=0x118960 | systid=2926 nice=0 sched=0/0 Cgrp=default handle=1149216 |  schedstat= (753021350 3774113668 6686) at Dalvik.system.NativeStart.run (Native Method) "JDWP" Daemon prio=5 tid=4 vmwait | Group= "System" scount=1 dscount=0 s=n obj=0x482f12a0 self=0x132940 | systid=2925 nice=0 sched=0/0 Cgrp=default handle=1255680 | schedstat= (2827103 29553323) at Dalvik.system.NativeStart.run (Native Method) "Signal Catcher" daemon prio=5 tid=3 Run nable | Group= "System" scount=0 dscount=0 s=n obj=0x482f11e8 self=0x135988 | systid=2924 nice=0 sched=0/0 Cgrp=default handle=1173688 |  schedstat= (11793815 12456169 7) at Dalvik.system.NativeStart.run (Native Method) "Heapworker" Daemon prio=5 tid=2 vmwait | Group= "System" scount=1 dscount=0 s=n obj=0x45496028 self=0x135848 | systid=2923 nice=0 sched=0/0 Cgrp=default handle=1222608 | schedstat= (79049792 1520840200 ) at Dalvik.system.NativeStart.run (Native Method)-----End 2922----- 

Each segment is a thread, and of course we look at the thread number 1. The key issues are identified by analysis :

At Com.android.mms.ui.slideshowpresenter$3.run (slideshowpresenter.java:531)

Navigate to code:

mhandler.post (New Runnable () {public void run () {                        try {presentregionmedia (view, (Regionmediamodel) model, datachanged);                            } catch (Omadrmexception e) {log.e (TAG, E.getmessage (), E);                                    Toast.maketext (Mcontext, mcontext.getstring (r.string.insufficient_drm_rights),                        Toast.length_short). Show ();                            } catch (IOException e) {log.e (TAG, E.getmessage (), E);                                    Toast.maketext (Mcontext, mcontext.getstring (r.string.insufficient_drm_rights),                                                Toast.length_short). Show (); }                    }

It is clear that the Handler.post method takes too long to execute. Continue to look at the Presentregionmedia (view, (Regionmediamodel) model, datachanged) method, and discover that the Mediaplayer.stop method is ultimately called in the framework.
This concludes our log analysis . You can start thinking about the solution .

Android Issue Analysis Method (illustrated with ANR)