task blocked for more than 120 seconds
Josef 'Jeff' Sipek
jeffpc at josefsipek.net
Fri Apr 20 08:58:20 CDT 2012
On Fri, Apr 20, 2012 at 08:56:03AM +1000, Dave Chinner wrote:
> On Thu, Apr 19, 2012 at 11:46:02AM -0400, Josef 'Jeff' Sipek wrote:
...
> > /dev/sda4 /var/data/disk0 xfs rw,noatime,attr2,filestreams,delaylog,nobarrier,inode64,logbufs=8,logbsize=256k,noquota 0 0
>
> Only unusual thing is the filestreams allocator is in use...
Yep. It seemed to make sense to use it since we just want the files to get
to disk.
> > fs3.ess ~ # xfs_info /var/data/disk0/
> > meta-data=/dev/sda4 isize=256 agcount=32, agsize=268435455 blks
> > = sectsz=512 attr=2
> > data = bsize=4096 blocks=8519632640, imaxpct=5
> > = sunit=0 swidth=0 blks
> > naming =version 2 bsize=4096 ascii-ci=0
> > log =internal bsize=4096 blocks=521728, version=2
>
> and it is a large log, so that's a definite candidate for long
> stalls pushing the tail of the log. The typical push that you'll get
> stalled on is trying to keep 25% fthe log space free, so there's
> potentially hundreds of megabytes of random 4/8k metadata writes to
> be done to free that space in the log...
FWIW, the filesystem was made using the default mkfs options (IOW: mkfs.xfs
/dev/sda4). I didn't even notice the log being 2GB. (I just assumed it'd
be the good ol' 128MB.)
> What was the size of the log on the previous incarnation of the
> filesystem?
I don't know. I checked the other file server that was set up at the same
time, and it has a log that's the same size.
...
> > The following applies to all of the spikes, but I'm specifically talking about
> > the spike from this morning. During the ~45 minute spike, there seems to be
> > very little disk I/O (<1 MByte/s compared to the usual 10 MBytes/s). Since
>
> That sounds like it might have dropped into random 4k write IO or
> inode cluster RMW cycles - a single large RAID6 volume is going to
> be no faster than a single spindle at this. Can you get `iostat -d
> -m -x 5` output when the next slowdown occurs so we can see the IOPS
> and utilisation as well as the bandwidth?
Right. Here's the output from a few minutes ago (I removed the empty lines
and redundant column headings):
fs3.ess ~ # iostat -d -m -x 5
Linux 3.2.2 (fs3.ess.sfj.cudaops.com) 04/20/12 _x86_64_ (6 CPU)
Device: rrqm/s wrqm/s r/s w/s rMB/s wMB/s avgrq-sz avgqu-sz await r_await w_await svctm %util
sda 11.90 129.18 261.81 457.22 2.81 6.76 27.26 4.44 6.18 9.60 4.22 0.82 59.02
sda 0.00 0.20 61.20 112.60 0.49 0.88 16.17 1.50 8.64 17.66 3.74 5.74 99.76
sda 0.00 0.60 61.40 117.60 0.48 0.92 16.02 1.33 7.41 16.18 2.82 5.56 99.52
sda 0.00 1.20 63.40 104.20 0.50 0.82 16.09 1.28 7.65 15.70 2.75 5.94 99.60
sda 0.00 43.00 59.20 166.60 0.46 1.64 19.05 1.63 7.23 16.82 3.82 4.41 99.60
sda 0.00 0.40 60.80 139.80 0.47 1.09 16.00 1.32 6.57 16.25 2.36 4.96 99.44
sda 0.00 1.20 59.60 108.00 0.47 0.85 16.08 1.22 7.34 16.82 2.10 5.95 99.68
sda 0.00 0.40 66.60 102.80 0.52 0.80 16.01 1.28 7.57 15.00 2.75 5.88 99.68
sda 0.00 4.80 67.00 111.60 0.52 0.91 16.39 1.21 6.75 14.85 1.88 5.58 99.68
sda 0.00 0.60 64.60 103.40 0.50 0.81 16.02 1.16 6.90 15.48 1.55 5.94 99.76
sda 0.00 23.00 65.20 122.60 0.51 1.14 17.96 1.34 7.13 15.28 2.80 5.31 99.68
sda 0.00 0.60 62.40 153.60 0.49 1.20 16.01 1.40 6.46 15.88 2.63 4.63 99.92
sda 0.00 13.60 56.20 131.20 0.44 1.13 17.13 1.39 7.43 17.81 2.98 5.31 99.52
sda 0.00 18.80 29.80 422.00 0.23 3.44 16.66 20.54 45.46 33.40 46.31 2.20 99.52
sda 0.00 0.40 80.40 2.00 0.63 0.01 15.98 0.99 12.09 12.39 0.00 12.06 99.36
sda 0.00 3.60 70.20 12.60 0.55 0.12 16.64 1.00 11.71 13.81 0.00 12.04 99.68
sda 0.00 28.20 66.60 40.40 0.52 0.54 20.22 1.12 10.68 15.33 3.01 9.29 99.36
sda 0.00 0.80 71.80 89.00 0.56 0.70 16.04 1.24 7.66 13.77 2.72 6.21 99.84
sda 0.00 3.60 56.60 156.00 0.44 1.24 16.24 1.51 7.10 17.58 3.29 4.69 99.68
sda 0.00 0.40 64.80 106.80 0.51 0.84 16.01 1.18 6.93 15.56 1.69 5.82 99.84
sda 0.00 4.60 22.80 439.40 0.18 3.46 16.14 25.95 56.14 43.68 56.78 2.16 99.68
sda 0.00 28.20 70.60 87.60 0.57 0.90 19.02 1.33 8.43 14.29 3.71 6.29 99.52
sda 0.00 0.60 83.60 4.00 0.65 0.03 16.02 0.99 11.33 11.88 0.00 11.33 99.28
sda 0.00 13.20 80.00 44.40 0.62 0.23 14.10 1.00 8.08 12.45 0.20 8.00 99.52
sda 0.00 1.00 74.60 41.40 0.58 0.33 16.06 1.08 9.23 13.22 2.05 8.58 99.52
sda 0.00 0.40 63.00 95.20 0.49 0.74 16.01 1.28 8.16 15.89 3.05 6.28 99.36
sda 0.00 5.00 22.60 482.60 0.18 3.81 16.15 9.94 19.65 43.68 18.53 1.98 100.00
sda 0.00 0.20 75.40 10.60 0.59 0.08 15.98 1.00 11.75 13.40 0.00 11.57 99.52
sda 0.00 0.00 78.00 1.60 0.61 0.01 16.00 1.00 12.50 12.76 0.00 12.53 99.76
sda 0.00 14.40 75.80 52.40 0.59 0.52 17.75 1.15 8.95 13.12 2.93 7.76 99.44
sda 0.00 36.40 70.60 101.80 0.55 1.08 19.34 1.29 7.47 14.11 2.86 5.77 99.44
sda 0.00 0.60 63.80 143.40 0.50 1.12 16.02 1.49 7.18 15.59 3.44 4.81 99.60
sda 0.00 32.80 55.40 197.00 0.43 1.79 18.05 1.67 6.62 17.92 3.44 3.94 99.44
sda 0.00 2.20 62.60 132.20 0.49 1.03 16.02 1.38 7.08 15.96 2.88 5.12 99.76
sda 0.00 6.20 64.20 122.40 0.50 1.00 16.49 1.35 7.20 15.45 2.88 5.34 99.60
sda 0.00 0.00 62.60 111.20 0.49 0.87 16.00 1.28 7.38 16.00 2.53 5.74 99.76
sda 0.00 7.20 58.20 121.60 0.45 1.00 16.61 1.16 6.27 16.54 1.36 5.53 99.36
sda 0.00 0.20 68.20 104.40 0.53 0.81 15.99 1.33 7.88 15.10 3.16 5.78 99.76
sda 0.00 14.60 62.40 122.40 0.49 1.07 17.23 1.49 8.08 16.00 4.04 5.40 99.76
And now while the system is coming back to the usual loadavg (of 30):
Device: rrqm/s wrqm/s r/s w/s rMB/s wMB/s avgrq-sz avgqu-sz await r_await w_await svctm %util
sda 0.00 26.00 29.00 1235.40 0.13 17.10 27.91 202.30 161.37 1792.52 123.08 0.79 100.00
sda 0.00 29.80 26.20 1095.60 0.11 15.34 28.22 185.88 187.19 2248.92 137.89 0.89 100.00
sda 0.00 28.20 11.80 1527.20 0.06 19.80 26.44 165.23 112.77 665.83 108.50 0.65 100.00
sda 0.20 2.80 412.40 320.20 2.09 7.00 25.40 61.10 87.40 53.49 131.06 1.37 100.00
sda 2.60 1.60 1056.00 52.20 5.82 0.57 11.81 21.87 19.68 20.65 0.03 0.90 100.00
sda 0.00 7.40 1256.40 34.40 5.77 0.30 9.63 24.81 19.33 19.85 0.19 0.77 100.00
sda 0.00 28.80 917.60 273.00 4.18 2.42 11.34 26.72 22.38 27.52 5.12 0.84 100.00
sda 0.00 0.20 1302.00 28.20 5.90 0.37 9.64 24.75 18.69 19.09 0.03 0.75 100.00
sda 0.00 42.60 61.40 964.60 0.30 11.75 24.05 158.59 144.06 323.64 132.63 0.97 100.00
sda 0.00 29.40 24.00 675.00 0.11 5.00 14.96 143.77 209.05 1007.17 180.67 1.43 100.00
sda 0.00 21.60 28.00 785.00 0.16 6.38 16.48 177.47 220.53 930.09 195.22 1.23 100.00
sda 0.00 31.00 24.40 964.20 0.13 10.67 22.36 177.09 177.76 767.02 162.85 1.01 100.00
sda 0.00 27.00 24.80 1174.20 0.11 14.33 24.68 170.26 144.93 911.90 128.73 0.83 100.00
sda 0.00 34.40 9.00 700.80 0.05 2.98 8.73 151.54 212.61 797.51 205.09 1.41 100.00
sda 0.00 37.20 9.00 776.60 0.05 4.09 10.78 152.84 192.65 775.91 185.89 1.27 100.00
sda 0.00 36.60 14.80 716.40 0.07 3.35 9.58 167.69 214.14 769.19 202.68 1.37 100.00
sda 0.00 5.80 54.00 1824.00 0.24 25.04 27.56 200.50 107.98 950.50 83.04 0.53 100.00
sda 0.00 1.80 207.60 1659.60 0.87 36.25 40.72 151.21 89.22 316.71 60.77 0.54 100.00
sda 0.00 2.00 1513.20 33.20 6.96 0.27 9.57 27.73 17.94 18.33 0.10 0.65 100.00
sda 0.00 1.60 1257.00 14.00 5.78 0.68 10.41 24.57 19.34 19.54 1.54 0.79 100.00
sda 0.00 14.20 1214.00 122.80 5.51 5.54 16.93 23.34 17.42 19.05 1.29 0.75 100.00
sda 0.00 13.60 892.80 590.40 4.12 2.67 9.38 25.95 16.39 23.63 5.45 0.67 100.00
sda 0.00 22.00 31.00 775.40 0.15 3.64 9.60 96.49 115.41 671.79 93.16 1.24 100.00
sda 0.00 29.40 29.60 679.40 0.14 4.54 13.52 153.30 215.36 860.62 187.25 1.41 100.00
sda 0.00 20.60 23.00 635.60 0.11 3.06 9.85 136.16 198.69 772.73 177.92 1.52 100.00
sda 0.00 21.40 21.00 909.20 0.10 7.39 16.49 178.96 196.48 1222.10 172.79 1.08 100.00
sda 0.00 6.00 51.80 1457.20 0.23 26.23 35.91 200.49 124.56 666.36 105.30 0.66 100.00
sda 0.00 38.60 29.60 701.00 0.12 3.23 9.40 182.10 267.15 1711.57 206.16 1.37 100.00
Oh, and:
fs3.ess ~ # cat /sys/block/sda/queue/scheduler
noop [deadline] cfq
Jeff.
--
You measure democracy by the freedom it gives its dissidents, not the
freedom it gives its assimilated conformists.
- Abbie Hoffman
More information about the xfs
mailing list