Android ANR Analysis/data/anr/trace.txt This file records the function stacks that generate ANR to help analyze

Log status in Android is very important, if as an Android programmer can not analyze log this, is not an introduction to Android. Let's say how to handle the log file.


When will the log file be generated?
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, the program is not responding, application no Response (ANR), by the way, the general main thread more than 5 seconds? There will be a processing of 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)------

The format is as follows:
------MEMORY INFO (/proc/meminfo)------
memtotal:347076 KB
memfree:56408 KB
buffers:7192 KB
cached:104064 KB
swapcached:0 KB
active:192592 KB
inactive:40548 KB
Active (anon): 129040 KB
Inactive (anon): 1104 KB
Active (file): 63552 KB
Inactive (file): 39444 KB
unevictable:7112 KB
mlocked:0 KB
swaptotal:0 KB
swapfree:0 KB
Dirty:44 KB
writeback:0 KB
anonpages:129028 KB
mapped:73728 KB
shmem:1148 KB
slab:13072 KB
sreclaimable:4564 KB
sunreclaim:8508 KB
kernelstack:3472 KB
pagetables:12172 KB
nfs_unstable:0 KB
bounce:0 KB
writebacktmp:0 KB
commitlimit:173536 KB
committed_as:7394524 KB
vmalloctotal:319488 KB
vmallocused:90752 KB
vmallocchunk: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 Com.wsomacp.permission.PROVIDER in package Com.android.mms
01-15 16:41:43.671 I/activitymanager (2466): Force stopping package Com.android.mms uid=10092
01-15 16:41:43.675 i/usagestats (2466): Something wrong here, didn ' t expect Com.sec.android.app.twlauncher to be paused
01-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 timeout for historyrecord{48589868 com.sec.android.app.twlauncher/. Launcher}
01-15 16:41:50.864 I/keyinputqueue (2466): Input Event
01-15 16:41:50.866 D/keyinputqueue (2466): Screencapturekeyflag setting 0
01-15 16:41:50.882 I/powermanagerservice (2466): Ulight 0->7|0
01-15 16:41:50.882 I/powermanagerservice (2466): Setting target 2:cur=0.0 target=70 delta=4.6666665 nominalCurrentValue =0
01-15 16:41:50.882 I/powermanagerservice (2466): Scheduling light animator!
01-15 16:41:51.706 D/powermanagerservice (2466): Enablelightsensor True
01-15 16:41:51.929 I/keyinputqueue (2466): Input Event
01-15 16:41:51.933 W/windowmanager (2466): No Focus window, dropping:keyevent{action=0 code=26 repeat=0 meta=0 scancode=2 6 mflags=9}



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


The format is as follows:
-----pid 21161 at 2011-01-15 16:49:01-----
CMD Line:com.android.mms

DALVIK 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=defaulthandle=-1345017808 | schedstat= (4151552996 5342265329 10995At Android.media.mediaplayer._reset (Native Method) at Android.media.MediaPlayer.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:48V) at Android.os.Handler.dispatchMessage (Handler.java:92) at Android.os.Looper.loop (Looper.java:123) at Android.app.ActivityThread.main (Activitythread.java:4627At 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.
Let's start by analyzing the log of this example.

Open the log file, because it is a ANR error, so Search "ANR", why add a space, you add and remove the comparison will know. You can block out many invalid information saved to the Anr.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:keydispatchingtimedout
01-15 16:49:02.433 E/activitymanager (2466): load:0.6/0.61/0.42
01-15 16:49:02.433 E/activitymanager (2466): CPU usage from 1337225ms to 57ms 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% kernel
01-15 16:49:02.433 E/activitymanager (2466):-flush-179:8: 0% = 0% user + 0% kernel
01-15 16:49:02.433 E/activitymanager (2466): total:25% = 10% user + 14% kernel + 0% iowait + 0% IRQ + 0% SOFTIRQ
01-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.

Then we analyze the virtual machine information, search "Dalvik Thread" keyword, quickly locate the application of the virtual machine information log, as follows:
-----pid 2922 at 2011-01-13 13:51:07-----
CMD Line:com.android.mms

DALVIK THREADS:

"Main" prio=5 tid=1NATIVE| group= "main" scount=1 dscount=0 s=n obj=0x4001d8d0 SELF=0XCCC8 | systid=2922 nice=0 sched=0/0 cgrp=defaulthandle=-1345017808 | schedstat= (3497492306 15312897923 10358At android.media.mediaplayer._release (Native Method) at Android.media.MediaPlayer.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:48V) at Android.os.Handler.dispatchMessage (Handler.java:92) at Android.os.Looper.loop (Looper.java:123) at Android.app.ActivityThread.main (Activitythread.java:4627At 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=11NATIVE| group= "main" scount=1 dscount=0 s=n obj=0x4837f808 self=0x242280 | systid=3239 nice=0 sched=0/0 cgrp=defaulthandle=2341032 | schedstat= (32410506 932842514 164) at Dalvik.system.NativeStart.run (Native Method)"Asyncqueryworker" Prio=5 tid=9WAIT| group= "main" scount=1 dscount=0 s=n obj=0x482f4b80 self=0x253e10 | systid=3236 nice=0 sched=0/0 cgrp=defaulthandle=2432120 | schedstat= (3225061 26561350 27) 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:110) at Android.os.HandlerThread.run (Handlerthread.java:60)"Thread-9" Prio=5 tid=8WAIT| group= "main" scount=1 dscount=0 s=n obj=0x4836e2b0 self=0x25af70 | systid=2929 nice=0 sched=0/0 cgrp=defaulthandle=2370896 | schedstat= (130248 4389035 2) at java.lang.Object.wait (Native Method)-Waiting on <0x4836e240>(a java.util.ArrayList) 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=7NATIVE| group= "main" scount=1 dscount=0 s=n obj=0x482f8ca0 self=0x130fd0 | systid=2928 nice=0 sched=0/0 cgrp=defaulthandle=1215968 | schedstat= (40610049 1837703846 195) at Dalvik.system.NativeStart.run (Native Method)"Binder Thread #1" Prio=5 tid=6NATIVE| group= "main" scount=1 dscount=0 s=n obj=0x482f4a78 self=0x128a50 | systid=2927 nice=0 sched=0/0 cgrp=defaulthandle=1201352 | schedstat= (40928066 928867585 190) at Dalvik.system.NativeStart.run (Native Method)"Compiler" Daemon prio=5 tid=5vmwait| Group= "System" scount=1 dscount=0 s=n obj=0x482f1348 self=0x118960 | systid=2926 nice=0 sched=0/0 cgrp=defaulthandle=1149216 | schedstat= (753021350 3774113668 6686) at Dalvik.system.NativeStart.run (Native Method)"JDWP" Daemon prio=5 tid=4vmwait| Group= "System" scount=1 dscount=0 s=n obj=0x482f12a0 self=0x132940 | systid=2925 nice=0 sched=0/0 cgrp=defaulthandle=1255680 | schedstat= (2827103 29553323 19) at Dalvik.system.NativeStart.run (Native Method)"Signal Catcher" daemon prio=5 tid=3RUNNABLE| Group= "System" scount=0 dscount=0 s=n obj=0x482f11e8 self=0x135988 | systid=2924 nice=0 sched=0/0 cgrp=defaulthandle=1173688 | schedstat= (11793815 12456169 7) at Dalvik.system.NativeStart.run (Native Method)"Heapworker" Daemon prio=5 tid=2vmwait| Group= "System" scount=1 dscount=0 s=n obj=0x45496028 self=0x135848 | systid=2923 nice=0 sched=0/0 cgrp=defaulthandle=1222608 | schedstat= (79049792 1520840200 95) at Dalvik.system.NativeStart.run (Native Method)

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 (NewRunnable () { Public voidrun () {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.

From: 38730309

Android ANR Analysis/data/anr/trace.txt This file records the function stacks that generate ANR to help analyze