On Wed, Mar 26, 2014 at 08:11:13PM +0100, Andres Freund wrote: > Hi, > > At LSF/MM there was a slot about postgres' problems with the kernel. Our > top#1 concern is frequent slow read()s that happen while another process > calls fsync(), even though we'd be perfectly fine if that fsync() took > ages. > The "conclusion" of that part was that it'd be very useful to have a > demonstration of the problem without needing a full blown postgres > setup. I've quickly hacked something together, that seems to show the > problem nicely. > > For a bit of context: lwn.net/SubscriberLink/591723/940134eb57fcc0b8/ > and the "IO Scheduling" bit in > http://archives.postgresql.org/message-id/20140310101537.GC10663%40suse.de > > The tools output looks like this: > gcc -std=c99 -Wall -ggdb ~/tmp/ioperf.c -o ioperf && ./ioperf > ... > wal[12155]: avg: 0.0 msec; max: 0.0 msec > commit[12155]: avg: 0.2 msec; max: 15.4 msec > wal[12155]: avg: 0.0 msec; max: 0.0 msec > read[12157]: avg: 0.2 msec; max: 9.4 msec > ... > read[12165]: avg: 0.2 msec; max: 9.4 msec > wal[12155]: avg: 0.0 msec; max: 0.0 msec > starting fsync() of files > finished fsync() of files > read[12162]: avg: 0.6 msec; max: 2765.5 msec > > So, the average read time is less than one ms (SSD, and about 50% cached > workload). But once another backend does the fsync(), read latency > skyrockets. > > A concurrent iostat shows the problem pretty clearly: > 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 1.00 0.00 6322.00 337.00 51.73 4.38 17.26 2.09 0.32 0.19 2.59 0.14 90.00 > sda 0.00 0.00 6016.00 303.00 47.18 3.95 16.57 2.30 0.36 0.23 3.12 0.15 94.40 > sda 0.00 0.00 6236.00 1059.00 49.52 12.88 17.52 5.91 0.64 0.20 3.23 0.12 88.40 > sda 0.00 0.00 105.00 26173.00 0.89 311.39 24.34 142.37 5.42 27.73 5.33 0.04 100.00 > sda 0.00 0.00 78.00 27199.00 0.87 324.06 24.40 142.30 5.25 11.08 5.23 0.04 100.00 > sda 0.00 0.00 10.00 33488.00 0.11 399.05 24.40 136.41 4.07 100.40 4.04 0.03 100.00 > sda 0.00 0.00 3819.00 10096.00 31.14 120.47 22.31 42.80 3.10 0.32 4.15 0.07 96.00 > sda 0.00 0.00 6482.00 346.00 52.98 4.53 17.25 1.93 0.28 0.20 1.80 0.14 93.20 > > While the fsync() is going on (or the kernel decides to start writing > out aggressively for some other reason) the amount of writes to the disk > is increased by two orders of magnitude. Unsurprisingly with disastrous > consequences for read() performance. We really want a way to pace the > writes issued to the disk more regularly. Hi Andreas, I've finally dug myself out from under the backlog from LSFMM far enough to start testing this on my local IO performance test rig. tl;dr: I can't reproduce this peaky behaviour on my test rig. I'm running in a 16p VM with 16GB RAM (in 4 nodes via fake-numa) and an unmodified benchmark on a current 3.15-linus tree. All storage (guest and host) is XFS based, guest VMs use virtio and direct IO to the backing storage. The host is using noop IO scheduling. The first IO setup I ran was a 100TB XFS filesystem in the guest. The backing file is a sparse file on an XFS filesystem on a pair of 240GB SSDs (Samsung 840 EVO) in RAID 0 via DM. The SSDs are exported as JBOD from a RAID controller which has 1GB of FBWC. The guest is capable of sustaining around 65,000 random read IOPS and 40,000 write IOPS through this filesystem depending on the tests being run. The iostat output looks like this: Device: rrqm/s wrqm/s r/s w/s rMB/s wMB/s avgrq-sz avgqu-sz await r_await w_await svctm %util vdc 0.00 0.00 1817.00 315.40 18.80 6.93 24.71 0.80 0.38 0.38 0.37 0.31 66.24 vdc 0.00 0.00 2094.20 323.20 21.82 7.10 24.50 0.81 0.33 0.34 0.27 0.28 68.48 vdc 0.00 0.00 1989.00 4500.20 20.50 56.64 24.34 24.82 3.82 0.43 5.32 0.12 80.16 vdc 0.00 0.00 2019.80 320.80 20.83 7.05 24.39 0.83 0.35 0.36 0.32 0.29 69.04 vdc 0.00 0.00 2206.60 323.20 22.57 7.10 24.02 0.87 0.34 0.34 0.33 0.28 71.92 vdc 0.00 0.00 2437.20 329.60 25.79 7.24 24.45 0.83 0.30 0.30 0.27 0.26 71.76 vdc 0.00 0.00 1224.40 11263.80 12.88 136.38 24.48 64.90 5.20 0.69 5.69 0.07 84.96 vdc 0.00 0.00 2074.60 319.40 21.03 7.01 23.99 0.84 0.35 0.36 0.30 0.29 68.96 vdc 0.00 0.00 1999.00 881.60 20.81 13.61 24.47 4.23 1.43 0.35 3.88 0.23 67.36 vdc 0.00 0.00 1193.40 2273.00 12.42 29.68 24.87 11.70 3.40 0.53 4.91 0.18 60.96 vdc 0.00 0.00 1724.00 314.40 17.80 6.91 24.83 0.74 0.36 0.36 0.35 0.30 61.52 vdc 0.00 0.00 2605.20 325.60 24.67 7.15 22.24 0.90 0.31 0.31 0.25 0.25 72.72 vdc 0.00 0.00 2340.60 324.40 23.85 7.12 23.80 0.83 0.31 0.31 0.29 0.26 68.96 vdc 0.00 0.00 2749.60 329.40 28.51 7.24 23.78 0.90 0.29 0.30 0.25 0.24 75.04 vdc 0.00 0.00 2619.60 324.60 27.72 7.13 24.24 0.88 0.30 0.30 0.28 0.24 71.76 vdc 0.00 0.00 1608.60 4532.40 17.17 56.40 24.54 25.78 4.20 0.50 5.51 0.12 75.36 vdc 0.00 0.00 2361.00 326.40 23.62 7.17 23.47 0.87 0.33 0.33 0.30 0.26 69.92 vdc 0.00 0.00 2460.00 326.00 25.89 7.16 24.30 0.88 0.32 0.32 0.26 0.26 72.72 vdc 0.00 0.00 2519.00 325.40 25.96 7.14 23.83 0.90 0.32 0.32 0.30 0.26 74.32 vdc 0.00 0.00 2709.80 326.20 28.91 7.17 24.34 0.94 0.31 0.30 0.36 0.25 75.52 vdc 0.00 0.00 2676.65 329.74 28.82 7.24 24.56 0.86 0.28 0.29 0.25 0.24 71.22 vdc 0.00 0.00 1788.40 4506.80 18.77 56.66 24.54 23.22 3.69 0.45 4.97 0.12 74.88 vdc 0.00 0.00 1850.40 319.60 19.76 7.02 25.28 0.80 0.37 0.37 0.34 0.30 64.80 Its obvious where the fsyncs are hitting, but they are making almost no impact on the read performance. The benchmark is simple not generating enough dirty data to overload the IO subsystem, and hence there's no latency spikes to speak of. Benchmark output across fsyncs also demonstrates that: .... read[12494]: avg: 0.4 msec; max: 9.8 msec read[12499]: avg: 0.4 msec; max: 9.8 msec read[12495]: avg: 0.4 msec; max: 9.8 msec commit[12491]: avg: 0.0 msec; max: 6.3 msec wal[12491]: avg: 0.0 msec; max: 0.0 msec wal[12491]: avg: 0.0 msec; max: 0.0 msec starting fsync() of files finished fsync() of files wal[12491]: avg: 0.0 msec; max: 0.7 msec commit[12491]: avg: 0.1 msec; max: 15.8 msec wal[12491]: avg: 0.0 msec; max: 0.1 msec wal[12491]: avg: 0.0 msec; max: 0.1 msec read[12492]: avg: 0.6 msec; max: 10.0 msec read[12496]: avg: 0.6 msec; max: 10.0 msec read[12507]: avg: 0.6 msec; max: 10.0 msec read[12505]: avg: 0.6 msec; max: 10.0 msec .... So, I though switching to spinning disks might show the problem. Same VM, this time using a 17TB linearly preallocated image file on an 18TB XFS filesystem on the host (virtio in the guest again) on a 12 disk RAID-0 (DM again) using a 12x2TB SAS drives exported as JBOD from a RAID controller with 512MB of BBWC. This is capable of about 2,000 random read IOPs, and write IOPS is dependent on the BBWC flushing behaviour (peaks at about 15,000, sustains 1500). Again, I don't see any bad behaviour: Device: rrqm/s wrqm/s r/s w/s rMB/s wMB/s avgrq-sz avgqu-sz await r_await w_await svctm %util vdd 0.00 0.00 128.00 154.20 1.46 6.02 54.24 1.02 3.62 7.22 0.62 3.17 89.44 vdd 0.00 0.00 133.80 154.40 1.43 6.03 53.04 1.08 3.76 7.42 0.59 3.05 87.84 vdd 0.00 0.00 132.40 751.60 1.36 12.75 32.70 7.26 8.21 7.90 8.27 1.06 93.76 vdd 0.00 0.00 138.60 288.60 1.47 7.62 43.57 2.69 6.30 7.24 5.85 2.15 91.68 vdd 0.00 0.00 141.20 157.00 1.51 6.12 52.36 1.12 3.75 7.26 0.59 3.11 92.64 vdd 0.00 0.00 136.80 154.00 1.52 6.02 53.09 1.04 3.57 6.92 0.60 3.10 90.08 vdd 0.00 0.00 135.00 154.20 1.46 6.02 52.99 1.04 3.60 7.00 0.62 3.03 87.68 vdd 0.00 0.00 147.20 155.80 1.50 6.09 51.26 1.19 3.92 7.45 0.59 3.06 92.72 vdd 0.00 0.00 139.60 154.00 1.50 6.02 52.43 1.03 3.53 6.79 0.58 2.97 87.28 vdd 0.00 0.00 126.80 913.80 1.27 14.81 31.63 7.87 7.56 9.02 7.36 0.89 92.16 vdd 0.00 0.00 148.20 156.80 1.51 6.11 51.15 1.17 3.83 7.25 0.59 3.03 92.32 vdd 0.00 0.00 142.60 155.80 1.49 6.09 52.03 1.12 3.76 7.23 0.60 3.05 90.88 vdd 0.00 0.00 146.00 156.60 1.49 6.12 51.48 1.16 3.84 7.32 0.60 3.03 91.76 vdd 0.00 0.00 148.80 157.20 1.56 6.14 51.54 1.10 3.58 6.78 0.54 2.92 89.36 vdd 0.00 0.00 149.80 156.80 1.52 6.12 51.05 1.14 3.73 7.10 0.52 2.96 90.88 vdd 0.00 0.00 127.20 910.60 1.29 14.82 31.80 8.17 7.87 8.62 7.77 0.88 91.44 vdd 0.00 0.00 150.80 157.80 1.58 6.15 51.27 1.09 3.53 6.67 0.52 2.91 89.92 vdd 0.00 0.00 153.00 156.60 1.53 6.12 50.56 1.17 3.80 7.07 0.60 2.95 91.20 vdd 0.00 0.00 161.20 157.00 1.54 6.13 49.36 1.27 4.00 7.36 0.55 2.97 94.48 vdd 0.00 0.00 152.10 157.09 1.55 6.14 50.91 1.15 3.73 7.06 0.50 2.98 92.22 vdd 0.00 0.00 154.80 157.80 1.50 6.16 50.18 1.19 3.82 7.14 0.57 2.88 90.00 vdd 0.00 0.00 122.20 922.80 1.24 14.93 31.70 8.30 7.94 8.81 7.83 0.90 93.68 vdd 0.00 0.00 139.80 153.60 1.46 5.98 51.98 1.09 3.74 7.14 0.65 3.02 88.48 vdd 0.00 0.00 134.60 153.60 1.44 6.00 52.87 1.09 3.78 7.38 0.63 3.15 90.88 vdd 0.00 0.00 141.00 153.40 1.55 5.99 52.49 1.05 3.57 6.79 0.60 3.04 89.44 vdd 0.00 0.00 130.20 154.20 1.44 6.02 53.76 1.04 3.65 7.28 0.59 3.14 89.44 vdd 0.00 0.00 136.60 154.20 1.30 6.02 51.52 1.19 4.07 8.02 0.58 3.03 88.24 vdd 0.00 0.00 119.00 872.20 1.29 14.29 32.20 7.98 8.05 8.59 7.98 0.93 92.64 vdd 0.00 0.00 139.00 154.00 1.58 6.00 53.01 1.06 3.62 6.95 0.61 3.12 91.52 vdd 0.00 0.00 146.00 155.40 1.52 6.07 51.60 1.12 3.71 7.05 0.57 3.01 90.72 vdd 0.00 0.00 145.20 156.60 1.55 6.12 52.01 1.13 3.73 7.10 0.60 3.07 92.80 vdd 0.00 0.00 147.80 156.80 1.51 6.12 51.36 1.13 3.72 7.07 0.56 2.97 90.56 vdd 0.00 0.00 142.80 157.00 1.48 6.12 51.98 1.11 3.70 7.20 0.52 3.02 90.56 vdd 0.00 0.00 125.20 922.00 1.36 14.92 31.85 8.34 7.96 8.47 7.90 0.88 92.56 Again, you can see exactly where the fsyncs are hitting, and again they are not massive spikes of write IO. And read latencies are showing: read[12711]: avg: 6.1 msec; max: 182.2 msec ... read[12711]: avg: 6.0 msec; max: 198.8 msec .... read[12711]: avg: 5.9 msec; max: 158.8 msec .... read[12711]: avg: 6.1 msec; max: 127.5 msec .... read[12711]: avg: 5.9 msec; max: 355.6 msec .... read[12711]: avg: 6.0 msec; max: 262.8 msec .... No significant outliers. The same for commits and wal: wal[12701]: avg: 0.0 msec; max: 0.2 msec wal[12701]: avg: 0.0 msec; max: 0.1 msec commit[12701]: avg: 0.0 msec; max: 1.0 msec wal[12701]: avg: 0.0 msec; max: 0.1 msec wal[12701]: avg: 0.0 msec; max: 0.1 msec starting fsync() of files finished fsync() of files wal[12701]: avg: 0.0 msec; max: 0.1 msec commit[12701]: avg: 0.1 msec; max: 129.2 msec wal[12701]: avg: 0.0 msec; max: 0.1 msec wal[12701]: avg: 0.0 msec; max: 0.1 msec commit[12701]: avg: 0.0 msec; max: 0.9 msec wal[12701]: avg: 0.0 msec; max: 0.2 msec wal[12701]: avg: 0.0 msec; max: 0.1 msec wal[12701]: avg: 0.0 msec; max: 0.1 msec commit[12701]: avg: 0.0 msec; max: 23.1 msec I'm not sure how you were generating the behaviour you reported, but the test program as it stands does not appear to be causing any problems at all on the sort of storage I'd expect large databases to be hosted on.... I've tried a few tweaks to the test program, but I haven't been able to make it misbehave. What do I need to tweak in the test program or my test VM to make the kernel misbehave like you reported? Cheers, Dave. -- Dave Chinner david@xxxxxxxxxxxxx` -- To unsubscribe from this list: send the line "unsubscribe linux-fsdevel" in the body of a message to majordomo@xxxxxxxxxxxxxxx More majordomo info at http://vger.kernel.org/majordomo-info.html
