osd: dout latency info in filestore

dout more latency info for each seq in filestore, this is useful for
tracking io request.

Signed-off-by: Xinze Chi <xmdxcxz@gmail.com>

diff --git a/src/os/FileStore.cc b/src/os/FileStore.cc
index 1e6ac23dbd69a71c5b4fc9c4aa63e37ec4c5d658..36c1cbed4f6d046c615ae133e152869028cea6f1 100644 (file)
--- a/src/os/FileStore.cc
+++ b/src/os/FileStore.cc
@@ -1810,14 +1810,15 @@ void FileStore::_finish_op(OpSequencer *osr)
   list<Context*> to_queue;
   Op *o = osr->dequeue(&to_queue);
   
-  dout(10) << "_finish_op " << o << " seq " << o->op << " " << *osr << "/" << osr->parent << dendl;
+  utime_t lat = ceph_clock_now(g_ceph_context);
+  lat -= o->start;
+
+  dout(10) << "_finish_op " << o << " seq " << o->op << " " << *osr << "/" << osr->parent << " lat " << lat << dendl;
   osr->apply_lock.Unlock();  // locked in _do_op
 
   // called with tp lock held
   op_queue_release_throttle(o);
 
-  utime_t lat = ceph_clock_now(g_ceph_context);
-  lat -= o->start;
   logger->tinc(l_os_apply_lat, lat);
 
   if (o->onreadable_sync) {

diff --git a/src/os/KeyValueStore.cc b/src/os/KeyValueStore.cc
index a1c02608af7b9b7a664ccbf55445c1e843946303..919dcee8697ce0ae5a1e4adbbe2b0f984381191c 100644 (file)
--- a/src/os/KeyValueStore.cc
+++ b/src/os/KeyValueStore.cc
@@ -1127,12 +1127,13 @@ void KeyValueStore::_finish_op(OpSequencer *osr)
   list<Context*> to_queue;
   Op *o = osr->dequeue(&to_queue);
 
-  dout(10) << "_finish_op " << o << " seq " << o->op << " " << *osr << "/" << osr->parent << dendl;
+  utime_t lat = ceph_clock_now(g_ceph_context);
+  lat -= o->start;
+
+  dout(10) << "_finish_op " << o << " seq " << o->op << " " << *osr << "/" << osr->parent << " lat " << lat << dendl;
   osr->apply_lock.Unlock();  // locked in _do_op
   op_queue_release_throttle(o);
 
-  utime_t lat = ceph_clock_now(g_ceph_context);
-  lat -= o->start;
   perf_logger->tinc(l_os_commit_lat, lat);
   perf_logger->tinc(l_os_apply_lat, lat);