Logcat hat Logs mit Zeitstempeln außerhalb der Reihenfolge

Question

Ich bin Debugging einer Datenverbindung und die Reihenfolge, in der Dinge passieren, ist wichtig. Ich verwende Logcat mit Zeitstempel mit ADB in einem Terminal und sammle Stunden von Logs, die ich später analysiere. Das Problem, das ich habe, ist manchmal, dass die Zeitstempel nicht sequentiell sind. Da Logcat ein Ringpuffer ist, kann ich nicht sehen, warum es so wäre. So, ich bin herumwandern, wenn es einen Fehler im Zeitstempel gibt oder wenn das Ereignis wirklich nicht sequenziell protokolliert wird und ich auf die Folge von Protokollen anstelle des Zeitstempels verweisen sollte (sehen Sie sich den Übergang von Zeile 8 und 9 an). Weiß das irgendjemand? der Befehl, die Protokolle zu erhalten ist:

adb logcat -b Radio -v Zeit

und das Protokoll:

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

Zeitstempel sind nicht sequentiell, da der Log.i Betrieb nicht atomar ist innerhalb System. Lassen Sie uns einen Blick darauf werfen, wie das Log.i in mehreren grundlegenden Schritten funktioniert: 1. Zuerst erhält es die Systemzeit 2. Dann formatiert es die Zeichenfolge mit der erhaltenen Systemzeit 3. Anwendung stellt die Nachricht auf den ausgehenden Puffer 4. Schließlich , Hintergrund Thread Zeit-zu-Zeit löscht Protokolldaten aus dem Anwendungskontext (zum zentralen Protokollierungssystem)

Stellen Sie sich vor, dass zwei Prozesse parallel ausgeführt werden. Im Pech pausiert der Scheduler Ihren Prozess in dem Moment, in dem er Schritt 1 beendet. Dann gibt der Scheduler CPU-Zeit für den nächsten Prozess, der Log.i aber mit genug Zeit macht, um seinen Log.i-Job zu beenden. Schließlich gibt der Scheduler unserem Prozess CPU-Zeit, um die Protokollierung zu beenden.

In diesem Beispiel sehen Sie, dass das Mischen von Zeitstempeln durch nicht-atomare Log.i-Operation und Pufferung ausgehender Protokolleinträge verursacht wird. Die Anwendung kann Protokolleinträge nach jedem Protokolleintrag nicht löschen, da der Kontextwechsel zwischen Anwendung und Protokollierungssystem sehr, sehr CPU-teuer ist. Stattdessen puffert es Protokolleinträge und wenn der Puffer voll ist oder einige Zeit verstreicht, führt es eine Protokollspülung durch. Dieser Ansatz verbessert die Leistung dramatisch.

Wenn Sie Einträge für die Auftragseinträge benötigen, können Sie diese vor der weiteren Verarbeitung bestellen.

Answer 2

Beachten Sie die Zeile unmittelbar vor der logcat Zeit außer Betrieb gesetzt wird:

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 

Insbesondere, Blick auf den Teil der Linie, wo es gained(ms): -423 sagt. Die folgende Zeile tritt dann bei 18:32:29.017 auf, was vollkommen konsistent mit einem Protokollereignis ist, das 16 ms nach dem Zurücksetzen der Systemuhr auf 423 ms auftritt.

Die Antwort von vit ist korrekt, da Log-Einträge durch andere Threads unterbrochen werden können, was auch zu Logging führen kann, was zu einer verwirrenden Ausgabe führt. Aber das ist in diesem Fall nicht der Fall.