Am 10.02.2015 um 21:36 schrieb Mark Nelson:
On 02/10/2015 02:24 PM, Stefan Priebe wrote:
Am 10.02.2015 um 20:40 schrieb Mark Nelson:
On 02/10/2015 01:13 PM, Stefan Priebe wrote:
Am 10.02.2015 um 20:10 schrieb Mark Nelson:
On 02/10/2015 12:55 PM, Stefan Priebe wrote:
Hello,
last year in june i already reported this but there was no real
result.
(http://lists.ceph.com/pipermail/ceph-users-ceph.com/2014-July/041070.html)
I then had the hope that this will be fixed itself when hammer is
released. Now i tried hammer an the results are bad as before.
Since firefly librbd1 / librados2 are 20% slower for 4k random iop/s
than dumpling - this is also the reason why i still stick to
dumpling.
I've now modified my test again to be a bit more clear.
Ceph cluster itself completely dumpling.
librbd1 / librados from dumpling (fio inside qemu): 23k iop/s for
random
4k writes
- stopped qemu
- cp -ra firefly_0.80.8/usr/lib/librados.so.2.0.0 /usr/lib/
- cp -ra firefly_0.80.8/usr/lib/librbd.so.1.0.0 /usr/lib/
- start qemu
same fio, same qemu, same vm, same host, same ceph dumpling storage,
different librados / librbd: 16k iop/s for random 4k writes
What's wrong with librbd / librados2 since firefly?
Hi Stephen,
Just off the top of my head, some questions to investigate:
What happens to single op latencies?
How to test this?
try your random 4k write test using libaio, direct IO, and iodepth=1.
Actually it would be interesting to know how it is with higher IO depths
as well (I assume this is what you are doing now?) Basically I want to
know if single-op latency changes and whether or not it gets hidden or
exaggerated with lots of concurrent IO.
dumpling:
ioengine=libaio and iodepth=32 with 32 threads:
Jobs: 32 (f=32): [wwwwwwwwwwwwwwwwwwwwwwwwwwwwwwww] [100.0% done]
[0K/85224K /s] [0 /21.4K iops] [eta 00m:00s]
ioengine=libaio and iodepth=1 with 32 threads:
Jobs: 32 (f=32): [wwwwwwwwwwwwwwwwwwwwwwwwwwwwwwww] [100.0% done]
[0K/79064K /s] [0 /19.8K iops] [eta 00m:00s]
firefly:
ioengine=libaio and iodepth=32 with 32 threads:
Jobs: 32 (f=32): [wwwwwwwwwwwwwwwwwwwwwwwwwwwwwwww] [100.0% done]
[0K/55781K /s] [0 /15.4K iops] [eta 00m:00s]
ioengine=libaio and iodepth=1 with 32 threads:
Jobs: 32 (f=32): [wwwwwwwwwwwwwwwwwwwwwwwwwwwwwwww] [100.0% done]
[0K/46055K /s] [0 /11.6K iops] [eta 00m:00s]
Sorry, please do this with only 1 thread. If you can include the
latency results too that would be great.
Sorry here again.
Cache on:
dumpling:
file1: (g=0): rw=randwrite, bs=4K-4K/4K-4K, ioengine=libaio, iodepth=1
2.0.8
Starting 1 thread
Jobs: 1 (f=1): [w] [100.0% done] [0K/42892K /s] [0 /10.8K iops] [eta
00m:00s]
file1: (groupid=0, jobs=1): err= 0: pid=3203
write: io=1273.1MB, bw=43483KB/s, iops=10870 , runt= 30001msec
slat (usec): min=5 , max=183 , avg= 8.99, stdev= 1.78
clat (usec): min=0 , max=6378 , avg=81.15, stdev=44.09
lat (usec): min=59 , max=6390 , avg=90.35, stdev=44.22
clat percentiles (usec):
| 1.00th=[ 59], 5.00th=[ 62], 10.00th=[ 64], 20.00th=[ 66],
| 30.00th=[ 69], 40.00th=[ 71], 50.00th=[ 74], 60.00th=[ 80],
| 70.00th=[ 87], 80.00th=[ 95], 90.00th=[ 105], 95.00th=[ 114],
| 99.00th=[ 135], 99.50th=[ 145], 99.90th=[ 179], 99.95th=[ 237],
| 99.99th=[ 2320]
bw (KB/s) : min=36176, max=46816, per=99.96%, avg=43465.49,
stdev=2169.33
lat (usec) : 2=0.01%, 4=0.01%, 20=0.01%, 50=0.01%, 100=85.24%
lat (usec) : 250=14.71%, 500=0.01%, 750=0.01%, 1000=0.01%
lat (msec) : 2=0.01%, 4=0.01%, 10=0.01%
cpu : usr=2.95%, sys=12.29%, ctx=329519, majf=0, minf=133
IO depths : 1=100.0%, 2=0.0%, 4=0.0%, 8=0.0%, 16=0.0%, 32=0.0%,
>=64=0.0%
submit : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%,
>=64=0.0%
complete : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%,
>=64=0.0%
issued : total=r=0/w=326130/d=0, short=r=0/w=0/d=0
Run status group 0 (all jobs):
WRITE: io=1273.1MB, aggrb=43482KB/s, minb=43482KB/s, maxb=43482KB/s,
mint=30001msec, maxt=30001msec
Disk stats (read/write):
sdb: ios=166/325241, merge=0/0, ticks=8/24624, in_queue=24492,
util=81.64%
firefly:
file1: (g=0): rw=randwrite, bs=4K-4K/4K-4K, ioengine=libaio, iodepth=1
2.0.8
Starting 1 thread
Jobs: 1 (f=1): [w] [100.0% done] [0K/44588K /s] [0 /11.2K iops] [eta
00m:00s]
file1: (groupid=0, jobs=1): err= 0: pid=2904
write: io=1212.1MB, bw=41401KB/s, iops=10350 , runt= 30001msec
slat (usec): min=5 , max=464 , avg= 8.95, stdev= 2.34
clat (usec): min=0 , max=4410 , avg=85.81, stdev=41.82
lat (usec): min=59 , max=4418 , avg=94.96, stdev=41.97
clat percentiles (usec):
| 1.00th=[ 59], 5.00th=[ 63], 10.00th=[ 65], 20.00th=[ 68],
| 30.00th=[ 72], 40.00th=[ 76], 50.00th=[ 80], 60.00th=[ 85],
| 70.00th=[ 94], 80.00th=[ 102], 90.00th=[ 112], 95.00th=[ 122],
| 99.00th=[ 145], 99.50th=[ 155], 99.90th=[ 189], 99.95th=[ 239],
| 99.99th=[ 2192]
bw (KB/s) : min=34352, max=45992, per=99.91%, avg=41363.80,
stdev=3314.63
lat (usec) : 2=0.01%, 50=0.01%, 100=77.26%, 250=22.69%, 500=0.02%
lat (usec) : 750=0.01%, 1000=0.01%
lat (msec) : 2=0.01%, 4=0.01%, 10=0.01%
cpu : usr=2.92%, sys=11.63%, ctx=313889, majf=0, minf=133
IO depths : 1=100.0%, 2=0.0%, 4=0.0%, 8=0.0%, 16=0.0%, 32=0.0%,
>=64=0.0%
submit : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%,
>=64=0.0%
complete : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%,
>=64=0.0%
issued : total=r=0/w=310521/d=0, short=r=0/w=0/d=0
Run status group 0 (all jobs):
WRITE: io=1212.1MB, aggrb=41401KB/s, minb=41401KB/s, maxb=41401KB/s,
mint=30001msec, maxt=30001msec
Disk stats (read/write):
sdb: ios=166/309726, merge=0/0, ticks=16/24772, in_queue=24688,
util=82.30%
sorry the old cache off results were wrong here are new ones also with
only one thread:
dumpling:
Jobs: 1 (f=1): [w] [100.0% done] [0K/2140K /s] [0 /535 iops] [eta 00m:00s]
file1: (groupid=0, jobs=1): err= 0: pid=2906
write: io=64424KB, bw=2147.5KB/s, iops=536 , runt= 30001msec
slat (usec): min=14 , max=848 , avg=30.27, stdev= 8.70
clat (usec): min=914 , max=74110 , avg=1826.25, stdev=604.49
lat (usec): min=1395 , max=74138 , avg=1857.26, stdev=604.48
clat percentiles (usec):
| 1.00th=[ 1592], 5.00th=[ 1656], 10.00th=[ 1688], 20.00th=[ 1736],
| 30.00th=[ 1768], 40.00th=[ 1784], 50.00th=[ 1816], 60.00th=[ 1832],
| 70.00th=[ 1864], 80.00th=[ 1896], 90.00th=[ 1928], 95.00th=[ 1960],
| 99.00th=[ 2064], 99.50th=[ 2384], 99.90th=[ 5024], 99.95th=[ 5600],
| 99.99th=[11712]
bw (KB/s) : min= 1768, max= 2240, per=100.00%, avg=2149.53,
stdev=56.30
lat (usec) : 1000=0.01%
lat (msec) : 2=97.67%, 4=2.11%, 10=0.20%, 20=0.01%, 100=0.01%
cpu : usr=0.72%, sys=2.12%, ctx=19289, majf=0, minf=133
IO depths : 1=100.0%, 2=0.0%, 4=0.0%, 8=0.0%, 16=0.0%, 32=0.0%,
>=64=0.0%
submit : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%,
>=64=0.0%
complete : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%,
>=64=0.0%
issued : total=r=0/w=16106/d=0, short=r=0/w=0/d=0
Run status group 0 (all jobs):
WRITE: io=64424KB, aggrb=2147KB/s, minb=2147KB/s, maxb=2147KB/s,
mint=30001msec, maxt=30001msec
Disk stats (read/write):
sdb: ios=168/16067, merge=0/0, ticks=164/29004, in_queue=29144,
util=96.93%
firefly:
file1: (g=0): rw=randwrite, bs=4K-4K/4K-4K, ioengine=libaio, iodepth=1
2.0.8
Starting 1 thread
Jobs: 1 (f=1): [w] [100.0% done] [0K/2141K /s] [0 /535 iops] [eta 00m:00s]
file1: (groupid=0, jobs=1): err= 0: pid=3034
write: io=63100KB, bw=2103.3KB/s, iops=525 , runt= 30001msec
slat (usec): min=17 , max=388 , avg=33.26, stdev= 6.55
clat (usec): min=1392 , max=54698 , avg=1862.25, stdev=478.79
lat (usec): min=1507 , max=54716 , avg=1896.28, stdev=478.69
clat percentiles (usec):
| 1.00th=[ 1624], 5.00th=[ 1688], 10.00th=[ 1720], 20.00th=[ 1768],
| 30.00th=[ 1800], 40.00th=[ 1832], 50.00th=[ 1848], 60.00th=[ 1880],
| 70.00th=[ 1896], 80.00th=[ 1928], 90.00th=[ 1960], 95.00th=[ 1992],
| 99.00th=[ 2096], 99.50th=[ 2512], 99.90th=[ 5344], 99.95th=[ 5984],
| 99.99th=[11840]
bw (KB/s) : min= 1760, max= 2160, per=100.00%, avg=2104.68,
stdev=49.36
lat (msec) : 2=95.18%, 4=4.57%, 10=0.23%, 20=0.01%, 100=0.01%
cpu : usr=0.88%, sys=2.09%, ctx=18938, majf=0, minf=133
IO depths : 1=100.0%, 2=0.0%, 4=0.0%, 8=0.0%, 16=0.0%, 32=0.0%,
>=64=0.0%
submit : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%,
>=64=0.0%
complete : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%,
>=64=0.0%
issued : total=r=0/w=15775/d=0, short=r=0/w=0/d=0
Run status group 0 (all jobs):
WRITE: io=63100KB, aggrb=2103KB/s, minb=2103KB/s, maxb=2103KB/s,
mint=30001msec, maxt=30001msec
Disk stats (read/write):
sdb: ios=170/15740, merge=0/0, ticks=268/28856, in_queue=29116,
util=96.45%
How's CPU usage? (Does perf report show anything useful?)
Can you get trace data?
I'm not familiar with trace or perf - what should do exactly?
you may need extra packages. Basically on VM host, during the test with
each library you'd do:
sudo perf record -a -g dwarf -F 99
(ctrl+c after a while)
sudo perf report --stdio > foo.txt
if you are on a kernel that doesn't have libunwind support:
sudo perf record -a -g
(ctrl+c after a while)
sudo perf report --stdio > foo.txt
Then look and see what's different. This may not catch anything though.
Don't have unwind.
Too bad, oh well.
Output is only full of hex values.
You'll at least need the correct debug symbols either compiled into the
library or available wherever your OS puts them. Sometimes the perf
cache needs to be manually edited so they point to the right place, it's
super annoying.
mhm i installed librbd1-dbg and librados2-dbg - but the output still
looks useless to me. Should i upload it somewhere?
Stefan
--
To unsubscribe from this list: send the line "unsubscribe ceph-devel" in
the body of a message to majordomo@xxxxxxxxxxxxxxx
More majordomo info at http://vger.kernel.org/majordomo-info.html
