From dd6779185715bbdf4cee340b3c03227f9539fc46 Mon Sep 17 00:00:00 2001 From: Dmitrii Golovanov Date: Fri, 31 May 2024 13:53:28 +0200 Subject: [PATCH] tests: kernel: timer_behavior: Additional stats recording Additional logging of kernel.timer.timer test case statistics for timer drift, variance, etc. as JSON-formatted records to make easier data collection and its further analysis. These log records will be processed by the Twister Harness recording feature which captures and parses timer statistics from the log output, then composes it into twister.json and recording.csv files. Signed-off-by: Dmitrii Golovanov --- .../timer/timer_behavior/src/jitter_drift.c | 51 +++++++++++++++++-- .../timer_behavior/src/tick_timer_train.c | 17 +++++++ .../kernel/timer/timer_behavior/testcase.yaml | 4 ++ 3 files changed, 69 insertions(+), 3 deletions(-) diff --git a/tests/kernel/timer/timer_behavior/src/jitter_drift.c b/tests/kernel/timer/timer_behavior/src/jitter_drift.c index d78adb40eaf..28ea47a790e 100644 --- a/tests/kernel/timer/timer_behavior/src/jitter_drift.c +++ b/tests/kernel/timer/timer_behavior/src/jitter_drift.c @@ -126,7 +126,7 @@ static double cycles_to_us(uint64_t cycles) /** * @brief Test a timers jitter and drift over time */ -static void do_test_using(void (*sample_collection_fn)(void)) +static void do_test_using(void (*sample_collection_fn)(void), const char *mechanism) { k_timeout_t actual_timeout = K_USEC(CONFIG_TIMER_TEST_PERIOD); uint64_t expected_duration = (uint64_t)actual_timeout.ticks * CONFIG_TIMER_TEST_SAMPLES; @@ -262,6 +262,51 @@ static void do_test_using(void (*sample_collection_fn)(void)) periodic_start, periodic_end, actual_time_us, expected_time_us, expected_time_drift_us, time_diff_us); + /* Record the stats gathered as a JSON object including related CONFIG_* params. */ + TC_PRINT("RECORD: {" + "\"testcase\":\"jitter_drift_timer\", \"mechanism\":\"%s\"" + ", \"stats_count\":%d, \"rollovers\":%d" + ", \"mean_us\":%.6f, \"mean_cycles\":%.0f" + ", \"stddev_us\":%.6f, \"stddev_cycles\":%.0f" + ", \"var_us\":%.6f, \"var_cycles\":%.0f" + ", \"min_us\":%.6f, \"min_cycles\":%llu" + ", \"max_us\":%.6f, \"max_cycles\":%llu" + ", \"timer_start_cycle\": %llu, \"timer_end_cycle\": %llu" + ", \"total_time_us\":%.6f" + ", \"expected_total_time_us\":%.6f" + ", \"expected_total_drift_us\":%.6f" + ", \"total_drift_us\":%.6f" + ", \"expected_period_cycles\":%.0f" + ", \"expected_period_drift_us\":%.6f" + ", \"sys_clock_hw_cycles_per_sec\":%d" + ", \"CONFIG_SYS_CLOCK_HW_CYCLES_PER_SEC\":%d" + ", \"CONFIG_SYS_CLOCK_TICKS_PER_SEC\":%d" + ", \"CONFIG_TIMER_TEST_PERIOD\":%d" + ", \"CONFIG_TIMER_TEST_SAMPLES\":%d" + ", \"CONFIG_TIMER_TEST_MAX_STDDEV\":%d" + "}\n", + mechanism, + CONFIG_TIMER_TEST_SAMPLES - periodic_rollovers, periodic_rollovers, + mean_us, mean_cyc, + stddev_us, stddev_cyc, + variance_us, variance_cyc, + min_us, min_cyc, + max_us, max_cyc, + periodic_start, periodic_end, + actual_time_us, + expected_time_us, + expected_time_drift_us, + time_diff_us, + expected_period, + expected_period_drift, + sys_clock_hw_cycles_per_sec(), + CONFIG_SYS_CLOCK_HW_CYCLES_PER_SEC, + CONFIG_SYS_CLOCK_TICKS_PER_SEC, + CONFIG_TIMER_TEST_PERIOD, + CONFIG_TIMER_TEST_SAMPLES, + CONFIG_TIMER_TEST_MAX_STDDEV + ); + /* Validate the maximum/minimum timer period is off by no more than 10% */ double test_period = (double)CONFIG_TIMER_TEST_PERIOD; double period_max_drift_percentage = @@ -300,7 +345,7 @@ ZTEST(timer_jitter_drift, test_jitter_drift_timer_period) k_sleep(K_SECONDS(CONFIG_TIMER_EXTERNAL_TEST_SYNC_DELAY)); gpio_pin_configure_dt(&timer_out, GPIO_OUTPUT_LOW); #endif - do_test_using(collect_timer_period_time_samples); + do_test_using(collect_timer_period_time_samples, "builtin"); } ZTEST(timer_jitter_drift, test_jitter_drift_timer_startdelay) @@ -314,7 +359,7 @@ ZTEST(timer_jitter_drift, test_jitter_drift_timer_startdelay) k_sleep(K_SECONDS(CONFIG_TIMER_EXTERNAL_TEST_SYNC_DELAY)); gpio_pin_configure_dt(&timer_out, GPIO_OUTPUT_LOW); #endif - do_test_using(collect_timer_startdelay_time_samples); + do_test_using(collect_timer_startdelay_time_samples, "startdelay"); } ZTEST_SUITE(timer_jitter_drift, NULL, NULL, NULL, NULL, NULL); diff --git a/tests/kernel/timer/timer_behavior/src/tick_timer_train.c b/tests/kernel/timer/timer_behavior/src/tick_timer_train.c index e4532b3f13b..a1daabb132e 100644 --- a/tests/kernel/timer/timer_behavior/src/tick_timer_train.c +++ b/tests/kernel/timer/timer_behavior/src/tick_timer_train.c @@ -136,6 +136,23 @@ ZTEST(timer_tick_train, test_one_tick_timer_train) timers[i].late_callbacks, (1000 * timers[i].late_callbacks + MAX_CALLBACKS/2) / MAX_CALLBACKS / 10, (1000 * timers[i].late_callbacks + MAX_CALLBACKS/2) / MAX_CALLBACKS % 10); + /* Record the stats gathered as a JSON object including related CONFIG_* params. */ + TC_PRINT("RECORD: {" + "\"testcase\":\"one_tick_timer_train\"" + ", \"timer\":%d, \"max_delta_cycles\":%u, \"max_delta_us\":%u" + ", \"late_callbacks\":%u" + ", \"perfect_delta_cycles\":%u, \"perfect_delta_us\":%u" + ", \"train_time_ms\":%u, \"busy_loops\":%u" + ", \"timers\":%u, \"expected_callbacks\":%u, \"expected_time_ms\":%u" + ", \"CONFIG_SYS_CLOCK_TICKS_PER_SEC\":%u" + "}\n", + i, timers[i].max_delta, k_cyc_to_us_near32(timers[i].max_delta), + timers[i].late_callbacks, + k_ticks_to_cyc_floor32(TIMERS), k_ticks_to_us_near32(TIMERS), + delta_time, busy_loops, + TIMERS, MAX_CALLBACKS, max_time, + CONFIG_SYS_CLOCK_TICKS_PER_SEC + ); max_delta = timers[i].max_delta > max_delta ? timers[i].max_delta : max_delta; k_timer_stop(&timers[i].tm); } diff --git a/tests/kernel/timer/timer_behavior/testcase.yaml b/tests/kernel/timer/timer_behavior/testcase.yaml index 11ac75e5597..b1417dce985 100644 --- a/tests/kernel/timer/timer_behavior/testcase.yaml +++ b/tests/kernel/timer/timer_behavior/testcase.yaml @@ -8,6 +8,10 @@ tests: - mcu simulation_exclude: - renode + harness_config: + record: + regex: "RECORD:(?P.*)" + as_json: ['metrics'] kernel.timer.timer_behavior_external: filter: dt_compat_enabled("test-kernel-timer-behavior-external") harness: pytest