Transferring data at "high" speed 115200bps over the serial line (even though the actual incoming line stream is about 37000bps according to the modem LCD panel) results in the following messages on the console at a rate of about 1 log line every 10 to 15 seconds. These buffer overruns have gradually become more frequent from about 3 lines and 24 overruns a day around September 2002 (when I started running Current - 4.x does not suffer from this) to the current flurry. sio1: 57 more interrupt-level buffer overflows (total 56638) sio1: 104 more interrupt-level buffer overflows (total 56742) sio1: 296 more interrupt-level buffer overflows (total 57038) sio1: 51 more interrupt-level buffer overflows (total 57089) sio1: 120 more interrupt-level buffer overflows (total 57209) sio1: 371 more interrupt-level buffer overflows (total 57580) These log messages were generated over 8392.50 seconds transferring 29876595 bytes over the serial interface. That is on average nearly 7 buffer overflows per second or almost 3 overflows per packet. Downloading and interactive use of the server at the end of this leased line is impaired as a result. How-To-Repeat: Transfer data at "high" speed over the serial interface.
On Mon, 5 May 2003, Ian Freislich wrote: > >Description: > Transferring data at "high" speed 115200bps over the serial > line (even though the actual incoming line stream is about > 37000bps according to the modem LCD panel) results in the > following messages on the console at a rate of about 1 log > line every 10 to 15 seconds. > > These buffer overruns have gradually become more frequent > from about 3 lines and 24 overruns a day around September > 2002 (when I started running Current - 4.x does not suffer > from this) to the current flurry. -current has excessive interrupt latency caused by Giant locking almost everything. Try changing this line in sio.c: cp4ticks = speed / 10 / hz * 4; to something like: cp4ticks = speed / 10 / hz * 40; or if you use a non-default value for hz (default is 100): cp4ticks = speed / 10 / 100 * 40; The original version provides enough buffering for about 4 hardclock ticks (default 40 msec on i386's; much smaller on some other arches) of input at full speed. The third version provides 400 msec of buffering. Transient interrupt latency problems are supposed to be made harmless by using rts flow control. There is a PR (maybe from you?) about rts flow control apparently not working for one modem. The hz term was never quite right here. It assumes that the specified value of hz actually works to within 100% (interrupt latency no larger than 2/hz seconds for the lowest priority interrupt handler in the system). The large interrupt latency of -current shows worst-case latency even 2/100 seconds on a multi-GHz machine may be too much for low priority interrupt handlers to ask for. The relevant interrupt handler (siopoll()) became a low priority interrupt handler when it got locked by Giant. Bruce
On Fri, 9 May 2003, Bruce Evans wrote: > ... > The original version provides enough buffering for about 4 hardclock > ticks (default 40 msec on i386's; much smaller on some other arches) > of input at full speed. The third version provides 400 msec of > buffering. PS: you should also try to find what is holding Giant for more than 40 msec. Most syscalls hold it from near their start to near their completion, but most syscalls don't take nearly that long. It is easy to write broken ones that do - just spin for a long time, or return a huge amount of data via sysctl. Bruce
Bruce Evans wrote: > On Mon, 5 May 2003, Ian Freislich wrote: > > > >Description: > > Transferring data at "high" speed 115200bps over the serial > > line (even though the actual incoming line stream is about > > 37000bps according to the modem LCD panel) results in the > > following messages on the console at a rate of about 1 log > > line every 10 to 15 seconds. > > > > These buffer overruns have gradually become more frequent > > from about 3 lines and 24 overruns a day around September > > 2002 (when I started running Current - 4.x does not suffer > > from this) to the current flurry. > > -current has excessive interrupt latency caused by Giant locking almost > everything. > > Try changing this line in sio.c: > > cp4ticks = speed / 10 / hz * 4; > > to something like: > > cp4ticks = speed / 10 / hz * 40; Thanks. Making this change seems to have fixed the problem. Will this be committed or do I need to maintain this privately until the larger interrupt latency problem is fixed? > Transient interrupt latency problems are supposed to be made harmless > by using rts flow control. There is a PR (maybe from you?) about rts > flow control apparently not working for one modem. Not me. Ian
I experience the same with FreeBSD 6.1-PRERELEASE! I just recompiled my kernel with the suggested change to sio.c, and the problem goes away... hmm. On a side note, since I changed the pci-slot (such that the PCI-800H-card didn't share the same irq with the adaptec scsi-controller), reboot does not work properly (system hangs after printing 'all buffers synced') so I have to powercycle manually, leading to the waring "/ was not properly dismounted". Feb 27 21:03:17 dialout kernel: sio12: 24 more interrupt-level buffer overflows (total 433) Feb 27 21:03:56 dialout kernel: sio12: 178 more interrupt-level buffer overflows (total 611) Feb 27 21:04:13 dialout kernel: sio12: 71 more interrupt-level buffer overflows (total 682) Feb 27 21:05:56 dialout kernel: sio12: 172 more interrupt-level buffer overflows (total 854) Feb 27 21:06:06 dialout kernel: sio12: 79 more interrupt-level buffer overflows (total 933) Feb 27 21:06:07 dialout kernel: sio12: 4 more interrupt-level buffer overflows (total 937) Feb 27 21:07:56 dialout kernel: sio12: 23 more interrupt-level buffer overflows (total 960) Feb 27 21:08:06 dialout kernel: sio12: 26 more interrupt-level buffer overflows (total 986) Interestingly, this only happens with the PCI-800H, but the system also has an older 8-port ISA-Card that works without any problems. And yes, the system is an old and slow PIII with 500 MHz only, but I have this problem even if only one modem is in use (sio12). I also don't know why the card can't use fast mode, unless this is because it looks like 2 cards with 4 ports that share an irq. --- 8< ----- dmesg ---------------------------------------------------- Copyright (c) 1992-2005 The FreeBSD Project. Copyright (c) 1979, 1980, 1983, 1986, 1988, 1989, 1991, 1992, 1993, 1994 The Regents of the University of California. All rights reserved. FreeBSD 6.1-PRERELEASE #1: Fri Feb 3 13:29:27 CET 2006 root@dialout2.dout1.b.intern:/usr/obj/usr/src/sys/B-DIALOUT Timecounter "i8254" frequency 1193182 Hz quality 0 CPU: Pentium III/Pentium III Xeon/Celeron (501.14-MHz 686-class CPU) Origin = "GenuineIntel" Id = 0x673 Stepping = 3 Features=0x383f9ff<FPU,VME,DE,PSE,TSC,MSR,PAE,MCE,CX8,SEP,MTRR,PGE,MCA,CMOV,PAT,PSE36,MMX,FXSR,SSE> real memory = 134205440 (127 MB) avail memory = 121810944 (116 MB) npx0: [FAST] npx0: <math processor> on motherboard npx0: INT 16 interface cpu0 on motherboard pcib0: <Intel 82443BX (440 BX) host to PCI bridge> pcibus 0 on motherboard pir0: <PCI Interrupt Routing Table: 7 Entries> on motherboard $PIR: Using invalid BIOS IRQ 15 from 0.10.INTA for link 0x62 $PIR: Using invalid BIOS IRQ 14 from 0.6.INTA for link 0x63 pci0: <PCI bus> on pcib0 agp0: <Intel 82443BX (440 BX) host to PCI bridge> mem 0xe4000000-0xe7ffffff at device 0.0 on pci0 pcib1: <PCI-PCI bridge> at device 1.0 on pci0 pci1: <PCI bus> on pcib1 pci1: <display, VGA> at device 0.0 (no driver attached) isab0: <PCI-ISA bridge> at device 4.0 on pci0 isa0: <ISA bus> on isab0 atapci0: <Intel PIIX4 UDMA33 controller> port 0x1f0-0x1f7,0x3f6,0x170-0x177,0x376,0xb800-0xb80f at device 4.1 on pci0 ata0: <ATA channel 0> on atapci0 ata1: <ATA channel 1> on atapci0 pci0: <serial bus, USB> at device 4.2 (no driver attached) pci0: <bridge> at device 4.3 (no driver attached) ahc0: <Adaptec aic7890/91 Ultra2 SCSI adapter> port 0xb000-0xb0ff mem 0xe1000000-0xe1000fff irq 14 at device 6.0 on pci0 ahc0: [GIANT-LOCKED] aic7890/91: Ultra2 Wide Channel A, SCSI Id=7, 32/253 SCBs fxp0: <Intel 82559 Pro/100 Ethernet> port 0xa800-0xa83f mem 0xe0800000-0xe0800fff,0xe0000000-0xe00fffff irq 15 at device 10.0 on pci0 miibus0: <MII bus> on fxp0 inphy0: <i82555 10/100 media interface> on miibus0 inphy0: 10baseT, 10baseT-FDX, 100baseTX, 100baseTX-FDX, auto fxp0: Ethernet address: 00:d0:b7:16:53:60 puc0: <Titan PCI-800H> port 0xa400-0xa41f,0xa000-0xa01f mem 0xdf800000-0xdf800fff,0xdf000000-0xdf000fff irq 10 at device 11.0 on pci0 sio12: <Titan PCI-800H> on puc0 sio12: type 16550A sio12: unable to activate interrupt in fast mode - using normal mode sio13: <Titan PCI-800H> on puc0 sio13: type 16550A sio13: unable to activate interrupt in fast mode - using normal mode sio14: <Titan PCI-800H> on puc0 sio14: type 16550A sio14: unable to activate interrupt in fast mode - using normal mode sio15: <Titan PCI-800H> on puc0 sio15: type 16550A sio15: unable to activate interrupt in fast mode - using normal mode puc1: <Titan PCI-800H> port 0x9800-0x981f,0x9400-0x941f mem 0xde800000-0xde800fff,0xde000000-0xde000fff irq 10 at device 11.1 on pci0 sio16: <Titan PCI-800H> on puc1 sio16: type 16550A sio16: unable to activate interrupt in fast mode - using normal mode sio17: <Titan PCI-800H> on puc1 sio17: type 16550A sio17: unable to activate interrupt in fast mode - using normal mode sio18: <Titan PCI-800H> on puc1 sio18: type 16550A sio18: unable to activate interrupt in fast mode - using normal mode sio19: <Titan PCI-800H> on puc1 sio19: type 16550A sio19: unable to activate interrupt in fast mode - using normal mode pmtimer0 on isa0 orm0: <ISA Option ROMs> at iomem 0xc0000-0xc7fff,0xc8000-0xcd7ff,0xd0000-0xd0fff on isa0 atkbdc0: <Keyboard controller (i8042)> at port 0x60,0x64 on isa0 atkbd0: <AT Keyboard> irq 1 on atkbdc0 kbd0 at atkbd0 atkbd0: [GIANT-LOCKED] fdc0: <Enhanced floppy controller> at port 0x3f0-0x3f5,0x3f7 irq 6 drq 2 on isa0 fdc0: [FAST] fd0: <1440-KB 3.5" drive> on fdc0 drive 0 ppc0: <Parallel port> at port 0x378-0x37f irq 7 on isa0 ppc0: SMC-like chipset (ECP/EPP/PS2/NIBBLE) in COMPATIBLE mode ppc0: FIFO with 16/16/9 bytes threshold ppbus0: <Parallel port bus> on ppc0 plip0: <PLIP network interface> on ppbus0 lpt0: <Printer> on ppbus0 lpt0: Interrupt-driven port ppi0: <Parallel I/O> on ppbus0 sc0: <System console> at flags 0x100 on isa0 sc0: VGA <32 virtual consoles, flags=0x300> sio0 at port 0x3f8-0x3ff irq 4 flags 0x10 on isa0 sio0: type 16550A sio1 at port 0x2f8-0x2ff irq 3 on isa0 sio1: type 16550A sio10 at port 0x130-0x137 flags 0xb05 on isa0 sio10: type 16550A (multiport) sio11 at port 0x138-0x13f irq 12 flags 0xb05 on isa0 sio11: type 16550A (multiport master) sio4 at port 0x100-0x107 flags 0xb05 on isa0 sio4: type 16550A (multiport) sio5 at port 0x108-0x10f flags 0xb05 on isa0 sio5: type 16550A (multiport) sio6 at port 0x110-0x117 flags 0xb05 on isa0 sio6: type 16550A (multiport) sio7 at port 0x118-0x11f flags 0xb05 on isa0 sio7: type 16550A (multiport) sio8 at port 0x120-0x127 flags 0xb05 on isa0 sio8: type 16550A (multiport) sio9 at port 0x128-0x12f flags 0xb05 on isa0 sio9: type 16550A (multiport) vga0: <Generic ISA VGA> at port 0x3c0-0x3df iomem 0xa0000-0xbffff on isa0 unknown: <PNP0401> can't assign resources (port) unknown: <PNP0501> can't assign resources (port) unknown: <PNP0501> can't assign resources (port) unknown: <PNP0700> can't assign resources (port) unknown: <PNP0c01> can't assign resources (memory) unknown: <PNP0303> can't assign resources (port) unknown: <PNP0c02> can't assign resources (port) Timecounter "TSC" frequency 501138120 Hz quality 800 Timecounters tick every 1.000 msec IP Filter: v4.1.8 initialized. Default = pass all, Logging = enabled da0 at ahc0 bus 0 target 6 lun 0 da0: <IBM DNES-309170W SAK0> Fixed Direct Access SCSI-3 device da0: 40.000MB/s transfers (20.000MHz, offset 31, 16bit), Tagged Queueing Enabled da0: 8748MB (17916240 512 byte sectors: 255H 63S/T 1115C) cd0 at ahc0 bus 0 target 4 lun 0 cd0: <PLEXTOR CD-ROM PX-40TS 1.10> Removable CD-ROM SCSI-2 device cd0: 20.000MB/s transfers (20.000MHz, offset 15) cd0: Attempt to query device size failed: NOT READY, Medium not present - tray closed Trying to mount root from ufs:/dev/da0s1a WARNING: / was not properly dismounted sio12: 80 more interrupt-level buffer overflows (total 80) sio12: 4 more interrupt-level buffer overflows (total 84)
Setting cp4ticks = speed / 10 / hz * 40; Fixes the problem for me as well on my boxes using a 3com modem. Without the change, its a constant series of sio4: 1 more interrupt-level buffer overflow (total 3501) sio4: 3 more interrupt-level buffer overflows (total 3504) sio4: 1 more interrupt-level buffer overflow (total 3505) sio4: 1 more interrupt-level buffer overflow (total 3506) sio4: 2 more interrupt-level buffer overflows (total 3508) sio4: 2 more interrupt-level buffer overflows (total 3510) sio4: 8 more interrupt-level buffer overflows (total 3518) sio4: 11 more interrupt-level buffer overflows (total 3529) sio4: 1 more interrupt-level buffer overflow (total 3530) sio4: 16 more interrupt-level buffer overflows (total 3546) sio4: 10 more interrupt-level buffer overflows (total 3556) sio4: 16 more interrupt-level buffer overflows (total 3572) sio4: 4 more interrupt-level buffer overflows (total 3576) sio4: 16 more interrupt-level buffer overflows (total 3592) sio4: 1 more interrupt-level buffer overflow (total 3593) sio4: 3 more interrupt-level buffer overflows (total 3596) while doing a file transfer over the dialup connection at 42Kb/s Copyright (c) 1992-2006 The FreeBSD Project. Copyright (c) 1979, 1980, 1983, 1986, 1988, 1989, 1991, 1992, 1993, 1994 The Regents of the University of California. All rights reserved. FreeBSD 6.1-PRERELEASE #1: Thu Mar 2 23:41:19 EST 2006 root@test.sentex.ca:/usr/obj/usr/src/sys/gas Timecounter "i8254" frequency 1193182 Hz quality 0 CPU: VIA C3 Nehemiah+RNG+ACE (796.77-MHz 686-class CPU) Origin = "CentaurHauls" Id = 0x698 Stepping = 8 Features=0x381b03f<FPU,VME,DE,PSE,TSC,MSR,MTRR,PGE,CMOV,PAT,MMX,FXSR,SSE> real memory = 232718336 (221 MB) avail memory = 218222592 (208 MB) npx0: [FAST] npx0: <math processor> on motherboard npx0: INT 16 interface acpi0: <CM400 AWRDACPI> on motherboard acpi0: Power Button (fixed) Timecounter "ACPI-fast" frequency 3579545 Hz quality 1000 acpi_timer0: <24-bit timer at 3.579545MHz> port 0x408-0x40b on acpi0 cpu0: <ACPI CPU> on acpi0 acpi_button0: <Power Button> on acpi0 acpi_button1: <Sleep Button> on acpi0 pcib0: <ACPI Host-PCI bridge> port 0xcf8-0xcff on acpi0 pci0: <ACPI PCI bus> on pcib0 agp0: <VIA PM800/PN800/PM880/PN880 host to PCI bridge> mem 0xf8000000-0xf9ffffff at device 0.0 on pci0 pcib1: <PCI-PCI bridge> at device 1.0 on pci0 pci1: <PCI bus> on pcib1 pci1: <display, VGA> at device 0.0 (no driver attached) puc0: <US Robotics (3Com) 3CP5609 PCI 16550 Modem> port 0xe700-0xe707 irq 7 at device 8.0 on pci0 sio4: <US Robotics (3Com) 3CP5609 PCI 16550 Modem> on puc0 sio4: type 16550A sio4: unable to activate interrupt in fast mode - using normal mode rl0: <RealTek 8139 10/100BaseTX> port 0xd000-0xd0ff mem 0xfc000000-0xfc0000ff irq 12 at device 10.0 on pci0 miibus0: <MII bus> on rl0 rlphy0: <RealTek internal media interface> on miibus0 rlphy0: 10baseT, 10baseT-FDX, 100baseTX, 100baseTX-FDX, auto rl0: Ethernet address: 00:03:1d:02:0b:fd pci0: <serial bus, FireWire> at device 11.0 (no driver attached) atapci0: <VIA 6420 SATA150 controller> port 0xee00-0xee07,0xef00-0xef03,0xe400-0xe407,0xe500-0xe503,0xe600-0xe60f,0xd400-0xd4ff irq 12 at device 15.0 on pci0 ata2: <ATA channel 0> on atapci0 ata3: <ATA channel 1> on atapci0 atapci1: <VIA 8237 UDMA133 controller> port 0x1f0-0x1f7,0x3f6,0x170-0x177,0x376,0xe800-0xe80f at device 15.1 on pci0 ata0: <ATA channel 0> on atapci1 ata1: <ATA channel 1> on atapci1 uhci0: <VIA 83C572 USB controller> port 0xe900-0xe91f irq 7 at device 16.0 on pci0 uhci0: [GIANT-LOCKED] usb0: <VIA 83C572 USB controller> on uhci0 usb0: USB revision 1.0 uhub0: VIA UHCI root hub, class 9/0, rev 1.00/1.00, addr 1 uhub0: 2 ports with 2 removable, self powered uhci1: <VIA 83C572 USB controller> port 0xea00-0xea1f irq 7 at device 16.1 on pci0 uhci1: [GIANT-LOCKED] usb1: <VIA 83C572 USB controller> on uhci1 usb1: USB revision 1.0 uhub1: VIA UHCI root hub, class 9/0, rev 1.00/1.00, addr 1 uhub1: 2 ports with 2 removable, self powered uhci2: <VIA 83C572 USB controller> port 0xeb00-0xeb1f irq 12 at device 16.2 on pci0 uhci2: [GIANT-LOCKED] usb2: <VIA 83C572 USB controller> on uhci2 usb2: USB revision 1.0 uhub2: VIA UHCI root hub, class 9/0, rev 1.00/1.00, addr 1 uhub2: 2 ports with 2 removable, self powered uhci3: <VIA 83C572 USB controller> port 0xec00-0xec1f irq 12 at device 16.3 on pci0 uhci3: [GIANT-LOCKED] usb3: <VIA 83C572 USB controller> on uhci3 usb3: USB revision 1.0 uhub3: VIA UHCI root hub, class 9/0, rev 1.00/1.00, addr 1 uhub3: 2 ports with 2 removable, self powered pci0: <serial bus, USB> at device 16.4 (no driver attached) pci0: <network> at device 16.5 (no driver attached) isab0: <PCI-ISA bridge> at device 17.0 on pci0 isa0: <ISA bus> on isab0 pci0: <multimedia, audio> at device 17.5 (no driver attached) vr0: <VIA VT6102 Rhine II 10/100BaseTX> port 0xe000-0xe0ff mem 0xfc004000-0xfc0040ff irq 7 at device 18.0 on pci0 miibus1: <MII bus> on vr0 ukphy0: <Generic IEEE 802.3u media interface> on miibus1 ukphy0: 10baseT, 10baseT-FDX, 100baseTX, 100baseTX-FDX, auto vr0: Ethernet address: 00:03:1d:02:0a:fd acpi_tz0: <Thermal Zone> on acpi0 fdc0: <floppy drive controller> port 0x3f2-0x3f5,0x3f7 irq 6 drq 2 on acpi0 fdc0: [FAST] sio0: <16550A-compatible COM port> port 0x3f8-0x3ff irq 4 flags 0x10 on acpi0 sio0: type 16550A, console sio1: <16550A-compatible COM port> port 0x2f8-0x2ff irq 3 on acpi0 sio1: type 16550A sio2: <16550A-compatible COM port> port 0x3e8-0x3ef irq 5 on acpi0 sio2: type 16550A sio3: <16550A-compatible COM port> port 0x2e8-0x2ef irq 11 on acpi0 sio3: type 16550A atkbdc0: <Keyboard controller (i8042)> port 0x60,0x64 irq 1 on acpi0 atkbd0: <AT Keyboard> irq 1 on atkbdc0 kbd0 at atkbd0 atkbd0: [GIANT-LOCKED] sc0: <System console> at flags 0x100 on isa0 sc0: VGA <16 virtual consoles, flags=0x300> vga0: <Generic ISA VGA> at port 0x3c0-0x3df iomem 0xa0000-0xbffff on isa0 Timecounter "TSC" frequency 796771027 Hz quality 800 Timecounters tick every 1.000 msec Fast IPsec: Initialized Security Association Processing. ipfw2 (+ipv6) initialized, divert loadable, rule-based forwarding enabled, default to accept, logging limited to 9100 packets/entry by default ad0: 38166MB <Seagate ST3402111A 3.AAD> at ata0-master UDMA100 Trying to mount root from ufs:/dev/ad0s1a -------------------------------------------------------------------- Mike Tancsa, tel +1 519 651 3400 Sentex Communications, mike@sentex.net Providing Internet since 1994 www.sentex.net Cambridge, Ontario Canada www.sentex.net/mike
I'm also able to confirm this being a problem My (only) fix was to change cp4ticks in sio.c to the last (third) suggested version: cp4ticks = speed / 10 / 100 * 40; as I'm using HZ=1000 in my kernelconfig, so it didn't work with "speed / 10 / hz * 40". I'm wondering if someone will commit this as a patch to RELENG_6 (and probably RELENG_5)? This is an _essential_ fix for using 3G/UMTS cards under FreeBSD as they're running with 384kbit/s which is fairly too fast without this fix (Novatel Merlin U530 + U630 are running as serial-over-pcmcia). Volker
Responsible Changed From-To: freebsd-bugs->remko I'll take it.
Another solution is to increase the value of HZ in your kernel config: options HZ=250 250 is sufficient for a Soekris net4501 it seems (i486 system, Elan AMD). Nick
Status check. I'm seeing the same thing in 6.3_RELENG using a USR modem = on a VMWare guest system.
Responsible Changed From-To: remko->freebsd-bugs I have held this locked for too long, reassign
For bugs matching the following criteria: Status: In Progress Changed: (is less than) 2014-06-01 Reset to default assignee and clear in-progress tags. Mail being skipped
Problem does not happen with uart. Closing.