>Number:         37305
>Category:       port-i386
>Synopsis:       APIC timing problems on MacBook
>Confidential:   no
>Severity:       non-critical
>Priority:       medium
>Responsible:    port-i386-maintainer
>State:          open
>Class:          sw-bug
>Submitter-Id:   net
>Arrival-Date:   Thu Nov 08 13:40:00 +0000 2007
>Originator:     Marco Trillo
>Release:        NetBSD 4.0_RC3
>Organization:
>Environment:
NetBSD 4.0_RC3 (GENERIC.MP) #0: Wed Oct 31 15:40:38 PDT 2007 builds@wb34:/home/builds/ab/netbsd-4/i386/200710310002Z-obj/home/builds/ab/netbsd-4/src/sys/arch/i386/compile/GENERIC.MP
>Description:
NetBSD 4.0_RC3/i386 has APIC timing problems when running the multiprocessor kernel on a 2x2.0 MacBook (with a 32-bit Core Duo).

The timing/calibration problem is manifested by the following examples:

# sleep 1
(will sleep 3.5 seconds approx)
# sleep 2
(will sleep 7 seconds)
# sleep 3
(will sleep 11 seconds)

In general, everything that has to do with delays or timing (sleep(1),
logout delay, keyboard repeat rate, kernel delays, etc.) runs slow --
in this case with a factor of 3.5, but this changes each reboot; it
may be a factor of 2 .

In the dmesg there is this line:
cpu0: calibrating local timer
cpu0: apic clock running at 579 MHz

The "apic clock" value changes with each reboot, for example I got 3xx MHz values too. This "miscalibration" also affects non-multiprocessor kernel (for example the default kernel included on the installation CD). I think the proper value for the APIC clock in this machine is 166 MHz.

Also, this timing problem seems to cause the second CPU to not start (cpu1: failed to start). However, if you generate USB interrupts by pressing keys in the keyboard before the kernel tries to start cpu1, it will start correctly (although its speed is not detected properly :

cpu1: Intel Pentium M (Yonah) (686-class), 7122.27 MHz

).

This suggests that this problem has something to do with USB. In fact, the fix described on the 'Fix' section is related to USB.

Full dmesg:

Copyright (c) 1996, 1997, 1998, 1999, 2000, 2001, 2002, 2003, 2004, 2005,
    2006, 2007
    The NetBSD Foundation, Inc.  All rights reserved.
Copyright (c) 1982, 1986, 1989, 1991, 1993
    The Regents of the University of California.  All rights reserved.

NetBSD 4.0_RC3 (GENERIC.MP) #0: Wed Oct 31 15:40:38 PDT 2007
	builds@wb34:/home/builds/ab/netbsd-4/i386/200710310002Z-obj/home/builds/ab/netbsd-4/src/sys/arch/i386/compile/GENERIC.MP
total memory = 480 MB
rbus: rbus_min_start set to 0x40000000
avail memory = 461 MB
timecounter: Timecounters tick every 10.000 msec
timecounter: Timecounter "i8254" frequency 1193182 Hz quality 100
mainbus0 (root)
cpu0 at mainbus0: apid 0 (boot processor)
cpu0: Intel Pentium M (Yonah) (686-class), 2063.77 MHz, id 0x6e8
cpu0: features bfe9fbff<FPU,VME,DE,PSE,TSC,MSR,PAE,MCE,CX8,APIC,SEP,MTRR>
cpu0: features bfe9fbff<PGE,MCA,CMOV,PAT,CFLUSH,DS,ACPI,MMX>
cpu0: features bfe9fbff<FXSR,SSE,SSE2,SS,HTT,TM,SBF>
cpu0: features2 c1a9<SSE3,MONITOR,VMX,EST,TM2,xTPR>
cpu0: "Genuine Intel(R) CPU           T2500  @ 2.00GHz"
cpu0: I-cache 32 KB 64B/line 8-way, D-cache 32 KB 64B/line 8-way
cpu0: L2 cache 2 MB 64B/line 8-way
cpu0: using thermal monitor 1
cpu0: Enhanced SpeedStep (1260 mV) 1667 MHz
cpu0: unknown Enhanced SpeedStep CPU.
cpu0: using only highest, current and lowest power states.
cpu0: Enhanced SpeedStep frequencies available (MHz): 2000 1667 1000
cpu0: calibrating local timer
cpu0: apic clock running at 579 MHz
cpu0: 64 page colors
cpu1 at mainbus0: apid 1 (application processor)
cpu1: starting
cpu1: Intel Pentium M (Yonah) (686-class), 7122.27 MHz, id 0x6e8
cpu1: features bfe9fbff<FPU,VME,DE,PSE,TSC,MSR,PAE,MCE,CX8,APIC,SEP,MTRR>
cpu1: features bfe9fbff<PGE,MCA,CMOV,PAT,CFLUSH,DS,ACPI,MMX>
cpu1: features bfe9fbff<FXSR,SSE,SSE2,SS,HTT,TM,SBF>
cpu1: features2 c1a9<SSE3,MONITOR,VMX,EST,TM2,xTPR>
cpu1: "Genuine Intel(R) CPU           T2500  @ 2.00GHz"
cpu1: I-cache 32 KB 64B/line 8-way, D-cache 32 KB 64B/line 8-way
cpu1: L2 cache 2 MB 64B/line 8-way
cpu1: using thermal monitor 1
ioapic0 at mainbus0 apid 1 (I/O APIC)
ioapic0: pa 0xfec00000, version 20, 24 pins
ioapic0: misconfigured as apic 0
ioapic0: remapped to apic 1
acpi0 at mainbus0: Advanced Configuration and Power Interface
acpi0: using Intel ACPI CA subsystem version 20060217
acpi0: X/RSDT: OemId <APPLE , Apple00,00000061>, AslId <    ,01000013>
acpi0: found ECDT, GPE 23
acpi0: SCI interrupting at int 9
acpi0: fixed-feature power button present
timecounter: Timecounter "ACPI-Fast" frequency 3579545 Hz quality 1000
ACPI-Fast 24-bit timer
ACPI Object Type 'Processor' (0x0c) at acpi0 not configured
ACPI Object Type 'Processor' (0x0c) at acpi0 not configured
acpiacad0 at acpi0 (ACPI0003): ACPI AC Adapter
acpilid0 at acpi0 (PNP0C0D): ACPI Lid Switch
APP0002 at acpi0 not configured
acpibut0 at acpi0 (PNP0C0C): ACPI Power Button
acpibut1 at acpi0 (PNP0C0E): ACPI Sleep Button
PNP0A08 [PCI Express/PCI-X Mode-2 Host Bridge] at acpi0 not configured
PNP0C02 [Plug and Play motherboard register resources] at acpi0 not configured
PNP0C0F [PCI interrupt link device] at acpi0 not configured
PNP0C0F [PCI interrupt link device] at acpi0 not configured
PNP0C0F [PCI interrupt link device] at acpi0 not configured
PNP0C0F [PCI interrupt link device] at acpi0 not configured
PNP0C0F [PCI interrupt link device] at acpi0 not configured
PNP0C0F [PCI interrupt link device] at acpi0 not configured
APP0001 at acpi0 not configured
APP0003 at acpi0 not configured
acpiec0 at acpi0 (PNP0C09): ACPI Embedded Controller
acpiec0: io 0x62,0x66
acpiec0: unable to map data register
ACPI0002 [Smart Battery Subsystem] at acpi0 not configured
IFX0101 at acpi0 not configured
PNP0200 [AT DMA Controller] at acpi0 not configured
INT0800 [Intel FWH Random Number Generator] at acpi0 not configured
PNP0103 [HPET Timer] at acpi0 not configured
PNP0000 [AT Interrupt Controller] at acpi0 not configured
npx1 at acpi0 (PNP0C04)
npx1: io 0xf0 irq 13
npx1: reported by CPUID; using exception 16
PNP0C02 [Plug and Play motherboard register resources] at acpi0 not configured
PNP0B00 [AT Real-Time Clock] at acpi0 not configured
attimer1 at acpi0 (PNP0100): AT Timer
attimer1: io 0x40-0x43,0x50-0x53
acpibat0 at acpi0 (PNP0C0A-0): ACPI Battery (Control Method)
pci0 at mainbus0 bus 0: configuration mode 1
pci0: i/o space, memory space enabled, rd/line, rd/mult, wr/inv ok
pchb0 at pci0 dev 0 function 0
pchb0: Intel 82945GM/PM/GMS Host Bridge (rev. 0x03)
agp0 at pchb0: unknown memory configuration, disabling
vga1 at pci0 dev 2 function 0: Intel 82945GM/PM/GMS Integrated
Graphics Device (rev. 0x03)
wsdisplay0 at vga1 kbdmux 1: console (80x25, vt100 emulation)
wsmux1: connecting to wsdisplay0
Intel 82945GM/PM/GMS Integrated Graphics Device (miscellaneous
display, revision 0x03) at pci0 dev 2 function 1 not configured
Intel product 0x27a3 (Time and Frequency DASP, revision 0x03) at pci0
dev 7 function 0 not configured
azalia0 at pci0 dev 27 function 0: Generic High Definition Audio Controller
azalia0: interrupting at ioapic0 pin 22 (irq 11)
azalia0: host: Intel 82801GB/GR High Definition Audio Controller (rev. 2)
azalia0: host: High Definition Audio rev. 1.0
ppb0 at pci0 dev 28 function 0: Intel 82801GB/GR PCI Express Port #1 (rev. 0x02)
pci1 at ppb0 bus 1
pci1: i/o space, memory space enabled, rd/line, wr/inv ok
mskc0 at pci1 dev 0 function 0mskc0: interrupt moderation is 0 us
, Yukon-2 EC rev. A3 (0x2): ioapic0 pin 16 (irq 11)
msk0 at mskc0 port A: Ethernet address 00:16:cb:ce:d1:cc
makphy0 at msk0 phy 0: Marvell 88E1111 Gigabit PHY, rev. 2
makphy0: 10baseT, 10baseT-FDX, 100baseTX, 100baseTX-FDX, 1000baseT,
1000baseT-FDX, auto
ppb1 at pci0 dev 28 function 1: Intel 82801GB/GR PCI Express Port #2 (rev. 0x02)
pci2 at ppb1 bus 2
pci2: i/o space, memory space enabled, rd/line, wr/inv ok
ath0 at pci2 dev 0 function 0
ath0: interrupting at ioapic0 pin 17 (irq 11)
ath0: 11a rates: 6Mbps 9Mbps 12Mbps 18Mbps 24Mbps 36Mbps 48Mbps 54Mbps
ath0: 11b rates: 1Mbps 2Mbps 5.5Mbps 11Mbps
ath0: 11g rates: 1Mbps 2Mbps 5.5Mbps 11Mbps 6Mbps 9Mbps 12Mbps 18Mbps
24Mbps 36Mbps 48Mbps 54Mbps
ath0: mac 10.3 phy 6.1 radio 10.2
uhci0 at pci0 dev 29 function 0: Intel 82801GB/GR USB UHCI Controller
(rev. 0x02)
uhci0: interrupting at ioapic0 pin 21 (irq 11)
usb0 at uhci0: USB revision 1.0
uhub0 at usb0
uhub0: Intel UHCI root hub, class 9/0, rev 1.00/1.00, addr 1
uhub0: 2 ports with 2 removable, self powered
uhci1 at pci0 dev 29 function 1: Intel 82801GB/GR USB UHCI Controller
(rev. 0x02)
uhci1: interrupting at ioapic0 pin 19 (irq 11)
usb1 at uhci1: USB revision 1.0
uhub1 at usb1
uhub1: Intel UHCI root hub, class 9/0, rev 1.00/1.00, addr 1
uhub1: 2 ports with 2 removable, self powered
uhci2 at pci0 dev 29 function 2: Intel 82801GB/GR USB UHCI Controller
(rev. 0x02)
uhci2: interrupting at ioapic0 pin 18 (irq 11)
usb2 at uhci2: USB revision 1.0
uhub2 at usb2
uhub2: Intel UHCI root hub, class 9/0, rev 1.00/1.00, addr 1
uhub2: 2 ports with 2 removable, self powered
uhci3 at pci0 dev 29 function 3: Intel 82801GB/GR USB UHCI Controller
(rev. 0x02)
uhci3: interrupting at ioapic0 pin 16 (irq 10)
usb3 at uhci3: USB revision 1.0
uhub3 at usb3
uhub3: Intel UHCI root hub, class 9/0, rev 1.00/1.00, addr 1
uhub3: 2 ports with 2 removable, self powered
ehci0 at pci0 dev 29 function 7: Intel 82801GB/GR USB EHCI Controller
(rev. 0x02)
ehci0: interrupting at ioapic0 pin 21 (irq 11)
ehci0: BIOS has given up ownership
ehci0: EHCI version 1.0
ehci0: companion controllers, 2 ports each: uhci0 uhci1 uhci2 uhci3
usb4 at ehci0: USB revision 2.0
uhub4 at usb4
uhub4: Intel EHCI root hub, class 9/0, rev 2.00/1.00, addr 1
uhub4: 8 ports with 8 removable, self powered
ppb2 at pci0 dev 30 function 0: Intel 82801BAM Hub-PCI Bridge (rev. 0xe2)
pci3 at ppb2 bus 3
pci3: i/o space, memory space enabled
fwohci0 at pci3 dev 3 function 0: Lucent Technologies FW322/323 IEEE
1394 Host Controller (rev. 0x61)
fwohci0: interrupting at ioapic0 pin 19 (irq 11)
fwohci0: OHCI version 1.0 (ROM=0)
fwohci0: No. of Isochronous channels is 8.
fwohci0: EUI64 00:16:cb:ff:fe:e1:c5:34
fwohci0: Phy 1394a available S400, 3 ports.
fwohci0: Link S400, max_rec 2048 bytes.
ieee1394if0 at fwohci0: IEEE1394 bus
fwip0 at ieee1394if0: IP over IEEE1394
fwohci0: Initiate bus reset
pcib0 at pci0 dev 31 function 0
pcib0: Intel 82801GBM LPC Interface Bridge (rev. 0x02)
piixide0 at pci0 dev 31 function 1
piixide0: Intel 82801GB/GR IDE Controller (ICH7) (rev. 0x02)
piixide0: bus-master DMA support present
piixide0: primary channel configured to compatibility mode
piixide0: primary channel interrupting at ioapic0 pin 14 (irq 14)
atabus0 at piixide0 channel 0
piixide0: secondary channel configured to compatibility mode
piixide0: secondary channel interrupting at ioapic0 pin 15 (irq 15)
atabus1 at piixide0 channel 1
piixide1 at pci0 dev 31 function 2
piixide1: Intel 82801GBM/GHM Serial ATA Controller (ICH7) (rev. 0x02)
piixide1: bus-master DMA support present
piixide1: primary channel configured to native-PCI mode
piixide1: using ioapic0 pin 19 (irq 11) for native-PCI interrupt
atabus2 at piixide1 channel 0
piixide1: secondary channel configured to native-PCI mode
atabus3 at piixide1 channel 1
Intel 82801GB/GR SMBus Controller (SMBus serial bus, revision 0x02) at
pci0 dev 31 function 3 not configured
isa0 at pcib0
pcppi0 at isa0 port 0x61
pcppi0: children must have an explicit unit
midi0 at pcppi0: PC speaker (CPU-intensive output)
sysbeep0 at pcppi0
isapnp0 at isa0 port 0x279: ISA Plug 'n Play device support
pcppi0: attached to attimer1
isapnp0: no ISA Plug 'n Play devices found
ioapic0: enabling
WARNING: Callback scheduled before sysmon task queue thread present.
fwohci0: node_id=0xc000ffc0, gen=2, CYCLEMASTER mode
ieee1394if0: 1 nodes, maxhop <= 0, cable IRM = 0 (me)
ieee1394if0: bus manager 0 (me)
timecounter: Timecounter "clockinterrupt" frequency 100 Hz quality 0
azalia0: codec[0]: Sigmatel STAC9221 (rev. 52.1)
azalia0: codec[0]: High Definition Audio rev. 1.0
azalia0: playback: max channels=8, encodings=1<PCM>
azalia0: playback: PCM
formats=e07e0<24bit,20bit,16bit,192kHz,176.4kHz,96kHz,88.2kHz,48kHz,44.1kHz>
azalia0: recording: max channels=4, encodings=1<PCM>
azalia0: recording: PCM
formats=e07e0<24bit,20bit,16bit,192kHz,176.4kHz,96kHz,88.2kHz,48kHz,44.1kHz>
audio0 at azalia0: full duplex, independent
Kernelized RAIDframe activated
atapibus0 at atabus0: 2 targets
cd0 at atapibus0 drive 0: <MATSHITADVD-R   UJ-857, , HBEA> cdrom removable
cd0: 32-bit data port
cd0: drive supports PIO mode 4, DMA mode 2, Ultra-DMA mode 4 (Ultra/66)
cd0(piixide0:0:0): using PIO mode 4, Ultra-DMA mode 4 (Ultra/66) (using DMA)
wd0 at atabus2 drive 1: <ST96812AS>
wd0: drive supports 16-sector PIO transfers, LBA48 addressing
wd0: 57231 MB, 116280 cyl, 16 head, 63 sec, 512 bytes/sect x 117210240 sectors
wd0: 32-bit data port
wd0: drive supports PIO mode 4, DMA mode 2, Ultra-DMA mode 6 (Ultra/133)
wd0(piixide1:0:1): using PIO mode 4, Ultra-DMA mode 6 (Ultra/133) (using DMA)
uhidev0 at uhub0 port 2 configuration 1 interface 0
uhidev0: Apple Computer Apple Internal Keyboard / Trackpad, rev
2.00/0.64, addr 2, iclass 3/1
ukbd0 at uhidev0
wskbd0 at ukbd0: console keyboard, using wsdisplay0
uhidev1 at uhub0 port 2 configuration 1 interface 1
uhidev1: Apple Computer Apple Internal Keyboard / Trackpad, rev
2.00/0.64, addr 2, iclass 3/1
uhidev1: 5 report ids
ums0 at uhidev1 reportid 2: 3 buttons
wsmouse0 at ums0 mux 0
uhid0 at uhidev1 reportid 5: input=63, output=0, feature=16
uhidev2 at uhub0 port 2 configuration 1 interface 2ugen0 at uhub4 port 4
ugen0: Apple Computer product 0x8300, rev 2.00/0.0c, addr 2

uhidev2: Apple Computer Apple Internal Keyboard / Trackpad, rev
2.00/0.64, addr 2, iclass 3/0
uhid1 at uhidev2: input=1, output=0, feature=0
uhub5 at uhub1 port 1
uhub5: Mitsumi Electric Hub in Apple Extended USB Keyboard, class 9/0,
rev 1.10/4.10, addr 2
uhub5: 3 ports with 2 removable, bus powered
uhidev3 at uhub5 port 3 configuration 1 interface 0
uhidev3: Mitsumi Electric Apple Extended USB Keyboard, rev 1.10/4.10,
addr 3, iclass 3/1
ukbd1 at uhidev3
boot device: wd0
root on wd0a dumps on wd0b
root file system type: ffs
cpu1: CPU 1 running
mskc0: interrupt moderation is 1000 us
wskbd1 at ukbd1 mux 1
wskbd1: connecting to wsdisplay0
uhidev4 at uhub5 port 3 configuration 1 interface 1
uhidev4: Mitsumi Electric Apple Extended USB Keyboard, rev 1.10/4.10,
addr 3, iclass 3/0
uhidev4: 3 report ids
uhid2 at uhidev4 reportid 2: input=1, output=0, feature=0
uhid3 at uhidev4 reportid 3: input=3, output=0, feature=0
uhidev5 at uhub2 port 2 configuration 1 interface 0
uhidev5: Apple Computer, Inc. IR Receiver, rev 2.00/1.10, addr 2, iclass 3/0
uhidev5: 38 report ids
uhid4 at uhidev5 reportid 36: input=4, output=0, feature=0
uhid5 at uhidev5 reportid 37: input=4, output=0, feature=0
uhid6 at uhidev5 reportid 38: input=4, output=0, feature=0
uhidev6 at uhub3 port 1 configuration 1 interface 0
uhidev6: Apple Computer product 0x1000, rev 2.00/19.65, addr 2, iclass 3/1
ukbd2 at uhidev6
wskbd2 at ukbd2 mux 1
wskbd2: connecting to wsdisplay0
uhidev7 at uhub3 port 1 configuration 1 interface 1
uhidev7: Apple Computer product 0x1000, rev 2.00/19.65, addr 2, iclass 3/1
ums1 at uhidev7: 5 buttons
wsmouse1 at ums1 mux 0
wsdisplay0: screen 1 added (80x25, vt100 emulation)
wsdisplay0: screen 2 added (80x25, vt100 emulation)
wsdisplay0: screen 3 added (80x25, vt100 emulation)
wsdisplay0: screen 4 added (80x25, vt100 emulation)
>How-To-Repeat:
Always repeatable when running a NetBSD kernel on the affected machine (MacBook, perhaps others too).
In fact, this problem also affects FreeBSD and Linux running on the same machines, so it's probably a quirk with these machines more than a bug in NetBSD itself.

>Fix:
This fix was described by Ryan Lortie regarding a similar problem with Linux, but it also works on NetBSD:

It appears that the cause of this problem is some feature of the Intel ICH7 called
"LEGACY_USB" which "causes legacy USB circuit to cause SMI";
apparently such SMIs being thrown in the middle of the calibration process botch the calibration and the timing problems occur.

Based on such report, I have added a quirk at the start of the
initrtclock() function in src/sys/arch/x86/isa/clock.c to disable the
LEGACY_USB SMI bit:

outl(0x430, inl(0x430) & ~8);

Indeed, the quirk appears to be working:

cpu0 at mainbus0: apid 0 (boot processor)
cpu0: Intel Pentium M (Yonah) (686-class), 1997.51 MHz
[snip]
cpu0: calibrating local timer
cpu0: apic clock running at 166 MHz
[snip]
cpu1: Intel Pentium M (Yonah) (686-class), 1997.33 MHz
[snip]

The apic clock is reported always at 166 MHz in each of the reboots,
no more different values in each reboot. Also the second core (cpu1) always starts correctly --without having to press any USB keys-- and the processor speed is
guessed correctly. The timing appears to work now:

# sleep 2
(sleeps 2 seconds)

This is a quirk; this needs to be done in a clean and portable way that doesn't cause problems in other machines. Also, does this affect any ICH7-based machine with USB devices?