Logcat ma logi z sygnaturami czasowymi poza kolejnością

Question

Debuguję połączenie danych i kolejność, w której coś się dzieje jest ważna. Używam logcat z datownikiem z ADB w terminalu i zbieram godziny logów, które analizuję później. Problemem, który mam, jest czasami, że znaczniki czasu nie są sekwencyjne. Ponieważ Logcat to bufor cykliczny, nie rozumiem, dlaczego tak się stało. Więc wędruję, jeśli jest błąd w sygnaturze czasowej lub jeśli zdarzenie naprawdę nie jest rejestrowane sekwencyjnie i powinienem odnieść się do sekwencji dzienników zamiast znacznika czasu (spójrz na przejście linii 8 i 9). Ktoś wie o tym? komenda używana do pobierania dzienników jest:

czas ADB logcat -b radia -v

i dziennik:

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

Sygnatury nie są sekwencyjne, ponieważ operacja Log.i nie jest atomowy w ciągu system. Zobaczmy jak działa Log.i w kilku podstawowych krokach: 1. Po pierwsze, otrzymuje on czas systemowy 2. Następnie formatuje ciąg znaków przy użyciu uzyskanego czasu systemowego 3. Aplikacja przesyła komunikat do bufora wychodzącego 4. Wreszcie , wątek tła od czasu do czasu wypróżnia dane logu poza kontekst aplikacji (do centralnego systemu rejestrowania)

Wyobraź sobie, że równolegle działają dwa procesy. W przypadku wystąpienia pecha program planujący wstrzymuje proces w momencie, gdy kończy etap 1. Następnie program planujący podaje czas procesora do następnego procesu, który również powoduje Log.i, ale z wystarczającą ilością czasu, aby zakończyć pracę Log.i. Wreszcie program planujący podaje czas procesora do naszego procesu, aby zakończyć operację rejestrowania.

W tym przykładzie można zobaczyć, że mieszanie znaczników czasu jest spowodowane nieatomową operacją Log.i i buforowaniem wychodzących wpisów dziennika. Aplikacja nie może opróżniać pozycji dziennika po każdym wpisie dziennika, ponieważ kontekst przełączania między aplikacją a systemem rejestrowania jest bardzo, bardzo kosztowną operacją. Zamiast tego buforuje wpisy w dzienniku, a gdy bufor się zapełni lub upłynie pewien czas, to zostanie on spłukany. Takie podejście radykalnie poprawia wydajność.

Jeśli potrzebujesz uporządkowanych wpisów w dzienniku, możesz zamówić je przed dalszym przetwarzaniem.

Answer 2

Uwaga linia natychmiast przed czasem logcat wysiada kolejności:

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 

szczególności spojrzeć na części linii, gdzie mówi gained(ms): -423. Następująca linia występuje wtedy pod numerem 18:32:29.017, co jest całkowicie zgodne z zdarzeniem z dziennika, które ma miejsce po 16 ms po przywróceniu zegara systemowego 423 ms.

Odpowiedź vit jest poprawna, ponieważ wpisy w dzienniku mogą być przerywane przez inne wątki, co może również prowadzić do logowania, co prowadzi do pewnych mylących wyników: ale nie dzieje się tak w tym przypadku.