2012-09-10 35 views
6

Estoy depurando una conexión de datos y la secuencia en la que suceden las cosas es importante. Uso logcat con sello de tiempo con ADB en un terminal y recopilo horas de registros que analizo más adelante. El problema que tengo es que, a veces, las marcas de tiempo no son secuenciales. Como Logcat es un buffer circular, no veo por qué sería así. Entonces, estoy deambulando si hay un error en la marca de tiempo o si el evento realmente no se registra secuencialmente y debería consultar la secuencia de registros en lugar de la marca de tiempo (mire la transición de las líneas 8 y 9). ¿Alguien sabe sobre eso? el comando utilizado para obtener los registros es:Logcat tiene registros con marcas de tiempo fuera de secuencia

tiempo adb de radio Logcat -b -v

y el registro de:

... 
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 
... 

Respuesta

11

marcas de tiempo no son secuenciales porque la operación no es Log.i atómica dentro de sistema. Echemos un vistazo cómo el Log.i funciona en varios pasos básicos: 1. Primero, obtiene la hora del sistema 2. A continuación, formatea cadena utilizando la hora del sistema obtenida 3. La aplicación coloca el mensaje en el búfer de salida 4. Finalmente , el tiempo del subproceso en segundo plano lava los datos de registro fuera del contexto de la aplicación (al sistema de registro central)

Imagine que se están ejecutando dos procesos en paralelo. En una situación de mala suerte, el planificador pausa su proceso en el momento en que finaliza el paso 1. Luego, el programador le da tiempo de CPU al siguiente proceso que también hace Log.i pero con tiempo suficiente para finalizar su trabajo Log.i. Finalmente, el programador da tiempo de CPU a nuestro proceso para finalizar la operación de registro.

En este ejemplo, puede ver que las marcas de tiempo de mezcla son causadas por la operación Log.i no atómica y el almacenamiento en búfer de las entradas de registro salientes. La aplicación no puede vaciar 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, muy costoso para la operación de la CPU. En su lugar, almacena en el buzón las entradas de registro y cuando el búfer está lleno o transcurre algún tiempo, realiza el enjuague del registro. Este enfoque mejora drásticamente el rendimiento.

Si necesita entradas de registro ordenadas, puede solicitarlas antes de continuar el proceso.

+0

Esta es una explicación muy completa y clara. Muchas gracias. Realmente lo aprecio. –

2

Nota la línea inmediatamente antes de la hora Logcat sale de orden:

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, un vistazo a la parte de la línea donde dice gained(ms): -423. A continuación, aparece la siguiente línea en 18:32:29.017, que es perfectamente coherente con un evento de registro que ocurre 16 ms después de que el reloj del sistema retrocedió 423 ms.

La respuesta de vit es correcta en cuanto a que las entradas de registro pueden ser interrumpidas por otros hilos, que también pueden registrar, dando lugar a una salida confusa: pero esto no es lo que está sucediendo en este caso.

Cuestiones relacionadas