Bug 11516
|
Description
Jason Vas Dias
2008-09-07 13:59:03 UTC
Created attachment 17659 [details]
reboot log
kernel log messages (with debug enabled) showing a boot of 2.6.26-rc5 , then, following the line beginning "REBOOT", a boot of 2.6.27-rc9
Created attachment 17660 [details]
kernel config for the 2.6.26-rc9 version
Created attachment 17661 [details]
kernel config for the 2.6.27-rc5 version
As seen from the <a href="http://bugzilla.kernel.org/attachment.cgi?id=17659&action=view"> Reboot Log attachment </a>, the time for the 2.6.26-rc9 boot up was @ 10 seconds: Sep 7 12:33:42 localhost kernel: Loaded 41213 symbols from /boot/System.map-2.6.26-rc9.jvd. Sep 7 12:33:53 localhost init: Entering runlevel: 3 The 2.6.27-rc5 initial boot up took 10 minutes, and the System.map file is not found (even though it DOES exist and is identical to the System.map from the build) and the log daemon is so flooded by these new "hub 3-0:1.0: state 7" messages that it gives up and exits - I did not kill it . Sep 7 15:56:33 localhost kernel: Inspecting /boot/System.map Sep 7 15:56:33 localhost kernel: Cannot find map file. Sep 7 15:56:42 localhost dhclient: bound to 135.207.58.230 -- renewal in 1721 seconds. Sep 7 15:57:01 localhost kernel: [ 50.204477] hub 3-0:1.0: state 7 ports 2 chg 0000 evt 0000 Sep 7 15:57:01 localhost kernel: [ 50.454454] hub 1-0:1.0: state 7 ports 2 chg 0000 evt 0000 Sep 7 15:57:01 localhost kernel: [ 50.454462] hub 3-0:1.0: state 7 ports 2 chg 0000 evt 0000 Sep 7 15:57:01 localhost kernel: Kernel logging (proc) stopped. S After @ 10mins of a single-user boot, a prompt was finally displayed. I then tried to reboot, and after the machine entered the "HALT" state (blank screen) it was unable to power-off - I had to manually reset using the power button twice before it was able to reboot. Exactly the same behavior occurs with the latest Fedora 10 kernel, so I don't think it's my config. I'm guessing it has something to do with CONFIG_TICK_ONESHOT=y CONFIG_NO_HZ=y CONFIG_HIGH_RES_TIMERS=y ... CONFIG_HZ_1000=y CONFIG_HZ=1000 CONFIG_SCHED_HRTICK=y and that's where I'll start investigating - also I noticed Arjan's "high res timer" tree and think I'll try that next - but I thought this was already in Linus' tree? Anyone got any other suggestions ? Reply-To: akpm@linux-foundation.org (switched to email. Please respond via emailed reply-to-all, not via the bugzilla web interface). On Sun, 7 Sep 2008 13:59:04 -0700 (PDT) bugme-daemon@bugzilla.kernel.org wrote: > http://bugzilla.kernel.org/show_bug.cgi?id=11516 > > Summary: severe performance degradation on x86_64 going from > 2.6.26-rc9 -> 2.6.27-rc5 > Product: Other > Version: 2.5 > KernelVersion: 2.6.27-rc9 > Platform: All > OS/Version: Linux > Tree: Mainline > Status: NEW > Severity: normal > Priority: P1 > Component: Other > AssignedTo: other_other@kernel-bugs.osdl.org > ReportedBy: jason.vas.dias@gmail.com > > > Latest working kernel version: > 2.6.26-rc9 > (git://git.kernel.org/pub/scm/linux/kernel/git/torvalds/linux-2.6.git > @2008-07-10) > > Earliest failing kernel version: > 2.6.27-rc9 > (git://git.kernel.org/pub/scm/linux/kernel/git/torvalds/linux-2.6.git > @2008-09-07) > > Distribution: > Gentoo / my Own + Fedora 10 > > Hardware Environment: > x86_64 AMD Turion TL-64 64-bit dual core > > Software Environment: > gcc-4.2.4 , glibc-2.8.90, both latest from savannah CVS @ 2008-07-10 > > Problem Description: > > After my monthly kernel update ( git-pull from Linus' tree + build ) > the whole machine started crawling instead of sprinting - this was > on my "own distro" (originally Gentoo based). > > Updating Fedora 10 from 2.6.26-0.115.rc9.git2.fc10 to > 2.6.27-0.305.rc5.git6.fc10 had the same effect > on a bog-standard Fedora 10 installation. > > Before I get out the toolbox and start investigating in-depth > (which I don't really have time to do at the moment), I thought > I'd check here first if anyone has seen this issue and if there > is any quick configuration / boot arg fix ? > > To quantify, normally boot-up takes less than 1 minute with the 2.6.26 > kernel; with the 2.6.27 kernel, it takes over 10 minutes, and the screen > is flooded with these "hub event change" messages - and the terminal > scrolls visibly slowly, and seems to be unable to keep up with even > my extremely slow typing rate. > > I'm attaching the config-2.6.26-rc9.jvd and config-2.6.27-rc5.jvd files, > and klogd logs from a bootup of each kernel. > > Any advice suggestions as to how to fix would be gratefully received. > > > Steps to reproduce: > > build and install latest kernel from Linus' tree. > I've tentatively categorised this post-2.6.26 regression under USB. Sep 7 15:56:33 localhost kernel: [ 21.190720] device: 'vcsa11': device_unregister Sep 7 15:56:33 localhost kernel: [ 21.190721] PM: Removing info for No Bus:vcsa11 Sep 7 15:56:33 localhost kernel: [ 21.190788] device: 'vcsa11': device_create_release Sep 7 15:56:33 localhost kernel: [ 21.205252] hub 1-0:1.0: state 7 ports 2 chg 0000 evt 0000 Sep 7 15:56:33 localhost kernel: [ 21.205305] hub 3-0:1.0: state 7 ports 2 chg 0000 evt 0000 Sep 7 15:56:33 localhost kernel: [ 21.460430] hub 1-0:1.0: state 7 ports 2 chg 0000 evt 0000 Sep 7 15:56:33 localhost kernel: [ 21.460454] hub 3-0:1.0: state 7 ports 2 chg 0000 evt 0000 Sep 7 15:56:33 localhost kernel: [ 21.704357] hub 1-0:1.0: state 7 ports 2 chg 0000 evt 0000 Sep 7 15:56:33 localhost kernel: [ 21.704366] hub 3-0:1.0: state 7 ports 2 chg 0000 evt 0000 Sep 7 15:56:33 localhost kernel: [ 21.954352] hub 1-0:1.0: state 7 ports 2 chg 0000 evt 0000 Sep 7 15:56:33 localhost kernel: [ 21.954374] hub 3-0:1.0: state 7 ports 2 chg 0000 evt 0000 Sep 7 15:56:33 localhost kernel: [ 22.204433] hub 1-0:1.0: state 7 ports 2 chg 0000 evt 0000 Sep 7 15:56:33 localhost kernel: [ 22.204441] hub 3-0:1.0: state 7 ports 2 chg 0000 evt 0000 Sep 7 15:56:33 localhost kernel: [ 22.454376] hub 1-0:1.0: state 7 ports 2 chg 0000 evt 0000 Sep 7 15:56:33 localhost kernel: [ 22.454384] hub 3-0:1.0: state 7 ports 2 chg 0000 evt 0000 Sep 7 15:56:33 localhost kernel: [ 22.704406] hub 1-0:1.0: state 7 ports 2 chg 0000 evt 0000 Sep 7 15:56:33 localhost kernel: [ 22.704414] hub 3-0:1.0: state 7 ports 2 chg 0000 evt 0000 Sep 7 15:56:33 localhost kernel: [ 22.960311] hub 1-0:1.0: state 7 ports 2 chg 0000 evt 0000 Sep 7 15:56:33 localhost kernel: [ 22.960335] hub 3-0:1.0: state 7 ports 2 chg 0000 evt 0000 Sep 7 15:56:34 localhost kernel: [ 23.204362] hub 1-0:1.0: state 7 ports 2 chg 0000 evt 0000 Sep 7 15:56:34 localhost kernel: [ 23.204384] hub 3-0:1.0: state 7 ports 2 chg 0000 evt 0000 Sep 7 15:56:34 localhost kernel: [ 23.454386] hub 1-0:1.0: state 7 ports 2 chg 0000 evt 0000 Sep 7 15:56:34 localhost kernel: [ 23.454394] hub 3-0:1.0: state 7 ports 2 chg 0000 evt 0000 Sep 7 15:56:34 localhost kernel: [ 23.704357] hub 1-0:1.0: state 7 ports 2 chg 0000 evt 0000 Sep 7 15:56:34 localhost kernel: [ 23.704366] hub 3-0:1.0: state 7 ports 2 chg 0000 evt 0000 Sep 7 15:56:34 localhost kernel: [ 23.954377] hub 1-0:1.0: state 7 ports 2 chg 0000 evt 0000 Sep 7 15:56:34 localhost kernel: [ 23.954696] hub 3-0:1.0: state 7 ports 2 chg 0000 evt 0000 Sep 7 15:56:35 localhost kernel: [ 24.204380] hub 1-0:1.0: state 7 ports 2 chg 0000 evt 0000 Sep 7 15:56:35 localhost kernel: [ 24.204389] hub 3-0:1.0: state 7 ports 2 chg 0000 evt 0000 Sep 7 15:56:35 localhost kernel: [ 24.454398] hub 1-0:1.0: state 7 ports 2 chg 0000 evt 0000 Sep 7 15:56:35 localhost kernel: [ 24.454406] hub 3-0:1.0: state 7 ports 2 chg 0000 evt 0000 Sep 7 15:56:35 localhost kernel: [ 24.704379] hub 1-0:1.0: state 7 ports 2 chg 0000 evt 0000 Sep 7 15:56:35 localhost kernel: [ 24.704402] hub 3-0:1.0: state 7 ports 2 chg 0000 evt 0000 Sep 7 15:56:35 localhost kernel: [ 24.954381] hub 1-0:1.0: state 7 ports 2 chg 0000 evt 0000 but it might be an x86 problem or anything, it's unclear. Jason, perhaps you could test a CONFIG_USB=n kernel? Well, I'm now trying Arjan's hrtimer tree: http://www.kernel.org/pub/scm/linux/kernel/git/arjan/linux-2.6-hrtimer.git - there were quite a few HR timer related diffs between this and Linus' tree - and I've disabled the "verbose USB core debug messages" config . It's building now - I'll post the results when done. Thanks, Jason Arjan's hrtimer stuff had no effect on this problem - and now I disabled USB core and driver core debug messages I get less information as to why. The boot up is just as quick as with 2.6.26-rc9 until the kernel begins processing udev events - then things just seem to grind to a halt. I'll try disabling USB completely next - isn't there any way to do so from the boot command line ? OK, this definitely is not purely a USB issue. I recompiled Arjans hrtimer tree ( http://git.kernel.org/?p=linux/kernel/git/arjan/linux-2.6-hrtimer.git;a=commit;h=96d2ab484e7a9bafdab44b8c7d1ef5944319b18c ) with CONFIG_USB_SUPPORT=no (BTW, why not add a 'usb=no' boot argument?) and the machine still crawls under the resulting 2.6.27-rc5 kernel. True, without USB the machine becomes usably quick (just!), and the kernel debug log is no longer flooded with those 'hub 1-0:1.0: state 7 ports 2 chg 0000 evt 0000' messages; but it still crawls. To quantify "crawls" : Under 2.6.26-rc9 (Linus' tree from @ 2008-07-10), here are some comand times: $ $ time (dd if=/dev/urandom bs=1MB count=1 2>/dev/null | sha1sum -;dd if=/dev/urandom bs=1MB count=1 2>/dev/null | sha1sum -;dd if=/dev/urandom bs=1MB count=1 >/dev/null | sha1sum -) e026089285fe644aa48aab7ef6e3cfe36d3215f3 - c9657aedb1fa5b2687ea1117846265f6ddd2e153 - da39a3ee5e6b4b0d3255bfef95601890afd80709 - 1+0 records in 1+0 records out 1000000 bytes (1.0 MB) copied, 0.206451 s, 4.8 MB/s real 0m0.700s user 0m0.013s sys 0m0.628s Under the 2.6.27-rc5.jvd_no_usb kernel (Arjan's hrtimer tree), the same command : $ time (dd if=/dev/urandom bs=1MB count=1 2>/dev/null | sha1sum -;dd if=/dev/urandom bs=1MB count=1 2>/dev/null | sha1sum -;dd if=/dev/urandom bs=1MB count=1 >/dev/null | sha1sum -) 01f07429c8019c0e6a9c8d6934d58dc9fa3a8fc7 - c11bff188c7b3501e7cae62cda213a92c5cddf73 - da39a3ee5e6b4b0d3255bfef95601890afd80709 - 1+0 records in 1+0 records out 1000000 bytes (1.0 MB) copied, 2.68622 s, 372 kB/s real 0m8.039s user 0m0.120s sys 0m7.021s That's @ ( 8 / 0.7 = 11.42 ) times slower ! Even worse is the behavior of the terminal driver - under a VT console, NOT an xterm, this command takes nearly 140 times slower under 2.6.27-rc5 than under 2.6.26-rc9 : Under 2.6.26-rc9: $ time dd if=/dev/urandom bs=100K count=1 | openssl base64 ... # lots of base64 text output real 0m0.129s user 0m0.007s sys 0m0.036s Under 2.6.27-rc5: $ time dd if=/dev/urandom bs=100K count=1 | openssl base64 ... # lots of base64 text output real 0m18.066s user 0m0.062s sys 0m0.449s That's 18 / 0.13 = 138 times slower ! This really makes 2.6.27-rc9 rather unusable because typing or viewing text on a terminal is too slow. There seems to have been a lot of activity in the high-res-timer + scheduling areas for x86_64 recently, so that would be my prime suspect - eg. with 2.6.26-rc9, you finally fixed this issue: dmesg.2.6.24-1:[ 35.299325] Could not switch to high resolution mode on CPU 0 dmesg.2.6.24-1:[ 35.299946] Could not switch to high resolution mode on CPU 1 so for the first time, multi-core x86_64 CPUs finally run in high resolution mode - thanks! But what happened to the x86_64 scheduling + timer code between 2.6.26 and 2.6.27 ? ... I will investigate this more fully when I have more time - likely not before next weekend - unless someone fixes this first ( I hope! ). I also raised a Fedora bug #461441 on this, because this issue also occurs with the latest FC 10 kernel ( 2.6.27-0.312.rc5.git7.fc10 ) : https://bugzilla.redhat.com//show_bug.cgi?id=461441 This is still an issue with latest HEAD 2.6.27-rc6 (Linus' GIT Tree 2008-09-21)??
I've tracked down three primary issues with this kernel :
1. All Switchable CPU Scaling Governors are DISABLED, even with powernow-k8
installed as a module and or with kernel recompiled to load powernow-k8
into built-ins.
By default, powernow-k8 is NOT installed with 2.6.27-+ kernels, whereas it
was with 2.6.26- kernels. This remained true before and after upgrade
from udev-124 -> 126 -> 128 .
After manual powernow-k8 module installed with modprobe, or is loaded as
built-in (both of which succeed) , the
/sys/devices/system/cpu/cpu[01]/cpufreq/*
files are all there - and all the correct /sys/devices/system/cpu/cpu[01]/cpufreq/*available* files display corrent values - except governor is
not switchable (governor displays as userspace), the cpuinfo_cur_freq
is at its lowest value (800000) as is scaling_max_freq even though available
freqs go up tp 2200000 which is the default under 2.6.26-rc9 .
Thus every moderately low-latency driver (such as the terminal, USB, keyboard,
network) is continually timing out, producing more log messages on the
already slow vesa terminal driver which eventually causes rsyslogd to crash
on timeout .
PLEASE RESTORE 2.6.27-rc7+ CPU FREQUENCY SWITCHING ON x86_64 CPU!!
I'll try to figure out how it comes to be disabled first - nothing
in the configuration has changed, but the new kernel overloads itself
simply by generating log messages on my AMD TL-64x2 2.2GHz SATA laptop,
while the old kernel can at least install the powernow-k8 driver and
comes with 2.2GHz as the default CPU clock frequency even without
powernow-k8 installed. This is beyond the limits of my both interested
novice kernel programming skills and my spare time at the moment
to explore more deeply - please could kernel developers advise -
more detailed logs can be collected. I have tried the latest fedora kernels
as of 2008-09-21 booting a 100% up-to-date Fedora 10 system with the same
result - only the latest RHEL-5.1 2.6.18 RedHat kernel does not suffer
this bug on my x86_64x2 / Dual-Core Athlon64 SMP + Xen enabled platform .
Other Symptoms are: 1. Failure to honor the "reboot" or "poweroff" commands at all - the machine goes into the "HALT" state, but never powers off. 2. It takes TWO manual RESET cycles with the power button to re-enable power-on . 3. No way to CPU frequency switch from LOWEST frequency (800000) on 2.2GHz 2 CPUs Can you please provide the output of dmesg right after boot for both kernels ? The boot log is missing the interesting parts.
Thanks,
tglx
*** Bug 11651 has been marked as a duplicate of this bug. *** On Tuesday, 23 of September 2008, Jason Vas Dias wrote:
> 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 .
Created attachment 18079 [details]
boot log from 2.6.27-rc7-tip.jvd, which fails to set CPU freq above 800Khz
Created attachment 18080 [details]
config from 2.6.27-rc7-tip.jvd
Created attachment 18081 [details]
System.map from 2.6.27-rc7-tip.jvd
Created attachment 18082 [details]
boot log from 2.6.26.5.jvd, which does not have the problem
Created attachment 18083 [details]
config from 2.6.26.5.jvd
Created attachment 18084 [details]
System map from 2.6.26.5.jvd
Created attachment 18085 [details]
acpidump from 2.6.26.5.jvd
Created attachment 18087 [details]
output of acpidump for 2.6.27-rc7-tip.jvd
Created attachment 18088 [details]
/proc/acpi files of 2.6.27-rc7-tip.jvd
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 | tee 2.6.27-rc7-tip.jvd.proc.acpi.dump
Created attachment 18089 [details]
/proc/acpi files of 2.6.26.5.jvd
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 | tee 2.6.26.5.jvd.proc.acpi.dump
Sorry for the delay in getting back to you all - finding spare time is difficult
for me at the moment.
Anyway, the problem still occurs with the latest linux-2.6-tip tree
( 2008-09-27@22:00 - c4077bb0691bcd26c546daa52b76a47ba954fc49 ), and with
the latest Fedora 10 kernel ( kernel-2.6.27-0.352.rc7.git1.fc10 ), but
not with the latest stable kernel ( 2.6.26.5 ) nor with 2.6.26-rc9 .
With EVERY 2.6.27 based kernel I've tested, since 2.6.27-rc1 , cpu frequency
switching is completely disabled, the AMD TL-64 dual-core 2.2Ghz CPU is stuck at
800Khz, and cannot be changed by any governor switch or valid modification of
/sys/devices/system/cpu/cpu0/cpufreq/scaling_{max_freq,setspeed}, usbcore floods the dmesg log with event change messages when it seems no event has
changed, and the machine cannot reboot (it can only enter the "HALT" state).
I'm analyzing the logs now, but have not been able to find anything obvious -
anyone have any ideas suggestions ?
In response to your questions:
On Friday 26 September 2008 11:17:59 Linus Torvalds wrote:
>
> On Fri, 26 Sep 2008, Jason Vas Dias wrote:
> >
> > There appears to be a serious problem with every 2.6.27-X kernel I've
> > tried - and I've tried quite a few from the linux-2.6, linux-acpi-2.6,
> > and linux-2.6-tip GIT trees, and the latest Fedora 10 kernels over the
> > past few weeks trying to solve this problem:
>
> So which trees work, and which don't?
Sorry for my lack of clarity - ANY 2.6.27 based tree from either your linux-2.6
tree, Len's linux-acpi tree, or Ingo's linux-2.6-tip tree, or the latest Fedora
10 Rawhide / Development kernels over the past three weeks have displayed the same problem - I've tried @ 8 trees over the past 3 weekends - sorry for not recording the master hash keys - I will in future.
> Also, since it seems entirely
> repeatable, this is a prime candidate for "git bisect" - it will be
> eventually faster to do than trying many different trees at random, even
> if you will likely need to reboot/compile about 12 times or so (assuming
> 2.6.27-rc1 is broken, and 2.6.26 works, which it sounds like).
>
> Bisecting really isn't that hard. Get the git tree, do
>
> git bisect start
> git bisect bad v2.6.27-rc1
> git bisect good v2.6.26
>
> and off you go. You don't even need to know a lot about git, there's a few
> quick tutorials out there if you haven't used it. See for example
>
> http://www.kernel.org/doc/local/git-quick.html
>
> which has an example git bisect run, in addition to just initial clone
> insutrctions.
>
Thank you! I'll try this next. I'm starting to hack around the powernow-k8
code, which in any case has the bug that it is not detecting that the CPU
frequency is set successfully or not - it should at least emit some dmesg
in either case, IMHO .
> > CPU frequency switching is completely disabled, the 2.2Ghz AMD TL-64
> > Dual Core CPU is stuck at 0.8Ghz, the machine cannot reboot or perform
> > any ACPI actions.
> >
> > There are no obvious failures indicated in the logs, only this:
> >
> > [ 0.000000] ACPI Error (tbfadt-0453): 32/64X address mismatch in
> "Pm2ControlBlock": [00008800] [0000000000008100], using 64X [20080609]
>
> Hmm. I don't know if it's ACPI-related, but the fact that it cannot even
> reboot etc sure seems to make it likely. Have you made the acpi lists
> aware of it (linux-acpi@vger.kernel.org and lenb are listed in
> MAINTAINERS)?
>
> Linus
>
I've now attached all available acpi information - the opinion of the ACPI
maintainers (whose emails are now attached to this bug) would be gratefully received.
On Friday 26 September 2008 11:40:40 Zhao Yakui <yakui.zhao@intel.com> wrote:
> Hi, Jason
> Will you please attach the output of acpidump, dmesg?
> From the log it seems that the BIOS gives the incorrect ACPI table.
> For example: the 32X/64X address don't match in FADT table.
> Of course you can open a new bug and attach the output of acpidump,
> dmesg.
> http://bugzilla.kernel.org/acpi
>
> thanks
Hi Zhao - thanks - this is now done.
I'm going to try to fix this - if no-one else does first!
Dave Jones :
I noticed your CPU Frequency tree from "7 weeks ago":
linux/kernel/git/davej/cpufreq.git Unnamed repository; edit this ...
( http://git.kernel.org/?...h=621114980de1e236ffa4e72899e226de75031a5f )
Has this been merged into 2.6.27-rc7 or not ? I'm checking out and doing
a diff with latest -tip tree now. I guess this is as good a place to start
investigative hacking as any ...
Thanks & Regards,
Jason
Can you please add "noapictimer" to the kernel command line ? > Can you please add "noapictimer" to the kernel command line ?
Wont help :) /me needs more coffee
Ok, I checked the proc/acpi outputs:
The limit entry is different and has the throttling limit set to T7
+++ /proc/acpi/processor/C001/limit:
-active limit: P0:T0
+active limit: P0:T7
user limit: P0:T0
-thermal limit: P0:T0
+thermal limit: P0:T7
Which is the active state:
+++ /proc/acpi/processor/C001/throttling:
state count: 8
-active state: T0
+active state: T7
state available: T0 to T7
states:
- *T0: 100%
+ T0: 100%
T1: 87%
T2: 75%
T3: 62%
T4: 50%
T5: 37%
T6: 25%
- T7: 12%
+ *T7: 12%
Can you please add "acpi.debug_level=0x11" to the kernel command line
of both .25 and .27 so we can get the ACPI debug info of setting the
limits/throttling state.
Thanks,
tglx
Thanks for the ACPI debug suggestion - I see what the problem is now . I tried gathering the complete boot logs with the ACPI debug argument you gave, but the dmesg buffer was not big enough to allow a complete log to be gathered, and the logs I could gather were huge - not suitable inclusion in a bug report. Basically, what is happening is that the drivers/acpi/thermal.c "thermal zone" module always thinks the processors are too hot, and ramps down their frequency until it reaches its lowest value. This is because for the 2.6.27 kernels, the thermal zone has a too low "passive" temperature value - (from the /proc/acpi files of 2.2.27 : http://bugzilla.kernel.org/attachment.cgi?id=18088&action=view) : +++ /proc/acpi/thermal_zone/TZ1/trip_points: critical (S5): 105 C passive: 16 C: tc1=1 tc2=2 tsp=100 devices=C000 C001 active[0]: 16 C: devices=C399 active[1]: 16 C: devices=C39A active[2]: 16 C: devices=C39B active[3]: 16 C: devices=C39C --- 16 degrees celsius is an unreasonably low value for the CPU, and while the current temperature of the CPU is greater than this '_PSV' threshold, drivers/acpi/thermal.c will decrease the CPU frequency; but as the CPU never gets colder than this value, the CPU frequency is always decreased to its lowest value within 70 seconds of booting (7 x the 10 second timer interval of thermal.c's acpi_thermal_check()'s timer). The 2.6.26 kernel's "trip_points" are set to reasonable values: +++ /proc/acpi/thermal_zone/TZ1/trip_points: critical (S5): 105 C passive: 95 C: tc1=1 tc2=2 tsp=100 devices=C000 C001 active[0]: 75 C: devices=C399 active[1]: 65 C: devices=C39A active[2]: 50 C: devices=C39B active[3]: 16 C: devices=C39C --- The "passive" threshold is a module parameter, but was not specified in either the 2.6.27 or 2.6.26 kernels: $ cat /sys/module/thermal/parameters/psv 0 The default value for the psv parameter in the ACPI DSDT is 16 C (2981 deci-Kelvin) found by decompiling it with iasl. Since the acpidump output under both kernels is identical, and the firmware ACPI tables must be the same, so the 2.6.27 ACPI code must be interpreting them slightly differently to the 2.6.26 code. Here are the acpi.debug=0x11 log excerpts showing the above is occurring: 1. Retreiving initial PSV from ACPI: [ 4.905673] evmisc-0128 [06] ev_queue_notify_reques: Dispatching Notify on [TZ1_] Node ffff880077b38680 Value 0x81 (**Device Specific**) [ 4.905683] evmisc-0202 [06] ev_queue_notify_reques: No notify handler for Notify (TZ1_, 81) node ffff880077b38680 [ 4.906506] utils-0291 [4294967295] evaluate_integer : Return value [3362] [ 4.906512] thermal-0262 [4294967295] thermal_get_temperatur: Temperature is 3362 dK [ 4.906534] utils-0291 [4294967295] evaluate_integer : Return value [3782] [ 4.906540] thermal-0383 [4294967295] thermal_trips_update : Found critical threshold [3782] [ 4.906551] nsutils-0869 [02] ns_get_node : _HOT, AE_NOT_FOUND [ 4.906560] utils-0047 [4294967295] util_eval_error : Evaluate [\_TZ_.TZ1_._HOT]: AE_NOT_FOUND [ 4.906566] thermal-0406 [4294967295] thermal_trips_update : No hot threshold [ 4.906580] Execute Method: [\_TZ_.TZ1_._PSV] (Node ffff880077b387a0) [ 4.908052] exregion-0186 [14] ex_system_memory_space: System-Memory (width 8) R/W 0 Address=0000000077FE7DC6 [ 4.908220] exregion-0289 [17] ex_system_io_space_han: System-IO (width 8) R/W 1 Address=0000000000000072 [ 4.908234] exregion-0289 [16] ex_system_io_space_han: System-IO (width 8) R/W 0 Address=0000000000000073 [ 4.908729] utils-0291 [4294967295] evaluate_integer : Return value [2891] [ 4.908750] utils-0291 [4294967295] evaluate_integer : Return value [1] [ 4.908771] utils-0291 [4294967295] evaluate_integer : Return value [2] [ 4.908792] utils-0291 [4294967295] evaluate_integer : Return value [100] [ 4.908826] utils-0420 [4294967295] evaluate_reference : Found reference [ffff8800778032a0] [ 4.908832] utils-0420 [4294967295] evaluate_reference : Found reference [ffff8800778032c0] 2. Throttling the processors down when their temperature exceeds 16 C: [ 24.757306] thermal-0262 [4294967294] thermal_get_temperatur: Temperature is 3332 dK [ 24.826155] thermal-0632 [4294967294] thermal_passive : trend[852]=(tc1[1]*(tmp[3332]-last[3362]))+(tc2[2]*(tmp[3332]-psv[2891])) [ 24.897221] cpufreq-core: updating policy for CPU 0 [ 24.897240] cpufreq-core: setting new policy for CPU 0: 800000 - 2200000 kHz [ 24.897246] freq-table: request for verification of policy (800000 - 2200000 kHz) for cpu 0 [ 24.897253] freq-table: verification lead to (800000 - 2200000 kHz) for cpu 0 [ 24.897271] freq-table: request for verification of policy (800000 - 1760000 kHz) for cpu 0 [ 24.897277] freq-table: verification lead to (800000 - 1760000 kHz) for cpu 0 [ 24.897285] cpufreq-core: new min and max freqs are 800000 - 1760000 kHz ... [ 25.171363] processor_throttling-0250 [4294967294] processor_throttling_n: PreChange Event:target T-state of CPU 1 is T1 [ 25.171946] processor_throttling-0260 [4294967294] processor_throttling_n: PostChange Event:CPU 1 is switched to T1 [ 25.171968] processor_thermal-0080 [4294967294] processor_apply_limit : Processor [1] limit set to (P0:T1) [ 25.171978] processor_thermal-0340 [4294967294] processor_set_thermal_: Thermal limit now (P0:T1) [ 25.171989] thermal-0911 [4294967294] thermal_check : TZ1: temperature[3332] sleep[10000] ... [ 1436.691903] thermal-0262 [4294967147] thermal_get_temperatur: Temperature is 3052 dK [ 1436.692172] thermal-0632 [4294967147] thermal_passive : trend[322]=(tc1[1]*(tmp[3052]-last[3052]))+(tc2[2]*(tmp[3052]-psv[2891])) [ 1436.693036] processor_thermal-0290 [4294967147] processor_set_thermal_: At maximum performance state [ 1436.693638] processor_thermal-0295 [4294967147] processor_set_thermal_: At maximum throttling state [ 1436.693874] processor_throttling-0250 [4294967147] processor_throttling_n: PreChange Event:target T-state of CPU 0 is T7 [ 1436.695743] processor_throttling-0260 [4294967147] processor_throttling_n: PostChange Event:CPU 0 is switched to T7 [ 1436.696473] processor_thermal-0080 [4294967147] processor_apply_limit : Processor [0] limit set to (P0:T7) [ 1436.696772] processor_thermal-0340 [4294967147] processor_set_thermal_: Thermal limit now (P0:T7) [ 1436.697472] processor_thermal-0290 [4294967147] processor_set_thermal_: At maximum performance state [ 1436.697710] processor_thermal-0295 [4294967147] processor_set_thermal_: At maximum throttling state [ 1436.697974] processor_throttling-0250 [4294967147] processor_throttling_n: PreChange Event:target T-state of CPU 1 is T7 [ 1436.704221] processor_throttling-0260 [4294967147] processor_throttling_n: PostChange Event:CPU 1 is switched to T7 [ 1436.704952] processor_thermal-0080 [4294967147] processor_apply_limit : Processor [1] limit set to (P0:T7) [ 1436.705183] processor_thermal-0340 [4294967147] processor_set_thermal_: Thermal limit now (P0:T7) [ 1436.705817] thermal-0911 [4294967147] thermal_check : TZ1: temperature[3052] sleep[10000] And then the frequency is at it lowest, with the temperature throttle at its highest, because the ACPI "PSV" value is set too low. This should be reassigned to the ACPI component, but I can't do that. Well, not necessarily. That still may be a result of the IO-APIC changes in .27. I had a similar issue on my test box that has been blacklisted and now works well. Jason, can you attach the output of dmidecode from your machine, please? Created attachment 18163 [details]
dmidecode output under 2.6.26.5
OK, here's the dmidecode output from kernel-2.6.26.5 .
I have confirmed that this is still a problem under Linus' 2.6.27-rc8 tree
of 2008-09-29 ( 94aca1dac6f6d21f4b07e4864baf7768cabcc6e7 ) .
I'm now building the latest linux-2.6-tip tree ( 800be01f27c9542ea4640d731874986c60f521e5 ) and am going to enable ACPI
table parsing debug to try to understand how the two kernels can be
parsing the same ACPI tables and get such different results .
Here is the relevant DSL from 'iasl -d /proc/acpi/dsdt' :
...
Method (_PSV, 0, NotSerialized)
{
Return (C391 (C384, 0x00))
}
...
Method (C391, 2, Serialized)
{
Store (0x01, Local0)
Store (Arg0, Local1)
If (LLess (Arg0, DerefOf (Index (C38C, Arg1))))
{
Store (0x00, Local0)
Add (Arg0, 0x01, Local1)
}
Store (DerefOf (Index (DerefOf (Index (DerefOf (Index (C37F, C392 (Arg1)
)), Local0)), Local1)), Local2)
If (LAnd (LEqual (\_SB.C03E, 0x01), LAnd (LEqual (Arg0, 0x00), LEqual (
Arg1, 0x00))))
{
If (\_SB.C08B.C0FE.C172.C1D5 ())
{
Store (0x0B4B, Local2)
}
}
If (LEqual (\_SB.C08B.C09F.C0A0, 0x01))
{
Store (0x0B4B, Local2)
}
Return (Local2)
}
Now 0x0B4B (2891 deci-Kelvin) is the infamous 16 degrees celsius default
_PSV value that the 2.6.27 kernels get ; under 2.6.26.5, the expression
Store (DerefOf (Index (DerefOf (Index (DerefOf (Index (C37F, C392 (Arg1)
)), Local0)), Local1)), Local2)
is evidently storing the correct 3682 deci-Kelvin ( 95 degrees celsius )
in "Local2" , and \_SB.C08B.C09F.C0A0 is not 1 -
ACPI debug output under 2.6.26.5:
[ 11.902295] Execute Method: [\_TZ_.TZ1_._PSV] (Node ffff810077b3b7c0)
[ 11.902295] exregion-0186 [15] ex_system_memory_space: System-Memory (width 8) R/W 0 Address=0000000077FE7DC6
[ 11.902295] exregion-0289 [18] ex_system_io_space_han: System-IO (width 8) R/W 1 Address=0000000000000072
[ 11.902295] exregion-0289 [17] ex_system_io_space_han: System-IO (width 8) R/W 0 Address=0000000000000073
[ 11.902295] utils-0291 [00] evaluate_integer : Return value [3682]
[ 11.902295] utils-0291 [00] evaluate_integer : Return value [1]
[ 11.902295] utils-0291 [00] evaluate_integer : Return value [2]
[ 11.902295] utils-0291 [00] evaluate_integer : Return value [100]
[ 11.902295] utils-0420 [00] evaluate_reference : Found reference [ffff8100778082c0]
[ 11.902295] utils-0420 [00] evaluate_reference : Found reference [ffff8100778082e0]
ACPI debug output under 2.6.27-rc7:
[ 4.906580] Execute Method: [\_TZ_.TZ1_._PSV] (Node ffff880077b387a0)
[ 4.908052] exregion-0186 [14] ex_system_memory_space: System-Memory (width 8) R/W 0 Address=0000000077FE7DC6
[ 4.908220] exregion-0289 [17] ex_system_io_space_han: System-IO (width 8) R/W 1 Address=0000000000000072
[ 4.908234] exregion-0289 [16] ex_system_io_space_han: System-IO (width 8) R/W 0 Address=0000000000000073
[ 4.908729] utils-0291 [4294967295] evaluate_integer : Return value [2891]
[ 4.908750] utils-0291 [4294967295] evaluate_integer : Return value [1]
[ 4.908771] utils-0291 [4294967295] evaluate_integer : Return value [2]
[ 4.908792] utils-0291 [4294967295] evaluate_integer : Return value [100]
[ 4.908826] utils-0420 [4294967295] evaluate_reference : Found reference [ffff8800778032a0]
[ 4.908832] utils-0420 [4294967295] evaluate_reference : Found reference [ffff8800778032c0]
I'm re-testing the above with the latest 2.6.27-rc8-tip kernel and will attach
the relevant output when done - at least I can give the "thermal.psv=95"
parameter to the new kernel so that the CPU stays at 2.2Ghz and a boot/reboot
cycle takes less than one hour! (But the active cooling devices stay always on).
On Sat, 4 Oct 2008, bugme-daemon@bugzilla.kernel.org wrote: < > I have confirmed that this is still a problem under Linus' 2.6.27-rc8 tree > of 2008-09-29 ( 94aca1dac6f6d21f4b07e4864baf7768cabcc6e7 ) . > I'm now building the latest linux-2.6-tip tree It really would be much better if you just tried to bisect it. It won't be fixed until somebody has a clue what caused it, or we find it almost by mistake, and nothing since -rc8 (or, indeed -rc7) is very likely to have fixed it. So testing new kernels probably won't help, while testing old kernels (with bisect) should hopefully be able to show what caused the breakage. Linus Created attachment 18175 [details]
Patch to test
Please check if this patch helps.
[BTW, the '.jvd' extension is not really helpful, because it confuses some tools. Please append '-jvd' to the file names instead.]
Yes, thanks, that fixed it ! After the patch the trip points were back to normal and the CPU frequency stays at 2.2GHz: $ cat /proc/acpi/thermal_zone/TZ1/trip_points critical (S5): 105 C passive: 95 C: tc1=1 tc2=2 tsp=100 devices=C000 C001 active[0]: 75 C: devices=C39B active[1]: 65 C: devices=C39C active[2]: 55 C: devices=C39D active[3]: 16 C: devices=C39E $ cat /sys/devices/system/cpu/cpu0/cpufreq/cpuinfo_cur_freq 2200000 But those multiple USB "event change" messages per-second when no event has changed remain, so I have to disable klogd logging to disk: [ 989.204090] hub 1-0:1.0: state 7 ports 2 chg 0000 evt 0000 [ 989.204099] hub 3-0:1.0: state 7 ports 2 chg 0000 evt 0000 [ 989.454584] hub 1-0:1.0: state 7 ports 2 chg 0000 evt 0000 [ 989.454594] hub 3-0:1.0: state 7 ports 2 chg 0000 evt 0000 [ 989.704080] hub 1-0:1.0: state 7 ports 2 chg 0000 evt 0000 [ 989.704090] hub 3-0:1.0: state 7 ports 2 chg 0000 evt 0000 [ 989.954084] hub 1-0:1.0: state 7 ports 2 chg 0000 evt 0000 [ 989.954094] hub 3-0:1.0: state 7 ports 2 chg 0000 evt 0000 [ 990.204091] hub 1-0:1.0: state 7 ports 2 chg 0000 evt 0000 [ 990.204100] hub 3-0:1.0: state 7 ports 2 chg 0000 evt 0000 [ 990.454112] hub 1-0:1.0: state 7 ports 2 chg 0000 evt 0000 [ 990.454122] hub 3-0:1.0: state 7 ports 2 chg 0000 evt 0000 [ 990.704089] hub 1-0:1.0: state 7 ports 2 chg 0000 evt 0000 [ 990.704098] hub 3-0:1.0: state 7 ports 2 chg 0000 evt 0000 [ 990.954088] hub 1-0:1.0: state 7 ports 2 chg 0000 evt 0000 [ 990.954098] hub 3-0:1.0: state 7 ports 2 chg 0000 evt 0000 [ 991.204334] hub 1-0:1.0: state 7 ports 2 chg 0000 evt 0000 [ 991.204343] hub 3-0:1.0: state 7 ports 2 chg 0000 evt 0000 [ 991.454094] hub 1-0:1.0: state 7 ports 2 chg 0000 evt 0000 [ 991.454103] hub 3-0:1.0: state 7 ports 2 chg 0000 evt 0000 [ 991.704083] hub 1-0:1.0: state 7 ports 2 chg 0000 evt 0000 [ 991.704093] hub 3-0:1.0: state 7 ports 2 chg 0000 evt 0000 [ 991.954089] hub 1-0:1.0: state 7 ports 2 chg 0000 evt 0000 [ 991.954098] hub 3-0:1.0: state 7 ports 2 chg 0000 evt 0000 This is probably a different issue - shall I raise a new bug on this ? Thanks! (In reply to comment #34) > Yes, thanks, that fixed it ! Thanks for the confirmation. > But those multiple USB "event change" messages per-second when no event has > changed remain, so I have to disable klogd logging to disk: > [ 989.204090] hub 1-0:1.0: state 7 ports 2 chg 0000 evt 0000 > [ 989.204099] hub 3-0:1.0: state 7 ports 2 chg 0000 evt 0000 > [ 989.454584] hub 1-0:1.0: state 7 ports 2 chg 0000 evt 0000 > [ 989.454594] hub 3-0:1.0: state 7 ports 2 chg 0000 evt 0000 > [ 989.704080] hub 1-0:1.0: state 7 ports 2 chg 0000 evt 0000 > [ 989.704090] hub 3-0:1.0: state 7 ports 2 chg 0000 evt 0000 > [ 989.954084] hub 1-0:1.0: state 7 ports 2 chg 0000 evt 0000 > [ 989.954094] hub 3-0:1.0: state 7 ports 2 chg 0000 evt 0000 > [ 990.204091] hub 1-0:1.0: state 7 ports 2 chg 0000 evt 0000 > [ 990.204100] hub 3-0:1.0: state 7 ports 2 chg 0000 evt 0000 > [ 990.454112] hub 1-0:1.0: state 7 ports 2 chg 0000 evt 0000 > [ 990.454122] hub 3-0:1.0: state 7 ports 2 chg 0000 evt 0000 > [ 990.704089] hub 1-0:1.0: state 7 ports 2 chg 0000 evt 0000 > [ 990.704098] hub 3-0:1.0: state 7 ports 2 chg 0000 evt 0000 > [ 990.954088] hub 1-0:1.0: state 7 ports 2 chg 0000 evt 0000 > [ 990.954098] hub 3-0:1.0: state 7 ports 2 chg 0000 evt 0000 > [ 991.204334] hub 1-0:1.0: state 7 ports 2 chg 0000 evt 0000 > [ 991.204343] hub 3-0:1.0: state 7 ports 2 chg 0000 evt 0000 > [ 991.454094] hub 1-0:1.0: state 7 ports 2 chg 0000 evt 0000 > [ 991.454103] hub 3-0:1.0: state 7 ports 2 chg 0000 evt 0000 > [ 991.704083] hub 1-0:1.0: state 7 ports 2 chg 0000 evt 0000 > [ 991.704093] hub 3-0:1.0: state 7 ports 2 chg 0000 evt 0000 > [ 991.954089] hub 1-0:1.0: state 7 ports 2 chg 0000 evt 0000 > [ 991.954098] hub 3-0:1.0: state 7 ports 2 chg 0000 evt 0000 > > This is probably a different issue - shall I raise a new bug on this ? Yes, these should be fixed by this commit: http://git.kernel.org/?p=linux/kernel/git/torvalds/linux-2.6.git;a=commit;h=07454bfff151d2465ada809bbaddf3548cc1097c Handled-By : Rafael J. Wysocki <rjw@sisk.pl> Patch : http://bugzilla.kernel.org/attachment.cgi?id=18175&action=view fixed by commit e84956f92a846246b09b34f2a728329c386d250f Might want to add HP Compaq 6715s laptops to the blacklist; exactly the same issue on one of those (and probably a lot of HP Compaq 6xxx's with a Turion CPU). > Might want to add HP Compaq 6715s laptops to the blacklist; exactly > the same issue on one of those (and probably a lot of HP Compaq 6xxx's > with a Turion CPU). could you check tip/master: http://people.redhat.com/mingo/tip.git/README it has a more generic, PCI ID based quirk, queued up for v2.6.28. Does that work fine on your HP Compaq 6715 laptop, out of box? Ingo Reopened the bug to track other systems that are not yet covered. Adrian Bunk, could you stop closing bugs you have zero involvement with? (In reply to comment #39) > http://people.redhat.com/mingo/tip.git/README > > it has a more generic, PCI ID based quirk, queued up for v2.6.28. Does > that work fine on your HP Compaq 6715 laptop, out of box? That will be -stable material too, I think? > > it has a more generic, PCI ID based quirk, queued up for v2.6.28. > > Does that work fine on your HP Compaq 6715 laptop, out of box? > > That will be -stable material too, I think? Correct. These two are queued up for v2.6.28: 8d89adf: x86: SB450: deprioritize DMI quirks 33fb0e4: x86: SB450: skip IRQ0 override if it is not routed to INT2 of IOAPIC and i already added a backport tag to 33fb0e4: Cc: <stable@kernel.org> Dmitry reported success with 33fb0e4 + 8d89adf. It will all work out fine in a natural way by the time .27.1 backport items are processed. Ingo Hello folks, Just wanted to note that mine Compaq 6715s with 32bit AMD Semperon CPU have the same problem. Adding it to the blacklist in arch/x86/kernel/acpi/boot.c solved (at least this) issue. I guess the whole 6715x series is affected... buggy HP hardware. greets, Matze Great thanks to everyone for the fixes for this!
However, there still remains a niggle:
Having merged Linus' and Ingo's -tip trees of 2008-10-10@22:30 EDT :
$ git remote add linus \
git://git.kernel.org/pub/scm/linux/kernel/git/torvalds/linux-2.6.git
$ git remote add tip \
git://git.kernel.org/pub/scm/linux/kernel/git/tip/linux-2.6-tip.git
$ git remote update
$ git checkout -b jvd tip/master
and built the resulting kernel, I now get this warning:
[ 0.000000] ------------[ cut here ]------------
[ 0.000000] WARNING: at arch/x86/kernel/acpi/boot.c:1410 dmi_ignore_irq0_timer_override+0x30/0x60()
[ 0.000000] ati_ixp4x0 quirk not complete.
[ 0.000000] Modules linked in:
[ 0.000000] Pid: 0, comm: swapper Not tainted 2.6.27-jvd #1
[ 0.000000] Call Trace:
[ 0.000000] [<ffffffff8024bd87>] warn_slowpath+0xb7/0xe0
[ 0.000000] [<ffffffff80213500>] ? nommu_map_single+0x30/0x70
[ 0.000000] [<ffffffff8024d077>] ? printk+0x67/0x70
[ 0.000000] [<ffffffff809871ca>] ? __reserve_early+0x7a/0xe0
[ 0.000000] [<ffffffff806bbab3>] ? init_memory_mapping+0x633/0x720
[ 0.000000] [<ffffffff80980140>] ? early_idt_handler+0x0/0x72
[ 0.000000] [<ffffffff8098baf0>] dmi_ignore_irq0_timer_override+0x30/0x60
[ 0.000000] [<ffffffff805a69f4>] dmi_check_system+0x74/0xc0
[ 0.000000] [<ffffffff8098c545>] acpi_boot_table_init+0x15/0xf0
[ 0.000000] [<ffffffff809850b5>] setup_arch+0x3f5/0x840
[ 0.000000] [<ffffffff80980140>] ? early_idt_handler+0x0/0x72
[ 0.000000] [<ffffffff806dadb6>] ? _spin_unlock+0x26/0x30
[ 0.000000] [<ffffffff80980140>] ? early_idt_handler+0x0/0x72
[ 0.000000] [<ffffffff80980cb1>] start_kernel+0x71/0x410
[ 0.000000] [<ffffffff8098027c>] x86_64_start_reservations+0x7c/0xc0
[ 0.000000] [<ffffffff809803da>] x86_64_start_kernel+0xea/0x110
[ 0.000000] ---[ end trace 4eaa2a86a8e2da22 ]---
[ 0.000000] HP 6715b laptop detected: Ignoring BIOS IRQ0 pin2 override
Trying to follow the LKML thread
"[PATCH] x86 ACPI: Blacklist two HP machines with buggy BIOSes (Re: 2.6.27-rc8+ - first impressions)"
it seems you've applied two fixes for this :
1) Adding an "early-quirk" to x86/kernel/early-quirks.c :
@181:
{ PCI_VENDOR_ID_ATI, PCI_DEVICE_ID_ATI_IXP400_SMBUS,
PCI_CLASS_SERIAL_SMBUS, PCI_ANY_ID, 0, ati_bugs },
2) "Blacklisting" HP 6715b laptops so that they assert
acpi_skip_timer_override==1 IFF the early quirk did not succeed
in arch/x86/kernel/acpi/boot.c, which is now generating the warning :
@1403:
static int __init dmi_ignore_irq0_timer_override(const struct dmi_system_id *d)
{
/*
* The ati_ixp4x0_rev() early PCI quirk should have set
* the acpi_skip_timer_override flag already:
*/
if (!acpi_skip_timer_override) {
WARN(1, KERN_ERR "ati_ixp4x0 quirk not complete.\n");
pr_notice("%s detected: Ignoring BIOS IRQ0 pin2 override\n",
d->ident);
acpi_skip_timer_override = 1;
}
return 0;
}
Evidently, the code in early-quirks.c did not recognize mine as a "problem"
system - my dsdt.dsl begins:
/*
* Intel ACPI Component Architecture
* AML Disassembler version 20080926
*
* Disassembly of dsdt, Mon Sep 29 21:40:26 2008
*
*
* Original Table Header:
* Signature "DSDT"
* Length 0x0001193C (71996)
* Revision 0x01 **** ACPI 1.0, no 64-bit math support
* Checksum 0x0C
* OEM ID "HP "
* OEM Table ID "SB400"
* OEM Revision 0x00010000 (65536)
* Compiler ID "MSFT"
* Compiler Version 0x03000001 (50331649)
*/
and my SMBus identifies as :
$ lspci -nn | grep SMBus
00:14.0 SMBus [0c05]: ATI Technologies Inc SB600 SMBus [1002:4385] (rev 14)
So mine is an "SB600", not an "SB400" / "SB450" ??
The #define PCI_DEVICE_ID_ATI_IXP400_SMBUS is :
include/linux/pci_ids.h:369:#define PCI_DEVICE_ID_ATI_IXP400_SMBUS 0x4372
whereas my PCI ID is defined as:
include/linux/pci_ids.h:374:#define PCI_DEVICE_ID_ATI_SBX00_SMBUS 0x4385
So I'm trying this patch:
<PATCH>
--- early-quirks.c~ 2008-10-10 22:32:34.000000000 -0400
+++ early-quirks.c 2008-10-11 01:07:49.000000000 -0400
@@ -178,6 +178,8 @@
PCI_CLASS_BRIDGE_HOST, PCI_ANY_ID, 0, fix_hypertransport_config },
{ PCI_VENDOR_ID_ATI, PCI_DEVICE_ID_ATI_IXP400_SMBUS,
PCI_CLASS_SERIAL_SMBUS, PCI_ANY_ID, 0, ati_bugs },
+ { PCI_VENDOR_ID_ATI, PCI_DEVICE_ID_ATI_SBX00_SMBUS,
+ PCI_CLASS_SERIAL_SMBUS, PCI_ANY_ID, 0, ati_bugs },
#ifdef CONFIG_DMAR
{ PCI_VENDOR_ID_INTEL, 0x29c0,
PCI_CLASS_BRIDGE_HOST, PCI_ANY_ID, 0, intel_g33_dmar },
</PATCH>
Perhaps you might consider also applying this ?
Also, RE: Comment #35:
> Yes, these should be fixed by this commit:
>
> http://git.kernel.org/?p=linux/kernel/git/torvalds/linux-2.6.git;a=commit;h=07454bfff151d2465ada809bbaddf3548cc1097c
No, those USB event change messages are still with me:
[ 2971.204312] hub 1-0:1.0: state 7 ports 2 chg 0000 evt 0000
[ 2971.204322] hub 3-0:1.0: state 7 ports 2 chg 0000 evt 0000
[ 2971.454090] hub 1-0:1.0: state 7 ports 2 chg 0000 evt 0000
[ 2971.454097] hub 3-0:1.0: state 7 ports 2 chg 0000 evt 0000
[ 2971.704074] hub 1-0:1.0: state 7 ports 2 chg 0000 evt 0000
[ 2971.704081] hub 3-0:1.0: state 7 ports 2 chg 0000 evt 0000
[ 2971.954075] hub 1-0:1.0: state 7 ports 2 chg 0000 evt 0000
[ 2971.954082] hub 3-0:1.0: state 7 ports 2 chg 0000 evt 0000
[ 2972.204314] hub 1-0:1.0: state 7 ports 2 chg 0000 evt 0000
[ 2972.204321] hub 3-0:1.0: state 7 ports 2 chg 0000 evt 0000
[ 2972.454326] hub 1-0:1.0: state 7 ports 2 chg 0000 evt 0000
[ 2972.454334] hub 3-0:1.0: state 7 ports 2 chg 0000 evt 0000
[ 2972.704318] hub 1-0:1.0: state 7 ports 2 chg 0000 evt 0000
[ 2972.704326] hub 3-0:1.0: state 7 ports 2 chg 0000 evt 0000
[ 2972.954073] hub 1-0:1.0: state 7 ports 2 chg 0000 evt 0000
[ 2972.954079] hub 3-0:1.0: state 7 ports 2 chg 0000 evt 0000
usbcore's hub.c seems to be vigorously reporting that it has nothing to report -
no USB devices are connected to any hub.
Any ideas what caused them to appear in 2.6.27-rc5 going from 2.6.26-rc9 ?
TIA, Jason
Nope, that early-quirks.c patch did NOT work - I'm still getting the dmi_ignore_irq0_timer_override warning calltrace with the patch - it did look too easy to be correct. I'll look at this some more tomorrow . *** Bug 11719 has been marked as a duplicate of this bug. *** BUG: arch/x86/kernel/early_quirks.c's ati_bugs() is not being called early enough!: yes that patch did cause my SMBus to berecognized, but it is not being called BEFORE the warning is generated in arch/x86/kernel/acpi/boot.c, but after ! I think it would be a good idea if the new ati_bugs() function is simply moved to acpi's boot.c - I try this next, if no-one else has already done so. Created attachment 18267 [details]
log from 2.6.27-tip
The workaround in the kernel is good, but from what I understand the best solution would be to fix the BIOS. Is HP aware of its buggy BIOS? Does someone reported the bug to HP? Jason, I am currently working on a fix for bug #11715 Your issue seems quite similar. WRT comment #44: > + { PCI_VENDOR_ID_ATI, PCI_DEVICE_ID_ATI_SBX00_SMBUS, > + PCI_CLASS_SERIAL_SMBUS, PCI_ANY_ID, 0, ati_bugs }, This would have been too easy. For SB600 some other bits have to be checked. Can you please attach output of "lspci -nnvvxxxx"? Thanks, Andreas IMHO this is a duplicate of bug #11715 dmesg shows that your machine has an override for IRQ0. This is obviously wrong as Linux needs to unmask IRQ0 in PIC to route timer interrupts to IOAPIC: [ 0.000000] ACPI: INT_SRC_OVR (bus 0 bus_irq 0 global_irq 2 dfl dfl) ... [ 0.000000] ACPI: IRQ0 used by override. [ 0.000000] ACPI: IRQ2 used by override. ... [ 0.092533] ..TIMER: vector=0x30 apic1=0 pin1=2 apic2=-1 pin2=-1 [ 0.093985] ..MP-BIOS bug: 8254 timer not connected to IO-APIC [ 0.093985] ...trying to set up timer (IRQ0) through the 8259A ... [ 0.093985] ..... (found apic 0 pin 2) ... [ 0.104133] ....... works. And when Linux unmasks INT2 of IOAPIC it stumbles over "HP's thermal trap point". Linux should skip the bogus timer override. Fix for testing follows. Created attachment 18305 [details]
Patch is against today's Linus' git (v2.6.27-3977-gc166ab7)
Please give it a try! Thanks.
Thanks Andreas! But niggle still remains:
boot.c's dmi_ignore_irq0_timer_override is still called BEFORE
early-quirks.c, so still gets this calltrace on the warning:
[ 0.000000] Call Trace:
[ 0.000000] [<ffffffff8024bd77>] warn_slowpath+0xb7/0xe0
[ 0.000000] [<ffffffff80213500>] ? nommu_map_single+0x30/0x70
[ 0.000000] [<ffffffff8024d067>] ? printk+0x67/0x70
[ 0.000000] [<ffffffff809871ca>] ? __reserve_early+0x7a/0xe0
[ 0.000000] [<ffffffff806bcfd3>] ? init_memory_mapping+0x633/0x720
[ 0.000000] [<ffffffff80980140>] ? early_idt_handler+0x0/0x72
[ 0.000000] [<ffffffff8098bb20>] dmi_ignore_irq0_timer_override+0x30/0x60
[ 0.000000] [<ffffffff805a6624>] dmi_check_system+0x74/0xc0
[ 0.000000] [<ffffffff8098c575>] acpi_boot_table_init+0x15/0xf0
[ 0.000000] [<ffffffff809850b5>] setup_arch+0x3f5/0x840
[ 0.000000] [<ffffffff80980140>] ? early_idt_handler+0x0/0x72
[ 0.000000] [<ffffffff806dc346>] ? _spin_unlock+0x26/0x30
[ 0.000000] [<ffffffff80980140>] ? early_idt_handler+0x0/0x72
[ 0.000000] [<ffffffff80980cb1>] start_kernel+0x71/0x410
[ 0.000000] [<ffffffff8098027c>] x86_64_start_reservations+0x7c/0xc0
[ 0.000000] [<ffffffff809803da>] x86_64_start_kernel+0xea/0x110
[ 0.000000] ---[ end trace 4eaa2a86a8e2da22 ]---
I suggest this patch:
$ diff -U0 arch/x86/kernel/acpi/boot.c~ arch/x86/kernel/acpi/boot.c
--- arch/x86/kernel/acpi/boot.c~ 2008-10-15 21:00:19.000000000 -0400
+++ arch/x86/kernel/acpi/boot.c 2008-10-15 21:52:18.000000000 -0400
@@ -1410 +1409,0 @@
- WARN(1, KERN_ERR "ati_ixp4x0 quirk not complete.\n");
How can ati_ixp4x0 quirk be "complete" at this stage when ati_bugs()
has not been invoked ?
Your ati_bugs() does not seem to be being invoked for my SMBus - here's
the 'lspci -nnvxxxx' output for it:
00:14.1 IDE interface [0101]: ATI Technologies Inc SB600 IDE [1002:438c] (prog-if 82 [Master PriP])
Subsystem: Hewlett-Packard Company Unknown device [103c:30c2]
Control: I/O+ Mem- BusMaster+ SpecCycle- MemWINV- VGASnoop- ParErr- Stepping- SERR- FastB2B- DisINTx-
Status: Cap- 66MHz+ UDF- FastB2B- ParErr- DEVSEL=medium >TAbort- <TAbort- <MAbort- >SERR- <PERR- INTx-
Latency: 64, Cache Line Size: 64 bytes
Interrupt: pin A routed to IRQ 16
Region 0: I/O ports at 01f0 [size=8]
Region 1: I/O ports at 03f4 [size=1]
Region 2: I/O ports at 0170 [size=8]
Region 3: I/O ports at 0374 [size=1]
Region 4: I/O ports at 5040 [size=16]
Kernel driver in use: ATIIXP_IDE
Kernel modules: pata_acpi, pata_atiixp, atiixp, ide-pci-generic
00: 02 10 8c 43 05 00 20 02 00 82 01 01 10 40 00 00
10: 01 00 00 00 01 00 00 00 01 00 00 00 01 00 00 00
20: 41 50 00 00 00 00 00 00 00 00 00 00 3c 10 c2 30
30: 00 00 00 00 00 00 00 00 00 00 00 00 0a 01 00 00
40: 99 20 00 00 ff 20 00 00 00 01 04 00 00 00 00 00
50: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00
60: 00 00 40 00 10 2c 01 07 01 00 00 00 ff ff 0f 00
70: 05 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00
80: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00
90: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00
a0: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00
b0: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00
c0: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00
d0: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00
e0: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00
f0: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00
Hmm, this is now identifying as "438c", not "4385" -
my SMBus PCI id changed from 2.6.27-@08-10-11 from pci_ids.h:
#define PCI_DEVICE_ID_ATI_IXP600_IDE 0x438c
#define PCI_DEVICE_ID_ATI_IXP700_SATA 0x4390
But my system is 100% SATA, so why do I see the "IDE" flavor ?
So, 2nd suggested patch:
--- arch/x86/kernel/early-quirks.c~ 2008-10-15 21:01:17.000000000 -0400
+++ arch/x86/kernel/early-quirks.c 2008-10-15 22:04:37.000000000 -0400
@@ -228 +228,9 @@
- { PCI_VENDOR_ID_ATI, PCI_DEVICE_ID_ATI_SBX00_SMBUS,
+ { PCI_VENDOR_ID_ATI, PCI_DEVICE_ID_ATI_SBX00,
+ PCI_CLASS_SERIAL_SMBUS, PCI_ANY_ID, 0, ati_bugs_contd },
+ { PCI_VENDOR_ID_ATI, PCI_DEVICE_ID_ATI_IXP600_SATA,
+ PCI_CLASS_SERIAL_SMBUS, PCI_ANY_ID, 0, ati_bugs_contd },
+ { PCI_VENDOR_ID_ATI, PCI_DEVICE_ID_ATI_IXP600_IDE,
+ PCI_CLASS_SERIAL_SMBUS, PCI_ANY_ID, 0, ati_bugs_contd },
+ { PCI_VENDOR_ID_ATI, PCI_DEVICE_ID_ATI_IXP700_IDE,
+ PCI_CLASS_SERIAL_SMBUS, PCI_ANY_ID, 0, ati_bugs_contd },
+ { PCI_VENDOR_ID_ATI, PCI_DEVICE_ID_ATI_IXP700_SATA,
BTW, I am going to raise a NEW bug about this USB message flood, which
also appeared going from 2.6.26.x -> 2.6.27 , with a patch that does
"when last event is same as this event, don't emit printk" :
[ 1325.204074] hub 1-0:1.0: state 7 ports 2 chg 0000 evt 0000
[ 1325.204080] hub 3-0:1.0: state 7 ports 2 chg 0000 evt 0000
[ 1325.454075] hub 1-0:1.0: state 7 ports 2 chg 0000 evt 0000
[ 1325.454082] hub 3-0:1.0: state 7 ports 2 chg 0000 evt 0000
[ 1325.704101] hub 1-0:1.0: state 7 ports 2 chg 0000 evt 0000
[ 1325.704108] hub 3-0:1.0: state 7 ports 2 chg 0000 evt 0000
[ 1325.954073] hub 1-0:1.0: state 7 ports 2 chg 0000 evt 0000
[ 1325.954080] hub 3-0:1.0: state 7 ports 2 chg 0000 evt 0000
[ 1326.204075] hub 1-0:1.0: state 7 ports 2 chg 0000 evt 0000
[ 1326.204082] hub 3-0:1.0: state 7 ports 2 chg 0000 evt 0000
[ 1326.454319] hub 1-0:1.0: state 7 ports 2 chg 0000 evt 0000
[ 1326.454328] hub 3-0:1.0: state 7 ports 2 chg 0000 evt 0000
Created attachment 18335 [details]
lspci -nnvxxxx under 2.6.27-jvd ( linus + tip + roland trees of 2008-10-15@21:00 )
Created attachment 18336 [details]
boot log from 2.6.27-rc7-jvd (linus + tip + roland GIT trees 2008-10-15@21:00)
Jason, thanks for the lspci output. It shows that timer interrupt is routed to INT0 of IOAPIC. Thus the propagated override for IRQ0 on your Laptop is bogus. (1) My patch from comment #52 should address and fix that problem. Without the need to add every now and then new Laptop models to the DMI list you are referring to. (2) All dmi-quirks dmi_ignore_irq0_timer_override should be removed (IMHO). I'll post a patch for this asap. (3) The usb-problem is another thing -- to open a new bugzilla is the right thing to do. Maybe you should have a look at bug #11715 -- symptoms are very similar. It just seems to be a slightly different laptop model than yours. This best explains why a DMI based quirk sucks to solve this problem. If you like to test my patch you should comment out the dmi quirk for "HP 6715b laptop" in arch/x86/acpi/boot.c Created attachment 18338 [details] remove superfluous DMI quirks This patch together with patch from attachment #18305 [details] should fix the problem and avoid the warning. Thanks ! patch works as expected. But are we POSITIVE that nothing can possibly depend on IRQ0 routing or thermal trip points BEFORE your code in 'early_quirks.c' gets run ? That's why I thought it might be better to move the early-quirks.c code to acpi/boot.c, since before ACPI boots, nothing can possibly depend on it. Regards, Jason Is this supposed to be fixed in 2.6.27.2 with this patch? http://git.kernel.org/?p=linux/kernel/git/stable/linux-2.6.27.y.git;a=commit;h=e87898fdba90f9a270ae6bdb8ce98da91338a951 Yes, but not on every box having this issue. You may need some more patches from the comments above. Short summary. I'd like to see following patches upstream and in 2.6.27-stable: (1) x86: SB450: skip IRQ0 override if it is not routed to INT2 of IOAPIC (already in Linus' git and in stable tree.) (2) x86: SB600: skip IRQ0 override if it is not routed to INT2 of IOAPIC (not yet in any git-tree but sent to Ingo) (3) Remove dmi-quirks for HP Laptops that advertise bogus override for IRQ0 (not yet in any git-tree but sent to Ingo, see attachement #18338) (2) and (3) are still not upstream but already posted to Ingo/LKML. Both should go into 2.6.27-stable, too. Regarding comment #58: > But are we POSITIVE that nothing can possibly depend > on IRQ0 routing or thermal trip points BEFORE your > code in 'early_quirks.c' gets run ? Yes, what we need is that a quirk is run before ACPI MADT table is parsed. Then we can set acpi_skip_timer_override if needed and the interrupt override for IRQ0 is skipped. Calling sequence in setup_arch (x86) is as follows: early_quirks() (detect bogus IRQ0 override) ... acpi_boot_init() (e.g. setup IO APIC/parse MADT) Thus early-quirks are executed before MADT is parsed. Jason, Ingo suggested to keep the dmi-quirks for at least 1 kernel version. But then it must be moved after early-quirks are executed. I'll attach a patch which does this. Can you please test it on your machine. Thanks, Andreas Created attachment 18401 [details]
x86: call dmi-quirks for HP Laptops after early-quirks are executed
> --> (http://bugzilla.kernel.org/attachment.cgi?id=18401&action=view)
> x86: call dmi-quirks for HP Laptops after early-quirks are executed
applied to tip/x86/urgent, thanks Andreas!
Ingo
Ingo, has that gone to Linus already? shipped in linux-2.6.28-rc1: commit 26adcfbf00e0726b4469070aa2f530dcf963f484 Author: Andreas Herrmann <andreas.herrmann3@amd.com> Date: Tue Oct 14 21:01:15 2008 +0200 x86: SB600: skip ACPI IRQ0 override if it is not routed to INT2 of IOAPIC Can this fix be applied on 2.6.27-stable? It's on its way to -stable from what I can tell. Still appears to not have been applied in 2.6.27.7. Sorry for the delay. I've just resend the fix for 2.6.27-stable. I'll update the bugzilla as soon as the fix is integrated. |