thr3ads.net - freebsd stable - RELENG_6: I/O deadlock under load [Oct 2006]

If this information is useful, please help other people find it:
Share via:

Ulrich Spoerlein

2006-Oct-27 06:37 UTC

RELENG_6: I/O deadlock under load

Hi all,

Our fileserver deadlocked, again. It is running RELENG_6 checked out
yesterday. I have enabled DDB, WITNESS and INVARIANTS and have it
hooked up via serial console.

I can not give out shell access, but I can run any command you might
consider useful, here's more details:

The system has two 3Ware controllers with a big RAID5 volume each:

3ware device driver for 9000 series storage controllers, version: 3.60.02.012
twa0: <3ware 9000 series Storage Controller> port 0x3000-0x303f mem
0xdc000000-0xddffffff,0xd8300000-0xd8300fff irq 48 at device 1.0 on
pci3
twa0: [FAST]
twa0: INFO: (0x15: 0x1300): Controller details:: Model 9550SXU-8LP, 8
ports, Firmware FE9X 3.04.00.005, BIOS BE9X 3.04.00.002
em0: <Intel(R) PRO/1000 Network Connection Version - 6.1.4> port
0x3040-0x307f mem 0xd8320000-0xd833ffff irq 54 at device 2.0 on pci3
em0: Ethernet address: 00:30:48:30:11:a2
em0: [FAST]
em1: <Intel(R) PRO/1000 Network Connection Version - 6.1.4> port
0x3080-0x30bf mem 0xd8340000-0xd835ffff irq 55 at device 2.1 on pci3
em1: Ethernet address: 00:30:48:30:11:a3
em1: [FAST]
pci1: <base peripheral, interrupt controller> at device 0.3 (no driver
attached)
pcib4: <ACPI PCI-PCI bridge> irq 16 at device 4.0 on pci0
pci4: <ACPI PCI bus> on pcib4
pcib5: <ACPI PCI-PCI bridge> irq 16 at device 6.0 on pci0
pci5: <ACPI PCI bus> on pcib5
pcib6: <ACPI PCI-PCI bridge> at device 0.0 on pci5
pci6: <ACPI PCI bus> on pcib6
pci5: <base peripheral, interrupt controller> at device 0.1 (no driver
attached)
pcib7: <ACPI PCI-PCI bridge> at device 0.2 on pci5
pci7: <ACPI PCI bus> on pcib7
twa1: <3ware 9000 series Storage Controller> port 0x4000-0x403f mem
0xde000000-0xdfffffff,0xd8500000-0xd8500fff irq 96 at device 1.0 on
pci7
twa1: [FAST]
twa1: INFO: (0x15: 0x1300): Controller details:: Model 9550SXU-8LP, 8
ports, Firmware FE9X 3.04.00.005, BIOS BE9X 3.04.00.002
da0 at twa0 bus 0 target 0 lun 0
da0: <AMCC 9550SXU-8L DISK 3.04> Fixed Direct Access SCSI-3 device
da0: 100.000MB/s transfers
da0: 1430448MB (2929557504 512 byte sectors: 255H 63S/T 182356C)
da1 at twa1 bus 0 target 0 lun 0
da1: <AMCC 9550SXU-8L DISK 3.04> Fixed Direct Access SCSI-3 device
da1: 100.000MB/s transfers
da1: 1430448MB (2929557504 512 byte sectors: 255H 63S/T 182356C)
SMP: AP CPU #1 Launched!
GEOM_MIRROR: Device gm0 created (id=3977032851).
GEOM_MIRROR: Device gm0: provider da0s1 detected.
GEOM_MIRROR: Device gm0: provider da1s1 detected.
GEOM_MIRROR: Device gm0: provider da1s1 activated.
GEOM_MIRROR: Device gm0: provider da0s1 activated.
GEOM_MIRROR: Device gm0: provider mirror/gm0 launched.

The base OS is sitting on a 8GB GMIRROR device across those two
volumes. There were multiple processes running at the time of the
deadlock:
Two dd if=/dev/urandom were writing to the filesystems on each volume.
An rsync was pumping data to a different server. This server also
exposed a part of the volume via GEOM_GATE to the deadlocked host.
This ggate device and a local device formed another gmirror, which was
just rebuilding.

I startet a dump of this gmirrored filesystem, but had to abort
because the tape drive was not recognized. I aborted the dump, ran
camcontrol rescan to get my /dev/sa0 device. mksnap_ffs was still
running, and as I was inpatient, I restarted my dump script. dump(8)
was blocking, because another mksnap_ffs was running. It looks like as
soon as the first mksnap_ffs was finished, the system deadlocked.

Yeah, this is pretty much, but the system has deadlocked before, with
*only* mksnap_ffs running, so I suspect this is the only culprit. I
could still enter the debugger via serial break (pinging the host
still works, switching virtual console work, BUT pressing enter on any
console produces nothing). It also continues to push out syslog
messages to the console ...

db> ps
  pid  ppid  pgrp   uid   state   wmesg     wchan    cmd
74669 82674 82674    25  N                           sendmail
35897 80497 80497     0  N                           sendmail
13932 81866  9485     0  SL      vnread   0xdc38a690 grep
81866 64561  9485     0  S       wait     0xc89a5000 sh
54507 32103 32103     0  SL+     pfault   0xc096db18 sleep
64561  9485  9485     0  S       piperd   0xc9cce4c8 perl5.8.8
 9485 24955  9485     0  Ss      wait     0xca6ad000 sh
24955  3564  3564     0  S       piperd   0xc9c85b28 cron
24201 10966 75715     0  SL+     physrd   0xdc38f600 dump
72560 10966 75715     0  SL+     physrd   0xdc389c50 dump
31224 10966 75715     0  SL+     physrd   0xdc38ae40 dump
10966  5349 75715     0  S+      sbwait   0xc86a7370 dump
 5349 43148 75715     0  S+      wait     0xca690430 dump
43148 75715 75715     0  S+      wait     0xcc284c90 sh
95955 59838 59838     0  S       nfslockd 0xc0967f08 rpc.lockd
59838     1 59838     0  Ss      select   0xc0964224 rpc.lockd
11779     1 11779     0  Ss      select   0xc0964224 rpc.statd
53756 59946 59946     0  S       -        0xc84fbc00 nfsd
50902 59946 59946     0  S       -        0xcc812200 nfsd
97900 59946 59946     0  S       -        0xca9e3000 nfsd
37548 59946 59946     0  S       -        0xcc811c00 nfsd
30961 59946 59946     0  S       -        0xcc811000 nfsd
62718 59946 59946     0  S       -        0xcc811600 nfsd
52612 59946 59946     0  S       -        0xcc811400 nfsd
51990 59946 59946     0  S       -        0xcc7d5a00 nfsd
24333 59946 59946     0  S       -        0xc8942a00 nfsd
35604 59946 59946     0  S       -        0xca9e3400 nfsd
96924 59946 59946     0  S       -        0xcc811800 nfsd
 8213 59946 59946     0  S       -        0xca9e3200 nfsd
91777 59946 59946     0  S       -        0xca9e3e00 nfsd
27135 59946 59946     0  S       -        0xcc811a00 nfsd
88659 59946 59946     0  S       -        0xc94a9c00 nfsd
22957 59946 59946     0  S       -        0xc8e25c00 nfsd
59946     1 59946     0  Ss      accept   0xc881019e nfsd
25073     1 25073     0  Ss      select   0xc0964224 mountd
61130     1 61130     0  Ss      select   0xc0964224 rpcbind
84138 96207 96207     0  S       sbwait   0xc8a3b638 heartbeat
28790 96207 96207     0  S       select   0xc0964224 heartbeat
65938 96207 96207     0  S       sbwait   0xc8ab079c heartbeat
96207     1 96207     0  Ss      select   0xc0964224 heartbeat
85402 68495 13044     0  S       select   0xc0964224 ssh
68495 31406 13044     0  S       pfault   0xc096db18 rsync
31406 80822 13044     0  SW      wait     0xc87e2a78 sh
80822 97693 13044     0  SW      wait     0xc87e2218 sh
97693 83489 13044     0  SW      wait     0xc8a62a78 sh
83489 13044 13044     0  SW      wait     0xc908d218 time
13044 32445 13044     0  SWs     wait     0xc908d648 sh
32445  3564  3564     0  S       piperd   0xc8751660 cron
32103 73903 32103     0  S+      wait     0xc908b218 sh
50439     1 50439     0  Ss      (threaded)          ggatec
100126                   S       kserel   0xc84d48d4 ggatec
100131                   S       kserel   0xc84d48d4 ggatec
100092                   S       connec   0xc86b219e ggatec
100111                   S       ksesigwa 0xc89a5350 ggatec
73903 82004 73903     0  SWs+    pause    0xc86c7034 tcsh
45760 82004 45760     0  Ss+     ttyin    0xc8ea0010 tcsh
75715 18700 75715     0  S+      wait     0xc89a5430 sh
18700 82004 18700     0  SWs+    pause    0xc8a64034 tcsh
79812 30532 79812     0  S+      nanslp   0xc0916ecc iostat
60930 82004 60930     0  Ss+     ttyin    0xc8426410 tcsh
30532 82004 30532     0  SWs+    pause    0xc850767c tcsh
82004     1 82004     0  Ss      select   0xc0964224 screen
78913     1 78913     0  ?s+                         getty
63737     1 63737     0  SWs+    ttyin    0xc8520010 getty
 4887     1  4887     0  SWs+    ttyin    0xc8520410 getty
57691     1 57691     0  SWs+    ttyin    0xc8515010 getty
95149     1 95149     0  SWs+    ttyin    0xc8517410 getty
 7519     1  7519     0  SWs+    ttyin    0xc8510c10 getty
33308     1 33308     0  SWs+    ttyin    0xc8514410 getty
57883     1 57883     0  SWs+    ttyin    0xc8516010 getty
30755     1 30755     0  SWs+    ttyin    0xc8516810 getty
63367     1 63367     0  SLs     pfault   0xc096db18 bsnmpd
 6138     1  6138     0  SWs     select   0xc0964224 inetd
 3564     1  3564     0  SLs     pfault   0xc096db18 cron
82674     1 82674    25  SLs     vmwait   0xc096db18 sendmail
80497     1 80497     0  SLs     vmwait   0xc096db18 sendmail
43757     1 43757     0  ?s                          sshd
14937     1 14937     0  Ss      biowr    0xdc49e708 ntpd
51469     1 11351     0  S       nanslp   0xc0916ecc smartd
37144     1 37144     0  Ss      select   0xc0964224 amd
96296     1 96296   115  SLs     pfault   0xc096db18 symon
28150     1 28150     0  Ss      bo_wwait 0xcc423a74 syslogd
17976     1 17976     0  SWs     select   0xc0964224 devd
   51     0     0     0  SL      gwrite   0xc8fdd420 [g_mirror share]
   50     0     0     0  SL      m:w1     0xc8420400 [g_mirror gm0]
   49     0     0     0  SL      -        0xe8c17d04 [schedcpu]
   48     0     0     0  SL      sdflush  0xc096d334 [softdepflush]
   47     0     0     0  SL      vlruwt   0xc84d2c90 [vnlru]
   46     0     0     0  SL      getblk   0xdc52ff70 [syncer]
   45     0     0     0  SL      psleep   0xc096478c [bufdaemon]
   44     0     0     0  SL      pgzero   0xc096e2a4 [pagezero]
   43     0     0     0  SL      psleep   0xc096ddf4 [vmdaemon]
   42     0     0     0  SL      wswbuf0  0xc096d554 [pagedaemon]
   41     0     0     0  WL                          [swi0: sio]
   40     0     0     0  WL                          [irq1: atkbd0]
   39     0     0     0  WL                          [irq17: ichsmb0]
   38     0     0     0  WL                          [irq15: ata1]
   37     0     0     0  WL                          [irq14: ata0]
   36     0     0     0  SL      usbevt   0xc841aa10 [usb4]
   35     0     0     0  WL                          [irq23: ehci0]
   34     0     0     0  SL      usbevt   0xc84e9210 [usb3]
   33     0     0     0  SL      usbevt   0xc84de210 [usb2]
   32     0     0     0  WL                          [irq18: uhci2]
   31     0     0     0  SL      usbevt   0xc84d6210 [usb1]
   30     0     0     0  WL                          [irq19: uhci1]
   29     0     0     0  SL      usbtsk   0xc0913b64 [usbtask]
   28     0     0     0  SL      usbevt   0xc848e210 [usb0]
   27     0     0     0  WL                          [irq16: uhci0 uhci3]
   26     0     0     0  SL      -        0xc844bb00 [em1 taskq]
   25     0     0     0  SL      -        0xc8480380 [em0 taskq]
   24     0     0     0  SL      idle     0xc844c000 [aic_recovery1]
   23     0     0     0  WL                          [irq25: ahd1]
   22     0     0     0  SL      idle     0xc8448000 [aic_recovery0]
   21     0     0     0  WL                          [irq24: ahd0]
   20     0     0     0  WL                          [irq9: acpi0]
   19     0     0     0  WL                          [swi5: +]
    9     0     0     0  SL      -        0xc840da80 [thread taskq]
   18     0     0     0  WL                          [swi6: Giant taskq]
    8     0     0     0  SL      -        0xc840dc00 [acpi_task_2]
    7     0     0     0  SL      -        0xc840dc00 [acpi_task_1]
    6     0     0     0  SL      -        0xc840dc00 [acpi_task_0]
   17     0     0     0  WL                          [swi6: task queue]
    5     0     0     0  SL      -        0xc840dd80 [kqueue taskq]
   16     0     0     0  WL                          [swi2: cambio]
   15     0     0     0  SL      -        0xc09118a0 [yarrow]
    4     0     0     0  SL      -        0xc0914388 [g_down]
    3     0     0     0  SL      -        0xc0914384 [g_up]
    2     0     0     0  SL      -        0xc091437c [g_event]
   14     0     0     0  WL                          [swi3: vm]
   13     0     0     0  WL                          [swi4: clock sio]
   12     0     0     0  WL                          [swi1: net]
   11     0     0     0  RL      CPU 0               [idle: cpu0]
   10     0     0     0  RL      CPU 1               [idle: cpu1]
    1     0     1     0  SLs     wait     0xc8337000 [init]
    0     0     0     0  SLs     vmwait   0xc096db18 [swapper]
41681 64561  9485     0  Z                           ifconfig
86595 64561  9485     0  Z                           df
db> show alllocks
Process 51 (g_mirror share) thread 0xc84d3a80 (100038)
exclusive sx gmirror:lock r = 0 (0xc84b8c2c) locked @
/usr/src/sys/modules/geom/geom_mirror/../../../geom/mirror/g_mirror.c:1809
db> where 51
Tracing pid 51 tid 100038 td 0xc84d3a80
sched_switch(c84d3a80,0,1) at sched_switch+0x177
mi_switch(1,0) at mi_switch+0x270
sleepq_switch(c8fdd420,c09165a0,0,c084049e,236,...) at sleepq_switch+0xc1
sleepq_timedwait(c8fdd420) at sleepq_timedwait+0x4a
msleep(c8fdd420,c0964860,4c,c0837cfb,64) at msleep+0x255
biowait(c8fdd420,c0837cfb,c8fdd420,c851b9c0,e8c1ac40,...) at biowait+0x52
g_write_data(c851b9c0,bb1cb200,ee,ca26a800,200,...) at g_write_data+0x8d
g_mirror_write_metadata(c84b8c00,c8710480,e8c1abc0,4d4f4547,494d3a3a,...)
at g_mirror_write_metadata+0x2e0
g_mirror_update_metadata(c8710480,e8c1ac7c,c0651510,c0a7e9a5,c080a66e,...)
at g_mirror_update_metadata+0x27
g_mirror_register_request(c083ee95,c84b8c2c,c84b8c6c,c84b8c80,202,...)
at g_mirror_register_request+0xea
g_mirror_worker(c84b8c00,e8c1ad38,c84b8c00,c0a79554,0,...) at
g_mirror_worker+0x6b8
fork_exit(c0a79554,c84b8c00,e8c1ad38) at fork_exit+0xa0
fork_trampoline() at fork_trampoline+0x8
--- trap 0x1, eip = 0, esp = 0xe8c1ad6c, ebp = 0 ---

db> show allpcpu
Current CPU: 0

cpuid        = 0
curthread    = 0xc8333780: pid 11 "idle: cpu0"
curpcb       = 0xe6e95d90
fpcurthread  = none
idlethread   = 0xc8333780: pid 11 "idle: cpu0"
APIC ID      = 0
currentldt   = 0x50
spin locks held:

cpuid        = 1
curthread    = 0xc8333600: pid 10 "idle: cpu1"
curpcb       = 0xe6e92d90
fpcurthread  = none
idlethread   = 0xc8333600: pid 10 "idle: cpu1"
APIC ID      = 6
currentldt   = 0x50
spin locks held:

db> show lockedvnods
Locked vnodes

0xc87f6990: tag ufs, type VDIR
    usecount 1, writecount 0, refcount 2 mountedhere 0
    flags ()
    v_object 0xcbb47294 ref 0 pages 0
     lock type ufs: EXCL (count 1) by thread 0xc8508600 (pid 14937)
        ino 94210, on dev ufs/var

0xcc423990: tag ufs, type VREG
    usecount 1, writecount 1, refcount 3 mountedhere 0
    flags ()
    v_object 0xcaea44a4 ref 0 pages 13
     lock type ufs: EXCL (count 1) by thread 0xc8509d80 (pid 28150)
        ino 94280, on dev ufs/var

0xca3ab330: tag ufs, type VREG
    usecount 1, writecount 0, refcount 1 mountedhere 0
    flags ()
     lock type ufs: EXCL (count 1) by thread 0xc8508600 (pid 14937)
        ino 94248, on dev ufs/var

0xc87c2770: tag ufs, type VREG
    usecount 5, writecount 0, refcount 6 mountedhere 0
    flags ()
    v_object 0xc8771210 ref 4 pages 6
     lock type ufs: SHARED (count 1)
        ino 565709, on dev ufs/usr

0xc8ee9660: tag syncer, type VNON
    usecount 1, writecount 0, refcount 2 mountedhere 0
    flags ()
     lock type syncer: EXCL (count 1) by thread 0xc84d3480 (pid 46)

0xc9278220: tag ufs, type VREG
    usecount 2, writecount 0, refcount 3 mountedhere 0
    flags (VV_SYSTEM)
    v_object 0xc8eca108 ref 0 pages 19358
     lock type snaplk: EXCL (count 1) by thread 0xc84d3480 (pid 46)
        ino 5, on dev mirror/share

If you need any further info or wish me to try different patches
against RELENG_6, don't hesistate. But please be quick about it, since
this file server has to go into production soon.

Uli

Ulrich Spoerlein

2006-Oct-28 17:53 UTC

head link

RELENG_6: I/O deadlock under load

Ulrich Spoerlein wrote:> Our fileserver deadlocked, again. It is running RELENG_6 checked out
> yesterday. I have enabled DDB, WITNESS and INVARIANTS and have it
> hooked up via serial console.
Happend again, now I have DEBUG_LOCKS and DEBUG_VFS_LOCK included. There
are hundreds of cron processes waiting on wmesg 'sysctl' (they seem to
have piled up prior to me entering the debugger).

db> show pcpu
cpuid        = 0
curthread    = 0xc8326780: pid 11 "idle: cpu0"
curpcb       = 0xe6f1fd90
fpcurthread  = none
idlethread   = 0xc8326780: pid 11 "idle: cpu0"
APIC ID      = 0
currentldt   = 0x50
spin locks held:
db> show allpcpu
Current CPU: 0

cpuid        = 0
curthread    = 0xc8326780: pid 11 "idle: cpu0"
curpcb       = 0xe6f1fd90
fpcurthread  = none
idlethread   = 0xc8326780: pid 11 "idle: cpu0"
APIC ID      = 0
currentldt   = 0x50
spin locks held:

cpuid        = 1
curthread    = 0xc8326600: pid 10 "idle: cpu1"
curpcb       = 0xe6f1cd90
fpcurthread  = none
idlethread   = 0xc8326600: pid 10 "idle: cpu1"
APIC ID      = 6
currentldt   = 0x50
spin locks held:

db> show alllocks
Process 60935 (gmirror) thread 0xc88ce780 (100122)
exclusive sx sysctl lock r = 0 (0xc0971dc0) locked @
/usr/src/sys/kern/kern_sysctl.c:1375
Process 50 (g_mirror gm0) thread 0xc86b7600 (100062)
exclusive sx gmirror:lock r = 0 (0xc84b282c) locked @
/usr/src/sys/geom/mirror/g_mirror.c:1809

'gm0' is the mirror where the OS resides on. It is 8GB in size and spans
across da0s1 and da1s1 which are RAID5 volumes attached through two
twa(4) controllers.

db> show lockedvnods
Locked vnodes

0xcb4a4984: tag ufs, type VREG
    usecount 1, writecount 0, refcount 3 mountedhere 0
    flags ()
    v_object 0xcc804e70 ref 0 pages 1
     lock type ufs: SHARED (count 1)#0 0xc0667314 at lockmgr+0x160
#1 0xc0783fea at ffs_lock+0x76
#2 0xc083688f at VOP_LOCK_APV+0x87
#3 0xc06d50b8 at vn_lock+0xac
#4 0xc06d478e at vn_read+0x132
#5 0xc0697a89 at dofileread+0x85
#6 0xc0697922 at kern_readv+0x36
#7 0xc069784d at read+0x45
#8 0xc0824037 at syscall+0x25b
#9 0xc08106af at Xint0x80_syscall+0x1f

        ino 8315, on dev ufs/root

0xc87682b8: tag ufs, type VDIR
    usecount 1, writecount 0, refcount 4 mountedhere 0
    flags ()
    v_object 0xcb4b6630 ref 0 pages 1
     lock type ufs: EXCL (count 1) by thread 0xc850b000 (pid 43987)#0 0xc06676a1
at lockmgr+0x4ed
#1 0xc0783fea at ffs_lock+0x76
#2 0xc083688f at VOP_LOCK_APV+0x87
#3 0xc06d50b8 at vn_lock+0xac
#4 0xc06c8f46 at vget+0xc2
#5 0xc06bd9be at cache_lookup+0x34a
#6 0xc06bdef2 at vfs_cache_lookup+0x92
#7 0xc083494f at VOP_LOOKUP_APV+0x87
#8 0xc06c20a2 at lookup+0x46e
#9 0xc06c19b6 at namei+0x39a
#10 0xc06d3e9f at vn_open_cred+0x5b
#11 0xc06d3e42 at vn_open+0x1e
#12 0xc06cd342 at kern_open+0xb6
#13 0xc06cd256 at open+0x1a
#14 0xc0824037 at syscall+0x25b
#15 0xc08106af at Xint0x80_syscall+0x1f

        ino 94210, on dev ufs/var

0xc87746cc: tag ufs, type VREG
    usecount 1, writecount 1, refcount 3 mountedhere 0
    flags ()
    v_object 0xc876a210 ref 0 pages 3
     lock type ufs: EXCL (count 1) by thread 0xc86b7000 (pid 14753)#0 0xc06676a1
at lockmgr+0x4ed
#1 0xc0783fea at ffs_lock+0x76
#2 0xc083688f at VOP_LOCK_APV+0x87
#3 0xc06d50b8 at vn_lock+0xac
#4 0xc06d4a54 at vn_write+0x138
#5 0xc0697d5f at dofilewrite+0x77
#6 0xc0697c03 at kern_writev+0x3b
#7 0xc0697bac at writev+0x30
#8 0xc0824037 at syscall+0x25b
#9 0xc08106af at Xint0x80_syscall+0x1f

        ino 94280, on dev ufs/var

0xca357414: tag ufs, type VDIR
    usecount 1, writecount 0, refcount 2 mountedhere 0
    flags ()
     lock type ufs: EXCL (count 1) by thread 0xc8cdf480 (pid 20101)#0 0xc06676a1
at lockmgr+0x4ed
#1 0xc0783fea at ffs_lock+0x76
#2 0xc083688f at VOP_LOCK_APV+0x87
#3 0xc06d50b8 at vn_lock+0xac
#4 0xc06c8f46 at vget+0xc2
#5 0xc06bd9be at cache_lookup+0x34a
#6 0xc06bdef2 at vfs_cache_lookup+0x92
#7 0xc083494f at VOP_LOOKUP_APV+0x87
#8 0xc06c20a2 at lookup+0x46e
#9 0xc06c19b6 at namei+0x39a
#10 0xc06cf3f1 at kern_stat+0x35
#11 0xc06cf39f at stat+0x1b
#12 0xc0824037 at syscall+0x25b
#13 0xc08106af at Xint0x80_syscall+0x1f

        ino 94211, on dev ufs/var

0xc875c15c: tag syncer, type VNON
    usecount 1, writecount 0, refcount 2 mountedhere 0
    flags ()
     lock type syncer: EXCL (count 1) by thread 0xc84ce480 (pid 46)#0 0xc06676a1
at lockmgr+0x4ed
#1 0xc06c00e1 at vop_stdlock+0x21
#2 0xc083688f at VOP_LOCK_APV+0x87
#3 0xc06d50b8 at vn_lock+0xac
#4 0xc06c8703 at sync_vnode+0xe3
#5 0xc06c89a1 at sched_sync+0x1ed
#6 0xc065e864 at fork_exit+0xa0
#7 0xc08106bc at fork_trampoline+0x8


0xc8771d98: tag ufs, type VREG
    usecount 3, writecount 0, refcount 4 mountedhere 0
    flags (VV_TEXT)
    v_object 0xc88ddbdc ref 1 pages 7
     lock type ufs: EXCL (count 1) by thread 0xc84ce480 (pid 46)#0 0xc06676a1 at
lockmgr+0x4ed
#1 0xc0783fea at ffs_lock+0x76
#2 0xc083688f at VOP_LOCK_APV+0x87
#3 0xc06d50b8 at vn_lock+0xac
#4 0xc06c8f46 at vget+0xc2
#5 0xc0782ab5 at ffs_sync+0x1c1
#6 0xc06caaa0 at sync_fsync+0x164
#7 0xc0835c1f at VOP_FSYNC_APV+0x9b
#8 0xc06c8726 at sync_vnode+0x106
#9 0xc06c89a1 at sched_sync+0x1ed
#10 0xc065e864 at fork_exit+0xa0
#11 0xc08106bc at fork_trampoline+0x8

        ino 259327, on dev ufs/usr

0xc8770828: tag ufs, type VDIR
    usecount 1, writecount 0, refcount 2 mountedhere 0
    flags ()
    v_object 0xc8b42a50 ref 0 pages 0
     lock type ufs: EXCL (count 1) by thread 0xc8cc4d80 (pid 48623)#0 0xc06676a1
at lockmgr+0x4ed
#1 0xc0783fea at ffs_lock+0x76
#2 0xc083688f at VOP_LOCK_APV+0x87
#3 0xc06d50b8 at vn_lock+0xac
#4 0xc06c8f46 at vget+0xc2
#5 0xc06bd9be at cache_lookup+0x34a
#6 0xc06bdef2 at vfs_cache_lookup+0x92
#7 0xc083494f at VOP_LOOKUP_APV+0x87
#8 0xc06c20a2 at lookup+0x46e
#9 0xc06c19b6 at namei+0x39a
#10 0xc06cf3f1 at kern_stat+0x35
#11 0xc06cf39f at stat+0x1b
#12 0xc0824037 at syscall+0x25b
#13 0xc08106af at Xint0x80_syscall+0x1f

        ino 353305, on dev ufs/usr

0xc8b81c3c: tag ufs, type VREG
    usecount 5, writecount 0, refcount 7 mountedhere 0
    flags (VV_TEXT)
    v_object 0xc8b588c4 ref 3 pages 207
     lock type ufs: SHARED (count 1) with 1 pending#0 0xc0667314 at
lockmgr+0x160
#1 0xc0783fea at ffs_lock+0x76
#2 0xc083688f at VOP_LOCK_APV+0x87
#3 0xc06d50b8 at vn_lock+0xac
#4 0xc06c8f46 at vget+0xc2
#5 0xc07aa3e7 at vnode_pager_lock+0x127
#6 0xc079828f at vm_fault+0x227
#7 0xc08239c6 at trap_pfault+0xce
#8 0xc082359b at trap+0x1eb
#9 0xc081065a at calltrap+0x5

        ino 353904, on dev ufs/usr

0xc8c5c828: tag ufs, type VREG
    usecount 1, writecount 1, refcount 2997 mountedhere 0
    flags ()
    v_object 0xc8ba1e70 ref 0 pages 446652
     lock type ufs: EXCL (count 1) by thread 0xc850b600 (pid 16977)#0 0xc06676a1
at lockmgr+0x4ed
#1 0xc0783fea at ffs_lock+0x76
#2 0xc083688f at VOP_LOCK_APV+0x87
#3 0xc06d50b8 at vn_lock+0xac
#4 0xc06d4a54 at vn_write+0x138
#5 0xc0697d5f at dofilewrite+0x77
#6 0xc0697c03 at kern_writev+0x3b
#7 0xc0697b29 at write+0x45
#8 0xc0824037 at syscall+0x25b
#9 0xc08106af at Xint0x80_syscall+0x1f

        ino 6, on dev mirror/share

0xcc95f2b8: tag ufs, type VREG
    usecount 1, writecount 1, refcount 1851 mountedhere 0
    flags ()
    v_object 0xcc804528 ref 0 pages 331134
     lock type ufs: EXCL (count 1) by thread 0xc86ea480 (pid 50442)#0 0xc06676a1
at lockmgr+0x4ed
#1 0xc0783fea at ffs_lock+0x76
#2 0xc083688f at VOP_LOCK_APV+0x87
#3 0xc06d50b8 at vn_lock+0xac
#4 0xc06d4a54 at vn_write+0x138
#5 0xc0697d5f at dofilewrite+0x77
#6 0xc0697c03 at kern_writev+0x3b
#7 0xc0697b29 at write+0x45
#8 0xc0824037 at syscall+0x25b
#9 0xc08106af at Xint0x80_syscall+0x1f

        ino 5, on dev da0s2e

0xcab1ac3c: tag ufs, type VREG
    usecount 1, writecount 0, refcount 1139 mountedhere 0
    flags ()
     lock type ufs: EXCL (count 1) by thread 0xc8b9dc00 (pid 34426)#0 0xc06676a1
at lockmgr+0x4ed
#1 0xc06c0ffe at vfs_hash_insert+0x26
#2 0xc0782e9f at ffs_vget+0x15b
#3 0xc07688ac at ffs_valloc+0x100
#4 0xc078f77c at ufs_makeinode+0x68
#5 0xc078c6f1 at ufs_create+0x25
#6 0xc0834b37 at VOP_CREATE_APV+0x9b
#7 0xc0770f7a at ffs_snapshot+0x322
#8 0xc0780cb0 at ffs_mount+0x8d8
#9 0xc06c42ab at vfs_domount+0x687
#10 0xc06c3a7f at vfs_donmount+0x2ef
#11 0xc06c621d at kernel_mount+0x6d
#12 0xc0780e85 at ffs_cmount+0x5d
#13 0xc06c3c12 at mount+0x156
#14 0xc0824037 at syscall+0x25b
#15 0xc08106af at Xint0x80_syscall+0x1f

        ino 6, on dev da0s2e

db> ps
  pid  ppid  pgrp   uid   state   wmesg     wchan    cmd
40384 40425 40425     0  S       sysctl l 0xc0971df0 cron
18974 40425 40425     0  S       sysctl l 0xc0971df0 cron
29806 40425 40425     0  S       sysctl l 0xc0971df0 cron
38225 40425 40425     0  S       sysctl l 0xc0971df0 cron
83456 40425 40425     0  S       sysctl l 0xc0971df0 cron
55635 40425 40425     0  S       sysctl l 0xc0971df0 cron
56207 40425 40425     0  S       sysctl l 0xc0971df0 cron
30952 40425 40425     0  S       sysctl l 0xc0971df0 cron
  485 40425 40425     0  S       sysctl l 0xc0971df0 cron
... hundreds more
32057 40425 40425     0  S       sysctl l 0xc0971df0 cron
79683 23876 23876     0  SL      vmpfw    0xc42ed220 sshd
97911 23876 23876     0  SL      vmpfw    0xc42ed220 sshd
67504 40425 40425     0  S       sysctl l 0xc0971df0 cron
... even more crons
55722 40425 40425     0  S       sysctl l 0xc0971df0 cron
 5605 23876 23876     0  SL      vmpfw    0xc42ed220 sshd
13648 23876 23876     0  SL      swread   0xc42ed220 sshd
38374 40425 40425     0  S       sysctl l 0xc0971df0 cron
... yet some hundred more
33848 40425 40425     0  S       sysctl l 0xc0971df0 cron
60935 71690  3566     0  S       g_waitfo 0xc9f76880 gmirror
71690 37484  3566     0  S       piperd   0xc95bc000 perl5.8.8
37484  3566  3566     0  S       piperd   0xc8709cc0 perl5.8.8
 3566 46050  3566     0  Ss      wait     0xc8e47430 sh
46050 40425 40425     0  S       piperd   0xc880b660 cron
48623 43770 26178     0  S       ufs      0xc8b81c94 sh
43770 48166 26178     0  S       piperd   0xc880b990 sh
20101 79935 79935     2  S       biord    0xdc566b1c sh
 8301 75724 75724     0  S       biord    0xdc5736b0 newsyslog
48166 26178 26178     0  S       piperd   0xc880bcc0 perl5.8.8
75724 37661 75724     0  Ss      wait     0xc8cc2c90 sh
79935 12147 79935     2  Ss      wait     0xc8b98218 sh
26178 41679 26178     0  Ss      wait     0xc86e8648 sh
12147 40425 40425     0  S       piperd   0xc8ef6b28 cron
37661 40425 40425     0  S       piperd   0xc8f0bcc0 cron
41679 40425 40425     0  S       piperd   0xc8f0b330 cron
59177 10624 40486     0  S       piperd   0xc951b000 awk
 4943 10624 40486     0  SL      vnread   0xdc390830 tw_cli
10624 51888 40486     0  S       wait     0xc8cd8000 sh
51888 96902 40486     0  S       piperd   0xc87ab4c8 sh
96902 40486 40486     0  S       piperd   0xc8c68198 perl5.8.8
40486 14946 40486     0  Ss      wait     0xc8cd7860 sh
14946 40425 40425     0  S       piperd   0xc95acb28 cron
34426 59514 56159     0  S+      biord    0xdc4049a4 mksnap_ffs
59514 13116 56159     0  S+      wait     0xc8e46648 sh
13116  7858 56159     0  S+      wait     0xc8e46430 dump
50442  9618  9618     0  S+      wdrain   0xc09bf8e4 dd
16977 52273 52273     0  S+      wdrain   0xc09bf8e4 dd
 7858 56159 56159     0  S+      wait     0xc850a430 sh
51796 61348 51796     0  Ss+     ttyin    0xc8481410 tcsh
 9618 24699  9618     0  S+      wait     0xc88cc430 sh
24699 61348 24699     0  SWs+    pause    0xc8b9867c tcsh
52273 78081 52273     0  S+      wait     0xc8b99860 sh
78081 61348 78081     0  SWs+    pause    0xc8b98894 tcsh
36839 58682 36839     0  S+      sysctl l 0xc0971df0 iostat
56159 21882 56159     0  S+      wait     0xc8b99218 sh
58682 61348 58682     0  SWs+    pause    0xc8a1967c tcsh
21882 61348 21882     0  SWs+    pause    0xc88cc67c tcsh
61348 90803 61348     0  Ss      select   0xc09bf344 screen
90803 63507 90803     0  S+      pause    0xc88cf894 screen
63507 73206 63507     0  SWs+    pause    0xc86e8cc4 tcsh
11117 73206 11117     0  Ss+     ttyin    0xc8528410 tcsh
73206 23876 73206     0  Ss      sysctl l 0xc0971df0 sshd
47418     1 47418     0  SWs+    ttyin    0xc8513410 getty
37674     1 37674     0  SWs+    ttyin    0xc8525010 getty
81454     1 81454     0  SWs+    ttyin    0xc8525410 getty
85718     1 85718     0  SWs+    ttyin    0xc8518810 getty
63281     1 63281     0  SWs+    ttyin    0xc851b410 getty
15399     1 15399     0  SWs+    ttyin    0xc8513810 getty
36534     1 36534     0  SWs+    ttyin    0xc851a010 getty
64717     1 64717     0  SWs+    ttyin    0xc851a810 getty
32019     1 32019     0  SWs+    ttyin    0xc8519010 getty
21692     1 21692     0  Ss      sysctl l 0xc0971df0 bsnmpd
37851     1 37851     0  SWs     select   0xc09bf344 inetd
34757 54856 54856     0  S       sbwait   0xc89c7370 heartbeat
58032 54856 54856     0  S       select   0xc09bf344 heartbeat
16232 54856 54856     0  S       sbwait   0xc877c638 heartbeat
54856     1 54856     0  Ss      select   0xc09bf344 heartbeat
40425     1 40425     0  Ss      nanslp   0xc0971fec cron
 8391     1  8391    25  Ss      sysctl l 0xc0971df0 sendmail
10886     1 10886     0  Ss      sysctl l 0xc0971df0 sendmail
23876     1 23876     0  Ss      select   0xc09bf344 sshd
43987     1 43987     0  Ss      biord    0xdc3e6200 ntpd
71800     1 30662     0  S       nanslp   0xc0971fec smartd
 1186 34002 34002     0  SW      nfslockd 0xc09c30e8 rpc.lockd
34002     1 34002     0  Ss      select   0xc09bf344 rpc.lockd
96123     1 96123     0  Ss      select   0xc09bf344 rpc.statd
81769     1 81769     0  Ss      select   0xc09bf344 amd
77412     1 77412     0  Ss      select   0xc09bf344 rpcbind
21109     1 21109   115  Ss      sysctl l 0xc0971df0 symon
14753     1 14753     0  Ss      biord    0xdc3c8a24 syslogd
46810     1 46810     0  SWs     select   0xc09bf344 devd
   51     0     0     0  SL      m:w1     0xc8676e00 [g_mirror share]
   50     0     0     0  SL      gwrite   0xc87f5dec [g_mirror gm0]
   49     0     0     0  SL      -        0xe8ca1d04 [schedcpu]
   48     0     0     0  SL      sdflush  0xc09c8514 [softdepflush]
   47     0     0     0  SL      vlruwt   0xc84cdc90 [vnlru]
   46     0     0     0  SL      biord    0xdc4f2030 [syncer]
   45     0     0     0  SL      wdrain   0xc09bf8e4 [bufdaemon]
   44     0     0     0  SL      pgzero   0xc09c9484 [pagezero]
   43     0     0     0  SL      psleep   0xc09c8fd4 [vmdaemon]
   42     0     0     0  SL      psleep   0xc09c8f90 [pagedaemon]
   41     0     0     0  WL                          [swi0: sio]
   40     0     0     0  WL                          [irq1: atkbd0]
   39     0     0     0  WL                          [irq17: ichsmb0]
   38     0     0     0  WL                          [irq15: ata1]
   37     0     0     0  WL                          [irq14: ata0]
   36     0     0     0  SL      usbevt   0xc8411a10 [usb4]
   35     0     0     0  WL                          [irq23: ehci0]
   34     0     0     0  SL      usbevt   0xc84e0210 [usb3]
   33     0     0     0  SL      usbevt   0xc84d1210 [usb2]
   32     0     0     0  WL                          [irq18: uhci2]
   31     0     0     0  SL      usbevt   0xc84d6210 [usb1]
   30     0     0     0  WL                          [irq19: uhci1]
   29     0     0     0  SL      usbtsk   0xc096ec04 [usbtask]
   28     0     0     0  SL      usbevt   0xc8485210 [usb0]
   27     0     0     0  WL                          [irq16: uhci0 uhci3]
   26     0     0     0  SL      -        0xc8449b00 [em1 taskq]
   25     0     0     0  SL      -        0xc847f380 [em0 taskq]
   24     0     0     0  SL      idle     0xc844a000 [aic_recovery1]
   23     0     0     0  WL                          [irq25: ahd1]
   22     0     0     0  SL      idle     0xc843d000 [aic_recovery0]
   21     0     0     0  WL                          [irq24: ahd0]
   20     0     0     0  WL                          [irq9: acpi0]
    9     0     0     0  SL      -        0xc8406980 [kqueue taskq]
    8     0     0     0  SL      -        0xc8406a80 [acpi_task_2]
    7     0     0     0  SL      -        0xc8406a80 [acpi_task_1]
    6     0     0     0  SL      -        0xc8406a80 [acpi_task_0]
   19     0     0     0  WL                          [swi5: +]
    5     0     0     0  SL      -        0xc8406c00 [thread taskq]
   18     0     0     0  WL                          [swi6: Giant taskq]
   17     0     0     0  WL                          [swi6: task queue]
   16     0     0     0  WL                          [swi2: cambio]
   15     0     0     0  SL      -        0xc096c920 [yarrow]
    4     0     0     0  SL      -        0xc096f488 [g_down]
    3     0     0     0  SL      -        0xc096f484 [g_up]
    2     0     0     0  SL      gmirror: 0xc84b285c [g_event]
   14     0     0     0  WL                          [swi3: vm]
   13     0     0     0  WL                          [swi4: clock sio]
   12     0     0     0  WL                          [swi1: net]
   11     0     0     0  RL      CPU 0               [idle: cpu0]
   10     0     0     0  RL      CPU 1               [idle: cpu1]
    1     0     1     0  SLs     wait     0xc832a000 [init]
    0     0     0     0  WLs                         [swapper]
78481 71690  3566     0  Z                           hostname
39905 37484  3566     0  Z                           df
75688 48166 26178     0  Z                           df
99435 96902 40486     0  Z                           df

db> trace 51
Tracing pid 51 tid 100038 td 0xc84cea80
sched_switch(c84cea80,0,1) at sched_switch+0x177
mi_switch(1,0) at mi_switch+0x270
sleepq_switch(c8676e00,c09716c0,0,c0895bd7,211,...) at sleepq_switch+0xc1
sleepq_wait(c8676e00,0,c088c7ec,6f8,c0970e40,...) at sleepq_wait+0x46
msleep(c8676e00,c8676e80,24c,c088ce4d,0) at msleep+0x279
g_mirror_worker(c8676e00,e8ca4d38,c8676e00,c0639754,0,...) at
g_mirror_worker+0x4d8
fork_exit(c0639754,c8676e00,e8ca4d38) at fork_exit+0xa0
fork_trampoline() at fork_trampoline+0x8
--- trap 0x1, eip = 0, esp = 0xe8ca4d6c, ebp = 0 ---
db> trace 50
Tracing pid 50 tid 100062 td 0xc86b7600
sched_switch(c86b7600,0,1) at sched_switch+0x177
mi_switch(1,0) at mi_switch+0x270
sleepq_switch(c87f5dec,c09716c0,0,c0895bd7,236,...) at sleepq_switch+0xc1
sleepq_timedwait(c87f5dec) at sleepq_timedwait+0x4a
msleep(c87f5dec,c09bf980,4c,c088b6e1,64) at msleep+0x255
biowait(c87f5dec,c088b6e1,c87f5dec,c86a6100,eaf13c88,...) at biowait+0x52
g_write_data(c86a6100,ffd5a800,1,c956a400,200,...) at g_write_data+0x8d
g_mirror_write_metadata(c86a1900,eaf13c08,c84b2800,c86a1900,eaf13c08,c84b282c,1,c088c7ec,2de)
at g_mirror_write_metadata+0x3eb
g_mirror_update_metadata(c86a1900) at g_mirror_update_metadata+0x55
g_mirror_unidle(c84b2800) at g_mirror_unidle+0xd5
g_mirror_register_request(c8838210) at g_mirror_register_request+0xd7
g_mirror_worker(c84b2800,eaf13d38,c84b2800,c0639754,0,...) at
g_mirror_worker+0x62e
fork_exit(c0639754,c84b2800,eaf13d38) at fork_exit+0xa0
fork_trampoline() at fork_trampoline+0x8
--- trap 0x1, eip = 0, esp = 0xeaf13d6c, ebp = 0 ---
db> trace 2
Tracing pid 2 tid 100001 td 0xc8326d80
sched_switch(c8326d80,0,1) at sched_switch+0x177
mi_switch(1,0) at mi_switch+0x270
sleepq_switch(c84b285c,c09716c0,0,c0895bd7,211,...) at sleepq_switch+0xc1
sleepq_wait(c84b285c,c08933e3,9f,c84b282c,c84b2800,...) at sleepq_wait+0x46
cv_wait(c84b285c,c0970588,c86a1a00,c84b2800,0,...) at cv_wait+0x17b
_sx_xlock(c84b282c,c088c7ec,c2e,c86a1a00,c86a1a00,...) at _sx_xlock+0x68
g_mirror_dumpconf(cb8fb020,c085ac70,c86a1a00,0,0,...) at g_mirror_dumpconf+0x376
g_conf_geom(cb8fb020,c86a1a00,0,0) at g_conf_geom+0x7c
g_conf_class(cb8fb020,c0902280,0,0,0) at g_conf_class+0x49
g_conf_specific(cb8fb020,0,0,0,0,...) at g_conf_specific+0x58
g_confxml(cb8fb020,0,66666667,e6f2bcf4,c062fc29,...) at g_confxml+0x3d
one_event(e6f2bd0c,c0631411,258,190,c06313a4,...) at one_event+0x172
g_run_events(258,190,c06313a4,c8325218,e6f2bd24,...) at g_run_events+0x9
g_event_procbody(0,e6f2bd38,0,c06313a4,0,...) at g_event_procbody+0x6d
fork_exit(c06313a4,0,e6f2bd38) at fork_exit+0xa0
fork_trampoline() at fork_trampoline+0x8
--- trap 0x1, eip = 0, esp = 0xe6f2bd6c, ebp = 0 ---
db> trace 60935
Tracing pid 60935 tid 100122 td 0xc88ce780
sched_switch(c88ce780,0,1) at sched_switch+0x177
mi_switch(1,0) at mi_switch+0x270
sleepq_switch(c9f76880,c09716c0,0,c0895bd7,236,...) at sleepq_switch+0xc1
sleepq_timedwait(c9f76880) at sleepq_timedwait+0x4a
msleep(c9f76880,0,4c,c088b366,3e8) at msleep+0x255
g_waitfor_event(c062f738,cb8fb020,2,0,0,0,0,1) at g_waitfor_event+0x73
sysctl_kern_geom_confxml(c0901b60,0,0,eaf9bbf4,c0901b60,...) at
sysctl_kern_geom_confxml+0x26
sysctl_root(0,eaf9bc74,3,eaf9bbf4) at sysctl_root+0x11b
userland_sysctl(c88ce780,eaf9bc74,3,8050000,bfbfb4d8,0,0,0,eaf9bc70,0,c0971700,0,c0893789,521)
at userland_sysctl+0xf4
__sysctl(c88ce780,eaf9bd04) at __sysctl+0x77
syscall(3b,3b,3b,3,bfbfb4d8,...) at syscall+0x25b
Xint0x80_syscall() at Xint0x80_syscall+0x1f
--- syscall (202, FreeBSD ELF32, __sysctl), eip = 0x2815509f, esp = 0xbfbfb3bc,
ebp = 0xbfbfb3f8 ---


Sadly, there is no kernel thread for the two twa controllers, why?

Should I try with option PREEMTION to see if the deadlock vanishes? And
is there some way to get at the time of the deadlock (by looking at the
oldest cron job, this should be a good estimate).

The gmirror<->sysctl locks seems suspicious to me. Shall I reboot and
reproduce the deadlock to see if it occurs at the same spot?

Any help would be greatly appreciated!

Ulrich Sp?rlein
-- 
A: Yes.>Q: Are you sure?
> >A: Because it reverses the logical flow of conversation.
> >>Q: Why is top posting frowned upon?

freebsd stable - Oct 2006 - RELENG_6: I/O deadlock under load

RELENG_6: I/O deadlock under load

RELENG_6: I/O deadlock under load