android - Logcat 具有时间戳乱序的日志

Question

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

adb logcat -b radio -v 时间

和日志:

...
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 资源的操作。相反，它会缓冲日志条目，当缓冲区已满或经过一段时间后，它会执行日志刷新。这种方法显着提高了性能。

如果您需要有序的日志条目，您可以在进一步处理之前对其进行排序。