Bug 461441 - severe performance degradation on x86_64 going from 2.6.26 -> 2.6.27
severe performance degradation on x86_64 going from 2.6.26 -> 2.6.27
Status: CLOSED RAWHIDE
Product: Fedora
Classification: Fedora
Component: kernel (Show other bugs)
rawhide
All Linux
medium Severity high
: ---
: ---
Assigned To: Kernel Maintainer List
Fedora Extras Quality Assurance
http://bugzilla.kernel.org/show_bug.c...
:
Depends On:
Blocks:
  Show dependency treegraph
 
Reported: 2008-09-07 22:17 EDT by Jason Vas Dias
Modified: 2008-11-09 15:43 EST (History)
1 user (show)

See Also:
Fixed In Version:
Doc Type: Bug Fix
Doc Text:
Story Points: ---
Clone Of:
Environment:
Last Closed: 2008-11-09 15:43:11 EST
Type: ---
Regression: ---
Mount Type: ---
Documentation: ---
CRM:
Verified Versions:
Category: ---
oVirt Team: ---
RHEL 7.3 requirements from Atomic Host:


Attachments (Terms of Use)
kernel config for the 2.6.27-rc7.jvd version (20.98 KB, application/x-bzip2)
2008-09-25 23:02 EDT, Jason Vas Dias
no flags Details
System.map for the 2.6.27-7.rc7.jvd.bz2 version (309.45 KB, application/x-bzip2)
2008-09-25 23:03 EDT, Jason Vas Dias
no flags Details
boot log from boot, which took @15 minutes to display a login: prompt (38.85 KB, application/x-bzip2)
2008-09-25 23:04 EDT, Jason Vas Dias
no flags Details
dmesg boot output from 2.6.27-tip-rc7.jvd (480.49 KB, application/octet-stream)
2008-09-28 04:46 EDT, Jason Vas Dias
no flags Details
all acpi info (528.06 KB, application/octet-stream)
2008-09-28 05:20 EDT, Jason Vas Dias
no flags Details


External Trackers
Tracker ID Priority Status Summary Last Updated
Linux Kernel 11516 None None None Never

  None (edit)
Description Jason Vas Dias 2008-09-07 22:17:43 EDT
Description of problem:
This is a duplicate of kernel.org bug <a href="http://bugzilla.kernel.org/show_bug.cgi?id=11516"> 11516 </a>, as it not only happens with these
upstream kernel 2.6.27-rc5 trees :
  git://git.kernel.org/pub/scm/linux/kernel/git/arjan/linux-2.6-hrtimer.git
  git://git.kernel.org/pub/scm/linux/kernel/git/torvalds/linux-2.6.git
but also with your latest 2.6.27-0.312.rc5.git7.fc10.x86_64 release.

Upgrading with yum from 2.6.26-0.115.rc9.git2.fc10 to 2.6.27-0.305.rc5.git6.fc10
(and now also 2.6.27-0.312.rc5.git7.fc10) resulted in SEVERE performance 
degradation - it made my AMD TL-64 dual-core 2.2Ghz laptop perform like my first
i286 with 512K RAM machine . The boot-up sequence, from boot to displaying the
X-Windows login prompt, went from taking <1 minute to over 15 minutes. 

Just thought I should let you know - please see full details at:
  http://bugzilla.kernel.org/show_bug.cgi?id=11516

Version-Release number of selected component (if applicable):
2.6.27-0.312.rc5.git7.fc10, 2.6.26-0.115.rc9.git2.fc10

How reproducible:
100%

Steps to Reproduce:
Upgrade with yum / pup to latest rawhide kernel
  
Actual results:
system is hosed - @ 1500% performance degradation.

Expected results:
system should perform as well as or better than with previous releases

Additional info:
Logs, details at: http://bugzilla.kernel.org/show_bug.cgi?id=11516
Comment 1 Jason Vas Dias 2008-09-25 22:58:11 EDT
Does anyone actually maintain the Fedora RawHide / Development kernels, or 
are they just there for show ?

This is still happening with latest 2.6.27 based kernels. I've tried 
latest linux-2.6-tip and linux-2.6-acpi git kernels, and combining their
diffs with Linus' latest linux-2.6 tree, and tried your latest 
2.6.27-0.352.rc7.git1.fc10.x86_64 kernel, with udev-{124,126,128} versions,
with the same results :
 
CPU RUNS AT LOWEST FREQUENCY AND CPU FREQUENCY SWITCHING IS COMPLETELY DISABLED

My CPU runs at 2.2GHz under the 2.6.26 kernels, but at 800KHz under the 2.6.27
kernels, both upstream and Fedora, compiled with either gcc-4.2.4 or gcc-4.3.2
or gcc-3.4.6, under either my own (initially Gentoo based) distro or under
Fedora Core 10 Rawhide distro , with very similar configs, and all get the 
same results.

The powernow-k8 driver and all governor modules load without complaint, and do
not produce any messages when valid configuration commands are issued:
  $ echo 2200000 > /sys/devices/system/cpu/cpu0/cpufreq/scaling_max_freq
  $ echo 2200000 > /sys/devices/system/cpu/cpu0/cpufreq/scaling_setspeed
  $ cat /sys/devices/system/cpu/cpu0/cpufreq/scaling_cur_freq
  800000

PS: why can't powernow-k8 be auto-loaded by udev ? I'm sure it used to be ...

The above command sequence prints "2200000" at the end under 2.6.26 kernels.

I've tried completely disabling USB and ACPI, with the same result.

I've attached the System.map, config, and boot.log from the occurence of this
bug, and what I said about 2.6.27-6 still holds for 2.6.27-7 .

Re: [Bug #11516] severe performance degradation on x86_64 going from 2.6.26-rc9 -&gt; 2.6.27-rc5
From: 
Jason Vas Dias <jason.vas.dias@gmail.com>
  To: 
"Rafael J. Wysocki" <rjw@sisk.pl>, Andrew Morton <akpm@linux-foundation.org>
  CC: 
Linux Kernel Mailing List <linux-kernel@vger.kernel.org>, Kernel Testers List <kernel-testers@vger.kernel.org>
  Date: 
Tuesday 05:49:28
   
Hi - 
Yes, this bug is still a problem with both the latest 2.6.27-rc6 kernel (from Linus' tree 2008-09-21)
and with the latest fedora 10 kernel .

CPU Frequency switching is completely disabled both when powernow-k8 (the correct cpufreq module for my
x86_64 AMD TL-64x2 2.2GHz CPU) is installed as a module or is built-in , and the CPU frequency remains
at its lowest setting; attempts to modify /sys/devices/system/cpu/cpu0/cpufreq/scaling_max_freq
and /sys/devices/system/cpu/cpu0/cpufreq/scaling_setspeed are not honored, even though 
/sys/devices/system/cpu/cpu0/cpufreq/governor is "userspace" 
and scaling_min_freq < scaling_setspeed > scaling_max_freq .

I see no messages from powernow-k8 indicating that it is aware it was unable to set the speed, though
I do see a message if I attempt to set an invalid speed (eg 600000) .

With 2.6.26-rc9, I get a default CPU clock frequency of 2200000 ; with 2.6.27-rc6, it becomes 800000 and
is not switchable. For some reason, powernow-k8 does not autoload with UDEV; but I don't really need it if
the speed is already set to its highest level.

On 2.6.27-rc6. after it manages to boot, any low-latency drivers time out (eg. USB, Terminal, Keyboard, Network) 
and the machine does not get through the boot-up sequence without becoming overloaded by the kernel's debugging log messages -
neither the network , the terminal or the keyboard work usably. 

Building a kernel with USB completely disabled and turning off debug log messages allows the machine to boot 
(after @ 15 minutes) but the speed is still at its lowest setting and cannot be changed.

Also, 2.6.27-rc6 is unable to reboot the machine: it can put the machine into the "HALT" state, with nothing displayed
on the screen, but the machine does not power-off until manual reset with the power-button. Then, after the machine
has powered-down, it cannot be powered up until the power-on button is depressed for at least two sections an released TWICE
in a row.

Neither booting with 'acpi=0' or compilation without USB support has any effect; it happens the same with a totally
standard Fedora 10 install with the latest 2.6.27 kernel as with my own heavily customized distro , and occurs when either
udev-{124,126,128} are installed, and regardless of compiling the kernel with gcc-4.2.4 , gcc-3.4.6, or gcc-4.3.2 .

Any help / suggestions would be greatly appreciated ! I've attached the Config, System.map and boot.log (compressed) .

Regards,
Jason
Comment 2 Jason Vas Dias 2008-09-25 23:02:55 EDT
Created attachment 317755 [details]
kernel config for the 2.6.27-rc7.jvd version
Comment 3 Jason Vas Dias 2008-09-25 23:03:35 EDT
Created attachment 317756 [details]
System.map for the 2.6.27-7.rc7.jvd.bz2 version
Comment 4 Jason Vas Dias 2008-09-25 23:04:25 EDT
Created attachment 317757 [details]
boot log from boot, which took @15 minutes to display a login: prompt
Comment 5 Dave Jones 2008-09-26 00:31:47 EDT
booting with cpufreq.debug=7 should give some clues as to why it's picking the slow speed by default.  Attach the dmesg log from that. (please don't bzip them either, as that makes them unviewable in the browser).
Comment 6 Jason Vas Dias 2008-09-28 04:46:04 EDT
Created attachment 317890 [details]
dmesg boot output from 2.6.27-tip-rc7.jvd
Comment 7 Jason Vas Dias 2008-09-28 05:18:28 EDT
Hi Dave - thanks! 

I did as you suggested and booted with cpufreq.debug=7 .

I've attached the log.

Here is a "typescript" log of attempting to set the frequency and dmesg output
after each action, running the latest 2.6.27-rc7-tip tree 
( http://git.kernel.org/?p=linux/kernel/git/x86/linux-2.6-tip.git;a=commit;h=c4077bb0691bcd26c546daa52b76a47ba954fc49 ) :

<![CDATA[
Script started on Sun Sep 28 03:33:44 2008
$ for f in  /sys/devices/system/cpu/cpu0/cpufreq/*; do echo '+++ '$f:; cat $f; echo '---'; donedevices/system/cpu/cpu0/cpufreq/*
+++ /sys/devices/system/cpu/cpu0/cpufreq/affected_cpus:
0 1
---
+++ /sys/devices/system/cpu/cpu0/cpufreq/cpuinfo_cur_freq:
800000
---
+++ /sys/devices/system/cpu/cpu0/cpufreq/cpuinfo_max_freq:
2200000
---
+++ /sys/devices/system/cpu/cpu0/cpufreq/cpuinfo_min_freq:
800000
---
+++ /sys/devices/system/cpu/cpu0/cpufreq/related_cpus:
0 1
---
+++ /sys/devices/system/cpu/cpu0/cpufreq/scaling_available_frequencies:
2200000 2000000 1800000 1600000 800000
---
+++ /sys/devices/system/cpu/cpu0/cpufreq/scaling_available_governors:
ondemand powersave userspace performance
---
+++ /sys/devices/system/cpu/cpu0/cpufreq/scaling_cur_freq:
800000
---
+++ /sys/devices/system/cpu/cpu0/cpufreq/scaling_driver:
powernow-k8
---
+++ /sys/devices/system/cpu/cpu0/cpufreq/scaling_governor:
userspace
---
+++ /sys/devices/system/cpu/cpu0/cpufreq/scaling_max_freq:
880000
---
+++ /sys/devices/system/cpu/cpu0/cpufreq/scaling_min_freq:
800000
---
+++ /sys/devices/system/cpu/cpu0/cpufreq/scaling_setspeed:
800000
---
$ dmesg -c > dev/null
$ echo 2200000 > /sys/devices/system/cpu/cpu0/cpufreq/scaling_max_freq
$ echo 2200000 > /sys/devices/system/cpu/cpu0/cpufreq/scaling_setspeed
$ cat /sys/devices/system/cpu/cpu0/cpufreq/scaling_max_freq;  cat  /sys/devices/system/cpu/cpu0/cpufreq/scaling_setspeed
880000
800000
root@jvdspc:/home/jason/2.6.27-tip-rc7.jvd$ dmesg
# ( @ 100 USB messages :
[ 2557.957726] hub 3-0:1.0: state 7 ports 2 chg 0000 evt 0000

[ 2558.206950] hub 1-0:1.0: state 7 ports 2 chg 0000 evt 0000

[ 2558.208051] hub 3-0:1.0: state 7 ports 2 chg 0000 evt 0000

[ 2558.456366] hub 1-0:1.0: state 7 ports 2 chg 0000 evt 0000

[ 2558.457971] hub 3-0:1.0: state 7 ports 2 chg 0000 evt 0000

[ 2558.706019] hub 1-0:1.0: state 7 ports 2 chg 0000 evt 0000

[ 2558.707028] hub 3-0:1.0: state 7 ports 2 chg 0000 evt 0000

[ 2558.955902] hub 1-0:1.0: state 7 ports 2 chg 0000 evt 0000

[ 2558.956201] hub 3-0:1.0: state 7 ports 2 chg 0000 evt 0000

[ 2559.205958] hub 1-0:1.0: state 7 ports 2 chg 0000 evt 0000

# ...
[ 2611.636188] APIC error on CPU1: 40(40)
[ 2611.636354] APIC error on CPU0: 40(40)
# ...
[ 2618.206172] hub 1-0:1.0: state 7 ports 2 chg 0000 evt 0000

[ 2618.207182] hub 3-0:1.0: state 7 ports 2 chg 0000 evt 0000

[ 2618.455341] hub 1-0:1.0: state 7 ports 2 chg 0000 evt 0000

[ 2618.455341] hub 3-0:1.0: state 7 ports 2 chg 0000 evt 0000

[ 2618.707874] hub 1-0:1.0: state 7 ports 2 chg 0000 evt 0000

[ 2618.708174] hub 3-0:1.0: state 7 ports 2 chg 0000 evt 0000

# ... )
[ 2618.755459] cpufreq-core: setting new policy for CPU 0: 800000 - 2200000 kHz
[ 2618.755727] freq-table: request for verification of policy (800000 - 2200000 kHz) for cpu 0
[ 2618.755959] freq-table: verification lead to (800000 - 2200000 kHz) for cpu 0
[ 2618.756966] freq-table: request for verification of policy (800000 - 880000 kHz) for cpu 0
[ 2618.757433] freq-table: verification lead to (800000 - 880000 kHz) for cpu 0
[ 2618.757667] cpufreq-core: new min and max freqs are 800000 - 880000 kHz
[ 2618.757866] cpufreq-core: governor: change or update limits
[ 2618.758300] cpufreq-core: __cpufreq_governor for CPU 0, event 3
[ 2618.758500] userspace: limit event for cpu 0: 800000 - 880000 kHz, currently 800000 kHz, last set to 2200000 kHz
[ 2618.758767] cpufreq-core: target for CPU 0: 880000 kHz, relation 1
[ 2618.759296] powernow-k8: targ: cpu 0, 880000 kHz, min 800000, max 880000, relation 1
[ 2618.759496] powernow-k8: targ: curr fid 0x0, vid 0x1e
[ 2618.759666] freq-table: request for target 880000 kHz (relation: 1) for cpu 0
[ 2618.759863] freq-table: target is 4 (800000 kHz, 7680)
[ 2618.760327] powernow-k8: cpu 0 transition to index 4
[ 2618.760497] powernow-k8: table matched fid 0x0, giving vid 0x1e
[ 2618.760662] powernow-k8: target matches current values (fid 0x0, vid 0x1e)
[ 2643.387590] userspace: cpufreq_set for cpu 0, freq 2200000 kHz
[ 2643.387856] cpufreq-core: target for CPU 0: 880000 kHz, relation 0
[ 2643.388891] powernow-k8: targ: cpu 0, 880000 kHz, min 800000, max 880000, relation 0
[ 2643.389328] powernow-k8: targ: curr fid 0x0, vid 0x1e
[ 2643.389527] freq-table: request for target 880000 kHz (relation: 0) for cpu 0
[ 2643.389759] freq-table: target is 4 (800000 kHz, 7680)
[ 2643.390364] powernow-k8: cpu 0 transition to index 4
[ 2643.390561] powernow-k8: table matched fid 0x0, giving vid 0x1e
[ 2643.390826] powernow-k8: target matches current values (fid 0x0, vid 0x1e)
$ dmesg -c > /dev/null ;  
$ cat  /sys/devices/system/cpu/cpu0/cpufreq/scaling_max_freq /sys/devices/system/cpu/cpu0/cpufreq/scaling_setspeed
880000
800000
$ exit
Script done on Sun Sep 28 03:49:44 2008
]]>

Sorry about the bzips - bugzilla wouldn't accept one of the files because it
was too large, so I bzip'ed them all.

BTW, I would have gathered logs from latest Fedora 10 Rawhide, kernel 
2.6.27-0.352.rc7.git1.fc10, which has the same problem, but the new Fedora 
boot-up sequence makes it impossible .
With the boot args:
'kernel /boot/vmlinuz-2.6.27-0.352.rc7.git1.fc10.x86_64 root=/dev/sda10 enforcing=0 audit=0 smack=0 debug debug.cpufreq=7 rhgb=0 netconsole=6666@135.207.58.230/eth0,666
6@135.207.58.227/ vga=0x356 1
'
In vesa mode, when the new / modifed "PCI Radeon Express" driver is
loaded, a "blank white screen of death" is displayed, VT switching is
disabled , and seemingly the "rc" script is never run, because my 
"dmesg > /var/log/boot.dmesg.log" that I added to it is never executed. 
In VGA mode, I can see the boot-up initially for a few seconds, but then the
boot argument "rhgb=0" is ignored, and X is started up; the silly "Fedora" splash screen was displayed for over an hour without a gdm or terminal login
appearing - VT switching was again disabled, and my "dmesg" commands in the rc scripts were never run , so no logs could be gathered from the Fedora kernel. Also, netconsole seems to be disabled, or the boot argument 
'netconsole=6666@135.207.58.230/eth0,6666@135.207.58.227/' is ignored - 
or perhaps it didn't get to initializing eth0 within the hour it had .
The last Fedora kernel I was able to run was 2.6.27-0.323.rc6.fc10, which
had the same crawling 0.8Ghz speed and frequency switch problems . I guess
I'll have to remove 'rhgb*.rpm' and try again . 

I'm looking at hacking around the cpufreq code with crash(1) to see if I can
figure out what the issue is .

It seems to be that this log sequence shows several issues :

[ 2643.387590] userspace: cpufreq_set for cpu 0, freq 2200000 kHz

no, it wasn't ! this message suggests the frequency was set to 2200000 kHz,
when it was not.

[ 2643.387856] cpufreq-core: target for CPU 0: 880000 kHz, relation 0

Now it seems to be confused - wasn't it trying to set the freq to 2200000 kHz ?

[ 2643.388891] powernow-k8: targ: cpu 0, 880000 kHz, min 800000, max 880000, relation 0
[ 2643.389328] powernow-k8: targ: curr fid 0x0, vid 0x1e
[ 2643.389527] freq-table: request for target 880000 kHz (relation: 0) for cpu 0

No, the request was for 2200000 kHz !!

It seems to me that cpufreq should not require a special debug.cpufreq setting to inform the user that their request for a new frequency 
    A) failed to be set
    B) was set successfully
IMHO, a dmesg should be emitted unconditionally on debug level 
in either case.

I think this whole issue and the USB message flood are all due to the kernel
being completely confused about its timing parameters, owing to ACPI not being
set up correctly. I've attached a dump of all ACPI info, more @ the kernel.org
bug report:  http://bugzilla.kernel.org/show_bug.cgi?id=11516 .
Comment 8 Jason Vas Dias 2008-09-28 05:20:33 EDT
Created attachment 317893 [details]
all acpi info

Output of command:
$ (find /proc/acpi -type f | while read f; do if [[  "$f" != /proc/acpi/event
]]; then  echo '+++ '$f':';  if [[ $f =~ dt$ ]]; then od -cx $f; else cat $f;
echo '---'; fi; fi; done) 2>&1
Comment 9 Christopher D. Stover 2008-11-02 16:38:04 EST
Jason, it appears this is fixed after looking at the upstream kernel bug tracker.  Can you confirm this so we can close this Jason?
Comment 10 Christopher D. Stover 2008-11-09 15:43:11 EST
Bug is fixed upstream.

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