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

power: subsystem: Application hangs when logging is enabled after entering deep sleep #23274

Closed
albertofloyd opened this issue Mar 5, 2020 · 3 comments · Fixed by #24254
Closed

power: subsystem: Application hangs when logging is enabled after entering deep sleep #23274

albertofloyd opened this issue Mar 5, 2020 · 3 comments · Fixed by #24254
Assignees
@dcpleung
Labels
area: Power Management bug The issue is a bug, or the PR is fixing a bug priority: medium Medium impact/importance bug

Comments

@albertofloyd
Copy link
Collaborator

albertofloyd commented Mar 5, 2020 •
edited
Loading

When logging is enabled and used in app that sleeps periodically for enough time to enter deep sleep (Sleep time higher than minimum residency)

After entering deep sleep the application thread never execute again which can be perceived as application hang.

Note: from kernel debug traces, deep sleep is exited but immediately re-entered, giving no opportunity for other threads to run.

Steps to reproduce the behavior:

  1. Get board sample code from samples: boards: mec15xxevb: Power management tests #23275
  2. cd samples/boards/mec15xxevb_assy6853
  3. mkdir build; cd build
  4. cmake -DBOARD=mec15xxevb_assy6853
  5. make
  6. Flash on EVB
  7. Check UART logs
    "Wake from light sleep" will be seen,
    "Wake from deep sleep" won't be seen

Expected behavior
Board test sleeps for different duration in a loop.
1st case app sleeps for 500 ms more than minimum light sleep residency.
2nd case app sleeps for 500 ms more than minimum deep sleep residency.

Note: Issue is not reproducible if logging is either completely disabled or not used in between k_sleep() during the test.

Impact
High cannot enable/use logging simultaneously with deep sleep.

Environment (please complete the following information):

  • OS: (e.g. Linux, MacOS, Windows)
  • Toolchain (e.g Zephyr SDK, ...)
  • Commit SHA or Version used
@albertofloyd albertofloyd added the bug The issue is a bug, or the PR is fixing a bug label Mar 5, 2020
@nashif nashif added priority: medium Medium impact/importance bug area: Power Management labels Mar 6, 2020
@wentongwu
Copy link
Contributor

wentongwu commented Mar 17, 2020 •
edited
Loading 

#ifdef CONFIG_KERNEL_DEBUG
#define K_DEBUG(fmt, ...) printk("[%s]  " fmt, __func__, ##__VA_ARGS__)
#else
#define K_DEBUG(fmt, ...)
#endif

if enabled CONFIG_KERNEL_DEBUG, it will use printk to output debug message. But for your test case, you also enable logging system with CONFIG_LOG=y, I think we should use same mechanism to do the output, so could you please try below patch with latest commit, and I test it locally, there is no hang like the description.

diff --git a/samples/boards/mec15xxevb_assy6853/power_management/prj.conf b/samples/boards/mec15xxevb_assy6853/power_management/prj.conf
index 328bcabbec..fc2b07a5e6 100644
--- a/samples/boards/mec15xxevb_assy6853/power_management/prj.conf
+++ b/samples/boards/mec15xxevb_assy6853/power_management/prj.conf
@@ -6,6 +6,7 @@ CONFIG_LOG_PROCESS_THREAD_SLEEP_MS=2100
 
 # Enable kernel debug
 CONFIG_KERNEL_DEBUG=y
+CONFIG_LOG_PRINTK=y
 CONFIG_THREAD_NAME=y
 # Enable PM debug in MEC1501 this will give indication in MCHP_060
 CONFIG_SYS_PM_DEBUG=y
diff --git a/samples/boards/mec15xxevb_assy6853/power_management/src/power_mgmt.c b/samples/boards/mec15xxevb_assy6853/power_management/src/power_mgmt.c
index 8a794a855e..f09ff6a647 100644
--- a/samples/boards/mec15xxevb_assy6853/power_management/src/power_mgmt.c
+++ b/samples/boards/mec15xxevb_assy6853/power_management/src/power_mgmt.c
@@ -193,6 +193,9 @@ int test_pwr_mgmt_multithread(bool use_logging, u8_t cycles)
 
        pm_reset_counters();
 
+       k_thread_abort(&threadA_id);
+       k_thread_abort(&threadB_id);
+
        return 0;
 }

@wentongwu wentongwu mentioned this issue Mar 18, 2020
Closed
@albertofloyd
Copy link
Collaborator Author

@wentongwu are you saying that the problem is due to wrong combination of debug options in KConfig? I will try the PR

@wentongwu
Copy link
Contributor

@wentongwu are you saying that the problem is due to wrong combination of debug options in KConfig? I will try the PR

@albertofloyd yes, please try it, thanks.

dcpleung added a commit to dcpleung/zephyr that referenced this issue Apr 10, 2020
@dcpleung
soc: mec1501: modifies interrupt restoration after deep sleep
ae7d97f 
z_power_soc_deep_sleep() is called with interrupt locked already
so restoring BASEPRI is pointless here, as it would only allow
exceptions afterwards. The situation is complicated by the fact
that kernel/idle.c:idle() only locks interrupt without unlocking
which means the BASEBRI at entry of z_power_soc_deep_sleep() is
already set to allow exceptions only but not lower priority
interrupts like timer. So when, e.g. timer, interrupt fires,
the SoC would come out of deep sleep but the waking interrupts
are never delivered since they are masked, and idle() will try
to sleep again. And now it gets into a loop of going into deep
sleep briefly and waking up immediately and it goes on and on.
The solution is not to restore BASEPRI and simply leave it at
zero. This is a workaround as a proper fix would involve
invasion changes to the PM subsystem.

Also, _sys_pm_power_state_exit_post_ops() is not being called
when deep sleep is involved, so PRIMASK needs to be reset
after coming out of deep sleep.

Fixes zephyrproject-rtos#23274

Signed-off-by: Daniel Leung <daniel.leung@intel.com>
@dcpleung dcpleung mentioned this issue Apr 10, 2020
Merged
@wentongwu wentongwu assigned dcpleung and unassigned wentongwu Apr 10, 2020
nashif pushed a commit that referenced this issue Apr 10, 2020
@dcpleung @nashif
soc: mec1501: modifies interrupt restoration after deep sleep
b935903 
z_power_soc_deep_sleep() is called with interrupt locked already
so restoring BASEPRI is pointless here, as it would only allow
exceptions afterwards. The situation is complicated by the fact
that kernel/idle.c:idle() only locks interrupt without unlocking
which means the BASEBRI at entry of z_power_soc_deep_sleep() is
already set to allow exceptions only but not lower priority
interrupts like timer. So when, e.g. timer, interrupt fires,
the SoC would come out of deep sleep but the waking interrupts
are never delivered since they are masked, and idle() will try
to sleep again. And now it gets into a loop of going into deep
sleep briefly and waking up immediately and it goes on and on.
The solution is not to restore BASEPRI and simply leave it at
zero. This is a workaround as a proper fix would involve
invasion changes to the PM subsystem.

Also, _sys_pm_power_state_exit_post_ops() is not being called
when deep sleep is involved, so PRIMASK needs to be reset
after coming out of deep sleep.

Fixes #23274

Signed-off-by: Daniel Leung <daniel.leung@intel.com>
avisconti pushed a commit to avisconti/zephyr that referenced this issue Apr 15, 2020
@dcpleung @avisconti
soc: mec1501: modifies interrupt restoration after deep sleep
60ddd81 
z_power_soc_deep_sleep() is called with interrupt locked already
so restoring BASEPRI is pointless here, as it would only allow
exceptions afterwards. The situation is complicated by the fact
that kernel/idle.c:idle() only locks interrupt without unlocking
which means the BASEBRI at entry of z_power_soc_deep_sleep() is
already set to allow exceptions only but not lower priority
interrupts like timer. So when, e.g. timer, interrupt fires,
the SoC would come out of deep sleep but the waking interrupts
are never delivered since they are masked, and idle() will try
to sleep again. And now it gets into a loop of going into deep
sleep briefly and waking up immediately and it goes on and on.
The solution is not to restore BASEPRI and simply leave it at
zero. This is a workaround as a proper fix would involve
invasion changes to the PM subsystem.

Also, _sys_pm_power_state_exit_post_ops() is not being called
when deep sleep is involved, so PRIMASK needs to be reset
after coming out of deep sleep.

Fixes zephyrproject-rtos#23274

Signed-off-by: Daniel Leung <daniel.leung@intel.com>
@albertofloyd albertofloyd mentioned this issue May 21, 2020
Closed
hakehuang pushed a commit to hakehuang/zephyr that referenced this issue Jun 20, 2020
@dcpleung @hakehuang
soc: mec1501: modifies interrupt restoration after deep sleep
956e7be 
z_power_soc_deep_sleep() is called with interrupt locked already
so restoring BASEPRI is pointless here, as it would only allow
exceptions afterwards. The situation is complicated by the fact
that kernel/idle.c:idle() only locks interrupt without unlocking
which means the BASEBRI at entry of z_power_soc_deep_sleep() is
already set to allow exceptions only but not lower priority
interrupts like timer. So when, e.g. timer, interrupt fires,
the SoC would come out of deep sleep but the waking interrupts
are never delivered since they are masked, and idle() will try
to sleep again. And now it gets into a loop of going into deep
sleep briefly and waking up immediately and it goes on and on.
The solution is not to restore BASEPRI and simply leave it at
zero. This is a workaround as a proper fix would involve
invasion changes to the PM subsystem.

Also, _sys_pm_power_state_exit_post_ops() is not being called
when deep sleep is involved, so PRIMASK needs to be reset
after coming out of deep sleep.

Fixes zephyrproject-rtos#23274

Signed-off-by: Daniel Leung <daniel.leung@intel.com>
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees

@dcpleung dcpleung

Labels
area: Power Management bug The issue is a bug, or the PR is fixing a bug priority: medium Medium impact/importance bug
Projects
None yet
Milestone
No milestone
4 participants
@nashif @albertofloyd @dcpleung @wentongwu