GNOME Bugzilla – Bug 361583
With Two Batteries, Twice as many Notification Bubbles
Last modified: 2006-12-01 01:43:02 UTC
Please describe the problem: Although everything else about the power management is great for me, I recently got a second battery and I've noticed some odd behavior. * If either of my batteries is full when I log into GNOME, it will pop a bubble saying that I'm "fully charged". * If either of my batteries is approaching empty, it will pop a bubble saying I'm "critically low" Fairly simply diagnosis, but I suppose it could be hardware specific. I'm using a Thinkpad T41 with a drive bay battery in addition to the standard battery. It happens whenever I'm unplugged. Steps to reproduce: Actual results: Expected results: Does this happen every time? Other information:
Created attachment 74529 [details] The $(lshal) output from my Laptop
I think gnome-power-manager's notifications are pretty broken with regard to multi-battery laptops. As I've only got the one in my laptop, it makes it hard to test. If I start making changes, is it possible for you to test HEAD for me? Thanks, Richard.
I would love to... I'll have plenty of testing time this weekend and next week.
I've been working on getting gnome-power-manager installed from CVS this afternoon, but I've been having a hell of a time with it. One of the requirements is gnome-session from CVS, so I started on that. Trying to build gnome-session required gnome-common, so I cvs'd/autogen'd/make/make install'd that as well. ./autogen.sh failed for gnome-session because I was missing the gnome-compiler-flags.m4 file. i found it in the gnome-common source and copied it to /usr/share/aclocal/ and was able to get gnome-session to begin to configure. I'm stuck now because the (gnome-session) configure script fails near the end with a syntax error: #-------------------------------------------------------------------------------- ... checking for X... libraries , headers checking for gethostbyname... yes checking for connect... yes checking for remove... yes checking for shmat... yes checking for IceConnectionNumber in -lICE... yes checking for XauFileName in -lXau... yes ./configure: line 23803: syntax error near unexpected token `)' ./configure: line 23803: ` *\\"* | *\\`* | *\\*) ac_try_echo=\$ac_try;;' #-------------------------------------------------------------------------------- Any suggestions? Might it be because I copied that m4 file?
Alright, I did a bit of digging around in the code. I'm guessing the problem lies in src/gpm-manager.c --> battery_status_changed_primary(GpmManager *manager, GpmPowerKind battery_kind, GpmPowerStatus *battery_status) The function is a callback on any battery status changes that HAL reports, and it seems to be in charge of asking to display the libnotify messages. I think the problem is that the GpmPowerStatus struct only stores data on one battery, and the function doesn't check the other batteries before reporting updates. Sooo... I don't really have a solution, but maybe that can tell you where to look?
I agree with the last comment from Stu -- I've seen the same problem on my Lenovo X60s with two batteries, and reading through the code, I found the same fishy looking function: battery_status_changed_primary(). It seems that g-p-m needs to use its idea of the total capacity (which it must have somewhere, since it displays a percentage in the status icon) to decide if the batteries are fully charged or critically low. Sorry, no patch since I'm not familiar enough with the code yet, but I'd be happy to test patches too.
I am helping debugging Ubuntu bug which looks the same as this one: https://launchpad.net/bugs/60442 Since I have used gnome-power-manager source as reference material to add multi battery support to kde-guidance-powermanager, I think it is not that bad for multi-battery support (particularly as author does not have HW). However, when I have browsed the code (2.16.1 version from Ubuntu Edgy), I am concerned that this check in gpm-power.c:964 is questionable: /* If the primary battery is neither charging nor discharging, and * the charge is low the battery is most likely broken. * In this case, we'll use the ac_adaptor to determine whether it's * charging or not. */ if (entry->battery_kind == GPM_POWER_KIND_PRIMARY && (! type_status->is_charging) && (! type_status->is_discharging) && type_status->percentage_charge > 0 && type_status->percentage_charge < GPM_POWER_MIN_CHARGED_PERCENTAGE) { Problem is that type_status->percentage_charge is always 0 at this point and is set later in this function. I am not sure that this could be the root cause of this bug, but I know from my HAL testing that it can happen that both charging and discharging are FALSE, at least when battery is fully charged, but I can also imagine timing issue with two battery support where we trigger warning/automated action when first battery is empty (not discharging anymore), while the second one did not report yet that it started discharging. Note that there are two ways how laptop implement discharging: 1. Both batteries are discharged (and charged) together 2. Travel battery is full discharged first (and built-in battery is charged first) I suspect that with case 2., we have this small probability that we come to this case that both charging and discharging are FALSE, and this influences that remaining_time is not recalculated later in that function. Disclaimer: this is just some findings that we want to share early, we plan to do some tests to confirm/reject the above theory.
(In reply to comment #7) > However, when I have browsed the code (2.16.1 version from Ubuntu Edgy), I am > concerned that this check in gpm-power.c:964 is questionable: Yes, you could be correct. Stu, can you try commenting out this check and see what the effect is please? > Problem is that type_status->percentage_charge is always 0 at this point and is > set later in this function. I am not sure that this could be the root cause of > this bug, but I know from my HAL testing that it can happen that both charging > and discharging are FALSE, at least when battery is fully charged, but I can > also imagine timing issue with two battery support where we trigger > warning/automated action when first battery is empty (not discharging anymore), > while the second one did not report yet that it started discharging. Sure, that sounds like a bug. > Note that there are two ways how laptop implement discharging: > 1. Both batteries are discharged (and charged) together > 2. Travel battery is full discharged first (and built-in battery is charged > first) Yes, agree. > I suspect that with case 2., we have this small probability that we come to > this case that both charging and discharging are FALSE, and this influences > that remaining_time is not recalculated later in that function. > > Disclaimer: this is just some findings that we want to share early, we plan to > do some tests to confirm/reject the above theory. That's great Luka, feel free to email the gnome-power-manager-list@gnome.org mailing list for discussion, your input would be great. And yes, what I really need is to get my hands on some multi-battery laptops and have a couple of hours hack session. But I can dream :-) Richard.
Ohh, forgot to mention, if you are reviewing code: CVS HEAD is much better code quality and should have less bugs than 2.16.x releases. There's some cool new stuff there too.
Richard, I think removing this condition may not help - I would rather if Stu can test it by removing both percentage_charge checks to look something like this: if (entry->battery_kind == GPM_POWER_KIND_PRIMARY && (! type_status->is_charging) && (! type_status->is_discharging)) This is probably not good as final solution (as fully charged battery also has both set as FALSE), but would help to diagnose this corner case.
Yea, I can definitely give Luka's suggestion a go tonight with the source from Edgy. Richard, I mentioned above that I was having some trouble compiling GPM from CVS... I'd be happy to give it another go if you could point me in the right direction.
Also: > 2. Travel battery is full discharged first (and built-in battery is charged > first) Is the case with my laptop.
Stu, can you email me on richard at hughsie.com and I'll give you a hand setting it up. It seems like you need to install gnome-common for a start.
Richard, moving the questionable code did not help - so percentage_charge check was not the problem. Good thing is that we have now the full debugs (see attachement gpm.log): [gpm_power_get_status_summary] gpm-power.c:1289 (21:58:06): tooltip: Computer is running on battery power Laptop battery 2 hours, 41 minutes remaining (72%) [battery_status_changed_primary] gpm-manager.c:2046 (21:58:06): Already notified 1 [battery_kind_cache_debug_print] gpm-power.c:481 (21:58:06): Device : Laptop battery [battery_kind_cache_debug_print] gpm-power.c:483 (21:58:06): number 2 design 102960 [battery_kind_cache_debug_print] gpm-power.c:485 (21:58:06): present 1 last_full 105130 [battery_kind_cache_debug_print] gpm-power.c:487 (21:58:06): percent 72 current 76440 [battery_kind_cache_debug_print] gpm-power.c:489 (21:58:06): charge 0 rate (raw) 28583 [battery_kind_cache_debug_print] gpm-power.c:491 (21:58:06): discharge 1 remaining 9654 [battery_kind_cache_debug_print] gpm-power.c:493 (21:58:06): capacity 0 [watch_device_properties_modified_cb] gpm-hal.c:849 (21:58:06): property modified '/org/freedesktop/Hal/devices/acpi_BAT2' [watch_device_property_modified] gpm-hal.c:820 (21:58:06): emitting property-modified : udi=/org/freedesktop/Hal/devices/acpi_BAT2, key=battery.charge_level.rate, added=0, removed=0, finally=0 [hal_device_property_modified_cb] gpm-hal-monitor.c:225 (21:58:06): udi=/org/freedesktop/Hal/devices/acpi_BAT2, key=battery.charge_level.rate, added=0, removed=0, finally=0 [hal_device_property_modified_cb] gpm-hal-monitor.c:240 (21:58:06): emitting battery-property-modified : /org/freedesktop/Hal/devices/acpi_BAT2, battery.charge_level.rate [hal_battery_property_modified_cb] gpm-power.c:1627 (21:58:06): Battery Property Modified: /org/freedesktop/Hal/devices/acpi_BAT2 [gpm_power_exp_aver] gpm-power.c:297 (21:58:06): factor = 0.800000, previous = 28502, new=0, result = 22801 [watch_device_property_modified] gpm-hal.c:820 (21:58:06): emitting property-modified : udi=/org/freedesktop/Hal/devices/acpi_BAT2, key=battery.reporting.rate, added=0, removed=0, finally=0 [hal_device_property_modified_cb] gpm-hal-monitor.c:225 (21:58:06): udi=/org/freedesktop/Hal/devices/acpi_BAT2, key=battery.reporting.rate, added=0, removed=0, finally=0 [hal_device_property_modified_cb] gpm-hal-monitor.c:240 (21:58:06): emitting battery-property-modified : /org/freedesktop/Hal/devices/acpi_BAT2, battery.reporting.rate [hal_battery_property_modified_cb] gpm-power.c:1627 (21:58:06): Battery Property Modified: /org/freedesktop/Hal/devices/acpi_BAT2 [watch_device_property_modified] gpm-hal.c:820 (21:58:06): emitting property-modified : udi=/org/freedesktop/Hal/devices/acpi_BAT2, key=battery.rechargeable.is_discharging, added=0, removed=0, finally=1 [hal_device_property_modified_cb] gpm-hal-monitor.c:225 (21:58:06): udi=/org/freedesktop/Hal/devices/acpi_BAT2, key=battery.rechargeable.is_discharging, added=0, removed=0, finally=1 [hal_device_property_modified_cb] gpm-hal-monitor.c:240 (21:58:06): emitting battery-property-modified : /org/freedesktop/Hal/devices/acpi_BAT2, battery.rechargeable.is_discharging [hal_battery_property_modified_cb] gpm-power.c:1627 (21:58:06): Battery Property Modified: /org/freedesktop/Hal/devices/acpi_BAT2 [battery_kind_cache_update] gpm-power.c:969 (21:58:06): 2 devices of type Laptop battery [battery_kind_cache_update] gpm-power.c:1024 (21:58:06): emitting battery-status-changed : Laptop battery [get_stock_id] gpm-manager.c:454 (21:58:06): Trying CRITICAL icon: primary, ups, mouse, keyboard [get_stock_id] gpm-manager.c:478 (21:58:06): Trying CHARGING icon: primary, ups [gpm_power_get_icon_from_status] gpm-power.c:894 (21:58:06): got filename: gpm-primary-080 [tray_icon_update] gpm-manager.c:537 (21:58:06): Going to use stock id: gpm-primary-080 [gpm_power_get_status_summary] gpm-power.c:1289 (21:58:06): tooltip: Computer is running on battery power Laptop battery discharging (72%) [battery_status_changed_primary] gpm-manager.c:2058 (21:58:06): Laptop battery: critical level: [battery_status_changed_primary] gpm-manager.c:2059 (21:58:06): charging=0 discharging=1: [battery_status_changed_primary] gpm-manager.c:2060 (21:58:06): pct_charge=72 remaining=2: [gpm_manager_is_policy_timout_valid] gpm-manager.c:224 (21:58:06): gpm_manager_is_policy_timeout_valid: check-foreground-console returned with 0 [gpm_power_get_icon_from_status] gpm-power.c:894 (21:58:06): got filename: gpm-primary-080 [gpm_tray_icon_notify] gpm-tray-icon.c:899 (21:58:06): doing notify: Power Critically Low [libnotify_event] gpm-tray-icon.c:809 (21:58:06): libnotify: Power Manager : The battery is below the critical level and this computer is about to shutdown. [gpm_info_event_log] gpm-info.c:611 (21:58:06): Adding 11 to the event log [gpm_info_update_event_tree] gpm-info.c:314 (21:58:06): event log: Wed Oct 18, 20:53:37: On battery [gpm_info_update_event_tree] gpm-info.c:314 (21:58:06): event log: Wed Oct 18, 20:53:38: Notification [gpm_info_update_event_tree] gpm-info.c:314 (21:58:06): event log: Wed Oct 18, 21:58:06: Notification [battery_kind_cache_debug_print] gpm-power.c:481 (21:58:06): Device : Laptop battery [battery_kind_cache_debug_print] gpm-power.c:483 (21:58:06): number 2 design 102960 [battery_kind_cache_debug_print] gpm-power.c:485 (21:58:06): present 1 last_full 105130 [battery_kind_cache_debug_print] gpm-power.c:487 (21:58:06): percent 72 current 76440 [battery_kind_cache_debug_print] gpm-power.c:489 (21:58:06): charge 0 rate (raw) 0 [battery_kind_cache_debug_print] gpm-power.c:491 (21:58:06): discharge 1 remaining 2 [battery_kind_cache_debug_print] gpm-power.c:493 (21:58:06): capacity 0 The "pct_charge=72 remaining=2" is new debug I added just before we execute the critical action, and it looks like that remaining time is wrong, even though that it was correct some debugs before (in the same second). It looks as another special case to be handled... :-(
Created attachment 74997 [details] gpm.log.gz
Ah yea, sorry Luka... I tried it out last night, and forgot to post that it hadn't worked. I sent an e-mail to Richard about it though.
Created attachment 75027 [details] The notifications near 40% are "Critically Low"
I've got time to work on this today and tomorrow Richard... any suggestions?
Alright, I've figured out at least part of this bug. From running gnome-power-manager in debug mode (gnome-power-manager --no-daemon --debug power) like Luka did above, I noticed this inconsistency: both batteries are not added immediately on startup. Hence, the order of startup looks like this: * bat0 added * battery_kind_cache_update called (reports 1 battery with 100% charge) * bat1 added * battery_kind_cache_update called again (reports 2 batteries with n% charge) So we need to make sure battery_kind_cache_update is not called for the first time until after we have all of the batteries listed. This will fix the "Full Charge" notification on login, and it might be a similar problem causing the "Critical" warning at 50%... I'll look into it. I'll start working on a patch, but one of you is probably more qualified to decide where the check should go so it isn't called too often.
Created attachment 75149 [details] GPM Startup Debug Output
Created attachment 75163 [details] [review] Do power-trust Check before Calculations This is a patch against CVS head to fix the "Fully Charged" message on startup. It checks that the power data is trusted before doing any of the event calculations. The issue with showing "Critically Low" for each battery is still out there.
Stu, please can you apply attachment 75163 [details] [review]. Thanks for looking into this.
(In reply to comment #7) > Problem is that type_status->percentage_charge is always 0 at this point and is > set later in this function. Fixed in 2-16 and HEAD. Thanks for pointing it out. Richard,
(In reply to comment #22) > Stu, please can you apply attachment 75163 [details] [review] [edit]. Thanks for looking into this. Ahh, I learn you have no commit privs. We'll have to fix that. I've done this: 2006-10-22 Richard Hughes <richard@hughsie.com> * src/gpm-manager.c: (battery_status_changed_primary): Don't do *any* action until the battery data is marked as valid. Patch from Stu Hood <stuhood@gmail.com>, many thanks.
Still trying to work through this one, but here is a simplified log like Luka's above. --------------------------------------------------------------------------- gpm-power.c:371 (23:26:50) factor_inv=0.200000, factor_pc=80 gpm-power.c:374 (23:26:50) factor=0.800000, previous=18224, new=29881, result=20555 gpm-power.c:1090 (23:26:50) ||bat0, current_charge=16570, charge_smoothed=0, charge_raw=0, remaining_raw=0|| gpm-power.c:1090 (23:26:50) ||bat1, current_charge=210, charge_smoothed=20555, charge_raw=29881, remaining_raw=25|| gpm-power.c:371 (23:27:20) factor_inv=0.200000, factor_pc=80 gpm-power.c:374 (23:27:20) factor=0.800000, previous=20555, new=29492, result=22342 gpm-power.c:1090 (23:27:20) ||bat0, current_charge=16570, charge_smoothed=0, charge_raw=0, remaining_raw=0|| gpm-power.c:1090 (23:27:20) ||bat1, current_charge=80, charge_smoothed=22342, charge_raw=29492, remaining_raw=9|| gpm-power.c:371 (23:27:32) factor_inv=0.200000, factor_pc=80 gpm-power.c:374 (23:27:32) factor=0.800000, previous=22342, new=0, result=17873 gpm-power.c:1090 (23:27:32) ||bat0, current_charge=16570, charge_smoothed=0, charge_raw=0, remaining_raw=0|| gpm-power.c:1090 (23:27:32) ||bat1, current_charge=0, charge_smoothed=0, charge_raw=0, remaining_raw=9|| gpm-power.c:362 (23:27:32) Telling rate with no ave factor (okay once) gpm-power.c:371 (23:27:32) factor_inv=1.000000, factor_pc=80 gpm-power.c:374 (23:27:32) factor=0.000000, previous=0, new=29534, result=29534 gpm-power.c:1090 (23:27:33) ||bat0, current_charge=16480, charge_smoothed=0, charge_raw=29534, remaining_raw=2008|| gpm-power.c:1090 (23:27:33) ||bat1, current_charge=0, charge_smoothed=0, charge_raw=0, remaining_raw=9|| gpm-power.c:371 (23:27:50) factor_inv=0.200000, factor_pc=80 gpm-power.c:374 (23:27:50) factor=0.800000, previous=29534, new=29474, result=29522 gpm-power.c:1090 (23:27:50) ||bat0, current_charge=16360, charge_smoothed=29522, charge_raw=29474, remaining_raw=1998|| gpm-power.c:1090 (23:27:50) ||bat1, current_charge=0, charge_smoothed=0, charge_raw=0, remaining_raw=9|| gpm-power.c:371 (23:28:20) factor_inv=0.200000, factor_pc=80 gpm-power.c:374 (23:28:20) factor=0.800000, previous=29522, new=29373, result=29492 gpm-power.c:1090 (23:28:20) ||bat0, current_charge=16110, charge_smoothed=29492, charge_raw=29373, remaining_raw=1974|| gpm-power.c:1090 (23:28:20) ||bat1, current_charge=0, charge_smoothed=0, charge_raw=0, remaining_raw=9|| --------------------------------------------------------------------------- The important thing to note is that there is a period during the switch between batteries where the rate_raw is 0 for both batteries. This calculates a rate_smoothed of 0 for both batteries for the two following periods. Since the sum of rate_smoothed for all batteries is 0, gpm_power_update_kind_cache uses the remaining time reported by HAL. I gathered this log while my computer was under stress, and HAL reports absolute trash values for remaining time when CPU load is high.
Created attachment 75283 [details] [review] Calculate exp ave for kind caches instead of devices This patch against CVS head should resolve the issue. It sums the raw_rates of all devices of each 'kind' and then calculates the exponential average (instead of calculating averages for each device and then adding them together). It needs some testing in everyday use, but single battery users will notice no difference, and it shouldn't lower the accuracy of multi-battery calculations.
Stu, that looks good. You might want to replace "#### uh oh ####" with "rate data zero, not saving" but otherwise the patch is good to commit. I'm glad you've understood the structure so well - maybe all those comments were worthwhile after all. :-) Luca, can you test the patch please? Thanks.
Created attachment 75313 [details] [review] Calculate exp ave for kind caches, not devices (better debug output) Ahh, yea =) You'll have to excuse me for my excessive updates and that debug message... I've attached the same patch with better debug output. I thought about the situation some more: the only people who might be affected by this change will be those with multi-battery devices that discharge at the same time AND use different charge units. To handle that case, we'd need a weighted average: do we want to worry about it? Otherwise, after some testing this one should be closed.
(In reply to comment #28) > I thought about the situation some more: the only people who might be affected > by this change will be those with multi-battery devices that discharge at the > same time AND use different charge units. To handle that case, we'd need a > weighted average: do we want to worry about it? No, the _BST acpi method is going to be common for BAT1 and BAT2 so we'll get the same units. Patch is good to commit.
Have you got commit privs yet? Do you want me to walk you through your first commit?
Haven't gotten a response back from the list yet, but yea... I'd love a walkthrough when the time comes. As I understand it, I'd make sure my gpm tree is clean with `cvs -z3 up -C`, apply my patch somehow, add the changes to the changelog, and then `cvs -z3 ci`? Thanks for your help!
Patch committed.