zfs hang in zio->io_cv) with dd read

John Hay jhay at meraka.org.za
Thu Oct 7 18:49:14 UTC 2010


On Thu, Oct 07, 2010 at 10:38:58AM -0700, Jeremy Chadwick wrote:
> On Thu, Oct 07, 2010 at 07:31:02PM +0200, John Hay wrote:
> > On Thu, Oct 07, 2010 at 06:19:48PM +0200, Goran Lowkrantz wrote:
> > > --On October 7, 2010 17:50:42 +0200 John Hay <jhay at meraka.org.za> wrote:
> > > 
> > > >On Thu, Oct 07, 2010 at 02:35:31PM +0200, Ivan Voras wrote:
> > > >>On 10/07/10 14:15, John Hay wrote:
> > > >>> Hi,
> > > >>>
> > > >>> I got hold of a SunFire X4500 with 48 X 500G disks and thought to try
> > > >>> FreeBSD 8-stable with zfs on it.
> > > >>>
> > > >>> I have setup the two boot disks in a zfs mirror and then the rest in
> > > >>> a pool of 6 X raidz2 of 7 disks each.
> > > >>>
> > > >>> I have created a 10G file with dd in the second pool, but if I try to
> > > >>> read it with dd, dd will hang in "zio->io_cv)" according to ^T. This
> > > >>> happens everytime. The first time I saw messages about an interrupt
> > > >>> storm, so I have put "hw.intr_storm_threshold=10000" in
> > > >>> /etc/sysctl.conf. According to "systat -vm 1" there is atapci for 2-3
> > > >>> seconds and then it is quiet.
> > > >>
> > > >>There are two things you could try: 1) use the AHCI driver
> > > >>(ahci_load="YES" in /boot/loader.conf) and 2) disable superpages, they
> > > >>don't get along on a few models of Opterons (vm.pmap.pg_ps_enabled=0 in
> > > >>/boot/loader.conf).
> > > >
> > > >ahci does not grab them. According to the ahci man page, it can handle
> > > >Marvell 88SX61xx, while these are MV88SX6081 according to pciconf -lcv:
> > > >
> > > >atapci0 at pci0:1:1:0:     class=0x010000 card=0x11ab11ab chip=0x608111ab
> > > >rev=0x09 hdr=0x00     vendor     = 'Marvell Semiconductor (Was: Galileo
> > > >Technology Ltd)'     device     = 'MV88SX6081 8-port SATA II PCI-X
> > > >Controller'
> > > >    class      = mass storage
> > > >    subclass   = SCSI
> > > >    cap 01[40] = powerspec 2  supports D0 D3  current D0
> > > >    cap 05[50] = MSI supports 1 message, 64 bit
> > > >    cap 07[60] = PCI-X 64-bit supports 133MHz, 512 burst read, 4 split
> > > >transactions
> > > 
> > > Then try mvs_load="YES"
> > > 
> > > mvs0 at pci0:6:2:0:	class=0x010000 card=0x11ab11ab chip=0x608111ab 
> > > rev=0x09 hdr=0x00
> > >    vendor     = 'Marvell Semiconductor (Was: Galileo Technology Ltd)'
> > >    device     = 'MV88SX6081 8-port SATA II PCI-X Controller'
> > >    class      = mass storage
> > >    subclass   = SCSI
> > > mvs1 at pci0:5:1:0:	class=0x010000 card=0x11ab11ab chip=0x608111ab 
> > > rev=0x09 hdr=0x00
> > >    vendor     = 'Marvell Semiconductor (Was: Galileo Technology Ltd)'
> > >    device     = 'MV88SX6081 8-port SATA II PCI-X Controller'
> > >    class      = mass storage
> > >    subclass   = SCSI
> > 
> > That helped, thanks. Now the disks are detected as adaXX devices.
> > 
> > The problem still happens though. I think it takes a little longer after
> > I have started dd before it hangs, but it still hangs.
> > 
> > One thing seems a little different though. Occasionaly a short burst of
> > interrupts on the mvsX devices do come through. It also seems that a few
> > seconds after I press ^T in the dd window, I see a burst of mvsX 
> > interrupts happen and dd will report in/out records and bytes. This did
> > not happen with the ata driver. It is still hanging in "zio->io_cv)"
> > though.
> > 
> > I also see these messages in /var/log/messages
> > 
> > Oct  7 17:08:04 thumper1 kernel: mvsch31: EMPTY CRPB 16 (->0) 0 4000
> > Oct  7 17:08:04 thumper1 kernel: mvsch31: EMPTY CRPB 17 (->0) 1 4000
> > Oct  7 17:08:04 thumper1 kernel: mvsch31: EMPTY CRPB 18 (->0) 2 4000
> > Oct  7 17:08:04 thumper1 kernel: mvsch31: EMPTY CRPB 20 (->0) 0 4000
> > Oct  7 17:08:04 thumper1 kernel: mvsch31: EMPTY CRPB 21 (->0) 1 4000
> > Oct  7 17:08:04 thumper1 kernel: mvsch31: EMPTY CRPB 22 (->0) 2 4000
> > Oct  7 17:08:04 thumper1 kernel: mvsch31: EMPTY CRPB 23 (->0) 0 4000
> > Oct  7 17:08:04 thumper1 kernel: mvsch31: EMPTY CRPB 24 (->0) 0 4000
> > Oct  7 17:08:04 thumper1 kernel: mvsch31: EMPTY CRPB 25 (->0) 1 4000
> > Oct  7 17:08:04 thumper1 kernel: 
> > Oct  7 17:08:04 thumper1 kernel: mvsch31: EMPTY CRPB 26 (->0) 0 4000
> > Oct  7 17:08:04 thumper1 kernel: mvsch31: EMPTY CRPB 27 (->0) 0 4000
> > Oct  7 17:08:04 thumper1 kernel: mvsch31: EMPTY CRPB 28 (->0) 1 4000
> > Oct  7 17:08:04 thumper1 kernel: mvsch31: EMPTY CRPB 29 (->0) 2 4000
> > Oct  7 17:08:04 thumper1 kernel: mvsch31: EMPTY CRPB 30 (->0) 3 4000
> > Oct  7 17:08:04 thumper1 kernel: mvsch31: EMPTY CRPB 31 (->0) 0 4000
> > Oct  7 17:08:04 thumper1 kernel: mvsch31: EMPTY CRPB 2 (->18) 1 4000
> > Oct  7 17:08:04 thumper1 kernel: mvsch31: EMPTY CRPB 5 (->18) 0 4000
> > Oct  7 17:08:04 thumper1 kernel: mvsch31: EMPTY CRPB 6 (->18) 0 4000
> > Oct  7 17:08:04 thumper1 kernel: mvsch31: EMPTY CRPB 7 (->18) 0 4000
> > Oct  7 17:08:04 thumper1 kernel: mvsch31: EMPTY CRPB 8 (->18) 1 4000
> > Oct  7 17:08:05 thumper1 kernel: 
> > Oct  7 17:08:05 thumper1 kernel: mvsch31: EMPTY CRPB 9 (->18) 2 4000
> > Oct  7 17:08:05 thumper1 kernel: mvsch31: EMPTY CRPB 10 (->18) 0 4000
> > Oct  7 17:08:05 thumper1 kernel: mvsch31: EMPTY CRPB 11 (->18) 1 4000
> > Oct  7 17:08:05 thumper1 kernel: mvsch31: EMPTY CRPB 12 (->18) 0 4000
> > Oct  7 17:08:05 thumper1 kernel: mvsch31: EMPTY CRPB 13 (->18) 0 4000
> > Oct  7 17:08:05 thumper1 kernel: mvsch31: EMPTY CRPB 14 (->18) 1 4000
> > Oct  7 17:08:05 thumper1 kernel: mvsch31: EMPTY CRPB 15 (->18) 2 4000
> > Oct  7 17:08:05 thumper1 kernel: mvsch31: EMPTY CRPB 16 (->18) 3 4000
> > Oct  7 17:08:05 thumper1 kernel: mvsch31: EMPTY CRPB 17 (->18) 0 4000
> > Oct  7 17:08:05 thumper1 kernel: mvsch31: EMPTY CRPB 18 (->22) 1 4000
> > Oct  7 17:08:05 thumper1 kernel: mvsch31: EMPTY CRPB 19 (->22) 2 4000
> > Oct  7 17:08:05 thumper1 kernel: 
> > Oct  7 17:08:05 thumper1 kernel: mvsch31: EMPTY CRPB 20 (->22) 3 4000
> > Oct  7 17:08:05 thumper1 kernel: mvsch20: EMPTY CRPB 30 (->31) 0 0000
> > Oct  7 17:08:05 thumper1 kernel: mvsch20: EMPTY CRPB 7 (->0) 0 4000
> > Oct  7 17:08:05 thumper1 kernel: mvsch20: EMPTY CRPB 8 (->0) 1 4000
> > Oct  7 17:08:05 thumper1 kernel: mvsch20: EMPTY CRPB 10 (->0) 3 4000
> > Oct  7 17:08:05 thumper1 kernel: mvsch20: EMPTY CRPB 11 (->0) 0 4000
> > Oct  7 17:08:05 thumper1 kernel: mvsch20: EMPTY CRPB 12 (->0) 1 4000
> > Oct  7 17:08:05 thumper1 kernel: mvsch20: EMPTY CRPB 13 (->0) 2 4000
> > Oct  7 17:08:05 thumper1 kernel: mvsch20: EMPTY CRPB 14 (->0) 3 4000
> > ...
> > Oct  7 17:08:09 thumper1 kernel: mvsch19: EMPTY CRPB 9 (->10) 0 0000
> > Oct  7 17:08:39 thumper1 kernel: mvsch19: Timeout on slot 1
> > Oct  7 17:08:39 thumper1 kernel: mvsch19: iec 02000000 sstat 00000123 serr 00000000 edma_s 00001024 dma_c 00000000 dma_s 00000000 rs 00000002 status 50
> > Oct  7 17:08:39 thumper1 kernel: mvsch22: EMPTY CRPB 19 (->0) 1 4000
> > Oct  7 17:08:39 thumper1 kernel: mvsch22: EMPTY CRPB 20 (->0) 3 4000
> > Oct  7 17:08:39 thumper1 kernel: mvsch22: EMPTY CRPB 21 (->0) 2 4000
> > ...
> > Oct  7 17:08:43 thumper1 kernel: mvsch18: EMPTY CRPB 14 (->15) 0 4000
> > Oct  7 17:08:43 thumper1 kernel: mvsch29: EMPTY CRPB 29 (->0) 0 4000
> > Oct  7 17:09:13 thumper1 kernel: mvsch29: Timeout on slot 1
> > Oct  7 17:09:13 thumper1 kernel: mvsch29: iec 02000000 sstat 00000123 serr 00000000 edma_s 00001025 dma_c 00000000 dma_s 00000000 rs 00000002 status 50
> > Oct  7 17:09:14 thumper1 kernel: mvsch20: EMPTY CRPB 27 (->0) 1 4000
> > Oct  7 17:09:14 thumper1 kernel: mvsch20: EMPTY CRPB 29 (->0) 3 4000
> > Oct  7 17:09:14 thumper1 kernel: mvsch20: EMPTY CRPB 30 (->0) 0 4000
> > ...
> > Oct  7 17:09:14 thumper1 kernel: mvsch20: EMPTY CRPB 26 (->29) 1 4000
> > Oct  7 17:09:14 thumper1 kernel: mvsch20: EMPTY CRPB 27 (->29) 2 4000
> > Oct  7 17:09:14 thumper1 kernel: mvsch20: EMPTY CRPB 28 (->29) 0 4000
> > Oct  7 17:09:14 thumper1 kernel: mvsch20: EMPTY CRPB 8 (->9) 0 0000
> > Oct  7 17:09:44 thumper1 kernel: mvsch20: Timeout on slot 1
> > Oct  7 17:09:44 thumper1 kernel: mvsch20: iec 02000000 sstat 00000123 serr 00000000 edma_s 00001123 dma_c 00000000 dma_s 00000000 rs 00000002 status 50
> > Oct  7 17:09:45 thumper1 kernel: mvsch12: EMPTY CRPB 26 (->27) 0 002a
> > Oct  7 17:10:15 thumper1 kernel: mvsch12: Timeout on slot 1
> > Oct  7 17:10:15 thumper1 kernel: mvsch12: iec 02000000 sstat 00000123 serr 00000000 edma_s 00001022 dma_c 00000000 dma_s 00000000 rs 00000002 status 50
> > Oct  7 17:10:15 thumper1 kernel: mvsch4: EMPTY CRPB 14 (->15) 0 0000
> > Oct  7 17:10:45 thumper1 kernel: mvsch4: Timeout on slot 1
> > Oct  7 17:10:45 thumper1 kernel: mvsch4: iec 02000000 sstat 00000123 serr 00000000 edma_s 00001020 dma_c 00000000 dma_s 00000000 rs 00000002 status 50
> > Oct  7 17:10:45 thumper1 kernel: mvsch22: EMPTY CRPB 7 (->0) 1 4000
> > Oct  7 17:10:45 thumper1 kernel: mvsch22: EMPTY CRPB 8 (->0) 0 4000
> > Oct  7 17:10:45 thumper1 kernel: mvsch22: EMPTY CRPB 9 (->0) 1 4000
> > ...
> > Oct  7 17:10:48 thumper1 kernel: mvsch19: EMPTY CRPB 21 (->26) 3 4000
> > Oct  7 17:10:48 thumper1 kernel: mvsch21: EMPTY CRPB 19 (->20) 0 0000
> > Oct  7 17:10:48 thumper1 kernel: mvsch21: EMPTY CRPB 28 (->29) 0 0000
> > Oct  7 17:11:18 thumper1 kernel: mvsch21: Timeout on slot 2
> > Oct  7 17:11:18 thumper1 kernel: mvsch21: iec 02000000 sstat 00000123 serr 00000000 edma_s 00001026 dma_c 00000000 dma_s 00000000 rs 00000014 status 50
> > Oct  7 17:11:18 thumper1 kernel: mvsch21:  ... waiting for slots 00000010
> > Oct  7 17:11:18 thumper1 kernel: mvsch21: Timeout on slot 4
> > Oct  7 17:11:18 thumper1 kernel: mvsch21: iec 02000000 sstat 00000123 serr 00000000 edma_s 00001026 dma_c 00000000 dma_s 00000000 rs 00000014 status 50
> > Oct  7 17:11:19 thumper1 kernel: mvsch27: EMPTY CRPB 22 (->23) 0 0000
> > Oct  7 17:11:19 thumper1 kernel: mvsch21: EMPTY CRPB 12 (->13) 0 4000
> > Oct  7 17:11:19 thumper1 kernel: mvsch29: EMPTY CRPB 6 (->7) 0 0000
> > ...
> > Oct  7 17:11:19 thumper1 kernel: mvsch1: EMPTY CRPB 13 (->16) 0 4000
> > Oct  7 17:11:19 thumper1 kernel: mvsch1: EMPTY CRPB 14 (->16) 1 4000
> > Oct  7 17:11:19 thumper1 kernel: mvsch1: EMPTY CRPB 15 (->16) 0 4000
> > Oct  7 17:11:49 thumper1 kernel: mvsch27: Timeout on slot 1
> > Oct  7 17:11:49 thumper1 kernel: mvsch27: iec 02000000 sstat 00000123 serr 00000000 edma_s 00001023 dma_c 00000000 dma_s 00000000 rs 00000002 status 50
> > Oct  7 17:11:49 thumper1 kernel: mvsch21: Timeout on slot 1
> > Oct  7 17:11:49 thumper1 kernel: mvsch21: iec 02000000 sstat 00000123 serr 00000000 edma_s 00001024 dma_c 00000000 dma_s 00000000 rs 00000002 status 50
> > Oct  7 17:11:49 thumper1 kernel: mvsch29: Timeout on slot 1
> > Oct  7 17:11:49 thumper1 kernel: mvsch29: iec 02000000 sstat 00000123 serr 00000000 edma_s 00001024 dma_c 00000000 dma_s 00000000 rs 0000000a status 50
> > Oct  7 17:11:49 thumper1 kernel: mvsch29:  ... waiting for slots 00000008
> > Oct  7 17:11:49 thumper1 kernel: mvsch3: Timeout on slot 2
> > Oct  7 17:11:49 thumper1 kernel: mvsch3: iec 02000000 sstat 00000123 serr 00000000 edma_s 00001023 dma_c 00000000 dma_s 00000000 rs 00000004 status 50
> > Oct  7 17:11:49 thumper1 kernel: mvsch1: EMPTY CRPB 18 (->20) 1 4000
> > Oct  7 17:11:49 thumper1 kernel: mvsch29: Timeout on slot 3
> > Oct  7 17:11:49 thumper1 kernel: mvsch29: iec 02000000 sstat 00000123 serr 00000000 edma_s 00001024 dma_c 00000000 dma_s 00000000 rs 0000000a status 50
> > Oct  7 17:11:49 thumper1 kernel: mvsch2: EMPTY CRPB 14 (->15) 0 0000
> > Oct  7 17:11:49 thumper1 kernel: mvsch30: EMPTY CRPB 21 (->22) 0 0000
> > Oct  7 17:11:49 thumper1 kernel: mvsch12: EMPTY CRPB 22 (->23) 0 0000
> > Oct  7 17:11:49 thumper1 kernel: mvsch23: EMPTY CRPB 30 (->0) 0 4000
> > ...
> > 
> > Ahh and dd did finish after a long time:
> > 
> > > dd if=tst.dd of=/dev/null bs=64k
> > load: 0.87  cmd: dd 1399 [zio->io_cv)] 35.50r 0.01u 10.57s 0% 868k
> > 107740+0 records in
> > 107740+0 records out
> > 7060848640 bytes transferred in 48.836175 secs (144582344 bytes/sec)
> > 
> > load: 0.44  cmd: dd 1399 [zio->io_cv)] 76.87r 0.01u 11.99s 0% 880k
> > 114476+0 records in
> > 114476+0 records out
> > 7502299136 bytes transferred in 83.218699 secs (90151603 bytes/sec)
> > load: 0.79  cmd: dd 1399 [zio->io_cv)] 104.27r 0.01u 12.37s 0% 880k
> > 118032+0 records in
> > 118032+0 records out
> > 7735345152 bytes transferred in 114.212610 secs (67727593 bytes/sec)
> > load: 0.29  cmd: dd 1399 [zio->io_cv)] 165.37r 0.01u 12.77s 0% 880k
> > 121816+0 records in
> > 121816+0 records out
> > 7983333376 bytes transferred in 174.702303 secs (45696784 bytes/sec)
> > load: 0.01  cmd: dd 1399 [zio->io_cv)] 454.84r 0.01u 15.57s 0% 880k
> > 134566+0 records in
> > 134566+0 records out
> > 8818917376 bytes transferred in 455.140146 secs (19376268 bytes/sec)
> > load: 0.00  cmd: dd 1399 [zio->io_cv)] 671.34r 0.02u 16.71s 0% 880k
> > 143446+0 records in
> > 143446+0 records out
> > 9400877056 bytes transferred in 699.953712 secs (13430712 bytes/sec)
> > 160000+0 records in
> > 160000+0 records out
> > 10485760000 bytes transferred in 1077.266770 secs (9733671 bytes/sec)
> 
> Isn't slow I/O one of the results of ARC starvation?

I doubt it. The machine has 16G RAM and is freshly rebooted. How do I
check? arc sysctls?

> 
> Please also provide vmstat -i output.

> vmstat -i
interrupt                          total       rate
irq17: ohci2                      719371        196
irq18: ohci3                       29530          8
irq19: ohci0 ohci1+                88188         24
irq24: mvs0                        31671          8
irq32: mvs1                        29130          7
irq38: mvs2                        34050          9
irq46: mvs3                        33879          9
irq52: em0                           360          0
irq53: em1                          6272          1
irq61: em2                          6557          1
irq62: em3                          1257          0
irq68: mvs4                        29187          7
irq76: mvs5                        29659          8
cpu0: timer                      7289010       1986
cpu1: timer                      7284596       1984
cpu2: timer                      7279595       1983
cpu3: timer                      7292655       1987
Total                           30184967       8224

John
-- 
John Hay -- jhay at meraka.csir.co.za / jhay at FreeBSD.org


More information about the freebsd-stable mailing list