Bug 5031

Summary: Sempron 2800+ (1.6GHz) sleeps half as long as it should
Product: Timers Reporter: Keith Hellman (khellman)
Component: Interval TimersAssignee: john stultz (john.stultz)
Status: REJECTED DUPLICATE    
Severity: normal CC: john.stultz, zwane
Priority: P2    
Hardware: i386   
OS: Linux   
Kernel Version: 2.6.12.4 Subsystem:
Regression: --- Bisected commit-id:
Attachments: cpufreq-info with apic boot
cpufreq without apic boot
dmesg with apic boot
dmesg without apic boot
config for 2.6.12.4 and dmesg/cpufreq output files

Description Keith Hellman 2005-08-08 22:46:14 UTC
Distribution: debian etch w/ Linus' 2.6.12.4 kernel tree from kernel.org
Hardware Environment: HP Pavilion ze2000 w/ Sempron 2800+ (1.6GHz CPU)
Software Environment: good ol plain vanilla X or console
Problem Description: 
$ time ssh <known_good_machine> sleep 10 
returns a time of 20s.  running the reverse from the <known_good_machine>:
<known_good_machine>$ time ssh <sempron_machine> sleep 10
consistently returns about 5s.

Steps to reproduce: Pretty much boot any kernel and run the above commands.
For the 2.6.12.4 mainline, I've tried the different modes of acpi, hpet=disable,
cpufreq on or off, disabled or not.  I've tried acpi=off, and I've made sure the
dyn_ticks patch is not in my kernel.

There appears to be recent reports of this:
- http://www.ussg.iu.edu/hypermail/linux/kernel/0412.2/0937.html
- http://infoarchive.net/sgroup/linux-kernel/248853/

I tried changing HZ to 2000 in asm/params.h and linux/jiffies.h, but that
produced no changes - which I'm a little surprised at.

Below I've include some /proc dumps and my latest dmesg output from the HZ=2000
kernel.  I'm very movtivated to provide any other information needed so don't
hesitate to ask.  I'm pretty sure I can patch, diff, and build test kernels
so just tell me what else needs to be done.

TIA
+++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++
== cpuinfo
processor	: 0
vendor_id	: AuthenticAMD
cpu family	: 15
model		: 28
model name	: Mobile AMD Sempron(tm) Processor 2800+
stepping	: 0
cpu MHz		: 1603.631
cache size	: 256 KB
fdiv_bug	: no
hlt_bug		: no
f00f_bug	: no
coma_bug	: no
fpu		: yes
fpu_exception	: yes
cpuid level	: 1
wp		: yes
flags		: fpu vme de pse tsc msr pae mce cx8 apic sep mtrr pge mca cmov pat pse36
clflush mmx fxsr sse sse2 syscall nx mmxext fxsr_opt 3dnowext 3dnow lahf_lm
bogomips	: 3112.20

== cmdline
root=/dev/hda1 ro acpi=noirq apm=off ide0=dma ide1=dma 
== interrupts
           CPU0       
  0:   10844477    IO-APIC-edge  timer
  1:       8544    IO-APIC-edge  i8042
  2:          0          XT-PIC  cascade
  9:          0    IO-APIC-edge  acpi
 12:       4711    IO-APIC-edge  i8042
 14:       7066    IO-APIC-edge  ide0
 15:         12    IO-APIC-edge  ide1
137:          1   IO-APIC-level  ATI IXP
145:       3342   IO-APIC-level  eth0
153:      23411   IO-APIC-level  ohci_hcd:usb1, ohci_hcd:usb2, ehci_hcd:usb3
NMI:          0 
LOC:    5422598 
ERR:          2
MIS:          0
$ uptime
 00:29:21 up  1:30,  4 users,  load average: 0.01, 0.04, 0.05
$ dmesg
Linux version 2.6.12.4-hpze2000-2khz (root@doberman) (gcc version 3.3.5 (Debian
1:3.3.5-13)) #1 Sun Aug 14 08:17:51 MDT 2005
BIOS-provided physical RAM map:
 BIOS-e820: 0000000000000000 - 000000000009f800 (usable)
 BIOS-e820: 000000000009f800 - 00000000000a0000 (reserved)
 BIOS-e820: 00000000000d2000 - 0000000000100000 (reserved)
 BIOS-e820: 0000000000100000 - 000000000def0000 (usable)
 BIOS-e820: 000000000def0000 - 000000000deff000 (ACPI data)
 BIOS-e820: 000000000deff000 - 000000000df00000 (ACPI NVS)
 BIOS-e820: 000000000df00000 - 0000000010000000 (reserved)
 BIOS-e820: 00000000fec00000 - 00000000fec10000 (reserved)
 BIOS-e820: 00000000fee00000 - 00000000fee01000 (reserved)
 BIOS-e820: 00000000fff80000 - 0000000100000000 (reserved)
0MB HIGHMEM available.
222MB LOWMEM available.
found SMP MP-table at 000f8330
On node 0 totalpages: 57072
  DMA zone: 4096 pages, LIFO batch:1
  Normal zone: 52976 pages, LIFO batch:31
  HighMem zone: 0 pages, LIFO batch:1
DMI present.
ACPI: RSDP (v000 HP                                    ) @ 0x000f8280
ACPI: RSDT (v001 HP     3096     0x20040608  LTP 0x00000000) @ 0x0def8c5b
ACPI: FADT (v001 HP     3096     0x20040608 PTL  0x0000005f) @ 0x0defee41
ACPI: SSDT (v001 PTLTD  POWERNOW 0x20040608  LTP 0x00000001) @ 0x0defeeb5
ACPI: MADT (v001 PTLTD  	 3096   0x20040608  LTP 0x00000000) @ 0x0defef6a
ACPI: MCFG (v001 PTLTD    MCFG   0x20040608  LTP 0x00000000) @ 0x0defefc4
ACPI: DSDT (v001 HP     3091     0x20040608 MSFT 0x0100000e) @ 0x00000000
ACPI: PM-Timer IO Port: 0x8008
ACPI: Local APIC address 0xfee00000
ACPI: LAPIC (acpi_id[0x00] lapic_id[0x00] enabled)
Processor #0 15:12 APIC version 16
ACPI: LAPIC_NMI (acpi_id[0x00] high edge lint[0x1])
Using ACPI for processor (LAPIC) configuration information
Intel MultiProcessor Specification v1.4
    Virtual Wire compatibility mode.
OEM ID:          Product ID:              APIC at: 0xFEE00000
I/O APIC #1 Version 33 at 0xFEC00000.
Enabling APIC mode:  Flat.  Using 1 I/O APICs
Processors: 1
Allocating PCI resources starting at 10000000 (gap: 10000000:eec00000)
Built 1 zonelists
Kernel command line: root=/dev/hda1 ro acpi=noirq apm=off ide0=dma ide1=dma 
mapped APIC to ffffd000 (fee00000)
mapped IOAPIC to ffffc000 (fec00000)
Initializing CPU#0
PID hash table entries: 1024 (order: 10, 16384 bytes)
Detected 1603.631 MHz processor.
Using pmtmr for high-res timesource
Console: colour VGA+ 80x25
Dentry cache hash table entries: 32768 (order: 5, 131072 bytes)
Inode-cache hash table entries: 16384 (order: 4, 65536 bytes)
Memory: 218496k/228288k available (1643k kernel code, 9244k reserved, 746k data,
176k init, 0k highmem)
Checking if this processor honours the WP bit even in supervisor mode... Ok.
Calibrating delay loop... 3112.20 BogoMIPS (lpj=778240)
Security Framework v1.0.0 initialized
Mount-cache hash table entries: 512
CPU: After generic identify, caps: 078bfbff c3d3fbff 00000000 00000000 00000000
00000000 00000001
CPU: After vendor identify, caps: 078bfbff c3d3fbff 00000000 00000000 00000000
00000000 00000001
CPU: L1 I Cache: 64K (64 bytes/line), D cache 64K (64 bytes/line)
CPU: L2 Cache: 256K (64 bytes/line)
CPU: After all inits, caps: 078bfbff c3d3fbff 00000000 00000010 00000000
00000000 00000001
Intel machine check architecture supported.
Intel machine check reporting enabled on CPU#0.
CPU: AMD Mobile AMD Sempron(tm) Processor 2800+ stepping 00
Enabling fast FPU save and restore... done.
Enabling unmasked SIMD FPU exception support... done.
Checking 'hlt' instruction... OK.
ACPI: setting ELCR to 0e28 (from 0c28)
ENABLING IO-APIC IRQs
..TIMER: vector=0x31 pin1=2 pin2=0
checking if image is initramfs...it isn't (bad gzip magic numbers); looks like
an initrd
Freeing initrd memory: 4452k freed
NET: Registered protocol family 16
PCI: PCI BIOS revision 2.10 entry at 0xfd8bc, last bus=6
PCI: Using configuration type 1
mtrr: v2.0 (20020519)
ACPI: Subsystem revision 20050309
ACPI: Interpreter enabled
ACPI: Using PIC for interrupt routing
ACPI: PCI Root Bridge [PCI0] (0000:00)
PCI: Probing PCI hardware (bus 00)
PCI: Ignoring BAR0-3 of IDE controller 0000:00:14.1
Boot video device is 0000:01:05.0
PCI: Transparent bridge - 0000:00:14.4
ACPI: PCI Interrupt Routing Table [\_SB_.PCI0._PRT]
ACPI: Embedded Controller [EC0] (gpe 24)
ACPI: PCI Interrupt Routing Table [\_SB_.PCI0.P2P_._PRT]
ACPI: PCI Interrupt Routing Table [\_SB_.PCI0.AGP_._PRT]
Linux Plug and Play Support v0.97 (c) Adam Belay
pnp: PnP ACPI init
pnp: PnP ACPI: found 10 devices
PnPBIOS: Disabled by ACPI PNP
PCI: Probing PCI hardware
PCI->APIC IRQ transform: 0000:00:13.0[A] -> IRQ 153
PCI->APIC IRQ transform: 0000:00:13.1[A] -> IRQ 153
PCI->APIC IRQ transform: 0000:00:13.2[A] -> IRQ 153
PCI->APIC IRQ transform: 0000:00:14.1[A] -> IRQ 137
PCI->APIC IRQ transform: 0000:00:14.5[B] -> IRQ 137
PCI->APIC IRQ transform: 0000:00:14.6[B] -> IRQ 137
PCI->APIC IRQ transform: 0000:01:05.0[A] -> IRQ 137
PCI->APIC IRQ transform: 0000:05:00.0[A] -> IRQ 145
PCI->APIC IRQ transform: 0000:05:09.0[A] -> IRQ 137
pnp: 00:07: ioport range 0x1080-0x1080 has been reserved
pnp: 00:07: ioport range 0x220-0x22f has been reserved
pnp: 00:07: ioport range 0x40b-0x40b has been reserved
pnp: 00:07: ioport range 0x4d0-0x4d1 has been reserved
VFS: Disk quotas dquot_6.5.1
Dquot-cache hash table entries: 1024 (order 0, 4096 bytes)
devfs: 2004-01-31 Richard Gooch (rgooch@atnf.csiro.au)
devfs: boot_options: 0x0
Initializing Cryptographic API
isapnp: Scanning for PnP cards...
isapnp: No Plug & Play device found
PNP: PS/2 Controller [PNP0303:KBC0,PNP0f13:MSE0] at 0x60,0x64 irq 1,12
serio: i8042 AUX port at 0x60,0x64 irq 12
serio: i8042 KBD port at 0x60,0x64 irq 1
Serial: 8250/16550 driver $Revision: 1.90 $ 48 ports, IRQ sharing enabled
io scheduler noop registered
io scheduler anticipatory registered
io scheduler deadline registered
io scheduler cfq registered
RAMDISK driver initialized: 16 RAM disks of 8192K size 1024 blocksize
NET: Registered protocol family 2
IP: routing cache hash table of 2048 buckets, 16Kbytes
TCP established hash table entries: 8192 (order: 4, 65536 bytes)
TCP bind hash table entries: 8192 (order: 3, 32768 bytes)
TCP: Hash tables configured (established 8192 bind 8192)
NET: Registered protocol family 8
NET: Registered protocol family 20
ACPI wakeup devices: 
KBC0 MSE0  P2P AUDO 
ACPI: (supports S0 S3 S4 S5)
RAMDISK: cramfs filesystem found at block 0
RAMDISK: Loading 4452KiB [1 disk] into ram disk... |/-\|/-\|/-\|/-\|/-\|/-\|/-\|/-\|/-\|/-\|/-\|/-\|/-\|/-\|/-\|/-\|/-\|/-\|/-\|/-\|/-\|/-\|/-\|/-\|/-\|/-\|/-\|/-\|/-\|/-\|/-\|/-\|/-\|/-\|/-\|/-\|/-\|/-\|/-\|/-\|/-\|/-\|/-\|/-\|/-\|/-\|/-\|/-\|/-\|/-\|/-\|/-\|/-\|/-\|/-\|/-\|/-\|/-\|/-\|/-\|/-\|/-\|/-\|/-\|/-\|/-\|/-\|/-\|/-\|/-done.
VFS: Mounted root (cramfs filesystem) readonly.
input: AT Translated Set 2 keyboard on isa0060/serio0
Freeing unused kernel memory: 176k freed
ide_setup: ide0=dma -- OBSOLETE OPTION, WILL BE REMOVED SOON!
ide_setup: ide1=dma -- OBSOLETE OPTION, WILL BE REMOVED SOON!
Uniform Multi-Platform E-IDE driver Revision: 7.00alpha2
ide: Assuming 33MHz system bus speed for PIO modes; override with idebus=xx
NET: Registered protocol family 1
ATIIXP: IDE controller at PCI slot 0000:00:14.1
ATIIXP: chipset revision 0
ATIIXP: not 100% native mode: will probe irqs later
    ide0: BM-DMA at 0x8410-0x8417, BIOS settings: hda:DMA, hdb:pio
    ide1: BM-DMA at 0x8418-0x841f, BIOS settings: hdc:DMA, hdd:pio
Probing IDE interface ide0...
hda: TOSHIBA MK4025GAS, ATA DISK drive
ide0 at 0x1f0-0x1f7,0x3f6 on irq 14
Probing IDE interface ide1...
hdc: Toshiba DVD-ROM SD-C2612, ATAPI CD/DVD-ROM drive
ide1 at 0x170-0x177,0x376 on irq 15
Probing IDE interface ide2...
Probing IDE interface ide3...
Probing IDE interface ide4...
Probing IDE interface ide5...
hda: max request size: 128KiB
hda: 78140160 sectors (40007 MB), CHS=65535/16/63, UDMA(100)
hda: cache flushes supported
 /dev/ide/host0/bus0/target0/lun0: p1 p2 p3 < p5 p6 p7 p8 p9 p10 >
EXT3-fs: mounted filesystem with ordered data mode.
kjournald starting.  Commit interval 5 seconds
Adding 747012k swap on /dev/hda2.  Priority:-1 extents:1
EXT3 FS on hda1, internal journal
Generic RTC Driver v1.07
hdc: ATAPI 24X DVD-ROM drive, 192kB Cache, DMA
Uniform CD-ROM driver Revision: 3.20
ACPI: CPU0 (power states: C1[C1] C2[C2])
ACPI: Processor [CPU0] (supports 8 throttling states)
powernow-k8: Found 1 AMD Athlon 64 / Opteron processors (version 1.40.4)
powernow-k8:    0 : fid 0x8 (1600 MHz), vid 0x8 (1350 mV)
powernow-k8:    1 : fid 0x0 (800 MHz), vid 0x13 (1075 mV)
cpu_init done, current fid 0x8, vid 0x8
device-mapper: 4.4.0-ioctl (2005-01-12) initialised: dm-devel@redhat.com
input: ImPS/2 Generic Wheel Mouse on isa0060/serio1
mice: PS/2 mouse device common for all mice
ts: Compaq touchscreen protocol output
kjournald starting.  Commit interval 5 seconds
EXT3 FS on dm-3, internal journal
EXT3-fs: mounted filesystem with ordered data mode.
kjournald starting.  Commit interval 5 seconds
EXT3 FS on dm-1, internal journal
EXT3-fs: mounted filesystem with ordered data mode.
kjournald starting.  Commit interval 5 seconds
EXT3 FS on dm-2, internal journal
EXT3-fs: mounted filesystem with ordered data mode.
kjournald starting.  Commit interval 5 seconds
EXT3 FS on dm-0, internal journal
EXT3-fs: mounted filesystem with ordered data mode.
8139too Fast Ethernet driver 0.9.27
eth0: RealTek RTL8139 at 0xa000, 00:c0:9f:b5:4f:73, IRQ 145
eth0:  Identified 8139 chip type 'RTL-8100B/8139D'
SCSI subsystem initialized
Linux agpgart interface v0.101 (c) Dave Jones
pci_hotplug: PCI Hot Plug PCI Core version: 0.5
shpchp: shpc_init : shpc_cap_offset == 0
shpchp: Standard Hot Plug PCI Controller Driver version: 0.4
usbcore: registered new driver usbfs
usbcore: registered new driver hub
ohci_hcd: 2004 Nov 08 USB 1.1 'Open' Host Controller (OHCI) Driver (PCI)
ohci_hcd 0000:00:13.0: PCI device 1002:4374 (ATI Technologies Inc)
ohci_hcd 0000:00:13.0: new USB bus registered, assigned bus number 1
ohci_hcd 0000:00:13.0: irq 153, io mem 0xd0000000
hub 1-0:1.0: USB hub found
hub 1-0:1.0: 4 ports detected
ohci_hcd 0000:00:13.1: PCI device 1002:4375 (ATI Technologies Inc)
usb 1-1: new low speed USB device using ohci_hcd and address 2
ohci_hcd 0000:00:13.1: new USB bus registered, assigned bus number 2
ohci_hcd 0000:00:13.1: irq 153, io mem 0xd0001000
hub 2-0:1.0: USB hub found
hub 2-0:1.0: 4 ports detected
usbcore: registered new driver hiddev
input: USB HID v1.10 Mouse [Logitech USB-PS/2 Optical Mouse] on usb-0000:00:13.0-1
usbcore: registered new driver usbhid
drivers/usb/input/hid-core.c: v2.01:USB HID core driver
ehci_hcd 0000:00:13.2: PCI device 1002:4373 (ATI Technologies Inc)
ehci_hcd 0000:00:13.2: new USB bus registered, assigned bus number 3
ehci_hcd 0000:00:13.2: irq 153, io mem 0xd0002000
ehci_hcd 0000:00:13.2: USB 2.0 initialized, EHCI 1.00, driver 10 Dec 2004
usb 1-1: USB disconnect, address 2
hub 3-0:1.0: USB hub found
hub 3-0:1.0: 8 ports detected
usb 1-1: new low speed USB device using ohci_hcd and address 3
input: USB HID v1.10 Mouse [Logitech USB-PS/2 Optical Mouse] on usb-0000:00:13.0-1
8139cp: 10/100 PCI Ethernet driver v1.2 (Mar 22, 2004)
input: PC Speaker
eth0: link up, 10Mbps, half-duplex, lpa 0x0000
NET: Registered protocol family 17
NET: Registered protocol family 10
Disabled Privacy Extensions on device c0329940(lo)
IPv6 over IPv4 tunneling driver
ACPI: Battery Slot [BAT1] (battery present)
ACPI: AC Adapter [ACAD] (on-line)
ACPI: Power Button (FF) [PWRF]
ACPI: Sleep Button (CM) [SLPB]
ACPI: Lid Switch [LID]
ACPI: Thermal Zone [THRM] (53 C)
eth0: no IPv6 routers present
APIC error on CPU0: 00(40)
APIC error on CPU0: 40(40)
Comment 1 Adrian Bunk 2005-08-08 23:43:31 UTC
*** Bug 5032 has been marked as a duplicate of this bug. ***
Comment 2 Zwane Mwaikambo 2005-08-09 06:47:14 UTC
Could you please boot with noapic? Also does the clock run twice as fast if you
enable; CONFIG_CPU_FREQ_DEFAULT_GOV_PERFORMANCE and CONFIG_CPU_FREQ_GOV_PERFORMANCE
Comment 3 john stultz 2005-08-09 10:42:58 UTC
Possibly related to Bug #3927 ?
Comment 4 john stultz 2005-08-09 10:48:34 UTC
Also possibly related: bug #3341 ?
Comment 5 Keith Hellman 2005-08-10 09:58:04 UTC
Created attachment 5584 [details]
cpufreq-info with apic boot
Comment 6 Keith Hellman 2005-08-10 09:58:38 UTC
Created attachment 5585 [details]
cpufreq without apic boot
Comment 7 Keith Hellman 2005-08-10 09:59:12 UTC
Created attachment 5586 [details]
dmesg with apic boot
Comment 8 Keith Hellman 2005-08-10 09:59:40 UTC
Created attachment 5587 [details]
dmesg without apic boot
Comment 9 Keith Hellman 2005-08-10 10:00:28 UTC
Created attachment 5588 [details]
config for 2.6.12.4 and dmesg/cpufreq output files
Comment 10 Keith Hellman 2005-08-10 10:01:29 UTC
Good News, but first:
- yes, this seems to be the same defect as #3927, sorry for submitting the duplicate
- no, it doesn't seem to be the same as #3341.  differences include twice as
fast versus 3x as fast, but probably most importantly, I can reproduce the
timing defect very reliably.  none of this 90% of the time its 2x, 10% its ok, &
only cold boots change the state.

Now the Good News I promised:  booting with noapic does in fact remedy the
problem.  this is the case with 2.6.12.4 stock as well as the debian 2.6.8-k7
debian package (for what that's worth).

I can't believe I didn't try noapic before posting.  Seems like such the obvious
parameter to try.

Here is something intersting:  cpufreq reports my CPU at 800MHz when I boot with
noapic and (I can raise it to 1.6GHz without any detrimental effects), and
cpufreq reports my CPU at 1.6GHz when the I boot without noapic and my machine
has a 2x clock.  I've posted relevent files.

Thanks again for all of your help, I would be happy to test any patches that
would allow me to turn the apic support back on, just let me know.

Comment 11 john stultz 2005-08-10 11:16:44 UTC
Agreed, I'm marking this as a dupe of #3927. 

If you want to use apic mode, you can alternatively use "no_timer_check" to work
around this issue.

*** This bug has been marked as a duplicate of 3927 ***
Comment 12 Keith Hellman 2005-08-10 18:01:30 UTC
I'm not sure if I should be posting this at the #3927 or here.  I've tried the
no_timer_check kernel param (this time against debian's 2.6.11 k7 kernel, sorry,
I had already removed the stock kernel) and it doesn't work, in fact it fails in
a strange way:
- with 'debug' and 'no_timer_check' as kernel params
- boots till the powernow_k8 module loads, then it stalls 
- I have to generate interrupts by scratching the touchpad to make the boot continue
- finally, the boot absolutely halts after usbcore is loaded and the usb bus is
(I assume) being probed.

Since the boot never finishes, I don't have dmesg output.  If there is a way to
record this and you'd like to see it, let me know and I'll try to provide a log.

BTW thanks for adding me to the #3927 CC list.