ucom/uftdi high interrupt load

Sat Jun 11 21:43:15 UTC 2011

Hello,

We ran into an odd problem last week with our serial consoles after moving 
the USB to serial adapters from an old 4.11 box to a box running 8.1.  We 
have two boxes that incorporate (I assume) hubs and a bunch of FTDI serial 
interfaces.  One has 16 ports, the other 8.  Each is plugged directly into 
a USB port on the rear of the mainboard.  We run conserver[1] to handle 
access to the serial ports.  From what I've observed, this application 
opens the ports when the daemon starts - it logs any output (handy for 
panics, or anything else that might spit interesting info to the console) 
and waits for clients to connect to it.

Everything had been working fine for a few weeks.  The box was rebooted 
recently to enable PostgreSQL to start normally (bumped SHM stuff in 
loader.conf).  After six days, we found that the consoles were 
unresponsive.  Restarting conserver brought us this each time we 
connected to a console for full read/write access:

[Thu Jun  9 10:04:59 2011] conserver (50113): ERROR: [h22] 
open(/dev/ttyU4): Interrupted system call: forcing down
[Thu Jun  9 10:04:59 2011] conserver (50112): ERROR: [h21] 
open(/dev/ttyU11): Interrupted system call: forcing down

All devices still appeared in /dev.  Stopping conserver and confirming it 
and all child processes were gone and then using picocom and cu yielded no 
response on the serial ports.

We also found (after the fact) that around the time the consoles became 
unresponsive, cpu usage went to nearly 90% and was mostly in the kernel 
process "intr":

root   12 70.5  0.0     0   136  ??  WL   Fri12AM 120:01.47  [intr]

A graph showing cpu usage (red is "system"):
http://i.imgur.com/0yO5l.png

I should note that we know the cpu spike and devices becoming unresponsive 
can be correlated because one of the serial ports runs a temperature 
monitor which is tied into our monitoring.  When the data goes stale, we 
get notified.

Issuing a "usbconfig -u 0 reset" caused all devices except for the root 
hub to disappear and not come back.  CPU usage also dipped a bit after 
that.  Rebooting was the only way to resolve the issue - perhaps plugging 
and unplugging would have worked, but that's a bit too complex for our 
remote hands.

I can supply full dmesg and more, but for now, here's a summary of the usb 
info from dmesg:

FreeBSD 8.1-RELEASE #7: Wed Dec 22 00:49:50 EST 2010

ohci0: <OHCI (generic) USB controller> mem 0xfe9fc000-0xfe9fcfff irq 10 at 
device 15.2 on pci0
ohci0: [ITHREAD]
...
usbus0: <OHCI (generic) USB controller> on ohci0
usbus0: 12Mbps Full Speed USB v1.0
ugen0.1: <(0x1166)> at usbus0
...
uhub0: <(0x1166) OHCI root HUB, class 9/0, rev 1.00/1.00, addr 1> on 
usbus0
uhub0: 4 ports with 4 removable, self powered
ugen0.2: <vendor 0x05e3> at usbus0
uhub1: <vendor 0x05e3 USB Hub, class 9/0, rev 1.01/0.11, addr 2> on usbus0
uhub1: 7 ports with 7 removable, self powered
ugen0.3: <FTDI> at usbus0
uftdi0: <USB FAST SERIAL ADAPTER> on usbus0
uftdi1: <USB FAST SERIAL ADAPTER> on usbus0
ugen0.4: <FTDI> at usbus0
uftdi2: <USB FAST SERIAL ADAPTER> on usbus0
uftdi3: <USB FAST SERIAL ADAPTER> on usbus0
ugen0.5: <FTDI> at usbus0
uftdi4: <USB FAST SERIAL ADAPTER> on usbus0
uftdi5: <USB FAST SERIAL ADAPTER> on usbus0
ugen0.6: <FTDI> at usbus0
uftdi6: <USB FAST SERIAL ADAPTER> on usbus0
uftdi7: <USB FAST SERIAL ADAPTER> on usbus0
ugen0.7: <FTDI> at usbus0
uftdi8: <USB FAST SERIAL ADAPTER> on usbus0
uftdi9: <USB FAST SERIAL ADAPTER> on usbus0
ugen0.8: <FTDI> at usbus0
uftdi10: <USB FAST SERIAL ADAPTER> on usbus0
uftdi11: <USB FAST SERIAL ADAPTER> on usbus0
ugen0.9: <vendor 0x05e3> at usbus0
uhub2: <vendor 0x05e3 USB Hub, class 9/0, rev 1.01/0.12, addr 9> on usbus0
uhub2: 4 ports with 4 removable, self powered
ugen0.10: <FTDI> at usbus0
uftdi12: <USB FAST SERIAL ADAPTER> on usbus0
uftdi13: <USB FAST SERIAL ADAPTER> on usbus0
ugen0.11: <FTDI> at usbus0
... (mangling below is as it appears in dmesg)
da1 at sym0 bus 0 scbus0 target 1 lun 0uftdi14: <USB FAST SERIAL ADAPTER> 
on usbus0
da1: <SEAGATE ST336807LW 0C01> Fixed Direct Access SCSI-3 device uftdi15: 
<USB FAST SERIAL ADAPTER> on usbus0 
...
Root mount waiting for: usbus0
ugen0.12: <vendor 0x0409> at usbus0
uhub3: <vendor 0x0409 product 0x0050, class 9/0, rev 2.00/1.00, addr 12> 
on usbus0
Root mount waiting for: usbus0
uhub3: 7 ports with 7 removable, self powered
ugen0.13: <FTDI> at usbus0
uftdi16: <FT232R USB UART> on usbus0
Root mount waiting for: usbus0
ugen0.14: <FTDI> at usbus0
uftdi17: <FT232R USB UART> on usbus0
Root mount waiting for: usbus0
ugen0.15: <FTDI> at usbus0
uftdi18: <FT232R USB UART> on usbus0
ugen0.16: <FTDI> at usbus0Root mount waiting for:
  usbus0
uftdi19: <FT232R USB UART> on usbus0
ugen0.17: <FTDI> at usbus0
uftdi20: <FT232R USB UART> on usbus0
Root mount waiting for: usbus0
ugen0.18: <FTDI> at usbus0
uftdi21: <FT232R USB UART> on usbus0
Root mount waiting for: usbus0
ugen0.19: <vendor 0x0409> at usbus0
uhub4: <vendor 0x0409 product 0x005a, class 9/0, rev 2.00/1.00, addr 19> 
on usbus0
uhub4: 4 ports with 4 removable, self powered
Root mount waiting for: usbus0
ugen0.20: <FTDI> at usbus0
uftdi22: <FT232R USB UART> on usbus0
Root mount waiting for: usbus0
ugen0.21: <FTDI> at usbus0
uftdi23: <FT232R USB UART> on usbus0
Trying to mount root from zfs:zroot

Thanks,

Charles

[1] - http://www.conserver.com/