Unexpected timing value behavior when using Zephyr timing functions.

[Adam K.]

I need to measure pulse widths with microsecond accuracy using a NRF7002DK. To do that I am using Zephyr Time Functions (CONFIG_TIMING_FUNCTIONS). My SDK is v2.6.0.

The pulses are routed to a GPIO interrupt that is configured GPIO_INT_LEVEL_ACTIVE to interrupt on a high and then GPIO_INT_LEVEL_INACTIVE on a low. The pulses are roughly 8400 microseconds wide +/- 300 microseconds.

My thread starts with:

wait_for_asserted = true;
gpio_pin_interrupt_configure_dt( &gpio, GPIO_INT_LEVEL_ACTIVE );

The GPIO interrupt callback is as follows:

static void gpio_callback(
   const struct device *dev,
   struct gpio_callback *cb,
   uint32_t pins )
{
   timing_t assert_time;
   timing_t deassert_time;
   uint64_t total_cycles;
   uint64_t total_time_in_us;
   uint32_t k_assert_time;
   uint32_t k_deassert_time;

   if ( wait_for_asserted )
   {
      timing_init();

      timing_start();
      assert_time = timing_counter_get();
      k_assert_time = k_uptime_get();

      wait_for_asserted = false;
      gpio_pin_interrupt_configure_dt( &gpio, GPIO_INT_LEVEL_INACTIVE );
   }
   else
   {
      deassert_time = timing_counter_get();
      k_deassert_time = k_uptime_get();
      timing_stop();

      wait_for_asserted = true;
      gpio_pin_interrupt_configure_dt( &gpio, GPIO_INT_LEVEL_ACTIVE );

      total_cycles = timing_cycles_get( &assert_time, &deassert_time );
      total_time_in_us = timing_cycles_to_ns( total_cycles ) / 1000;

      if ( total_time_in_us >= 2000 )
      {
         struct msg_item_s msg;

         msg.id = MSG_ID_ASSERTION;
         msg.time_in_us = total_time_in_us;
         msg.assert_time = assert_time;
         msg.deassert_time = deassert_time;
         msg.k_assert_time = k_assert_time;
         msg.k_deassert_time = k_deassert_time;

         k_msgq_put( &msgq, &msg, K_NO_WAIT );
      }
   }
}

When my thread receives the message I print the following:

printk( "time_in_us: %llu\n", msg.time_in_us );
printk( "assert_time: %llu\n", msg.assert_time );
printk( "deassert_time: %llu\n", msg.deassert_time );
printk( "k_assert_time: %u\n", msg.k_assert_time );
printk( "k_deassert_time: %u\n", msg.k_deassert_time );

Immediately after system reset, I run the routine and get the following debug:

ime_in_us: 8624
assert_time: 3747779501
deassert_time: 3748331488
k_assert_time: 61866
k_deassert_time: 61875

time_in_us: 8245
assert_time: 3760017779
deassert_time: 3760545462
k_assert_time: 62059
k_deassert_time: 62068

This is exactly what I would expect.

However after about a minute of system uptime, I see the following behavior until I reset the processor:

time_in_us: 3184
assert_time: 3856154728
deassert_time: 3856358507
k_assert_time: 64802
k_deassert_time: 64811

time_in_us: 3059
assert_time: 3858003423
deassert_time: 3858199205
k_assert_time: 64947
k_deassert_time: 64956

I have verified on my oscilloscope that that the pulse widths are still roughly 8400 microseconds and the k_uptime_get values confirm this, but the timing_cycle values are not correct.

I have tried many different combinations of using the timing functions but continue to see the same behavior.

Please advise. Thank you.

[Adam K.]

I copied the callback code incorrectly as the assert and deassert time variables are declared static within the callback function.

   static timing_t assert_time;
   static timing_t deassert_time;
   static uint32_t k_assert_time;
   static uint32_t k_deassert_time;
   uint64_t total_cycles;
   uint64_t total_cs_time_in_us;

FYI - the erroneous timing values seem to happen as soon as the k_uptime is 64000 or greater.

[Kazi Afroza Sultana]

Hello,

Can you try to use GPIOTE+TIMER+(D)PPI in the application like this example https://github.com/sigurdnev/ncs-playground/blob/master/samples/pulse_detector/src/main.c? It would be more accurate than what you have done now.