Logcat的日志时间戳不按顺序排列

Question

我正在调试数据连接,事情发生的顺序很重要.我在终端中使用带有ADB时间戳的logcat,并收集我稍后分析的小时日志.我遇到的问题是,时间戳有时不是顺序的.由于Logcat是一个循环缓冲区,我不明白为什么会这样.所以,如果时间戳中存在错误或者事件实际上没有按顺序记录,我就会徘徊,我应该参考日志序列而不是时间戳(请参阅第8和第9行转换).有人知道吗？用于获取日志的命令是:

adb logcat -b radio -v time

和日志:

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

时间戳不是顺序的,因为Log.i操作在系统内不是原子的.让我们看看Log.i如何在基本的几个步骤中工作:1.首先,它获取系统时间2.然后使用获得的系统时间格式化字符串3.应用程序将消息放入传出缓冲区4.最后,后台线程时间 - 时间将日志数据从应用程序上下文中刷新(到中央日志记录系统)

想象一下,并行运行两个进程.在运气不好的情况下,调度程序会在完成步骤1的过程中暂停您的进程.然后调度程序将CPU时间给予下一个进程,这也使Log.i有足够的时间来完成它的Log.i作业.最后,调度程序为我们的进程提供CPU时间来完成日志记录操作.

在此示例中,您可以看到混合时间戳是由非原子Log.i操作和传出日志条目的缓冲引起的.应用程序无法在每个日志条目之后刷新日志条目,因为在应用程序和日志记录系统之间切换上下文非常非常昂贵的CPU操作.相反,它缓冲日志条目,当缓冲区已满或经过一段时间后,它会执行日志刷新.这种方法大大提高了性能.

如果您需要订购日志条目,可以在进一步处理之前订购它们.