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 <[email protected]>

Author: pabigot

tests/kernel/critical/src/main.c

@@ -78,19 +78,31 @@ void critical_rtn(struct k_work *unused)
  *
  * @brief Common code for invoking offload work
  *
+ * @param tag text identifying the invocation context
+ *
  * @param count number of critical section calls made thus far
  *
  * @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;
 
-	mseconds = k_uptime_get();
-	while (k_uptime_get() < mseconds + NUM_MILLISECONDS) {
+	last = mseconds = k_uptime_get();
+	TC_PRINT("Start %s at %u\n", tag, (u32_t)last);
+	while (((now = k_uptime_get())) < mseconds + NUM_MILLISECONDS) {
 		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_submit_to_queue(&offload_work_q, &work_item);
 		count++;
@@ -103,6 +115,7 @@ u32_t critical_loop(u32_t count)
 		 */
 #endif
 	}
+	TC_PRINT("End %s at %u\n", tag, (u32_t)now);
 
 	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 */
 
-	alt_thread_iterations = critical_loop(alt_thread_iterations);
+	alt_thread_iterations = critical_loop("alt1", alt_thread_iterations);
 
 	k_sem_give(&REGRESS_SEM);
 
 	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);
 }
@@ -156,7 +169,7 @@ void regression_thread(void *arg1, void *arg2, void *arg3)
 
 	k_sem_give(&ALT_SEM);   /* Activate alternate_thread() */
 
-	ncalls = critical_loop(ncalls);
+	ncalls = critical_loop("reg1", ncalls);
 
 	/* Wait for alternate_thread() to complete */
 	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,
 		      "Unexpected value for <critical_var>");
 
+	TC_PRINT("Enable timeslicing at %u\n", k_uptime_get_32());
 	k_sched_time_slice_set(10, 10);
 
 	k_sem_give(&ALT_SEM);   /* Re-activate alternate_thread() */
 
-	ncalls = critical_loop(ncalls);
+	ncalls = critical_loop("reg2", ncalls);
 
 	/* Wait for alternate_thread() to finish */
 	zassert_true(k_sem_take(&REGRESS_SEM, TEST_TIMEOUT) == 0,