Skip to content

Instantly share code, notes, and snippets.

@rzarzynski

rzarzynski/reference_43b88419d4f87da514721848d28fe949cf0ecb9e.txt

Last active January 4, 2018 22:52
Show Gist options
  • Save rzarzynski/916ef92669950148b45659d2fb404bcb to your computer and use it in GitHub Desktop.
Save rzarzynski/916ef92669950148b45659d2fb404bcb to your computer and use it in GitHub Desktop.
Download ZIP
wip-bs-async-read-rebased: profilling of the sync read path
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=11881: Thu Jan 4 23:25:27 2018
read: IOPS=25.3k, BW=98.0MiB/s (104MB/s)(5939MiB/60002msec)
slat (nsec): min=1000, max=7019.8k, avg=7565.57, stdev=28274.55
clat (usec): min=31, max=99654, avg=1254.29, stdev=778.99
lat (usec): min=128, max=99655, avg=1261.86, stdev=778.78
clat percentiles (usec):
| 1.00th=[ 351], 5.00th=[ 537], 10.00th=[ 660], 20.00th=[ 824],
| 30.00th=[ 947], 40.00th=[ 1045], 50.00th=[ 1139], 60.00th=[ 1254],
| 70.00th=[ 1385], 80.00th=[ 1565], 90.00th=[ 1926], 95.00th=[ 2343],
| 99.00th=[ 3425], 99.50th=[ 3982], 99.90th=[ 5473], 99.95th=[ 6390],
| 99.99th=[20841]
bw ( KiB/s): min=59704, max=108104, per=99.99%, avg=101350.81, stdev=6159.38, samples=120
iops : min=14926, max=27026, avg=25337.69, stdev=1539.85, samples=120
lat (usec) : 50=0.01%, 100=0.01%, 250=0.16%, 500=3.77%, 750=11.00%
lat (usec) : 1000=20.55%
lat (msec) : 2=55.60%, 4=8.43%, 10=0.46%, 20=0.01%, 50=0.01%
lat (msec) : 100=0.01%
cpu : usr=41.09%, sys=28.60%, ctx=1794030, 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=1520499,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=98.0MiB/s (104MB/s), 98.0MiB/s-98.0MiB/s (104MB/s-104MB/s), io=5939MiB (6228MB), run=60002-60002msec
Disk stats (read/write):
nvme0n1: ios=262444/2578, merge=0/194, ticks=17888/83160, in_queue=101220, util=18.11%
==========================================================================================
CPU cycles (perf)
- 39,43% 0,05% tp_osd_tp ceph-osd [.] PGOpItem::run
- 39,39% PGOpItem::run
- 38,70% OSD::dequeue_op
- 36,97% PrimaryLogPG::do_request
- 35,43% PrimaryLogPG::do_op
- 22,94% PrimaryLogPG::execute_ctx
- 10,41% PrimaryLogPG::prepare_transaction
- 10,21% PrimaryLogPG::do_osd_ops
- 7,77% PrimaryLogPG::do_read
- 7,64% ReplicatedBackend::objects_read_sync
- 7,43% BlueStore::read
- 4,91% BlueStore::_do_read
1,45% BlueStore::BufferSpace::read
- 1,13% bluestore_blob_t::map
- 1,11% 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
- KernelDevice::read
+ 0,95% __GI___libc_pread64
+ 1,43% RWLock::get_read
0,53% BlueStore::Collection::get_onode
+ 1,88% md_config_t::get_val<bool>
+ 7,33% PrimaryLogPG::complete_read_ctx
+ 1,55% PrimaryLogPG::close_op_ctx
+ 0,78% PrimaryLogPG::do_osd_op_effects
+ 1,97% PrimaryLogPG::maybe_await_blocked_head
1,68% MOSDOp::finish_decode
+ 1,49% std::__cxx11::basic_ostringstream<char, std::char_traits<char>, std::allocator<char> >::basic_ostringstream
0,89% PG::op_has_sufficient_caps
+ 0,84% PrimaryLogPG::find_object_context
0,74% PrimaryLogPG::OpContext::OpContext
+ 0,62% OpRequest::mark_flag_point
0,55% Connection::get_priv
+ 0,65% OpRequest::mark_flag_point
0,54% Connection::get_priv
0,63% Mu
tex::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=1563: Thu Jan 4 22:36:31 2018
read: IOPS=21.5k, BW=83.8MiB/s (87.9MB/s)(5030MiB/60002msec)
slat (nsec): min=991, max=5377.8k, avg=7995.13, stdev=37270.86
clat (usec): min=121, max=39030, avg=1481.98, stdev=941.24
lat (usec): min=133, max=41810, avg=1489.97, stdev=941.06
clat percentiles (usec):
| 1.00th=[ 359], 5.00th=[ 553], 10.00th=[ 693], 20.00th=[ 881],
| 30.00th=[ 1020], 40.00th=[ 1156], 50.00th=[ 1287], 60.00th=[ 1434],
| 70.00th=[ 1614], 80.00th=[ 1909], 90.00th=[ 2474], 95.00th=[ 3032],
| 99.00th=[ 4686], 99.50th=[ 5604], 99.90th=[ 9110], 99.95th=[11469],
| 99.99th=[23462]
bw ( KiB/s): min=32808, max=99040, per=99.98%, avg=85827.54, stdev=9656.14, samples=120
iops : min= 8202, max=24760, avg=21456.85, stdev=2414.05, samples=120
lat (usec) : 250=0.16%, 500=3.35%, 750=9.02%, 1000=15.76%
lat (msec) : 2=53.90%, 4=16.01%, 10=1.72%, 20=0.06%, 50=0.01%
cpu : usr=38.71%, sys=28.27%, ctx=1537840, 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=1287764,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=83.8MiB/s (87.9MB/s), 83.8MiB/s-83.8MiB/s (87.9MB/s-87.9MB/s), io=5030MiB (5275MB), run=60002-60002msec
Disk stats (read/write):
nvme0n1: ios=263384/4101, merge=0/218, ticks=18448/87672, in_queue=106516, util=20.82%
==========================================================================================
CPU cycles (perf)
- 43,03% 0,06% tp_osd_tp ceph-osd [.] PGOpItem::run
- 42,97% PGOpItem::run
- 42,10% OSD::dequeue_op
- 39,88% PrimaryLogPG::do_request
- 38,18% PrimaryLogPG::do_op
- 24,29% PrimaryLogPG::execute_ctx
- 11,54% PrimaryLogPG::prepare_transaction
- 11,37% PrimaryLogPG::do_osd_ops
- 8,93% PrimaryLogPG::do_read
- 8,75% ReplicatedBackend::objects_read_sync
- 8,53% BlueStore::read
- 6,05% BlueStore::_do_read
- 2,71% BlueStore::_consult_cache
1,36% BlueStore::BufferSpace::read
+ 1,72% BlueStore::PlainRegionReader::issue_io
+ 1,32% RWLock::get_read
+ 0,56% BlueStore::Collection::get_onode
+ 1,90% md_config_t::get_val<bool>
+ 6,94% PrimaryLogPG::complete_read_ctx
+ 1,55% PrimaryLogPG::close_op_ctx
+ 0,96% PrimaryLogPG::do_osd_op_effects
+ 0,59% ObjectContext::ondisk_read_unlock
+ 0,59% Mutex::Unlock
0,53% MOSDOpReply::MOSDOpReply
+ 2,45% PrimaryLogPG::maybe_await_blocked_head
1,69% MOSDOp::finish_decode
+ 1,43% std::__cxx11::basic_ostringstream<char, std::char_traits<char>, std::allocator<char> >::basic_ostringstream
+ 1,01% PrimaryLogPG::find_object_context
1,01% PG::op_has_sufficient_caps
0,85% PrimaryLogPG::OpContext::OpContext
0,82% Connection::get_priv
+ 0,78% OpRequest::mark_flag_point
0,54% PrimaryLogPG::get_rw_locks
0,64% Connection::get_priv
0,81% Connection::get_priv
+ 0,80% 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