diff --git a/src/os/filestore/FileStore.cc b/src/os/filestore/FileStore.cc index 1fb4839455e..39caf0a25a6 100644 --- a/src/os/filestore/FileStore.cc +++ b/src/os/filestore/FileStore.cc @@ -629,6 +629,7 @@ FileStore::FileStore(CephContext* cct, const std::string &base, plb.add_time_avg(l_filestore_commitcycle_latency, "commitcycle_latency", "Average latency of commit"); plb.add_u64_counter(l_filestore_journal_full, "journal_full", "Journal writes while full"); plb.add_time_avg(l_filestore_queue_transaction_latency_avg, "queue_transaction_latency_avg", "Store operation queue latency"); + plb.add_time(l_filestore_sync_pause_max_lat, "sync_pause_max_latency", "Max latency of op_wq pause before syncfs"); logger = plb.create_perf_counters(); @@ -4010,8 +4011,7 @@ void FileStore::sync_entry() } dout(20) << " done waiting for checkpoint " << cid << " to complete" << dendl; } - } else - { + } else { apply_manager.commit_started(); op_tp.unpause(); @@ -4043,6 +4043,10 @@ void FileStore::sync_entry() utime_t lat = done - start; utime_t dur = done - startwait; dout(10) << __FUNC__ << ": commit took " << lat << ", interval was " << dur << dendl; + utime_t max_pause_lat = logger->tget(l_filestore_sync_pause_max_lat); + if (max_pause_lat == utime_t() || max_pause_lat < dur - lat) { + logger->tinc(l_filestore_sync_pause_max_lat, dur - lat); + } logger->inc(l_filestore_commitcycle); logger->tinc(l_filestore_commitcycle_latency, lat); diff --git a/src/os/filestore/FileStore.h b/src/os/filestore/FileStore.h index 88a1d3170d0..b99316f78d5 100644 --- a/src/os/filestore/FileStore.h +++ b/src/os/filestore/FileStore.h @@ -94,6 +94,7 @@ enum { l_filestore_bytes, l_filestore_apply_latency, l_filestore_queue_transaction_latency_avg, + l_filestore_sync_pause_max_lat, l_filestore_last, }; diff --git a/src/osd/OSD.cc b/src/osd/OSD.cc index 142f3b2aa84..07ae5c8396a 100644 --- a/src/osd/OSD.cc +++ b/src/osd/OSD.cc @@ -2948,6 +2948,11 @@ void OSD::create_logger() l_osd_op_rw_prepare_lat, "op_rw_prepare_latency", "Latency of read-modify-write operations (excluding queue time and wait for finished)"); + osd_plb.add_time_avg(l_osd_op_before_queue_op_lat, "op_before_queue_op_lat", + "Latency of IO before calling queue(before really queue into ShardedOpWq)"); // client io before queue op_wq latency + osd_plb.add_time_avg(l_osd_op_before_dequeue_op_lat, "op_before_dequeue_op_lat", + "Latency of IO before calling dequeue_op(already dequeued and get PG lock)"); // client io before dequeue_op latency + osd_plb.add_u64_counter( l_osd_sop, "subop", "Suboperations"); osd_plb.add_u64_counter( @@ -9195,6 +9200,7 @@ void OSD::enqueue_op(spg_t pg, OpRequestRef& op, epoch_t epoch) op->osd_trace.keyval("priority", op->get_req()->get_priority()); op->osd_trace.keyval("cost", op->get_req()->get_cost()); op->mark_queued_for_pg(); + logger->tinc(l_osd_op_before_queue_op_lat, latency); op_shardedwq.queue(make_pair(pg, PGQueueable(op, epoch))); } @@ -9219,6 +9225,8 @@ void OSD::dequeue_op( << " " << *(op->get_req()) << " pg " << *pg << dendl; + logger->tinc(l_osd_op_before_dequeue_op_lat, latency); + Session *session = static_cast( op->get_req()->get_connection()->get_priv()); if (session) { diff --git a/src/osd/OSD.h b/src/osd/OSD.h index e5edaccc281..03b56735ec5 100644 --- a/src/osd/OSD.h +++ b/src/osd/OSD.h @@ -94,6 +94,9 @@ enum { l_osd_op_rw_process_lat, l_osd_op_rw_prepare_lat, + l_osd_op_before_queue_op_lat, + l_osd_op_before_dequeue_op_lat, + l_osd_sop, l_osd_sop_inb, l_osd_sop_lat,