Logcat has logs with timestamps out of sequence

Question

I'm debugging a data connection and the sequence in which things happen is important. I use logcat with time stamp with ADB in a terminal and collect hours of logs that I analyze later. The problem I have is, sometimes, the timestamps are not sequential. Since Logcat is a circular buffer, I can't see why it would be that way. So, I'm wandering if there is a bug in the timestamp or if the event are really not logged sequentially and I should refer to the sequence of logs instead of the timestamp (look at the line 8 and 9 transition) . Anybody knows about that? the command used to get the logs is:

adb logcat -b radio -v time

and the log:

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

Timestamps are not sequential because the Log.i operation is not atomic within system. Let's have a look how the Log.i works in basic several steps: 1. First, it gets the system time 2. Then it formats string using obtained system time 3. Application puts message to outgoing buffer 4. Finally, background thread time-to time flushes log data out of the application context (to central logging system)

Imagine that there are running two processes in parallel. In bad luck situation the scheduler pauses your process in moment it finishes step 1. Then the scheduler givess CPU time to next process which also makes Log.i but with enough time to finish it's Log.i job. Finally, the scheduler gives CPU time to our process to finish logging operation.

On this example you can see that mixing time stamps is caused by non-atomic Log.i operation and buffering of outgoing log entries. Application can not flush log entries after each log entry, because switching context between application and logging system is very, very CPU expensive operation. Instead, it buffers log entries and when buffer is full or some time elapses, then it performs log flush. This approach dramatically improves performance.

If you need orderred log entries, you can order them before further processing.

Answer 2

Note the line immediately before the logcat time gets out of order:

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

Specifically, look at the part of the line where it says gained(ms): -423. The following line then occurs at 18:32:29.017, which is perfectly consistent with a log event happening 16ms after the system clock was set back 423ms.

vit's answer is correct in that log entries can be interrupted by other threads, which may also do logging, leading to some confusing output: but this is not what is happening in this case.