k_uptime_get() returning wrong values

[GuyYaniv]

Hi,

I'm trying to measure message travel time using Gazel and k_uptime_get() so I can understand the packet intervals.

I'm using gzll_ack_payload_device and gzll_ack_payload_host from v2.6.1 sample apps modified to send k_uptime_get() as the payload and measure the delta received in the ACK's payload (see git diffs below).

I'm seeing time deltas of 115 msec when I try to use k_uptime_get() stamping.

Then I used LED flashing on both DK boards to be able to measure the timing and I see 1 msec from device to host and 3 msec from host ACK back to device which makes more sense (Analyzer images below)

What is the reason for k_uptime_get() to return wrong reading? I checked the build/zephyr/.config file and I see CONFIG_SYS_CLOCK_TICKS_PER_SEC=32768.

Thanks,

Guy.

diff --git a/samples/gazell/gzll_ack_payload_device/src/main.c b/samples/gazell/gzll_ack_payload_device/src/main.c
index 58bb7fc93..1e8b863ea 100644
--- a/samples/gazell/gzll_ack_payload_device/src/main.c
+++ b/samples/gazell/gzll_ack_payload_device/src/main.c
@@ -17,7 +17,7 @@ LOG_MODULE_REGISTER(app);
 #define PIPE_NUMBER 0

 /* 1-byte payload length is used when transmitting. */
-#define TX_PAYLOAD_LENGTH 1
+#define TX_PAYLOAD_LENGTH 8

 /* Maximum number of transmission attempts */
 #define MAX_TX_ATTEMPTS 100
@@ -51,6 +51,7 @@ K_MSGQ_DEFINE(gzll_msgq,
 static K_SEM_DEFINE(main_sem, 0, 1);

 static struct k_work gzll_work;
+static uint64_t start_time, end_time;

 static void gzll_tx_result_handler(struct gzll_tx_result *tx_result);
 static void gzll_work_handler(struct k_work *work);
@@ -99,8 +100,10 @@ int main(void)
        }
 #endif

-       data_payload[0] = ~dk_get_buttons();
+       // data_payload[0] = ~dk_get_buttons();

+       *(uint64_t *)data_payload = k_uptime_get();
+       LOG_INF("Entering data payload %llu", *(uint64_t *)data_payload);
        result_value = nrf_gzll_add_packet_to_tx_fifo(PIPE_NUMBER, data_payload, TX_PAYLOAD_LENGTH);
        if (!result_value) {
                LOG_ERR("Cannot add packet to GZLL TX FIFO");
@@ -170,11 +173,13 @@ static void gzll_device_report_tx(bool success,

 void nrf_gzll_device_tx_success(uint32_t pipe, nrf_gzll_device_tx_info_t tx_info)
 {
+       LOG_INF("Tx success payload %s in ACK", tx_info.payload_received_in_ack?"received":"not received");
        gzll_device_report_tx(true, pipe, &tx_info);
 }

 void nrf_gzll_device_tx_failed(uint32_t pipe, nrf_gzll_device_tx_info_t tx_info)
 {
+       LOG_INF("Tx failed");
        gzll_device_report_tx(false, pipe, &tx_info);
 }

@@ -207,6 +212,7 @@ static void gzll_tx_result_handler(struct gzll_tx_result *tx_result)

        if (tx_result->success) {
                if (tx_result->info.payload_received_in_ack) {
+                       end_time = k_uptime_get();
                        /* Pop packet and write first byte of the payload to the GPIO port. */
                        result_value = nrf_gzll_fetch_packet_from_rx_fifo(tx_result->pipe,
                                                                          ack_payload,
@@ -214,22 +220,32 @@ static void gzll_tx_result_handler(struct gzll_tx_result *tx_result)
                        if (!result_value) {
                                LOG_ERR("RX fifo error");
                        } else if (ack_payload_length > 0) {
-                               err = dk_set_leds(ack_payload[0] & DK_ALL_LEDS_MSK);
+                               err = dk_set_leds_state(0, DK_ALL_LEDS_MSK);
                                if (err) {
                                        LOG_ERR("Cannot output LEDs (err: %d)", err);
                                }
+                               // LOG_INF("ACK payload %llu end time %llu", *(uint64_t *)ack_payload, end_time);
+                               LOG_INF("Time diff %lld", k_uptime_delta((uint64_t *)ack_payload));
                        }
                }
        } else {
                LOG_ERR("Gazell transmission failed");
        }

+       k_msleep(100);
        /* Load data payload into the TX queue. */
-       data_payload[0] = ~dk_get_buttons();
+       start_time=k_uptime_get();
+       // LOG_INF("Uptime %lld", start_time);
+       *(uint64_t *)data_payload = k_uptime_get();
+       // LOG_INF("Entering data payload %llu", *(uint64_t *)data_payload);
        result_value = nrf_gzll_add_packet_to_tx_fifo(tx_result->pipe,
                                                      data_payload,
                                                      TX_PAYLOAD_LENGTH);
        if (!result_value) {
                LOG_ERR("TX fifo error");
        }
+       err = dk_set_leds_state(DK_ALL_LEDS_MSK, 0);
+       if (err) {
+               LOG_ERR("Cannot output LEDs (err: %d)", err);
+       }
 }

diff --git a/samples/gazell/gzll_ack_payload_device/src/main.c b/samples/gazell/gzll_ack_payload_device/src/main.c
index 58bb7fc93..1e8b863ea 100644
--- a/samples/gazell/gzll_ack_payload_device/src/main.c
+++ b/samples/gazell/gzll_ack_payload_device/src/main.c
@@ -17,7 +17,7 @@ LOG_MODULE_REGISTER(app);
 #define PIPE_NUMBER 0

 /* 1-byte payload length is used when transmitting. */
-#define TX_PAYLOAD_LENGTH 1
+#define TX_PAYLOAD_LENGTH 8

 /* Maximum number of transmission attempts */
 #define MAX_TX_ATTEMPTS 100
@@ -51,6 +51,7 @@ K_MSGQ_DEFINE(gzll_msgq,
 static K_SEM_DEFINE(main_sem, 0, 1);

 static struct k_work gzll_work;
+static uint64_t start_time, end_time;

 static void gzll_tx_result_handler(struct gzll_tx_result *tx_result);
 static void gzll_work_handler(struct k_work *work);
@@ -99,8 +100,10 @@ int main(void)
        }
 #endif

-       data_payload[0] = ~dk_get_buttons();
+       // data_payload[0] = ~dk_get_buttons();

+       *(uint64_t *)data_payload = k_uptime_get();
+       LOG_INF("Entering data payload %llu", *(uint64_t *)data_payload);
        result_value = nrf_gzll_add_packet_to_tx_fifo(PIPE_NUMBER, data_payload, TX_PAYLOAD_LENGTH);
        if (!result_value) {
                LOG_ERR("Cannot add packet to GZLL TX FIFO");
@@ -170,11 +173,13 @@ static void gzll_device_report_tx(bool success,

 void nrf_gzll_device_tx_success(uint32_t pipe, nrf_gzll_device_tx_info_t tx_info)
 {
+       LOG_INF("Tx success payload %s in ACK", tx_info.payload_received_in_ack?"received":"not received");
        gzll_device_report_tx(true, pipe, &tx_info);
 }

 void nrf_gzll_device_tx_failed(uint32_t pipe, nrf_gzll_device_tx_info_t tx_info)
 {
+       LOG_INF("Tx failed");
        gzll_device_report_tx(false, pipe, &tx_info);
 }

@@ -207,6 +212,7 @@ static void gzll_tx_result_handler(struct gzll_tx_result *tx_result)

        if (tx_result->success) {
                if (tx_result->info.payload_received_in_ack) {
+                       end_time = k_uptime_get();
                        /* Pop packet and write first byte of the payload to the GPIO port. */
                        result_value = nrf_gzll_fetch_packet_from_rx_fifo(tx_result->pipe,
                                                                          ack_payload,
@@ -214,22 +220,32 @@ static void gzll_tx_result_handler(struct gzll_tx_result *tx_result)
                        if (!result_value) {
                                LOG_ERR("RX fifo error");
                        } else if (ack_payload_length > 0) {
-                               err = dk_set_leds(ack_payload[0] & DK_ALL_LEDS_MSK);
+                               err = dk_set_leds_state(0, DK_ALL_LEDS_MSK);
                                if (err) {
                                        LOG_ERR("Cannot output LEDs (err: %d)", err);
                                }
+                               // LOG_INF("ACK payload %llu end time %llu", *(uint64_t *)ack_payload, end_time);
+                               LOG_INF("Time diff %lld", k_uptime_delta((uint64_t *)ack_payload));
                        }
                }
        } else {
                LOG_ERR("Gazell transmission failed");
        }

+       k_msleep(100);
        /* Load data payload into the TX queue. */
-       data_payload[0] = ~dk_get_buttons();
+       start_time=k_uptime_get();
+       // LOG_INF("Uptime %lld", start_time);
+       *(uint64_t *)data_payload = k_uptime_get();
+       // LOG_INF("Entering data payload %llu", *(uint64_t *)data_payload);
        result_value = nrf_gzll_add_packet_to_tx_fifo(tx_result->pipe,
                                                      data_payload,
                                                      TX_PAYLOAD_LENGTH);
        if (!result_value) {
                LOG_ERR("TX fifo error");
        }
+       err = dk_set_leds_state(DK_ALL_LEDS_MSK, 0);
+       if (err) {
+               LOG_ERR("Cannot output LEDs (err: %d)", err);
+       }
 }

[Naeem Maroof]

Hello,

Are you changing both of the projects? I see that you have uploaded the modifications of the same file two times (i.e of the payload device).

Can you share some console logs from both devices?

How are you measuring? Are you measuring the time for two-way trip (transmission from device and receiving acknowledgement back at device)? Or between device and host?

I can see that you are calculating delta on the device side like this:

LOG_INF("Time diff %lld", k_uptime_delta((uint64_t *)ack_payload));

but two devices have their own booting time, and hence you should be measuring the DELTA from the time packet was sent to the time acknowledgement is received. But this code is not doing that. This code is taking the DELTA between the current-time-of-Device and the time (of Host) at which ACK was sent.