android - 使用耗时类型设置警报会在内核中打印来自 dmesg 的不准确延迟

Question

谁能解释一下内核日志中的时间戳差异？

我们编写了一个在指定时间唤醒 Android 的应用程序，该应用程序利用 AlarmManager API 并设置:

AlarmManager.ELAPSED_REALTIME_WAKEUP

该应用程序按预期运行，并在用户指定的时间正确唤醒。但是内核时间戳存在差异。我跟踪源代码从 AlarmManagerService.java 到 alarm-dev.c 并确认 Android 正确设置了闹钟唤醒时间并将其发送到内核(例如从Java层Android使用SystemClock.elapsedRealtime()获取运行时间，加上100秒，转换成秒和纳秒的值，最后通过JNI发送给内核层。

但是，在读取 dmesg 日志时，内核时间戳似乎存在差异。当调用状态为 ANDROID_ALARM_SET(0): 的 alarm_ioctl 函数时，dmesg 打印了以下消息:

[20450.036529] alarm 2 set 20544.720000000

这意味着 [20450.036529] 是当前时间，20544.720000000 是 AlarmManager 唤醒 Android 的时间。值 20544.720000000 是从 Android 层和 logcat 的时间戳(例如 logcat -v time)设置的，这个值是 Android 应该唤醒的时间。

从 Android 层到内核层用时不到十分之一秒，但为什么增量为 94.683471，比应有的 5.316529 少？或者耗时是否与 dmesg 打印的内核时间不同？

另一个有趣的观察结果是，如上所述，应用确实会在用户指定的时间唤醒。所以在这种情况下，在用户调用应用 AlarmManager 后，平板电脑会在 100 秒内唤醒。

谢谢，

引用资料:

• AlarmManagerService.java
• alarm-dev.c

Answer 1

选项 1

您可能希望在消息中嵌入时间戳，而不是依赖 printk() 生成的时间戳。这种方法至少应该给你一个真实的时间测量。

选项 2

您可以研究 kernel/printk.c 使用的 API 来获取时间戳。

如果 printk 正在使用 cpu_clock() 您可能需要考虑以下几点:

CPU Clock

 14  * What:
 15  *
 16  * cpu_clock(i) provides a fast (execution time) high resolution
 17  * clock with bounded drift between CPUs. The value of cpu_clock(i)
 18  * is monotonic for constant i. The timestamp returned is in nanoseconds