Logcat tiene registros con marcas de tiempo fuera de secuencia

Estoy depurando una conexión de datos y la secuencia en la que suceden las cosas es importante. Utilizo logcat con sello de tiempo con ADB en una terminal y recojo horas de registros que analizaré más adelante. El problema que tengo es, a veces, las marcas de tiempo no son secuenciales. Dado que Logcat es un buffer circular, no puedo ver por qué sería así. Por lo tanto, estoy deambulando si hay un error en la marca de tiempo o si el evento realmente no se registran secuencialmente y debo referirme a la secuencia de registros en lugar de la marca de tiempo (mire la línea 8 y 9 de transición). ¿Alguien sabe sobre eso? El comando utilizado para obtener los registros es:

Adb logcat -b radio -v tiempo

Y el registro:

... 09-06 18:32:29.426 D/GSM ( 200): getNitzTimeZone returning America/Detroit 09-06 18:32:29.434 I/AT ( 65): AT(14)< +CGDCONT: 1,"IP","pda.bell.ca","",0,0 09-06 18:32:29.434 I/AT ( 65): AT(14)< OK 09-06 18:32:29.434 E/RIL ( 65): processRequest: OPERATOR 09-06 18:32:29.434 E/AT ( 65): ---AT+COPS=3,0;+COPS?;+COPS=3,1;+COPS?;+COPS=3,2;+COPS? 09-06 18:32:29.434 I/AT ( 65): AT(14)> AT+COPS=3,0;+COPS?;+COPS=3,1;+COPS?;+COPS=3,2;+COPS? 09-06 18:32:29.434 D/RILJ ( 200): [UNSL]< UNSOL_DATA_CALL_LIST_CHANGED [DataCallState: { cid: 1, active: 0, type: IP, apn: pda.bell.ca, address: }] 09-06 18:32:29.434 I/GSM ( 200): NITZ: Setting time of day to Thu Sep 06 18:32:29 EDT 2012 NITZ receive delay(ms): 14 gained(ms): -423 from 12/09/06,22:32:29-16,1 09-06 18:32:29.017 I/AT ( 65): AT(14)< +COPS: 0,0,"Bell",2 09-06 18:32:29.017 I/AT ( 65): AT(14)< +COPS: 0,1,"Bell",2 09-06 18:32:29.017 I/AT ( 65): AT(14)< +COPS: 0,2,"302610",2 09-06 18:32:29.017 I/AT ( 65): AT(14)< OK 09-06 18:32:29.017 I/RIL ( 65): swiril_cache_set: updating cache for OPERATOR 09-06 18:32:29.017 E/RIL ( 65): processRequest: GPRS_REGISTRATION_STATE 09-06 18:32:29.017 E/AT ( 65): --- AT+CGREG? 09-06 18:32:29.017 I/AT ( 65): AT(14)> AT+CGREG? 09-06 18:32:29.017 D/RILJ ( 200): [0612]< OPERATOR {Bell, Bell, 302610} 09-06 18:32:29.025 I/AT ( 65): AT(14)< +CGREG: 2,1,"2D8C","067C358F",2 09-06 18:32:29.025 I/AT ( 65): AT(14)< OK 09-06 18:32:29.025 I/RIL ( 65): swiril_cache_set: updating cache for GPRS_REGISTRATION_STATE 09-06 18:32:29.025 E/RIL ( 65): processRequest: REGISTRATION_STATE 09-06 18:32:29.025 E/AT ( 65): --- AT*CNTI=0 09-06 18:32:29.025 I/AT ( 65): AT(14)> AT*CNTI=0 09-06 18:32:29.025 D/RILJ ( 200): [0613]< GPRS_REGISTRATION_STATE {1, 2d8c, 067c358f, 3} 09-06 18:32:29.029 I/AT ( 65): AT(14)< *CNTI: 0,UMTS ... 

2 Solutions collect form web for “Logcat tiene registros con marcas de tiempo fuera de secuencia”

Las marcas de tiempo no son secuenciales porque la operación Log.i no es atómica dentro del sistema. Vamos a echar un vistazo a cómo funciona Log.i en varios pasos básicos: 1. En primer lugar, se obtiene el tiempo del sistema 2. A continuación, se formatea cadena utilizando el tiempo del sistema obtenido 3. La aplicación pone el mensaje de búfer saliente 4. Por último, Al tiempo descarga los datos de registro fuera del contexto de la aplicación (al sistema de registro central)

Imagine que hay dos procesos en ejecución en paralelo. En situación de mala suerte el programador hace una pausa en su proceso en el momento en que termina el paso 1. Entonces el programador pierde tiempo CPU al próximo proceso que también hace Log.i pero con tiempo suficiente para terminar su trabajo Log.i. Por último, el programador da tiempo de CPU a nuestro proceso para finalizar la operación de registro.

En este ejemplo se puede ver que la mezcla de sellos de tiempo es causada por la operación no atómica Log.i y el almacenamiento en búfer de entradas de registro salientes. La aplicación no puede enjuagar las entradas de registro después de cada entrada de registro, porque el cambio de contexto entre la aplicación y el sistema de registro es muy, operación muy costosa CPU. En su lugar, almacena las entradas de registro y cuando el búfer está lleno o transcurre algún tiempo, entonces realiza el rastreo de registro. Este enfoque mejora drásticamente el rendimiento.

Si necesita entradas de registro ordenadas, puede ordenarlas antes de procesarlas.

Anote la línea inmediatamente antes de que el tiempo de logcat se descomponga:

 09-06 18:32:29.434 I/GSM ( 200): NITZ: Setting time of day to Thu Sep 06 18:32:29 EDT 2012 NITZ receive delay(ms): 14 gained(ms): -423 from 12/09/06,22:32:29-16,1 

Específicamente, mira la parte de la línea donde dice gained(ms): -423 . La línea siguiente entonces ocurre en 18:32:29.017 , que es perfectamente coherente con un acontecimiento de registro que sucede 16ms después de que el reloj del sistema fuera ajustado detrás 423ms.

Vit es correcta en que las entradas de registro pueden ser interrumpidas por otros subprocesos, lo que también puede hacer el registro, dando lugar a una salida confusa: pero esto no es lo que está sucediendo en este caso.

  • Android studio logcat no funciona
  • ¿Cómo selecciono el dispositivo que está mostrando LogCat en eclipse?
  • Navegación InteLiJ IDEA logcat
  • Señal fatal 11 (SIGSEGV) en 0x00000000 (código = 1), subproceso 32140
  • Manejo de espacios en logcat
  • Deshabilitar salidas nativas de logcat en Android
  • ¿Cómo deshabilitar D / libc de registrar la información de red en logcat?
  • No se puede ejecutar el código fuente Linphone-android en el dispositivo real
  • FlipAndroid es un fan de Google para Android, Todo sobre Android Phones, Android Wear, Android Dev y Aplicaciones para Android Aplicaciones.