powerd should avoid creating battery estimates when both nominal and instantaneous voltages are bogus |
||||||
Issue descriptionPaul reported getting a low battery alert containing "87% remaining" on a minnie running 55.0.2883.54 at http://feedback/product/208/neutron?lView=rd&lReport=22406027582. There's a very suspicious "0s until empty" message near the end of the powerd log that was probably responsible for this. --- ... [1201/092730:INFO:daemon.cc(774)] On battery at 89% (displayed as 91%), 6.646/7.500Ah at 1.387A, 8h7m7s until empty (7h50m38s until shutdown) [1201/092800:INFO:daemon.cc(774)] On battery at 88% (displayed as 91%), 6.637/7.500Ah at 1.151A, 7h23m51s until empty (7h8m48s until shutdown) [1201/092830:INFO:daemon.cc(774)] On battery at 88% (displayed as 91%), 6.630/7.500Ah at 0.697A, 7h13m43s until empty (6h59m until shutdown) [1201/092900:INFO:daemon.cc(774)] On battery at 88% (displayed as 91%), 6.623/7.500Ah at 0.706A, 7h11m5s until empty (6h56m27s until shutdown) [1201/092930:INFO:daemon.cc(774)] On battery at 88% (displayed as 91%), 6.616/7.500Ah at 1.337A, 6h16m3s until empty (6h3m16s until shutdown) [1201/093000:INFO:daemon.cc(774)] On battery at 88% (displayed as 91%), 6.609/7.500Ah at 0.711A, 7h10m50s until empty (6h56m10s until shutdown) [1201/093030:INFO:daemon.cc(774)] On battery at 88% (displayed as 90%), 6.603/7.500Ah at 0.718A, 7h55m9s until empty (7h38m58s until shutdown) [1201/093100:INFO:daemon.cc(774)] On battery at 88% (displayed as 90%), 6.597/7.500Ah at 0.710A, 7h53m15s until empty (7h37m6s until shutdown) [1201/093130:INFO:daemon.cc(774)] On battery at 88% (displayed as 90%), 6.590/7.500Ah at 0.873A, 7h34m35s until empty (7h19m4s until shutdown) [1201/093200:INFO:daemon.cc(774)] On battery at 88% (displayed as 90%), 6.584/7.500Ah at 0.700A, 8h52m7s until empty (8h33m56s until shutdown) [1201/093230:INFO:daemon.cc(774)] On battery at 88% (displayed as 90%), 6.578/7.500Ah at 0.689A, 8h54m48s until empty (8h36m30s until shutdown) [1201/093300:INFO:daemon.cc(774)] On battery at 88% (displayed as 90%), 6.571/7.500Ah at 0.755A, 8h48m55s until empty (8h30m49s until shutdown) [1201/093330:INFO:daemon.cc(774)] On battery at 88% (displayed as 90%), 6.563/7.500Ah at 1.062A, 8h2m42s until empty (7h46m9s until shutdown) [1201/093401:INFO:daemon.cc(774)] On battery at 87% (displayed as 90%), 6.557/7.500Ah at 0.747A, 8h17m37s until empty (8h33s until shutdown) [1201/093441:INFO:daemon.cc(774)] On battery at 87% (displayed as 90%), 6.547/7.500Ah at 0.934A, 7h49m6s until empty (7h32m58s until shutdown) [1201/093511:INFO:daemon.cc(774)] On battery at 87% (displayed as 90%), 6.538/7.500Ah at 0.762A, 7h40m25s until empty (7h24m35s until shutdown) [1201/093542:INFO:daemon.cc(774)] On battery at 87% (displayed as 89%), 6.528/7.500Ah at 1.513A, 6h30m17s until empty (6h16m49s until shutdown) [1201/093612:INFO:daemon.cc(774)] On battery at 87% (displayed as 89%), 6.519/7.500Ah at 0.759A, 6h54m47s until empty (6h40m28s until shutdown) [1201/093642:INFO:daemon.cc(774)] On battery at 87% (displayed as 89%), 6.511/7.500Ah at 0.717A, 6h56m56s until empty (6h42m31s until shutdown) [1201/093712:INFO:daemon.cc(774)] On battery at 87% (displayed as 89%), 6.504/7.500Ah at 1.033A, 6h47m52s until empty (6h33m45s until shutdown) [1201/093742:INFO:daemon.cc(774)] On battery at 87% (displayed as 89%), 6.495/7.500Ah at 0.968A, 6h30m29s until empty (6h16m57s until shutdown) [1201/093812:INFO:daemon.cc(774)] On battery at 87% (displayed as 89%), 6.488/7.500Ah at 0.707A, 7h45m12s until empty (7h29m4s until shutdown) [1201/093842:INFO:daemon.cc(774)] On battery at 86% (displayed as 89%), 6.482/7.500Ah at 0.741A, 7h46m47s until empty (7h30m35s until shutdown) [1201/093912:INFO:daemon.cc(774)] On battery at 86% (displayed as 89%), 6.476/7.500Ah at 0.787A, 7h38m38s until empty (7h22m42s until shutdown) [1201/093942:INFO:daemon.cc(774)] On battery at 86% (displayed as 89%), 6.467/7.500Ah at 0.992A, 7h42m29s until empty (7h26m23s until shutdown) [1201/094012:INFO:daemon.cc(774)] On battery at 86% (displayed as 88%), 6.459/7.500Ah at 1.005A, 7h37m52s until empty (7h21m55s until shutdown) [1201/094042:INFO:daemon.cc(774)] On battery at 86% (displayed as 88%), 6.452/7.500Ah at 0.771A, 7h30m34s until empty (7h14m51s until shutdown) [1201/094112:INFO:daemon.cc(774)] On battery at 86% (displayed as 88%), 6.444/7.500Ah at 1.083A, 6h56m49s until empty (6h42m16s until shutdown) [1201/094142:INFO:daemon.cc(774)] On battery at 86% (displayed as 88%), 6.436/7.500Ah at 0.716A, 7h2m46s until empty (6h48m until shutdown) [1201/094212:INFO:daemon.cc(774)] On battery at 86% (displayed as 88%), 6.428/7.500Ah at 0.750A, 7h25m52s until empty (7h10m16s until shutdown) [1201/094242:INFO:daemon.cc(774)] On battery at 86% (displayed as 88%), 6.421/7.500Ah at 0.690A, 8h22s until empty (7h43m32s until shutdown) [1201/094312:INFO:daemon.cc(774)] On battery at 85% (displayed as 88%), 6.412/7.500Ah at 0.766A, 8h18s until empty (7h43m27s until shutdown) [1201/094342:INFO:daemon.cc(774)] On battery at 85% (displayed as 88%), 6.404/7.500Ah at 0.740A, 8h44m38s until empty (8h26m12s until shutdown) [1201/094412:INFO:daemon.cc(774)] On battery at 85% (displayed as 88%), 6.395/7.500Ah at 1.125A, 7h51m16s until empty (7h34m41s until shutdown) [1201/094442:INFO:daemon.cc(774)] On battery at 85% (displayed as 87%), 6.387/7.500Ah at 0.761A, 7h49m24s until empty (7h32m52s until shutdown) [1201/094512:INFO:daemon.cc(774)] On battery at 85% (displayed as 87%), 6.379/7.500Ah at 0.746A, 7h42m28s until empty (7h26m9s until shutdown) [1201/094542:INFO:daemon.cc(774)] On battery at 85% (displayed as 87%), 6.371/7.500Ah at 0.909A, 7h26m28s until empty (7h10m42s until shutdown) [1201/094612:INFO:daemon.cc(774)] On battery at 85% (displayed as 87%), 6.364/7.500Ah at 0.706A, 7h29m32s until empty (7h13m39s until shutdown) [1201/094643:INFO:daemon.cc(774)] On battery at 85% (displayed as 87%), 6.357/7.500Ah at 0.746A, 8h13m3s until empty (7h55m36s until shutdown) [1201/094713:INFO:daemon.cc(774)] On battery at 85% (displayed as 87%), 6.349/7.500Ah at 1.310A, 0s until empty [1201/094743:INFO:daemon.cc(774)] On battery at 85% (displayed as 87%), 6.341/7.500Ah at 0.984A, 6h48m39s until empty (6h34m9s until shutdown) [1201/094813:INFO:daemon.cc(774)] On battery at 84% (displayed as 87%), 6.334/7.500Ah at 1.519A, 6h55s until empty (5h48m5s until shutdown) [1201/094843:INFO:daemon.cc(774)] On battery at 84% (displayed as 87%), 6.324/7.500Ah at 1.406A, 5h18m3s until empty (5h6m44s until shutdown) [1201/094913:INFO:daemon.cc(774)] On battery at 84% (displayed as 86%), 6.315/7.500Ah at 1.568A, 4h39m8s until empty (4h29m11s until shutdown) --- It's non-obvious to me from the log why this happened. The charge and current look reasonable to me. I'll look through the code to see if there's some other input to the calculation that could've caused this.
,
Dec 5 2016
Those values should be coming from the battery fuel gauge. Doug may remember if there are known issues with Minnie's fuel gauge?
,
Dec 6 2016
Opinions about whether it'd be better for powerd to still go ahead with the update while leaving the battery time estimates unset vs. giving up on the update entirely when both the nominal and instantaneous voltages are zero? It looks like it was a transient issue here. Can we count on that being the case? If it can be persistent, I'd rather continue passing updated percentages to Chrome while leaving the estimates unset (which I think will result in Chrome displaying "Calculating...").
,
Dec 6 2016
I believe nominal voltage is simply not supported by Minnie's battery. We're not using "sbs_battery" on minnie. I don't remember cases with the instantaneous voltage being 0 though. Possibly if we had EC logs we could see some errors reading the battery? We had to tweak the EC i2c driver a bit I think because the battery would hold the line low for a really long while. Maybe it's even longer than we ever accounted for? Bugs with some history: * http://crosbug.com/p/37123 === Oh, but maybe this is the root cause: <4>[22450.787789] cros-ec-spi spi0.0: EC failed to respond in time <3>[22450.788035] cros-ec-spi spi0.0: Command xfer error (err:-110) <3>[22450.788048] bq27x00-battery 20-0055: error reading voltage <3>[22450.788061] power_supply bq27500-0: driver failed to report `voltage_now' property: -110 === So basically we had an EC/AP communications glitch. I'm not aware of that being terribly common. We could file a bug for it, but I probably won't be able to work on it myself right now, so we'd want to find an owner or leave it alone until we see more instances. It would be easy to "paper over" this by adding some retries, possibly. I think sbs battery usually has some of these, so adding it to the BQ driver might not be insane? I hate retries, but ... Also notice that possibly just adding some more allowance for how long commands take to respond could possibly make this work. Like I said that battery in minnie likes to clock stretch. A lot. Possible it just stretched things too far and the kernel gave up waiting for an EC response??? I'd have to dig to see if this is really a plausible explanation since it's been a while since I looked at all these bits.
,
Dec 6 2016
@3: Would it make sense to just ignore any single "totally insane" value? AKA a change in more than 10% all at once it likely to be bogus ?
,
Dec 6 2016
#5: I'm not sure about that. I'm pretty comfortable making powerd bail when it gets obviously-broken inputs from the kernel (e.g. zero or negative values where that's impossible), but I'm more hesitant to throw out plausible-but-iffy numbers (which I don't think I've heard about before, in any case).
,
Dec 9 2016
The following revision refers to this bug: https://chromium.googlesource.com/chromiumos/platform2/+/c01456dcc1967b44dabfeb0d9102c6ea431f5145 commit c01456dcc1967b44dabfeb0d9102c6ea431f5145 Author: Daniel Erat <derat@chromium.org> Date: Tue Dec 06 00:17:23 2016 power: Abort power status update when unable to get voltage. Make powerd give up on refreshing the power status when both the nominal and instantaneous voltages are zero (which shouldn't happen, but apparently does on minnie). Currently, powerd can pass bad "0 seconds until empty" estimates to Chrome in this case, which may result in nonsensical low-battery notifications being displayed to the user. BUG= chromium:671374 TEST=updated tests Change-Id: If86d2688e7a4eff801fa69d1e1624f10429b11e2 Reviewed-on: https://chromium-review.googlesource.com/417163 Commit-Ready: Dan Erat <derat@chromium.org> Tested-by: Dan Erat <derat@chromium.org> Reviewed-by: Douglas Anderson <dianders@chromium.org> Reviewed-by: Dan Erat <derat@chromium.org> [modify] https://crrev.com/c01456dcc1967b44dabfeb0d9102c6ea431f5145/power_manager/powerd/system/power_supply.cc [modify] https://crrev.com/c01456dcc1967b44dabfeb0d9102c6ea431f5145/power_manager/powerd/system/power_supply_unittest.cc
,
Dec 9 2016
Doug, reassigning to you for the EC/AP side.
,
Dec 9 2016
,
Dec 9 2016
,
Dec 9 2016
,
Jun 29 2017
Verified in Chrome OS 9693.1.0, 61.0.3144.0 |
||||||
►
Sign in to add a comment |
||||||
Comment 1 by derat@chromium.org
, Dec 5 2016