bartoszek/zephyr
1
0
Fork 0
Code Issues Pull Requests Packages Projects Releases Wiki Activity

tests: kernel: timer_behavior: Additional stats recording

Browse Source 
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 <dmitrii.golovanov@intel.com>
This commit is contained in:
Dmitrii Golovanov 2024-05-31 13:53:28 +02:00 committed by Anas Nashif
parent 35e313f9e5
commit dd67791857
3 changed files with 69 additions and 3 deletions
Show Stats Download Patch File Download Diff File Expand all files Collapse all files

51
tests/kernel/timer/timer_behavior/src/jitter_drift.c
View File

@ -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);

17
tests/kernel/timer/timer_behavior/src/tick_timer_train.c
View File

@ -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);
}

4
tests/kernel/timer/timer_behavior/testcase.yaml
View File

@ -8,6 +8,10 @@ tests:
- mcu
simulation_exclude:
- renode
harness_config:
record:
regex: "RECORD:(?P<metrics>.*)"
as_json: ['metrics']
kernel.timer.timer_behavior_external:
filter: dt_compat_enabled("test-kernel-timer-behavior-external")
harness: pytest