From 9f4852b7e9bbceb1fadb04eb68da43037f0b09d5 Mon Sep 17 00:00:00 2001 From: Nicolas Boichat Date: Wed, 12 Dec 2018 11:30:51 +0800 Subject: 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 Reviewed-on: https://chromium-review.googlesource.com/1372876 --- core/cortex-m/task.c | 21 ++++++++++++++------- core/cortex-m0/task.c | 23 +++++++++++++++-------- 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); -- cgit v1.2.1