GPIOTE interrupts with around 30us latency?

[Fernando Fontes]

Hi guys,

I've been working with the NRF52832 in the past days and I'm having issues with the GPIOTE interrupts.

It seems that there a latency of around 30us until the interrupt handler is called? 

To give a bit of context I'm working with the TDC1000 which is an Ultrasonic Sensing Analog Front End that will return the distance by triggering an interrupt on the stop pin. To calculate the distance I need to have the start interrupt time and use it to subtract with the stop interrupt time. Since it's an 1MHz transducer, it means that 10us is equal to 7mm (10 * 1450 / 2). That's why I really need the interrupts to work with zero latency. In theory if the latency is always the same it should still work since it will compensate when subtracting, but I'm afraid that is not the case. To measure the time I'm using a timer running at 16MHz which should give me enough accuracy (1/16).

The way I've code the interrupts was:

#define TIMER_INST_IDX 0

static const struct gpio_dt_spec tdc1000_en = GPIO_DT_SPEC_GET_OR(DT_ALIAS(tdc1000_en), gpios, {0});
static const struct gpio_dt_spec tdc1000_rst = GPIO_DT_SPEC_GET_OR(DT_ALIAS(tdc1000_rst), gpios, {0});
static const struct gpio_dt_spec tdc1000_trigger = GPIO_DT_SPEC_GET_OR(DT_ALIAS(tdc1000_trigger), gpios, {0});
static const struct gpio_dt_spec tdc1000_chsel = GPIO_DT_SPEC_GET_OR(DT_ALIAS(tdc1000_chsel), gpios, {0});
static const struct gpio_dt_spec tdc1000_start = GPIO_DT_SPEC_GET_OR(DT_ALIAS(tdc1000_start), gpios, {0});
static const struct gpio_dt_spec tdc1000_stop = GPIO_DT_SPEC_GET_OR(DT_ALIAS(tdc1000_stop), gpios, {0});
static const struct gpio_dt_spec tdc1000_errb = GPIO_DT_SPEC_GET_OR(DT_ALIAS(tdc1000_errb), gpios, {0});

static const struct gpio_dt_spec *required_gpios_ins[3] = {&tdc1000_start, &tdc1000_stop, &tdc1000_errb};
static const gpio_flags_t gpio_ins_flags[3] = {GPIO_INPUT | GPIO_PULL_DOWN, GPIO_INPUT | GPIO_PULL_DOWN, GPIO_INPUT};
static const gpio_flags_t gpio_ins_int_flags[3] = {GPIO_INT_EDGE_TO_ACTIVE, GPIO_INT_EDGE_TO_ACTIVE, GPIO_INT_EDGE_TO_INACTIVE};

K_MSGQ_DEFINE(gpio_interrupt_q, sizeof(gpio_int_context_t), INT_QUEUE_SIZE, 4);

static nrfx_timer_t tof_timer_inst = NRFX_TIMER_INSTANCE(TIMER_INST_IDX);

uint8_t tank_reader_init(void)
{
    int err;
        for (uint8_t i = 0; i < sizeof(required_gpios_ins) / sizeof(struct gpio_dt_spec *); i++)
    {
        if (!gpio_is_ready_dt(required_gpios_ins[i]))
        {
            LOG_ERR("One of the required GPIO's port is not ready.\n");
            return EXIT_FAILURE;
        }

        err = gpio_pin_configure_dt(required_gpios_ins[i], gpio_ins_flags[i]);
        if (err != 0)
        {
            LOG_ERR("Error %d: failed to configure %s pin %d",
                    err, required_gpios_ins[i]->port->name, required_gpios_ins[i]->pin);
            return EXIT_FAILURE;
        }

        err = gpio_pin_interrupt_configure_dt(required_gpios_ins[i], gpio_ins_int_flags[i]);
        if (err != 0)
        {
            LOG_ERR("Error %d: failed to configure interrupt on %s pin %d",
                    err, required_gpios_ins[i]->port->name, required_gpios_ins[i]->pin);
            return EXIT_FAILURE;
        }

        gpio_init_callback(gpio_cb_data[i], gpio_interrupt_handler, BIT(required_gpios_ins[i]->pin));

        gpio_add_callback(required_gpios_ins[i]->port, gpio_cb_data[i]);
    }

    // Configure timer that will later be used for measuring the ToF
    nrfx_err_t status;
    uint32_t base_frequency = NRF_TIMER_BASE_FREQUENCY_GET(tof_timer_inst.p_reg);
    LOG_INF("Base frequency: %u", base_frequency); // 16000000
    nrfx_timer_config_t config = NRFX_TIMER_DEFAULT_CONFIG(base_frequency);
    config.mode = NRF_TIMER_MODE_TIMER;
    config.bit_width = TIMER_BITMODE_BITMODE_32Bit; // approx. 4.4 min
    config.p_context = &tof_timer_inst;
    status = nrfx_timer_init(&tof_timer_inst, &config, NULL);
    if (status != NRFX_SUCCESS)
    {
        LOG_ERR("Error while configuring timer for ToF reading!");
        return EXIT_FAILURE;
    }

    NVIC_SetPriority(GPIOTE_IRQn, IRQ_PRIO_LOWEST);
    NVIC_SetPriority(TIMER0_IRQn, IRQ_PRIO_LOWEST);

    return EXIT_SUCCESS;
}

uint8_t tank_reader_get_level() {
    // flush
    k_msgq_purge(&gpio_interrupt_q);

    LOG_INF("Triggering TDC");

    // enables 16Mhz timer ()
    nrfx_timer_enable(&tof_timer_inst);
    if (!nrfx_timer_is_enabled(&tof_timer_inst))
    {
        LOG_ERR("Timer is not working. Unable to calculate ToF!");
        return EXIT_FAILURE;
    }
    nrfx_timer_clear(&tof_timer_inst); // reset

    uint32_t triggered_timer_value = nrfx_timer_capture(&tof_timer_inst, NRF_TIMER_CC_CHANNEL0);
    tank_reader_drive_trigger_tdc(1);
    tank_reader_drive_trigger_tdc(0);

    // wait for trigger start
    if ((k_msgq_get(&gpio_interrupt_q, &interrupt_context, K_MSEC(1)) == 0) && (interrupt_context.pin == TDC1000_START_PIN))
    {
        uint32_t timeout_count_start = (uint32_t)k_uptime_get();
        uint32_t elapsed = 0;

        LOG_INF("TX pulses transmitted after: %.2f usec.", (double)((interrupt_context.cycle_count - triggered_timer_value) * 0.0625f));

        uint32_t stop_cycle_count[INT_QUEUE_SIZE] = {0};
        uint32_t start_cycle_count = interrupt_context.cycle_count;
        uint8_t stop_cycles_detected = 0;

        // wait for reply
        while ((timeout > elapsed) && (k_msgq_get(&gpio_interrupt_q, &interrupt_context, K_MSEC(timeout - elapsed)) == 0))
        {
            // update elapsed for timeout calculation
            elapsed = (uint32_t)k_uptime_get() - timeout_count_start;

            if (interrupt_context.pin == TDC1000_ERRB_PIN)
            {
                LOG_ERR("ERRB pin triggered! Timeout...");
                break;
            }
            else if (interrupt_context.pin == TDC1000_STOP_PIN)
            {
                stop_cycle_count[stop_cycles_detected++] = interrupt_context.cycle_count;
            }
        }

        // stop the timer now
        nrfx_timer_disable(&tof_timer_inst);
    }
}

static void gpio_interrupt_handler(const struct device *dev, struct gpio_callback *cb, uint32_t pins)
{
    static gpio_int_context_t int_context = {0};

    int_context.cycle_count = nrfx_timer_capture(&tof_timer_inst, NRF_TIMER_CC_CHANNEL0);

    if (cb == &tdc1000_start_cb_data)
    {
        int_context.pin = TDC1000_START_PIN;
        // LOG_INF("Interrupt from START pin at %" PRIu32 "\n", int_context.cycle_count);
    }
    else if (cb == &tdc1000_stop_cb_data)
    {
        int_context.pin = TDC1000_STOP_PIN;
        // LOG_INF("Interrupt from STOP pin at %" PRIu32 "\n", int_context.cycle_count);
    }
    else if (cb == &tdc1000_errb_cb_data)
    {
        int_context.pin = TDC1000_ERRB_PIN;
        // LOG_INF("Interrupt from ERRB pin at %" PRIu32 "\n", int_context.cycle_count);
    }
    else
    {
        // Nothing to do
        return;
    }

    // add to the queue
    k_msgq_put(&gpio_interrupt_q, &int_context, K_NO_WAIT);
}

my prj.conf

CONFIG_SENSOR=y
CONFIG_LIS2DH=y
CONFIG_I2C=y
CONFIG_GPIO=y
CONFIG_LOG=y
CONFIG_USE_SEGGER_RTT=y
CONFIG_CONSOLE=y
CONFIG_RTT_CONSOLE=y
CONFIG_UART_CONSOLE=n
CONFIG_SERIAL=y
CONFIG_UART_INTERRUPT_DRIVEN=y
CONFIG_ADC=y
CONFIG_MCP970X=y
CONFIG_BT=y
CONFIG_PWM=y
CONFIG_CLOCK_CONTROL=y
CONFIG_SPI=y

CONFIG_WDT_LOG_LEVEL_INF=n
CONFIG_WATCHDOG=n
CONFIG_WDT_DISABLE_AT_BOOT=n

CONFIG_REQUIRES_FLOAT_PRINTF=y
CONFIG_BT_DEVICE_NAME="Beacon"

CONFIG_MAIN_THREAD_PRIORITY=10

CONFIG_LIS2DH_TRIGGER_OWN_THREAD=n
CONFIG_LIS2DH_ACCEL_RANGE_2G=y
CONFIG_LIS2DH_OPER_MODE_LOW_POWER=y
CONFIG_LIS2DH_ODR_1=y

CONFIG_NRFX_TIMER0=y

CONFIG_ZERO_LATENCY_IRQS=y

overlay:

&gpiote0 {
    interrupts = <6 0>;
};

The very first print (elapsed time since the trigger signal and the start interrupt): "TX pulses transmitted after: 30.2 usec" is wrong. I've used the oscilloscope to measure it and it reports 4.4us instead. 

But then the stop pulses seem to match the reality which let me think that the latency is always the same which still makes the code to work but it's not ideal. 

Calling NVIC_SetPriority seems to have no effect.

NVIC_SetPriority(GPIOTE_IRQn, IRQ_PRIO_LOWEST);

NVIC_SetPriority(TIMER0_IRQn, IRQ_PRIO_LOWEST);

Any other suggestions? Is this an expected behaviour when using Zephyr OS or is this something that can be fixable? I guess that I can try to have a counter instead of the timer, and use the stop and start pins to start and stop the counter? 

Thank you for the ongoing support,

Best regards,

Fernando Fontes

[Einar Thorsrud]

Hi Fernando,

Yes, this is what I had in mind, and it looks good. With this, the interrupt latency does not affect the measurements. Note that depending on what fits best, you can also clear the timer like this so you will get an absolute cycle count between each event and not have to handle the timer wraping around.

[Fernando Fontes]

Hi Einar,

Yes, I could do that, but I'm cleaning the timer before starting the reading and the time of flight should not exceed 1ms. So, there turn around is not an issue with the 32 bit counter. 

I only have one question left. If I understood correctly ppi will capture the timer value and store it in the timer.p_reg register. Since I'm doing NRF_TIMER_TASK_CAPTURE0, the result will be on CHANNEL0 right? Is it possible that gpiote_event_handler is not fast enough and I could have the ppi capturing the value between two pulses and overwriting the register?

Best regards,

Fernando Fontes

[Einar Thorsrud]

Hi Fernando,

Yes, that is right. If you trigger NRF_TIMER_TASK_CAPTURE0, the result will be in the CC register for channel 0, and the next time you capture on the same channel, it will be overwritten. There are several channels though, so you could map different events to different capture tasks via PPI (in this case you could map each of the three GPIOTE events to separate capture tasks).