Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

mec15xxevb_assy6853:running samples/boards/mec15xxevb_assy6853/power_management Sleep entry latency is higher than expected #29330

Closed
maksimmasalski opened this issue Oct 19, 2020 · 16 comments
Closed

mec15xxevb_assy6853:running samples/boards/mec15xxevb_assy6853/power_management Sleep entry latency is higher than expected #29330

maksimmasalski opened this issue Oct 19, 2020 · 16 comments
Assignees
@ceolin
Labels
bug The issue is a bug, or the PR is fixing a bug priority: low Low impact/importance bug

Comments

@maksimmasalski
Copy link
Collaborator

maksimmasalski commented Oct 19, 2020 •
edited
Loading

Describe the bug
Running samples/boards/mec15xxevb_assy6853/power_management failed. Sleep entry latency is higher than expected

To Reproduce
Steps to reproduce the behavior:

  1. sanitycheck --hardware-map ~/mec1.file --device-testing -T samples/boards/mec15xxevb_assy6853/power_management -vv
  2. See the output

Expected behavior
Sleep entry latency shouldn't be higher than expected. Test suite must not fail due to timeout in sanitycheck, caused by its forever loop. Seems, like that sample was not designed to be run in sanitycheck. When I run that sample in west, it can't come to the end.

Impact
Can't use sample in sanitycheck

Logs and console output

DEBUG   - DEVICE: *** Booting Zephyr OS build zephyr-v2.4.0-689-g84158f54b902  ***
DEBUG   - DEVICE: [00:00:00.005,615] <wrn> pwrmgmt_test: PM single-thread test started for cycles: 5, logging: 0
DEBUG   - DEVICE: [00:00:00.005,645] <inf> pwrmgmt_test: About to enter light sleep
DEBUG   - DEVICE: Wake from Light Sleep
DEBUG   - DEVICE: PM >
DEBUG   - DEVICE: [00:00:01.507,629] <inf> pwrmgmt_test: About to enter deep Sleep
DEBUG   - DEVICE: [00:00:01.508,178] <inf> pwrmgmt_test: PM sleep entry latency 0.001 seconds
DEBUG   - DEVICE: Wake from Deep Sleep
DEBUG   - DEVICE: PM <
DEBUG   - DEVICE: Wake from Light Sleep
DEBUG   - DEVICE: PM >
DEBUG   - DEVICE: [00:00:04.610,565] <inf> pwrmgmt_test: PM sleep residency 3.102 seconds
DEBUG   - DEVICE: [00:00:04.610,595] <inf> pwrmgmt_test: About to enter light sleep
DEBUG   - DEVICE: [00:00:06.112,579] <inf> pwrmgmt_test: About to enter deep Sleep
DEBUG   - DEVICE: [00:00:06.730,407] <inf> pwrmgmt_test: PM sleep entry latency 0.618 seconds
DEBUG   - DEVICE: [00:00:06.730,407] <wrn> pwrmgmt_test: Sleep entry latency is higher than expected
DEBUG   - DEVICE: Wake from Deep Sleep
DEBUG   - DEVICE: PM <
DEBUG   - DEVICE: Wake from Light Sleep
DEBUG   - DEVICE: PM >
DEBUG   - DEVICE: [00:00:09.215,515] <inf> pwrmgmt_test: PM sleep residency 2.485 seconds
DEBUG   - DEVICE: [00:00:09.215,515] <inf> pwrmgmt_test: About to enter light sleep
DEBUG   - DEVICE: [00:00:10.717,529] <inf> pwrmgmt_test: About to enter deep Sleep
DEBUG   - DEVICE: [00:00:11.335,357] <inf> pwrmgmt_test: PM sleep entry latency 0.618 seconds
DEBUG   - DEVICE: [00:00:11.335,357] <wrn> pwrmgmt_test: Sleep entry latency is higher than expected
DEBUG   - DEVICE: Wake from Deep Sleep
DEBUG   - DEVICE: PM <
DEBUG   - DEVICE: Wake from Light Sleep
DEBUG   - DEVICE: PM >
DEBUG   - DEVICE: [00:00:13.820,465] <inf> pwrmgmt_test: PM sleep residency 2.485 seconds
DEBUG   - DEVICE: [00:00:13.820,465] <inf> pwrmgmt_test: About to enter light sleep
DEBUG   - DEVICE: [00:00:15.322,479] <inf> pwrmgmt_test: About to enter deep Sleep
DEBUG   - DEVICE: [00:00:15.940,307] <inf> pwrmgmt_test: PM sleep entry latency 0.618 seconds
DEBUG   - DEVICE: [00:00:15.940,307] <wrn> pwrmgmt_test: Sleep entry latency is higher than expected
DEBUG   - DEVICE: Wake from Deep Sleep
DEBUG   - DEVICE: PM <
DEBUG   - DEVICE: Wake from Light Sleep
DEBUG   - DEVICE: PM >
DEBUG   - DEVICE: [00:00:18.425,415] <inf> pwrmgmt_test: PM sleep residency 2.485 seconds
DEBUG   - DEVICE: [00:00:18.425,415] <inf> pwrmgmt_test: About to enter light sleep
DEBUG   - DEVICE: [00:00:19.927,429] <inf> pwrmgmt_test: About to enter deep Sleep
DEBUG   - DEVICE: [00:00:20.545,257] <inf> pwrmgmt_test: PM sleep entry latency 0.618 seconds
DEBUG   - DEVICE: [00:00:20.545,257] <wrn> pwrmgmt_test: Sleep entry latency is higher than expected
DEBUG   - DEVICE: Wake from Deep Sleep
DEBUG   - DEVICE: PM <
DEBUG   - DEVICE: PM >
DEBUG   - DEVICE: [00:00:23.030,364] <inf> pwrmgmt_test: PM sleep residency 2.485 seconds
DEBUG   - DEVICE: [00:00:23.030,395] <inf> pwrmgmt_test: PM single-thread completed
DEBUG   - DEVICE: [00:00:23.030,395] <inf> pwrmgmt_test: PM state[0] entry counter 5
DEBUG   - DEVICE: [00:00:23.030,395] <inf> pwrmgmt_test: PM state[0] exit counter 5
DEBUG   - DEVICE: [00:00:23.030,395] <inf> pwrmgmt_test: PM state[1] entry counter 5
DEBUG   - DEVICE: [00:00:23.030,395] <inf> pwrmgmt_test: PM state[1] exit counter 5
DEBUG   - DEVICE: [00:00:23.030,426] <wrn> pwrmgmt_test: PM single-thread test started for cycles: 5, logging: 1
DEBUG   - DEVICE: [00:00:23.030,426] <inf> pwrmgmt_test: About to enter light sleep
DEBUG   - DEVICE: [00:00:24.530,578] <inf> pwrmgmt_test: Wake from Light Sleep
DEBUG   - DEVICE: [00:00:24.530,578] <inf> pwrmgmt_test: About to enter deep Sleep
DEBUG   - DEVICE: [00:00:24.598,876] <inf> pwrmgmt_test: PM sleep entry latency 0.068 seconds
DEBUG   - DEVICE: PM <
DEBUG   - DEVICE: PM >
DEBUG   - DEVICE: [00:00:27.631,103] <inf> pwrmgmt_test: Wake from Deep Sleep
DEBUG   - DEVICE: [00:00:27.631,469] <inf> pwrmgmt_test: PM sleep residency 3.033 seconds
DEBUG   - DEVICE: [00:00:27.631,469] <inf> pwrmgmt_test: About to enter light sleep
DEBUG   - DEVICE: [00:00:29.131,652] <inf> pwrmgmt_test: Wake from Light Sleep
DEBUG   - DEVICE: [00:00:29.131,652] <inf> pwrmgmt_test: About to enter deep Sleep
DEBUG   - DEVICE: [00:00:29.762,969] <inf> pwrmgmt_test: PM sleep entry latency 0.631 seconds
DEBUG   - DEVICE: [00:00:29.763,000] <wrn> pwrmgmt_test: Sleep entry latency is higher than expected
DEBUG   - DEVICE: PM <
DEBUG   - DEVICE: PM >
DEBUG   - DEVICE: [00:00:32.232,177] <inf> pwrmgmt_test: Wake from Deep Sleep
DEBUG   - DEVICE: [00:00:32.232,543] <inf> pwrmgmt_test: PM sleep residency 2.470 seconds
DEBUG   - DEVICE: [00:00:32.232,543] <inf> pwrmgmt_test: About to enter light sleep
DEBUG   - DEVICE: [00:00:33.732,727] <inf> pwrmgmt_test: Wake from Light Sleep
DEBUG   - DEVICE: [00:00:33.732,727] <inf> pwrmgmt_test: About to enter deep Sleep
DEBUG   - DEVICE: [00:00:34.364,044] <inf> pwrmgmt_test: PM sleep entry latency 0.632 seconds
DEBUG   - DEVICE: [00:00:34.364,074] <wrn> pwrmgmt_test: Sleep entry latency is higher than expected
DEBUG   - DEVICE: PM <
DEBUG   - DEVICE: PM >
DEBUG   - DEVICE: [00:00:36.833,251] <inf> pwrmgmt_test: Wake from Deep Sleep
DEBUG   - DEVICE: [00:00:36.833,618] <inf> pwrmgmt_test: PM sleep residency 2.469 seconds
DEBUG   - DEVICE: [00:00:36.833,618] <inf> pwrmgmt_test: About to enter light sleep
DEBUG   - DEVICE: [00:00:38.333,801] <inf> pwrmgmt_test: Wake from Light Sleep
DEBUG   - DEVICE: [00:00:38.333,801] <inf> pwrmgmt_test: About to enter deep Sleep
DEBUG   - DEVICE: [00:00:38.965,118] <inf> pwrmgmt_test: PM sleep entry latency 0.632 seconds
DEBUG   - DEVICE: [00:00:38.965,148] <wrn> pwrmgmt_test: Sleep entry latency is higher than expected
DEBUG   - DEVICE: PM <
DEBUG   - DEVICE: PM >
DEBUG   - DEVICE: [00:00:41.434,326] <inf> pwrmgmt_test: Wake from Deep Sleep
DEBUG   - DEVICE: [00:00:41.434,692] <inf> pwrmgmt_test: PM sleep residency 2.469 seconds
DEBUG   - DEVICE: [00:00:41.434,692] <inf> pwrmgmt_test: About to enter light sleep
DEBUG   - DEVICE: [00:00:42.934,875] <inf> pwrmgmt_test: Wake from Light Sleep
DEBUG   - DEVICE: [00:00:42.934,875] <inf> pwrmgmt_test: About to enter deep Sleep
DEBUG   - DEVICE: [00:00:43.566,192] <inf> pwrmgmt_test: PM sleep entry latency 0.632 seconds
DEBUG   - DEVICE: [00:00:43.566,223] <wrn> pwrmgmt_test: Sleep entry latency is higher than expected
DEBUG   - DEVICE: PM <
DEBUG   - DEVICE: Thread task B init[00:00:46.035,400] <inf> pwrmgmt_test: Wake from Deep Sleep
DEBUG   - DEVICE: [00:00:46.035,766] <inf> pwrmgmt_test: PM sleep residency 2.469 seconds
DEBUG   - DEVICE: [00:00:46.035,766] <inf> pwrmgmt_test: PM single-thread completed
DEBUG   - DEVICE: [00:00:46.035,766] <inf> pwrmgmt_test: PM state[0] entry counter 5
DEBUG   - DEVICE: [00:00:46.035,797] <inf> pwrmgmt_test: PM state[0] exit counter 5
DEBUG   - DEVICE: [00:00:46.035,797] <inf> pwrmgmt_test: PM state[1] entry counter 5
DEBUG   - DEVICE: [00:00:46.035,797] <inf> pwrmgmt_test: PM state[1] exit counter 5
DEBUG   - DEVICE: [00:00:46.035,797] <inf> pwrmgmt_test: Thread task A init
DEBUG   - DEVICE: [00:00:46.037,384] <wrn> pwrmgmt_test: PM multi-thread test started for cycles: 5, logging: 0
DEBUG   - DEVICE: [00:00:46.037,384] <inf> pwrmgmt_test: Suspend...
DEBUG   - DEVICE: [00:00:46.037,414] <inf> pwrmgmt_test: About to enter light sleep
DEBUG   - DEVICE: Wake from Light Sleep
DEBUG   - DEVICE: ABPM >
DEBUG   - DEVICE: [00:00:47.539,398] <inf> pwrmgmt_test: Resume
DEBUG   - DEVICE: [00:00:47.539,581] <inf> pwrmgmt_test: Suspend...
DEBUG   - DEVICE: [00:00:47.539,581] <inf> pwrmgmt_test: About to enter deep sleep
DEBUG   - DEVICE: [00:00:47.540,100] <inf> pwrmgmt_test: PM sleep entry latency 0.001 seconds
DEBUG   - DEVICE: Wake from Deep Sleep
DEBUG   - DEVICE: PM <
DEBUG   - DEVICE: ABWake from Light Sleep
DEBUG   - DEVICE: ABPM >
DEBUG   - DEVICE: [00:00:50.642,517] <inf> pwrmgmt_test: PM sleep residency 3.102 seconds
DEBUG   - DEVICE: [00:00:50.642,547] <inf> pwrmgmt_test: Resume
DEBUG   - DEVICE: [00:00:50.642,700] <inf> pwrmgmt_test: Suspend...
DEBUG   - DEVICE: [00:00:50.642,700] <inf> pwrmgmt_test: About to enter light sleep
DEBUG   - DEVICE: [00:00:52.144,714] <inf> pwrmgmt_test: Resume
DEBUG   - DEVICE: [00:00:52.144,897] <inf> pwrmgmt_test: Suspend...
DEBUG   - DEVICE: [00:00:52.144,897] <inf> pwrmgmt_test: About to enter deep sleep
DEBUG   - DEVICE: [00:00:52.782,104] <inf> pwrmgmt_test: PM sleep entry latency 0.638 seconds
DEBUG   - DEVICE: [00:00:52.782,135] <wrn> pwrmgmt_test: Sleep entry latency is higher than expected
DEBUG   - DEVICE: Wake from Deep Sleep
DEBUG   - DEVICE: PM <
DEBUG   - DEVICE: ABWake from Light Sleep
DEBUG   - DEVICE: ABPM >
DEBUG   - DEVICE: [00:00:55.247,833] <inf> pwrmgmt_test: PM sleep residency 2.465 seconds
DEBUG   - DEVICE: [00:00:55.247,863] <inf> pwrmgmt_test: Resume
DEBUG   - DEVICE: [00:00:55.248,016] <inf> pwrmgmt_test: Suspend...
DEBUG   - DEVICE: [00:00:55.248,016] <inf> pwrmgmt_test: About to enter light sleep
DEBUG   - DEVICE: [00:00:56.750,030] <inf> pwrmgmt_test: Resume
DEBUG   - DEVICE: [00:00:56.750,213] <inf> pwrmgmt_test: Suspend...
DEBUG   - DEVICE: [00:00:56.750,213] <inf> pwrmgmt_test: About to enter deep sleep
DEBUG   - DEVICE: [00:00:57.387,420] <inf> pwrmgmt_test: PM sleep entry latency 0.637 seconds
DEBUG   - DEVICE: [00:00:57.387,451] <wrn> pwrmgmt_test: Sleep entry latency is higher than expected
DEBUG   - DEVICE: Wake from Deep Sleep
DEBUG   - DEVICE: PM <
DEBUG   - Timed out while monitoring serial output on mec15xxevb_assy6853
DEBUG   - run status: timeout
INFO    - 1/1 mec15xxevb_assy6853       samples/boards/mec15xxevb_assy6853/power_management/sample.board.mec15xxevb_assy6853 FAILED Timeout (device 113.389s)
ERROR   - see: /home/ztest/work/zephyrproject/zephyr/sanity-out/mec15xxevb_assy6853/samples/boards/mec15xxevb_assy6853/power_management/sample.board.mec15xxevb_assy6853/handler.log

DEBUG   - running footprint_reports
INFO    - 0 of 1 tests passed (0.00%), 1 failed, 0 skipped with 0 warnings in 120.17 seconds
INFO    - In total 1 test cases were executed on 1 out of total 294 platforms (0.34%)
INFO    - 1 tests executed on platforms, 0 tests were only built.

Environment (please complete the following information):

  • OS: Linux Ubuntu 18.04.4 LTS
  • Toolchain Zephyr SDK 0.11.4
  • Commit SHA 84158f5

Additional context
Add any other context about the problem here.
@maksimmasalski maksimmasalski added bug The issue is a bug, or the PR is fixing a bug priority: low Low impact/importance bug labels Oct 19, 2020
@nashif
Copy link
Member

nashif commented Oct 19, 2020

This is a sample that runs without any tests, so it will run until it times out.
So you need to check the output using a harness.

With regard to "latency is higher than expected", not sure what is the expecation here, this is a sample that just spits some text out, what are we testing for here exactly? When did this start to fail? Was it always like this?

@maksimmasalski maksimmasalski mentioned this issue Oct 20, 2020
Closed
@ceolin ceolin self-assigned this Oct 28, 2020
@ceolin
Copy link
Member

ceolin commented Oct 28, 2020

@maksimmasalski regarding @nashif question, what is the latency issue here ? Is there any time constraint that this test is not achieving because of pm ?

@maksimmasalski
Copy link
Collaborator Author

@ceolin I checked the code, I found out that someone changed original value, should be less than 300, but in code is 500 ms, that also doesn't help, because now it is even more than 500ms.

/* Maximum latency should be less than 300 ms */
#define MAX_EXPECTED_MS_LATENCY   500ul

In fact I don't know who defined Maximum latency threshold. Why is 500? Why is 300? Tmrw I will clarify that.

@maksimmasalski
Copy link
Collaborator Author

@scottwcpg
Do you know what can be expected time for the Sleep entry latency on the Microchip board?
Because right now necessary to understand if there is an issue or wrong time value in that sample.

@scottwcpg
Copy link
Collaborator

@maksimmasalski
Sleep entry timing depends upon peripheral activity and the chip level sleep entry code. Once the code programs the sleep mode and executes the ARM WFI instruction HW takes over. The CPU should stay halted until a wake event (interrupt). I suspect the sleep entry code has a spin loop looking at bits called CLK_REQ which indicate peripherals requiring clocks. The code may be waiting on all of these bits to clear (no clocks required) before issuing the WFI instruction. If some peripheral is still claiming it needs a clock (UART for debug connection, eSPI because the Host is still sending data) then the sleep entry will spin for a longer time.

@maksimmasalski
Copy link
Collaborator Author

@maksimmasalski
Sleep entry timing depends upon peripheral activity and the chip level sleep entry code. Once the code programs the sleep mode and executes the ARM WFI instruction HW takes over. The CPU should stay halted until a wake event (interrupt). I suspect the sleep entry code has a spin loop looking at bits called CLK_REQ which indicate peripherals requiring clocks. The code may be waiting on all of these bits to clear (no clocks required) before issuing the WFI instruction. If some peripheral is still claiming it needs a clock (UART for debug connection, eSPI because the Host is still sending data) then the sleep entry will spin for a longer time.

Thank you for you detailed answer. Based upon your reply I understand that is not an issue, just the hardware special aspects.

@albertofloyd
Copy link
Collaborator

albertofloyd commented Nov 11, 2020 •
edited
Loading

@scottwcpg the test is running with no host attached (no eSPI traffic) so only UART and even though other drivers are enabled, there is no activity.

Nevertheless, the "latency" referred that the original test intended to measure was not consider SoC time to enter sleep.
The idea was only to measure the time for the kernel sleep residency portion.

@ceolin @wentongwu @nashif please correct if my understanding of the power management subsystem hooks below is not correct.

Test sequence

  1. All threads suspended
  2. Test saves k_uptime_get (trigger_time)
  3. Perfom long sleep k_msleep(CONFIG_SYS_PM_MIN_RESIDENCY_DEEP_SLEEP_1 + DP_EXTRA_SLP_TIME);
  4. Power subsystem policy is evaluated
  5. Power subsystem performs sys_suspend
  6. Power subsystem calls sys_pm_notify_power_state_entry hook
  7. Test calculates sleep entry latency = current time - trigger time
  8. Power subsytem calls sys_set_power_state
  9. MCHP-specific code to put SoC into light or deep sleep.

FYI Time between point 7 to point 9 for deep sleep is < 100 ms

@ceolin
Copy link
Member

ceolin commented Nov 13, 2020

@scottwcpg the test is running with no host attached (no eSPI traffic) so only UART and even though other drivers are enabled, there is no activity.

Nevertheless, the "latency" referred that the original test intended to measure was not consider SoC time to enter sleep.
The idea was only to measure the time for the kernel sleep residency portion.

@ceolin @wentongwu @nashif please correct if my understanding of the power management subsystem hooks below is not correct.

Test sequence

  1. All threads suspended
  2. Test saves k_uptime_get (trigger_time)
  3. Perfom long sleep k_msleep(CONFIG_SYS_PM_MIN_RESIDENCY_DEEP_SLEEP_1 + DP_EXTRA_SLP_TIME);
  4. Power subsystem policy is evaluated
  5. Power subsystem performs sys_suspend
  6. Power subsystem calls sys_pm_notify_power_state_entry hook
  7. Test calculates sleep entry latency = current time - trigger time
  8. Power subsytem calls sys_set_power_state
  9. MCHP-specific code to put SoC into light or deep sleep.

FYI Time between point 7 to point 9 for deep sleep is < 100 ms

I may be wrong, but I think there is one thing not considered here. The logging subsys has it is own thread that may be scheduled after your thread call k_msleep() avoiding the idle thread of immediately run and as uptime_get() is collected before it the delta calculated when your thread wake up may be greater than expected.

@albertofloyd
Copy link
Collaborator

Agreed @ceolin. I just tried last night, disabling logging (CONFIG_LOG=Y) reduces this latency considerably to few ms.
Since this makes difficult any other debugging when PM is enabled.
If I recall correctly there was previous work to make the logging thread aware of sleep states to mitigate impact on this.

@ceolin
Copy link
Member

ceolin commented Nov 13, 2020

I am not aware about this in the previous work. But that is definitely something that we need to be aware.

@maksimmasalski
Copy link
Collaborator Author

@albertofloyd Is it a real issue, or seems like just wrong CONFIG setup?

@albertofloyd
Copy link
Collaborator

I don't think CONFIG_LOG=y is mutually exclusive with PM enabled, is it?
Actually test was designed to ensure PM was evaluated with and without logging since there were some app hangs in the past

@maksimmasalski
Copy link
Collaborator Author

That means if CONFIG_LOG enabled, logging thread not aware of sleep states and impacts on them. Right?

@maksimmasalski
Copy link
Collaborator Author

@albertofloyd You said that actual test was designed to ensure PM was evaluated with and without logging. That sample demonstrates it and works. @albertofloyd @ceolin Do you think that we can close that issue for now?

@ceolin
Copy link
Member

ceolin commented Nov 18, 2020

We definitely have a problem that is the log subsystem not be power awareness. IMHO we should close this issue and open a new one about it.

@ceolin ceolin mentioned this issue Nov 18, 2020
Closed
@maksimmasalski
Copy link
Collaborator Author

Moved to #30121

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees

@ceolin ceolin

Labels
bug The issue is a bug, or the PR is fixing a bug priority: low Low impact/importance bug
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
5 participants
@nashif @ceolin @albertofloyd @scottwcpg @maksimmasalski