New issue
Advanced search Search tips
Note: Color blocks (like or ) mean that a user may not be available. Tooltip shows the reason.

Issue 914208 link

Starred by 1 user

Issue metadata

Status: Verified
Owner:
Closed: Dec 19
Cc:
Components:
EstimatedDays: ----
NextAction: ----
OS: Chrome
Pri: 2
Type: Bug



Sign in to add a comment

ec: taskinfo: "Time in exceptions" is unreasonable

Project Member Reported by drinkcat@chromium.org, Dec 12

Issue description

Let the EC run for >4300 seconds (I believe it affects most EC chips), and look at taskinfo (below on kukui):

> taskinfo
Task Ready Name         Events      Time (s)  StkUsed
   0 R << idle >>       00000000 2698.807373  144/256
   1 R HOOKS            00000000    2.591418  520/640
   2 R CHARGER          80000000   34.478960  504/640
   3   USB_CHG          00000000    0.000870  376/488
   4   CHIPSET          00000000    0.001839  376/640
   5   PDCMD            00000000    0.000009  120/640
   6   HOSTCMD          00000000    2.392066  576/640
   7 R CONSOLE          00000000    0.040129  348/640
   8   PD_C0            00000000    0.897627  608/768
   9   PD_INT_C0        00000000    0.022740  440/488
  10   EMMC             00000000    0.002223  288/640
IRQ counts by type:
   2       75
   5       26
   7    17395
  15   671785
  27      830
Service calls:               373426
Total exceptions:           1063537
Task switches:               744508
Task switching started:    0.000541 s
Time in tasks:          7048.810609 s
Time in exceptions:     4309.552610 s

Time in exceptions is unreasonable: it should probably be
4309.552610 - (2**32)/1000000 => 15.552610 s

This is probably due to core/cortex-m/task.c:svc_handler, that records time exc_start_time just before the interrupt handler the 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, the clksrc_high is updated, so there appear to be a 4294s gap between the 2 measurements.
 
Project Member

Comment 1 by bugdroid1@chromium.org, Dec 18

The following revision refers to this bug:
  https://chromium.googlesource.com/chromiumos/platform/ec/+/9f4852b7e9bbceb1fadb04eb68da43037f0b09d5

commit 9f4852b7e9bbceb1fadb04eb68da43037f0b09d5
Author: Nicolas Boichat <drinkcat@chromium.org>
Date: Tue Dec 18 12:28:56 2018

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

[modify] https://crrev.com/9f4852b7e9bbceb1fadb04eb68da43037f0b09d5/core/cortex-m/task.c
[modify] https://crrev.com/9f4852b7e9bbceb1fadb04eb68da43037f0b09d5/core/cortex-m0/task.c

Project Member

Comment 2 by bugdroid1@chromium.org, Dec 18

Labels: merge-merged-firmware-octopus-11297.B
The following revision refers to this bug:
  https://chromium.googlesource.com/chromiumos/platform/ec/+/e046ae9a1b7ed0f86d8a8eeab496c6e22a252ea1

commit e046ae9a1b7ed0f86d8a8eeab496c6e22a252ea1
Author: Nicolas Boichat <drinkcat@chromium.org>
Date: Tue Dec 18 21:27:48 2018

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
Reviewed-on: https://chromium-review.googlesource.com/c/1383319
Reviewed-by: Jett Rink <jettrink@chromium.org>
Commit-Queue: Jett Rink <jettrink@chromium.org>
Tested-by: Jett Rink <jettrink@chromium.org>
Trybot-Ready: Jett Rink <jettrink@chromium.org>

[modify] https://crrev.com/e046ae9a1b7ed0f86d8a8eeab496c6e22a252ea1/core/cortex-m/task.c
[modify] https://crrev.com/e046ae9a1b7ed0f86d8a8eeab496c6e22a252ea1/core/cortex-m0/task.c

Status: Verified (was: Started)

Sign in to add a comment