tests/subsys/pm/power_mgmt_soc: fix various bugs

- Reduce "extra" added latency when trying to enter light
  sleep from 500ms to 50us, since light sleep states
  (e.g. "WFI idle") usually have microsecond-range residency
  times.
- Keep "extra" latency when entering deep sleep the same at
  1100ms (as we're trying to enter the deepest sleep state
  available, it doesn't hurt).
- Replace k_uptime_delta() with manual subtraction since
  k_uptime_delta() updates starting timestamp which leads to
  incorrect timing measurement when k_uptime_delta() is
  called for the second time.
- Measuring PM sleep entry latency using pm_notifier entry
  callback, do it only for the first PM entry event after
  calling k_usleep(), as during the sleep PM entry & exit
  may happen multiple times and that is normal.

Signed-off-by: Roman Dobrodii <rdobrodii@antmicro.com>
This commit is contained in:
Roman Dobrodii 2023-04-11 16:19:36 +02:00 committed by Carles Cufí
parent ddab8786fd
commit 2f0ce5a3e8

View file

@ -20,12 +20,17 @@ LOG_MODULE_REGISTER(pwrmgmt_test);
#define THREAD_A_SLEEP_TIME 100ul
#define THREAD_B_SLEEP_TIME 1000ul
/* Maximum latency should be less than 300 ms */
/* Maximum latency should be less than 500 ms */
#define MAX_EXPECTED_MS_LATENCY 500ul
/* Sleep some extra time than minimum residency */
#define DP_EXTRA_SLP_TIME 1100ul
#define LT_EXTRA_SLP_TIME 500ul
/* Sleep some extra time than minimum residency:
* - for light it should be very little so that we get only into light sleep
* and not accidentally into a deep sleep.
* - for deep sleep it can be very long as we want to ensure that we enter
* the deepest sleep state possible.
*/
#define LT_EXTRA_SLP_TIME_US 50ul
#define DP_EXTRA_SLP_TIME_US 1100000ul
#define SEC_TO_MSEC 1000ul
@ -43,6 +48,7 @@ struct pm_counter {
/* Track time elapsed */
static int64_t trigger_time;
static bool checks_enabled;
static bool measure_entry_latency;
/* Track entry/exit to sleep */
struct pm_counter pm_counters[PM_STATE_COUNT];
@ -56,14 +62,13 @@ static void pm_latency_check(void)
int secs;
int msecs;
latency = k_uptime_delta(&trigger_time);
latency = k_uptime_get() - trigger_time;
secs = (int)(latency / SEC_TO_MSEC);
msecs = (int)(latency % SEC_TO_MSEC);
zassert_false(secs > 0, "Sleep entry latency is too high");
zassert_false(msecs > MAX_EXPECTED_MS_LATENCY,
"Sleep entry latency is higher than expected");
zassert_false(secs > 0 || msecs > MAX_EXPECTED_MS_LATENCY,
"Sleep entry latency is too high: %d.%03d s.",
secs, msecs);
}
static void notify_pm_state_entry(enum pm_state state)
@ -73,7 +78,15 @@ static void notify_pm_state_entry(enum pm_state state)
}
pm_counters[(int)state].entry_cnt++;
pm_latency_check();
if (measure_entry_latency) {
pm_latency_check();
/* After first PM entry disable further checks since there can
* be multiple PM entry-exit events e.g. due to spurious
* wakeup
*/
measure_entry_latency = false;
}
}
static void notify_pm_state_exit(enum pm_state state)
@ -116,6 +129,7 @@ static void pm_reset_counters(void)
}
checks_enabled = false;
measure_entry_latency = false;
}
static void pm_trigger_marker(void)
@ -134,7 +148,7 @@ static void pm_exit_marker(void)
printk("PM <\n");
if (trigger_time > 0) {
residency_delta = k_uptime_delta(&trigger_time);
residency_delta = k_uptime_get() - trigger_time;
secs = (int)(residency_delta / SEC_TO_MSEC);
msecs = (int)(residency_delta % SEC_TO_MSEC);
LOG_INF("PM sleep residency %d.%03d seconds", secs, msecs);
@ -223,9 +237,10 @@ int test_pwr_mgmt_multithread(uint8_t cycles)
LOG_INF("Suspend...");
suspend_all_tasks();
LOG_INF("About to enter light sleep");
measure_entry_latency = true;
pm_trigger_marker();
k_msleep((residency_info[0].min_residency_us / 1000U) +
LT_EXTRA_SLP_TIME);
k_usleep(residency_info[0].min_residency_us +
LT_EXTRA_SLP_TIME_US);
LOG_INF("Wake from Light Sleep");
pm_exit_marker();
@ -240,10 +255,11 @@ int test_pwr_mgmt_multithread(uint8_t cycles)
suspend_all_tasks();
LOG_INF("About to enter deep sleep");
measure_entry_latency = true;
pm_trigger_marker();
k_msleep(
(residency_info[residency_info_len - 1].min_residency_us /
1000U) + DP_EXTRA_SLP_TIME);
k_usleep(
residency_info[residency_info_len - 1].min_residency_us +
DP_EXTRA_SLP_TIME_US);
LOG_INF("Wake from Deep Sleep");
pm_exit_marker();
@ -273,9 +289,10 @@ int test_pwr_mgmt_singlethread(uint8_t cycles)
/* Trigger Light Sleep 1 state. 48MHz PLL stays on */
LOG_INF("About to enter light sleep");
measure_entry_latency = true;
pm_trigger_marker();
k_msleep((residency_info[0].min_residency_us / 1000U) +
LT_EXTRA_SLP_TIME);
k_usleep(residency_info[0].min_residency_us +
LT_EXTRA_SLP_TIME_US);
LOG_INF("Wake from Light Sleep");
pm_exit_marker();
@ -284,11 +301,11 @@ int test_pwr_mgmt_singlethread(uint8_t cycles)
/* states in its residency policy will simply enter light */
/* sleep states instead */
LOG_INF("About to enter deep Sleep");
measure_entry_latency = true;
pm_trigger_marker();
k_msleep(
(residency_info[residency_info_len - 1].min_residency_us /
1000U) + DP_EXTRA_SLP_TIME);
k_usleep(
residency_info[residency_info_len - 1].min_residency_us +
DP_EXTRA_SLP_TIME_US);
LOG_INF("Wake from Deep Sleep");
pm_exit_marker();
}
@ -310,17 +327,19 @@ int test_dummy_init(void)
checks_enabled = true;
while (iterations-- > 0) {
LOG_INF("About to enter light sleep");
measure_entry_latency = true;
pm_trigger_marker();
k_msleep((residency_info[0].min_residency_us / 1000U) +
LT_EXTRA_SLP_TIME);
k_usleep(residency_info[0].min_residency_us +
LT_EXTRA_SLP_TIME_US);
LOG_INF("Wake from Light Sleep");
pm_exit_marker();
LOG_INF("About to enter deep Sleep");
measure_entry_latency = true;
pm_trigger_marker();
k_msleep(
(residency_info[residency_info_len - 1].min_residency_us /
1000U) + DP_EXTRA_SLP_TIME);
k_usleep(
residency_info[residency_info_len - 1].min_residency_us +
DP_EXTRA_SLP_TIME_US);
LOG_INF("Wake from Deep Sleep");
pm_exit_marker();
}