Re: speed decrease since firefly,giant,hammer the 2nd try

[Alexandre DERUMIER <aderumier@odiso.com>]

Hi Stefan,

I could be interesting to see if you have the same speed decrease with fio-librbd on the host,
without the qemu layer.

the perf reports don't seem to be too much different.
do you have the same cpu usage ? (check qemu process usage)


----- Mail original -----
De: "Stefan Priebe" <s.priebe@profihost.ag>
À: "Mark Nelson" <mnelson@redhat.com>, "ceph-devel" <ceph-devel@vger.kernel.org>
Envoyé: Dimanche 15 Février 2015 19:40:45
Objet: Re: speed decrease since firefly,giant,hammer the 2nd try

Hi Mark, 

what's next? 

I've this test cluster only for 2 more days. 

Here some perf Details: 

dumpling: 
12,65% libc-2.13.so [.] 0x79000 
2,86% libc-2.13.so [.] malloc 
2,80% kvm [.] 0xb59c5 
2,59% libc-2.13.so [.] free 
2,35% [kernel] [k] __schedule 
2,16% [kernel] [k] _raw_spin_lock 
1,92% [kernel] [k] __switch_to 
1,58% [kernel] [k] lapic_next_deadline 
1,09% [kernel] [k] update_sd_lb_stats 
1,08% [kernel] [k] _raw_spin_lock_irqsave 
0,91% librados.so.2.0.0 [.] ceph_crc32c_le_intel 
0,91% libpthread-2.13.so [.] pthread_mutex_trylock 
0,87% [kernel] [k] resched_task 
0,72% [kernel] [k] cpu_startup_entry 
0,71% librados.so.2.0.0 [.] crush_hash32_3 
0,66% [kernel] [k] leave_mm 
0,65% librados.so.2.0.0 [.] Mutex::Lock(bool) 
0,64% [kernel] [k] idle_cpu 
0,62% libpthread-2.13.so [.] __pthread_mutex_unlock_usercnt 
0,59% [kernel] [k] try_to_wake_up 
0,56% [kernel] [k] wake_futex 
0,50% librados.so.2.0.0 [.] ceph::buffer::ptr::release() 

firefly: 
12,56% libc-2.13.so [.] 0x7905d 
2,82% libc-2.13.so [.] malloc 
2,64% libc-2.13.so [.] free 
2,61% kvm [.] 0x34322f 
2,33% [kernel] [k] __schedule 
2,14% [kernel] [k] _raw_spin_lock 
1,83% [kernel] [k] __switch_to 
1,62% [kernel] [k] lapic_next_deadline 
1,17% [kernel] [k] _raw_spin_lock_irqsave 
1,09% [kernel] [k] update_sd_lb_stats 
1,08% libpthread-2.13.so [.] pthread_mutex_trylock 
0,85% libpthread-2.13.so [.] __pthread_mutex_unlock_usercnt 
0,77% [kernel] [k] resched_task 
0,74% librbd.so.1.0.0 [.] 0x71b73 
0,72% librados.so.2.0.0 [.] Mutex::Lock(bool) 
0,68% librados.so.2.0.0 [.] crush_hash32_3 
0,67% [kernel] [k] idle_cpu 
0,65% [kernel] [k] leave_mm 
0,65% [kernel] [k] cpu_startup_entry 
0,59% [kernel] [k] try_to_wake_up 
0,51% librados.so.2.0.0 [.] ceph::buffer::ptr::release() 
0,51% [kernel] [k] wake_futex 

Stefan 

Am 11.02.2015 um 06:42 schrieb Stefan Priebe: 
> 
> Am 11.02.2015 um 05:45 schrieb Mark Nelson: 
>> On 02/10/2015 04:18 PM, Stefan Priebe wrote: 
>>> 
>>> Am 10.02.2015 um 22:38 schrieb Mark Nelson: 
>>>> On 02/10/2015 03:11 PM, Stefan Priebe wrote: 
>>>>> 
>>>>> mhm i installed librbd1-dbg and librados2-dbg - but the output still 
>>>>> looks useless to me. Should i upload it somewhere? 
>>>> 
>>>> Meh, if it's all just symbols it's probably not that helpful. 
>>>> 
>>>> I've summarized your results here: 
>>>> 
>>>> 1 concurrent 4k write (libaio, direct=1, iodepth=1) 
>>>> 
>>>> IOPS Latency 
>>>> wb on wb off wb on wb off 
>>>> dumpling 10870 536 ~100us ~2ms 
>>>> firefly 10350 525 ~100us ~2ms 
>>>> 
>>>> So in single op tests dumpling and firefly are far closer. Now let's 
>>>> see each of these cases with iodepth=32 (still 1 thread for now). 
>>> 
>>> 
>>> dumpling: 
>>> 
>>> file1: (g=0): rw=randwrite, bs=4K-4K/4K-4K, ioengine=libaio, iodepth=32 
>>> 2.0.8 
>>> Starting 1 thread 
>>> Jobs: 1 (f=1): [w] [100.0% done] [0K/72812K /s] [0 /18.3K iops] [eta 
>>> 00m:00s] 
>>> file1: (groupid=0, jobs=1): err= 0: pid=3011 
>>> write: io=2060.6MB, bw=70329KB/s, iops=17582 , runt= 30001msec 
>>> slat (usec): min=1 , max=3517 , avg= 3.42, stdev= 7.30 
>>> clat (usec): min=93 , max=7475 , avg=1815.72, stdev=233.43 
>>> lat (usec): min=219 , max=7477 , avg=1819.27, stdev=233.52 
>>> clat percentiles (usec): 
>>> | 1.00th=[ 1480], 5.00th=[ 1576], 10.00th=[ 1608], 20.00th=[ 
>>> 1672], 
>>> | 30.00th=[ 1704], 40.00th=[ 1752], 50.00th=[ 1800], 60.00th=[ 
>>> 1832], 
>>> | 70.00th=[ 1896], 80.00th=[ 1960], 90.00th=[ 2064], 95.00th=[ 
>>> 2128], 
>>> | 99.00th=[ 2352], 99.50th=[ 2448], 99.90th=[ 4704], 99.95th=[ 
>>> 5344], 
>>> | 99.99th=[ 7072] 
>>> bw (KB/s) : min=59696, max=77840, per=100.00%, avg=70351.27, 
>>> stdev=4783.25 
>>> lat (usec) : 100=0.01%, 250=0.01%, 500=0.01%, 750=0.01%, 1000=0.53% 
>>> lat (msec) : 2=85.02%, 4=14.31%, 10=0.13% 
>>> cpu : usr=1.96%, sys=6.71%, ctx=22791, majf=0, minf=133 
>>> IO depths : 1=0.1%, 2=0.1%, 4=0.1%, 8=0.1%, 16=0.1%, 32=100.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.1%, 64=0.0%, 
>>> >=64=0.0% 
>>> issued : total=r=0/w=527487/d=0, short=r=0/w=0/d=0 
>>> 
>>> Run status group 0 (all jobs): 
>>> WRITE: io=2060.6MB, aggrb=70329KB/s, minb=70329KB/s, maxb=70329KB/s, 
>>> mint=30001msec, maxt=30001msec 
>>> 
>>> Disk stats (read/write): 
>>> sdb: ios=166/526079, merge=0/0, ticks=24/890120, in_queue=890064, 
>>> util=98.73% 
>>> 
>>> firefly: 
>>> 
>>> file1: (g=0): rw=randwrite, bs=4K-4K/4K-4K, ioengine=libaio, iodepth=32 
>>> 2.0.8 
>>> Starting 1 thread 
>>> Jobs: 1 (f=1): [w] [100.0% done] [0K/69096K /s] [0 /17.3K iops] [eta 
>>> 00m:00s] 
>>> file1: (groupid=0, jobs=1): err= 0: pid=2982 
>>> write: io=1784.9MB, bw=60918KB/s, iops=15229 , runt= 30002msec 
>>> slat (usec): min=1 , max=1389 , avg= 3.43, stdev= 5.32 
>>> clat (usec): min=117 , max=8235 , avg=2096.88, stdev=396.30 
>>> lat (usec): min=540 , max=8258 , avg=2100.43, stdev=396.61 
>>> clat percentiles (usec): 
>>> | 1.00th=[ 1608], 5.00th=[ 1720], 10.00th=[ 1768], 20.00th=[ 
>>> 1832], 
>>> | 30.00th=[ 1896], 40.00th=[ 1944], 50.00th=[ 2008], 60.00th=[ 
>>> 2064], 
>>> | 70.00th=[ 2160], 80.00th=[ 2256], 90.00th=[ 2512], 95.00th=[ 
>>> 2896], 
>>> | 99.00th=[ 3600], 99.50th=[ 3792], 99.90th=[ 5088], 99.95th=[ 
>>> 6304], 
>>> | 99.99th=[ 6752] 
>>> bw (KB/s) : min=36717, max=73712, per=99.94%, avg=60879.92, 
>>> stdev=8302.27 
>>> lat (usec) : 250=0.01%, 750=0.01% 
>>> lat (msec) : 2=48.56%, 4=51.18%, 10=0.26% 
>>> cpu : usr=2.03%, sys=5.48%, ctx=20440, majf=0, minf=133 
>>> IO depths : 1=0.1%, 2=0.1%, 4=0.1%, 8=0.1%, 16=0.1%, 32=100.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.1%, 64=0.0%, 
>>> >=64=0.0% 
>>> issued : total=r=0/w=456918/d=0, short=r=0/w=0/d=0 
>>> 
>>> Run status group 0 (all jobs): 
>>> WRITE: io=1784.9MB, aggrb=60918KB/s, minb=60918KB/s, maxb=60918KB/s, 
>>> mint=30002msec, maxt=30002msec 
>>> 
>>> Disk stats (read/write): 
>>> sdb: ios=166/455574, merge=0/0, ticks=12/897748, in_queue=897696, 
>>> util=98.96% 
>>> 
>> 
>> Ok, so it looks like as you increase concurrency the effect increases 
>> (ie contention?). Does the same thing happen without cache enabled? 
> 
> here again without rbd cache: 
> 
> dumpling: 
> file1: (g=0): rw=randwrite, bs=4K-4K/4K-4K, ioengine=libaio, iodepth=32 
> 2.0.8 
> Starting 1 thread 
> Jobs: 1 (f=1): [w] [100.0% done] [0K/83488K /s] [0 /20.9K iops] [eta 
> 00m:00s] 
> file1: (groupid=0, jobs=1): err= 0: pid=3000 
> write: io=2449.2MB, bw=83583KB/s, iops=20895 , runt= 30005msec 
> slat (usec): min=1 , max=975 , avg= 4.50, stdev= 5.25 
> clat (usec): min=364 , max=80566 , avg=1525.87, stdev=1194.57 
> lat (usec): min=519 , max=80568 , avg=1530.51, stdev=1194.44 
> clat percentiles (usec): 
> | 1.00th=[ 660], 5.00th=[ 780], 10.00th=[ 876], 20.00th=[ 1032], 
> | 30.00th=[ 1144], 40.00th=[ 1240], 50.00th=[ 1304], 60.00th=[ 1384], 
> | 70.00th=[ 1480], 80.00th=[ 1640], 90.00th=[ 2096], 95.00th=[ 2960], 
> | 99.00th=[ 6816], 99.50th=[ 7840], 99.90th=[11712], 99.95th=[13888], 
> | 99.99th=[18816] 
> bw (KB/s) : min=47184, max=95432, per=100.00%, avg=83639.19, 
> stdev=7973.92 
> lat (usec) : 500=0.01%, 750=3.82%, 1000=14.40% 
> lat (msec) : 2=70.57%, 4=7.91%, 10=3.11%, 20=0.17%, 50=0.01% 
> lat (msec) : 100=0.01% 
> cpu : usr=3.12%, sys=11.49%, ctx=74951, majf=0, minf=133 
> IO depths : 1=0.1%, 2=0.1%, 4=0.1%, 8=0.1%, 16=0.1%, 32=100.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.1%, 64=0.0%, 
> >=64=0.0% 
> issued : total=r=0/w=626979/d=0, short=r=0/w=0/d=0 
> 
> Run status group 0 (all jobs): 
> WRITE: io=2449.2MB, aggrb=83583KB/s, minb=83583KB/s, maxb=83583KB/s, 
> mint=30005msec, maxt=30005msec 
> 
> Disk stats (read/write): 
> sdb: ios=168/625292, merge=0/0, ticks=144/916096, in_queue=916128, 
> util=99.93% 
> 
> 
> firefly: 
> 
> fio --filename=/dev/sdb --direct=1 --rw=randwrite --bs=4k --numjobs=1 
> --thread --iodepth=32 --ioengine=libaio --runtime=30 --group_reporting 
> --name=file1 
> file1: (g=0): rw=randwrite, bs=4K-4K/4K-4K, ioengine=libaio, iodepth=32 
> 2.0.8 
> Starting 1 thread 
> Jobs: 1 (f=1): [w] [100.0% done] [0K/90044K /s] [0 /22.6K iops] [eta 
> 00m:00s] 
> file1: (groupid=0, jobs=1): err= 0: pid=2970 
> write: io=2372.9MB, bw=80976KB/s, iops=20244 , runt= 30006msec 
> slat (usec): min=1 , max=4047 , avg= 4.36, stdev= 7.17 
> clat (usec): min=197 , max=76656 , avg=1575.29, stdev=1165.74 
> lat (usec): min=523 , max=76660 , avg=1579.79, stdev=1165.59 
> clat percentiles (usec): 
> | 1.00th=[ 676], 5.00th=[ 804], 10.00th=[ 916], 20.00th=[ 1096], 
> | 30.00th=[ 1224], 40.00th=[ 1304], 50.00th=[ 1384], 60.00th=[ 1448], 
> | 70.00th=[ 1544], 80.00th=[ 1704], 90.00th=[ 2128], 95.00th=[ 2736], 
> | 99.00th=[ 6752], 99.50th=[ 7904], 99.90th=[12096], 99.95th=[14656], 
> | 99.99th=[18560] 
> bw (KB/s) : min=47800, max=91952, per=99.91%, avg=80900.88, 
> stdev=7234.98 
> lat (usec) : 250=0.01%, 500=0.01%, 750=2.95%, 1000=11.38% 
> lat (msec) : 2=73.81%, 4=8.81%, 10=2.85%, 20=0.19%, 50=0.01% 
> lat (msec) : 100=0.01% 
> cpu : usr=2.99%, sys=10.60%, ctx=66549, majf=0, minf=133 
> IO depths : 1=0.1%, 2=0.1%, 4=0.1%, 8=0.1%, 16=0.1%, 32=100.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.1%, 64=0.0%, 
> >=64=0.0% 
> issued : total=r=0/w=607445/d=0, short=r=0/w=0/d=0 
> 
> Run status group 0 (all jobs): 
> WRITE: io=2372.9MB, aggrb=80976KB/s, minb=80976KB/s, maxb=80976KB/s, 
> mint=30006msec, maxt=30006msec 
> 
> Disk stats (read/write): 
> sdb: ios=170/605440, merge=0/0, ticks=156/916492, in_queue=916560, 
> util=99.93% 
> 
> Stefan 
> 
-- 
To unsubscribe from this list: send the line "unsubscribe ceph-devel" in 
the body of a message to majordomo@vger.kernel.org 
More majordomo info at http://vger.kernel.org/majordomo-info.html 

--
To unsubscribe from this list: send the line "unsubscribe ceph-devel" in
the body of a message to majordomo@vger.kernel.org
More majordomo info at  http://vger.kernel.org/majordomo-info.html