Originally Posted by
stevecs
That is strange.
I'm encountering some more strange behavior. I've been ignoring writes a little until now, but started testing this again today. A single test pass was still running after some 5(!) hours. The total amount of data to be written would have been 16 GB. IO stat showed me this:
Code:
Device: tps MB_read/s MB_wrtn/s MB_read MB_wrtn
sda 276.67 0.00 0.27 0 0
sdb 0.00 0.00 0.00 0 0
sdc 0.00 0.00 0.00 0 0
sdc1 0.00 0.00 0.00 0 0
sdc2 0.00 0.00 0.00 0 0
sdd 0.00 0.00 0.00 0 0
dm-0 0.00 0.00 0.00 0 0
dm-1 0.00 0.00 0.00 0 0
dm-2 0.00 0.00 0.00 0 0
I can imagine that sometimes the onboard cache on the Areca controller might need some time to empty itself, but speeds where consistently this low for the entire duration.
I canceled the test and tested with 16MB and 128MB of data to be written for a single pass.
The first pass of the following test was bizarrely slow again, but the second pass 'suddenly' picked up speed:
Code:
T Q Bytes Ops Time Rate IOPS Latency %CPU OP_Type ReqSize
TARGET PASS0001 0 32 134217728 32768 99.731 1.346 328.56 0.0030 0.02 write 4096
TARGET PASS0002 0 32 134217728 32768 3.193 42.037 10262.91 0.0001 0.09 write 4096
TARGET PASS0003 0 32 134217728 32768 1.700 78.930 19269.97 0.0001 0.16 write 4096
TARGET PASS0004 0 32 134217728 32768 1.347 99.642 24326.67 0.0000 0.25 write 4096
TARGET PASS0005 0 32 134217728 32768 3.774 35.562 8682.02 0.0001 0.09 write 4096
TARGET Average 0 32 671088640 163840 108.036 6.212 1516.53 0.0007 0.02 write 4096
Combined 1 32 671088640 163840 109.000 6.157 1503.12 0.0007 0.01 write 4096
Maybe the controller happened to have a back log of writes to be done to the actual disks and it just happened that after the first pass the cache was available to accept new data again at a decent speed, but I don't think the cache should work that way, does it?
I'm running the script you gave me with one loop added, for the block size, and now the array seems to be writing at a rather normal speed again although a lot of time the figures between passes do differ greatly. E.g. :
Code:
T Q Bytes Ops Time Rate IOPS Latency %CPU OP_Type ReqSize
^MTARGET PASS0001 0 128 134217728 8192 3.236 41.474 2531.35 0.0004 5.74 write 16384
^MTARGET PASS0002 0 128 134217728 8192 2.080 64.541 3939.27 0.0003 0.80 write 16384
^MTARGET PASS0003 0 128 134217728 8192 0.429 312.631 19081.47 0.0001 0.81 write 16384
^MTARGET PASS0004 0 128 134217728 8192 0.402 333.493 20354.77 0.0000 0.89 write 16384
^MTARGET PASS0005 0 128 134217728 8192 0.372 360.663 22013.10 0.0000 1.27 write 16384
^MTARGET Average 0 128 671088640 40960 6.455 103.968 6345.68 0.0002 0.80 write 16384
^M Combined 1 128 671088640 40960 6.455 103.968 6345.68 0.0002 0.49 write 16384
This looks a lot like the 'gaps' I've seen in the results given by bm-flash. Namely, bm-flash doesn't test a total fixed amount of megabytes, but tests for some time and when that time elapses it moves on to the next test. I can't really wrap my head around this. I tried the 8Kib request size a couple of 100 times, and it was consistently fast. I won't dump the hundreds of lines of results of that here, but this is a snapshot from it:
Code:
TARGET PASS0023 0 32 134217728 16384 0.597 224.723 27431.99 0.0000 0.25 write 8192
TARGET PASS0024 0 32 134217728 16384 0.602 223.133 27237.94 0.0000 0.36 write 8192
TARGET PASS0025 0 32 134217728 16384 0.604 222.281 27133.87 0.0000 0.21 write 8192
TARGET PASS0026 0 32 134217728 16384 0.597 224.898 27453.31 0.0000 0.24 write 8192
TARGET PASS0027 0 32 134217728 16384 0.599 224.087 27354.35 0.0000 0.31 write 8192
TARGET PASS0028 0 32 134217728 16384 0.608 220.632 26932.66 0.0000 0.25 write 8192
TARGET PASS0029 0 32 134217728 16384 0.598 224.550 27410.87 0.0000 0.38 write 8192
TARGET PASS0030 0 32 134217728 16384 0.588 228.214 27858.21 0.0000 0.27 write 8192
TARGET PASS0031 0 32 134217728 16384 0.600 223.534 27286.88 0.0000 0.23 write 8192
TARGET PASS0032 0 32 134217728 16384 0.598 224.319 27382.65 0.0000 0.33 write 8192
TARGET PASS0033 0 32 134217728 16384 0.611 219.798 26830.78 0.0000 0.28 write 8192
TARGET PASS0034 0 32 134217728 16384 0.606 221.305 27014.77 0.0000 0.24 write 8192
TARGET PASS0035 0 32 134217728 16384 0.607 221.042 26982.61 0.0000 0.45 write 8192
TARGET PASS0036 0 32 134217728 16384 0.593 226.310 27625.74 0.0000 0.38 write 8192
TARGET PASS0037 0 32 134217728 16384 0.587 228.826 27932.83 0.0000 0.30 write 8192
TARGET PASS0038 0 32 134217728 16384 0.601 223.478 27280.02 0.0000 0.25 write 8192
TARGET PASS0039 0 32 134217728 16384 0.595 225.523 27529.70 0.0000 0.25 write 8192
TARGET PASS0040 0 32 134217728 16384 0.597 224.821 27443.98 0.0000 0.32 write 8192
TARGET PASS0041 0 32 134217728 16384 0.597 224.741 27434.24 0.0000 0.32 write 8192
TARGET PASS0042 0 32 134217728 16384 0.605 221.809 27076.29 0.0000 0.21 write 8192
TARGET PASS0043 0 32 134217728 16384 0.603 222.421 27151.00 0.0000 0.38 write 8192
TARGET PASS0044 0 32 134217728 16384 0.602 222.932 27213.32 0.0000 0.29 write 8192
TARGET PASS0045 0 32 134217728 16384 0.606 221.631 27054.61 0.0000 0.29 write 8192
TARGET PASS0046 0 32 134217728 16384 0.591 227.098 27721.89 0.0000 0.45 write 8192
TARGET PASS0047 0 32 134217728 16384 0.599 223.944 27336.92 0.0000 0.39 write 8192
Then I switched to the 2KiB request size again, and things slowed down again:
Code:
TARGET PASS0001 0 32 134217728 65536 7.288 18.415 8991.82 0.0001 0.13 write 2048
TARGET PASS0002 0 32 134217728 65536 7.002 19.169 9359.76 0.0001 0.06 write 2048
TARGET PASS0003 0 32 134217728 65536 2.404 55.823 27257.08 0.0000 0.25 write 2048
TARGET PASS0004 0 32 134217728 65536 31.388 4.276 2087.93 0.0005 0.02 write 2048
TARGET PASS0005 0 32 134217728 65536 76.843 1.747 852.86 0.0012 0.01 write 2048
TARGET PASS0006 0 32 134217728 65536 75.700 1.773 865.73 0.0012 0.01 write 2048
TARGET PASS0007 0 32 134217728 65536 42.965 3.124 1525.34 0.0007 0.01 write 2048
Thereafter I switched to 8KiB again, it first started slow and then was fast again:
Code:
TARGET PASS0001 0 32 134217728 16384 20.080 6.684 815.95 0.0012 0.03 write 8192
TARGET PASS0002 0 32 134217728 16384 3.438 39.035 4765.01 0.0002 0.18 write 8192
TARGET PASS0003 0 32 134217728 16384 0.662 202.631 24735.23 0.0000 0.37 write 8192
TARGET PASS0004 0 32 134217728 16384 0.626 214.401 26171.94 0.0000 0.24 write 8192
TARGET PASS0005 0 32 134217728 16384 0.603 222.636 27177.26 0.0000 0.42 write 8192
TARGET PASS0006 0 32 134217728 16384 0.608 220.797 26952.78 0.0000 0.33 write 8192
TARGET PASS0007 0 32 134217728 16384 0.603 222.688 27183.57 0.0000 0.23 write 8192
TARGET PASS0008 0 32 134217728 16384 0.603 222.475 27157.57 0.0000 0.27 write 8192
TARGET PASS0009 0 32 134217728 16384 0.616 218.035 26615.59 0.0000 0.21 write 8192
It almost looks like the alternation in writing between block sizes causes some serious (internal) 'trashing' effect or so to take place. I'm not sure yet though...
When I start the test for writing a total of 1024 MB, it also starts slow. This creeps me out a little. How does the RAID controller in advance 'know' that 1024 MB is going to be written. I take it that xdd writes this 1024 MB totally at random in the 64 GB file on which it operates. This is the result for writing 1024 MB total, which is way different from writing 128 MB a couple of hundred times right after each other:
Code:
TARGET PASS0001 0 32 1073741824 131072 352.669 3.045 371.66 0.0027 0.00 write 8192
TARGET PASS0002 0 32 1073741824 131072 19.656 54.627 6668.38 0.0001 0.06 write 8192
TARGET PASS0003 0 32 1073741824 131072 20.078 53.478 6528.10 0.0002 0.05 write 8192
TARGET PASS0004 0 32 1073741824 131072 26.033 41.246 5034.89 0.0002 0.03 write 8192
TARGET PASS0005 0 32 1073741824 131072 21.058 50.990 6224.40 0.0002 0.04 write 8192
TARGET PASS0006 0 32 1073741824 131072 21.431 50.103 6116.08 0.0002 0.04 write 8192
TARGET PASS0007 0 32 1073741824 131072 21.174 50.712 6190.37 0.0002 0.04 write 8192
TARGET PASS0008 0 32 1073741824 131072 30.574 35.119 4287.02 0.0002 0.03 write 8192
TARGET PASS0009 0 32 1073741824 131072 21.966 48.882 5966.98 0.0002 0.03 write 8192
TARGET PASS0010 0 32 1073741824 131072 19.553 54.916 6703.58 0.0001 0.05 write 8192
TARGET Average 0 32 10737418240 1310720 542.097 19.807 2417.87 0.0004 0.01 write 8192
Combined 1 32 10737418240 1310720 554.000 19.382 2365.92 0.0004 0.01 write 8192
(p.s. I hope it doesn't bother anyone that I'm 'dumping' so many figures here)
Reply With Quote
Bookmarks