898707 - [B2G][Helix][Power key] Press power key can not always wake the device up from sleep

Status: RESOLVED INVALID

(Firefox OS Graveyard :: Vendcom, defect, P1)

Description

[DingYu]

User Agent: Mozilla/4.0 (compatible; MSIE 8.0; Windows NT 6.1; Trident/4.0; SLCC2; .NET CLR 2.0.50727; .NET CLR 3.5.30729; .NET CLR 3.0.30729; Media Center PC 6.0; aff-kingsoft-ciba; .NET4.0C; .NET4.0E; Tablet PC 2.0)

Steps to reproduce:

[Software]
git clone https://github.com/mozilla-b2g/B2G.git
cd B2G
BRANCH=v1.1.0hd ./config.sh helix

[Probability ] 
high

[Step]
1、power on the device,  press power key or wait for timeout, the device will go to sleep.
2、let the device sit in the sleep mode more than 30 minutes.
3、press the power key to wake up the deivce.

sometimes it can wake up, sometimes it will flicker on and then back off again.
the probability is high. After continue press power key a while, then we can easy repo the issue.


Actual results:

Device should always wake up immediately after press power key.


Expected results:

Sometimes it can not wake up after press power key.

Comment 1

[Swaroopa Vantipalli [:swaroopa]]

I have noticed this  number of times too.
When the phone is connected to the charger it wakes up immediately, but when its not connected to the charger, then sometimes it does not wake up immediately after pressing power key.

Comment 2

[DingYu]

I debug and find kernel has reported the power-button-press and power-button-release messages to B2G. when it can not wake up the device, B2G will take a long time to process the messages and call "request_suspend_state" to wakeup/sleep.

Comment 3

[Wayne Chang [:wchang]]

Can we check if this is also observed on leo? comment 2 suggests it maybe b2g related.

keven, can you find someone to check this?

Comment 4

[Wayne Chang [:wchang]]

Hi Viral,

Keven suggests you can check this... thanks :)

Comment 5

[Alan Huang]

(In reply to DingYu from comment #2)
> I debug and find kernel has reported the power-button-press and
> power-button-release messages to B2G. when it can not wake up the device,
> B2G will take a long time to process the messages and call
> "request_suspend_state" to wakeup/sleep.

Hi,

To clarify this is lower level or gecko bug, there are two actions need your help.

1. (Power key press part)
Do you have log for "kernel has reported the power-button-press and power-button-release messages to B2G"? Is it from InputReader? Otherwise, we may not be sure of it.
If you need to enable log in gecko/widget/gonk/libui/InputReader.cpp, you can check it's code and enable DEBUG_RAW_EVENTS define. Also, ensure all LOGD is enabled in your BSP, or you will miss some log in logcat. Once we can see raw event of power key, then we can say "kernel has reported the power-button-press and power-button-release messages to B2G"

2. (Suspend/resume part) 
Please enable Power HAL log in set_screen_state() of hardware/libhardware_legacy/power/power.c, and collect information from it and kernel suspen/resume information. Then we could know it is blocked before chrome process call into Power HAL or in Power HAL itself.

Thanks!

Comment 6

[bhavana bajaj [:bajaj]]

Can you also help understand the frequency of the issue as well?

Comment 7

[DingYu]

It is a gecko bug. The probability is high.

I attached the kmsglog and applogcat.

press 3 times power key, it has no response. until we connect the device to USB, the messages have been processed. please pay attention to the event timestamp.

kmsglog :
log from to line 4220 to the end, report_hs_key: key report   
request_suspend_state: wakeup/sleep 
[LCD_DEBUG]: LCD on/off   

applogcat:
please pay attention to line 2612 to the end

it reads the event immediately, but gecko doesn't process it in time.

Comment 8

[DingYu]

Attachment: applogcat-log

Comment 9

[DingYu]

Attachment: kmsgcat-log

Comment 10

[viral [:viralwang]]

Hi DingYu,

1) Since we still can not easily reproduce in our side. Could you please help to show us how to reproduce?
The reproduce steps in description looks like we should wait some time to power collapse and try to press power key.
However, the attached log show there are lots of power key events which make me confused.

2) We found the interval between "active wake lock" and "Freezing remaining freezable tasks" seems kind of critical. 
My suggestion is to increae the wake lock time from 500ms(not sure) to 1s for 
"active wake lock mmc2_detect", "active wake lock mmc1_detect".

If the issue still found in 1s wake lock time, please used "adb logcat -v time thread" to capture more detail information for us.

Thank you.

Comment 11

[DingYu]

Hi viral,
The probability is not 100%, but I think we can easy to repro the issue.
1)you can try to reprouce it by two ways:(without USB connected)
a. let the device sit in the sleep mode more than 30 minutes. then press power key to wakeup the device, sometimes it can not wake up even you press power key several times.
b. press power key as quickly as you can for tens of time, then try to press power key to wakeup/sleep the device normally. sometimes it can not wake up, then if you press the power key again, it will flicker on and then back off again. if the issue not happened, repeat

2)please tell me increae the wake lock time from 500ms to 1s for 
"active wake lock mmc2_detect", "active wake lock mmc1_detect".

From the log attached, the log I don't mentioned is that I try to repro the issue. you just need to pay attention to the segment log I mentioned, which I press power key 3 times and the device can not wakeup. 

thanks

denghuachang
[phone]

Comment 12

[dkumar]

In reply to comment 3.
I was not able to reproduce this issue on Leo Moz RIL and today's Com RIL, Also tried to follow the steps mentioned in comment 11 and was still unsuccessful.

Build ID: 20130801070210
Gecko: http://hg.mozilla.org/releases/mozilla-b2g18/rev/aff662053ee8
Gaia: ddb922ed002e88d01f71199da32ff75911b455b2
Platform Version: 18.1

Comment 13

[DingYu]

I think you can get help from Swaroopa Vantipalli, he can reproduce the issue from Comment 1.

Comment 14

[Swaroopa Vantipalli [:swaroopa]]

This is issue happens only on Helix device.
Leo does not have this problem.

Comment 15

[viral [:viralwang]]

(In reply to DingYu from comment #11)
> 2)please tell me increae the wake lock time from 500ms to 1s for 
> "active wake lock mmc2_detect", "active wake lock mmc1_detect".
> 
> From the log attached, the log I don't mentioned is that I try to repro the
> issue. you just need to pay attention to the segment log I mentioned, which
> I press power key 3 times and the device can not wakeup. 

The reason we think the wake lock time need to increase is that we can not make sure the time between "active wake lock" and "power key event pressed".
Log shows InputReader receive the power key but didn't not wake the device up in time.
One possible reason is "Freezing remaining freezable tasks" comes before device wake up, so we need to check the symptom with longer wake lock time.
If the issue still happened, we need to check the thread behavior by "adb logcat -v time thread" as comment 10 description.
Thank you.

Comment 16

[Wayne Chang [:wchang]]

for comment 14

shifting to hd?

Comment 17

[Marco Chen [:mchen]]

Hi Swaroopa,

Could you help to provide more info about this bug because we can't reproduce it by ourselves now? Thanks.

Q1: Can you provide the reproduce steps?

Q2: What is the frequency you met on your reproduce steps?

Q3: What partner image version your used? and what gaia/gecko version your used if you updated them?

Q4: Can you provide the kernel log (adb shell dmesg) and adb logcat contained your reproduced result? (you can get log after you reproduced successfully since kernel or adb logs are in the circular buffer)

Comment 18

[Marco Chen [:mchen]]

Hi DingYu,

Could you help to answer some question here? Thanks.

Q1: The kernel log showed that the user pressed power key many times during a short period. Is this a mandatory test step?

01-08 04:39:09 <6>[157, b2g] [ 2809.744708] request_suspend_state: wakeup (3->0) at 2809749479387 (1980-01-08 04:39:09.625545000 UTC)
01-08 04:39:09 <4>[90, khsclntd] [ 2809.888126] report_hs_key:Press power key ,key=255 ,now time (04:39:09.768948333 UTC)
01-08 04:39:09 <4>[90, khsclntd] [ 2809.943488] report_hs_key:Press power key ,key=81 ,now time (04:39:09.824311666 UTC)
01-08 04:39:09 <4>[90, khsclntd] [ 2810.081908] report_hs_key:Press power key ,key=255 ,now time (04:39:09.962725000 UTC)
01-08 04:39:10 <6>[157, b2g] [ 2810.144328] request_suspend_state: sleep (0->3) at 2810149097720 (1980-01-08 04:39:10.025164999 UTC)

Q2: Or could you provide a clean kernel/adb logs which will just see one time of power key with pressing/releasing and device can't be woken up? And please enable the kernel log for wake_lock, wake_unlock, wake_lock_timeout and wake_lock_time_expired.

Q3: Refer to the log as below, it is strange that system took 10 seconds to go back suspend mode again. According to that there is no one set power state from 3 to 0 so kernel should go to suspend immediately once no wakelock alive. Do you know that why system didn't go back to suspend but take 10 seconds?

01-08 04:40:13 <6>[3446, kworker/u:3] [ 2829.015451] active wake lock mmc1_detec
01-08 04:40:13 <4>[90, khsclntd] [ 2829.117408] report_hs_key:Press power key ,key=255 ,now time (04:40:13.128758333 UTC)
01-08 04:40:23 <4>[4896, kworker/u:5] [ 2829.170833] Freezing user space processes ... 01-08 04:40:23 (elapsed 0.03 seconds) done.

Comment 19

[Marco Chen [:mchen]]

Hi DingYu,

Follow the Q3 on comment 18, I suspect that 

  1. The timestamp of "01-08 04:40:13" is for timing of printing log out.
  2. The timestamp of "[ 2829.015451]" is for timing of saving into kernel's circular log buffer.

If I am right then actually the duration of keeping system woken up is just (2829.170833 - 2829.015451 =~ 0.12 seconds). That is too short for responding from Gecko. In general case from CAF's source code there should be an unknow_wakelock which will hold 0.5 seconds for keeping system woken up.

Can you help to confirm what I suspect here?

Comment 20

[Swaroopa Vantipalli [:swaroopa]]

Below are the answers to the questions:
Q1. STR
1.1 Do not connect the phone to the charger. Let the phone go to sleep.
1.2 Click on the power button to wake up the phone.

Observe that the device does not wake up immediately. 

Q2. The frequency is at least 4/5 when I saw the issue previously. But today it was only 1 out of the many times I tried.
Q3. The partner image is dated 0729 . But I did see this issue occurring frequently on Friday with the same partner Image.
Q4. Unfortunately I missed to capture the log the one time I encountered it today. Will provide when I see next time.

Comment 21

[Jason Smith [:jsmith]]

Pulling qawanted per the above comment.

Comment 22

[Marco Chen [:mchen]]

There are two root causes of this bug.

Root cause 1:
  a. When device is in "suspend state already" - power state 3.
  b. To press power key will wake up app processor.
  c. Kernel pass the power key to userspace.
  d. During userspace tried to process the power key kernel go back to suspend again due to no wakelock alive.
  
  Suggestion Solution:
    This is what Viral suggested already. To enable unknown_wakeup of wakelock (0.5 second) in linux kernel can solve this issue because it give the time for userspace to process the power key.

Root cause 2:
  a. When device is in "On state already" - power state 0.
  b. To press first time of power key will let device go into suspend state.
  c. During kernel's suspend flow, there is a stage called "Freezing user space processes". After this stage, userspace havs no change to do anything already.
  d. Unfortunately the second time of power key events is coming. (according to step c., userspace has no chance to process this second power key event)
  e. Device went to suspend completely.
  f. time is going.
  g. Some reason of RPC call wake up the app process then resume flow is completed and "un-freezing user space process".
  e. In this stage userspace process get the chance to process second time of power key at step d.
  h. Then user will see device is woken up.

Comment 23

[Wayne Chang [:wchang]]

see bug 904544 for  

> Root cause 2:
>   a. When device is in "On state already" - power state 0.
>   b. To press first time of power key will let device go into suspend state.
>   c. During kernel's suspend flow, there is a stage called "Freezing user
> space processes". After this stage, userspace havs no change to do anything
> already.
>   d. Unfortunately the second time of power key events is coming. (according
> to step c., userspace has no chance to process this second power key event)
>   e. Device went to suspend completely.
>   f. time is going.
>   g. Some reason of RPC call wake up the app process then resume flow is
> completed and "un-freezing user space process".
>   e. In this stage userspace process get the chance to process second time
> of power key at step d.
>   h. Then user will see device is woken up.

Comment 24

[Evelyn Hung]

Alan, is this the problem you suspect it's due to kernel OOM situation?

Comment 25

[Alan Huang]

(In reply to Evelyn Hung [:evelyn] from comment #24)
> Alan, is this the problem you suspect it's due to kernel OOM situation?

No, not this case.

Comment 26

[Wayne Chang [:wchang]]

Dinyu,
can you confirm you have addressed this in your latest kernel builds?

(In reply to Marco Chen [:mchen] (Summit 10/03 ~10/08) from comment #22)
> There are two root causes of this bug.
> 
> Root cause 1:
>   a. When device is in "suspend state already" - power state 3.
>   b. To press power key will wake up app processor.
>   c. Kernel pass the power key to userspace.
>   d. During userspace tried to process the power key kernel go back to
> suspend again due to no wakelock alive.
>   
>   Suggestion Solution:
>     This is what Viral suggested already. To enable unknown_wakeup of
> wakelock (0.5 second) in linux kernel can solve this issue because it give
> the time for userspace to process the power key.
>

Comment 27

[:gerard-majax]

Can we have an explanation on the root cause of this ?

Comment 29

[Marco Chen [:mchen]]

(In reply to Alexandre LISSY :gerard-majax from comment #27)
> Can we have an explanation on the root cause of this ?

Please refer to comment 22.