| View previous topic :: View next topic |
| Author |
Message |
mrpringle
Apprentice
Joined: 27 May 2007
Posts: 284
|
 Posted: Wed Dec 17, 2008 5:32 am Post subject: crazy acpi battery event sequence |
 |
|
Hi,
I think there may be an issue with acpid, or at least my configuration.
Here is a snipped of /var/log/messages when I unplug the AC and then replug it in about 30 seconds later.
| Code: |
Dec 17 16:23:02 adam-nb acpid: received event "ac_adapter AC 00000080 00000000"
Dec 17 16:23:02 adam-nb acpid: notifying client 5237[0:0]
Dec 17 16:23:02 adam-nb acpid: notifying client 3622[102:440]
Dec 17 16:23:02 adam-nb acpid: notifying client 5237[0:0]
Dec 17 16:23:02 adam-nb acpid: executing action "/etc/acpi/default.sh ac_adapter AC 00000080 00000000"
Dec 17 16:23:02 adam-nb logger: ACPI event unhandled: ac_adapter AC 00000080 00000000
Dec 17 16:23:02 adam-nb acpid: action exited with status 0
Dec 17 16:23:02 adam-nb acpid: completed event "ac_adapter AC 00000080 00000000"
Dec 17 16:23:02 adam-nb acpid: received event "processor CPU0 00000080 00000004"
Dec 17 16:23:02 adam-nb acpid: notifying client 5237[0:0]
Dec 17 16:23:02 adam-nb acpid: notifying client 3622[102:440]
Dec 17 16:23:02 adam-nb acpid: notifying client 5237[0:0]
Dec 17 16:23:02 adam-nb acpid: executing action "/etc/acpi/default.sh processor CPU0 00000080 00000004"
Dec 17 16:23:02 adam-nb logger: ACPI event unhandled: processor CPU0 00000080 00000004
Dec 17 16:23:02 adam-nb acpid: action exited with status 0
Dec 17 16:23:02 adam-nb acpid: completed event "processor CPU0 00000080 00000004"
Dec 17 16:23:02 adam-nb acpid: received event "processor CPU1 00000080 00000004"
Dec 17 16:23:02 adam-nb acpid: notifying client 5237[0:0]
Dec 17 16:23:02 adam-nb acpid: notifying client 3622[102:440]
Dec 17 16:23:02 adam-nb acpid: notifying client 5237[0:0]
Dec 17 16:23:02 adam-nb acpid: executing action "/etc/acpi/default.sh processor CPU1 00000080 00000004"
Dec 17 16:23:02 adam-nb logger: ACPI event unhandled: processor CPU1 00000080 00000004
Dec 17 16:23:02 adam-nb acpid: action exited with status 0
Dec 17 16:23:02 adam-nb acpid: completed event "processor CPU1 00000080 00000004"
Dec 17 16:23:03 adam-nb acpid: received event "battery BAT0 00000080 00000001"
Dec 17 16:23:03 adam-nb acpid: notifying client 5237[0:0]
Dec 17 16:23:03 adam-nb acpid: notifying client 3622[102:440]
Dec 17 16:23:03 adam-nb acpid: notifying client 5237[0:0]
Dec 17 16:23:03 adam-nb acpid: executing action "/etc/acpi/default.sh battery BAT0 00000080 00000001"
Dec 17 16:23:03 adam-nb logger: ACPI event unhandled: battery BAT0 00000080 00000001
Dec 17 16:23:03 adam-nb acpid: action exited with status 0
Dec 17 16:23:03 adam-nb acpid: completed event "battery BAT0 00000080 00000001"
Dec 17 16:23:18 adam-nb acpid: received event "processor CPU0 00000080 00000000"
Dec 17 16:23:18 adam-nb acpid: notifying client 5237[0:0]
Dec 17 16:23:18 adam-nb acpid: notifying client 3622[102:440]
Dec 17 16:23:18 adam-nb acpid: notifying client 5237[0:0]
Dec 17 16:23:18 adam-nb acpid: executing action "/etc/acpi/default.sh processor CPU0 00000080 00000000"
Dec 17 16:23:18 adam-nb logger: ACPI event unhandled: processor CPU0 00000080 00000000
Dec 17 16:23:18 adam-nb acpid: action exited with status 0
Dec 17 16:23:18 adam-nb acpid: completed event "processor CPU0 00000080 00000000"
Dec 17 16:23:18 adam-nb acpid: received event "processor CPU1 00000080 00000000"
Dec 17 16:23:18 adam-nb acpid: notifying client 5237[0:0]
Dec 17 16:23:18 adam-nb acpid: notifying client 3622[102:440]
Dec 17 16:23:18 adam-nb acpid: notifying client 5237[0:0]
Dec 17 16:23:18 adam-nb acpid: executing action "/etc/acpi/default.sh processor CPU1 00000080 00000000"
Dec 17 16:23:18 adam-nb logger: ACPI event unhandled: processor CPU1 00000080 00000000
Dec 17 16:23:18 adam-nb acpid: action exited with status 0
Dec 17 16:23:18 adam-nb acpid: completed event "processor CPU1 00000080 00000000"
Dec 17 16:23:27 adam-nb acpid: received event "ac_adapter AC 00000080 00000001"
Dec 17 16:23:27 adam-nb acpid: notifying client 5237[0:0]
Dec 17 16:23:27 adam-nb acpid: notifying client 3622[102:440]
Dec 17 16:23:27 adam-nb acpid: notifying client 5237[0:0]
Dec 17 16:23:27 adam-nb acpid: executing action "/etc/acpi/default.sh ac_adapter AC 00000080 00000001"
Dec 17 16:23:27 adam-nb logger: ACPI event unhandled: ac_adapter AC 00000080 00000001
Dec 17 16:23:27 adam-nb acpid: action exited with status 0
Dec 17 16:23:27 adam-nb acpid: completed event "ac_adapter AC 00000080 00000001"
Dec 17 16:23:28 adam-nb acpid: received event "battery BAT0 00000080 00000001"
Dec 17 16:23:28 adam-nb acpid: notifying client 5237[0:0]
Dec 17 16:23:28 adam-nb acpid: notifying client 3622[102:440]
Dec 17 16:23:28 adam-nb acpid: notifying client 5237[0:0]
Dec 17 16:23:28 adam-nb acpid: executing action "/etc/acpi/default.sh battery BAT0 00000080 00000001"
Dec 17 16:23:28 adam-nb logger: ACPI event unhandled: battery BAT0 00000080 00000001
Dec 17 16:23:28 adam-nb acpid: action exited with status 0
Dec 17 16:23:28 adam-nb acpid: completed event "battery BAT0 00000080 00000001"
|
The sequence of acpi events seem very strange to me and causes issues with cpufreqd and other CPU scaling programs.
The "processor CPU<X>" events seems to cause the CPU scaling settings I've set to become ineffective when unplugging the AC.
Has anyone encountered the same issue.
Thanks
Last edited by mrpringle on Wed Dec 17, 2008 9:19 am; edited 1 time in total |
|
| Back to top |
|
 |
dmpogo
Advocate
Joined: 02 Sep 2004
Posts: 3468
Location: Canada
|
| Posted: Wed Dec 17, 2008 6:07 am Post subject: |
|
|
What's wrong here ? These are report from acpid what ACPI events were transmitted. Actually none of them were handled by acpid, and that's it.
They may have been handled by other programs that listen to acpi events themselves.
The only thing is that I don't think my laptop emits 'processor' events when AC is unplugged, is that what you are worried about ? |
|
| Back to top |
|
|
mrpringle
Apprentice
Joined: 27 May 2007
Posts: 284
|
| Posted: Wed Dec 17, 2008 7:41 am Post subject: |
|
|
| dmpogo wrote: | | What's wrong here ? |
There are two issues I think, NB: I cleared the messages log before unplugging the AC.
Why does an ac_adapter event occur initially followed by a battery event when I disconnected the AC and why does a battery event follow and ac event which reconnecting the power?
I would have expected to see an battery event when removing the cord and an AC event when plugging in the cord.
My main concern is with the processor CPU<X> event. To demonstrate what I mean, I disabled acpid and cpufreqd and set the governor to performance mode with a CPU max frequency of 100% (2.1GHz).
I unplugged the AC and 5 seconds later issued the cpufreq-set command to change max CPU frequency to 1.6GHz.
As soon as I unplugged the AC the CPU was scaled down to 800MHz and the cpufreq-set command had no affect. I have no idea why the CPU was scaled down, must be the BIOS kicking in and trying to do some power management itself, although I can't find any specific options in the BIOS menu.
I then repeated the exact same test as above, but ran the cpufreq-set command approximately 16 seconds after unplugging the AC. This time the CPU scaled to 1.6GHz when the cpufreq-set command executed.
To speculate I would say the processor CPUX events (which occur approximately 16 secs) apart are responsible for the CPU scaling down and not being allowed to scale up when the AC is initially disconnected. The solution would be to put an acpid trigger on the Processor CPUX event, but I was wondering whether anyone else has dealt with the same problem. |
|
| Back to top |
|
|
dmpogo
Advocate
Joined: 02 Sep 2004
Posts: 3468
Location: Canada
|
| Posted: Wed Dec 17, 2008 8:37 am Post subject: |
|
|
| mrpringle wrote: |
There are two issues I think, NB: I cleared the messages log before unplugging the AC.
Why does an ac_adapter event occur initially followed by a battery event when I disconnected the AC and why does a battery event follow and ac event which reconnecting the power?
I would have expected to see an battery event when removing the cord and an AC event when plugging in the cord.
[/code]
In both cases the status of the battery is changed, so no suprise the event is generated.
[code]
My main concern is with the processor CPU<X> event. To demonstrate what I mean, I disabled acpid and cpufreqd and set the governor to performance mode with a CPU max frequency of 100% (2.1GHz).
I unplugged the AC and 5 seconds later issued the cpufreq-set command to change max CPU frequency to 1.6GHz.
As soon as I unplugged the AC the CPU was scaled down to 800MHz and the cpufreq-set command had no affect. I have no idea why the CPU was scaled down, must be the BIOS kicking in and trying to do some power management itself, although I can't find any specific options in the BIOS menu.
I then repeated the exact same test as above, but ran the cpufreq-set command approximately 16 seconds after unplugging the AC. This time the CPU scaled to 1.6GHz when the cpufreq-set command executed.
To speculate I would say the processor CPUX events (which occur approximately 16 secs) apart are responsible for the CPU scaling down and not being allowed to scale up when the AC is initially disconnected. The solution would be to put an acpid trigger on the Processor CPUX event, but I was wondering whether anyone else has dealt with the same problem. |
This is more interesting but I need to sleep first  I suspect that (if you don't run cpufreqd daemon in the first place) you have some settings in your desktop power management that kick in. |
|
| Back to top |
|
|
mrpringle
Apprentice
Joined: 27 May 2007
Posts: 284
|
| Posted: Wed Dec 17, 2008 8:54 am Post subject: |
|
|
| dmpogo wrote: |
This is more interesting but I need to sleep first I suspect that (if you don't run cpufreqd daemon in the first place) you have some settings in your desktop power management that kick in. |
I forgot to mention it's a Dell XPS M1330 laptop. As I said I've been through the BIOS and the only settings which stood out were the intel speedstep (enabled / off) and dynamic acceleration (enabled / off). I have left these both as enabled which is the default settings. |
|
| Back to top |
|
|
dmpogo
Advocate
Joined: 02 Sep 2004
Posts: 3468
Location: Canada
|
| Posted: Wed Dec 17, 2008 6:25 pm Post subject: |
|
|
| mrpringle wrote: |
To speculate I would say the processor CPUX events (which occur approximately 16 secs) apart are responsible for the CPU scaling down and not being allowed to scale up when the AC is initially disconnected. |
Actually, your speculation is correct. I looked into ACPI specification at
http://www.acpi.info/spec30a.htm
and as far as I understand, in the event description
| Code: |
processor CPU0 00000080 00000004
|
00000080 means the notification that the CPU performance state description is changed, while 0000004 says that now only
states P4 and above are available (states are numbered P0 ... Pn with P0 being the highest frequency one). I bet P4 state
is 800Mhz for you.
and indeed 16 sec later, new event
| Code: |
processor CPU0 00000080 00000000
|
tells that now all the states from P0 onwards are available.
You can check the hypothesis by manually reading info in /proc/acpi/processor/CPU0
Now why is it done, I don't know. It could be SpeedStep. |
|
| Back to top |
|
|
mrpringle
Apprentice
Joined: 27 May 2007
Posts: 284
|
| Posted: Wed Dec 17, 2008 10:46 pm Post subject: |
|
|
| dmpogo wrote: | | mrpringle wrote: |
To speculate I would say the processor CPUX events (which occur approximately 16 secs) apart are responsible for the CPU scaling down and not being allowed to scale up when the AC is initially disconnected. |
Actually, your speculation is correct. I looked into ACPI specification at
http://www.acpi.info/spec30a.htm
and as far as I understand, in the event description
| Code: |
processor CPU0 00000080 00000004
|
00000080 means the notification that the CPU performance state description is changed, while 0000004 says that now only
states P4 and above are available (states are numbered P0 ... Pn with P0 being the highest frequency one). I bet P4 state
is 800Mhz for you.
and indeed 16 sec later, new event
| Code: |
processor CPU0 00000080 00000000
|
tells that now all the states from P0 onwards are available.
You can check the hypothesis by manually reading info in /proc/acpi/processor/CPU0
Now why is it done, I don't know. It could be SpeedStep. |
Wow, after searching google for hours I could not find anything useful, I suppose you just need to know where to look. I'll play around with the BIOS settings and see what I can come up with.
Thanks for your help. |
|
| Back to top |
|
|
dmpogo
Advocate
Joined: 02 Sep 2004
Posts: 3468
Location: Canada
|
| Posted: Thu Dec 18, 2008 4:49 am Post subject: |
|
|
well, that was easy, I put
processor CPU0 00000080 00000004
as a search item into google BTW, it is a strategy I found really useful - just cut a paste an error or info message into Google.
When I think why is it happening, wild ideas come to my mind - like some engineers found that on this model switch to battery
cases a bit of instability which may hang CPU at highest frequency, so they programmed BIOS to go to the lowest frequency for few sec until
system sabilizes |
|
| Back to top |
|
|
|
Kernel & Hardware
