Phone does not suspend

Bug #1505241 reported by Pat McGowan on 2015-10-12
28
This bug affects 5 people
Affects Status Importance Assigned to Milestone
Canonical System Image
High
Simon Fels
bluez (Ubuntu)
High
Simon Fels

Bug Description

I am seeing both the MX4 on proposed and the E4.5 on stable exhibit similar behavior
According to the logs they are not able to suspend due to active wakeup sources.
(I am running a BT test kernel on the MX4 3.10.35+)

Pat McGowan (pat-mcgowan) wrote :
Pat McGowan (pat-mcgowan) wrote :

The phone was plugged in from around 5pm to 8pm. Quick drain can be seen from that time on. (The graph incorrectly shows a gain in charge from 2pm which is not possible, I assume it missed some events.

Pat McGowan (pat-mcgowan) wrote :

The phone was plugged in from around 5pm to 8pm. Quick drain can be seen from that time on. (The graph incorrectly shows a gain in charge from 2pm which is not possible, I assume it missed some events.

Changed in canonical-devices-system-image:
assignee: nobody → kevin gunn (kgunn72)
Pat McGowan (pat-mcgowan) wrote :

Actually this is from the previous log, this is repeated thousand of times

Oct 11 05:16:54 ubuntu-phablet kernel: [82715.640877] active wakeup source: MT662x
Oct 11 05:16:54 ubuntu-phablet kernel: [82715.640896] active wakeup source: EINT wakelock
Oct 11 05:16:55 ubuntu-phablet kernel: [82716.655950] active wakeup source: MT662x
Oct 11 05:16:57 ubuntu-phablet kernel: [82718.728492] PM: suspend entry 2015-10-11 09:16:57.752096077 UTC
Oct 11 05:16:57 ubuntu-phablet kernel: [82718.728512] PM: Syncing filesystems ... done.
Oct 11 05:16:57 ubuntu-phablet kernel: [82718.759147] Freezing user space processes ...
Oct 11 05:16:57 ubuntu-phablet kernel: [82718.760219] active wakeup source: MT662x
Oct 11 05:16:57 ubuntu-phablet kernel: [82718.760250] active wakeup source: EINT wakelock
Oct 11 05:16:57 ubuntu-phablet kernel: [82718.760260]
Oct 11 05:16:57 ubuntu-phablet kernel: [82718.760275] Freezing of tasks aborted after 0.001 seconds (20 tasks refusing to freeze, wq_busy=0):
Oct 11 05:16:57 ubuntu-phablet kernel: [82718.760315]
Oct 11 05:16:57 ubuntu-phablet kernel: [82718.760323] Restarting tasks ... done.
Oct 11 05:16:57 ubuntu-phablet kernel: [82718.762588] msdc: 0,mmc_schedule_delayed_work ret= 1
Oct 11 05:16:57 ubuntu-phablet kernel: [82718.762658] PM: suspend exit 2015-10-11 09:16:57.786272461 UTC
Oct 11 05:16:57 ubuntu-phablet kernel: [82718.762692] WQ warning! work (try_to_suspend, c0f38b2c) execute more than 1 sec, time: 3121820846 ns
Oct 11 05:16:57 ubuntu-phablet kernel: [82718.762946] active wakeup source: MT662x
Oct 11 05:16:57 ubuntu-phablet kernel: [82718.762966] active wakeup source: EINT wakelock
Oct 11 05:16:58 ubuntu-phablet kernel: [82719.775967] active wakeup source: MT662x
Oct 11 05:17:00 ubuntu-phablet kernel: [82721.868468] PM: suspend entry 2015-10-11 09:17:00.892072692 UTC
Oct 11 05:17:00 ubuntu-phablet kernel: [82721.868487] PM: Syncing filesystems ... done.
Oct 11 05:17:00 ubuntu-phablet kernel: [82721.895468] Freezing user space processes ...
Oct 11 05:17:00 ubuntu-phablet kernel: [82721.896555] active wakeup source: MT662x
Oct 11 05:17:00 ubuntu-phablet kernel: [82721.896585]
Oct 11 05:17:00 ubuntu-phablet kernel: [82721.896600] Freezing of tasks aborted after 0.001 seconds (20 tasks refusing to freeze, wq_busy=0):
Oct 11 05:17:00 ubuntu-phablet kernel: [82721.896641]
Oct 11 05:17:00 ubuntu-phablet kernel: [82721.896649] Restarting tasks ... done.
Oct 11 05:17:00 ubuntu-phablet kernel: [82721.898617] msdc: 0,mmc_schedule_delayed_work ret= 1
Oct 11 05:17:00 ubuntu-phablet kernel: [82721.898685] PM: suspend exit 2015-10-11 09:17:00.922299385 UTC
Oct 11 05:17:00 ubuntu-phablet kernel: [82721.898717] WQ warning! work (try_to_suspend, c0f38b2c) execute more than 1 sec, time: 3135993923 ns
Oct 11 05:17:00 ubuntu-phablet kernel: [82721.898757] active wakeup source: MT662x
Oct 11 05:17:01 ubuntu-phablet CRON[11160]: (root) CMD ( cd / && run-parts --report /etc/cron.hourly)

summary: - Phone did not suspend after incoming text message
+ Phone did not suspend
description: updated

if it were screen related mir team might be able to help, but this seems to be strictly power mode issue, cmiiaw

Changed in canonical-devices-system-image:
assignee: kevin gunn (kgunn72) → John McAleely (john.mcaleely)
description: updated
Changed in powerd (Ubuntu):
assignee: nobody → kevin gunn (kgunn72)
assignee: kevin gunn (kgunn72) → nobody
Changed in canonical-devices-system-image:
status: New → Confirmed
Launchpad Janitor (janitor) wrote :

Status changed to 'Confirmed' because the bug affects multiple users.

Changed in powerd (Ubuntu):
status: New → Confirmed
Pat McGowan (pat-mcgowan) wrote :

@yc for thoughts on why that part would cause those wakeups

Changed in canonical-devices-system-image:
assignee: John McAleely (john.mcaleely) → Yuan-Chen Cheng (ycheng-twn)
Simon Fels (morphis) wrote :

The wakeup source hold here "MT662x" is the combo connectivity chip responsible for WiFi/BT/GPS.

@Pat: Can you describe a bit more what you did with the device before this happened or what it was connected to?

Pat McGowan (pat-mcgowan) wrote :

@simon as I recall, I was out for the afternoon, I am pretty sure I used a map app to get where I was going
I am suspecting gps here since the other report has wifi abd bt off, and the report at bug #1511312 mentions he usually has gps off

Pat McGowan (pat-mcgowan) wrote :
summary: - Phone did not suspend
+ [mx4] Phone did not suspend

@pat, I guess you only saw it once, right ? I also hit by something similar long ago, but only happened once:
https://bugs.launchpad.net/bugs/1461589 (private bug)

Changed in canonical-devices-system-image:
importance: Undecided → Medium
Pat McGowan (pat-mcgowan) wrote :

This happened again this weekend. I am pretty sure its every time you use GPS from an app, will try to confirm.

Pat McGowan (pat-mcgowan) wrote :

Now seeing this repeated every few secs

Nov 2 09:07:20 ubuntu-phablet kernel: [ 5513.682920] PM: suspend entry 2015-11-02 14:07:20.071298692 UTC
Nov 2 09:07:20 ubuntu-phablet kernel: [ 5513.682938] PM: Syncing filesystems ... done.
Nov 2 09:07:20 ubuntu-phablet kernel: [ 5513.715728] Freezing user space processes ...
Nov 2 09:07:20 ubuntu-phablet kernel: [ 5513.716807] active wakeup source: WLAN timeout
Nov 2 09:07:20 ubuntu-phablet kernel: [ 5513.716834] active wakeup source: EINT wakelock
Nov 2 09:07:20 ubuntu-phablet kernel: [ 5513.716845]
Nov 2 09:07:20 ubuntu-phablet kernel: [ 5513.716859] Freezing of tasks aborted after 0.001 seconds (20 tasks refusing to freeze, wq_busy=0):
Nov 2 09:07:20 ubuntu-phablet kernel: [ 5513.716903]
Nov 2 09:07:20 ubuntu-phablet kernel: [ 5513.716911] Restarting tasks ... done.
Nov 2 09:07:20 ubuntu-phablet kernel: [ 5513.718951] msdc: 0,mmc_schedule_delayed_work ret= 1
Nov 2 09:07:20 ubuntu-phablet kernel: [ 5513.719022] PM: suspend exit 2015-11-02 14:07:20.107407923 UTC
Nov 2 09:07:20 ubuntu-phablet kernel: [ 5513.719052] WQ warning! work (try_to_suspend, c0eaab2c) execute more than 1 sec, time: 1017252385 ns
Nov 2 09:07:20 ubuntu-phablet kernel: [ 5513.719090] active wakeup source: WLAN timeout
Nov 2 09:07:20 ubuntu-phablet kernel: [ 5513.719110] active wakeup source: EINT wakelock
Nov 2 09:07:21 ubuntu-phablet kernel: [ 5514.693126] PM: suspend entry 2015-11-02 14:07:21.081505154 UTC

Pat McGowan (pat-mcgowan) wrote :

Use google maps, get location, put it in the background
Recieved a couple texts when suspended, eventually got into the same state as earlier

Nov 2 09:57:01 ubuntu-phablet kernel: [ 361.001763] PM: suspend entry 2015-11-02 14:57:01.474846087 UTC
Nov 2 09:57:01 ubuntu-phablet kernel: [ 361.001782] PM: Syncing filesystems ... done.
Nov 2 09:57:01 ubuntu-phablet kernel: [ 361.033651] Freezing user space processes ...
Nov 2 09:57:01 ubuntu-phablet kernel: [ 361.035298] active wakeup source: MT662x
Nov 2 09:57:01 ubuntu-phablet kernel: [ 361.035326] active wakeup source: EINT wakelock
Nov 2 09:57:01 ubuntu-phablet kernel: [ 361.035337]
Nov 2 09:57:01 ubuntu-phablet kernel: [ 361.035350] Freezing of tasks aborted after 0.001 seconds (20 tasks refusing to freeze, wq_busy=0):
Nov 2 09:57:01 ubuntu-phablet kernel: [ 361.035391]
Nov 2 09:57:01 ubuntu-phablet kernel: [ 361.035399] Restarting tasks ... done.
Nov 2 09:57:01 ubuntu-phablet kernel: [ 361.037492] msdc: 0,mmc_schedule_delayed_work ret= 1
Nov 2 09:57:01 ubuntu-phablet kernel: [ 361.037559] PM: suspend exit 2015-11-02 14:57:01.510651010 UTC
Nov 2 09:57:01 ubuntu-phablet kernel: [ 361.037590] WQ warning! work (try_to_suspend, c0eaab2c) execute more than 1 sec, time: 3117540769 ns
Nov 2 09:57:01 ubuntu-phablet kernel: [ 361.037626] active wakeup source: MT662x
Nov 2 09:57:01 ubuntu-phablet kernel: [ 361.037647] active wakeup source: EINT wakelock
Nov 2 09:57:02 ubuntu-phablet kernel: [ 362.047413] active wakeup source: MT662x

Pat McGowan (pat-mcgowan) wrote :

Wifi was off for last comment

tags: added: battery
tags: added: power-bugs
removed: battery
Pat McGowan (pat-mcgowan) wrote :

Happens every time I use location from a map app.
Battery drains around 2.5%+ overnight, should be less than 1%

Changed in canonical-devices-system-image:
importance: Medium → High
Pat McGowan (pat-mcgowan) wrote :

to clarify that was 2.5% per hr

no longer affects: location-service (Ubuntu)
no longer affects: powerd (Ubuntu)
Pat McGowan (pat-mcgowan) wrote :

E4.5 log after a reboot

summary: - [mx4] Phone did not suspend
+ Phone does not suspend
description: updated
Pat McGowan (pat-mcgowan) wrote :

MX4 log after a reboot

Pat McGowan (pat-mcgowan) wrote :

/proc/wakeup_reason from MX4

description: updated
Pat McGowan (pat-mcgowan) wrote :

Running suspend-blocker on the logs shows the krillin is suspended, despite the log containing reports of "suspended 0 seconds"

Suspends:
  6 suspends aborted (9.09%).
  60 suspends succeeded (90.91%).
  total time: 1735.045357 seconds (95.52%).
  minimum: 0.077456 seconds.
  maximum: 119.005703 seconds.
  mean: 28.917423 seconds.
  mode: 14.000000 seconds.
  median: 15.945897 seconds.

Time between successful suspends:
  total time: 81.430986 seconds (4.48%).
  minimum: 0.072164 seconds.
  maximum: 7.749603 seconds.
  mean: 1.380186 seconds.
  mode: 1.000000 seconds.
  median: 1.002277 seconds.

It seems that battery life has become greatly reduced on my MX4 since the last OTA-7 update.
I'm unsure if this is something to do with my daily use of the phone or if this is a known problem.
having left the device on charge during the night, by mid day with little interaction it 50% full.
Granted I have the wifi enabled and Bluetooth for connection to my vehicle.
I'm not doing anything different today than what I've done before the recent update.

Was advise to submit the Syslog to this bug.

Pat McGowan (pat-mcgowan) wrote :

With Bluetooth disabled the MX4 does suspend so I suspect the test kernel for my issue, will try reverting

Pat McGowan (pat-mcgowan) wrote :

marking invalid as it works fine with the shipping kernel

Changed in canonical-devices-system-image:
status: Confirmed → Invalid
Simon Fels (morphis) on 2015-11-06
tags: added: bluez5
Changed in canonical-devices-system-image:
assignee: Yuan-Chen Cheng (ycheng-twn) → nobody
assignee: nobody → Simon Fels (morphis)
Simon Fels (morphis) on 2015-11-10
Changed in bluez (Ubuntu):
status: New → In Progress
assignee: nobody → Simon Fels (morphis)
Simon Fels (morphis) on 2015-11-10
Changed in bluez (Ubuntu):
importance: Undecided → High

@Pat you mentioned a testing kernel on the MX4, but not on the BQ. If this happens in the BQ as well running a stable kernel that means we're still chasing this bug, right?

Pat McGowan (pat-mcgowan) wrote :

@Julia yes there could be a bug still on BQ

Simon Fels (morphis) wrote :

I tried to reproduce this with two MX4:

- First one running rc-proposed, the newer kernel with upgraded bluetooth stack and bluez4.
- Second one running rc-proposed, the newer kernel with upgraded bluetooth stack and bluez5.

Pat was running the first combination. I saw similar kernel suspend aborts due to the wakeup source MT662x being still active but not such a huge battery drain as Pat had. My battery only lost around 15-20% in ~20h where I just plugged it into my laptop for a few min to fetch a recent syslog in between. The rest of the time the phone was just laying around being paired and connect to a bluetooth device, being connected to a WiFi network and got a GPS fix before I turned the screen off.

Statistics look like this:

Resume wakeup causes:
  EINT, 909 100.00%

Suspend failure causes:
  tasks freezer abort 536 99.81%
  devices failed to suspend 1 0.19%

Suspends:
  588 suspends aborted (39.28%).
  909 suspends succeeded (60.72%).
  total time: 10361.993895 seconds (87.08%).
  minimum: 0.400780 seconds.
  maximum: 74.526359 seconds.
  mean: 11.399333 seconds.
  mode: 14.000000 seconds.
  median: 13.158011 seconds.

Time between successful suspends:
  total time: 1537.561435 seconds (12.92%).
  minimum: 0.897107 seconds.
  maximum: 11.649660 seconds.
  mean: 1.693350 seconds.
  mode: 1.000000 seconds.
  median: 1.030588 seconds.

Simon Fels (morphis) wrote :

Worth to mentioned but doesn't prove anything yet: When turning bluetooth off

Nov 13 06:06:18 ubuntu-phablet kernel: [60938.696811] [HCI-STP][I]hci_stp_close:hdev(0xd91de000)
Nov 13 06:06:18 ubuntu-phablet kernel: [60938.696829] [HCI-STP][I]hci_stp_flush:done
Nov 13 06:06:18 ubuntu-phablet kernel: [60938.696841] Flush type = 0 Rx Queue
Nov 13 06:06:18 ubuntu-phablet kernel: [60938.696856] ############ BT OFF ====>>sec=1447394778, usec=940213
Nov 13 06:06:18 ubuntu-phablet kernel: [60938.710524] ############ BT OFF <====>sec=1447394778, usec=953871
Nov 13 06:06:18 ubuntu-phablet kernel: [60938.710541] [HCI-STP][I]hci_stp_close:WMT turn off BT OK!
Nov 13 06:06:18 ubuntu-phablet kernel: [60938.742769] [CONN-MD-DFT][I]conn_md_thread:no msg queued in msg queue...
....
Nov 13 06:06:35 ubuntu-phablet kernel: [60955.707955] PM: suspend entry 2015-11-13 06:06:35.951294414 UTC
Nov 13 06:06:35 ubuntu-phablet kernel: [60955.707976] PM: Syncing filesystems ... done.
Nov 13 06:06:35 ubuntu-phablet kernel: [60955.732748] Freezing user space processes ...
Nov 13 06:06:35 ubuntu-phablet kernel: [60955.733966] active wakeup source: MT662x
Nov 13 06:06:35 ubuntu-phablet kernel: [60955.733995]
Nov 13 06:06:35 ubuntu-phablet kernel: [60955.734010] Freezing of tasks aborted after 0.001 seconds (24 tasks refusing to freeze, wq_busy=0):
Nov 13 06:06:35 ubuntu-phablet kernel: [60955.734051]
Nov 13 06:06:35 ubuntu-phablet kernel: [60955.734060] Restarting tasks ... done.
Nov 13 06:06:35 ubuntu-phablet kernel: [60955.736030] msdc: 0,mmc_schedule_delayed_work ret= 1
Nov 13 06:06:35 ubuntu-phablet kernel: [60955.736098] PM: suspend exit 2015-11-13 06:06:35.979446414 UTC
Nov 13 06:06:35 ubuntu-phablet kernel: [60955.736116] WQ warning! work (try_to_suspend, c0eaab2c) execute more than 1 sec, time: 635923103499 ns

So suspend still fails even if BT is turned off.

Simon Fels (morphis) wrote :

Disabling WiFi as next step lets the device suspend (but being woken up by EINT shortly afterwards again).

Simon Fels (morphis) wrote :

Generally I see aborted suspends because of the MT662x wakeup source also on rc-proposed with its current kernel but not in such a high frequency as Pat or I saw them before.

Simon Fels (morphis) wrote :

QA did a test run and measure power usage on an MX4 device. Results are stored at http://people.canonical.com/~platform-qa/power-results/?Chttp://people.canonical.com/~platform-qa/power-results/?C=M;O=D=M;O=D Test run number is 166.

According to QA they don't show anything significant difference to normal runs.

Colin Ian King (colin-king) wrote :

From the syslog in comment #2,

Suspend blocking wakelocks:
  None

Resume wakeup causes:
  EINT, 553 97.88%
  CLDMA_MD 6 1.06%
  CLDMA_MD, 6 1.06%

Suspend failure causes:
  tasks freezer abort 2548 99.96%
  devices failed to suspend 1 0.04%

Time between successful suspends:
   Interval (seconds) Frequency Cumulative Time (Seconds)
     0.500 - 0.999 222 39.78% 207.71 1.64%
     1.000 - 1.999 222 39.78% 324.46 2.56%
     2.000 - 3.999 69 12.37% 186.37 1.47%
     4.000 - 7.999 33 5.91% 177.43 1.40%
     8.000 - 15.999 4 0.72% 32.98 0.26%
    16.000 - 31.999 0 0.00% 0.00 0.00%
    32.000 - 63.999 1 0.18% 54.62 0.43%
    64.000 - 127.999 1 0.18% 127.39 1.01%
   128.000 - 255.999 0 0.00% 0.00 0.00%
   256.000 - 511.999 2 0.36% 632.91 5.00%
   512.000 - 1023.999 1 0.18% 1014.42 8.02%
  1024.000 - 2047.999 1 0.18% 1989.64 15.72%
  2048.000 - 4095.999 1 0.18% 2373.90 18.76%
  4096.000 - 8191.999 1 0.18% 5532.61 43.72%

Duration of successful suspends:
   Interval (seconds) Frequency Cumulative Time (Seconds)
     0.250 - 0.499 7 1.25% 2.70 0.04%
     0.500 - 0.999 15 2.68% 11.42 0.18%
     1.000 - 1.999 22 3.94% 31.21 0.48%
     2.000 - 3.999 68 12.16% 192.50 2.98%
     4.000 - 7.999 340 60.82% 1959.54 30.29%
     8.000 - 15.999 12 2.15% 139.92 2.16%
    16.000 - 31.999 31 5.55% 705.55 10.91%
    32.000 - 63.999 53 9.48% 2672.92 41.32%
    64.000 - 127.999 11 1.97% 752.79 11.64%

Suspends:
  2584 suspends aborted (82.21%).
  559 suspends succeeded (17.79%).
  total time: 6468.553336 seconds (33.83%).
  minimum: 0.333752 seconds.
  maximum: 106.062716 seconds.
  mean: 11.571652 seconds.
  mode: 6.000000 seconds.
  median: 5.974301 seconds.

Time between successful suspends:
  total time: 12654.471830 seconds (66.17%).
  minimum: 0.898421 seconds.
  maximum: 5532.614185 seconds.
  mean: 22.678265 seconds.
  mode: 1.000000 seconds.
  median: 1.155373 seconds.

Simon Fels (morphis) wrote :

Marked as In-Progress for system-image now too as BlueZ5 has landed in the overlay ppa.

Changed in canonical-devices-system-image:
status: Invalid → In Progress
Simon Fels (morphis) wrote :

Have a MX4 being active now for more than 3 days and not getting this problem with rc-proposed (which has BlueZ 5 merged) again

simon@nirvana ...-bluez5-upgrade/suspend-problem-arale % ~/Work/ubuntu2/suspend-blocker/suspend-blocker syslog
syslog:
Suspends:
  421 suspends aborted (13.66%).
  2661 suspends succeeded (86.34%).
  total time: 14336.580655 seconds (24.56%).
  minimum: 0.273411 seconds.
  maximum: 29.424044 seconds.
  mean: 5.387667 seconds.
  mode: 2.000000 seconds.
  median: 4.020927 seconds.

Time between successful suspends:
  total time: 44043.299598 seconds (75.44%).
  minimum: 0.907498 seconds.
  maximum: 38991.833792 seconds.
  mean: 16.557631 seconds.
  mode: 1.000000 seconds.
  median: 1.220935 seconds.
simon@nirvana ...-bluez5-upgrade/suspend-problem-arale % adb shell
uphablet@ubuntu-phablet:~$ uptime
 08:33:51 up 3 days, 13:00, 1 user, load average: 0.00, 0.01, 0.02

Simon Fels (morphis) wrote :

@Pat: Are you running rc-proposed? If yes, did you see anything over the weekend which looks like this is still happening with bluez5 being merged?

Pat McGowan (pat-mcgowan) wrote :

My test MX4 did suspend reasonably over a period of several hours, trying my daily driver now

Pat McGowan (pat-mcgowan) wrote :

On my MX4 after half a day of use

Suspends:
  6826 suspends aborted (99.53%).
  32 suspends succeeded (0.47%).

Battery dropped 50% overnight

Pat McGowan (pat-mcgowan) wrote :
Simon Fels (morphis) on 2015-11-26
tags: added: bluetooth-ota9
Simon Fels (morphis) wrote :

Added some debug statements to the arale kernel and now waiting for the problem to reappear here to find out more details.

Simon Fels (morphis) wrote :

If somebody else wants to do this too the used boot.img for arale is attached here.

The attachment "0001-Add-STP-MT662x-wakelock-traces.patch" seems to be a patch. If it isn't, please remove the "patch" flag from the attachment, remove the "patch" tag, and if you are a member of the ~ubuntu-reviewers, unsubscribe the team.

[This is an automated message performed by a Launchpad user owned by ~brian-murray, for any issues please contact him.]

tags: added: patch
Pat McGowan (pat-mcgowan) wrote :

Log with debugging kernel, pretty high fail to suspend rate

Suspends:
  262 suspends aborted (38.93%).
  411 suspends succeeded (61.07%).
  total time: 7293.604631 seconds (84.86%).
  minimum: 0.319212 seconds.
  maximum: 1359.032827 seconds.
  mean: 17.745997 seconds.
  mode: 6.000000 seconds.
  median: 6.060202 seconds.

Time between successful suspends:
  total time: 1300.874846 seconds (15.14%).
  minimum: 0.000080 seconds.
  maximum: 308.381052 seconds.
  mean: 3.172865 seconds.
  mode: 1.000000 seconds.
  median: 1.186014 seconds.

Simon Fels (morphis) wrote :

I went through Pats log file and it looks basically like this: The system doesn't go into sleep mode as their is still ongoing data flowing over the transport to the BT/WiFi/GPS combo chip. If that is real or a bug isn't clear yet. I am currently going through the responsible driver and see how this is actually supposed to work.

Simon Fels (morphis) wrote :

I looked through the code in the mx4 kernel now a bit more and the reason for the hold wakelock is that there is simply data flowing. What triggers the data flow or what data is actually flowing is not clear yet but I don't see any HCI frames receiving on the bluetooth stack side so far when this happens.

Next steps are to find a proper fix:

1. Find out what is actually sending data and why
2. Look into the difference between mx4 and krillin on the kernel side and see if that helps us
3. Trace the trigger through the whole MTK stack and see what is actually causing the activity

Pat McGowan (pat-mcgowan) wrote :

syslog with phone plugged in and charging for several hours, then unplugged, then charging again. All raidios on but did not connect to BT.
suspend-blocker is no longer able to parse the log output so unsure the suspend success.

Simon Fels (morphis) wrote :

@Pat: Does it print out something like:

Suspend blocking wakelocks:
  None

Resume wakeup causes:
  None

Suspend failure causes:
  None

Suspends:
  0 suspends aborted (0.00%).
  0 suspends succeeded (0.00%).
  total time: 0.000000 seconds (0.00%).
  minimum: 0.000000 seconds.
  maximum: 0.000000 seconds.
  mean: 0.000000 seconds.
  mode: 0.000000 seconds.
  median: 0.000000 seconds.

Time between successful suspends:
  total time: 0.000000 seconds (0.00%).
  minimum: 0.000000 seconds.
  maximum: 0.000000 seconds.
  mean: 0.000000 seconds.
  mode: 0.000000 seconds.
  median: 0.000000 seconds.

If yes, that is right. The log file does not contain any suspend attempt (from the kernel side) and your phone will never try to suspend as long as a usb cable is plugged in.

Pat McGowan (pat-mcgowan) wrote :

I think I long ago added a bug on that, when plugged in to a charger we should certainly suspend, its not an active USB data connection so we should not hold the wakelock in that case.

Pat McGowan (pat-mcgowan) wrote :

Latest log

Suspend blocking wakelocks:
  None

Resume wakeup causes:
  EINT, 170 98.84%
  CLDMA_MD 1 0.58%
  CLDMA_MD, 1 0.58%

Suspend failure causes:
  tasks freezer abort 783 99.87%
  devices failed to suspend 1 0.13%

Time between successful suspends:
   Interval (seconds) Frequency Cumulative Time (Seconds)
     0.250 - 0.499 1 0.59% 0.42 0.02%
     0.500 - 0.999 66 38.82% 61.81 2.23%
     1.000 - 1.999 63 37.06% 94.71 3.42%
     2.000 - 3.999 18 10.59% 41.06 1.48%
     4.000 - 7.999 15 8.82% 87.16 3.15%
     8.000 - 15.999 0 0.00% 0.00 0.00%
    16.000 - 31.999 1 0.59% 16.47 0.60%
    32.000 - 63.999 0 0.00% 0.00 0.00%
    64.000 - 127.999 0 0.00% 0.00 0.00%
   128.000 - 255.999 4 2.35% 634.54 22.92%
   256.000 - 511.999 1 0.59% 261.71 9.45%
   512.000 - 1023.999 0 0.00% 0.00 0.00%
  1024.000 - 2047.999 1 0.59% 1570.61 56.73%

Duration of successful suspends:
   Interval (seconds) Frequency Cumulative Time (Seconds)
     0.250 - 0.499 3 1.75% 1.13 0.04%
     0.500 - 0.999 0 0.00% 0.00 0.00%
     1.000 - 1.999 10 5.85% 12.97 0.48%
     2.000 - 3.999 17 9.94% 48.77 1.81%
     4.000 - 7.999 91 53.22% 514.08 19.12%
     8.000 - 15.999 11 6.43% 122.08 4.54%
    16.000 - 31.999 9 5.26% 212.36 7.90%
    32.000 - 63.999 22 12.87% 1165.36 43.35%
    64.000 - 127.999 8 4.68% 611.53 22.75%

Suspends:
  789 suspends aborted (82.19%).
  171 suspends succeeded (17.81%).
  total time: 2688.280289 seconds (49.27%).
  minimum: 0.365635 seconds.
  maximum: 124.066354 seconds.
  mean: 15.720937 seconds.
  mode: 6.000000 seconds.
  median: 6.060716 seconds.

Time between successful suspends:
  total time: 2768.483611 seconds (50.73%).
  minimum: 0.424609 seconds.
  maximum: 1570.606069 seconds.
  mean: 16.285198 seconds.
  mode: 1.000000 seconds.
  median: 1.247488 seconds.

Pat McGowan (pat-mcgowan) wrote :

With the latest kernel with fix for temperature controller reports things are much improved.

Resume wakeup causes:
  EINT, 2903 94.47%
  CLDMA_MD 85 2.77%
  CLDMA_MD, 85 2.77%

Suspend failure causes:
  tasks freezer abort 113 99.12%
  devices failed to suspend 1 0.88%

254 suspends aborted (7.83%).
2988 suspends succeeded (92.17%).

Simon Fels (morphis) wrote :

Attached is the log from Pat which shows the actual problem together with some verbose logging.

From the log the reason for the continous hold wakelock MT662x are therm events we're receiving from the WiFi/BT/.. combo chip. They start to flood at one point which will keep the device awake. One krillin interestingly we don't have support for this enabled at all and those events just never come in. What triggers the flood of therm events isn't clear yet but a first attempt to just disable them gave very good results as Pat showed above.

I've uploaded a fix for this to get some more eyes on this.

Simon Fels (morphis) on 2016-01-06
Changed in bluez (Ubuntu):
status: In Progress → Invalid
status: Invalid → Won't Fix
Changed in canonical-devices-system-image:
status: In Progress → Fix Committed
status: Fix Committed → Fix Released
Changed in canonical-devices-system-image:
status: Fix Released → Fix Committed
milestone: none → ww02-2016
Changed in canonical-devices-system-image:
status: Fix Committed → In Progress
Pat McGowan (pat-mcgowan) wrote :

Device part 20160106-6a15a0b

Changed in canonical-devices-system-image:
status: In Progress → Fix Committed
Changed in canonical-devices-system-image:
status: Fix Committed → Fix Released
To post a comment you must log in.
This report contains Public information  Edit
Everyone can see this information.

Other bug subscribers