tests: kernel: critical: add output to support diagnostics

As implemented this test runs for 20 s with no output, which makes it
difficult to identify the cause of failure.  Add output indicating
progress, and emit diagnostics a particular failure observed on iMX
boards.

Signed-off-by: Peter Bigot <peter.bigot@nordicsemi.no>
This commit is contained in:
Peter Bigot 2019-11-11 14:14:46 -06:00 committed by Anas Nashif
commit e5af53a32f

View file

@ -78,19 +78,31 @@ void critical_rtn(struct k_work *unused)
* *
* @brief Common code for invoking offload work * @brief Common code for invoking offload work
* *
* @param tag text identifying the invocation context
*
* @param count number of critical section calls made thus far * @param count number of critical section calls made thus far
* *
* @return number of critical section calls made by a thread * @return number of critical section calls made by a thread
*/ */
u32_t critical_loop(u32_t count) u32_t critical_loop(const char *tag,
u32_t count)
{ {
s64_t now;
s64_t last;
s64_t mseconds; s64_t mseconds;
mseconds = k_uptime_get(); last = mseconds = k_uptime_get();
while (k_uptime_get() < mseconds + NUM_MILLISECONDS) { TC_PRINT("Start %s at %u\n", tag, (u32_t)last);
while (((now = k_uptime_get())) < mseconds + NUM_MILLISECONDS) {
struct k_work work_item; struct k_work work_item;
if (now < last) {
TC_PRINT("Time went backwards: %u < %u\n",
(u32_t)now, (u32_t)last);
}
last = now;
k_work_init(&work_item, critical_rtn); k_work_init(&work_item, critical_rtn);
k_work_submit_to_queue(&offload_work_q, &work_item); k_work_submit_to_queue(&offload_work_q, &work_item);
count++; count++;
@ -103,6 +115,7 @@ u32_t critical_loop(u32_t count)
*/ */
#endif #endif
} }
TC_PRINT("End %s at %u\n", tag, (u32_t)now);
return count; return count;
} }
@ -124,13 +137,13 @@ void alternate_thread(void *arg1, void *arg2, void *arg3)
k_sem_take(&ALT_SEM, K_FOREVER); /* Wait to be activated */ k_sem_take(&ALT_SEM, K_FOREVER); /* Wait to be activated */
alt_thread_iterations = critical_loop(alt_thread_iterations); alt_thread_iterations = critical_loop("alt1", alt_thread_iterations);
k_sem_give(&REGRESS_SEM); k_sem_give(&REGRESS_SEM);
k_sem_take(&ALT_SEM, K_FOREVER); /* Wait to be re-activated */ k_sem_take(&ALT_SEM, K_FOREVER); /* Wait to be re-activated */
alt_thread_iterations = critical_loop(alt_thread_iterations); alt_thread_iterations = critical_loop("alt2", alt_thread_iterations);
k_sem_give(&REGRESS_SEM); k_sem_give(&REGRESS_SEM);
} }
@ -156,7 +169,7 @@ void regression_thread(void *arg1, void *arg2, void *arg3)
k_sem_give(&ALT_SEM); /* Activate alternate_thread() */ k_sem_give(&ALT_SEM); /* Activate alternate_thread() */
ncalls = critical_loop(ncalls); ncalls = critical_loop("reg1", ncalls);
/* Wait for alternate_thread() to complete */ /* Wait for alternate_thread() to complete */
zassert_true(k_sem_take(&REGRESS_SEM, TEST_TIMEOUT) == 0, zassert_true(k_sem_take(&REGRESS_SEM, TEST_TIMEOUT) == 0,
@ -165,11 +178,12 @@ void regression_thread(void *arg1, void *arg2, void *arg3)
zassert_equal(critical_var, ncalls + alt_thread_iterations, zassert_equal(critical_var, ncalls + alt_thread_iterations,
"Unexpected value for <critical_var>"); "Unexpected value for <critical_var>");
TC_PRINT("Enable timeslicing at %u\n", k_uptime_get_32());
k_sched_time_slice_set(10, 10); k_sched_time_slice_set(10, 10);
k_sem_give(&ALT_SEM); /* Re-activate alternate_thread() */ k_sem_give(&ALT_SEM); /* Re-activate alternate_thread() */
ncalls = critical_loop(ncalls); ncalls = critical_loop("reg2", ncalls);
/* Wait for alternate_thread() to finish */ /* Wait for alternate_thread() to finish */
zassert_true(k_sem_take(&REGRESS_SEM, TEST_TIMEOUT) == 0, zassert_true(k_sem_take(&REGRESS_SEM, TEST_TIMEOUT) == 0,