diff options
author | Vic Yang <victoryang@chromium.org> | 2013-09-18 10:57:13 +0800 |
---|---|---|
committer | chrome-internal-fetch <chrome-internal-fetch@google.com> | 2013-09-23 06:10:32 +0000 |
commit | a4f3a72cf86ec99a765b3bf787aaf5b515e44030 (patch) | |
tree | c06e195aa92dc7e370432d1f20a0b5ee6699b1f8 | |
parent | f27c00768489ae6b81a1366116744fec7f849ba8 (diff) | |
download | chrome-ec-a4f3a72cf86ec99a765b3bf787aaf5b515e44030.tar.gz |
Record average runtime and delay of hooks
In additional to recording the maximum runtime and delay, let's also
keep track of the moving average. The average is calculated by:
New_Avg = (Old_Avg * 7 + New_Val) / 8
every time the hook fires.
The average values are only accurate for hooks that fire enough times,
but it won't be useful anyway for a hook that only fires just once or
twice.
Also, show warning if HOOK_TICK or HOOK_SECOND fires more than 10% late.
BUG=chrome-os-partner:21801
TEST=On Kirby, check average values are sane.
TEST='waitms 800' and see warning of HOOK_TICK firing late.
BRANCH=None
Change-Id: I453545830d854c6c5bfc795d01fc558a965cff6e
Signed-off-by: Vic Yang <victoryang@chromium.org>
Reviewed-on: https://chromium-review.googlesource.com/169704
Reviewed-by: Randall Spangler <rspangler@chromium.org>
-rw-r--r-- | common/hooks.c | 55 |
1 files changed, 43 insertions, 12 deletions
diff --git a/common/hooks.c b/common/hooks.c index 8de8ccd9e1..492ccd98b4 100644 --- a/common/hooks.c +++ b/common/hooks.c @@ -58,6 +58,33 @@ static int defer_new_call; static uint64_t max_hook_tick_delay; static uint64_t max_hook_second_delay; static uint64_t max_hook_run_time[ARRAY_SIZE(hook_list)]; + +static uint64_t avg_hook_tick_delay; +static uint64_t avg_hook_second_delay; +static uint64_t avg_hook_run_time[ARRAY_SIZE(hook_list)]; + +static inline void update_hook_average(uint64_t *avg, uint64_t time) +{ + *avg = (*avg * 7 + time) >> 3; +} + +static void record_hook_delay(uint64_t now, uint64_t last, uint64_t interval, + uint64_t *max_delay, uint64_t *avg_delay) +{ + uint64_t delayed = now - last - interval; + /* Ignore the first call */ + if (last == -interval) + return; + + if (delayed > *max_delay) + *max_delay = delayed; + update_hook_average(avg_delay, delayed); + + /* Warn if delayed by more than 10% */ + if (delayed * 10 > interval) + CPRINTF("Hook at interval %d us delayed by %d us\n", + (uint32_t)interval, (uint32_t)delayed); +} #endif void hook_notify(enum hook_type type) @@ -98,6 +125,7 @@ void hook_notify(enum hook_type type) run_time = get_time().val - start_time; if (run_time > max_hook_run_time[type]) max_hook_run_time[type] = run_time; + update_hook_average(avg_hook_run_time + type, run_time); #endif } @@ -167,10 +195,9 @@ void hook_task(void) if (t - last_tick >= HOOK_TICK_INTERVAL) { #ifdef CONFIG_HOOK_DEBUG - uint64_t delayed = t - last_tick - HOOK_TICK_INTERVAL; - if (last_tick != -HOOK_TICK_INTERVAL && - delayed > max_hook_tick_delay) - max_hook_tick_delay = delayed; + record_hook_delay(t, last_tick, HOOK_TICK_INTERVAL, + &max_hook_tick_delay, + &avg_hook_tick_delay); #endif hook_notify(HOOK_TICK); last_tick = t; @@ -178,10 +205,9 @@ void hook_task(void) if (t - last_second >= SECOND) { #ifdef CONFIG_HOOK_DEBUG - uint64_t delayed = t - last_second - SECOND; - if (last_second != -SECOND && - delayed > max_hook_second_delay) - max_hook_second_delay = delayed; + record_hook_delay(t, last_second, SECOND, + &max_hook_second_delay, + &avg_hook_second_delay); #endif hook_notify(HOOK_SECOND); last_second = t; @@ -218,12 +244,14 @@ void hook_task(void) /* Console commands */ #ifdef CONFIG_HOOK_DEBUG -static void print_hook_delay(uint32_t interval, uint32_t delay) +static void print_hook_delay(uint32_t interval, uint32_t delay, uint32_t avg) { int percentage = delay * 100 / interval; + int percent_avg = avg * 100 / interval; ccprintf(" Interval: %7d us\n", interval); ccprintf(" Max delayed: %7d us (%d%%)\n\n", delay, percentage); + ccprintf(" Average: %7d us (%d%%)\n\n", avg, percent_avg); } static int command_stats(int argc, char **argv) @@ -231,14 +259,17 @@ static int command_stats(int argc, char **argv) int i; ccprintf("HOOK_TICK:\n"); - print_hook_delay(HOOK_TICK_INTERVAL, max_hook_tick_delay); + print_hook_delay(HOOK_TICK_INTERVAL, max_hook_tick_delay, + avg_hook_tick_delay); ccprintf("HOOK_SECOND:\n"); - print_hook_delay(SECOND, max_hook_second_delay); + print_hook_delay(SECOND, max_hook_second_delay, avg_hook_second_delay); ccprintf("Max run time for each hook:\n"); for (i = 0; i < ARRAY_SIZE(hook_list); ++i) - ccprintf("%3d:%6d us\n", i, (uint32_t)max_hook_run_time[i]); + ccprintf("%3d:%6d us (Avg: %5d us)\n", i, + (uint32_t)max_hook_run_time[i], + (uint32_t)avg_hook_run_time[i]); return EC_SUCCESS; } |