osd, messenger, librados: lttng enhancements

Few critical functions have been instrumented with function tracing
and oid tracing calls to help routing performance analysis.
Oid tracing events are heavily dependent on functional changes and may need
to be revised as and when core data flow logic changes.

Signed-off-by: Anjaneya Chagam <anjaneya.chagam@intel.com>

diff --git a/src/librados/CMakeLists.txt b/src/librados/CMakeLists.txt
index da9207e1a9782117ab508d8f421d80a063d4cedd..d8b48256e94a0ae860e601db77179aa597d7b283 100644 (file)
--- a/src/librados/CMakeLists.txt
+++ b/src/librados/CMakeLists.txt
@@ -40,3 +40,6 @@ if(WITH_EMBEDDED)
     $<TARGET_OBJECTS:librados_api_obj>
     $<TARGET_OBJECTS:librados_objs>)
 endif()
+if(WITH_LTTNG AND WITH_EVENTTRACE)
+  add_dependencies(librados_api_obj eventtrace_tp)
+endif()

diff --git a/src/librados/IoCtxImpl.cc b/src/librados/IoCtxImpl.cc
index 33cfc6d2327d5cacb9744f649a9782dcc67ea13a..b4185fdc3919afe85bc617999453e393ef0e1da8 100644 (file)
--- a/src/librados/IoCtxImpl.cc
+++ b/src/librados/IoCtxImpl.cc
@@ -21,6 +21,7 @@
 #include "librados/RadosClient.h"
 #include "include/assert.h"
 #include "common/valgrind.h"
+#include "common/EventTrace.h"
 
 #define dout_subsys ceph_subsys_rados
 #undef dout_prefix
@@ -803,8 +804,12 @@ int librados::IoCtxImpl::aio_operate_read(const object_t &oid,
                                          int flags,
                                          bufferlist *pbl)
 {
+  FUNCTRACE();
   Context *onack = new C_aio_Complete(c);
 
+#if defined(WITH_LTTNG) && defined(WITH_EVENTTRACE)
+  ((C_aio_Complete *) onack)->oid = oid;
+#endif
   c->is_read = true;
   c->io = this;
 
@@ -819,12 +824,17 @@ int librados::IoCtxImpl::aio_operate(const object_t& oid,
                                     ::ObjectOperation *o, AioCompletionImpl *c,
                                     const SnapContext& snap_context, int flags)
 {
+  FUNCTRACE();
+  OID_EVENT_TRACE(oid.name.c_str(), "RADOS_WRITE_OP_BEGIN");
   auto ut = ceph::real_clock::now();
   /* can't write to a snapshot */
   if (snap_seq != CEPH_NOSNAP)
     return -EROFS;
 
   Context *onack = new C_aio_Complete(c);
+#if defined(WITH_LTTNG) && defined(WITH_EVENTTRACE)
+  ((C_aio_Complete *) onack)->oid = oid;
+#endif
 
   c->io = this;
   queue_aio_write(c);
@@ -841,11 +851,16 @@ int librados::IoCtxImpl::aio_read(const object_t oid, AioCompletionImpl *c,
                                  bufferlist *pbl, size_t len, uint64_t off,
                                  uint64_t snapid)
 {
+  FUNCTRACE();
   if (len > (size_t) INT_MAX)
     return -EDOM;
 
+  OID_EVENT_TRACE(oid.name.c_str(), "RADOS_READ_OP_BEGIN");
   Context *onack = new C_aio_Complete(c);
 
+#if defined(WITH_LTTNG) && defined(WITH_EVENTTRACE)
+  ((C_aio_Complete *) onack)->oid = oid;
+#endif
   c->is_read = true;
   c->io = this;
   c->blp = pbl;
@@ -862,11 +877,16 @@ int librados::IoCtxImpl::aio_read(const object_t oid, AioCompletionImpl *c,
                                  char *buf, size_t len, uint64_t off,
                                  uint64_t snapid)
 {
+  FUNCTRACE();
   if (len > (size_t) INT_MAX)
     return -EDOM;
 
+  OID_EVENT_TRACE(oid.name.c_str(), "RADOS_READ_OP_BEGIN");
   Context *onack = new C_aio_Complete(c);
 
+#if defined(WITH_LTTNG) && defined(WITH_EVENTTRACE)
+  ((C_aio_Complete *) onack)->oid = oid;
+#endif
   c->is_read = true;
   c->io = this;
   c->bl.clear();
@@ -899,12 +919,16 @@ int librados::IoCtxImpl::aio_sparse_read(const object_t oid,
                                         bufferlist *data_bl, size_t len,
                                         uint64_t off, uint64_t snapid)
 {
+  FUNCTRACE();
   if (len > (size_t) INT_MAX)
     return -EDOM;
 
   Context *nested = new C_aio_Complete(c);
   C_ObjectOperation *onack = new C_ObjectOperation(nested);
 
+#if defined(WITH_LTTNG) && defined(WITH_EVENTTRACE)
+  ((C_aio_Complete *) nested)->oid = oid;
+#endif
   c->is_read = true;
   c->io = this;
 
@@ -922,8 +946,10 @@ int librados::IoCtxImpl::aio_write(const object_t &oid, AioCompletionImpl *c,
                                   const bufferlist& bl, size_t len,
                                   uint64_t off)
 {
+  FUNCTRACE();
   auto ut = ceph::real_clock::now();
   ldout(client->cct, 20) << "aio_write " << oid << " " << off << "~" << len << " snapc=" << snapc << " snap_seq=" << snap_seq << dendl;
+  OID_EVENT_TRACE(oid.name.c_str(), "RADOS_WRITE_OP_BEGIN");
 
   if (len > UINT_MAX/2)
     return -E2BIG;
@@ -933,6 +959,9 @@ int librados::IoCtxImpl::aio_write(const object_t &oid, AioCompletionImpl *c,
 
   Context *onack = new C_aio_Complete(c);
 
+#if defined(WITH_LTTNG) && defined(WITH_EVENTTRACE)
+  ((C_aio_Complete *) onack)->oid = oid;
+#endif
   c->io = this;
   queue_aio_write(c);
 
@@ -948,6 +977,7 @@ int librados::IoCtxImpl::aio_write(const object_t &oid, AioCompletionImpl *c,
 int librados::IoCtxImpl::aio_append(const object_t &oid, AioCompletionImpl *c,
                                    const bufferlist& bl, size_t len)
 {
+  FUNCTRACE();
   auto ut = ceph::real_clock::now();
 
   if (len > UINT_MAX/2)
@@ -957,6 +987,9 @@ int librados::IoCtxImpl::aio_append(const object_t &oid, AioCompletionImpl *c,
     return -EROFS;
 
   Context *onack = new C_aio_Complete(c);
+#if defined(WITH_LTTNG) && defined(WITH_EVENTTRACE)
+  ((C_aio_Complete *) onack)->oid = oid;
+#endif
 
   c->io = this;
   queue_aio_write(c);
@@ -974,6 +1007,7 @@ int librados::IoCtxImpl::aio_write_full(const object_t &oid,
                                        AioCompletionImpl *c,
                                        const bufferlist& bl)
 {
+  FUNCTRACE();
   auto ut = ceph::real_clock::now();
 
   if (bl.length() > UINT_MAX/2)
@@ -983,6 +1017,9 @@ int librados::IoCtxImpl::aio_write_full(const object_t &oid,
     return -EROFS;
 
   Context *onack = new C_aio_Complete(c);
+#if defined(WITH_LTTNG) && defined(WITH_EVENTTRACE)
+  ((C_aio_Complete *) onack)->oid = oid;
+#endif
 
   c->io = this;
   queue_aio_write(c);
@@ -1002,6 +1039,7 @@ int librados::IoCtxImpl::aio_writesame(const object_t &oid,
                                       size_t write_len,
                                       uint64_t off)
 {
+  FUNCTRACE();
   auto ut = ceph::real_clock::now();
 
   if ((bl.length() > UINT_MAX/2) || (write_len > UINT_MAX/2))
@@ -1014,6 +1052,9 @@ int librados::IoCtxImpl::aio_writesame(const object_t &oid,
 
   Context *onack = new C_aio_Complete(c);
 
+#if defined(WITH_LTTNG) && defined(WITH_EVENTTRACE)
+  ((C_aio_Complete *) onack)->oid = oid;
+#endif
   c->io = this;
   queue_aio_write(c);
 
@@ -1029,6 +1070,7 @@ int librados::IoCtxImpl::aio_writesame(const object_t &oid,
 
 int librados::IoCtxImpl::aio_remove(const object_t &oid, AioCompletionImpl *c, int flags)
 {
+  FUNCTRACE();
   auto ut = ceph::real_clock::now();
 
   /* can't write to a snapshot */
@@ -1037,6 +1079,9 @@ int librados::IoCtxImpl::aio_remove(const object_t &oid, AioCompletionImpl *c, i
 
   Context *onack = new C_aio_Complete(c);
 
+#if defined(WITH_LTTNG) && defined(WITH_EVENTTRACE)
+  ((C_aio_Complete *) onack)->oid = oid;
+#endif
   c->io = this;
   queue_aio_write(c);
 
@@ -1296,8 +1341,12 @@ int librados::IoCtxImpl::aio_exec(const object_t& oid, AioCompletionImpl *c,
                                  const char *cls, const char *method,
                                  bufferlist& inbl, bufferlist *outbl)
 {
+  FUNCTRACE();
   Context *onack = new C_aio_Complete(c);
 
+#if defined(WITH_LTTNG) && defined(WITH_EVENTTRACE)
+  ((C_aio_Complete *) onack)->oid = oid;
+#endif
   c->is_read = true;
   c->io = this;
 
@@ -1314,8 +1363,12 @@ int librados::IoCtxImpl::aio_exec(const object_t& oid, AioCompletionImpl *c,
                                  const char *cls, const char *method,
                                  bufferlist& inbl, char *buf, size_t out_len)
 {
+  FUNCTRACE();
   Context *onack = new C_aio_Complete(c);
 
+#if defined(WITH_LTTNG) && defined(WITH_EVENTTRACE)
+  ((C_aio_Complete *) onack)->oid = oid;
+#endif
   c->is_read = true;
   c->io = this;
   c->bl.clear();
@@ -1337,6 +1390,7 @@ int librados::IoCtxImpl::read(const object_t& oid,
 {
   if (len > (size_t) INT_MAX)
     return -EDOM;
+  OID_EVENT_TRACE(oid.name.c_str(), "RADOS_READ_OP_BEGIN");
 
   ::ObjectOperation rd;
   prepare_assert_ops(&rd);
@@ -1904,6 +1958,9 @@ void librados::IoCtxImpl::C_aio_Complete::finish(int r)
     c->io->complete_aio_write(c);
   }
 
+#if defined(WITH_LTTNG) && defined(WITH_EVENTTRACE)
+  OID_EVENT_TRACE(oid.name.c_str(), "RADOS_OP_COMPLETE");
+#endif
   c->put_unlock();
 }
 

diff --git a/src/librados/IoCtxImpl.h b/src/librados/IoCtxImpl.h
index 0b8fa8605cafc351d55b413f1ca27fd6f64b73ae..97af6b32591f80f8797fc12bbe630e847e987b7a 100644 (file)
--- a/src/librados/IoCtxImpl.h
+++ b/src/librados/IoCtxImpl.h
@@ -178,6 +178,9 @@ struct librados::IoCtxImpl {
   };
 
   struct C_aio_Complete : public Context {
+#if defined(WITH_LTTNG) && defined(WITH_EVENTTRACE)
+    object_t oid;
+#endif
     AioCompletionImpl *c;
     explicit C_aio_Complete(AioCompletionImpl *_c);
     void finish(int r);

diff --git a/src/librados/RadosClient.cc b/src/librados/RadosClient.cc
index 90b1b1048a04c9295baf6a6286b7f4d517409e7d..2045516eafe6dfbad16d49f94a4856860bba0920 100644 (file)
--- a/src/librados/RadosClient.cc
+++ b/src/librados/RadosClient.cc
@@ -47,6 +47,7 @@
 #include "RadosClient.h"
 
 #include "include/assert.h"
+#include "common/EventTrace.h"
 
 #define dout_subsys ceph_subsys_rados
 #undef dout_prefix

diff --git a/src/msg/async/AsyncConnection.cc b/src/msg/async/AsyncConnection.cc
index fc4b75197cf2c16da4fa3ff1d0d6a1dca7383ba0..9125ac3f6080db3958be88f4568000c826085ea5 100644 (file)
--- a/src/msg/async/AsyncConnection.cc
+++ b/src/msg/async/AsyncConnection.cc
@@ -21,6 +21,10 @@
 #include "AsyncMessenger.h"
 #include "AsyncConnection.h"
 
+#include "messages/MOSDOp.h"
+#include "messages/MOSDOpReply.h"
+#include "common/EventTrace.h"
+
 // Constant to limit starting sequence number to 2^31.  Nothing special about it, just a big number.  PLR
 #define SEQ_MASK  0x7fffffff 
 
@@ -324,6 +328,9 @@ void AsyncConnection::process()
 {
   ssize_t r = 0;
   int prev_state = state;
+#ifdef WITH_LTTNG
+  utime_t ltt_recv_stamp = ceph_clock_now();
+#endif
   bool need_dispatch_writer = false;
   std::lock_guard<std::mutex> l(lock);
   last_active = ceph::coarse_mono_clock::now();
@@ -425,6 +432,9 @@ void AsyncConnection::process()
 
       case STATE_OPEN_MESSAGE_HEADER:
         {
+#ifdef WITH_LTTNG
+          ltt_recv_stamp = ceph_clock_now();
+#endif
           ldout(async_msgr->cct, 20) << __func__ << " begin MSG" << dendl;
           ceph_msg_header header;
           ceph_msg_header_old oldheader;
@@ -740,6 +750,18 @@ void AsyncConnection::process()
 
           message->set_connection(this);
 
+#if defined(WITH_LTTNG) && defined(WITH_EVENTTRACE)
+          if (message->get_type() == CEPH_MSG_OSD_OP || message->get_type() == CEPH_MSG_OSD_OPREPLY) {
+            utime_t ltt_processed_stamp = ceph_clock_now();
+            double usecs_elapsed = (ltt_processed_stamp.to_nsec()-ltt_recv_stamp.to_nsec())/1000;
+            ostringstream buf;
+            if (message->get_type() == CEPH_MSG_OSD_OP)
+              OID_ELAPSED_WITH_MSG(message, usecs_elapsed, "TIME_TO_DECODE_OSD_OP", false);
+            else
+              OID_ELAPSED_WITH_MSG(message, usecs_elapsed, "TIME_TO_DECODE_OSD_OPREPLY", false);
+          }
+#endif
+
           // note last received message.
           in_seq.set(message->get_seq());
          ldout(async_msgr->cct, 5) << " rx " << message->get_source() << " seq "
@@ -1850,6 +1872,7 @@ void AsyncConnection::accept(ConnectedSocket socket, entity_addr_t &addr)
 
 int AsyncConnection::send_message(Message *m)
 {
+  FUNCTRACE();
   lgeneric_subdout(async_msgr->cct, ms,
                   1) << "-- " << async_msgr->get_myaddr() << " --> "
                      << get_peer_addr() << " -- "
@@ -1864,6 +1887,11 @@ int AsyncConnection::send_message(Message *m)
   m->get_header().src = async_msgr->get_myname();
   m->set_connection(this);
 
+  if (m->get_type() == CEPH_MSG_OSD_OP)
+    OID_EVENT_TRACE_WITH_MSG(m, "SEND_MSG_OSD_OP_BEGIN", true);
+  else if (m->get_type() == CEPH_MSG_OSD_OPREPLY)
+    OID_EVENT_TRACE_WITH_MSG(m, "SEND_MSG_OSD_OPREPLY_BEGIN", true);
+
   if (async_msgr->get_myaddr() == get_peer_addr()) { //loopback connection
     ldout(async_msgr->cct, 20) << __func__ << " " << *m << " local" << dendl;
     std::lock_guard<std::mutex> l(write_lock);
@@ -2147,6 +2175,7 @@ void AsyncConnection::prepare_send_message(uint64_t features, Message *m, buffer
 
 ssize_t AsyncConnection::write_message(Message *m, bufferlist& bl, bool more)
 {
+  FUNCTRACE();
   assert(can_write == WriteStatus::CANWRITE);
   m->set_seq(out_seq.inc());
 
@@ -2242,6 +2271,10 @@ ssize_t AsyncConnection::write_message(Message *m, bufferlist& bl, bool more)
   } else {
     ldout(async_msgr->cct, 10) << __func__ << " sending " << m << " continuely." << dendl;
   }
+  if (m->get_type() == CEPH_MSG_OSD_OP)
+    OID_EVENT_TRACE_WITH_MSG(m, "SEND_MSG_OSD_OP_END", false);
+  else if (m->get_type() == CEPH_MSG_OSD_OPREPLY)
+    OID_EVENT_TRACE_WITH_MSG(m, "SEND_MSG_OSD_OPREPLY_END", false);
   m->put();
 
   return rc;

diff --git a/src/msg/async/AsyncMessenger.cc b/src/msg/async/AsyncMessenger.cc
index 5a8d107117b81617186a1905df13ce244f2bac26..21dd0b641946f3b305ad03bac1cfd57d3c997b59 100644 (file)
--- a/src/msg/async/AsyncMessenger.cc
+++ b/src/msg/async/AsyncMessenger.cc
@@ -25,6 +25,10 @@
 #include "common/Timer.h"
 #include "common/errno.h"
 
+#include "messages/MOSDOp.h"
+#include "messages/MOSDOpReply.h"
+#include "common/EventTrace.h"
+
 #define dout_subsys ceph_subsys_ms
 #undef dout_prefix
 #define dout_prefix _prefix(_dout, this)
@@ -500,6 +504,12 @@ ConnectionRef AsyncMessenger::get_loopback_connection()
 
 int AsyncMessenger::_send_message(Message *m, const entity_inst_t& dest)
 {
+  FUNCTRACE();
+  if (m && m->get_type() == CEPH_MSG_OSD_OP)
+    OID_EVENT_TRACE(((MOSDOp *)m)->get_oid().name.c_str(), "SEND_MSG_OSD_OP");
+  else if (m && m->get_type() == CEPH_MSG_OSD_OPREPLY)
+    OID_EVENT_TRACE(((MOSDOpReply *)m)->get_oid().name.c_str(), "SEND_MSG_OSD_OP_REPLY");
+
   ldout(cct, 1) << __func__ << "--> " << dest.name << " "
       << dest.addr << " -- " << *m << " -- ?+"
       << m->get_data().length() << " " << m << dendl;

diff --git a/src/os/CMakeLists.txt b/src/os/CMakeLists.txt
index f751f97ed038e14ecc3b0519756f2547c70d16dd..b86261c7c393b881e2b07d79d4481bc39b6fe63b 100644 (file)
--- a/src/os/CMakeLists.txt
+++ b/src/os/CMakeLists.txt
@@ -113,3 +113,7 @@ if(WITH_SPDK)
     list(APPEND SPDK_LIBRARIES spdk_${lib})
   endforeach()
 endif(WITH_SPDK)
+
+if(WITH_LTTNG AND WITH_EVENTTRACE)
+  add_dependencies(os eventtrace_tp)
+endif()

diff --git a/src/os/bluestore/BlockDevice.cc b/src/os/bluestore/BlockDevice.cc
index f43914fa2889ea76fa6b1c4e6a08aca4f4ccf89f..f0d6b4d7384393640b6c29c3333323f4edbb0fbc 100644 (file)
--- a/src/os/bluestore/BlockDevice.cc
+++ b/src/os/bluestore/BlockDevice.cc
@@ -23,6 +23,7 @@
 #endif
 
 #include "common/debug.h"
+#include "common/EventTrace.h"
 
 #define dout_context cct
 #define dout_subsys ceph_subsys_bdev

diff --git a/src/os/bluestore/BlueStore.cc b/src/os/bluestore/BlueStore.cc
index 9eb88409e460695ef846e09efd86788fa5e91346..6cd3f290159c4efaba32c151a9708538968bb8cf 100644 (file)
--- a/src/os/bluestore/BlueStore.cc
+++ b/src/os/bluestore/BlueStore.cc
@@ -29,6 +29,7 @@
 #include "BlueFS.h"
 #include "BlueRocksEnv.h"
 #include "auth/Crypto.h"
+#include "common/EventTrace.h"
 
 #define dout_context cct
 #define dout_subsys ceph_subsys_bluestore
@@ -5071,6 +5072,7 @@ int BlueStore::_do_read(
   bufferlist& bl,
   uint32_t op_flags)
 {
+  FUNCTRACE();
   boost::intrusive::set<Extent>::iterator ep, eend;
   int r = 0;
 
@@ -6986,6 +6988,7 @@ int BlueStore::queue_transactions(
     TrackedOpRef op,
     ThreadPool::TPHandle *handle)
 {
+  FUNCTRACE();
   Context *onreadable;
   Context *ondisk;
   Context *onreadable_sync;

diff --git a/src/os/bluestore/BlueStore.h b/src/os/bluestore/BlueStore.h
index d74f9256d01a48fba7799376e033c96b15a305c4..c7a9f3348a49e1d5333055c2839e26fa5f746dfe 100644 (file)
--- a/src/os/bluestore/BlueStore.h
+++ b/src/os/bluestore/BlueStore.h
@@ -39,6 +39,8 @@
 
 #include "bluestore_types.h"
 #include "BlockDevice.h"
+#include "common/EventTrace.h"
+
 class Allocator;
 class FreelistManager;
 class BlueFS;
@@ -1205,10 +1207,36 @@ public:
       return "???";
     }
 
+#if defined(WITH_LTTNG) && defined(WITH_EVENTTRACE)
+    const char *get_state_latency_name(int state) {
+      switch (state) {
+      case l_bluestore_state_prepare_lat: return "prepare";
+      case l_bluestore_state_aio_wait_lat: return "aio_wait";
+      case l_bluestore_state_io_done_lat: return "io_done";
+      case l_bluestore_state_kv_queued_lat: return "kv_queued";
+      case l_bluestore_state_kv_committing_lat: return "kv_committing";
+      case l_bluestore_state_kv_done_lat: return "kv_done";
+      case l_bluestore_state_wal_queued_lat: return "wal_queued";
+      case l_bluestore_state_wal_applying_lat: return "wal_applying";
+      case l_bluestore_state_wal_aio_wait_lat: return "wal_aio_wait";
+      case l_bluestore_state_wal_cleanup_lat: return "wal_cleanup";
+      case l_bluestore_state_finishing_lat: return "finishing";
+      case l_bluestore_state_done_lat: return "done";
+      }
+      return "???";
+    }
+#endif
+
     void log_state_latency(PerfCounters *logger, int state) {
       utime_t lat, now = ceph_clock_now();
       lat = now - last_stamp;
       logger->tinc(state, lat);
+#if defined(WITH_LTTNG) && defined(WITH_EVENTTRACE)
+      if (state >= l_bluestore_state_prepare_lat && state <= l_bluestore_state_done_lat) {
+        double usecs = (now.to_nsec()-last_stamp.to_nsec())/1000;
+        OID_ELAPSED("", usecs, get_state_latency_name(state));
+      }
+#endif
       last_stamp = now;
     }
 

diff --git a/src/osd/CMakeLists.txt b/src/osd/CMakeLists.txt
index ee64f89c040fd4b12820d1e225924077bd339a43..c817e724980e44fe3a410453e34591451051dc59 100644 (file)
--- a/src/osd/CMakeLists.txt
+++ b/src/osd/CMakeLists.txt
@@ -38,3 +38,6 @@ target_link_libraries(osd ${LEVELDB_LIBRARIES} ${CMAKE_DL_LIBS} ${ALLOC_LIBS})
 if(WITH_LTTNG)
   add_dependencies(osd oprequest-tp osd-tp pg-tp)
 endif()
+if(WITH_LTTNG AND WITH_EVENTTRACE)
+  add_dependencies(osd eventtrace_tp)
+endif()

diff --git a/src/osd/OSD.cc b/src/osd/OSD.cc
index 0347b15117d991c19abbba8362cb812243381946..a1f2acc919346d2680db5f1ed5d457e4bcafa0c0 100644 (file)
--- a/src/osd/OSD.cc
+++ b/src/osd/OSD.cc
@@ -138,6 +138,7 @@
 
 #include "include/assert.h"
 #include "common/config.h"
+#include "common/EventTrace.h"
 
 #ifdef WITH_LTTNG
 #define TRACEPOINT_DEFINE
@@ -1443,6 +1444,7 @@ void OSDService::handle_misdirected_op(PG *pg, OpRequestRef op)
 
 void OSDService::dequeue_pg(PG *pg, list<OpRequestRef> *dequeued)
 {
+  FUNCTRACE();
   if (dequeued)
     osd->op_shardedwq.dequeue_and_get_ops(pg, dequeued);
   else
@@ -4766,6 +4768,7 @@ void OSD::RemoveWQ::_process(
   pair<PGRef, DeletingStateRef> item,
   ThreadPool::TPHandle &handle)
 {
+  FUNCTRACE();
   PGRef pg(item.first);
   SnapMapper &mapper = pg->snap_mapper;
   OSDriver &driver = pg->osdriver;
@@ -6083,6 +6086,7 @@ void OSD::session_notify_pg_cleared(
 
 void OSD::ms_fast_dispatch(Message *m)
 {
+  FUNCTRACE();
   if (service.is_stopping()) {
     m->put();
     return;
@@ -6107,6 +6111,7 @@ void OSD::ms_fast_dispatch(Message *m)
     session->put();
   }
   service.release_map(nextmap);
+  OID_EVENT_TRACE_WITH_MSG(m, "MS_FAST_DISPATCH_END", false); 
 }
 
 void OSD::ms_fast_preprocess(Message *m)
@@ -8988,6 +8993,9 @@ void OSD::dequeue_op(
   PGRef pg, OpRequestRef op,
   ThreadPool::TPHandle &handle)
 {
+  FUNCTRACE();
+  OID_EVENT_TRACE_WITH_MSG(op->get_req(), "DEQUEUE_OP_BEGIN", false);
+
   utime_t now = ceph_clock_now();
   op->set_dequeued_time(now);
   utime_t latency = now - op->get_req()->get_recv_stamp();
@@ -9032,6 +9040,7 @@ void OSD::dequeue_op(
 
   // finish
   dout(10) << "dequeue_op " << op << " finish" << dendl;
+  OID_EVENT_TRACE_WITH_MSG(op->get_req(), "DEQUEUE_OP_END", true);
 }
 
 

diff --git a/src/osd/OSD.h b/src/osd/OSD.h
index 62f55b12e7d3c2aaef0698d9e513803ebb68de30..e8d02010d0b79fe1f306f31fbc993678e7443e8c 100644 (file)
--- a/src/osd/OSD.h
+++ b/src/osd/OSD.h
@@ -53,6 +53,7 @@ using namespace std;
 #include "common/PrioritizedQueue.h"
 #include "messages/MOSDOp.h"
 #include "include/Spinlock.h"
+#include "common/EventTrace.h"
 
 #define CEPH_OSD_PROTOCOL    10 /* cluster internal */
 
@@ -1867,6 +1868,7 @@ private:
     };
 
     void dequeue(PG *pg) {
+      FUNCTRACE();
       return dequeue_and_get_ops(pg, nullptr);
     }
 

diff --git a/src/osd/PG.cc b/src/osd/PG.cc
index 2942f30aff89f0a28a83e6247ede4ae3f80ced73..c5329be0fca220a2d82270c30f938f421667b80a 100644 (file)
--- a/src/osd/PG.cc
+++ b/src/osd/PG.cc
@@ -52,6 +52,7 @@
 #include "messages/MOSDSubOpReply.h"
 #include "messages/MOSDRepOpReply.h"
 #include "common/BackTrace.h"
+#include "common/EventTrace.h"
 
 #ifdef WITH_LTTNG
 #define TRACEPOINT_DEFINE

diff --git a/src/osd/PrimaryLogPG.cc b/src/osd/PrimaryLogPG.cc
index 496947000bc1c39a75e331aa9e44dca586c4336b..a06f67c030f063f07b44d1d4ee9ee7cd2d400db5 100644 (file)
--- a/src/osd/PrimaryLogPG.cc
+++ b/src/osd/PrimaryLogPG.cc
@@ -39,6 +39,7 @@
 #include "messages/MOSDPGUpdateLogMissingReply.h"
 #include "messages/MCommandReply.h"
 #include "mds/inode_backtrace.h" // Ugh
+#include "common/EventTrace.h"
 
 #include "common/config.h"
 #include "include/compat.h"
@@ -1732,6 +1733,7 @@ bool PrimaryLogPG::check_src_targ(const hobject_t& soid, const hobject_t& toid)
  */
 void PrimaryLogPG::do_op(OpRequestRef& op)
 {
+  FUNCTRACE();
   MOSDOp *m = static_cast<MOSDOp*>(op->get_req());
   assert(m->get_type() == CEPH_MSG_OSD_OP);
 
@@ -3060,6 +3062,7 @@ void PrimaryLogPG::promote_object(ObjectContextRef obc,
 
 void PrimaryLogPG::execute_ctx(OpContext *ctx)
 {
+  FUNCTRACE();
   dout(10) << __func__ << " " << ctx << dendl;
   ctx->reset_obs(ctx->obc);
   ctx->update_log_only = false; // reset in case finish_copyfrom() is re-running execute_ctx
@@ -8539,6 +8542,7 @@ void PrimaryLogPG::eval_repop(RepGather *repop)
 
 void PrimaryLogPG::issue_repop(RepGather *repop, OpContext *ctx)
 {
+  FUNCTRACE();
   const hobject_t& soid = ctx->obs->oi.soid;
   dout(7) << "issue_repop rep_tid " << repop->rep_tid
           << " o " << soid
@@ -9141,6 +9145,7 @@ int PrimaryLogPG::find_object_context(const hobject_t& oid,
                                      bool map_snapid_to_clone,
                                      hobject_t *pmissing)
 {
+  FUNCTRACE();
   assert(oid.pool == static_cast<int64_t>(info.pgid.pool()));
   // want the head?
   if (oid.snap == CEPH_NOSNAP) {

diff --git a/src/osd/ReplicatedBackend.cc b/src/osd/ReplicatedBackend.cc
index a59ae096f931637df338b0b08a472510a9caaabd..183628b1b3614579afa1f4d5bd5510a8f131ac1a 100644 (file)
--- a/src/osd/ReplicatedBackend.cc
+++ b/src/osd/ReplicatedBackend.cc
@@ -21,6 +21,7 @@
 #include "messages/MOSDPGPush.h"
 #include "messages/MOSDPGPull.h"
 #include "messages/MOSDPGPushReply.h"
+#include "common/EventTrace.h"
 
 #define dout_context cct
 #define dout_subsys ceph_subsys_osd
@@ -613,6 +614,8 @@ void ReplicatedBackend::submit_transaction(
 void ReplicatedBackend::op_applied(
   InProgressOp *op)
 {
+  FUNCTRACE();
+  OID_EVENT_TRACE_WITH_MSG((op && op->op) ? op->op->get_req() : NULL, "OP_APPLIED_BEGIN", true);
   dout(10) << __func__ << ": " << op->tid << dendl;
   if (op->op)
     op->op->mark_event("op_applied");
@@ -633,6 +636,8 @@ void ReplicatedBackend::op_applied(
 void ReplicatedBackend::op_commit(
   InProgressOp *op)
 {
+  FUNCTRACE();
+  OID_EVENT_TRACE_WITH_MSG((op && op->op) ? op->op->get_req() : NULL, "OP_COMMIT_BEGIN", true);
   dout(10) << __func__ << ": " << op->tid << dendl;
   if (op->op)
     op->op->mark_event("op_commit");

diff --git a/src/osdc/CMakeLists.txt b/src/osdc/CMakeLists.txt
index 5335e2aea6b07fe08004a2dd4521d205d77b3f19..8593f2f4ed3d642b3754fe2cfec96ccfd83481d8 100644 (file)
--- a/src/osdc/CMakeLists.txt
+++ b/src/osdc/CMakeLists.txt
@@ -6,3 +6,6 @@ set(osdc_rbd_files
   Striper.cc)
 add_library(osdc_rbd_objs OBJECT ${osdc_rbd_files})
 add_library(osdc STATIC ${osdc_files} $<TARGET_OBJECTS:osdc_rbd_objs>)
+if(WITH_LTTNG AND WITH_EVENTTRACE)
+  add_dependencies(osdc eventtrace_tp)
+endif()

diff --git a/src/osdc/Objecter.cc b/src/osdc/Objecter.cc
index 2227795a111f766c7f6accc0d0df09861f2d7d79..d125df1957571efec1280464fc1fedaf774fe7bb 100644 (file)
--- a/src/osdc/Objecter.cc
+++ b/src/osdc/Objecter.cc
@@ -48,6 +48,7 @@
 #include "common/scrub_types.h"
 #include "include/str_list.h"
 #include "common/errno.h"
+#include "common/EventTrace.h"
 
 using ceph::real_time;
 using ceph::real_clock;
@@ -3907,6 +3908,7 @@ void Objecter::_pool_op_submit(PoolOp *op)
  */
 void Objecter::handle_pool_op_reply(MPoolOpReply *m)
 {
+  FUNCTRACE();
   shunique_lock sul(rwlock, acquire_shared);
   if (!initialized.read()) {
     sul.unlock();