CODEWITHSUNDEEP
linuxtimerlinux-kernelembedded-linuxkernel-module
BillE
BillE

Reputation: 13

Why am I getting time drift when using linux hrtimer for one second callbacks?

Within an embedded linux kernel module I am trying to implement a measurement action that occurs every second and I am using hrtimer to provide the timing. The function below is the callback that is registered when the timer is set up. Of concern is the proper method to add time to the hrtimer for its next callback trigger. I am using 'hrtimer_add_expires_ns' with the understanding that this will add xx ns to the time that was last set for the timer to "expire".

static enum hrtimer_restart delay_callback (struct hrtimer* MeasDelay)
{
    hrtimer_add_expires_ns (MeasDelay, MS2NS(1000));

    printk (KERN_ALERT "Delay Callback (%d).\n", DelayCount);

    if (0 == DelayCount)
    {
        /* Reset delay counter */
        DelayCount = MEASDELAYSECS;

        /* Setup stuff to do when counter reaches zero */

    }
    else
    { 
        /* Drop the counter */
        DelayCount--;
    }

    return HRTIMER_RESTART;
}

When running this code and looking at /var/log/syslog I am seeing an ever increasing "drift" time on the messages stored in the log:

Feb 15 13:48:15 blah: [ 4731.033628] Delay Callback (5).  
Feb 15 13:48:16 blah: [ 4732.034576] Delay Callback (4).  
Feb 15 13:48:17 blah: [ 4733.035861] Delay Callback (3).  
Feb 15 13:48:18 blah: [ 4734.036855] Delay Callback (2).  
Feb 15 13:48:19 blah: [ 4735.038025] Delay Callback (1).  
Feb 15 13:48:20 blah: [ 4736.039170] Delay Callback (0).  
Feb 15 13:48:21 blah: [ 4737.040332] Delay Callback (5).  
Feb 15 13:48:22 blah: [ 4738.041493] Delay Callback (4).  
Feb 15 13:48:23 blah: [ 4739.042621] Delay Callback (3).  
Feb 15 13:48:24 blah: [ 4740.043792] Delay Callback (2).  
Feb 15 13:48:25 blah: [ 4741.044949] Delay Callback (1).  
Feb 15 13:48:26 blah: [ 4742.046109] Delay Callback (0).  
Feb 15 13:48:27 blah: [ 4743.047264] Delay Callback (5).  
Feb 15 13:48:28 blah: [ 4744.048436] Delay Callback (4).  
Feb 15 13:48:29 blah: [ 4745.049567] Delay Callback (3).  
Feb 15 13:48:30 blah: [ 4746.050725] Delay Callback (2).  
Feb 15 13:48:31 blah: [ 4747.051852] Delay Callback (1).  
Feb 15 13:48:32 blah: [ 4748.054040] Delay Callback (0).

Each callback execution time-stamp is slightly more than the 1 second expected. I do understand that the time-stamp is when the message is stored but I would expect that the times would "dither" rather than continually advance...if the timer was doing what I am expecting which is add one second to the last expire time (not "now").

In other words I would expect the logged time-stamps to always be trying to be in multiples of one second from the initial timer start time (Time-stamps edited to show what I expected if timer was started at xxxx.040000):

Feb 15 13:48:21 blah: [ 4737.040073] Delay Callback (5).  
Feb 15 13:48:22 blah: [ 4738.040100] Delay Callback (4).  
Feb 15 13:48:23 blah: [ 4739.040098] Delay Callback (3).  
Feb 15 13:48:24 blah: [ 4740.040050] Delay Callback (2).  
Feb 15 13:48:25 blah: [ 4741.040110] Delay Callback (1).  
Feb 15 13:48:26 blah: [ 4742.040101] Delay Callback (0).  
Feb 15 13:48:27 blah: [ 4743.041234] Delay Callback (5).  
Feb 15 13:48:28 blah: [ 4744.040030] Delay Callback (4).  
Feb 15 13:48:29 blah: [ 4745.040075] Delay Callback (3).  
Feb 15 13:48:30 blah: [ 4746.040099] Delay Callback (2).  
Feb 15 13:48:31 blah: [ 4747.040057] Delay Callback (1).  
Feb 15 13:48:32 blah: [ 4748.040040] Delay Callback (0).

Thanks for any help providing a better understanding of the use of the linux hrtimers.

Upvotes: 1

Views: 486

Answers (1)

Tsyvarev
Tsyvarev

Reputation: 66153

HR timer and printk use different time sources, so intervals, measured by them doesn't need to be equal.

printk uses low resolution (but fast) time source, based on jiffies. HR timer, as you can guess by the name, uses time source with higher resolution (if available).

You can check that timer's fields ._softexpires and .node.expires are incremented with fixed step. Exactly these fields are responsible for firing the timer.

Upvotes: 1

Related Questions