Android Log Learning

First, the bug appeared, Need to "kill" it is a scary bug, but as long as you understand, Android bug is very good solution, because Android provides the log mechanism, the specific underlying code, in the future to analyze, as long as you will see the bug, Application development in Android is also very simple. Let's take a look at the ANR in Android, how does the ANR appear, very simple. # adb Shell # CD Data/app # monkey-p Com.xxx.xxx-v (Com.xxx.xxx is the package name of your application, if you want to know monkey detailed usage, execute monkey Help) actually a lot of excellent an The Droid application will appear ANR, such as the UC Browser,so on, if you are interested can go back to try, so that the ANR appeared. Start making modifications to prepare for the log file. Someone asked where the log file is? Generally under the/data/log (but the real machine only). You can take a look through the command adb shell, pull the log file to your computer, get the log file, we are ready to start working. I upload the detailed log file to the attachment for your reference. For http://download.csdn.net/detail/andy_android/3785393 Two, the type of Log android.util.Log commonly used methods have the following six: LOG.V () log.d () log.i () LOG.W (), LOG.E () and LOG.A () (new additions to Android 4.0).      Corresponds to Verbose,debug,info,warn,error,assert according to the initial letter.      1, LOG.V debugging color is black, any message will be output, here V for verbose wordy meaning, usually use is LOG.V ("," ");      2, LOG.D output color is blue, only the meaning of debug debugging output, but he will output the upper level of information, filtering up can be DDMS by the logcat tag to choose. 3, LOG.I output is green, general informational message information, it will not output LOG.V and LOG.D information, but will show I, W and e information 4,     LOG.W, which is orange, can be seen as a warning warning, generally requires us to focus on optimizing the Android code, while selecting it will also output LOG.E information. 5, LOG.E is red, can think of error errors, here only showRed error message, these errors need our careful analysis, view the stack of information.      6 LOG.A for 4.0 new added. Start Eclipse, open Ddms Everyone can see in the Logcat (as long as the Android 4.0 ADT) Three, how to analyze and research log files, how to read the log information. 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. Log is divided into fatal and ANR when will the log file be generated? Log generation We all know that we all know that through DDMS to see log (this is needless to say), but when will generate a log file? A log file is typically generated in the following situations. 1, program abnormal exit, Uncausedexception (Fatal) 2, program forced shutdown, forceclosed (FC) (Fatal) 3, program unresponsive, Applicationno Response (for short, ANR) ANR occurs when the following two a-Interface action button Click-Wait response time more than 5 seconds B Handlemessage callback function executes more than 10 seconds, broadcasterreciver in the Onrecive () method processing more than 10 seconds 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)-format as follows:--memory info (/proc/meminfo)--memtotal:347076 KB memfree:5 6408 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:0kb swaptotal: 0 KB swapfree:0 KB dirty:44kb writeback:0 KB anonpages:129028 KB mapped:73728 KB shmem:1148kb slab:13072kb SReclaim  able:4564 KB sunreclaim:8508 KB kernelstack:3472 KB pagetables:12172 KB nfs_unstable:0 KB bounce:0kb writebacktmp:0 KB commitlimit:173536 KB committed_as:7394524 KB vmalloctotal:319488 KB vmallocused:90752 KB vmallocchunk:181252 kB2 , event 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-1516:41:43.671 W/packagemanager (2466): Unknown Permissioncom.wsomacp.permission.PROVIDER in Package Com.android.mms 01-1516:41:43.671 I/activitymanager (2466): Force stopping Packagecom.android.mms uid=10092 01-1516:41:43.675 i/usagestats (2466): Something wrong here, didn ' t expectcom.sec.android.app.twlauncher to be paused 01- 1516:41:44.108 I/activitymanaGER (2466): Start proccom.sec.android.widgetapp.infoalarm for Servicecom.sec.android.widgetapp.infoalarm/.engine. dataservice:pid=20634uid=10005 gids={3003, 1015, 3002} 01-1516:41:44.175 W/activitymanager (2466): Activity Pause Timeout forhistoryrecord{48589868com.sec.android.app.twlauncher/. Launcher} 01-1516:41:50.864 I/keyinputqueue (2466): Input event 01-1516:41:50.866 D/keyinputqueue (2466): Screencapturekeyflag setting0 01-1516:41:50.882 I/powermanagerservice (2466): Ulight 0->7|0 01-1516:41:50.882 I/ Powermanagerservice (2466): Setting target 2:cur=0.0target=70 delta=4.6666665 nominalcurrentvalue=0 01-1516:41:50.882 I/powermanagerservice (2466): Scheduling lightanimator! 01-1516:41:51.706 D/powermanagerservice (2466): Enablelightsensortrue 01-1516:41:51.929 I/KeyInputQueue (2466): Input Event 01-1516:41:51.933 W/windowmanager (2466): No Focus window, dropping:keyevent{action=0 code=26 repeat=0 meta=0 Scanc ODE=26MFLAGS=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-1516:49:02) —— —— VMs traces at last ANR (/data/anr/traces.txt:2011-01-15 1 6:49:02)--format as follows:-–pid 21161 at 2011-01-15 16:49:01-–cmdline:com.android.mmsdalvikthreads: "Main" prio=5 tid=1 NATIVE |gr oup= "main" scount=1 dscount=0 s=n obj=0x4001d8d0self=0xccc8 |systid=21161 nice=0 sched=0/0 cgrp=default handle=- 1345017808 |schedstat= (4151552996 5342265329 10995) atandroid.media.mediaplayer._reset (Native Method) Atandroid.media.MediaPlayer.reset (mediaplayer.java:1218) atandroid.widget.VideoView.release (videoview.java:499) Atandroid.widget.VideoView.access2100 (videoview.java:50) atandroid.widget.VideoView6.surfaceDestroyed ( videoview.java:489) atandroid.view.SurfaceView.reportSurfaceDestroyed (surfaceview.java:572) Atandroid.view.SurfaceView.updateWindow (surfaceview.java:476) Atandroid.view.SurfaceView.onWindowVisibilityChanged (surfaceview.java:206) Atandroid.view.View.dispatchDetachedFromWindow (view.java:6082) Atandroid.view.ViewGroup.dispatchDetAchedfromwindow (viewgroup.java:1156) atandroid.view.ViewGroup.removeAllViewsInLayout (viewgroup.java:2296) Atandroid.view.ViewGroup.removeAllViews (viewgroup.java:2254) Atcom.android.mms.ui.SlideView.reset ( slideview.java:687) Atcom.android.mms.ui.SlideshowPresenter.presentSlide (slideshowpresenter.java:189) Atcom.android.mms.ui.SlideshowPresenter3.run (slideshowpresenter.java:531) 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:4627) atjava.lang.reflect.Method.invokeNative ( Nativemethod) Atjava.lang.reflect.Method.invoke (method.java:521) Atcom.android.internal.os.ZygoteInitMethodAndArgsCaller.run (zygoteinit.java:858) Atcom.android.internal.os.ZygoteInit.main (zygoteinit.java:616) atdalvik.system.NativeStart.main (Nativemethod) 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, locate the key thingInformation, if the information is not clear, then search the application package for virtual machine information, view the specific process and thread tracking logs, 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. Locate the key event information as follows: 01-1516:49:02.433 E/activitymanager (2466): ANR in Com.android.mms (Com.android.mms/.ui. slideshowactivity) 01-1516:49:02.433 E/activitymanager (2466): Reason:keydispatchingtimedout 01-1516:49:02.433 E/ Activitymanager (2466): load:0.6/0.61/0.42 01-1516:49:02.433 E/activitymanager (2466): CPU usage from 1337225ms to57m S ago:01-1516:49:02.433 e/activitymanager (2466): sensorserver_ya:8% = 0% user + 8% kernel/faults:40 minor ... 01-1516:49:02.433 E/activitymanager (2466):-com.android.mms:0% = 0% user + 0% kernel 01-1516:49:02.433 E/ActivityManager (2466):-flush-179:8: 0% =0% user + 0% kernel 01-1516:49:02.433 e/activitymanager (2466): total:25% = 10% user + 14%kern El + 0% iowait + 0% IRQ + 0% SOFTIRQ 01-1516:49:02.436 i/(2466):d umpmesg > "/data/log/dumpstate_app_anr.log" We use natural languageTo describe the log, this is a kind of ability. 01-1516: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 Activitymanager (process number 2466) The following error occurred: the. Ui.slideshowactivity below the Com.android.mms package is not responding. 01-1516:49:02.433 E/activitymanager (2466): Reason:keydispatchingtimedout translation: Reasons, keydispatchingtimeout-key Assignment Timeout 01-1516:49:02.433 E/activitymanager (2466): load:0.6/0.61/0.42 Translator: 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 overloading Dispatchtouchevent (MOTIONEVENTEV) 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 "dalvikthread" keyword, quickly locate the application of the virtual machine information log, as follows:-–pid 2922 at 2011-01-13 13:51:07-–cmdline: Com.android.mmsDALVIKTHREADS: "Main" prio=5 tid=1 NATIVE |group= "main" scount=1 dscount=0 s=n OBJ=0X4001D8D0SELF=0XCCC8 |systid=2922 nice=0 sched=0/0 Cgrp=default handle=-1345017808 |schedstat= (3497492306 15312897923 10358) atandroid.media.mediaplayer._release (Native Method) Atandroid.media.MediaPlayer.release (mediaplayer.java:1206) Atandroid.widget.VideoView.stopPlayback ( videoview.java:196) Atcom.android.mms.ui.SlideView.stopVideo (slideview.java:640) Atcom.android.mms.ui.SlideshowPresenter.presentVideo (slideshowpresenter.java:443) Atcom.android.mms.ui.SlideshowPresenter.presentRegionMedia (slideshowpresenter.java:219) Atcom.android.mms.ui.SlideshowPresenter4.run (slideshowpresenter.java:516) 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:4627) atjava.lang.reflect.Method.invokeNative ( Nativemethod) Atjava.lang.reflect.Method.invoke (method.java:521) Atcom.android.internal.os.ZygoteInitMethodAndArgsCaller.run (zygoteinit.java:858) Atcom.android.internal.os.ZygoteInit.main (zygoteinit.java:616) Atdalvik.system.NativeStart.Main (Native Method) "Binderthread #3" prio=5 tid=11 Native |group= "main" scount=1 dscount=0 s=n obj=0x4837f808self= 0x242280 |systid=3239 nice=0 sched=0/0 cgrp=default handle=2341032 |schedstat= (32410506 932842514 164) Atdalvik.system. Nativestart.run (Native Method) "Asyncqueryworker" prio=5 tid=9 WAIT |group= "main" scount=1 dscount=0 s=n obj= 0x482f4b80self=0x253e10 |systid=3236 nice=0 sched=0/0 cgrp=default handle=2432120 |schedstat= (3225061 26561350) Atja  Va.lang.Object.wait (Native Method)-waiting on<0x482f4da8>(a android.os.MessageQueue) atjava.lang.Object.wait (object.java:288) Atandroid.os.MessageQueue.next ( messagequeue.java:146) Atandroid.os.Looper.loop (looper.java:110) Atandroid.os.HandlerThread.run ( handlerthread.java:60) "Thread-9" prio=5 tid=8 WAIT |group= "main" scount=1 dscount=0 s=n obj=0x4836e2b0self=0x25af70 | systid=2929 nice=0 sched=0/0 cgrp=default handle=2370896 |schedstat= (130248 4389035 2) atjava.lang.Object.wait (Native M Ethod)-waiting on<0x4836e240> (a java.util.ArrayList) atjava.lang.Object.wait (object.java:288) Atcom.android.mms.data.contactcontactscachetaskstack$1.run (contact.java:488) Atjava.lang.Thread.run (Thread.java : 1096) "Binderthread #2" prio=5 tid=7 NATIVE |group= "main" scount=1 dscount=0 s=n obj=0x482f8ca0self=0x130fd0 |sysTid= 2928 nice=0 sched=0/0 cgrp=default handle=1215968 |schedstat= (40610049 1837703846 195) Atdalvik.system.NativeStart.run (Native Method) "Binderthread #1" prio=5 tid=6 Native |group= "main" scount=1 dscount=0 s=n obj=0x482f4a78self=0x128a50 |sy stid=2927 nice=0 sched=0/0 cgrp=default handle=1201352 |schedstat= (40928066 928867585) Atdalvik.system.NativeStart . Run (Native Method) "Compiler" daemon prio=5 tid=5 vmwait |group= "System" scount=1 dscount=0 s=n obj=0x482f1348self= 0x118960 |systid=2926 nice=0 sched=0/0 cgrp=default handle=1149216 |schedstat= (753021350 3774113668 6686) atdalvik.syst Em. Nativestart.run (Native Method) "JDWP" daemon prio=5 tid=4 vmwait |group= "System" scount=1 dscount=0 s=n obj=0x482f12a0self=0x132940 |systid=2925 nice=0 sched=0/0 cgrp=default handle=1255680 |schedstat= (2827103 29553323) atdal Vik.system.NativeStart.run (Native Method) "Signalcatcher" daemon prio=5 tid=3 RUNNABLE |group= "System" scount=0 Dscount =0 s=n obj=0x482f11e8self=0x135988 |systid=2924 nice=0 sched=0/0 cgrp=default handle=1173688 |schedstat= (11793815 12456169 7) Atdalvik.system.NativeStart.run (Native Method) "Heapworker" daemon prio=5 tid=2 vmwait |group= "System" Scount=1 dscount=0 s=n obj=0x45496028self=0x135848 |systid=2923 nice=0 sched=0/0 cgrp=default handle=1222608 |schedstat = (79049792 1520840200) atdalvik.system.NativeStart.run (Native Method)-–end 2922-– Each segment is a thread, of course, we still look at the thread number 1 of the main path. The key problem is found through analysis: Atcom.android.mms.ui.slideshowpresenter$3.run (slideshowpresenter.java:531) locates to code: Mhandler.post ( Newrunnable () {public void run () {try {Presentregionmedia (view, (Regionmediamodel) model, datachanged);} catch (Omadrme Xception 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. Thirdly, how to solve the problem of the execution time process of an operation by handler or multithreading. In combination with the above analysis, we know that the problem appears to be an operation Presentregionmedia (view, (Regionmediamodel) model, datachanged) in the thread queue, and that the interface is not responsive due to the long execution time. It is, of course, a more typical practice to control thread queues. Here we have to mention the handler. What is the role and status of handler in Android? Messages are passed between threads through the SendMessage method. We usually use the back-table thread to deliver messages to the main thread, and the main thread to do the update interface after the notification. Schedule tasks by managing Message Queuing (MessageQueue). This is often overlooked, and many books do not mention the effect. Handler The word Chinese means the manager, the handler means. By this means, as the name implies, we know that this object is an object of manipulation. So who's going to do it? Message Queuing (MessageQueue) is of course. Android Message Queuing is similar to the Win32 queue design. are linear structures, FIFO. In fact, the smartphone platform used this message structure a long time ago. Palm, for example, is just the whole process of sharing a message queue, while Android is a queue for threads. Whether each thread or child thread has aThe rest of the queue? Unfortunately, no, it's not necessary. In Android, only lines that use Looper friend have message queues. Of course, if you want to simply build a thread with a message queue is also handy, directly using Handlerthread, this class inherits from the thread class. I won't say much about it. You know! Handler has two ways to manipulate Message Queuing. One is to send the message body via the SendMessage (message) method, and the other is to send the Runnable object through the Post (Runnable) method. Note: Note that although the sending methods have different parameters, they are using the same message queue. I remember that the Mars video tutorial says there are two queues, one message queue and one thread queue. This argument is wrong. In fact there is only one message queue, not the so-called thread queue. Of course, post (Runnable) does not start a new thread, it is still on the current thread. Note: There is also a saying that the handler object is in the main thread, which is also wrong, exactly in the production of his threads. Although often we are in the main thread to produce his. So how do we build multithreaded programs on Android? It's simple, it's a multithreaded way of Java. Either implement the Runnable interface or inherit the thread class. The concepts of thread synchronization, thread locking, threading async, thread pooling are the same. I will not be tired of the statement. Well, after a little bit of a brief introduction, we have some handler foundation, and now we begin to go back to our question and start to analyze: Mhandler.post (newrunnable () {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 (); From the above code, we can see that the Player control buttons (such as play, pause, stop) and so on, are placed in the message queue by Handler.post (Runnable), sort to handle. The reason why there is no response is that it is possible that a control operation is too time consuming or resource intensive. At this time to receive new messages to be processed, it will not be processed. So I'm trying to get a task that has only one control player button in the queue at the same time. I made the following changes to the code: Runnabler = new Runnable () {public void run () {try {Presentregionmedia (view, (Regionmediamodel) model, Datach anged); } 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 (); }}mhandler.removecallbacks (R); Mhandler.post (R); The code slowly looks, the idea is simple: in fact, before postrunnable the same runnable instance that was saved in the queue. This guarantees that only one operation in the queue is processed at the same time. Unfortunately, it does not take effect. : (After the change, the problem still exists, want to cry without tears.) Again, I'll change the whole mode to message and try again, the core code is as follows: if (Mhandler.hasmessages (Media_play_what_messageflag)) {REturn; } messagemsg = Mhandler.obtainmessage (); Msg.what= this. Media_play_what_messageflag; Msg.obj= Mmeidaplaymessageobj; Mhandler.sendmessagedelayed (msg,1000); code slowly look, the idea is very simple, by sending a message, the first detection if there is a related message queue, directly out of the function, do not do any processing, or delay a second after a message sent to the queue. Why I spent 1 seconds this long time, because this long time if can not handle, it is not the stress test problem, but the method itself is a problem, this is also through the elimination of the law to try to exclude is because the screen is too fast to produce problems. Compile, try again, very not, and not effective, unfortunately I guess. Look at the heavens! Now the problem is obvious: not the stress test when you click on the ANR, but some of the methods themselves have problems. Past our log-–pid 2922 at 2011-01-13 13:51:07-–cmdline:com.android.mmsdalvikthreads: "Main" prio=5 tid=1 NATIVE |group= "Ma In "Scount=1 dscount=0 s=n obj=0x4001d8d0self=0xccc8 |systid=2922 nice=0 sched=0/0 cgrp=default handle=-1345017808 | schedstat= (3497492306 15312897923 10358) atandroid.media.mediaplayer._release (Native Method) Atandroid.media.MediaPlayer.release (mediaplayer.java:1206) Atandroid.widget.VideoView.stopPlayback ( videoview.java:196) Atcom.android.mms.ui.SlideView.stopVideo (slideview.java:640) It's easy to know the problem is that release () is called after each execution of the Mediaplayer.stop () method call to free the player resource. And this method died in the _release () method. This is a NATIve method. So the truth is, the problem is that the native method _release () is called on the MediaPlayer of the framework layer.

Android Log Learning