Android ANR error troubleshooting

Log plays a very important role in Android. As an android programmer, log analysis cannot be performed. Therefore, there is no entry level for Android. Next we will talk about how to process log files.

When will log files be generated?
We all know that the log is generated, and we all know that the log is viewed through ddms. But when will the log file be generated? Generally, log files are generated in the following situations.
1. The program exits unexpectedly, and the uncaused exception
2. Force closed (FC)
3. The program has no response. Application No response (ANR for short). By the way, if the main thread has been processed for more than 5 seconds, ANR will
4. manually generated.


To get a log file, you need to divide it into multiple sections. The log file is very long and contains more than a dozen small units of information, but it should not be scared. In fact, it is mainly composed of three major units.

1. Basic system information, including memory, CPU, process queue, virtual memory, and garbage collection.

------ 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
Kernelstacks: 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 the main analysis 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 CT 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,101 5, 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 = 26 mflags = 9}

3. Virtual Machine information, including process and thread tracking information, is a good place to track process and thread specific points.
------ VM traces just now (/data/ANR/traces.txt. bugreport: 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 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
| Shard id = 21161 nice = 0 sched = 0/0 CRL = default handle =-1345017808
| Schedstat = (4151552996 5342265329 10995)
At 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: 587)
At Android. OS. handler. dispatchmessage (handler. Java: 92)
At Android. OS. lorule. Loop (lorule. 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)

Certificate ---------------------------------------------------------------------------------------------------------------------------------------
I have summarized the basic steps for observing log files. 1. If it is an ANR problem, search for the "ANR" keyword. Quickly locate critical events.
2. For forceclosed and other abnormal exit information, search for the "Fatal" keyword to quickly locate the key event information.
3. After locating the critical event information, if the information is not clear enough, search the virtual machine information of the application package, view the specific process and thread tracking logs, and locate the code.

In this way, when a problem occurs, you do not need to perform breakpoint debugging. you can locate the problem directly and try again and again.
Next, we will start to analyze the log of this example.

Open the log file because it is an ANR error. Therefore, search for "ANR". Why should I add a space? You can simply add and remove it and make a comparison. It can block a lot of invalid information stored in the ANR. log file.

Locate the critical 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 1337225 ms 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% 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 logs. This is also a capability.
01-15 16:49:02. 433 E/activitymanager (2466): ANR in COM. Android. MMS (COM. Android. MMS/. UI. slideshowactivity)
Translation: activitymanager (process number: 433) has the following error at, 2 seconds, 2466 milliseconds: The. UI. slideshowactivity under the com. Android. MMS package has no response.

01-15 16:49:02. 433 E/activitymanager (2466): reason: keydispatchingtimedout
Translation: cause: keydispatchingtimeout-key allocation timeout

01-15 16:49:02. 433 E/activitymanager (2466): load: 0.6/0.61/0.42
5 minutes, 10 minutes, 15 minutes average load: 0.6, 0.61, 0.42

Here we probably know what the problem is. Combined with our previous operation process, we know that the problem is that the button event may not be handled at some time when the button is clicked, resulting in no response for timeout. Now it seems that you can start your work. We know that the activity processes click screen events by reloading dispatchtouchevent (motionevent eV. Then we can find the cause by analyzing it. But is that enough?
In fact, it is not enough. At least we cannot know exactly where the problem is. We just guess, for example, in this application, I found that multiple I/O operations are in the main thread, which may cause problems, but it is difficult to determine which one is, so the information we currently have is not enough.

Then we analyze the virtual machine information and search for the keyword "Dalvik thread" to quickly locate the virtual machine information log of this application, as shown below:
----- PID 2922 at 13:51:07 -----
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
| Shard id = 2922 nice = 0 sched = 0/0 CRL = default handle =-1345017808
| Schedstat = (3497492306 15312897923 10358)
At 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: 587)
At Android. OS. handler. dispatchmessage (handler. Java: 92)
At Android. OS. lorule. Loop (lorule. 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
| Shard id = 3239 nice = 0 sched = 0/0 CRL = 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
| Shard id = 3236 nice = 0 sched = 0/0 CRL = default handle = 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. lorule. Loop (lorule. Java: 110)
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
| Shard id = 2929 nice = 0 sched = 0/0 CRL = default handle = 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 = 7 native
| Group = "Main" scount = 1 dscount = 0 s = n OBJ = 0x482f8ca0 self = 0x130fd0
| Shard id = 2928 nice = 0 sched = 0/0 CRL = default handle = 1215968
| Schedstat = (40610049 1837703846 195)
At Dalvik. system. nativestart. Run (native method)

"Binder thread #1" PRIO = 5 tid = 6 native
| Group = "Main" scount = 1 dscount = 0 s = n OBJ = 0x482f4a78 self = 0x128a50
| Shard id = 2927 nice = 0 sched = 0/0 CRL = default handle = 1201352
| Schedstat = (40928066 928867585 190)
At Dalvik. system. nativestart. Run (native method)

"Compiler" daemon PRIO = 5 tid = 5 vmwait
| Group = "system" scount = 1 dscount = 0 s = n OBJ = 0x482f1348self = 0x118960
| Shard id = 2926 nice = 0 sched = 0/0 CRL = 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
| Shard id = 2925 nice = 0 sched = 0/0 CRL = default handle = 1255680
| Schedstat = (2827103 29553323 19)
At Dalvik. system. nativestart. Run (native method)

"Signal catcher" daemon PRIO = 5 tid = 3 runnable
| Group = "system" scount = 0 dscount = 0 s = n OBJ = 0x482f11e8 self = 0x135988
| Shard id = 2924 nice = 0 sched = 0/0 CRL = 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
| Shard id = 2923 nice = 0 sched = 0/0 CRL = default handle = 1222608
| Schedstat = (79049792 1520840200 95)
At Dalvik. system. nativestart. Run (native method)

----- End2922 -----

Each section is a thread. Of course, we still need to look at the main thread with thread number 1. The key problems found through analysis are as follows:
At com. Android. mms. UI. slideshowpresenter $ 3.run( slideshowpresenter. Java: 531)
Locate the 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 execution time after the handler. Post method is too long. Continue to check the presentregionmedia (view, (regionmediamodel) model, datachanged); method. It is found that the mediaplayer. Stop method is called in the framework.
So far, our log analysis has come to an end. You can start to think about the solution.