Skip to content

Instantly share code, notes, and snippets.

@rzarzynski

rzarzynski/reference_43b88419d4f87da514721848d28fe949cf0ecb9e.txt

Last active January 5, 2018 00:57
Show Gist options
  • Save rzarzynski/b521940ae61064e414d2030fc68b0322 to your computer and use it in GitHub Desktop.
Save rzarzynski/b521940ae61064e414d2030fc68b0322 to your computer and use it in GitHub Desktop.
Download ZIP
wip-bs-async-read-rebased: profilling of the sync read path with buffering disabled
Raw
reference_43b88419d4f87da514721848d28fe949cf0ecb9e.txt
4 KiB randread over 1 GiB RBD volume provisioned with 4 MiB chunks
rbd_iodepth32: (groupid=0, jobs=1): err= 0: pid=13417: Fri Jan 5 01:18:41 2018
read: IOPS=22.9k, BW=89.4MiB/s (93.8MB/s)(5366MiB/60003msec)
slat (nsec): min=975, max=1999.6k, avg=7852.04, stdev=29403.40
clat (usec): min=92, max=239443, avg=1388.82, stdev=1764.49
lat (usec): min=201, max=239536, avg=1396.67, stdev=1764.73
clat percentiles (usec):
| 1.00th=[ 433], 5.00th=[ 611], 10.00th=[ 725], 20.00th=[ 881],
| 30.00th=[ 1004], 40.00th=[ 1106], 50.00th=[ 1221], 60.00th=[ 1336],
| 70.00th=[ 1483], 80.00th=[ 1713], 90.00th=[ 2147], 95.00th=[ 2606],
| 99.00th=[ 3720], 99.50th=[ 4293], 99.90th=[ 8029], 99.95th=[20841],
| 99.99th=[81265]
bw ( KiB/s): min= 3928, max=108232, per=99.99%, avg=91570.00, stdev=14015.78, samples=120
iops : min= 982, max=27058, avg=22892.46, stdev=3503.94, samples=120
lat (usec) : 100=0.01%, 250=0.01%, 500=2.09%, 750=9.25%, 1000=18.62%
lat (msec) : 2=57.35%, 4=11.98%, 10=0.62%, 20=0.03%, 50=0.03%
lat (msec) : 100=0.01%, 250=0.01%
cpu : usr=41.14%, sys=27.88%, ctx=1681998, majf=0, minf=7
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 rwt: total=1373749,0,0, short=0,0,0, dropped=0,0,0
latency : target=0, window=0, percentile=100.00%, depth=32
Run status group 0 (all jobs):
READ: bw=89.4MiB/s (93.8MB/s), 89.4MiB/s-89.4MiB/s (93.8MB/s-93.8MB/s), io=5366MiB (5627MB), run=60003-60003msec
Disk stats (read/write):
nvme0n1: ios=1370352/3079, merge=0/239, ticks=103872/14696, in_queue=120016, util=81.86%
==========================================================================================
CPU cycles (perf)
- 43,17% 0,05% tp_osd_tp ceph-osd [.] PGOpItem::run
- 43,12% PGOpItem::run
- 42,29% OSD::dequeue_op
- 40,78% PrimaryLogPG::do_request
- 39,40% PrimaryLogPG::do_op
- 28,57% PrimaryLogPG::execute_ctx
- 16,57% PrimaryLogPG::prepare_transaction
- 16,32% PrimaryLogPG::do_osd_ops
- 14,12% PrimaryLogPG::do_read
- 13,97% ReplicatedBackend::objects_read_sync
- 13,75% BlueStore::read
- 11,66% BlueStore::_do_read
- 8,08% bluestore_blob_t::map
- 7,93% std::_Function_handler<int (unsigned long, unsigned long), BlueStore::_do_read(BlueStore::Collection*, boost::intrusive_ptr<BlueStore::Onode>, unsigned long, unsigned long, ceph::buffer::list&, unsigned int)::{lambda(unsigned long, unsigned long)#2}>::_M_invoke
- 7,90% KernelDevice::read
+ 6,53% __GI___libc_pread64
0,71% ceph::buffer::create_aligned_in_mempool
0,53% BlueStore::_verify_csum
+ 1,05% RWLock::get_read
+ 1,65% md_config_t::get_val<bool>
+ 6,82% PrimaryLogPG::complete_read_ctx
+ 1,42% PrimaryLogPG::close_op_ctx
+ 0,76% PrimaryLogPG::do_osd_op_effects
+ 0,63% ObjectContext::ondisk_read_unlock
0,55% MOSDOpReply::MOSDOpReply
0,52% Mutex::Unlock
+ 1,66% PrimaryLogPG::maybe_await_blocked_head
1,49% MOSDOp::finish_decode
+ 1,40% std::__cxx11::basic_ostringstream<char, std::char_traits<char>, std::allocator<char> >::basic_ostringstream
0,72% PG::op_has_sufficient_caps
+ 0,67% PrimaryLogPG::find_object_context
0,65% PrimaryLogPG::OpContext::OpContext
0,52% OpRequest::mark_flag_point
0,55% OpRequest::mark_flag_point
+ 0,77% Mutex::Unlock
Raw
wip-bs-async-read-rebased+always_sync_read.txt
4 KiB randread over 1 GiB RBD volume provisioned with 4 MiB chunks
rbd_iodepth32: (groupid=0, jobs=1): err= 0: pid=27666: Fri Jan 5 01:46:41 2018
read: IOPS=21.7k, BW=84.9MiB/s (89.1MB/s)(5096MiB/60002msec)
slat (nsec): min=999, max=1884.9k, avg=8294.28, stdev=31565.35
clat (usec): min=68, max=152555, avg=1462.40, stdev=1728.08
lat (usec): min=187, max=152564, avg=1470.69, stdev=1728.44
clat percentiles (usec):
| 1.00th=[ 445], 5.00th=[ 627], 10.00th=[ 750], 20.00th=[ 914],
| 30.00th=[ 1037], 40.00th=[ 1156], 50.00th=[ 1270], 60.00th=[ 1385],
| 70.00th=[ 1549], 80.00th=[ 1795], 90.00th=[ 2278], 95.00th=[ 2737],
| 99.00th=[ 3982], 99.50th=[ 4686], 99.90th=[19268], 99.95th=[36439],
| 99.99th=[80217]
bw ( KiB/s): min= 6528, max=104784, per=99.97%, avg=86948.88, stdev=14925.40, samples=120
iops : min= 1632, max=26196, avg=21737.19, stdev=3731.36, samples=120
lat (usec) : 100=0.01%, 250=0.01%, 500=1.79%, 750=8.27%, 1000=16.97%
lat (msec) : 2=58.16%, 4=13.84%, 10=0.81%, 20=0.07%, 50=0.07%
lat (msec) : 100=0.02%, 250=0.01%
cpu : usr=39.64%, sys=28.29%, ctx=1723076, majf=0, minf=7
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 rwt: total=1304622,0,0, short=0,0,0, dropped=0,0,0
latency : target=0, window=0, percentile=100.00%, depth=32
Run status group 0 (all jobs):
READ: bw=84.9MiB/s (89.1MB/s), 84.9MiB/s-84.9MiB/s (89.1MB/s-89.1MB/s), io=5096MiB (5344MB), run=60002-60002msec
Disk stats (read/write):
nvme0n1: ios=1301499/4014, merge=0/179, ticks=103788/11932, in_queue=116968, util=80.92%
==========================================================================================
CPU cycles (perf)
- 44,18% 0,06% tp_osd_tp ceph-osd [.] PGOpItem::run
- 44,12% PGOpItem::run
- 43,26% OSD::dequeue_op
- 41,68% PrimaryLogPG::do_request
- 40,30% PrimaryLogPG::do_op
- 29,05% PrimaryLogPG::execute_ctx
- 17,11% PrimaryLogPG::prepare_transaction
- 16,90% PrimaryLogPG::do_osd_ops
- 14,78% PrimaryLogPG::do_read
- 14,59% ReplicatedBackend::objects_read_sync
- 14,37% BlueStore::read
- 12,34% BlueStore::_do_read
- 8,56% BlueStore::PlainRegionReader::issue_io
- 8,02% std::_Function_handler<int (unsigned long, unsigned long), std::_Bind<std::function<int (unsigned long, unsigned long, ceph::buffer::list*, unsigned long)> (std::_Placeholder<1>, std::_Placeholder<2>, ceph::buffer::list*, int)> >::_M_invoke
- 7,98% std::_Function_handler<int (unsigned long, unsigned long, ceph::buffer::list*, unsigned long), BlueStore::_do_read(BlueStore::Collection*, boost::intrusive_ptr<BlueStore::Onode>, unsigned long, unsigned long, ceph::buffer::list&, unsigned int)::{lambda(unsigned long, unsigned long, ceph::buffer::list*, unsigned long)#1}>::_M_invoke
+ 7,94% KernelDevice::read
- 1,21% BlueStore::PlainRegionReader::postprocess
0,72% BlueStore::RegionReader::_verify_csum
1,04% BlueStore::_consult_cache
+ 1,02% RWLock::get_read
+ 1,60% md_config_t::get_val<bool>
+ 6,63% PrimaryLogPG::complete_read_ctx
+ 1,43% PrimaryLogPG::close_op_ctx
+ 0,75% PrimaryLogPG::do_osd_op_effects
+ 0,72% ObjectContext::ondisk_read_unlock
+ 0,58% Mutex::Unlock
+ 1,74% PrimaryLogPG::maybe_await_blocked_head
1,51% MOSDOp::finish_decode
+ 1,32% std::__cxx11::basic_ostringstream<char, std::char_traits<char>, std::allocator<char> >::basic_ostringstream
0,77% PG::op_has_sufficient_caps
+ 0,74% PrimaryLogPG::find_object_context
0,66% PrimaryLogPG::OpContext::OpContext
0,58% OpRequest::mark_flag_point
0,56% OpRequest::mark_flag_point
+ 0,81% Mutex::Unlock
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment