Android kernel printk() and clock_gettime(CLOCK_BOOTTIME) time reversal of 60ms

Question

I need to measure Android kernel and framework processing time for mouse HID event.

• USB mouse device side, I use Arduino Micro with HID mouse sample. It send HID event every 10ms.
• Linux Kernel, I put printk() on hid_irq_in(), hid_input_report() in hid-core.c
• Android framework, I add logcat with clock_gettime(CLOCK_BOOTTIME) on InputReader::process.
• Android sample App, I put Log.d() elapsedRealtimeNanos() on View.OnTouchListener

Problem: App side onTouchListner time is 60ms earlier than kernel hid_irq_in(). kernel IRQ should be 1-2ms before onTouchListener.

I am not sure why time is reverted. If I use not accurate way to get time, let me know.

Answer 1

"dmesg" add timestamp of printk() message. But that time is not synced with clock_gettime(CLOCK_BOOTTIME) in userland.

I need to call ktime_get_boottime() then printk() in kernel code. That time is synced with clock_gettime(CLOCK_BOOTTIME) in userland.

With this measurement, I found handling mouse left click event takes 3ms in kernel and framework.