higher SIM power use on krillin since rc-proposed 196

[Selene ToyKeeper]

I'm seeing weird and buggy power behavior on krillin ever since rc-proposed 196 (and thus also in rc 38, the OTA8.5 release candidate). The root cause isn't determined yet, but there's a high probability it's related to the landing for bug 1480877.

This issue only occurs on krillin (not arale), and only when a SIM is installed and enabled.

Before: ~9 mA
http://people.canonical.com/~platform-qa/power-results/2015-12-08_03:19:30-krillin-195-power_usage_idle/graph.png

After: ~35 mA
http://people.canonical.com/~platform-qa/power-results/2015-12-08_07:36:16-krillin-196-power_usage_idle/graph.png

Here's the commit log for 196:

http://people.canonical.com/~lzemczak/landing-team/ubuntu-touch/rc-proposed/196.commitlog

Something appears to be waking up the phone and keeping it awake about half the time, causing the power graph to look like a square wave instead of a flat line. I don't see additional forks or crashes in the logs, which suggests a long-running process is responsible.

[Lorn Potter (lorn-potter)]

I have added an updated patch to #1480877.
The nm bearer plugin was still scanning wifi at every update request. which could be responsible for the wake ups you see.

[Jean-Baptiste Lallement (jibel)]

It would corroborate Dave's observation when he did field testing earlier this week and noted an increased power consumption on krillin.

[Timo Jyrinki (timo-jyrinki)]

qtbase 5.4.1+dfsg-2ubuntu11~vivid2 is ready for testing at https://requests.ci-train.ubuntu.com/#/ticket/761 with Lorn's net-bearer-nm-disconnect-ap-signals6.patch from bug #1480877 that includes a fix for both u-s-s crasher bug #1523975 and a potential fix to too many wifi scanning updates bug #1524133.

[Tony Espy (awe)]

This doesn't make much sense to me, as the only additions to the bearer mgmt plugin were a few DBus disconnect signal calls. The bulk of the changes were removing unused DBus logic which should have resulted in less wakeups, not more.

I'll take a look at Lorn's updated patch...

[Jean-Baptiste Lallement (jibel)]

Same change in behaviour between krillin rc 37 (OTA8)
http://people.canonical.com/~platform-qa/power-results/2015-11-19_15:49:55-krillin-37-power_usage_idle/graph.png

and krillin rc 38 (OTA8.5 candidate)
http://people.canonical.com/~platform-qa/power-results/2015-12-07_22:37:35-krillin-38-power_usage_idle/graph.png

[Lorn Potter (lorn-potter)]

I don't think the change to qt bearer would have any impact of wifi power consumption, unless there is something in the device specific parts that calls QNetworkConfigurationManager::updateConfigurations() at regular intervals.

On mako at least the wifi scan part of the nm bearer backend never gets called in regular operation.

[Tony Espy (awe)]

I agree with Lorn. I added a review of his latest modifications to the bearer-mgmt patch for bug #1480877, and that the additional changes are fixing anything that would impact battery usage.

Just to be sure, I re-installed OTA8 on my krillin ( stable, #27; aka OTA8 ) and checked WiFi scanning behavior. As expected, if a location-services consumer app is displayed ( eg. HERE, Today scope, Nearby scope ), scans are performed every 12-15s, regardless of whether or not the device is associated. Moving to another app or scope ( eg. Apps scope ), the scan interval starts at 30s, and rises to a maximum of 60s. If the device is associated to an access point, then this interval will eventually rise to 2m.

I then re-flashed the rc ( OTA8.5 ) image and re-checked, and the results are the same. I see no increase in the frequency of WiFi scanning in any of the scenarios described above.

[Selene ToyKeeper (toykeeper)]

Further testing reveals it's not wifi or bluetooth. The issue happens whenever a SIM is installed and enabled (no flight mode).

I'm still getting details on what's eating power, though.

[Simon Fels (morphis)]

Does someone has a syslog handing when this problem occurs? Would be interesting to see which wakelocks actually are being hold and causing us to not suspend.

[Pat McGowan (pat-mcgowan)]

My krillin with 8.5 after overnight is still at 99% battery level. The syslog looks fine wrt suspend. It does not have a SIM installed.
The attached graphs look like some extra activity occurs when resumed, but it is not prevented from suspending.

[Pat McGowan (pat-mcgowan)]

- it happens when a SIM is inserted and flight mode is off.
- The problem has only been observed in the lab when a SIM is installed but has expired service.
- field test didn't confirm the problem nor any user noticeable degradation of battery life.
- The fix has been released to rc-proposed 6 days ago and no one reported a decrease in battery life.
- The issue is not reproducible since we reset the lab entirely last night.

[Tony Espy (awe)]

@Pat

Do you need me to continue with investigation? We discussed during our network/telephony hangout this morning, and had talked about trying to isolate whether or not this is related to the the push notification service, as it's the only process which routinely wakes the system. One suggestion was to disable push-notifications and re-test...

[Pat McGowan (pat-mcgowan)]

There was a fix made for bug #1500839 to disable push when there was no data connection but wondering if we are not properly detecting that when the SIM's data plan is expired, it may seem to have a connection and retry

[Selene ToyKeeper (toykeeper)]

Yes, the syslog is available:
http://people.canonical.com/~platform-qa/power-results/2015-12-10_09:15:24-krillin-39-power_usage_idle/1/

So, after some frustrating tests I've found that the issue only occurs with a SIM which has an expired service plan. And it seems to be intermittent somehow. The lack of issues with an active SIM could just be luck though, so I hope to confirm that soon.

After a botched flash last night (server outage mid-flash), I couldn't get the issue to happen at all for the rest of the night. But I left it polling for updates and as soon as it started testing a new build the issue came back. Hopefully today I can quantify it more and get info on what process(es) are staying too busy.

But with the data available so far, I wouldn't consider this a blocker. Not many people use expired SIMs (and it didn't happen in the case of one expired SIM plus one active SIM).