NetBSD Problem Report #36824

From ggm@apnic.net  Fri Aug 24 01:16:10 2007
Return-Path: <ggm@apnic.net>
Received: from mail.netbsd.org (mail.netbsd.org [204.152.190.11])
	by narn.NetBSD.org (Postfix) with ESMTP id 8EB5163B898
	for <gnats-bugs@gnats.NetBSD.org>; Fri, 24 Aug 2007 01:16:10 +0000 (UTC)
Message-Id: <20070823235957.ADE791A405@garlic.apnic.net>
Date: Fri, 24 Aug 2007 09:59:57 +1000 (EST)
From: ggm@pobox.com
Reply-To: ggm@pobox.com
To: gnats-bugs@NetBSD.org
Subject: CF card reading creates 97% interrupt storm
X-Send-Pr-Version: 3.95

>Number:         36824
>Category:       kern
>Synopsis:       CF card reading creates 97% interrupt storm
>Confidential:   no
>Severity:       serious
>Priority:       medium
>Responsible:    joerg
>State:          closed
>Class:          sw-bug
>Submitter-Id:   net
>Arrival-Date:   Fri Aug 24 01:20:00 +0000 2007
>Closed-Date:    Wed Jun 17 18:56:16 +0000 2020
>Last-Modified:  Wed Jun 17 18:56:16 +0000 2020
>Originator:     George Michaelson
>Release:        NetBSD 4.99.28
>Organization:
George Michaelson                      email:           ggm@apnic.net
Senior Technical Officer, APNIC          sip:      ggm@voip.apnic.net
http://www.apnic.net                   phone:         +61 7 3858 3100
>Environment:


System: NetBSD garlique.algebras.org 4.99.28 NetBSD 4.99.28 (GGM_ACPI) #4: Mon Aug 13 09:57:37 EST 2007 ggm@garlique.algebras.org:/data/Build/obj/usr/src/sys/arch/i386/compile/GGM_ACPI i386
Architecture: i386
Machine: i386
>Description:
	I mount a SanDisk UltraII 2.0Gb CF card, formatted as ms-dos
	(camera) and cp -r its directory contents.

	the Card entry causes this dmesg:

wdc2 at pcmcia1 function 0: <SanDisk, SDP, 5/3 0.6>
wdc2: i/o mapped mode
atabus2 at wdc2 channel 0
wd1 at atabus2 drive 0: <SanDisk SDCFH-2048>
wd1: drive supports 4-sector PIO transfers, LBA addressing
wd1: 1953 MB, 3970 cyl, 16 head, 63 sec, 512 bytes/sect x 4001760 sectors
wd1: drive supports PIO mode 4
wd1 detached

	While this is going on, X, xmms (audio) ground to a stuttering
	halt. Ok, nothing unusual there, but it was at the extreme end.

	I had a top up, and noticed the system was 97% interrupt, close
	to zero in system and usertime.



>How-To-Repeat:
	well.. its probably not that simple, jobmix and all that
	but anyone with an interactive jobmix laptop and a CF reader
	could try.

>Fix:
	nfi. But, it might be worth instrumenting something to tell if
	the amount of interrupt service is getting excessive maybe and
	log it?


>Release-Note:

>Audit-Trail:

Responsible-Changed-From-To: kern-bug-people->joerg
Responsible-Changed-By: joerg@NetBSD.org
Responsible-Changed-When: Thu, 22 May 2008 20:55:33 +0000
Responsible-Changed-Why:
Sounds like an interrupt issue.


State-Changed-From-To: open->feedback
State-Changed-By: joerg@NetBSD.org
State-Changed-When: Thu, 22 May 2008 20:55:33 +0000
State-Changed-Why:
Can you please update to newer current and see if the problem
still exists? I've fixed an important bug that could result in
cbb not getting an interupt with the results as you have.


From: "George Michaelson" <ggm@pobox.com>
To: gnats-bugs@netbsd.org
Cc: joerg@netbsd.org, kern-bug-people@netbsd.org, netbsd-bugs@netbsd.org, 
	gnats-admin@netbsd.org
Subject: Re: kern/36824 (CF card reading creates 97% interrupt storm)
Date: Sat, 24 May 2008 10:40:20 +1000

 ok. I installed current as of last night (24th May) and this is still a problem.

 the symptoms I see are, 99% to 100% interrupt shown in top while doing
 a CP from an MS-DOS camera DCIM dirtree off the CF
 card, into a FFS1 /var/tmp.

 once the first copy is done, its in filecache and subsequent copies
 are almost immediate. but if you umount/mount the CF device and
 repeat, the interrupt count goes right back up to 99% during the copy.

 X becomes un-responsive, window start (eg twm -> new xterm) is
 sluggish in the extreme, cursor disappears, but a top window running
 continues to update and shows the high interrupt rate.

 I don't want to over-state this as a major problem btw. it appears now
 to be very contained to doing active copy off the device, and it stops
 as soon as the filebuf cache is full. More recent kernels may well
 have reduced the impact of this.

 the dmesg on the card is:

 May 24 20:37:22  /netbsd: wdc2 at pcmcia1 function 0: <SanDisk, SDP, 5/3 0.6>
 May 24 20:37:22  /netbsd: wdc2: i/o mapped mode
 May 24 20:37:22  /netbsd: atabus2 at wdc2 channel 0
 May 24 20:37:22  /netbsd: wd1 at atabus2 drive 0
 May 24 20:37:22  /netbsd: : <SanDisk SDCFH-2048>
 May 24 20:37:22  /netbsd: wd1: drive supports 4-sector PIO transfers,
 LBA addressing
 May 24 20:37:22  /netbsd: wd1: 1953 MB, 3970 cyl, 16 head, 63 sec, 512
 bytes/sect x 4001760 sectors
 May 24 20:37:22  /netbsd: wd1: drive supports PIO mode 4

 there are no kernel msgs or logs about problems. Its just about user
 responsiveness, and the interrupt count shown by top.

 any more useful info or debug I can do?

 -George

 On Fri, May 23, 2008 at 6:55 AM,  <joerg@netbsd.org> wrote:
 > Synopsis: CF card reading creates 97% interrupt storm
 >
 > Responsible-Changed-From-To: kern-bug-people->joerg
 > Responsible-Changed-By: joerg@NetBSD.org
 > Responsible-Changed-When: Thu, 22 May 2008 20:55:33 +0000
 > Responsible-Changed-Why:
 > Sounds like an interrupt issue.
 >
 >
 > State-Changed-From-To: open->feedback
 > State-Changed-By: joerg@NetBSD.org
 > State-Changed-When: Thu, 22 May 2008 20:55:33 +0000
 > State-Changed-Why:
 > Can you please update to newer current and see if the problem
 > still exists? I've fixed an important bug that could result in
 > cbb not getting an interupt with the results as you have.
 >
 >
 >
 >

From: George Michaelson <ggm@pobox.com>
To: gnats-bugs@netbsd.org
Cc: 
Subject: Re: kern/36824 (CF card reading creates 97% interrupt storm)
Date: Tue, 27 May 2008 16:00:57 +1000

 --Apple-Mail-4--514860270
 Content-Type: text/plain;
 	charset=US-ASCII;
 	format=flowed;
 	delsp=yes
 Content-Transfer-Encoding: 7bit

 On Sun, May 25, 2008 at 1:53 AM, Joerg Sonnenberger
 <joerg@britannica.bec.de> wrote:
 > On Sat, May 24, 2008 at 10:40:20AM +1000, George Michaelson wrote:
 >> the symptoms I see are, 99% to 100% interrupt shown in top while  
 >> doing
 >> a CP from an MS-DOS camera DCIM dirtree off the CF
 >> card, into a FFS1 /var/tmp.
 >
 > The interrupt shown is the one used by the cardbus device?
 > From the dmesg it is using PIO, which is not surprising to put a high
 > CPU load. At least include a full dmesg please.

 here is s full dmesg.  this is from a cold boot with the CF card  
 inserted.

 please let me know if there is anything else useful I can supply.

 -George

 >
 > Joerg
 >

 --Apple-Mail-4--514860270
 Content-Disposition: attachment;
 	filename=dmesg.txt
 Content-Type: text/plain;
 	x-unix-mode=0666;
 	name="dmesg.txt"
 Content-Transfer-Encoding: 7bit

 Copyright (c) 1996, 1997, 1998, 1999, 2000, 2001, 2002, 2003, 2004, 2005,
     2006, 2007, 2008
     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.99.63 (GENERIC) #1: Fri May 23 01:14:23 EST 2008
 	ggm@snoid:/usr/obj/sys/arch/i386/compile/GENERIC
 total memory = 1022 MB
 avail memory = 993 MB
 timecounter: Timecounters tick every 10.000 msec
 timecounter: Timecounter "i8254" frequency 1193182 Hz quality 100
 IBM 2672PHM (ThinkPad X31)
 mainbus0 (root)
 cpu0 at mainbus0: Intel 686-class, 599MHz, id 0x695
 cpu0: Enhanced SpeedStep (956 mV) 600 MHz
 cpu0: Enhanced SpeedStep frequencies available (MHz): 1600 1400 1200 1000 800 600
 acpi0 at mainbus0: Intel ACPICA 20080321
 acpi0: X/RSDT: OemId <IBM   ,TP-1Q   ,00003020>, AslId < LTP,00000000>
 acpi_pci_link: WARNING: powerhook_establish is deprecated
 LNKA: ACPI: Found matching pin for 0.29.INTA at func 0: 11
 acpi_pci_link: WARNING: powerhook_establish is deprecated
 LNKD: ACPI: Found matching pin for 0.29.INTB at func 1: 11
 acpi_pci_link: WARNING: powerhook_establish is deprecated
 LNKC: ACPI: Found matching pin for 0.29.INTC at func 2: 11
 acpi_pci_link: WARNING: powerhook_establish is deprecated
 LNKH: ACPI: Found matching pin for 0.29.INTD at func 7: 11
 LNKC: ACPI: Found matching pin for 0.31.INTA at func 1: 255
 acpi_pci_link: WARNING: powerhook_establish is deprecated
 LNKB: ACPI: Found matching pin for 0.31.INTB at func 3: 11
 LNKA: ACPI: Found matching pin for 1.0.INTA at func 0: 11
 LNKA: ACPI: Found matching pin for 2.0.INTA at func 0: 11
 LNKB: ACPI: Found matching pin for 2.0.INTB at func 1: 11
 LNKC: ACPI: Found matching pin for 2.0.INTC at func 2: 11
 LNKA: ACPI: Found matching pin for 2.1.INTA at func 0: 11
 LNKC: ACPI: Found matching pin for 2.2.INTA at func 0: 11
 acpi_pci_link: WARNING: powerhook_establish is deprecated
 acpiecdt0 at acpi0: ACPI Embedded Controller via ECDT
 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
 acpilid0 at acpi0 (LID, PNP0C0D): ACPI Lid Switch
 acpibut0 at acpi0 (SLPB, PNP0C0E): ACPI Sleep Button
 attimer1 at acpi0 (TIMR, PNP0100): AT Timer
 attimer1: io 0x40-0x43 irq 0
 pcppi1 at acpi0 (SPKR, PNP0800)
 pcppi1: io 0x61
 midi0 at pcppi1: PC speaker (CPU-intensive output)
 sysbeep0 at pcppi1
 npx1 at acpi0 (FPU, PNP0C04)
 npx1: io 0xf0 irq 13
 npx1: reported by CPUID; using exception 16
 pckbc1 at acpi0 (KBD, PNP0303): kbd port
 pckbc1: io 0x60,0x64 irq 1
 pckbc2 at acpi0 (MOU, IBM3780): aux port
 pckbc2: irq 12
 UART (PNP0501) at acpi0 not configured
 FIR (IBM0071) at acpi0 not configured
 acpiec0 at acpi0 (EC, PNP0C09-0): ACPI Embedded Controller (disabled)
 acpibat0 at acpi0 (BAT0, PNP0C0A-0): ACPI Battery (Control Method)
 acpibat1 at acpi0 (BAT2, PNP0C0A-1): ACPI Battery (Control Method)
 acpiacad0 at acpi0 (AC, ACPI0003-0): ACPI AC Adapter
 thinkpad0 at acpi0 (HKEY, IBM0068)
 thinkpad0: using CMOS at \UCMS
 thinkpad0: using EC at acpiecdt0
 acpitz0 at acpi0 (THM0): critical 91.0C passive 22.0C, passive cooling
 apm0 at acpi0: Power Management spec V1.2
 attimer1: attached to pcppi1
 pckbd0 at pckbc1 (kbd slot)
 pckbc1: using irq 1 for kbd slot
 wskbd0 at pckbd0: console keyboard
 pms0 at pckbc1 (aux slot)
 pckbc1: using irq 12 for aux slot
 wsmouse0 at pms0 mux 0
 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: vendor 0x8086 product 0x3340 (rev. 0x03)
 agp0 at pchb0: aperture at 0xd0000000, size 0x10000000
 ppb0 at pci0 dev 1 function 0: vendor 0x8086 product 0x3341 (rev. 0x03)
 pci1 at ppb0 bus 1
 pci1: i/o space, memory space enabled
 vga1 at pci1 dev 0 function 0: vendor 0x1002 product 0x4c59 (rev. 0x00)
 wsdisplay0 at vga1 kbdmux 1: console (80x25, vt100 emulation), using wskbd0
 wsmux1: connecting to wsdisplay0
 drm at vga1 not configured
 uhci0 at pci0 dev 29 function 0: vendor 0x8086 product 0x24c2 (rev. 0x01)
 uhci0: interrupting at irq 11
 usb0 at uhci0: USB revision 1.0
 uhci1 at pci0 dev 29 function 1: vendor 0x8086 product 0x24c4 (rev. 0x01)
 uhci1: interrupting at irq 11
 usb1 at uhci1: USB revision 1.0
 uhci2 at pci0 dev 29 function 2: vendor 0x8086 product 0x24c7 (rev. 0x01)
 uhci2: interrupting at irq 11
 usb2 at uhci2: USB revision 1.0
 ehci0 at pci0 dev 29 function 7: vendor 0x8086 product 0x24cd (rev. 0x01)
 ehci0: interrupting at irq 11
 ehci0: EHCI version 1.0
 ehci0: companion controllers, 2 ports each: uhci0 uhci1 uhci2
 usb3 at ehci0: USB revision 2.0
 ppb1 at pci0 dev 30 function 0: vendor 0x8086 product 0x2448 (rev. 0x81)
 pci2 at ppb1 bus 2
 pci2: i/o space, memory space enabled
 cbb0 at pci2 dev 0 function 0: vendor 0x1180 product 0x0476 (rev. 0xaa)
 cbb1 at pci2 dev 0 function 1: vendor 0x1180 product 0x0476 (rev. 0xaa)
 fwohci0 at pci2 dev 0 function 2: vendor 0x1180 product 0x0552 (rev. 0x02)
 fwohci0: interrupting at irq 11
 fwohci0: OHCI version 1.0 (ROM=0)
 fwohci0: No. of Isochronous channels is 4.
 fwohci0: EUI64 00:06:1b:03:10:03:af:90
 fwohci0: Phy 1394a available S400, 2 ports.
 fwohci0: Link S400, max_rec 2048 bytes.
 ieee1394if0 at fwohci0: IEEE1394 bus
 fwip0 at ieee1394if0: IP over IEEE1394
 fwohci0: Initiate bus reset
 wm0 at pci2 dev 1 function 0: Intel i82540EP 1000BASE-T Ethernet, rev. 3
 wm0: interrupting at irq 11
 wm0: 32-bit 33MHz PCI bus
 wm0: 64 word (6 address bits) MicroWire EEPROM
 wm0: Ethernet address 00:0d:60:80:47:94
 makphy0 at wm0 phy 1: Marvell 88E1011 Gigabit PHY, rev. 4
 makphy0: 10baseT, 10baseT-FDX, 100baseTX, 100baseTX-FDX, 1000baseT, 1000baseT-FDX, auto
 ath0 at pci2 dev 2 function 0
 ath0: interrupting at 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 5.6 phy 4.1 5 GHz radio 1.7 2 GHz radio 2.3
 cbb0: cacheline 0x0 lattimer 0x40
 cbb0: bhlc 0x824000
 cbb0: interrupting at irq 11
 cardslot0 at cbb0 slot 0 flags 0
 cardbus0 at cardslot0: bus 3
 pcmcia0 at cardslot0
 cbb1: cacheline 0x0 lattimer 0x40
 cbb1: bhlc 0x824000
 cbb1: interrupting at irq 11
 cardslot1 at cbb1 slot 1 flags 0
 cardbus1 at cardslot1: bus 6
 pcmcia1 at cardslot1
 pcib0 at pci0 dev 31 function 0
 pcib0: vendor 0x8086 product 0x24cc (rev. 0x01)
 piixide0 at pci0 dev 31 function 1
 piixide0: Intel 82801DBM IDE Controller (ICH4-M) (rev. 0x01)
 piixide0: bus-master DMA support present
 piixide0: primary channel configured to compatibility mode
 piixide0: primary channel interrupting at irq 14
 atabus0 at piixide0 channel 0
 piixide0: secondary channel configured to compatibility mode
 piixide0: secondary channel interrupting at irq 15
 atabus1 at piixide0 channel 1
 ichsmb0 at pci0 dev 31 function 3: vendor 0x8086 product 0x24c3 (rev. 0x01)
 ichsmb0: interrupting at irq 11
 iic0 at ichsmb0: I2C bus
 auich0 at pci0 dev 31 function 5: i82801DB/DBM (ICH4/ICH4M) AC-97 Audio
 auich0: interrupting at irq 11
 auich0: ac97: Analog Devices AD1981B codec; headphone, 20 bit DAC, no 3D stereo
 auich0: ac97: ext id 601<AC97_22,AMAP,VRA>
 vendor 0x8086 product 0x24c6 (modem communications, revision 0x01) at pci0 dev 31 function 6 not configured
 isa0 at pcib0
 com0 at isa0 port 0x3f8-0x3ff irq 4: ns16550a, working fifo
 com1 at isa0 port 0x2f8-0x2ff irq 3: ns16550a, working fifo
 fwohci0: BUS reset
 fwohci0: node_id=0xc800ffc0, gen=1, CYCLEMASTER mode
 ieee1394if0: 1 nodes, maxhop <= 0, cable IRM = 0 (me)
 ieee1394if0: bus manager 0 (me)
 timecounter: Timecounter "clockinterrupt" frequency 100 Hz quality 0
 auich0: measured ac97 link rate at 47999 Hz, will use 48000 Hz
 audio0 at auich0: full duplex, mmap, independent
 uhub0 at usb0: vendor 0x8086 UHCI root hub, class 9/0, rev 1.00/1.00, addr 1
 uhub0: 2 ports with 2 removable, self powered
 uhub1 at usb1: vendor 0x8086 UHCI root hub, class 9/0, rev 1.00/1.00, addr 1
 uhub1: 2 ports with 2 removable, self powered
 uhub2 at usb2: vendor 0x8086 UHCI root hub, class 9/0, rev 1.00/1.00, addr 1
 uhub2: 2 ports with 2 removable, self powered
 uhub3 at usb3: vendor 0x8086 EHCI root hub, class 9/0, rev 2.00/1.00, addr 1
 uhub3: 6 ports with 6 removable, self powered
 acpibat0: battery info: Panasonic, LION, IBM-92P1096   652
 acpibat1: battery info: SANYO, LION, IBM-02K7043    71
 acpiacad0: AC adapter offline.
 wdc2 at pcmcia1 function 0: <SanDisk, SDP, 5/3 0.6>
 wdc2: i/o mapped mode
 atabus2 at wdc2 channel 0
 wd0 at atabus0 drive 0: <FUJITSU MHT2060AT>
 wd0: drive supports 16-sector PIO transfers, LBA 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 5 (Ultra/100)
 wd0(piixide0:0:0): using PIO mode 4, Ultra-DMA mode 5 (Ultra/100) (using DMA)
 wd1 at atabus2 drive 0: <SanDisk SDCFH-2048>
 wd1: drive supports 4-sector PIO transfers, LBA addressing
 wd1: 1953 MB, 3970 cyl, 16 head, 63 sec, 512 bytes/sect x 4001760 sectors
 wd1: drive supports PIO mode 4
 Kernelized RAIDframe activated
 pad0: outputs: 44100Hz, 16-bit, stereo
 audio1 at pad0: half duplex
 findroot: unable to read block 63301768
 boot device: wd0
 root on wd0a dumps on wd0b
 root file system type: ffs
 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)
 umass0 at uhub3 port 3 configuration 1 interface 0
 umass0: CBM Flash Disk, rev 2.00/1.00, addr 2
 umass0: using SCSI over Bulk-Only
 scsibus0 at umass0: 2 targets, 1 lun per target
 sd0 at scsibus0 target 0 lun 0: <CBM, Flash Disk, 5.00> disk removable
 sd0: fabricating a geometry
 sd0: 987 MB, 987 cyl, 64 head, 32 sec, 512 bytes/sect x 2021888 sectors
 sd0: fabricating a geometry

 --Apple-Mail-4--514860270--

State-Changed-From-To: feedback->open
State-Changed-By: joerg@NetBSD.org
State-Changed-When: Thu, 05 Jun 2008 11:21:48 +0000
State-Changed-Why:
Feedback provided


State-Changed-From-To: open->closed
State-Changed-By: jdolecek@NetBSD.org
State-Changed-When: Wed, 17 Jun 2020 18:56:16 +0000
State-Changed-Why:
Just closing, not expecting to be able to test with -current after 12 years.
In case you do please let me know the result and I reopen if appropriate.


>Unformatted:

Home	PR Database Search