From mboxrd@z Thu Jan 1 00:00:00 1970 From: Stephen Blake Subject: "An unexpected IO-APIC was found" Date: Fri, 07 Nov 2003 18:44:58 +0000 Sender: linux-smp-owner@vger.kernel.org Message-ID: <3FABE82A.97ADDDEF@ntlworld.com> Mime-Version: 1.0 Content-Type: multipart/mixed; boundary="------------0E836366BFB57BEDA3E3E8C9" Return-path: List-Id: To: linux-smp@vger.kernel.org This is a multi-part message in MIME format. --------------0E836366BFB57BEDA3E3E8C9 Content-Type: text/plain; charset=us-ascii Content-Transfer-Encoding: 7bit Dear Sirs, I am having a problem of low computational speed. The command dmesg has given a message "An unexpected IO-APIC was found" recommending that it be e-mailed to you. The complete dmesg is attached to this e-mail. I also include the text of a message that I have sent to Support SUSE LINUX AG which may further illuminate the problem. *********** Text sent to SUSE support ************** I have an old 500MHz Pentium 3 running SuSE Linux 7.1 (kernel 2.4.0). I needed to speed up the execution of a numerical algorithm running in scilab, so I put together a 3GHz P4 XEON APIC v16 on a Shuttle FB61 main board with SuSE Linux 9.0 (kernel 2.4.21-99 SMP4G). To my surprise, the *old* P3 system runs the scilab program *faster* than the new P4. The vmstat command gives the following CPU information when the scilab program is iterating. ----- cpu ----- us sy id wa P3 82 18 0 P4 8 43 49 0 top gives: P4 without scilab: 0.5% user, 40.1% system, 0.0% nice, 59.9% idle P4 with scilab: 30% user, 50% system, 0.0% nice, 20% idle P3 without scilab: 0.3% user, 0.1% system, 0.0% nice, 99.4% idle P3 with scilab: 83% user, 17% system, 0.0% nice, 0% idle Also, the times for running scilab on the P4 vary from run to run. The scilab test runs for 19 iterations of my algorithm. On one run this took 42sec and on the next run with the same data 80sec. On the 80sec run top was showing user time falling to 8% after a while whilst the system was always around 50% with idle taking up the difference. I don't know if this is significant, but the result of the command dmesg gives a lot of information, and within this information is the message "An unexpected IO-APIC was found. If this kernel release is less than three months old please report this to linux-smp@vger.kernel.org". Here is the fragment from dmesg surrounding the message. IO APIC #2...... .... register #00: 02000000 ....... : physical APIC id: 02 ....... : Delivery Type: 0 ....... : LTS : 0 .... register #01: 00178020 ....... : max redirection entries: 0017 ....... : PRQ implemented: 1 ....... : IO APIC version: 0020 .... register #02: 00178020 ....... : arbitration: 00 An unexpected IO-APIC was found. If this kernel release is less than three months old please report this to linux-smp@vger.kernel.org .... IRQ redirection table: NR Log Phy Mask Trig IRR Pol Stat Dest Deli Vect: 00 000 00 1 0 0 0 0 0 0 00 01 003 03 0 0 0 0 0 1 1 39 The complete result of dmesg is attached to this e-mail. ***************** End of text ****************** Yours sincerely Stephen Blake --------------0E836366BFB57BEDA3E3E8C9 Content-Type: text/plain; charset=us-ascii; name="dmesg.txt" Content-Transfer-Encoding: 7bit Content-Disposition: inline; filename="dmesg.txt" SB61 00000.04096) @ 0x00000000 ACPI: Local APIC address 0xfee00000 ACPI: LAPIC (acpi_id[0x00] lapic_id[0x00] enabled) Processor #0 Pentium 4(tm) XEON(tm) APIC version 16 ACPI: LAPIC (acpi_id[0x01] lapic_id[0x01] enabled) Processor #1 Pentium 4(tm) XEON(tm) APIC version 16 ACPI: LAPIC_NMI (acpi_id[0x00] polarity[0x1] trigger[0x1] lint[0x1]) ACPI: LAPIC_NMI (acpi_id[0x01] polarity[0x1] trigger[0x1] lint[0x1]) ACPI: IOAPIC (id[0x02] address[0xfec00000] global_irq_base[0x0]) IOAPIC[0]: Assigned apic_id 2 IOAPIC[0]: apic_id 2, version 32, address 0xfec00000, IRQ 0-23 ACPI: INT_SRC_OVR (bus[0] irq[0x0] global_irq[0x2] polarity[0x0] trigger[0x0]) ACPI: INT_SRC_OVR (bus[0] irq[0x9] global_irq[0x9] polarity[0x1] trigger[0x3]) Using ACPI (MADT) for SMP configuration information Building zonelist for node : 0 Kernel command line: root=/dev/hdc2 vga=0x317 desktop splash=silent bootsplash: silent mode. Initializing CPU#0 Detected 3007.240 MHz processor. Console: colour dummy device 80x25 Calibrating delay loop... 5947.39 BogoMIPS Memory: 1015352k/1040320k available (1880k kernel code, 16260k reserved, 638k data, 188k init, 122816k highmem) Dentry cache hash table entries: 131072 (order: 8, 1048576 bytes) Inode cache hash table entries: 65536 (order: 7, 524288 bytes) Mount cache hash table entries: 512 (order: 0, 4096 bytes) Buffer-cache hash table entries: 65536 (order: 6, 262144 bytes) Page-cache hash table entries: 262144 (order: 8, 1048576 bytes) CPU: Trace cache: 12K uops, L1 D cache: 8K CPU: L2 cache: 512K CPU: Physical Processor ID: 0 Intel machine check architecture supported. Intel machine check reporting enabled on CPU#0. CPU: After generic, caps: bfebfbff 00000000 00000000 00000000 CPU: Common caps: bfebfbff 00000000 00000000 00000000 Enabling fast FPU save and restore... done. Enabling unmasked SIMD FPU exception support... done. Checking 'hlt' instruction... OK. POSIX conformance testing by UNIFIX mtrr: v1.40 (20010327) Richard Gooch (rgooch@atnf.csiro.au) mtrr: detected mtrr type: Intel CPU: Trace cache: 12K uops, L1 D cache: 8K CPU: L2 cache: 512K CPU: Physical Processor ID: 0 Intel machine check reporting enabled on CPU#0. CPU: After generic, caps: bfebfbff 00000000 00000000 00000000 CPU: Common caps: bfebfbff 00000000 00000000 00000000 CPU0: Intel(R) Pentium(R) 4 CPU 3.00GHz stepping 09 per-CPU timeslice cutoff: 1462.59 usecs. task migration cache decay timeout: 2 msecs. enabled ExtINT on CPU#0 ESR value before enabling vector: 00000000 ESR value after enabling vector: 00000000 Booting processor 1/1 eip 3000 Initializing CPU#1 masked ExtINT on CPU#1 ESR value before enabling vector: 00000000 ESR value after enabling vector: 00000000 Calibrating delay loop... 5996.54 BogoMIPS CPU: Trace cache: 12K uops, L1 D cache: 8K CPU: L2 cache: 512K CPU: Physical Processor ID: 0 Intel machine check reporting enabled on CPU#1. CPU: After generic, caps: bfebfbff 00000000 00000000 00000000 CPU: Common caps: bfebfbff 00000000 00000000 00000000 CPU1: Intel(R) Pentium(R) 4 CPU 3.00GHz stepping 09 Total of 2 processors activated (11943.93 BogoMIPS). cpu_sibling_map[0] = 1 cpu_sibling_map[1] = 0 ENABLING IO-APIC IRQs init IO_APIC IRQs IO-APIC (apicid-pin) 2-0, 2-16, 2-17, 2-18, 2-19, 2-20, 2-21, 2-22, 2-23 not connected. ..TIMER: vector=0x31 pin1=2 pin2=0 number of MP IRQ sources: 16. number of IO-APIC #2 registers: 24. testing the IO APIC....................... IO APIC #2...... .... register #00: 02000000 ....... : physical APIC id: 02 ....... : Delivery Type: 0 ....... : LTS : 0 .... register #01: 00178020 ....... : max redirection entries: 0017 ....... : PRQ implemented: 1 ....... : IO APIC version: 0020 .... register #02: 00178020 ....... : arbitration: 00 An unexpected IO-APIC was found. If this kernel release is less than three months old please report this to linux-smp@vger.kernel.org .... IRQ redirection table: NR Log Phy Mask Trig IRR Pol Stat Dest Deli Vect: 00 000 00 1 0 0 0 0 0 0 00 01 003 03 0 0 0 0 0 1 1 39 02 003 03 0 0 0 0 0 1 1 31 03 003 03 0 0 0 0 0 1 1 41 04 003 03 0 0 0 0 0 1 1 49 05 003 03 0 0 0 0 0 1 1 51 06 003 03 0 0 0 0 0 1 1 59 07 003 03 0 0 0 0 0 1 1 61 08 003 03 0 0 0 0 0 1 1 69 09 003 03 1 1 0 0 0 1 1 71 0a 003 03 0 0 0 0 0 1 1 79 0b 003 03 0 0 0 0 0 1 1 81 0c 003 03 0 0 0 0 0 1 1 89 0d 003 03 0 0 0 0 0 1 1 91 0e 003 03 0 0 0 0 0 1 1 99 0f 003 03 0 0 0 0 0 1 1 A1 10 000 00 1 0 0 0 0 0 0 00 11 000 00 1 0 0 0 0 0 0 00 12 000 00 1 0 0 0 0 0 0 00 13 000 00 1 0 0 0 0 0 0 00 14 000 00 1 0 0 0 0 0 0 00 15 000 00 1 0 0 0 0 0 0 00 16 000 00 1 0 0 0 0 0 0 00 17 000 00 1 0 0 0 0 0 0 00 IRQ to pin mappings: IRQ0 -> 0:2 IRQ1 -> 0:1 IRQ3 -> 0:3 IRQ4 -> 0:4 IRQ5 -> 0:5 IRQ6 -> 0:6 IRQ7 -> 0:7 IRQ8 -> 0:8 IRQ9 -> 0:9 IRQ10 -> 0:10 IRQ11 -> 0:11 IRQ12 -> 0:12 IRQ13 -> 0:13 IRQ14 -> 0:14 IRQ15 -> 0:15 .................................... done. Using local APIC timer interrupts. calibrating APIC timer ... ..... CPU clock speed is 3006.0393 MHz. ..... host bus clock speed is 200.0426 MHz. cpu: 0, clocks: 200426, slice: 66808 CPU0 cpu: 1, clocks: 200426, slice: 66808 CPU1 checking TSC synchronization across CPUs: passed. migration_task 0 on cpu=0 migration_task 1 on cpu=1 ACPI: Subsystem revision 20030619 PCI: PCI BIOS revision 2.10 entry at 0xfb4f0, last bus=1 PCI: Using configuration type 1 Looking for DSDT in initrd ... not found! IOAPIC[0]: Set PCI routing entry (2-9 -> 0x71 -> IRQ 9) Mode:1 Active:1 ACPI: Interpreter enabled ACPI: Using IOAPIC for interrupt routing ACPI: System [ACPI] (supports S0 S1 S4 S5) ACPI: PCI Root Bridge [PCI0] (00:00) PCI: Probing PCI hardware (bus 00) PCI: Ignoring BAR0-3 of IDE controller 00:1f.2 Transparent bridge - Intel Corp. 82801BA/CA/DB/EB PCI Bridge ACPI: PCI Interrupt Routing Table [\_SB_.PCI0._PRT] ACPI: PCI Interrupt Routing Table [\_SB_.PCI0.HUB0._PRT] ACPI: PCI Interrupt Link [LNKA] (IRQs 3 4 5 7 9 *10 11 12 14 15) ACPI: PCI Interrupt Link [LNKB] (IRQs 3 4 *5 7 9 10 11 12 14 15) ACPI: PCI Interrupt Link [LNKC] (IRQs 3 4 5 7 9 10 *11 12 14 15) ACPI: PCI Interrupt Link [LNKD] (IRQs 3 4 5 7 9 10 *11 12 14 15) ACPI: PCI Interrupt Link [LNKE] (IRQs *3 4 5 7 9 10 11 12 14 15) ACPI: PCI Interrupt Link [LNKF] (IRQs 3 4 5 7 9 10 11 12 14 15) ACPI: PCI Interrupt Link [LNK0] (IRQs 3 4 5 7 9 10 11 12 14 15) ACPI: PCI Interrupt Link [LNK1] (IRQs 3 4 5 7 *9 10 11 12 14 15) PCI: Probing PCI hardware IOAPIC[0]: Set PCI routing entry (2-16 -> 0xa9 -> IRQ 16) Mode:1 Active:1 00:00:02[A] -> 2-16 -> IRQ 16 IOAPIC[0]: Set PCI routing entry (2-17 -> 0xb1 -> IRQ 17) Mode:1 Active:1 00:00:02[B] -> 2-17 -> IRQ 17 IOAPIC[0]: Set PCI routing entry (2-18 -> 0xb9 -> IRQ 18) Mode:1 Active:1 00:00:02[C] -> 2-18 -> IRQ 18 IOAPIC[0]: Set PCI routing entry (2-19 -> 0xc1 -> IRQ 19) Mode:1 Active:1 00:00:02[D] -> 2-19 -> IRQ 19 Pin 2-16 already programmed Pin 2-18 already programmed Pin 2-17 already programmed Pin 2-16 already programmed Pin 2-19 already programmed Pin 2-18 already programmed IOAPIC[0]: Set PCI routing entry (2-23 -> 0xc9 -> IRQ 23) Mode:1 Active:1 00:00:1d[D] -> 2-23 -> IRQ 23 Pin 2-16 already programmed Pin 2-17 already programmed Pin 2-18 already programmed Pin 2-19 already programmed Pin 2-19 already programmed IOAPIC[0]: Set PCI routing entry (2-20 -> 0xd1 -> IRQ 20) Mode:1 Active:1 00:01:07[B] -> 2-20 -> IRQ 20 IOAPIC[0]: Set PCI routing entry (2-21 -> 0xd9 -> IRQ 21) Mode:1 Active:1 00:01:07[C] -> 2-21 -> IRQ 21 IOAPIC[0]: Set PCI routing entry (2-22 -> 0xe1 -> IRQ 22) Mode:1 Active:1 00:01:07[D] -> 2-22 -> IRQ 22 Pin 2-18 already programmed Pin 2-19 already programmed Pin 2-20 already programmed Pin 2-21 already programmed Pin 2-20 already programmed Pin 2-21 already programmed Pin 2-22 already programmed Pin 2-23 already programmed PCI: Using ACPI for IRQ routing PCI: if you experience problems, try using option 'pci=noacpi' or even 'acpi=off' Linux NET4.0 for Linux 2.4 Based upon Swansea University Computer Society NET3.039 Initializing RT netlink socket apm: BIOS version 1.2 Flags 0x07 (Driver version 1.16) apm: disabled - APM is not SMP safe. PISCH: Plug In Scheduler Interface (Version 6) Starting kswapd bigpage subsystem: allocated 0 bigpages (=0MB). allocated 32 pages and 32 bhs reserved for the highmem bounces kinoded started VFS: Disk quotas vdquot_6.5.1 aio_setup: num_physpages = 65020 aio_setup: sizeof(struct page) = 48 vesafb: framebuffer at 0xe8000000, mapped to 0xf881b000, size 8000k vesafb: mode is 1024x768x16, linelength=2048, pages=4 vesafb: protected mode interface info at a5f3:1f5f vesafb: scrolling: redraw vesafb: directcolor: size=0:5:6:5, shift=0:11:5:0 bootsplash 3.0.9-2003/09/08: looking for picture.... silenjpeg size 22326 bytes, found (1024x768, 11098 bytes, v3). bootsplash: silent jpeg found. bootsplash: silent jpeg found. Console: switching to colour frame buffer device 118x38 fb0: VESA VGA frame buffer device pty: 256 Unix98 ptys configured Serial driver version 5.05c (2001-07-08) with HUB-6 MANY_PORTS MULTIPORT SHARE_IRQ SERIAL_PCI enabled ttyS00 at 0x03f8 (irq = 4) is a 16550A Real Time Clock Driver v1.10e Floppy drive(s): fd0 is 1.44M FDC 0 is a post-1991 82077 RAMDISK driver initialized: 16 RAM disks of 64000K size 1024 blocksize loop: loaded (max 16 devices) Uniform Multi-Platform E-IDE driver Revision: 7.00beta4-2.4 ide: Assuming 33MHz system bus speed for PIO modes; override with idebus=xx ICH5-SATA: IDE controller at PCI slot 00:1f.2 ICH5-SATA: chipset revision 2 ICH5-SATA: not 100% native mode: will probe irqs later ide0: BM-DMA at 0xf000-0xf007, BIOS settings: hda:DMA, hdb:pio ide1: BM-DMA at 0xf008-0xf00f, BIOS settings: hdc:DMA, hdd:pio hda: GCR-8523B, ATAPI CD/DVD-ROM drive hdc: Maxtor 6Y160M0, ATA DISK drive blk: queue c046e1c4, I/O limit 4095Mb (mask 0xffffffff) ide0 at 0x1f0-0x1f7,0x3f6 on irq 14 ide1 at 0x170-0x177,0x376 on irq 15 hdc: attached ide-disk driver. hdc: host protected area => 1 hdc: 320173056 sectors (163929 MB) w/7936KiB Cache, CHS=19929/255/63, UDMA(33) ide-floppy driver 0.99.newide Partition check: hdc: hdc1 hdc2 ide-floppy driver 0.99.newide md: md driver 0.90.0 MAX_MD_DEVS=256, MD_SB_DISKS=27 md: Autodetecting RAID arrays. md: autorun ... md: ... autorun DONE. NET4: Linux TCP/IP 1.0 for NET4.0 IP Protocols: ICMP, UDP, TCP, IGMP IP: routing cache hash table of 8192 buckets, 64Kbytes TCP: Hash tables configured (established 262144 bind 65536) Linux IP multicast router 0.06 plus PIM-SM NET4: Unix domain sockets 1.0/SMP for Linux NET4.0. cryptoapi: loaded RAMDISK: Compressed image found at block 0 Freeing initrd memory: 284k freed VFS: Mounted root (ext2 filesystem). reiserfs: found format "3.6" with standard journal reiserfs: enabling write barrier flush mode reiserfs: using ordered data mode reiserfs: checking transaction log (device ide1(22,2)) ... for (ide1(22,2)) Using r5 hash to sort names VFS: Mounted root (reiserfs filesystem) readonly. Trying to move old root to /initrd ... failed Unmounting old root Trying to free ramdisk memory ... okay Freeing unused kernel memory: 188k freed md: Autodetecting RAID arrays. md: autorun ... md: ... autorun DONE. Adding Swap: 1052216k swap-space (priority 42) reiserfs: enabling write barrier flush mode reiserfs: enabling write barrier flush mode 8139too Fast Ethernet driver 0.9.26 eth0: RealTek RTL8139 Fast Ethernet at 0xf9230000, 00:30:1b:b0:07:7d, IRQ 18 eth0: Identified 8139 chip type 'RTL-8139C' eth0: Setting half-duplex based on auto-negotiated partner ability 0000. ohci1394: $Rev: 1045 $ Ben Collins ohci1394_0: OHCI-1394 1.0 (PCI): IRQ=[20] MMIO=[f5001000-f50017ff] Max Packet=[2048] ieee1394: Host added: ID:BUS[0-00:1023] GUID[00301bb0000007e1] raw1394: /dev/raw1394 device initialized usb.c: registered new driver usbdevfs usb.c: registered new driver hub PCI: Setting latency timer of device 00:1d.7 to 64 ehci_hcd 00:1d.7: Intel Corp. 82801EB USB2 Enhanced Host Controller ehci_hcd 00:1d.7: irq 23, pci mem f9234000 usb.c: new USB bus registered, assigned bus number 1 ehci_hcd 00:1d.7: enabled 64bit PCI DMA PCI: 00:1d.7 PCI cache line size set incorrectly (0 bytes) by BIOS/FW. PCI: 00:1d.7 PCI cache line size corrected to 32. ehci_hcd 00:1d.7: USB 2.0 enabled, EHCI 1.00, driver 2003-Jun-19/2.4 hub.c: USB hub found hub.c: 8 ports detected usb-uhci.c: $Revision: 1.275 $ time 14:35:56 Sep 24 2003 usb-uhci.c: High bandwidth mode enabled PCI: Setting latency timer of device 00:1d.0 to 64 usb-uhci.c: USB UHCI at I/O 0xb000, IRQ 16 usb-uhci.c: Detected 2 ports usb.c: new USB bus registered, assigned bus number 2 hub.c: USB hub found hub.c: 2 ports detected PCI: Setting latency timer of device 00:1d.1 to 64 usb-uhci.c: USB UHCI at I/O 0xb400, IRQ 19 usb-uhci.c: Detected 2 ports usb.c: new USB bus registered, assigned bus number 3 hub.c: USB hub found hub.c: 2 ports detected PCI: Setting latency timer of device 00:1d.2 to 64 usb-uhci.c: USB UHCI at I/O 0xb800, IRQ 18 usb-uhci.c: Detected 2 ports usb.c: new USB bus registered, assigned bus number 4 hub.c: USB hub found hub.c: 2 ports detected PCI: Setting latency timer of device 00:1d.3 to 64 usb-uhci.c: USB UHCI at I/O 0xbc00, IRQ 16 usb-uhci.c: Detected 2 ports usb.c: new USB bus registered, assigned bus number 5 hub.c: USB hub found hub.c: 2 ports detected usb-uhci.c: v1.275:USB Universal Host Controller Interface driver uhci.c: USB Universal Host Controller Interface driver v1.1 mice: PS/2 mouse device common for all mice ACPI: Power Button (FF) [PWRF] ACPI: Fan [FAN] (on) ACPI: Processor [CPU0] (supports C1) ACPI: Processor [CPU1] (supports C1) ACPI: Thermal Zone [THRM] (39 C) PCI: Setting latency timer of device 00:1f.5 to 64 IPsec Security Association Database (SADB): initialized. IPsec Security Policy Database (SPD): initialized. IPsec PF_KEY V2: initialized IPv6 v0.8 (usagi-cvs/IPsec6 based StS) for NET4.0 IPv6 over IPv4 tunneling driver intel8x0: clocking to 48000 parport0: PC-style at 0x378 [PCSPP,TRISTATE] lp0: using parport0 (polling). usb.c: registered new driver serial usbserial.c: USB Serial support registered for Generic usbserial.c: USB Serial Driver core v1.4 isapnp: Scanning for PnP cards... isapnp: No Plug & Play device found Linux agpgart interface v0.99 (c) Jeff Hartmann agpgart: Maximum main memory to use for agp memory: 933M agpgart: Detected an Intel(R) 865G Chipset. agpgart: Detected 8060K stolen memory. agpgart: AGP aperture is 128M @ 0xe8000000 mtrr: 0xe8000000,0x8000000 overlaps existing 0xe8000000,0x400000 Linux video capture interface: v1.00 eth0: no IPv6 routers present ide-floppy driver 0.99.newide hda: attached ide-cdrom driver. hda: ATAPI 52X CD-ROM drive, 128kB Cache Uniform CD-ROM driver Revision: 3.12 stebla@linu --------------0E836366BFB57BEDA3E3E8C9--