How to analyze Android Log

First, let's take a look at the AndroidLog format. The following log is printed in the so-called long format. As you can see from the previous Logcat introduction, the long format will display the time, tag, and so on as a separate line.

[12-09 21:39:35. 510 396: 416 I/ActivityManager]

Start procnet. coollet. infzmreader: umengService_v1 for service
Net. coollet. infzmreader/com. umeng. message.

UmengService: pid = 21745 uid = 10039 gids = {50039,300 3}

[12-09 21:39:35. 518 21745: 21745I/dalvikvm]

Turning on JNI app bug workarounds fortarget SDK version 8...

[12-09 21:39:35. 611 21745: 21745D/AgooService]

OnCreate ()

Let's take the first behavior as an example: is the date, 21:39:35. 510 is the time 396 is the process number, 416 is the thread number, I represents the log priority, ActivityManager is the log label.

In application development, this information may not be very useful. However, in system development, these are important auxiliary information. Many of the logs analyzed by development engineers are captured by test engineers, so some logs may not be the logs with errors at the time. If this happens, no matter how you analyze it, it is impossible to draw a correct conclusion. How can we avoid this situation to the maximum extent? The author asked the test engineer to fill in the time when the bug was reported. In this way, combined with the timestamp information in the log, you can roughly determine whether the log is in the case of an error. Based on the bug occurrence time provided by the test engineer, the development engineer can quickly locate the error location in the long log information to narrow down the analysis scope.

At the same time, we should also note that the time information may be incorrectly used in log analysis. For example, when analyzing multithreading-related problems, we sometimes need to judge the cause of the Error Based on the sequence of log statement execution in two different threads, however, we cannot determine the sequence of two log segments in the log file because the two threads output logs randomly in a short period of time, the log printing sequence is not exactly the same as the execution sequence. Can we determine the time stamp of log? Likewise, no, because the timestamp is actually the time when the system prints the output log, not the time when the log function is called. In this case, the only way is to call the system time function to obtain the current time before outputting the log, and then print the output through the log information. This is troublesome, but only the time obtained is reliable and can be used as the basis for our judgment.

Another misuse of the timestamp in log is to use it to analyze program performance. An engineer with many years of work experience showed me his performance analysis results. However, I am skeptical about the report, which is far different from the actual situation, so I asked the engineer how he came to the conclusion. He was surprised by his answer. The data he calculated was the timestamp before the log information. As we have mentioned earlier, the timestamp before the log is different from the time when the log function is called. This is caused by the System Buffer log information, and the time difference between the two is not fixed. Therefore, the performance of codes between two log segments may be relatively high by calculating the timestamps attached to log information. The correct method is as mentioned above: Get the system time in the program, print the output, and use the printed time to calculate the time spent.

After learning about the time, let's talk about the process Id and thread Id. They are also an important basis for log analysis. We can see that the log information of different processes is actually mixed and output together, which brings a lot of trouble for us to analyze logs. Sometimes, even two adjacent logs in a function may exchange logs of different processes, that is, the first log of process A is followed by the second log of process B. If such A combination is not carefully analyzed, it is easy to draw A wrong conclusion. At this time, you must carefully read the process Id before the log and put the logs with the same Id together.

Logs of different processes have the same problem. Logs output by different threads also have the same problem. When Logcat is added with-vthread, the thread Id can be printed. Note that the Android thread Id is not exactly the same as the Linux thread Id. First, in the Android system, the function gettid () of Linux used by the C ++ layer to obtain the thread Id cannot obtain the thread Id. The process Id is actually returned when gettid () is called. As an alternative, we can call pthread_self () to obtain a unique value to indicate the current native thread. Android also provides the androidGetThreaId () function to obtain the thread Id. This function is actually calling the pthread_self function. However, the Thread Id at the Java layer is another value. The Thread Id at the Java layer is obtained by calling the Thread's getId method, the returned value of this method is actually a global variable maintained by Android in the java layer of each process. Therefore, this value is different from the value obtained by the C ++ layer. This is also a problem we should pay attention to when analyzing logs. If it is a Java-layer thread Id, the general value will be relatively small, about several hundred; if it is a C ++-layer thread, the value is relatively large. In the log sample in the previous section, we can easily see that the first log is the log output by the Jave layer, and the second log is output by the native layer. With this understanding, we should not see the thread ids before the two log segments when analyzing the log to draw a simple conclusion that the two log segments are different, pay attention to the differences between the Jave layer and the native layer to avoid being misled.

AndroidLog priorities are converted to simple character tags such as V, I, D, W, and E during output printing. During system log analysis, it is difficult to identify a log file from the beginning to the end, and use a search tool to find the error mark. For example, search "E/" to see if there is any log indicating an error. Therefore, if every engineer involved in system development can output logs according to the priority definition defined by Android, this will make our heavy log analysis work easier.

Android has two common serious problems: Program crash and ANR. Program crashes and ANR may occur both on the java layer and on the native layer. If the problem occurs on the java layer, the cause of the error is generally easier to locate. If it is a native layer problem, in many cases, it is not that easy to solve the problem. Let's first look at a java layer crash example:

I/ActivityManager (396): Start proccom. test. crash for activity com. test. crash/. MainActivity:
Pid = 1760 uid = 10065 gids = {50065,102 8}

D/AndroidRuntime (1760): Shutting downVM

W/dalvikvm (1760): threadid = 1: threadexiting with uncaught exception (group = 0x40c38930)

E/AndroidRuntime (1760): FATALEXCEPTION: main

E/AndroidRuntime (1760): java. lang. RuntimeException: Unable to start activityComponentInfo
{Com. test. crash/com. test. crash. MainActivity}: java. lang. NullPointerException

E/AndroidRuntime (1760): atandroid. app. ActivityThread. initialize mlaunchactivity (ActivityThread. java: 2180)

E/AndroidRuntime (1760 ):Atandroid. app. ActivityThread. handleLaunchActivity (ActivityThread. java: 2230)

E/AndroidRuntime (1760 ):Atandroid. app. ActivityThread. access $600 (ActivityThread. java: 141)

E/AndroidRuntime (1760 ):Atandroid. app. ActivityThread $ H. handleMessage (ActivityThread. java: 1234)

E/AndroidRuntime (1760 ):Atandroid. OS. Handler. dispatchMessage (Handler. java: 99)

E/AndroidRuntime (1760 ):Atandroid. OS. lorule. loop (lorule. java: 137)

E/AndroidRuntime (1760 ):Atandroid. app. ActivityThread. main (ActivityThread. java: 5050)

E/AndroidRuntime (1760 ):Atjava. lang. reflect. Method. invokeNative (NativeMethod)

E/AndroidRuntime (1760 ):Atjava. lang. reflect. Method. invoke (Method. java: 511)

E/AndroidRuntime (1760 ):Atcom. android. internal. OS. ZygoteInit $ MethodAndArgsCaller. run
(Maid. java: 793)

E/AndroidRuntime (1760 ):Atcom. android. internal. OS. ZygoteInit. main (ZygoteInit. java: 560)

E/AndroidRuntime (1760 ):Atdalvik. system. NativeStart. main (NativeMethod)

E/AndroidRuntime (1760 ):Caused by: java. lang. NullPointerException

E/AndroidRuntime (1760 ): Atcom. test. crash. MainActivity. setViewText (MainActivity. java: 29)

E/AndroidRuntime (1760 ):Atcom. test. crash. MainActivity. onCreate (MainActivity. java: 17)

E/AndroidRuntime (1760 ):Atandroid. app. Activity. javasmcreate (Activity. java: 5104)

E/AndroidRuntime (1760): atandroid. app. Instrumentation. callActivityOnCreate (Instrumentation. java: 1080)

E/AndroidRuntime (1760): atandroid. app. ActivityThread. initialize mlaunchactivity (ActivityThread. java: 2144)

E/AndroidRuntime (1760 ):... 11 more

I/Process (1760): Sending signal. PID: 1760 SIG: 9

W/ActivityManager (396 ): Force finishing activitycom. test. crash/. MainActivity

When the code at the Jave layer encounters a crash problem, the system will usually print a detailed error message. For example, the above example shows not only the cause of the error, but also the file and number of lines in the error. Based on this information, we can easily locate the problem. Although the crash on the native layer also outputs stack log information, it is not easy to understand. Next let's look at an example of a native layer crash:

F/libc (2102): Fatal signal 11 (SIGSEGV) at 0x00000000 (code = 1), thread2102 (testapp)

D/dalvikvm (26630): GC_FOR_ALLOC freed 604 K, 11% free 11980 K/13368 K, paused 36 ms, total36ms

I/dalvikvm-heap (26630): Grow heap (frag case) to 11.831 MB for 102416-byteallocation

D/dalvikvm (26630): GC_FOR_ALLOC freed 1 K, 11% free 12078 K/13472 K, paused 34 ms, total34ms

I/DEBUG (127 ): **************************************** ********

I/DEBUG (127): Build fingerprint:
'Android/full_maguro/maguro: 4.2.2/JDQ39/eng. liuchao.20130619.201255: userdebug/test-keys'

I/DEBUG (127): Revision: '9'

I/DEBUG (127): pid: 2102, tid: 2102, name: testapp>>>./Testapp <

I/DEBUG (127): signal 11 (SIGSEGV), code 1 (SEGV_MAPERR), fault addr00000000

I/DEBUG (127 ): R0 00000020R172136874R2 400ff520R300000000

I/DEBUG (127 ): R4 400ff469R5beb4ab24R6 00000001R7beb4ab2c

I/DEBUG (127 ): R8 00000000R900000000Sl 00000000Fpbeb4ab1c

I/DEBUG (127 ): Ip 4009b5dcSpbeb4aae8Lr 400ff46fPc400ff45eCpsr60000030

I/DEBUG (127 ): D0000000008dae8D120178ced84450cec8

I/DEBUG (127 ): D220178cef84108cee8D320178cf181168cf08

I/DEBUG (127 ): D420178c5a84410c598D520178ca081168c5b8

I/DEBUG (127 ): D620178ce682138ce58D720178ce884268ce78

I/DEBUG (127 ): D80000000000000000D90000000000000000

I/DEBUG (127 ): D10 0000000000000000D110000000000000000

I/DEBUG (127 ): D120000000000000000D130000000000000000

I/DEBUG (127 ): D14 0000000000000000D150000000000000000

I/DEBUG (127 ): D16 c1dcf7c087fec8b4D173f50624dd2f1a9fc

I/DEBUG (127 ): D18 41c7b1ac89800000D190000000000000000

I/DEBUG (127 ): D20 0000000000000000D20000000000000000

I/DEBUG (127 ): D22 0000000000000000D230000000000000000

I/DEBUG (127 ): D24 0000000000000000D250000000000000000

I/DEBUG (127 ): D26 0000000000000000D270000000000000000

I/DEBUG (127 ): D28 0000000000000000D290000000000000000

I/DEBUG (127 ): D30 0000000000000000D30000000000000000

I/DEBUG (127 ): Scr 00000010

I/DEBUG (127 ):

I/DEBUG (127): backtrace:

I/DEBUG (127 ): #00Pc0000045e/System/bin/testapp

I/DEBUG (127 ): #01Pc0000046b/System/bin/testapp

I/DEBUG (127 ): #02Pc00000001f/System/lib/libc. so (_ libc_init + 38)

I/DEBUG (127 ): #03Pc00000400/System/bin/testapp

I/DEBUG (127 ):

I/DEBUG (127): stack:

I/DEBUG (127 ): Beb4aaa8201700c8

I/DEBUG (127 ): Beb4aaac00000000

I/DEBUG (127 ): Beb4aab000000000

I/DEBUG (127 ): Beb4aab4401cbee0/System/bin/linker

I/DEBUG (127 ): Beb4aab800001000

I/DEBUG (127 ): Beb4aabc40201.pdf/System/lib/libc. so (_ libc_fini)

I/DEBUG (127 ): Beb4aac040201.pdf/System/lib/libc. so (_ libc_fini)

I/DEBUG (127 ): Beb4aac440100eac/System/bin/testapp

I/DEBUG (127 ): Beb4aac800000000

I/DEBUG (127 ): Beb4aacc400ff469/System/bin/testapp

I/DEBUG (127 ): Beb4aad0Beb4ab24[Stack]

I/DEBUG (127 ): Beb4aad400000001

I/DEBUG (127 ): Beb4aad8Beb4ab2c[Stack]

I/DEBUG (127 ): Beb4aadc00000000

I/DEBUG (127 ): Beb4aae0Df0027ad

I/DEBUG (127 ): Beb4aae400000000

I/DEBUG (127 ): #00Beb4aae800000000

I/DEBUG (127 ): ................

I/DEBUG (127 ): #01Beb4aae800000000

I/DEBUG (127 ): Beb4aaec401e9721/System/lib/libc. so (_ libc_init + 40)

I/DEBUG (127 ): #02Beb4aaf0Beb4ab08[Stack]

I/DEBUG (127 ): Beb4aaf400000000

I/DEBUG (127 ): Beb4aaf800000000

I/DEBUG (127 ): Beb4aafc00000000

I/DEBUG (127 ): Beb4ab0000000000

I/DEBUG (127 ): Beb4ab04400ff404/System/bin/testapp

I/DEBUG (127 ):

This log is not so easy to understand, but we can still see a lot of information from it. Let's learn how to analyze this log. First, let's look at the following line:

Pid: 2102, tid: 2102, name: testapp>>>./Testapp <

From this line, we can know the pid and tid of the crash process. As we mentioned above, Android calls the gettid function to get the actual process ID, so the pid here is the same as tid. After knowing the process number, we can flip the log to see what the last log printed by the Process is. This can narrow down the scope.

The following describes the process name and startup parameters. The next line is important. It tells us the cause of the error from the system perspective:

Signal 11 (SIGSEGV), code 1 (SEGV_MAPERR), fault addr 00000000

Signal11 is one of the signals defined in Linux. It means Invalidmemory reference, which is invalid memory reference. With "faultaddr 00000000", we can basically determine that this is a crash caused by a null pointer. Of course, this is a Crash example specially made by the author to explain. It is easier to judge. Most actual examples may not be so easy.

Next, the log prints information about all the registers and stacks of the cpu. The most important thing here is the backtrace information obtained from the stack:

I/DEBUG (127): backtrace:

I/DEBUG (127 ): #00Pc0000045e/System/bin/testapp

I/DEBUG (127 ): #01Pc0000046b/System/bin/testapp

I/DEBUG (127 ): #02Pc00000001f/System/lib/libc. so (_ libc_init + 38)

I/DEBUG (127 ): #03Pc00000400/System/bin/testapp

Because there is no symbolic information in the actual running system, the file name and number of lines are not displayed in the printed log. This requires us to translate it with the symbolic information table left during compilation. Android provides a tool to do this translation: arm-eabi-addr2line, located under the prebuilts/gcc/linux-x86/arm/arm-eabi-4.6/bin directory. Easy to use:

#./Arm-eabi-addr2line-f-eout/target/product/hammerhead/symbols/system/bin/testapp0x0000045e

The-f parameter indicates the printed function name. The-e parameter indicates the module path of the signed table, and the address to be converted. The result of this command in my compiling environment is:

Memcpy /Home/rd/compile/android-4.4_r1.2/bionic/libc/include/string. h: 108

The three remaining addresses are translated as follows:

Main/Home/rd/compile/android-4.4_r1.2/packages/apps/testapp/app_main.cpp: 38

Out_vformat/Home/rd/compile/android-4.4_r1.2/bionic/libc/bionic/libc_logging.cpp: 361

_ StartLibgcc2.c: 0

Using this information, we can quickly locate the problem. However, it is troublesome to manually translate one line. The author uses a script found on the Internet to translate all lines at a time. Readers who need it can find it online.

After learning how to analyze common Log files, let's take a look at how to analyze ANR Log files.