core/cortex-m*/task: Record 32-bit exception times

"time in exceptions" looks unreasonable after > 4294s (when 32-bit
microsecond timer wraps around).

This is because core/cortex-m/task.c:svc_handler records time
exc_start_time just before the interrupt handler for 32-bit
timer interrupt runs, so the high word of the system clock
(clksrc_high) is not updated yet (while the low 32-bits already
wrapped around). After the handler runs, clksrc_high is updated,
so there appear to be a 4294s gap between the 2 measurements.

Fix this by recording the low 32-bit timer value only. There will
never be more than 4294s between exceptions, and this fixes the
wrap-around issue as well.

BRANCH=none
BUG=chromium:914208
TEST=Flash kukui (cortex-m0) and kukui_scp (cortex-m), let system
     run for 4300+s, no more accounting error in "Time in exceptions".

Change-Id: If52855ef093ac1a1d38432555694c83742feb8f1
Signed-off-by: Nicolas Boichat <drinkcat@chromium.org>
Reviewed-on: https://chromium-review.googlesource.com/1372876

2 files changed, 29 insertions, 15 deletions

diff --git a/core/cortex-m/task.c b/core/cortex-m/task.c
index 4d47041e8a..b7aa30c955 100644
--- a/core/cortex-m/task.c
+++ b/core/cortex-m/task.c
@@ -51,8 +51,12 @@ static const char * const task_names[] = {
 
 #ifdef CONFIG_TASK_PROFILING
 static uint64_t task_start_time; /* Time task scheduling started */
-static uint64_t exc_start_time;  /* Time of task->exception transition */
-static uint64_t exc_end_time;    /* Time of exception->task transition */
+/*
+ * We only keep 32-bit values for exception start/end time, to avoid
+ * accounting errors when we service interrupt when the timer wraps around.
+ */
+static uint32_t exc_start_time;  /* Time of task->exception transition */
+static uint32_t exc_end_time;    /* Time of exception->task transition */
 static uint64_t exc_total_time;  /* Total time in exceptions */
 static uint32_t svc_calls;       /* Number of service calls */
 static uint32_t task_switches;   /* Number of times active task changed */
@@ -245,7 +249,7 @@ void svc_handler(int desched, task_id_t resched)
 	task_ *current, *next;
 #ifdef CONFIG_TASK_PROFILING
 	int exc = get_interrupt_context();
-	uint64_t t;
+	uint32_t t;
 #endif
 
 	/*
@@ -261,7 +265,7 @@ void svc_handler(int desched, task_id_t resched)
 	 * start time explicitly.
 	 */
 	if (exc == 0xb) {
-		exc_start_time = get_time().val;
+		exc_start_time = get_time().le.lo;
 		svc_calls++;
 	}
 #endif
@@ -293,7 +297,7 @@ void svc_handler(int desched, task_id_t resched)
 
 #ifdef CONFIG_TASK_PROFILING
 	/* Track time in interrupts */
-	t = get_time().val;
+	t = get_time().le.lo;
 	exc_total_time += (t - exc_start_time);
 
 	/*
@@ -337,7 +341,7 @@ void __keep task_start_irq_handler(void *excep_return)
 	 * Get time before checking depth, in case this handler is
 	 * pre-empted.
 	 */
-	uint64_t t = get_time().val;
+	uint32_t t = get_time().le.lo;
 	int irq = get_interrupt_context() - 16;
 
 	/*
@@ -715,7 +719,10 @@ void task_clear_fp_used(void)
 int task_start(void)
 {
 #ifdef CONFIG_TASK_PROFILING
-	task_start_time = exc_end_time = get_time().val;
+	timestamp_t t = get_time();
+
+	task_start_time = t.val;
+	exc_end_time = t.le.lo;
 #endif
 	start_called = 1;
 
diff --git a/core/cortex-m0/task.c b/core/cortex-m0/task.c
index d70dff1d59..32dabcaf19 100644
--- a/core/cortex-m0/task.c
+++ b/core/cortex-m0/task.c
@@ -51,8 +51,12 @@ static const char * const task_names[] = {
 
 #ifdef CONFIG_TASK_PROFILING
 static uint64_t task_start_time; /* Time task scheduling started */
-static uint64_t exc_start_time;  /* Time of task->exception transition */
-static uint64_t exc_end_time;    /* Time of exception->task transition */
+/*
+ * We only keep 32-bit values for exception start/end time, to avoid
+ * accounting errors when we service interrupt when the timer wraps around.
+ */
+static uint32_t exc_start_time;  /* Time of task->exception transition */
+static uint32_t exc_end_time;    /* Time of exception->task transition */
 static uint64_t exc_total_time;  /* Total time in exceptions */
 static uint32_t svc_calls;       /* Number of service calls */
 static uint32_t task_switches;   /* Number of times active task changed */
@@ -200,7 +204,7 @@ task_  __attribute__((noinline)) *__svc_handler(int desched, task_id_t resched)
 	task_ *current, *next;
 #ifdef CONFIG_TASK_PROFILING
 	int exc = get_interrupt_context();
-	uint64_t t;
+	uint32_t t;
 #endif
 
 	/* Priority is already at 0 we cannot be interrupted */
@@ -211,7 +215,7 @@ task_  __attribute__((noinline)) *__svc_handler(int desched, task_id_t resched)
 	 * start time explicitly.
 	 */
 	if (exc == 0xb) {
-		t = get_time().val;
+		t = get_time().le.lo;
 		current_task->runtime += (t - exc_end_time);
 		exc_end_time = t;
 		svc_calls++;
@@ -244,7 +248,7 @@ task_  __attribute__((noinline)) *__svc_handler(int desched, task_id_t resched)
 
 #ifdef CONFIG_TASK_PROFILING
 	/* Track additional time in re-sched exception context */
-	t = get_time().val;
+	t = get_time().le.lo;
 	exc_total_time += (t - exc_end_time);
 
 	exc_end_time = t;
@@ -274,7 +278,7 @@ void task_start_irq_handler(void *excep_return)
 	 * Get time before checking depth, in case this handler is
 	 * pre-empted.
 	 */
-	uint64_t t = get_time().val;
+	uint32_t t = get_time().le.lo;
 	int irq = get_interrupt_context() - 16;
 
 	/*
@@ -301,7 +305,7 @@ void task_start_irq_handler(void *excep_return)
 
 void task_end_irq_handler(void *excep_return)
 {
-	uint64_t t = get_time().val;
+	uint32_t t = get_time().le.lo;
 	/*
 	 * Continue iff the tasks are ready and we are not called from another
 	 * exception (as the time accouting is done in the outer irq).
@@ -657,7 +661,10 @@ void task_pre_init(void)
 int task_start(void)
 {
 #ifdef CONFIG_TASK_PROFILING
-	task_start_time = exc_end_time = get_time().val;
+	timestamp_t t = get_time();
+
+	task_start_time = t.val;
+	exc_end_time = t.le.lo;
 #endif
 
 	return __task_start(&start_called);