Cómo analizar los registros de Android
[ 12-09 21:39:35.510 396: 416 I/ActivityManager]
Inicie procnet.coollet.infzmreader: umengService_v1 para el servicio
net.
UmengService: pid=21745 uid=10039 gids={50039, 3003, 1015, 1028}
[12-09 21:39:35.518 21745:21745I/dalvikvm]
Activando soluciones de errores de la aplicación JNI para Target SDK versión 8...
[ 12-09 21:39:35.611 21745:21745D/AgooService ]
onCreate()
Tomemos la primera línea como ejemplo: 12-09 es la fecha, 21:39:35.510 es la hora, 396 es el número de proceso, 416 es el número de hilo, I representa la prioridad del registro y ActivityManager es la marca de registro.
En el desarrollo de aplicaciones, esta información puede resultar de poca utilidad. Pero en el desarrollo de sistemas, ésta es información auxiliar importante. Muchos de los registros analizados por los ingenieros de desarrollo fueron capturados por ingenieros de pruebas, por lo que es posible que algunos ni siquiera sean los que salieron mal en ese momento. Si este es el caso, no importa cómo lo analices, es poco probable que llegues a la conclusión correcta. ¿Cómo evitar al máximo esta situación? Exijo que los ingenieros de pruebas completen la hora en que ocurrió el error al informar un error. De esta manera, combinada con la información de la marca de tiempo en el registro, puede determinar aproximadamente si se produjo el error en el registro. Además, según el momento en el que ocurrió el error proporcionado por el ingeniero de pruebas, el ingeniero de desarrollo puede localizar rápidamente la ubicación del error en la extensa información del registro y limitar el alcance del análisis.
Al mismo tiempo, cabe señalar que se puede abusar de la información de tiempo en el análisis de registros. Por ejemplo, al analizar problemas de subprocesos múltiples, a veces necesitamos juzgar la causa del error en función del orden de ejecución de las declaraciones de registro en dos subprocesos diferentes, pero no podemos usar el orden en que aparecen los dos registros en el archivo de registro como la condición de juicio, esto se debe a que en un corto período de tiempo, el orden en que los dos subprocesos generan los registros es aleatorio y el orden de impresión de los registros no es exactamente el mismo que el orden de ejecución. El orden de impresión de los registros no es exactamente el mismo que el orden de ejecución. Entonces, ¿podemos usar la marca de tiempo del registro para determinar esto? Todavía no funciona, porque la marca de tiempo es en realidad la hora en que el sistema imprime el registro, no la hora en que se llama a la función de registro. La única forma es llamar a la función de hora del sistema para obtener la hora antes de que se genere el registro y luego imprimir la información del registro. Es un poco engorroso, pero es la única manera de obtener tiempos confiables en los que basar tu juicio.
Otra forma de abusar de las marcas de tiempo de registro es utilizarlas para analizar el rendimiento del programa. Un ingeniero con muchos años de experiencia me mostró los resultados de su análisis de desempeño, pero yo era escéptico ante el informe, que estaba lejos de la realidad, y le pregunté cómo había llegado el ingeniero a esa conclusión. Su respuesta sorprendió al autor. Los datos que utilizó para el cálculo fueron la marca de tiempo delante de la información del registro. Como dijimos antes, la marca de tiempo antes del registro es diferente del momento en que se llama a la función de registro. Esto se debe a que el sistema almacena en el búfer la información del registro y la diferencia de tiempo entre los dos tiempos no es fija. Por lo tanto, utilizar la marca de tiempo adjunta antes de la información del registro para calcular el rendimiento del código entre los dos registros producirá un error relativamente grande.
El método correcto es el mismo que el anterior: obtenga la hora del sistema en el programa e imprímala, luego use la hora que imprimimos para calcular el tiempo empleado.
Después de comprender el tiempo, hablemos sobre el ID del proceso y el ID del hilo, que también son importantes para analizar el registro. En los archivos de registro que vemos, la información de registro de diferentes procesos en realidad se mezcla y se genera, lo que nos genera muchos problemas al analizar los registros. A veces, incluso dos registros adyacentes en una función tendrán registros de diferentes procesos generados alternativamente, es decir, el primer registro es para el proceso A y el segundo registro es para el proceso B. Si no analiza esta combinación con cuidado, es fácil sacar conclusiones equivocadas. En este punto, debemos mirar cuidadosamente la ID del proceso frente al registro y juntar los registros con la misma ID.
Los registros de diferentes procesos tienen este problema y los registros de diferentes subprocesos también tienen el mismo problema. Logcat con -vthread puede imprimir la identificación del subproceso, pero una cosa a la que debemos prestar atención es que la identificación del subproceso de Android no es exactamente la misma que normalmente llamamos la identificación del subproceso de Linux. En primer lugar, en Android, la función de Linux gettid() utilizada por la capa C para obtener la identificación del subproceso no puede obtener la identificación del subproceso. Llamar a gettid() en realidad devuelve la identificación del proceso. Como alternativa, podemos llamar a pthread_self() para obtener un valor único para marcar el hilo local actual. Android también proporciona una función androidGetThreaId() para obtener el ID del hilo. Esta función en realidad llama a la función pthread_self. Pero en la capa Java, el ID del hilo es otro valor. El ID del hilo de la capa Java se obtiene llamando al método getId de Thread. El valor de retorno de este método en realidad proviene de una variable global mantenida por Android en la capa Java de cada proceso. este valor No es lo mismo que el valor obtenido por la capa C. Esto es a lo que debemos prestar atención al analizar registros. Si se trata de un ID de subproceso de capa Java, el valor generalmente será relativamente pequeño, alrededor de unos cientos, si se trata de un subproceso de capa C, el valor será relativamente grande. En el ejemplo de registro anterior, podemos ver fácilmente que el primer registro es el registro de salida de la capa Java y el segundo es el registro de salida de la capa nativa. Sabiendo esto, cuando analicemos los registros, no veremos que los ID de los subprocesos delante de los dos registros sean diferentes y simplemente concluiremos que son dos registros de subprocesos diferentes. También debemos prestar atención a la diferencia entre la capa Java y la capa. capa nativa, para evitar engaño.
Las prioridades de AndroidLog se convierten en marcadores de caracteres simples como V, I, D, W, E, etc. en la impresión. Al analizar los registros del sistema, apenas podemos ver un archivo de registro de principio a fin. En este momento, podemos usar herramientas de búsqueda para encontrar marcadores de error. Por ejemplo, busque "E/" para ver si algún registro muestra errores. Por lo tanto, si todos los ingenieros involucrados en el desarrollo del sistema pueden cumplir con la definición de Android del significado de prioridad del registro de salida, nuestro análisis de registros pesados será relativamente más fácil. fácil.
Hay dos tipos principales de problemas graves que son comunes en los sistemas Android: fallos de programas y ANR. Los fallos del programa y los ANR pueden ocurrir tanto en la capa Java como en la capa nativa. Si el problema ocurre en la capa de Java, generalmente es más fácil encontrar la causa del error. Si el problema ocurre a nivel local, en muchos casos no es tan fácil de resolver.
Veamos un ejemplo de un fallo de la capa Java:
I/ActivityManager( 396): Inicie proccom.test.crash para la actividad com.test.crash/.MainActivity:
pid =1760 uid= 10065 gids={50065, 1028}
D/AndroidRuntime( 1760): ApagandoVM
W/dalvikvm( 1760): threadid=1: subprocesamiento con excepción no detectada (grupo=0x40c38930)
E/AndroidRuntime( 1760): FATALEXCEPTION: principal
E/AndroidRuntime( 1760): java.lang.RuntimeException: no se puede iniciar actividadComponentInfo
{com.test.crash/com.test.crash.MainActivity}: java.lang.NullPointerException
E/AndroidRuntime(1760): enandroid.app.ActivityThread.performLaunchActivity(ActivityThread.java: 2180 )
E/AndroidRuntime( 1760): atandroid.app.ActivityThread.handleLaunchActivity(ActivityThread.java: 2230)
E/AndroidRuntime( 1760).: atandroid.app.ActivityThread acceso$600(ActivityThread.java：141)
E/AndroidRuntime(1760): enandroid.app.ActivityThread$H.handleMessage(ActivityThread.java：1234)
E/AndroidRuntime. (1760): enandroid.os.Handler.dispatchMessage(Handler.java：99)
E /AndroidRuntime(1760): enandroid.os.Looper.loop(Looper.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.inte
rnal.os.ZygoteInit$MethodAndArgsCaller.run
(ZygoteInit.java:793)
E/AndroidRuntime(1760): atcom.android.internal.os.ZygoteInit.main(ZygoteInit .java: 560)
E/AndroidRuntime( 1760): atdalvik.system.NativeStart.: Causado por: java.lang.NullPointerException
E/AndroidRuntime( 1760): atdalvik. system.NativeStart.main(NativeMethod)
E/AndroidRuntime( 1760): atdalvik.system.NativeStart.main(NativeMethod)
E/AndroidRuntime( 1760).test.crash. MainActivity.onCreate(MainActivity.java：17)
E/AndroidRuntime( 1760): atandroid.app.Activity.performCreate(Activity.java：5104)
E/AndroidRuntime( 1760 ): en android.app.Instrumentation.callActivityOnCreate(Instrumentation.java:1080)
E/AndroidRuntime(1760): enandroid.app.ActivityThread.performLaunchActivity(ActivityThread.java:2144)
E/AndroidRuntime( 1760): ... 11más
I/Process ( 1760): Enviando señal.PID: 1760 SIG: 9
W/ActivityManager( 396): Forzado Fin de actividadcom.test.crash/.MainActivity
Cuando el código de la capa Java falla, el sistema generalmente imprime información de error muy detallada. Por ejemplo, el ejemplo anterior no solo proporciona el motivo del error, sino también el archivo y el número de línea del error. Aunque la información del registro de pila se genera para fallas de la capa local, no es tan fácil de leer.
Aquí hay otro ejemplo de una falla de la capa nativa:
F/libc (2102): señal fatal 11 (SIGSEGV) en 0x00000000 (código=1), hilo2102 (testapp)
D / dalvikvm(26630): GC_FOR_ALLOC liberó 604K, 11 libres 11980K/13368K, pausado 36ms, total36ms
I/dalvikvm-heap(26630): Aumente el montón (caso de fragmentación) a 11,831MB para una asignación de 102416bytes
D/dalvikvm(26630): GC_FOR_ALLOC liberado 1K, 11 libres 12078K/13472K, pausado 34ms, total34ms
I/DEBUG(127): *** eng.liuchao.20130619.201255: userdebug /test-keys'
I/DEBUG (127): Revisión: '9'
I/DEBUG (127): pid: 2102, tid: 2102, nombre: testapp gt ;gt;gt;./testapp lt;lt;lt;
I/DEBUG (127): señal 11 (SIGSEGV), código 1 (SEGV_MAPERR), dirección de fallo00000000
I /DEBUG ( 127): r0 00000020 r173696874 r2 400ff520 r300000000
I/DEBUG ( 127): R4 400ff469 R5BEB4AB24 R6 00000001 R7BEB4AB2C
I/DEBUG ( 12 7): R8 00000000 R900000000 SL 00000000 FPBEB4AB1C
I/DEBUG (127): IP 4009B5DEC SPBEB4AEAE8 LR 400FF46F PCC400FF45E CPSR 60000030
I/DEBUG (127): d0 000000004108dae8 d1 08cec8
127) :D6 4108CE684108CE58 D7 4108CE884108CE78
I/DEBUG ( 127 ): D8 0000000000000000 D9 0000000000000000
I/DEBUG ( 127 ): D10 000000000 D1100000000000000
Yo /DEBUG ( 1 27):d120000000000000000 d13000000000000000000
I/DEBUG (127): d1
4 000000000000000 d1500000000000000000
I/DEBUG (127): d16 c1dcf7c087fec8b4 d173f50624dd2f1a9fc
I/DEBUG (127): D18 41C7B 000 D190000000000000000
I/DEPURACIÓN ( 127 ) : D20 0000000000000000 D2100000000000000000000
I/DEBUG ( 127): D22 0000000000000000 D2300000000000000000
00000000000000000 D250000000000000000
I/DEBUG (127): D26 0000000000000000 D27000000000000
I/DEBUG ( 127): D28 0000000000000000 D29000000000000
I/DEBUG ( 127): D30 00000000000 00000 D31000000000000000000000
I/DEBUG ( 1 27): SCR 00000010
I/DEBUG (127):
I/DEBUG (127): rastreo inverso:
I/DEBUG (127): # 00 pc0000045e /system/bin /testapp
I/DEBUG (127): #01 pc0000046b /system/bin/testapp
I/DEBUG (127): #02 pc0001271f /system /lib/libc.so (__libc_init 38)
I/DEBUG (127): #03 pc00000400 /system/bin/testapp
I/DEBUG (127):
I/ DEBUG (127): pila:
I/DEBUG (127): beb4aaa8 000000c8
I/DEBUG (127): beb4aaac 00000000
I/DEBUG ( 127): beb4aab0 00000000
I/DEBUG (127).beb4aab4 401cbee0 /system/bin/linker
I/DEBUG (127): beb4aab8 00001000
I/DEBUG (127): beb4aabc 4020191d /system/lib/libc.so (__ libc_fini)
I/DEBUG (127): beb4aac0 4020191d /system/lib/libc so (__libc_fini)
I/DEBUG (127): beb4aac4 40100eac /system/bin/testapp
I/DEBUG (127): beb4aac8 00000000
I/DEBUG (127): beb4aacc 400ff469 /system/bin/testapp
I/DEBUG (127): beb4aad0 beb4ab24 [pila]
I/DEBUG (127): beb4aad4 00000001
I/DEBUG (127): beb4aad8 beb4ab2c [pila]
I/DEBUG (127): beb4aadc 00000000
I/DEBUG (127): beb4aae0 df0027ad
I/DEBUG (127): beb4aae4 00000000
I/DEBUG (127): #00 beb4aae8 00000000
I/DEBUG (127).: ........ .......
I/DEBUG ( 127): #01 beb4aae8 00000000
I/DEBUG ( 127): beb4aaec 401e9721 / system/lib/libc.so (__libc_init 40)
I/DEBUG (127).#02 beb4aaf0 beb4ab08 [pila]
I/DEBUG (127): beb4aaf4 00000000< / p>
I/DEBUG (127): beb4aaf8 00000000
I/DEBUG (127): beb4aafc 00000000
I/DEBUG (127): beb4ab00 00000000
I/DEBUG (127): beb4ab04 400ff404 /system/bin/testapp
I/DEBUG (127):
Este registro no es fácil de entender, pero sigue siendo A Se puede ver mucha información en él. Aprendamos a analizar este tipo de registro. Primero mire la siguiente línea:
pid: 2102, tid: 2102, nombre: testapp gt;. /testapp lt;lt;lt;
Desde esta línea podemos conocer el pid y el tid del proceso bloqueado. Ya hemos mencionado que Android llama a la función gettid para obtener el número de ID del proceso real, por lo que. pid aquí es lo mismo que tid. Ahora que sabemos el número de proceso, podemos regresar y revisar los registros para ver cuál fue el último registro impreso por ese proceso, para poder limitarlo.
La siguiente línea es el nombre del proceso y los parámetros de inicio. La siguiente línea es más importante porque nos dice qué salió mal desde la perspectiva del sistema:
Señal 11 (SIGSEGV), código 1 (SEGV_MAPERR), dirección de falla 00000000
La señal 11 es Una de las señales definidas por Linux se llama referencia de memoria no válida. Combinado con "faultaddr 00000000", básicamente podemos determinar que se trata de un bloqueo causado por un puntero nulo. Por supuesto, este es un ejemplo de accidente creado especialmente por el autor para su explicación. Es más fácil de juzgar. La mayoría de los ejemplos reales pueden no ser tan fáciles.
El siguiente registro imprimirá todos los registros y la información de la pila de la CPU. Lo más importante aquí es la información de seguimiento de la pila:
I/DEBUG (127): seguimiento de la pila:<. /p>
p>
I/DEBUG (127): #00 pc0000045e / / system/bin/testapp
I/DEBUG (127): #01 pc0000046b /system/bin/ testapp
I/DEBUG (127): #02 pc0001271f /system/lib/libc.so (__libc_ init 38)
I/DEBUG (127): #03 pc00000400 /system /bin/testapp
Dado que no hay información de símbolos en el sistema en ejecución real, el nombre del archivo y el número de línea no se pueden ver en el registro impreso. Android proporciona una herramienta: arm-eabi-addr2line, ubicada en el directorio prebuilts/gcc/linux-x86/arm/arm-eabi-4.6/bin. El uso es muy sencillo:
#./arm-eabi-addr2line -f -eout/target/product/hammerhead/symbols/system/bin/testapp0x0000045e
El parámetro -f indica que El nombre de la función impresa; el parámetro -e representa la ruta del módulo con la tabla de símbolos y finalmente la dirección del módulo a convertir. En el entorno de compilación del autor, el resultado de este comando es:
memcpy /home/rd/compile/android-4.4_r1.2/bionic/libc/include/string.h: 108
La conversión de las tres direcciones restantes es la siguiente:
main /home/rd/compile/android-4.4_r1.2/pack/include/string.h: 108
memcpy /home/rd/compile/android-4.4_r1.2/bionic/libc/include/string.h：1084_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
_start libgcc2.c: 0
Usando esta información, Puede encontrar rápidamente el problema. Sin embargo, traducir manualmente línea por línea es engorroso. Utilicé un script que encontré en Internet que traduce todas las líneas de una sola vez.
Reimprimir