Skip site navigation (1)Skip section navigation (2)
Date:      Fri, 07 Oct 2005 14:39:40 -0500
From:      "Douglas K. Rand" <rand@meridian-enviro.com>
To:        freebsd-stable@freebsd.org
Subject:   5.4 hangs on disk IO
Message-ID:  <873bndw1z7.wl%rand@meridian-enviro.com>

next in thread | raw e-mail | index | archive | help
I've got 2 FreeBSD 5.4 systems that seem to get stuck doing disk
IO. When the system gets hung, it seems to refuse to do any disk
io. It will continue to respond to pings, and the tty driver on the
serial console continues to work and echo characters. But all the
processes seem to get stuck in the state "ufs". On the serial console
I tried sync, which then hangs, and ^T produces:

athearn# sync
load: 0.66  cmd: csh 4138 [ufs] 0.00u 0.00s 0% 1748k

One of the systems emits these error messages on the console:

swap_pager: indefinite wait buffer: device: da0s1a, blkno: 2, size: 4096
swap_pager: indefinite wait buffer: device: da0s1h, blkno: 6, size: 4096
swap_pager: indefinite wait buffer: device: da0s1h, blkno: 7, size: 4096
swap_pager: indefinite wait buffer: device: da0s1h, blkno: 15, size: 4096
swap_pager: indefinite wait buffer: device: da0s1a, blkno: 26, size: 4096

Other than that difference, both systems hang the same way.

The interesting part is that it only seems to happen when I run
amd. With amd running one of our users can hang the system in about
5-10 minutes of heavy disk traffic to a LOCAL disk. The local disk
with the heaviest traffic is "behind" a amd managed symlink. If I
don't run amd and do all the NFS mounts by hand and build the symlink
by hand, the system runs fine. I've tried both the stock amd that
comes with 5.4, the fairly outdated 6.0.10-20040513, and the brand new
6.1.2.1 from ports.=20

=46rom the kernel debugger I can't even panic or call boot(0) with out
errors.=20

I can easily reproduce the hang, so if there is any suggestions for
things to poke at with the kernel debugger on the serial console, let
me know.

Here's the result of ps from a hung system, along with the errors from
panic and boot(0):

db> ps
  pid   proc     uid  ppid  pgrp  flag   stat  wmesg    wchan  cmd
 4138 c34051c4    0   530  4138 4000012 [SLPQ ufs 0xc346b2bc][SLP] csh
 4137 c3e8be20 1002   740   735 4000000 [SLPQ sbwait 0xc366fe84][SLP] perl5=
.8.7
 4136 c3e8bc5c 1002   741   735 4000000 [SLPQ sbwait 0xc3a95d40][SLP] perl5=
.8.7
 4135 c3e071c4 1002   743   735 0004000 [SLPQ nfs 0xc35a7e14][SLP] mkdir
 4134 c3d8e1c4 1002   749   735 0004000 [SLPQ ufs 0xc346b2bc][SLP] perl5.8.7
 4132 c3e6154c 1002   739   735 0004000 [SLPQ nfs 0xc35a7e14][SLP] remap
 2355 c3714a98 1000   682  2355 0004002 [SLPQ select 0xc06787c4][SLP] top
  749 c3ba3c5c 1002     1   735 0004002 [SLPQ wait 0xc3ba3c5c][SLP] tclsh8.4
  748 c348f54c 1002     1   735 0004002 [SLPQ accept 0xc36a6a5a][SLP] perl5=
.8.7
  747 c3710a98 1002     1   735 0004002 [SLPQ accept 0xc3a6154a][SLP] perl5=
.8.7
  746 c370fa98 1002     1   735 0004002 [SLPQ accept 0xc374e17e][SLP] perl5=
.8.7
  745 c3ba3e20 1002     1   735 0004002 [SLPQ accept 0xc374e68e][SLP] perl5=
.8.7
  744 c3ba6000 1002     1   735 0004002 [SLPQ accept 0xc35ac7d2][SLP] perl5=
.8.7
  743 c3ba61c4 1002     1   735 0004002 [SLPQ wait 0xc3ba61c4][SLP] perl5.8=
.7
  742 c3ba6388 1002     1   735 0004002 [SLPQ accept 0xc366f406][SLP] perl5=
.8.7
  741 c34b6e20 1002     1   735 0004002 [SLPQ wait 0xc34b6e20][SLP] perl5.8=
.7
  740 c34b6388 1002     1   735 0004002 [SLPQ wait 0xc34b6388][SLP] perl5.8=
.7
  739 c34b6c5c 1002     1   735 0004002 [SLPQ wait 0xc34b6c5c][SLP] perl5.8=
.7
  682 c34ef000 1000   681   682 0004002 [SLPQ pause 0xc34ef038][SLP] zsh
  681 c340954c 1000   678   678 0000100 [SLPQ select 0xc06787c4][SLP] sshd
  678 c348ca98    0   442   678 0000100 [SLPQ sbwait 0xc3a616ec][SLP] sshd
  530 c3710e20    0   529   530 0004002 [SLPQ ppwait 0xc3710e20][SLP] csh
  529 c370f388    0     1   529 0004102 [SLPQ wait 0xc370f388][SLP] login
  528 c3710388    0     1   528 0004002 [SLPQ ttyin 0xc31d0a10][SLP] getty
  527 c348c1c4    0     1   527 0004002 [SLPQ ttyin 0xc31b8410][SLP] getty
  526 c348f388    0     1   526 0004002 [SLPQ ttyin 0xc31b8010][SLP] getty
  525 c34ef8d4    0     1   525 0004002 [SLPQ ttyin 0xc3166c10][SLP] getty
  524 c34b6a98    0     1   524 0004002 [SLPQ ttyin 0xc3166210][SLP] getty
  523 c348f8d4    0     1   523 0004002 [SLPQ ttyin 0xc3166410][SLP] getty
  522 c348ce20    0     1   522 0004002 [SLPQ ttyin 0xc3166610][SLP] getty
  521 c34f3e20    0     1   521 0004002 [SLPQ ttyin 0xc3166810][SLP] getty
  491 c3405388    0     1   490 0000000 [SLPQ ufs 0xc346b2bc][SLP] snmpd
  464 c3710710    0     1   464 0000000 [SLPQ ufs 0xc346b2bc][SLP] cron
  452 c34b6710   25     1   452 0000100 [SLPQ pause 0xc34b6748][SLP] sendma=
il
  448 c3714000    0     1   448 0000100 [SLPQ pause 0xc3714038][SLP] sendma=
il
  442 c34f38d4    0     1   442 0000100 [SLPQ select 0xc06787c4][SLP] sshd
  427 c3409710    0     1   427 0000000 [SLPQ select 0xc06787c4][SLP] ntpd
  382 c3167c5c    0   378   378 0000000 [SLPQ - 0xc3383c00][SLP] nfsd
  381 c34ef388    0   378   378 0000000 [SLPQ - 0xc33d7200][SLP] nfsd
  380 c34f354c    0   378   378 0000000 [SLPQ - 0xc33f6400][SLP] nfsd
  379 c34b654c    0   378   378 0000000 [SLPQ - 0xc338f000][SLP] nfsd
  378 c3405710    0     1   378 0000000 [SLPQ accept 0xc365403a][SLP] nfsd
  376 c34f3388    0     1   376 0000000 [SLPQ select 0xc06787c4][SLP] mountd
  325 c348fe20    0     1   325 0100000 [SLPQ ufs 0xc346b2bc][SLP] amd
  302 c34ef710    0     1   302 0000000 [SLPQ ufs 0xc346b2bc][SLP] ypbind
  289 c34efe20    0     1   289 0000000 [SLPQ ufs 0xc346b2bc][SLP] rpcbind
  271 c3409e20    0     1   271 0000000 [SLPQ select 0xc06787c4][SLP] syslo=
gd
  253 c348fa98    0     1   253 0000000 [SLPQ select 0xc06787c4][SLP] devd
   66 c3405a98    0     0     0 0000204 [SLPQ - 0xe6b9cd14][SLP] schedcpu
   65 c3405c5c    0     0     0 0000204 [SLPQ - 0xc067b1ec][SLP] nfsiod 3
   64 c3405e20    0     0     0 0000204 [SLPQ - 0xc067b1e8][SLP] nfsiod 2
   63 c3409000    0     0     0 0000204 [SLPQ - 0xc067b1e4][SLP] nfsiod 1
   62 c34091c4    0     0     0 0000204 [SLPQ - 0xc067b1e0][SLP] nfsiod 0
   61 c3409388    0     0     0 0000204 [SLPQ syncer 0xc064e30c][SLP] syncer
   60 c31131c4    0     0     0 0000204 [SLPQ vlruwt 0xc31131c4][SLP] vnlru
   59 c3113388    0     0     0 0000204 [SLPQ psleep 0xc0678cac][SLP] bufda=
emon
   58 c311354c    0     0     0 000020c [SLPQ pgzero 0xc0681a54][SLP] pagez=
ero
   57 c3113710    0     0     0 0000204 [SLPQ psleep 0xc0681aa8][SLP] vmdae=
mon
   56 c31138d4    0     0     0 0000204 [SLPQ psleep 0xc0681a64][SLP] paged=
aemon
   55 c3113a98    0     0     0 0000204 [IWAIT] swi0: sio
    9 c3113c5c    0     0     0 0000204 [SLPQ actask 0xc0753bec][SLP] acpi_=
task2
    8 c3113e20    0     0     0 0000204 [SLPQ actask 0xc0753bec][SLP] acpi_=
task1
    7 c3167000    0     0     0 0000204 [SLPQ actask 0xc0753bec][SLP] acpi_=
task0
   54 c31671c4    0     0     0 0000204 [IWAIT] swi6:+
   53 c3167388    0     0     0 0000204 [IWAIT] swi6: task queue
   52 c316754c    0     0     0 0000204 [IWAIT] swi6: acpitaskq
   51 c3167710    0     0     0 0000204 [IWAIT] swi3: cambio
   50 c31678d4    0     0     0 0000204 [IWAIT] swi2: camnet
    6 c30fba98    0     0     0 0000204 [SLPQ - 0xc3158140][SLP] kqueue tas=
kq
   49 c30fbc5c    0     0     0 0000204 [IWAIT] swi6:+
    5 c30fbe20    0     0     0 0000204 [SLPQ - 0xc3158200][SLP] thread tas=
kq
   48 c310f000    0     0     0 0000204 [SLPQ - 0xc0646180][SLP] yarrow
    4 c310f1c4    0     0     0 0000204 [SLPQ - 0xc0648c08][SLP] g_down
    3 c310f388    0     0     0 0000204 [SLPQ - 0xc0648c04][SLP] g_up
    2 c310f54c    0     0     0 0000204 [SLPQ - 0xc0648bfc][SLP] g_event
   47 c310f710    0     0     0 0000204 [IWAIT] swi1: net
   46 c310f8d4    0     0     0 0000204 [IWAIT] swi4: vm
   45 c310fa98    0     0     0 000020c [IWAIT] swi5: clock sio
   44 c310fc5c    0     0     0 0000204 [IWAIT] irq0: clk
   43 c310fe20    0     0     0 0000204 [IWAIT] irq31:
   42 c3113000    0     0     0 0000204 [IWAIT] irq30:
   41 c30ef54c    0     0     0 0000204 [IWAIT] irq29:
   40 c30ef710    0     0     0 0000204 [IWAIT] irq28: iir0
   39 c30ef8d4    0     0     0 0000204 [IWAIT] irq27:
   38 c30efa98    0     0     0 0000204 [IWAIT] irq26:
   37 c30efc5c    0     0     0 0000204 [IWAIT] irq25: bge1
   36 c30efe20    0     0     0 0000204 [IWAIT] irq24: bge0
   35 c30fb000    0     0     0 0000204 [IWAIT] irq23:
   34 c30fb1c4    0     0     0 0000204 [IWAIT] irq22:
   33 c30fb388    0     0     0 0000204 [IWAIT] irq21:
   32 c30fb54c    0     0     0 0000204 [IWAIT] irq20:
   31 c30fb710    0     0     0 0000204 [IWAIT] irq19:
   30 c30fb8d4    0     0     0 0000204 [IWAIT] irq18:
   29 c309d1c4    0     0     0 0000204 [IWAIT] irq17:
   28 c309d388    0     0     0 0000204 [IWAIT] irq16:
   27 c309d54c    0     0     0 0000204 [IWAIT] irq15: ata1
   26 c309d710    0     0     0 0000204 [IWAIT] irq14: ata0
   25 c309d8d4    0     0     0 0000204 [IWAIT] irq13:
   24 c309da98    0     0     0 0000204 [IWAIT] irq12:
   23 c309dc5c    0     0     0 0000204 [IWAIT] irq11:
   22 c309de20    0     0     0 0000204 [IWAIT] irq10:
   21 c30ef000    0     0     0 0000204 [IWAIT] irq9: acpi0
   20 c30ef1c4    0     0     0 0000204 [IWAIT] irq8: rtc
   19 c30ef388    0     0     0 0000204 [IWAIT] irq7:
   18 c3094000    0     0     0 0000204 [IWAIT] irq6:
   17 c30941c4    0     0     0 0000204 [IWAIT] irq5:
   16 c3094388    0     0     0 0000204 [IWAIT] irq4: sio0
   15 c309454c    0     0     0 0000204 [IWAIT] irq3:
   14 c3094710    0     0     0 0000204 [IWAIT] irq1: atkbd0
   13 c30948d4    0     0     0 000020c [CPU 0] idle: cpu0
   12 c3094a98    0     0     0 000020c [CPU 1] idle: cpu1
   11 c3094c5c    0     0     0 000020c [CPU 2] idle: cpu2
   10 c3094e20    0     0     0 000020c [CPU 3] idle: cpu3
    1 c309d000    0     0     1 0004200 [SLPQ wait 0xc309d000][SLP] init
    0 c0648d00    0     0     0 0000200 [SLPQ sched 0xc0648d00][SLP] swapper

With INVARIANTS and WITNESS compiled in I get:

db>  panic
panic: from debugger
cpuid =3D 3
panic: mi_switch: switch in a critical section
cpuid =3D 3
panic: mi_switch: switch in a critical section

[These two messages continue until the system resets itself.]


But with out INVARIANTS and WITNESS I get:

db> panic
panic: from debugger
cpuid =3D 3
KDB: stack backtrace:
kdb_backtrace(ffe787e,722dddb9,ffc09014,c3095300,c31ce200) at kdb_backtrace=
+0x29
mi_switch(1,0,e493da60,c04b441c,c3095300) at mi_switch+0xf6
sched_bind(c3095300,0) at sched_bind+0x44
boot(104,104,c3095300,0,c06144d0) at boot+0x64
panic(c05f6e6b,e493db40,c04374d8,c04cc3cf,0) at panic+0x1b9
db_panic(c04cc3cf,0,ffffffff,e493dab4,0) at db_panic+0xd
db_command(c063eee4,c0619b20,c06144d0,c06144d4,c05f6e79) at db_command+0x264
db_command_loop(0,0,e493db6c,e493db58,e493dba0) at db_command_loop+0x5c
db_trap(3,0,3,c3095300,e493dbec) at db_trap+0xdd
kdb_trap(3,0,e493dbf4) at kdb_trap+0x8b
trap(18,10,10,61,c31a8000) at trap+0x464
calltrap() at calltrap+0x5
--- trap 0x3, eip =3D 0xc04cc3cf, esp =3D 0xe493dc34, ebp =3D 0xe493dc34 ---
kdb_enter(c060dc65) at kdb_enter+0x2b
siointr1(c31a8000) at siointr1+0xd5
siointr(c31a8000) at siointr+0x5e
intr_execute_handlers(c308f490,e493dca0,4,e493dce4,c05ccf13) at intr_execut=
e_handlers+0x7d
lapic_handle_intr(34) at lapic_handle_intr+0x2e
Xapic_isr1() at Xapic_isr1+0x33
--- interrupt, eip =3D 0xc072c5a9, esp =3D 0xe493dce4, ebp =3D 0xe493dce4 -=
--
acpi_cpu_c1(2aca5ff6,5ec6eb58,e493dd04,c3095300,4) at acpi_cpu_c1+0x5
acpi_cpu_idle(e493dd20,c04a1119,c3094e20,c04a1080,0) at acpi_cpu_idle+0xcf
cpu_idle(c3094e20,c04a1080,0,e493dd34,c04a0e19) at cpu_idle+0x28
idle_proc(0,e493dd48) at idle_proc+0x99
fork_exit(c04a1080,0,e493dd48) at fork_exit+0x75
fork_trampoline() at fork_trampoline+0x8
--- trap 0x1, eip =3D 0, esp =3D 0xe493dd7c, ebp =3D 0 ---

db> call boot(0)
KDB: stack backtrace:
kdb_backtrace(80ae517e,df7fe2e7,ffc09014,c3095300,c06144d0) at kdb_backtrac=
e+0x29
mi_switch(1,0,e493da20,c04b441c,c3095300) at mi_switch+0xf6
sched_bind(c3095300,0) at sched_bind+0x44
boot(0,0,0,0,0,0,0,0,0,0) at boot+0x64
db_fncall(0,0,0,e493dab4,0) at db_fncall+0xf6
db_command(c063eee4,c0619b20,c06144d0,c06144d4,c05f6e79) at db_command+0x264
db_command_loop(0,0,e493db6c,e493db58,e493dba0) at db_command_loop+0x5c
db_trap(3,0,3,c3095300,e493dbec) at db_trap+0xdd
kdb_trap(3,0,e493dbf4) at kdb_trap+0x8b
trap(18,10,10,61,c31a8000) at trap+0x464
calltrap() at calltrap+0x5
--- trap 0x3, eip =3D 0xc04cc3cf, esp =3D 0xe493dc34, ebp =3D 0xe493dc34 ---
kdb_enter(c060dc65) at kdb_enter+0x2b
siointr1(c31a8000) at siointr1+0xd5
siointr(c31a8000) at siointr+0x5e
intr_execute_handlers(c308f490,e493dca0,4,e493dce4,c05ccf13) at intr_execut=
e_handlers+0x7d
lapic_handle_intr(34) at lapic_handle_intr+0x2e
Xapic_isr1() at Xapic_isr1+0x33
--- interrupt, eip =3D 0xc072c5a9, esp =3D 0xe493dce4, ebp =3D 0xe493dce4 -=
--
acpi_cpu_c1(2aca5ff6,5ec6eb58,e493dd04,c3095300,4) at acpi_cpu_c1+0x5
Macpi_cpu_idle(e493dd20,c04a1119,c3094e20,c04a1080,0) at acpi_cpu_idle+0xcf
cpu_idle(c3094e20,c04a1080,0,e493dd34,c04a0e19) at cpu_idle+0x28
idle_proc(0,e493dd48) at idle_proc+0x99
fork_exit(c04a1080,0,e493dd48) at fork_exit+0x75
fork_trampoline() at fork_trampoline+0x8
--- trap 0x1, eip =3D 0, esp =3D 0xe493dd7c, ebp =3D 0 ---

db> call cpu_reset()
cpu_reset called on cpu#3
cpu_reset: Restarting BSP
cpu_reset_proxy: Stopped CPU 3


And my kernel config file:

machine         i386
cpu             I686_CPU
ident           KATO

makeoptions     MODULES_OVERRIDE=3D"acpi"

options         SCHED_4BSD
options         INET
options         FFS
options         SOFTUPDATES
options         UFS_ACL
options         UFS_DIRHASH
options         NFSCLIENT
options         NFSSERVER
options         CD9660
options         PROCFS
options         PSEUDOFS
options         COMPAT_43
options         SCSI_DELAY=3D500
options         ADAPTIVE_GIANT
options         DDB
options         KDB
options         KDB_UNATTENDED
options         ALT_BREAK_TO_DEBUGGER
options         INVARIANTS
options         INVARIANT_SUPPORT
options         WITNESS
options         INCLUDE_CONFIG_FILE
options         MAXDSIZ=3D(1024*1024*1024)
options         DFLDSIZ=3D(256*1024*1024)
options         SMP

device          apic
device          isa
device          pci

device          ata
device          atapicd

device          iir
device          scbus
device          da
device          pass
device          ips

device          atkbdc
device          atkbd
device          vga
device          sc

device          npx

device          sio

device          miibus
device          bge

device          loop
device          mem
device          io
device          random
device          ether
device          pty
device          bpf



Want to link to this message? Use this URL: <https://mail-archive.FreeBSD.org/cgi/mid.cgi?873bndw1z7.wl%rand>