title: Logcat has logs with timestamps out of sequence
body: <p>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:</p>
  
  <p>adb logcat -b radio -v time</p>
  
  <p>and the log:</p>
  
  <pre><code>...
  09-06 18:32:29.426 D/GSM     (  200): getNitzTimeZone returning America/Detroit
  09-06 18:32:29.434 I/AT      (   65): AT(14)&lt; +CGDCONT: 1,"IP","pda.bell.ca","",0,0
  09-06 18:32:29.434 I/AT      (   65): AT(14)&lt; 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)&gt; AT+COPS=3,0;+COPS?;+COPS=3,1;+COPS?;+COPS=3,2;+COPS?
  09-06 18:32:29.434 D/RILJ    (  200): [UNSL]&lt; 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)&lt; +COPS: 0,0,"Bell",2
  09-06 18:32:29.017 I/AT      (   65): AT(14)&lt; +COPS: 0,1,"Bell",2
  09-06 18:32:29.017 I/AT      (   65): AT(14)&lt; +COPS: 0,2,"302610",2
  09-06 18:32:29.017 I/AT      (   65): AT(14)&lt; 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)&gt; AT+CGREG?
  09-06 18:32:29.017 D/RILJ    (  200): [0612]&lt; OPERATOR {Bell, Bell, 302610}
  09-06 18:32:29.025 I/AT      (   65): AT(14)&lt; +CGREG: 2,1,"2D8C","067C358F",2
  09-06 18:32:29.025 I/AT      (   65): AT(14)&lt; 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)&gt; AT*CNTI=0
  09-06 18:32:29.025 D/RILJ    (  200): [0613]&lt; GPRS_REGISTRATION_STATE {1, 2d8c, 067c358f, 3}
  09-06 18:32:29.029 I/AT      (   65): AT(14)&lt; *CNTI: 0,UMTS
  ...
  </code></pre>