Logcat ha log con data e ora fuori sequenza

Question

Sto eseguendo il debug di una connessione dati e la sequenza in cui le cose accadono è importante. Uso logcat con time stamp con ADB in un terminale e raccolgo ore di log che analizzo in seguito. Il problema che ho è, a volte, i timestamp non sono sequenziali. Dal momento che Logcat è un buffer circolare, non riesco a capire perché sarebbe così. Quindi, sto vagando se c'è un bug nel timestamp o se l'evento non è registrato in modo sequenziale e dovrei fare riferimento alla sequenza di log al posto del timestamp (guarda la transizione riga 8 e 9). Qualcuno lo sa? il comando utilizzato per ottenere i registri è:

tempo adb Radio logcat -b -v

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

Answer 1

timestamp non sono sequenziali perché l'operazione non è Log.i atomica entro sistema. Diamo un'occhiata a come il Log.i funziona in diversi passaggi di base: 1. Prima ottiene l'ora di sistema 2. Quindi formatta la stringa utilizzando l'ora di sistema ottenuta 3. L'applicazione mette il messaggio al buffer in uscita 4. Infine , thread in background time-to time scarica i dati del log dal contesto dell'applicazione (al sistema di registrazione centrale)

Immaginate che siano in esecuzione due processi in parallelo. In caso di sfortuna, lo scheduler sospende il processo nel momento in cui termina il passaggio 1. Quindi lo schedulatore dà tempo CPU al processo successivo che rende anche Log.i ma con tempo sufficiente per terminare il lavoro di Log.i. Infine, lo scheduler fornisce al tempo della CPU il nostro processo per completare l'operazione di registrazione.

In questo esempio è possibile vedere che i timestamp di missaggio sono causati dall'operazione non logica Log.i e dal buffering delle voci di registro in uscita. L'applicazione non è in grado di svuotare le voci di registro dopo ogni voce di registro, perché il contesto di commutazione tra l'applicazione e il sistema di registrazione è un'operazione molto costosa, molto costosa. Al contrario, memorizza le voci del registro e quando il buffer è pieno o trascorre qualche tempo, esegue lo scarico del registro. Questo approccio migliora notevolmente le prestazioni.

Se sono necessarie voci di registro ordinate, è possibile ordinarle prima di ulteriori elaborazioni.

Answer 2

Nota la riga immediatamente prima del tempo logcat esce di ordine:

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 

In particolare, guarda la parte della linea in cui si dice gained(ms): -423. La seguente riga si verifica a 18:32:29.017, che è perfettamente coerente con un evento di registro che si verifica 16 ms dopo che l'orologio di sistema è stato disattivato di 423 ms.

La risposta di vit è corretta in quanto le voci del registro possono essere interrotte da altri thread, che possono anche fare il log, causando un output confuso: ma questo non è ciò che sta accadendo in questo caso.