Android FAQ-Log Analysis

Common android dead-end problems-Log Analysis

========================================================== ========================================================== ==============================
In normal work, a lot of code can be debugged in eclipse + ndk, but if you need to use specific hardware devices, such as media playback devices that cannot be simulated, debugging can only be performed on hardware (boxes or mobile phones. At this time, the only debugging method is that logcat generates log information for analysis.

When will log files be generated? Generally, log files are generated in the following situations.
1. Program exited uncaused exception
2. Force close (FC) of the program)
3. The program does not respond to Application No response (ANR for short). Generally, if the main thread exceeds 5 seconds, then ANR will
4. manually generate

Log on to the console and enter the logcat command for output.

Part 1

1. Introduction to analysis tools

A. CAT/proc/meminfo displays basic memory information.

------ Memory Info (/proc/meminfo )------

Memtotal: 285184 KB
Memfree: 106360 KB
Buffers: 0 KB
Cached: 60036 KB
Swapcached: 0 KB
Active: 98160 KB
Inactive: 49100 KB
Active (Anon): 87260 KB
Inactive (Anon): 288 KB
Active (File): 10900 KB
Inactive (File): 48812 KB
Unevictable: 0 KB
Mlocked: 0 KB
Swaptotal: 0 KB
Swapfree: 0 KB
Dirty: 0 KB
Writeback: 0 KB
Anonpages: 87240 KB
Mapped: 26500 KB
Shmem: 324 KB
Slab: 13340 KB
Sreclaimable: 1672 KB
Sunreclaim: 11668 KB
Kernelstacks: 2160 KB
Pagetables: 5600 KB
Nfs_unstable: 0 KB
Bounce: 0 KB
Writebacktmp: 0 KB
Commitlimit: 142592 KB
Committed_as: 1065600 KB
Vmalloctotal: 417792 KB
Vmallocused: 137700 KB
Vmallocchunk: 254980 KB

Pay attention to the following values:
Memtotal: 285184 kb // total physical memory size
Memfree: 106360 kb // available memory
Buffers: 0 kb // disk cache memory size
Cached: 60036 KB

# Free
Free
Total used free shared Buffers
Mem: 285184 178884 106300 0 0
Swap: 0 0 0
Total: 285184 178884 106300

In Linux, there is such an idea that the memory does not need to be white, so it tries its best to cache and buffer some data to facilitate the next use.
But in fact, these memories can also be used immediately.
So free memory = free + buffers + cached = total-used

Several other commands can be used:
/Proc/meminfo memory usage information of the machine
/Proc/Pid/maps PID is the process number and displays the virtual address occupied by the current process.
Memory occupied by/proc/Pid/statm Process

B. View Process Information
------ CPU Info (top-N 1-D 1-M 30-T )------
Displays the resource usage of various processes in the system in real time, similar to the Windows Task Manager.

C. Some operation tools provided by Android
------ Procrank (procrank )------
------ Procmem (procmem )------
------ Showmap (showmap )------
... I will not list them one by one. If you are interested, you can check them out.

The code of this tool is located in/system/extras of Android.

D. Virtual Memory viewing tool
------ Virtual memory stats (/proc/vmstat )------
------ Vmalloc Info (/proc/vmallocinfo )------

2. Time information is also our main analysis information

The format is as follows:
------ System Log (logcat-B system-V Time-D *: V )------
$: Logcat-B system-V Time-D *: V

01-02 08:00:02. 570 I/systemserver (957): Notification Manager
01-02 08:00:02. 570 I/systemserver (957): Device storage Monitor
01-02 08:00:02. 580 I/systemserver (957): Location Manager
01-02 08:00:02. 580 I/systemserver (957): Search Service
01-02 08:00:02. 590 I/systemserver (957): Dropbox Service
01-02 08:00:02. 590 I/systemserver (957): wallpaper Service

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 1516 at 08:03:07 -----
Cmd Line: COM. ipanel. Join. appstore

Dalvik threads:
(Mutexes: tll = 0 TSL = 0 tscl = 0 ghl = 0 hwl = 0 hwll = 0)
"Main" PRIO = 5 tid = 1 native
| Group = "Main" scount = 1 dscount = 0 OBJ = 0x4001f188 self = 0xd028
| Shard id = 1516 nice = 0 sched = 3/0 RGPS = [fopen-error: 2] handle =-1345017744

Part 2

How to analyze log information

1. Keyword eye for error information
"Error" "failxx" "E/" and other error messages
Solve these problems first

2. dynamic database crashes

View keywords similar to "build fingerprint :"
I/debug (692 ): **************************************** ********
I/debug (692): Build fingerprint: 'generic/generic: 2.3.1/grh78/eng. userdev-rd6-input.20120221.113348: Eng/test-keys'
I/debug (692): PID: 694, TID: 694 >>>/ system/bin/mediaserver <
I/debug (692): Signal 11 (SIGSEGV), Code 1 (segv_maperr), fault ADDR 00000 input module init -->
010

For this information, you can view the Analysis of the Dynamic Library:
Http://blog.csdn.net/andyhuabing/article/details/7074979

3. Solve the Problem of throwing exceptions in Java
E/usbobservers (957): Java. Lang. nullpointerexception
E/usbobserver (957): At com. Android. server. usbobserver. INIT (usbobserver. Java: 131)
E/usbobserver (957): At com. Android. server. usbobserver. <init> (usbobserver. Java: 65)
E/usbobserver (957): At com. Android. server. serverthread. Run (systemserver. Java: 419)
I/systemserver (957): Ui mode Manager Service

Find the Java code and analyze its implementation.

4. ANR Problems
Search for the "ANR" keyword to quickly locate the key event information.

Locate the critical event information as follows:
I/dalvikvm (1014): wrote stack traces to '/data/ANR/traces.txt'
I/process (957): Sending signal. PID: 1124 Sig: 9
E/activitymanager (957): ANR in COM. ipanel. Join. appstore
E/activitymanager (957): reason: Broadcast of intent {act = android. appwidget. action. appwidget_update CMP = com. ipanel. join. appstore /. widget. smallwidget1 (has extras )}
E/activitymanager (957): load: 1.57/0.38/0.13
E/activitymanager (957): CPU usage from 6290 ms to 0 Ms ago:
E/activitymanager (957): 70% 957/system_server: 1.1% user + 69% kernel/faults: 204 minor
E/activitymanager (957): 8.7% 1014/COM. ipanel. Join. Home. Jelly: 7.7% user + 0.9% kernel/faults: 899 minor
E/activitymanager (957): 0.3% 687/yaffs-bg-1: 0% user + 0.3% Kernel
E/activitymanager (957): 0.3% 688/yaffs-bg-1: 0% user + 0.3% Kernel
E/activitymanager (957): 0.3% 935/irkeyservice: 0% user + 0.3% Kernel
E/activitymanager (957): 0% 890/galcore daemon: 0% user + 0% Kernel
E/activitymanager (957): 0.1% 1076/COM. ipanel. Join. Browser: 0.1% user + 0% Kernel
E/activitymanager (957): 0.1% 1124/COM. ipanel. Join. appstore: 0.1% user + 0% Kernel
E/activitymanager (957): 75% Total: 4.7% user + 70% Kernel
E/activitymanager (957): CPU usage from 622 ms to 1169 Ms later:
E/activitymanager (957): 71% 957/system_server: 0% user + 71% kernel/faults: 2 minor
E/activitymanager (957): 67% 965/surfaceflinger: 0% user + 67% Kernel
E/activitymanager (957): 1.9% 973/activitymanager: 1.9% user + 0% Kernel
E/activitymanager (957): 1.9% 991/cursormove: 0% user + 1.9% Kernel
E/activitymanager (957): 7.6% 1014/COM. ipanel. Join. Home. Jelly: 7.6% user + 0% kernel/faults: 31 minor
E/activitymanager (957): 5.7% 1119/thread-13: 5.7% user + 0% Kernel
E/activitymanager (957): 1.9% 1123/thread-13: 1.9% user + 0% Kernel
E/activitymanager (957): 76% Total: 1.8% user + 72% kernel + 1.8% softirq

Specifies which Java package has a problem
E/activitymanager (957): ANR in COM. ipanel. Join. appstore

The following error occurs when the process number is 957: the broadcast problem in the com. ipanel. Join. appstore package

ANR reason:
E/activitymanager (957): reason: Broadcast of intent {act = android. appwidget. action. appwidget_update CMP = com. ipanel. join. appstore /. widget. smallwidget1 (has extras )}

This is the ANR stack call file.
I/dalvikvm (1014): wrote stack traces to '/data/ANR/traces.txt'

Through the above log information analysis, it should have timed out when receiving a broadcast message.

After analyzing the VM information, open/data/ANR/traces.txt. You can use ADB pull/data/ANR/traces.txt.

Every section here is a thread. Of course we still look at the main thread with thread number 1. The key problems found through analysis are as follows:

Search for the keyword "Dalvik Threads" to quickly locate the virtual machine information log of the application.
 
----- PID 1516 at 08:03:07 -----
Cmd Line: COM. ipanel. Join. appstore

Dalvik threads:
(Mutexes: tll = 0 TSL = 0 tscl = 0 ghl = 0 hwl = 0 hwll = 0)
"Main" PRIO = 5 tid = 1 native
| Group = "Main" scount = 1 dscount = 0 OBJ = 0x4001f188 self = 0xd028
| Shard id = 1516 nice = 0 sched = 3/0 RGPS = [fopen-error: 2] handle =-1345017744
At org. Apache. Harmony. luni. Platform. osnetworksystem. Connect (native method)
At Dalvik. system. blockguard $ wrappednetworksystem. Connect (blockguard. Java: 357)
At org.apache.harmony.luni.net. plainsocketimpl. Connect (plainsocketimpl. Java: 204)
At org.apache.harmony.luni.net. plainsocketimpl. Connect (plainsocketimpl. Java: 437)
At java.net. Socket. Connect (socket. Java: 983)
At org.apache.harmony.luni.internal.net. www. Protocol. http. httpconnection. <init> (httpconnection. Java: 74)
At org.apache.harmony.luni.internal.net. www. Protocol. http. httpconnection. <init> (httpconnection. Java: 48)
At org.apache.harmony.luni.internal.net. www. Protocol. http. httpconnection $ address. Connect (httpconnection. Java: 298)
At org.apache.harmony.luni.internal.net. www. Protocol. http. httpconnectionpool. Get (httpconnectionpool. Java: 89)
At org.apache.harmony.luni.internal.net. www.protocol. http. httpurlconnectionimpl. gethttpconnection (httpurlconnectionimpl. Java: 285)
At org.apache.harmony.luni.internal.net. www. Protocol. http. httpurlconnectionimpl. makeconnection (httpurlconnectionimpl. Java: 267)
At org.apache.harmony.luni.internal.net. www. Protocol. http. httpurlconnectionimpl. retrieveresponse (httpurlconnectionimpl. Java: 1018)
At org.apache.harmony.luni.internal.net. www. Protocol. http. httpurlconnectionimpl. getresponsecode (httpurlconnectionimpl. Java: 726)
At com. ipanel. Join. appstore. http. defaulthttprequest. doget (defaulthttprequest. Java: 35)
At com. ipanel. Join. appstore. widget. abssmallwidget. requestapps (abssmallwidget. Java: 117)
At com. ipanel. Join. appstore. widget. abssmallwidget. getremoteviews (abssmallwidget. Java: 56)

In fact, from this sentence:
At org. Apache. Harmony. luni. Platform. osnetworksystem. Connect (native method)
Basically, it is confirmed that the socket-> connect connection times out, resulting in the main thread failing to respond within 5 seconds, resulting in an ANR error. The default connect connection timeout time is 75 s.
In fact, the solution is to use the non-blocking method for connection.

From the CPU usage, we can also see that it is blocked in the kernel.
E/activitymanager (957): 75% Total: 4.7% user + 70% Kernel

5. An error occurred while executing dexopt.

W/dalvikvm (1803): dexopt: --- end 'settingsprovider.apk '--- status = 0x000a, process failed
E/dalvikvm (1803): unable to extract + optimize Dex from '/system/APP/settingsprovider.apk'
E/systemserver (1803): failure starting input Manager Service
E/systemserver (1803): Java. lang. runtimeexception: Unable to get provider COM. android. providers. settings. settingsprovider: Java. lang. classnotfoundexception: COM. android. providers. settings. settingsprovider in loader Dalvik. system. pathclassloader [/system/APP/settingsprovider.apk]
E/systemserver (1803): at Android. App. activitythread. installprovider (activitythread. Java: 3557)
E/systemserver (1803): at Android. App. activitythread. getprovider (activitythread. Java: 3356)

As shown in the preceding figure, an error occurred while extracting or optimizing the extract + optimize Dex APK file.
1. There is no magic number error, which is irrelevant to atomic operations (this is a fast locking and unlocking lightweight operation function)
2. An error occurred while executing dexopt.
It is found that there is no space on the server hard disk, resulting in no space for decompression during the boot file system and Failure

6. crashes or random crashes by default after the system is started
This error occurs:
12-01 08:11:56. 027: Warn/sharedbufferstack (312): waitforcondition (lockcondition) timed out (identity = 19, status = 0). CPU may be pegged. trying again.
12-01 08:11:57. 315: Warn/sharedbufferstack (312): waitforcondition (lockcondition) timed out (identity = 19, status = 0). CPU may be pegged. trying again.
12-01 08:11:59. 318: Warn/sharedbufferstack (312): waitforcondition (lockcondition) timed out (identity = 19, status = 0). CPU may be pegged. trying again.
12-01 08:12:03. 332: Warn/sharedbufferstack (312): waitforcondition (lockcondition) timed out (identity = 19, status = 0). CPU may be pegged. trying again.
12-01 08:12:05. 329: Warn/sharedbufferstack (312): waitforcondition (lockcondition) timed out (identity = 19, status = 0). CPU may be pegged. trying again.
12-01 08:12:07. 216: Warn/keycharactermap (312): no keyboard for ID 0
12-01 08:12:07. 216: Warn/keycharactermap (312): Using default keymap:/system/usr/keychars/Qwerty. KCM. Bin

View memory: CAT/proc/meminfo found that there is only a few MB of free memory. Increase the memory of the Android system to solve the problem.

There is also a deadlock in the implementation of the gralloc module, please find out.