Why does my hrtimer callback return too early after forwarding it?

Question

I want to use a hrtimer to control two hardware gpio pins to do some bus signalling. I set up a hrtimer in a kernel module like this

#include <linux/slab.h>
#include <linux/delay.h>
#include <linux/ktime.h>
#include <linux/hrtimer.h>

#define PIN_A_HIGH_TO_A_LOW_US  48  /* microseconds */
#define PIN_A_LOW_TO_B_LOW_US   24  /* microseconds */

static struct kt_data {
    struct hrtimer timer;
    ktime_t period;
} *data;

typedef enum {
    eIdle = 0,
    eSetPinALow,
    eSetPinBLow,
} teControlState;

static enum hrtimer_restart TimerCallback(struct hrtimer *var);
static void StopTimer(void);

static teControlState cycle_state = eIdle;

static enum hrtimer_restart TimerCallback(struct hrtimer *var)
{
    local_irq_disable();

    switch (cycle_state) {
    case eSetPinALow:
        SetPinA_Low();
        data->period = ktime_set(0, PIN_A_LOW_TO_B_LOW_US * 1000);
        cycle_state = eSetPinBLow;
        break;
    case eSetPinBLow:
        SetPinB_Low();
        /* Do Stuff */
        /* no break */
    default:
        cycle_state = eIdle;
        break;
    }

    if (cycle_state != eIdle) {
        hrtimer_forward_now(var, data->period);
        local_irq_enable();
        return HRTIMER_RESTART;
    }

    local_irq_enable();
    return HRTIMER_NORESTART;
}

void StartBusCycleControl(void)
{
    SetPinA_High();
    SetPinB_High();

    data->period = ktime_set(0, PIN_A_HIGH_TO_A_LOW_US * 1000);
    cycle_state = eSetPinALow;
    hrtimer_start(&data->timer, data->period, HRTIMER_MODE_REL);
}

int InitTimer(void)
{
    data = kmalloc(sizeof(*data), GFP_KERNEL);

    if (data) {
        hrtimer_init(&data->timer, CLOCK_MONOTONIC, HRTIMER_MODE_REL);
        data->timer.function = TimerCallback;
        printk(KERN_INFO DRV_NAME
               ": %s hr timer successfully initialized\n", __func__);
        return 0;
    } else {
        printk(KERN_CRIT DRV_NAME
               ": %s failed to initialize the hr timer\n", __func__);
        return -ENOMEM;
    }
}

So the idea is that

• both pins are high at the start
• hrtimer is set to expire after 48 microseconds
• in the callback function, pin A is pulled to low
• the timer is pushed forward 24 microseconds
• the second time the callback is triggered, pin B is pulled to low

I use a BeagleBoneBlack with Kernel 4.1.2 with the rt-preempt patches.

What I see at the scope is that the first timer works like a charm with about 65-67 microseconds (I can live with that). but the forwarding seems to malfunction because the times I measure between pin A going low and pin B going low are between 2 and 50 microseconds. So in essence, the second time the callback is triggered sometimes happens before the 24 microseconds I defined. And that timing doesn't work for my use case.

Any pointers to what I am doing wrong?

Answer 1

So to answer this myself: This is a problem of wrong expectations.

What we expected here is to set the timer forward during the callback by the amount we set (24us). But if we take a look at the kernel implementation of hrtimer_forward_now()we can see that the time is actually added to the last event/occurrence of the timer (see the calculation of delta):

From Linux/kernel/time/hrtimer.c

833 u64 hrtimer_forward(struct hrtimer *timer, ktime_t now, ktime_t interval)
834 {
835         u64 orun = 1;
836         ktime_t delta;
837 
838         delta = ktime_sub(now, hrtimer_get_expires(timer));
839 
840         if (delta.tv64 < 0)
841                 return 0;
842 
843         if (WARN_ON(timer->state & HRTIMER_STATE_ENQUEUED))
844                 return 0;
845 
846         if (interval.tv64 < hrtimer_resolution)
847                 interval.tv64 = hrtimer_resolution;
848 
849         if (unlikely(delta.tv64 >= interval.tv64)) {
850                 s64 incr = ktime_to_ns(interval);
851 
852                 orun = ktime_divns(delta, incr);
853                 hrtimer_add_expires_ns(timer, incr * orun);
854                 if (hrtimer_get_expires_tv64(timer) > now.tv64)
855                         return orun;
856                 /*
857                  * This (and the ktime_add() below) is the
858                  * correction for exact:
859                  */
860                 orun++;
861         }
862         hrtimer_add_expires(timer, interval);
863 
864         return orun;
865 }

That means that the time delay it took between the timer firing and the callback actually executing is not taken into account here. The hrtimers are meant to be precise in interval timing and not be influenced by the usual delays between firing and the callback. Where our expectancy was to include that time into the calculation because we wanted the timer to restart from the moment we executed an action in the timer callback.

I tried to draw this into the following diagram:

Following the red numbered bubbles we get:

1. timer is started with X time to fire
2. time X has passed, the timer is triggered
3. after "delay X" depending on the load of the system and other factors, the callback function for the hrtimer is called
4. hrtimer_forward_now sets the new timer forward based on the last event plus the new expected time (which might be only 2us in the future instead of 24)
5. Here is the discrepancy of expectation vs reality. The hrtimer fires 24us after the last event when we expect it to fire 24us after the call to forward_now()

To sum it all up, we completely trashed the above code example and went with a usleep_range() call between triggering the two GPIO pins. The underlying implementation of that function is also done with hrtimer but it is hidden from the user and it acts as we expect in this case.