Bug 8288 - acpi logs flood by "processor CPU1" events
acpi logs flood by "processor CPU1" events
Status: CLOSED CODE_FIX
Product: ACPI
Classification: Unclassified
Component: Power-Processor
i386 Linux
: P2 normal
Assigned To: Alexey Starikovskiy
:
Depends on:
Blocks:
  Show dependency treegraph
 
Reported: 2007-03-31 03:00 UTC by Michalis Giannakidis
Modified: 2008-05-16 13:35 UTC (History)
3 users (show)

See Also:
Kernel Version: 2.6.19-gentoo-r5, 2.6.20-gentoo-r4 , 2.6.21-rc5
Tree: Mainline
Regression: ---


Attachments
Output of acpidump (70.10 KB, application/octet-stream)
2007-11-20 15:29 UTC, Michalis Giannakidis
Details
Don't send repeating event (838 bytes, patch)
2007-11-20 15:39 UTC, Alexey Starikovskiy
Details | Diff

Description Michalis Giannakidis 2007-03-31 03:00:59 UTC
Most recent kernel where this bug did *NOT* occur: unknown
Distribution: gentoo Linux
Hardware Environment:  i686 Intel(R) Pentium(R) M processor
Software Environment: gentoo Linux
Problem Description: 

System logs (/var/log/acpi ) floods with messages like 'received event
"processor CPU1 00000080 00000004"'.
Seems to be coming from CONFIG_ACPI_PROCESSOR

Steps to reproduce:

(The following messages are form 2.6.19-gentoo-r5, but the same also occurs
under 2.6.21-rc5)

When I compile the kernel to use CONFIG_ACPI_PROCESSOR:
  | Prompt: Processor                                                     
  │   Defined at drivers/acpi/Kconfig:141                                    
  │   Depends on: !X86_VOYAGER && !X86_VISWS && !IA64_HP_SIM && (IA64 || X8
  │   Location:                                                            
  │     -> Power management options (ACPI, APM)                            
  │       -> ACPI (Advanced Configuration and Power Interface) Support     
  │         -> ACPI Support (ACPI [=y]

and CPU Frequency scaling (module: speedstep_centrino)
system logs (/var/log/acpi ) floods with event messages.
Actual Results:  
[Fri Mar 23 00:22:36 2007] received event "processor CPU1 00000080 00000004"
[Fri Mar 23 00:22:36 2007] notifying client 5512[103:409]
[Fri Mar 23 00:22:36 2007] notifying client 5785[0:0]
[Fri Mar 23 00:22:36 2007] executing action "/etc/acpi/default.sh processor
CPU1 00000080 00000004"
[Fri Mar 23 00:22:36 2007] BEGIN HANDLER MESSAGES
[Fri Mar 23 00:22:36 2007] END HANDLER MESSAGES
[Fri Mar 23 00:22:36 2007] action exited with status 0
[Fri Mar 23 00:22:36 2007] completed event "processor CPU1 00000080 00000004"
[Fri Mar 23 00:22:52 2007] received event "processor CPU1 00000080 00000004"
[Fri Mar 23 00:22:52 2007] notifying client 5512[103:409]
[Fri Mar 23 00:22:52 2007] notifying client 5785[0:0]
[Fri Mar 23 00:22:52 2007] executing action "/etc/acpi/default.sh processor
CPU1 00000080 00000004"
[Fri Mar 23 00:22:52 2007] BEGIN HANDLER MESSAGES
[Fri Mar 23 00:22:52 2007] END HANDLER MESSAGES
[Fri Mar 23 00:22:52 2007] action exited with status 0
[Fri Mar 23 00:22:52 2007] completed event "processor CPU1 00000080 00000004"


ACPI Processor seems to be needed for speedstep_centrino and CPU frequency
scaling to work.

Removing ACPI Processor support stops the messages, and brakes
speedstep_centrino.

The same bug has also been reported in gentoo bugzilla:
http://bugs.gentoo.org/show_bug.cgi?id=171860
Comment 1 Michalis Giannakidis 2007-04-11 08:32:01 UTC
I also noticed, that if I start cpufreqd ( /etc/init.d/cpufreqd start ) the
number of events reaching the acpid log increases. The increase is from one
event every 30 sec (in kernel 2.6.21-rc5), to many events per second.
Comment 2 Venkatesh Pallipadi 2007-09-13 17:51:33 UTC
Can you try to go to init 1 and check whether you still see these messages?
Comment 3 Michalis Giannakidis 2007-09-17 09:03:47 UTC
I switch to init 1 (by telinit 1)

The same CPU1 messages appear in the acpi log, when both acpid and cpufreqd have been started.
Comment 4 Michalis Giannakidis 2007-10-23 08:32:26 UTC
I made these changes in my kernel config:
246c246
< CONFIG_ACPI_SLEEP_PROC_SLEEP=y
---
> # CONFIG_ACPI_SLEEP_PROC_SLEEP is not set
248,250c248,250
< CONFIG_ACPI_AC=y
< CONFIG_ACPI_BATTERY=y
< CONFIG_ACPI_BUTTON=y
---
> CONFIG_ACPI_AC=m
> CONFIG_ACPI_BATTERY=m
> CONFIG_ACPI_BUTTON=m
660c660,663
< # CONFIG_THINKPAD_ACPI is not set
---
> CONFIG_THINKPAD_ACPI=m
> # CONFIG_THINKPAD_ACPI_DEBUG is not set
> # CONFIG_THINKPAD_ACPI_DOCK is not set
> CONFIG_THINKPAD_ACPI_BAY=y
678c681
< # CONFIG_BLK_DEV_IDEACPI is not set
---
> CONFIG_BLK_DEV_IDEACPI=y

I noticed that the acpid messages are generated only when the ac module is loaded. Also, the messages (in my case) seem to have two sources/clients.

One source is the klaptop application with probes for the status of the battery, by default every 20 sec. I changed that, and the acpid log messages moved 30 sec apart.

The other source is related to hald-addon-acpi (pid of client in the logs). I don't know what triggers this event. Again, this is related to the ac module. 
Comment 5 Alexey Starikovskiy 2007-11-20 14:28:38 UTC
Michalis,
could you please attach acpidump output?
Comment 6 Michalis Giannakidis 2007-11-20 15:29:11 UTC
Created attachment 13663 [details]
Output of acpidump

I attach the acpidump output.

See also the initial report in gentoo bugzilla, where others, with different setups, have also reported the same issue.
Comment 7 Alexey Starikovskiy 2007-11-20 15:39:02 UTC
Created attachment 13664 [details]
Don't send repeating event

Please try this patch
Comment 8 Michalis Giannakidis 2007-11-21 10:16:37 UTC
I upgraded the kernel to Linux 2.6.23-gentoo-r2, applied the patch. The acpi events are not repeated in the acpid logs. 

Fixed? Any tests I should run?
Comment 9 Alexey Starikovskiy 2007-11-21 10:57:13 UTC
No, thanks for testing.
Comment 10 Venkatesh Pallipadi 2008-01-15 14:10:31 UTC
Alexey,

Shouldn't saved be percpu for SMP case?

Thanks,
Venki
Comment 11 Alexey Starikovskiy 2008-01-15 14:27:39 UTC
Venki,
saved is allocated on the stack of the routine, so each time you enter the function for each processor, you will get new location for a variable, so 
percpu is not needed. If you choose to save something on a heap -- in some struct or globally, you should use percpu... IMHO...
Comment 12 Venkatesh Pallipadi 2008-01-16 18:16:02 UTC
Oops. I read the patch wrong. You are right. This patch looks fine.

Thanks,
Venki
Comment 13 Len Brown 2008-01-17 02:44:03 UTC
The patch in comment #7 was applied as commit
e790cc8bbb990df900eabdda18a5a480d22a60c8
"ACPI: EC: Workaround for optimized controllers (version 3)"
in linux-2.6.24.rc4 for bug 9327

closed.
Comment 14 Alexey Starikovskiy 2008-01-17 03:17:59 UTC
Len,
this is not for 8288...

Regards,
Alex.
bugme-daemon@bugzilla.kernel.org wrote:
> http://bugzilla.kernel.org/show_bug.cgi?id=8288
> 
> 
> len.brown@intel.com changed:
> 
>            What    |Removed                     |Added
> ----------------------------------------------------------------------------
>              Status|RESOLVED                    |CLOSED
> 
> 
> 
> 
> ------- Comment #13 from len.brown@intel.com  2008-01-17 02:44 -------
> The patch in comment #7 was applied as commit
> e790cc8bbb990df900eabdda18a5a480d22a60c8
> "ACPI: EC: Workaround for optimized controllers (version 3)"
> in linux-2.6.24.rc4 for bug 9327
> 
> closed.
> 
> 

Comment 15 Yves-Alexis Perez 2008-05-05 12:11:52 UTC
Using 2.6.25.1 I still have a lot of these logs here:

corsac@hidalgo: grep -c "received event \"processor" /var/log/syslog
8468

Linux hidalgo 2.6.25.1 #8 SMP Sun May 4 18:00:18 CEST 2008 x86_64 GNU/Linux

If you need more info…
Comment 16 Zhang Rui 2008-05-11 19:40:30 UTC
The patch for this problem is already upstream.
So please try the latest kernel release to see if the problem still exists.
If yes, it should be a different problem, please open another bug report.
Comment 17 Diogo Condeço 2008-05-16 13:35:22 UTC
I'm using a 2.6.25-18 kernell in my Asus laptop with fedora 9 and the BUG continues.

When I execute acpi_listen it shows tons of:
"processor CPU1 00000081 00000000". And after a while it crashes, leaving no trace behind. I've checked the logs, and keeped the laptop in a terminal expecting something to be shown but nothing. This happens with livecd too.

The output of top shows me that kacpi_notify, kacpid and udev are consuming almost all the CPU.

Previous kernels have the same problem.

Any more info feel free to ask.

Best regards,
Diogo Condeço

Note You need to log in before you can comment on or make changes to this bug.