[mako] phone does not deep suspend after incoming call

[Pat McGowan]

From the meta battery bug # 1372413
mako running 191

the syslog shows and incoming call occurred. After that, the phone does NOT deep suspend at all. Eventually, the phone drains at 03:55:33 on the 7th of Feb. So I think somebody needs to look at the way incoming calls seem to block deep suspend.

Feb 6 17:12:05 ubuntu-phablet kernel: [ 1535.537188] suspend: abort suspend
Feb 6 17:12:06 ubuntu-phablet powerd[948]: message repeated 3 times: [ signalling activity via HAL]
Feb 6 17:12:06 ubuntu-phablet powerd[948]: incoming call
Feb 6 17:12:06 ubuntu-phablet kernel: [ 1537.243247] request_suspend_state: wakeup (3->0) at 1537348691404 (2015-02-06 22:12:06.717124433 UTC)
Feb 6 17:12:06 ubuntu-phablet kernel: [ 1537.243399] [Touch D]touch enable
Feb 6 17:12:06 ubuntu-phablet kernel: [ 1537.249046] mipi_dsi_panel_power: mipi lcd function started status = 1
Feb 6 17:12:06 ubuntu-phablet kernel: [ 1537.252739] mipi_dsi_panel_power : reset start.
Feb 6 17:12:06 ubuntu-phablet kernel: [ 1537.278162] mipi_lgit_lcd_on started
Feb 6 17:12:06 ubuntu-phablet kernel: [ 1537.335418] mipi_lgit_lcd_on finished
Feb 6 17:12:06 ubuntu-phablet kernel: [ 1537.341950] lm3530_backlight_on, ++ lm3530_backlight_on

[Pat McGowan (pat-mcgowan)]

So far I have not been able to reproduce on a krillin.

[Pat McGowan (pat-mcgowan)]

On mako

After an incoming call

Suspend blocking wakelocks:
  None

Resume wakeup causes:
  None

Suspend failure causes:
  devices failed to suspend 1 100.00%

Time between successful suspends:
   Interval (seconds) Frequency Cumulative Time (Seconds)
  1024.000 - 2047.999 2 100.00% 2904.77 100.00%

Duration of successful suspends:
   Interval (seconds) Frequency Cumulative Time (Seconds)
     0.000 - 0.124 2 66.67% 0.21 61.75%
     0.125 - 0.249 1 33.33% 0.13 38.25%

Suspends:
  23 suspends aborted (88.46%).
  3 suspends succeeded (11.54%).
  total time: 0.346546 seconds (0.01%).
  minimum: 0.097185 seconds.
  maximum: 0.132541 seconds.
  mean: 0.115515 seconds.
  mode: 0.000000 seconds.
  median: 0.116819 seconds.

Time between successful suspends:
  total time: 2904.770453 seconds (99.99%).
  minimum: 1371.857538 seconds.
  maximum: 1532.912915 seconds.
  mean: 1452.385227 seconds.
  mode: 1533.000000 seconds.
  median: 1452.385227 seconds.

Before the call:
Suspend blocking wakelocks:
  wlan 12 44.44%
  main 4 14.81%
  powerd_power_request 4 14.81%
  qcom_rx_wakelock 4 14.81%
  alarm_rtc 2 7.41%
  event1-1490 1 3.70%

Resume wakeup causes:
  None

Suspend failure causes:
  late suspend wakelock 23 95.83%
  devices failed to suspend 1 4.17%

Time between successful suspends:
   Interval (seconds) Frequency Cumulative Time (Seconds)
     0.000 - 0.124 198 84.98% 2.22 0.27%
     0.125 - 0.249 1 0.43% 0.13 0.02%
     0.250 - 0.499 2 0.86% 0.87 0.10%
     0.500 - 0.999 2 0.86% 1.97 0.24%
     1.000 - 1.999 11 4.72% 18.02 2.17%
     2.000 - 3.999 6 2.58% 16.86 2.03%
     4.000 - 7.999 2 0.86% 10.11 1.21%
     8.000 - 15.999 2 0.86% 22.88 2.75%
    16.000 - 31.999 3 1.29% 56.85 6.83%
    32.000 - 63.999 0 0.00% 0.00 0.00%
    64.000 - 127.999 4 1.72% 368.77 44.32%
   128.000 - 255.999 2 0.86% 333.35 40.06%

Duration of successful suspends:
   Interval (seconds) Frequency Cumulative Time (Seconds)
     0.250 - 0.499 9 3.85% 3.76 0.12%
     0.500 - 0.999 22 9.40% 20.37 0.66%
     1.000 - 1.999 11 4.70% 15.96 0.52%
     2.000 - 3.999 17 7.26% 57.94 1.88%
     4.000 - 7.999 41 17.52% 245.60 7.99%
     8.000 - 15.999 51 21.79% 610.75 19.86%
    16.000 - 31.999 80 34.19% 1985.41 64.57%
    32.000 - 63.999 3 1.28% 134.98 4.39%

Suspends:
  44 suspends aborted (15.83%).
  234 suspends succeeded (84.17%).
  total time: 3074.782490 seconds (78.70%).
  minimum: 0.400589 seconds.
  maximum: 59.991308 seconds.
  mean: 13.140096 seconds.
  mode: 1.000000 seconds.
  median: 10.982936 se...

[Ricardo Salveti (rsalveti)]

Is this last comment produced from a new syslog file? If so, mind attaching it here as well?

Would you mind enabling debug on powerd as well when trying to reproduce this issue? I pushed that by default on vivid, and should have it enabled by default on RTM as well once the gates are opened for new landings.

For now please just change /etc/init/powerd.conf and remove the comment from line "#env POWERD_DEBUG=1". Then reboot and try to reproduce it again (attaching the syslog).

[Pat McGowan (pat-mcgowan)]

Sorry forgot to upload the syslog, this is just the time after the incoming call
I do have powerd debug enabled

[Ricardo Salveti (rsalveti)]

Your log is actually fine from powerd's perspective (powerd is indeed trying to suspend and releasing everything it can), but in your case it seems the usb device is blocking suspend:
Feb 19 16:01:04 ubuntu-phablet kernel: [ 5926.373385] usb 1-1: abort suspend
Feb 19 16:01:04 ubuntu-phablet kernel: [ 5926.373446] dpm_run_callback(): usb_dev_suspend+0x0/0x20 returns -16
Feb 19 16:01:04 ubuntu-phablet kernel: [ 5926.373477] PM: Device 1-1 failed to suspend async: error -16

The interesting piece is that you disconnected the usb cable right in the beginning of the log file. IIRC mako talks with the modem via USB, which might explain why it's failing to suspend.

The problem is that this is probably a bug in mako's kernel, as our userspace is indeed behaving as expected (and probably why we can't reproduce this bug with krillin).