6

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

adb logcat -b 收音机 -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
...
4

2 回答 2

12

时间戳不是连续的，因为 Log.i 操作在系统内不是原子的。让我们看一下 Log.i 是如何在基本的几个步骤中工作的： 1. 首先，它获取系统时间 2. 然后使用获取的系统时间格式化字符串 3. 应用程序将消息发送到传出缓冲区 4. 最后，后台线程时间- to time 将日志数据从应用程序上下文中刷新（到中央日志系统）

想象一下，有两个进程并行运行。在运气不好的情况下，调度程序会在它完成第 1 步的那一刻暂停您的进程。然后调度程序将 CPU 时间分配给下一个进程，这也产生 Log.i，但有足够的时间来完成它的 Log.i 工作。最后，调度程序为我们的进程提供 CPU 时间来完成日志记录操作。

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

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

于 2012-11-02T11:51:02.470 回答
2

请注意在 logcat 时间出现故障之前的行：

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

具体来说，看看它说的那一行的部分gained(ms): -423。下一行然后出现在18:32:29.017，这与系统时钟设置回 423 毫秒后 16 毫秒发生的日志事件完全一致。

vit 的回答是正确的，因为日志条目可能会被其他线程中断，这些线程也可能进行日志记录，从而导致一些令人困惑的输出：但这不是在这种情况下发生的情况。

于 2013-08-23T04:08:56.033 回答