From c743bdac885ba63fc1de3a3995dbc76741fa1da6 Mon Sep 17 00:00:00 2001 From: Ivan Grokhotkov Date: Mon, 21 Aug 2017 22:33:52 +0800 Subject: [PATCH 1/5] soc/rtc: round APB clock frequency to nearest MHz --- components/soc/esp32/rtc_clk.c | 6 +++++- 1 file changed, 5 insertions(+), 1 deletion(-) diff --git a/components/soc/esp32/rtc_clk.c b/components/soc/esp32/rtc_clk.c index 7f6d99291..aee0a39ff 100644 --- a/components/soc/esp32/rtc_clk.c +++ b/components/soc/esp32/rtc_clk.c @@ -500,7 +500,11 @@ void rtc_clk_apb_freq_update(uint32_t apb_freq) uint32_t rtc_clk_apb_freq_get() { - return reg_val_to_clk_val(READ_PERI_REG(RTC_APB_FREQ_REG)) << 12; + uint32_t freq_hz = reg_val_to_clk_val(READ_PERI_REG(RTC_APB_FREQ_REG)) << 12; + // round to the nearest MHz + freq_hz += MHZ / 2; + uint32_t remainder = freq_hz % MHZ; + return freq_hz - remainder; } From 1af63843490f273e1702ebca48e50f975853e7c5 Mon Sep 17 00:00:00 2001 From: Ivan Grokhotkov Date: Wed, 30 Aug 2017 08:43:02 +0800 Subject: [PATCH 2/5] esp_timer: lock-free implementation of esp_timer_get_time The implementation of esp_timer_get_time used a critical section, which resulted in a call time of ~1.8us. To make esp_timer_get_time more useable as a high-resolution time source, this change replaces the lock with polling. Call time is reduced to ~0.7us. --- components/esp32/esp_timer_esp32.c | 38 ++++++++++++++++----- components/esp32/test/test_esp_timer.c | 47 ++++++++++++++++++++++++++ 2 files changed, 76 insertions(+), 9 deletions(-) diff --git a/components/esp32/esp_timer_esp32.c b/components/esp32/esp_timer_esp32.c index 864167b2b..3e08338a5 100644 --- a/components/esp32/esp_timer_esp32.c +++ b/components/esp32/esp_timer_esp32.c @@ -126,15 +126,35 @@ static inline bool IRAM_ATTR timer_overflow_happened() uint64_t IRAM_ATTR esp_timer_impl_get_time() { - portENTER_CRITICAL(&s_time_update_lock); - uint32_t timer_val = REG_READ(FRC_TIMER_COUNT_REG(1)); - uint64_t result = s_time_base_us; - if (timer_overflow_happened()) { - result += s_timer_us_per_overflow; - } - uint32_t ticks_per_us = s_timer_ticks_per_us; - portEXIT_CRITICAL(&s_time_update_lock); - return result + timer_val / ticks_per_us; + uint32_t timer_val; + uint64_t time_base; + uint32_t ticks_per_us; + bool overflow; + uint64_t us_per_overflow; + + do { + /* Read all values needed to calculate current time */ + timer_val = REG_READ(FRC_TIMER_COUNT_REG(1)); + time_base = s_time_base_us; + overflow = timer_overflow_happened(); + ticks_per_us = s_timer_ticks_per_us; + us_per_overflow = s_timer_us_per_overflow; + + /* Read them again and compare */ + if (REG_READ(FRC_TIMER_COUNT_REG(1)) > timer_val && + time_base == *((volatile uint64_t*) &s_time_base_us) && + ticks_per_us == *((volatile uint32_t*) &s_timer_ticks_per_us) && + overflow == timer_overflow_happened()) { + break; + } + + /* If any value has changed (other than the counter increasing), read again */ + } while(true); + + uint64_t result = time_base + + (overflow ? us_per_overflow : 0) + + timer_val / ticks_per_us; + return result; } void IRAM_ATTR esp_timer_impl_set_alarm(uint64_t timestamp) diff --git a/components/esp32/test/test_esp_timer.c b/components/esp32/test/test_esp_timer.c index a5b23a51f..a24cbfe5a 100644 --- a/components/esp32/test/test_esp_timer.c +++ b/components/esp32/test/test_esp_timer.c @@ -322,3 +322,50 @@ TEST_CASE("esp_timer for very short intervals", "[esp_timer]") vSemaphoreDelete(semaphore); } + + +TEST_CASE("esp_timer_get_time call takes less than 1us", "[esp_timer]") +{ + uint64_t begin = esp_timer_get_time(); + volatile uint64_t end; + const int iter_count = 10000; + for (int i = 0; i < iter_count; ++i) { + end = esp_timer_get_time(); + } + int ns_per_call = (int) ((end - begin) * 1000 / iter_count); + printf("esp_timer_get_time: %dns per call\n", ns_per_call); + TEST_ASSERT(ns_per_call < 1000); +} + +/* This test runs for about 10 minutes and is disabled in CI */ +TEST_CASE("esp_timer_get_time returns monotonic values", "[esp_timer][ignore]") +{ + void timer_test_task(void* arg) { + uint64_t last = esp_timer_get_time(); + + const int iter_count = 1000000000; + for (int i = 0; i < iter_count; ++i) { + uint64_t now = esp_timer_get_time(); + if (now < last || now - last > 100) { + printf("core_id:%d now: %lld last:%lld\n", xPortGetCoreID(), now, last); + fflush(stdout); + abort(); + } + last = now; + } + + xSemaphoreGive((SemaphoreHandle_t) arg); + vTaskDelete(NULL); + } + + SemaphoreHandle_t done_1 = xSemaphoreCreateBinary(); + SemaphoreHandle_t done_2 = xSemaphoreCreateBinary(); + + xTaskCreatePinnedToCore(&timer_test_task, "t1", 4096, (void*) done_1, 6, NULL, 0); + xTaskCreatePinnedToCore(&timer_test_task, "t2", 4096, (void*) done_2, 6, NULL, 1); + + TEST_ASSERT_TRUE( xSemaphoreTake(done_1, portMAX_DELAY) ); + TEST_ASSERT_TRUE( xSemaphoreTake(done_2, portMAX_DELAY) ); + vSemaphoreDelete(done_1); + vSemaphoreDelete(done_2); +} From 9a2c62cf2bf7a0bb03c60348aa2fc592406a317a Mon Sep 17 00:00:00 2001 From: Ivan Grokhotkov Date: Mon, 21 Aug 2017 22:33:03 +0800 Subject: [PATCH 3/5] unity: add reference clock for use in unit tests --- .../components/unity/include/test_utils.h | 19 ++ .../components/unity/ref_clock.c | 169 ++++++++++++++++++ 2 files changed, 188 insertions(+) create mode 100644 tools/unit-test-app/components/unity/ref_clock.c diff --git a/tools/unit-test-app/components/unity/include/test_utils.h b/tools/unit-test-app/components/unity/include/test_utils.h index 2fad41a10..ba9c62db4 100644 --- a/tools/unit-test-app/components/unity/include/test_utils.h +++ b/tools/unit-test-app/components/unity/include/test_utils.h @@ -15,6 +15,7 @@ // Utilities for esp-idf unit tests +#include #include /* Return the 'flash_test' custom data partition (type 0x55) @@ -22,3 +23,21 @@ */ const esp_partition_t *get_test_data_partition(); +/** + * @brief Initialize reference clock + * + * Reference clock provides timestamps at constant 1 MHz frequency, even when + * the APB frequency is changing. + */ +void ref_clock_init(); + +/** + * @brief Deinitialize reference clock + */ +void ref_clock_deinit(); + +/** + * @brief Get reference clock timestamp + * @return number of microseconds since the reference clock was initialized + */ +uint64_t ref_clock_get(); diff --git a/tools/unit-test-app/components/unity/ref_clock.c b/tools/unit-test-app/components/unity/ref_clock.c new file mode 100644 index 000000000..ab732970b --- /dev/null +++ b/tools/unit-test-app/components/unity/ref_clock.c @@ -0,0 +1,169 @@ +// Copyright 2017 Espressif Systems (Shanghai) PTE LTD +// +// Licensed under the Apache License, Version 2.0 (the "License"); +// you may not use this file except in compliance with the License. +// You may obtain a copy of the License at +// +// http://www.apache.org/licenses/LICENSE-2.0 +// +// Unless required by applicable law or agreed to in writing, software +// distributed under the License is distributed on an "AS IS" BASIS, +// WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. +// See the License for the specific language governing permissions and +// limitations under the License. + +/* Unit tests need to have access to reliable timestamps even if CPU and APB + * clock frequencies change over time. This reference clock is built upon two + * peripherals: one RMT channel and one PCNT channel, plus one GPIO to connect + * these peripherals. + * + * RMT channel is configured to use REF_TICK as clock source, which is a 1 MHz + * clock derived from APB_CLK using a set of dividers. The divider is changed + * automatically by hardware depending on the current clock source of APB_CLK. + * For example, if APB_CLK is derived from PLL, one divider is used, and when + * APB_CLK is derived from XTAL, another divider is used. RMT channel clocked + * by REF_TICK is configured to generate a continuous 0.5 MHz signal, which is + * connected to a GPIO. PCNT takes the input signal from this GPIO and counts + * the edges (which occur at 1MHz frequency). PCNT counter is only 16 bit wide, + * so an interrupt is configured to trigger when the counter reaches 30000, + * incrementing a 32-bit millisecond counter maintained by software. + * Together these two counters may be used at any time to obtain the timestamp. + */ + +#include "test_utils.h" +#include "soc/rmt_struct.h" +#include "soc/pcnt_struct.h" +#include "soc/pcnt_reg.h" +#include "soc/gpio_sig_map.h" +#include "soc/dport_reg.h" +#include "rom/gpio.h" +#include "rom/ets_sys.h" +#include "driver/gpio.h" +#include "esp_intr_alloc.h" +#include "freertos/FreeRTOS.h" + +/* Select which RMT and PCNT channels, and GPIO to use */ +#define REF_CLOCK_RMT_CHANNEL 7 +#define REF_CLOCK_PCNT_UNIT 0 +#define REF_CLOCK_GPIO 21 + +#define REF_CLOCK_PRESCALER_MS 30 + +static void IRAM_ATTR pcnt_isr(void* arg); + +static intr_handle_t s_intr_handle; +static portMUX_TYPE s_lock = portMUX_INITIALIZER_UNLOCKED; +static volatile uint32_t s_milliseconds; + +void ref_clock_init() +{ + assert(s_intr_handle == NULL && "already initialized"); + + // Route RMT output to GPIO matrix + gpio_matrix_out(REF_CLOCK_GPIO, RMT_SIG_OUT0_IDX + REF_CLOCK_RMT_CHANNEL, false, false); + + + // Initialize RMT + DPORT_SET_PERI_REG_MASK(DPORT_PERIP_CLK_EN_REG, DPORT_RMT_CLK_EN); + DPORT_CLEAR_PERI_REG_MASK(DPORT_PERIP_RST_EN_REG, DPORT_RMT_RST); + RMT.apb_conf.fifo_mask = 1; + rmt_item32_t data = { + .duration0 = 1, + .level0 = 1, + .duration1 = 0, + .level1 = 0 + }; + RMTMEM.chan[REF_CLOCK_RMT_CHANNEL].data32[0] = data; + RMTMEM.chan[REF_CLOCK_RMT_CHANNEL].data32[1].val = 0; + + + RMT.conf_ch[REF_CLOCK_RMT_CHANNEL].conf0.clk_en = 1; + RMT.conf_ch[REF_CLOCK_RMT_CHANNEL].conf1.tx_start = 0; + RMT.conf_ch[REF_CLOCK_RMT_CHANNEL].conf1.mem_owner = 0; + RMT.conf_ch[REF_CLOCK_RMT_CHANNEL].conf1.mem_rd_rst = 1; + RMT.conf_ch[REF_CLOCK_RMT_CHANNEL].conf1.apb_mem_rst = 1; + RMT.conf_ch[REF_CLOCK_RMT_CHANNEL].conf0.carrier_en = 0; + RMT.conf_ch[REF_CLOCK_RMT_CHANNEL].conf0.div_cnt = 1; + RMT.conf_ch[REF_CLOCK_RMT_CHANNEL].conf0.mem_size = 1; + RMT.conf_ch[REF_CLOCK_RMT_CHANNEL].conf1.ref_always_on = 0; + RMT.conf_ch[REF_CLOCK_RMT_CHANNEL].conf1.tx_conti_mode = 1; + RMT.conf_ch[REF_CLOCK_RMT_CHANNEL].conf1.tx_start = 1; + + // Route signal to PCNT + int pcnt_sig_idx = (REF_CLOCK_PCNT_UNIT < 5) ? + PCNT_SIG_CH0_IN0_IDX + 4 * REF_CLOCK_PCNT_UNIT : + PCNT_SIG_CH0_IN5_IDX + 4 * (REF_CLOCK_PCNT_UNIT - 5); + gpio_matrix_in(REF_CLOCK_GPIO, pcnt_sig_idx, false); + if (REF_CLOCK_GPIO != 20) { + PIN_INPUT_ENABLE(GPIO_PIN_MUX_REG[REF_CLOCK_GPIO]); + } else { + PIN_INPUT_ENABLE(PERIPHS_IO_MUX_GPIO20_U); + } + + // Initialize PCNT + DPORT_SET_PERI_REG_MASK(DPORT_PERIP_CLK_EN_REG, DPORT_PCNT_CLK_EN); + DPORT_CLEAR_PERI_REG_MASK(DPORT_PERIP_RST_EN_REG, DPORT_PCNT_RST); + + PCNT.conf_unit[REF_CLOCK_PCNT_UNIT].conf0.ch0_hctrl_mode = 0; + PCNT.conf_unit[REF_CLOCK_PCNT_UNIT].conf0.ch0_lctrl_mode = 0; + PCNT.conf_unit[REF_CLOCK_PCNT_UNIT].conf0.ch0_pos_mode = 1; + PCNT.conf_unit[REF_CLOCK_PCNT_UNIT].conf0.ch0_neg_mode = 1; + PCNT.conf_unit[REF_CLOCK_PCNT_UNIT].conf0.thr_l_lim_en = 0; + PCNT.conf_unit[REF_CLOCK_PCNT_UNIT].conf0.thr_h_lim_en = 1; + PCNT.conf_unit[REF_CLOCK_PCNT_UNIT].conf0.thr_zero_en = 0; + PCNT.conf_unit[REF_CLOCK_PCNT_UNIT].conf0.thr_thres0_en = 0; + PCNT.conf_unit[REF_CLOCK_PCNT_UNIT].conf0.thr_thres1_en = 0; + PCNT.conf_unit[REF_CLOCK_PCNT_UNIT].conf2.cnt_h_lim = REF_CLOCK_PRESCALER_MS * 1000; + + // Enable PCNT and wait for it to start counting + PCNT.ctrl.val &= ~(BIT(REF_CLOCK_PCNT_UNIT * 2 + 1)); + PCNT.ctrl.val |= BIT(REF_CLOCK_PCNT_UNIT * 2); + PCNT.ctrl.val &= ~BIT(REF_CLOCK_PCNT_UNIT * 2); + + // Enable interrupt + s_milliseconds = 0; + ESP_ERROR_CHECK(esp_intr_alloc(ETS_PCNT_INTR_SOURCE, ESP_INTR_FLAG_IRAM, pcnt_isr, NULL, &s_intr_handle)); + PCNT.int_clr.val = BIT(REF_CLOCK_PCNT_UNIT); + PCNT.int_ena.val = BIT(REF_CLOCK_PCNT_UNIT); +} + +static void IRAM_ATTR pcnt_isr(void* arg) +{ + portENTER_CRITICAL(&s_lock); + PCNT.int_clr.val = BIT(REF_CLOCK_PCNT_UNIT); + s_milliseconds += REF_CLOCK_PRESCALER_MS; + portEXIT_CRITICAL(&s_lock); +} + +void ref_clock_deinit() +{ + assert(s_intr_handle && "deinit called without init"); + + // Disable interrupt + PCNT.int_ena.val &= ~BIT(REF_CLOCK_PCNT_UNIT); + esp_intr_free(s_intr_handle); + s_intr_handle = NULL; + + // Disable RMT + RMT.conf_ch[REF_CLOCK_RMT_CHANNEL].conf1.tx_start = 0; + RMT.conf_ch[REF_CLOCK_RMT_CHANNEL].conf0.clk_en = 0; + DPORT_CLEAR_PERI_REG_MASK(DPORT_PERIP_CLK_EN_REG, DPORT_RMT_CLK_EN); + DPORT_SET_PERI_REG_MASK(DPORT_PERIP_RST_EN_REG, DPORT_RMT_RST); + + // Disable PCNT + PCNT.ctrl.val |= ~(BIT(REF_CLOCK_PCNT_UNIT * 2 + 1)); + DPORT_CLEAR_PERI_REG_MASK(DPORT_PERIP_CLK_EN_REG, DPORT_PCNT_CLK_EN); + DPORT_SET_PERI_REG_MASK(DPORT_PERIP_RST_EN_REG, DPORT_PCNT_RST); +} + +uint64_t ref_clock_get() +{ + portENTER_CRITICAL(&s_lock); + uint32_t microseconds = PCNT.cnt_unit[REF_CLOCK_PCNT_UNIT].cnt_val; + uint32_t milliseconds = s_milliseconds; + if (PCNT.int_st.val & BIT(REF_CLOCK_PCNT_UNIT)) { + milliseconds += REF_CLOCK_PRESCALER_MS; + } + portEXIT_CRITICAL(&s_lock); + return 1000 * (uint64_t) milliseconds + (uint64_t) microseconds; +} From c5632d301299f75cdb273684b25c3eb8dc1570f5 Mon Sep 17 00:00:00 2001 From: Ivan Grokhotkov Date: Wed, 30 Aug 2017 09:01:37 +0800 Subject: [PATCH 4/5] esp32: use ref_clock in esp_timer and delay tests --- components/esp32/test/test_delay.c | 57 ++++++++++++++------ components/esp32/test/test_esp_timer.c | 75 +++++++++++++------------- 2 files changed, 78 insertions(+), 54 deletions(-) diff --git a/components/esp32/test/test_delay.c b/components/esp32/test/test_delay.c index c34c3bda7..7cecc0de7 100644 --- a/components/esp32/test/test_delay.c +++ b/components/esp32/test/test_delay.c @@ -6,17 +6,21 @@ #include "rom/ets_sys.h" #include "freertos/FreeRTOS.h" #include "freertos/task.h" +#include "freertos/semphr.h" +#include "test_utils.h" typedef struct { int delay_us; int method; + int result; + SemaphoreHandle_t done; } delay_test_arg_t; static void test_delay_task(void* p) { - const delay_test_arg_t* arg = (delay_test_arg_t*) p; - struct timeval tv_start, tv_stop; - gettimeofday(&tv_start, NULL); + delay_test_arg_t* arg = (delay_test_arg_t*) p; + vTaskDelay(1); + uint64_t start = ref_clock_get(); switch (arg->method) { case 0: ets_delay_us(arg->delay_us); @@ -27,32 +31,51 @@ static void test_delay_task(void* p) default: TEST_FAIL(); } - gettimeofday(&tv_stop, NULL); - int real_delay_us = (tv_stop.tv_sec - tv_start.tv_sec) * 1000000 + - tv_stop.tv_usec - tv_start.tv_usec; - printf("%s core=%d expected=%d actual=%d\n", arg->method ? "vTaskDelay" : "ets_delay_us", - xPortGetCoreID(), arg->delay_us, real_delay_us); - TEST_ASSERT_TRUE(abs(real_delay_us - arg->delay_us) < 1000); - vTaskDelay(1); + uint64_t stop = ref_clock_get(); + + arg->result = (int) (stop - start); + xSemaphoreGive(arg->done); vTaskDelete(NULL); } -TEST_CASE("ets_delay produces correct delay on both CPUs", "[delay][ignore]") +TEST_CASE("ets_delay produces correct delay on both CPUs", "[delay]") { int delay_ms = 50; - const delay_test_arg_t args = { .delay_us = delay_ms * 1000, .method = 0 }; + const delay_test_arg_t args = { + .delay_us = delay_ms * 1000, + .method = 0, + .done = xSemaphoreCreateBinary() + }; + ref_clock_init(); xTaskCreatePinnedToCore(test_delay_task, "", 2048, (void*) &args, 3, NULL, 0); - vTaskDelay(delay_ms / portTICK_PERIOD_MS + 1); + TEST_ASSERT( xSemaphoreTake(args.done, delay_ms * 2 / portTICK_PERIOD_MS) ); + TEST_ASSERT_INT32_WITHIN(1000, args.delay_us, args.result); + xTaskCreatePinnedToCore(test_delay_task, "", 2048, (void*) &args, 3, NULL, 1); - vTaskDelay(delay_ms / portTICK_PERIOD_MS + 1); + TEST_ASSERT( xSemaphoreTake(args.done, delay_ms * 2 / portTICK_PERIOD_MS) ); + TEST_ASSERT_INT32_WITHIN(1000, args.delay_us, args.result); + + ref_clock_deinit(); + vSemaphoreDelete(args.done); } TEST_CASE("vTaskDelay produces correct delay on both CPUs", "[delay]") { int delay_ms = 50; - const delay_test_arg_t args = { .delay_us = delay_ms * 1000, .method = 1 }; + const delay_test_arg_t args = { + .delay_us = delay_ms * 1000, + .method = 1, + .done = xSemaphoreCreateBinary() + }; + ref_clock_init(); xTaskCreatePinnedToCore(test_delay_task, "", 2048, (void*) &args, 3, NULL, 0); - vTaskDelay(delay_ms / portTICK_PERIOD_MS + 1); + TEST_ASSERT( xSemaphoreTake(args.done, delay_ms * 2 / portTICK_PERIOD_MS) ); + TEST_ASSERT_INT32_WITHIN(1000, args.delay_us, args.result); + xTaskCreatePinnedToCore(test_delay_task, "", 2048, (void*) &args, 3, NULL, 1); - vTaskDelay(delay_ms / portTICK_PERIOD_MS + 1); + TEST_ASSERT( xSemaphoreTake(args.done, delay_ms * 2 / portTICK_PERIOD_MS) ); + TEST_ASSERT_INT32_WITHIN(1000, args.delay_us, args.result); + + ref_clock_deinit(); + vSemaphoreDelete(args.done); } diff --git a/components/esp32/test/test_esp_timer.c b/components/esp32/test/test_esp_timer.c index a24cbfe5a..c2cee90e4 100644 --- a/components/esp32/test/test_esp_timer.c +++ b/components/esp32/test/test_esp_timer.c @@ -7,6 +7,7 @@ #include "freertos/FreeRTOS.h" #include "freertos/task.h" #include "freertos/semphr.h" +#include "test_utils.h" TEST_CASE("esp_timer orders timers correctly", "[esp_timer]") { @@ -65,15 +66,15 @@ TEST_CASE("esp_timer produces correct delay", "[esp_timer]") { void timer_func(void* arg) { - struct timeval* ptv = (struct timeval*) arg; - gettimeofday(ptv, NULL); + uint64_t* p_end = (uint64_t*) arg; + *p_end = ref_clock_get(); } - volatile struct timeval tv_end = {0}; + uint64_t t_end; esp_timer_handle_t timer1; esp_timer_create_args_t args = { .callback = &timer_func, - .arg = (struct timeval*) &tv_end, + .arg = &t_end, .name = "timer1" }; TEST_ESP_OK(esp_timer_create(&args, &timer1)); @@ -81,21 +82,21 @@ TEST_CASE("esp_timer produces correct delay", "[esp_timer]") const int delays_ms[] = {20, 100, 200, 250}; const size_t delays_count = sizeof(delays_ms)/sizeof(delays_ms[0]); + ref_clock_init(); for (size_t i = 0; i < delays_count; ++i) { - tv_end = (struct timeval) {0}; - struct timeval tv_start; - gettimeofday(&tv_start, NULL); + t_end = 0; + uint64_t t_start = ref_clock_get(); TEST_ESP_OK(esp_timer_start_once(timer1, delays_ms[i] * 1000)); vTaskDelay(delays_ms[i] * 2 / portTICK_PERIOD_MS); - TEST_ASSERT(tv_end.tv_sec != 0 || tv_end.tv_usec != 0); - int32_t ms_diff = (tv_end.tv_sec - tv_start.tv_sec) * 1000 + - (tv_end.tv_usec - tv_start.tv_usec) / 1000; + TEST_ASSERT(t_end != 0); + int32_t ms_diff = (t_end - t_start) / 1000; printf("%d %d\n", delays_ms[i], ms_diff); TEST_ASSERT_INT32_WITHIN(portTICK_PERIOD_MS, delays_ms[i], ms_diff); } + ref_clock_deinit(); TEST_ESP_OK( esp_timer_dump(stdout) ); @@ -111,16 +112,14 @@ TEST_CASE("periodic ets_timer produces correct delays", "[esp_timer]") esp_timer_handle_t timer; size_t cur_interval; int intervals[NUM_INTERVALS]; - struct timeval tv_start; + uint64_t t_start; } test_args_t; void timer_func(void* arg) { test_args_t* p_args = (test_args_t*) arg; - struct timeval tv_now; - gettimeofday(&tv_now, NULL); - int32_t ms_diff = (tv_now.tv_sec - p_args->tv_start.tv_sec) * 1000 + - (tv_now.tv_usec - p_args->tv_start.tv_usec) / 1000; + uint64_t t_end = ref_clock_get(); + int32_t ms_diff = (t_end - p_args->t_start) / 1000; printf("timer #%d %dms\n", p_args->cur_interval, ms_diff); p_args->intervals[p_args->cur_interval++] = ms_diff; // Deliberately make timer handler run longer. @@ -141,9 +140,9 @@ TEST_CASE("periodic ets_timer produces correct delays", "[esp_timer]") .name = "timer1" }; TEST_ESP_OK(esp_timer_create(&create_args, &timer1)); - + ref_clock_init(); args.timer = timer1; - gettimeofday(&args.tv_start, NULL); + args.t_start = ref_clock_get(); TEST_ESP_OK(esp_timer_start_periodic(timer1, delay_ms * 1000)); vTaskDelay(delay_ms * (NUM_INTERVALS + 1)); @@ -152,7 +151,7 @@ TEST_CASE("periodic ets_timer produces correct delays", "[esp_timer]") for (size_t i = 0; i < NUM_INTERVALS; ++i) { TEST_ASSERT_INT32_WITHIN(portTICK_PERIOD_MS, (i + 1) * delay_ms, args.intervals[i]); } - + ref_clock_deinit(); TEST_ESP_OK( esp_timer_dump(stdout) ); TEST_ESP_OK( esp_timer_delete(timer1) ); @@ -176,7 +175,7 @@ TEST_CASE("multiple timers are ordered correctly", "[esp_timer]") test_common_t* common; bool pass; SemaphoreHandle_t done; - struct timeval* tv_start; + uint64_t t_start; } test_args_t; void timer_func(void* arg) @@ -185,10 +184,7 @@ TEST_CASE("multiple timers are ordered correctly", "[esp_timer]") // check order size_t count = p_args->common->count; int expected_index = p_args->common->order[count]; - struct timeval tv_timer; - gettimeofday(&tv_timer, NULL); - int ms_since_start = (tv_timer.tv_sec - p_args->tv_start->tv_sec) * 1000 + - (tv_timer.tv_usec - p_args->tv_start->tv_usec) / 1000; + int ms_since_start = (ref_clock_get() - p_args->t_start) / 1000; printf("Time %dms, at count %d, expected timer %d, got timer %d\n", ms_since_start, count, expected_index, p_args->timer_index); if (expected_index != p_args->timer_index) { @@ -217,8 +213,8 @@ TEST_CASE("multiple timers are ordered correctly", "[esp_timer]") SemaphoreHandle_t done = xSemaphoreCreateCounting(3, 0); - struct timeval tv_now; - gettimeofday(&tv_now, NULL); + ref_clock_init(); + uint64_t now = ref_clock_get(); test_args_t args1 = { .timer_index = 1, @@ -226,7 +222,7 @@ TEST_CASE("multiple timers are ordered correctly", "[esp_timer]") .common = &common, .pass = true, .done = done, - .tv_start = &tv_now + .t_start = now }; test_args_t args2 = { @@ -235,7 +231,7 @@ TEST_CASE("multiple timers are ordered correctly", "[esp_timer]") .common = &common, .pass = true, .done = done, - .tv_start = &tv_now + .t_start = now }; test_args_t args3 = { @@ -244,7 +240,7 @@ TEST_CASE("multiple timers are ordered correctly", "[esp_timer]") .common = &common, .pass = true, .done = done, - .tv_start = &tv_now + .t_start = now }; @@ -276,6 +272,8 @@ TEST_CASE("multiple timers are ordered correctly", "[esp_timer]") TEST_ASSERT_TRUE(args2.pass); TEST_ASSERT_TRUE(args3.pass); + ref_clock_deinit(); + TEST_ESP_OK( esp_timer_dump(stdout) ); TEST_ESP_OK( esp_timer_delete(args1.timer) ); @@ -337,27 +335,29 @@ TEST_CASE("esp_timer_get_time call takes less than 1us", "[esp_timer]") TEST_ASSERT(ns_per_call < 1000); } -/* This test runs for about 10 minutes and is disabled in CI */ +/* This test runs for about 10 minutes and is disabled in CI. + * Such run time is needed to have FRC2 timer overflow a few times. + */ TEST_CASE("esp_timer_get_time returns monotonic values", "[esp_timer][ignore]") { void timer_test_task(void* arg) { - uint64_t last = esp_timer_get_time(); + int64_t delta = esp_timer_get_time() - ref_clock_get(); const int iter_count = 1000000000; for (int i = 0; i < iter_count; ++i) { uint64_t now = esp_timer_get_time(); - if (now < last || now - last > 100) { - printf("core_id:%d now: %lld last:%lld\n", xPortGetCoreID(), now, last); - fflush(stdout); - abort(); - } - last = now; + uint64_t ref_now = ref_clock_get(); + int64_t diff = (int64_t) (now - ref_now) - delta; + /* Allow some difference due to rtos tick interrupting task between + * getting 'now' and 'ref_now'. + */ + TEST_ASSERT_INT32_WITHIN(100, 0, (int) diff); } xSemaphoreGive((SemaphoreHandle_t) arg); vTaskDelete(NULL); } - + ref_clock_init(); SemaphoreHandle_t done_1 = xSemaphoreCreateBinary(); SemaphoreHandle_t done_2 = xSemaphoreCreateBinary(); @@ -368,4 +368,5 @@ TEST_CASE("esp_timer_get_time returns monotonic values", "[esp_timer][ignore]") TEST_ASSERT_TRUE( xSemaphoreTake(done_2, portMAX_DELAY) ); vSemaphoreDelete(done_1); vSemaphoreDelete(done_2); + ref_clock_deinit(); } From 06af8cd0860f6ed0dff79452ed2b285b056bdd6b Mon Sep 17 00:00:00 2001 From: Ivan Grokhotkov Date: Wed, 30 Aug 2017 11:15:29 +0800 Subject: [PATCH 5/5] esp_timer: return signed timestamp (int64_t) Since timestamps are 64-bit, loosing one bit of range due to sign does not present an issue, however for applications doing calculations on timestamps, signed return type is more convenient. --- components/esp32/esp_timer.c | 4 ++-- components/esp32/esp_timer.h | 2 +- components/esp32/test/test_esp_timer.c | 24 ++++++++++++------------ 3 files changed, 15 insertions(+), 15 deletions(-) diff --git a/components/esp32/esp_timer.c b/components/esp32/esp_timer.c index 75374c0f4..f747446aa 100644 --- a/components/esp32/esp_timer.c +++ b/components/esp32/esp_timer.c @@ -443,7 +443,7 @@ esp_err_t esp_timer_dump(FILE* stream) return ESP_OK; } -uint64_t IRAM_ATTR esp_timer_get_time() +int64_t IRAM_ATTR esp_timer_get_time() { - return esp_timer_impl_get_time(); + return (int64_t) esp_timer_impl_get_time(); } diff --git a/components/esp32/esp_timer.h b/components/esp32/esp_timer.h index e187cacd5..f5ba21967 100644 --- a/components/esp32/esp_timer.h +++ b/components/esp32/esp_timer.h @@ -190,7 +190,7 @@ esp_err_t esp_timer_delete(esp_timer_handle_t timer); * @return number of microseconds since esp_timer_init was called (this normally * happens early during application startup). */ -uint64_t esp_timer_get_time(); +int64_t esp_timer_get_time(); /** * @brief Dump the list of timers to a stream diff --git a/components/esp32/test/test_esp_timer.c b/components/esp32/test/test_esp_timer.c index c2cee90e4..246aac9d8 100644 --- a/components/esp32/test/test_esp_timer.c +++ b/components/esp32/test/test_esp_timer.c @@ -66,11 +66,11 @@ TEST_CASE("esp_timer produces correct delay", "[esp_timer]") { void timer_func(void* arg) { - uint64_t* p_end = (uint64_t*) arg; + int64_t* p_end = (int64_t*) arg; *p_end = ref_clock_get(); } - uint64_t t_end; + int64_t t_end; esp_timer_handle_t timer1; esp_timer_create_args_t args = { .callback = &timer_func, @@ -85,7 +85,7 @@ TEST_CASE("esp_timer produces correct delay", "[esp_timer]") ref_clock_init(); for (size_t i = 0; i < delays_count; ++i) { t_end = 0; - uint64_t t_start = ref_clock_get(); + int64_t t_start = ref_clock_get(); TEST_ESP_OK(esp_timer_start_once(timer1, delays_ms[i] * 1000)); @@ -112,13 +112,13 @@ TEST_CASE("periodic ets_timer produces correct delays", "[esp_timer]") esp_timer_handle_t timer; size_t cur_interval; int intervals[NUM_INTERVALS]; - uint64_t t_start; + int64_t t_start; } test_args_t; void timer_func(void* arg) { test_args_t* p_args = (test_args_t*) arg; - uint64_t t_end = ref_clock_get(); + int64_t t_end = ref_clock_get(); int32_t ms_diff = (t_end - p_args->t_start) / 1000; printf("timer #%d %dms\n", p_args->cur_interval, ms_diff); p_args->intervals[p_args->cur_interval++] = ms_diff; @@ -175,7 +175,7 @@ TEST_CASE("multiple timers are ordered correctly", "[esp_timer]") test_common_t* common; bool pass; SemaphoreHandle_t done; - uint64_t t_start; + int64_t t_start; } test_args_t; void timer_func(void* arg) @@ -214,7 +214,7 @@ TEST_CASE("multiple timers are ordered correctly", "[esp_timer]") SemaphoreHandle_t done = xSemaphoreCreateCounting(3, 0); ref_clock_init(); - uint64_t now = ref_clock_get(); + int64_t now = ref_clock_get(); test_args_t args1 = { .timer_index = 1, @@ -324,8 +324,8 @@ TEST_CASE("esp_timer for very short intervals", "[esp_timer]") TEST_CASE("esp_timer_get_time call takes less than 1us", "[esp_timer]") { - uint64_t begin = esp_timer_get_time(); - volatile uint64_t end; + int64_t begin = esp_timer_get_time(); + volatile int64_t end; const int iter_count = 10000; for (int i = 0; i < iter_count; ++i) { end = esp_timer_get_time(); @@ -345,9 +345,9 @@ TEST_CASE("esp_timer_get_time returns monotonic values", "[esp_timer][ignore]") const int iter_count = 1000000000; for (int i = 0; i < iter_count; ++i) { - uint64_t now = esp_timer_get_time(); - uint64_t ref_now = ref_clock_get(); - int64_t diff = (int64_t) (now - ref_now) - delta; + int64_t now = esp_timer_get_time(); + int64_t ref_now = ref_clock_get(); + int64_t diff = now - (ref_now + delta); /* Allow some difference due to rtos tick interrupting task between * getting 'now' and 'ref_now'. */