Bug 8288

Summary: acpi logs flood by "processor CPU1" events
Product: ACPI Reporter: Michalis Giannakidis (mgiannakidis)
Component: Power-ProcessorAssignee: Alexey Starikovskiy (astarikovskiy)
Status: CLOSED CODE_FIX    
Severity: normal CC: acpi-bugzilla, corsac, kernel
Priority: P2    
Hardware: i386   
OS: Linux   
Kernel Version: 2.6.19-gentoo-r5, 2.6.20-gentoo-r4 , 2.6.21-rc5 Subsystem:
Regression: --- Bisected commit-id:
Attachments: Output of acpidump
Don't send repeating event

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