tracing: add tracetool.py and convert tracepoints

Signed-off-by: Mohamad Gebai <mgebai@suse.com>

CMakeLists.txt

@@ -66,7 +66,8 @@ endif(WITH_MANPAGE)
 
 include_directories(
   ${PROJECT_BINARY_DIR}/src/include
-  ${PROJECT_SOURCE_DIR}/src)
+  ${PROJECT_SOURCE_DIR}/src
+  ${PROJECT_SOURCE_DIR}/build)
 
 if(OFED_PREFIX)
   include_directories(SYSTEM ${OFED_PREFIX}/include)

ceph.spec.in

@@ -174,6 +174,8 @@ BuildRequires:	liboath-devel
 BuildRequires:	libtool
 BuildRequires:	libxml2-devel
 BuildRequires:	libuuid-devel
+BuildRequires:	lttng-tools-devel
+BuildRequires:	lttng-ust-devel
 BuildRequires:	make
 BuildRequires:	ncurses-devel
 BuildRequires:	parted
@@ -1175,6 +1177,7 @@ ${CMAKE} .. \
     -DWITH_MANPAGE=ON \
     -DWITH_PYTHON3=%{python3_version} \
     -DWITH_MGR_DASHBOARD_FRONTEND=OFF \
+    -DWITH_LTTNG_LOGGING=ON \
 %if %{with python2}
     -DWITH_PYTHON2=ON \
 %else
@@ -1330,6 +1333,8 @@ rm -rf %{buildroot}
 %{_libdir}/libos_tp.so*
 %{_libdir}/libosd_tp.so*
 %endif
+%{_libdir}/liblogging_tp.so*
+%{_libdir}/libceph_logging_tp.so*
 %config(noreplace) %{_sysconfdir}/logrotate.d/ceph
 %if 0%{?fedora} || 0%{?rhel}
 %config(noreplace) %{_sysconfdir}/sysconfig/ceph

src/CMakeLists.txt

@@ -290,6 +290,7 @@ add_subdirectory(json_spirit)
 include_directories(SYSTEM "${CMAKE_SOURCE_DIR}/src/xxHash")
 include_directories(SYSTEM "${CMAKE_SOURCE_DIR}/src/rapidjson/include")
 
+add_subdirectory(fmt)
 if(WITH_SEASTAR)
   find_package(fmt 5.2.1 QUIET)
   if(NOT fmt_FOUND)
@@ -405,6 +406,8 @@ endif()
 add_library(common STATIC ${ceph_common_objs})
 target_link_libraries(common ${ceph_common_deps})
 
+#target_link_libraries(common dispatchqueue_tp)
+
 add_library(ceph-common SHARED ${ceph_common_objs})
 target_link_libraries(ceph-common ${ceph_common_deps})
 # appease dpkg-shlibdeps

src/ceph_osd.cc

@@ -55,6 +55,8 @@
 
 namespace {
 
+TracepointProvider::Traits dispatchqueue_tracepoint_traits("libdispatchqueue_tp.so", "dispatchqueue_tracing");
+
 TracepointProvider::Traits osd_tracepoint_traits("libosd_tp.so",
                                                  "osd_tracing");
 TracepointProvider::Traits os_tracepoint_traits("libos_tp.so",
@@ -653,6 +655,7 @@ int main(int argc, const char **argv)
   init_async_signal_handler();
   register_async_signal_handler(SIGHUP, sighup_handler);
 
+  TracepointProvider::initialize<dispatchqueue_tracepoint_traits>(g_ceph_context);
   TracepointProvider::initialize<osd_tracepoint_traits>(g_ceph_context);
   TracepointProvider::initialize<os_tracepoint_traits>(g_ceph_context);
 #ifdef WITH_OSD_INSTRUMENT_FUNCTIONS

src/common/hobject.cc

@@ -355,7 +355,11 @@ int cmp(const hobject_t& l, const hobject_t& r)
   return 0;
 }
 
-
+ghobject_t::operator std::string() const {
+  std::stringstream out;
+  out << *this;
+  return out.str();
+}
 
 // This is compatible with decode for hobject_t prior to
 // version 5.

src/common/hobject.h

@@ -464,6 +464,7 @@ struct ghobject_t {
     (*this) = temp;
   }
 
+  operator std::string() const;
   void encode(ceph::buffer::list& bl) const;
   void decode(ceph::buffer::list::const_iterator& bl);
   void decode(json_spirit::Value& v);

src/common/options.cc

@@ -603,6 +603,10 @@ std::vector<Option> get_global_options() {
                    "log_graylog_host",
                    "log_graylog_port"}),
 
+    Option("dispatchqueue_tracing", Option::TYPE_BOOL, Option::LEVEL_ADVANCED)
+    .set_default(false)
+    .set_description(""),
+
     Option("err_to_graylog", Option::TYPE_BOOL, Option::LEVEL_BASIC)
     .set_default(false)
     .set_description("send critical error log lines to remote graylog server")

src/common/types.cc

@@ -29,4 +29,10 @@ ostream &operator<<(ostream &lhs, const shard_id_t &rhs)
   return lhs << (unsigned)(uint8_t)rhs.id;
 }
 
+byte_u_t::operator std::string() {
+  stringstream out;
+  out << *this;
+  return out.str();
+}
+
 #endif

src/include/config-h.in.cmake

@@ -178,6 +178,9 @@
 /* Define if you want to use LTTng */
 #cmakedefine WITH_LTTNG
 
+/* Define if you want to use LTTng for logging instead of dout */
+#cmakedefine WITH_LTTNG_LOGGING
+
 /* Define if you want to OSD function instrumentation */
 #cmakedefine WITH_OSD_INSTRUMENT_FUNCTIONS
 

src/include/interval_set.h

@@ -724,6 +724,13 @@ class interval_set {
     other = std::move(m);
   }
 
+public:
+  operator std::string() const {
+    std::stringstream out;
+    out << *this;
+    return out.str();
+  }
+
 private:
   // data
   uint64_t _size;

src/include/tracing/ceph_logging_impl.h

@@ -0,0 +1,36 @@
+#ifndef CEPH_LOGGING_IMPL_H
+#define CEPH_LOGGING_IMPL_H
+
+#include <string>
+#include <stdarg.h>
+#include <fmt/include/fmt/format.h>
+#include <fmt/include/fmt/ostream.h>
+
+#include "tracing/ceph_logging.h"
+
+using fmt::format;
+
+#define trace(ll, ss, fmt, ...) __trace(ll, ss, format(fmt, __VA_ARGS__))
+#define trace_error(ss, fmt, ...) __trace(-1, ss, format(fmt, __VA_ARGS__))
+
+//static inline void trace(int loglevel, string subsys, const char *fmt, void *arg, ...)
+static inline void __trace(int loglevel, string subsys, string str)
+{
+  str = subsys + ": " + str;
+  if (loglevel <= -1) {
+    str = "Error: " + str;
+    tracepoint(ceph_logging, log_error, (char*)str.c_str());
+  } else if (loglevel <= 1) {
+    tracepoint(ceph_logging, log_critical, (char*)str.c_str());
+  } else if (loglevel <= 5) {
+    tracepoint(ceph_logging, log_warning, (char*)str.c_str());
+  } else if (loglevel <= 10) {
+    tracepoint(ceph_logging, log_info, (char*)str.c_str());
+  } else if (loglevel <= 15) {
+    tracepoint(ceph_logging, log_debug, (char*)str.c_str());
+  } else {
+    tracepoint(ceph_logging, log_verbose, (char*)str.c_str());
+  }
+}
+
+#endif // CEPH_LOGGING_IMPL_H

src/include/types.h

@@ -469,6 +469,7 @@ inline std::ostream& operator<<(std::ostream& out, const si_u_t& b)
 struct byte_u_t {
   uint64_t v;
   explicit byte_u_t(uint64_t _v) : v(_v) {};
+  operator std::string();
 };
 
 inline std::ostream& operator<<(std::ostream& out, const byte_u_t& b)

src/include/utime.h

@@ -225,6 +225,12 @@ class utime_t {
     return ts;
   }
 
+  operator std::string() {
+    stringstream out;
+    localtime(out);
+    return out.str();
+  }
+
   void sleep() const {
     struct timespec ts;
     to_timespec(&ts);

src/include/uuid.h

@@ -68,6 +68,9 @@ struct uuid_d {
 
   void dump(ceph::Formatter *f) const;
   static void generate_test_instances(std::list<uuid_d*>& o);
+  operator std::string() {
+    return to_string();
+  }
 };
 WRITE_CLASS_ENCODER(uuid_d)
 

src/log/Log.cc

@@ -22,6 +22,26 @@
 
 #include <iostream>
 
+#ifdef WITH_LTTNG_LOGGING
+#define TRACEPOINT_DEFINE
+#define TRACEPOINT_PROBE_DYNAMIC_LINKAGE
+//#include "tracing/bluefs.h"
+#include "tracing/bluestore.h"
+#include "tracing/bluestore_blob.h"
+#include "tracing/bluestore_gc.h"
+#include "tracing/bluestore_lru_cache.h"
+#include "tracing/bluestore_twoqcache.h"
+#include "tracing/bitmapallocator.h"
+#include "tracing/bmap_freelist_manager.h"
+#include "tracing/ceph_logging.h"
+#include "tracing/asyncconnection.h"
+#include "tracing/dispatchqueue.h"
+#undef TRACEPOINT_PROBE_DYNAMIC_LINKAGE
+#undef TRACEPOINT_DEFINE
+#else
+#define tracepoint(...)
+#endif
+
 #define MAX_LOG_BUF 65536
 
 namespace ceph {

src/mgr/DaemonState.cc

@@ -44,12 +44,12 @@ void DeviceState::set_life_expectancy(utime_t from, utime_t to, utime_t now)
   life_expectancy = make_pair(from, to);
   life_expectancy_stamp = now;
   if (from != utime_t()) {
-    metadata["life_expectancy_min"] = from;
+    metadata["life_expectancy_min"] = stringify(from);
   } else {
     metadata["life_expectancy_min"] = "";
   }
   if (to != utime_t()) {
-    metadata["life_expectancy_max"] = to;
+    metadata["life_expectancy_max"] = stringify(to);
   } else {
     metadata["life_expectancy_max"] = "";
   }

src/msg/DispatchQueue.cc

@@ -16,10 +16,20 @@
 #include "DispatchQueue.h"
 #include "Messenger.h"
 #include "common/ceph_context.h"
+#include "common/TracepointProvider.h"
 
 #define dout_subsys ceph_subsys_ms
 #include "common/debug.h"
 
+#ifdef WITH_LTTNG_LOGGING
+#include "include/tracing/dispatchqueue_impl.h"
+#else
+#define trace(...)
+#define trace_error(...)
+#endif
+
+
+//static TracepointProvider::Traits tracepoint_traits("libdispatchqueue_tp.so", "dispatchqueue_tracing");
 
 /*******************
  * DispatchQueue
@@ -38,18 +48,34 @@ double DispatchQueue::get_max_age(utime_t now) const {
 
 uint64_t DispatchQueue::pre_dispatch(const ref_t<Message>& m)
 {
-  ldout(cct,1) << "<== " << m->get_source_inst()
-	       << " " << m->get_seq()
-	       << " ==== " << *m
-	       << " ==== " << m->get_payload().length()
-	       << "+" << m->get_middle().length()
-	       << "+" << m->get_data().length()
-	       << " (" << ceph_con_mode_name(m->get_connection()->get_con_mode())
-	       << " " << m->get_footer().front_crc << " "
-	       << m->get_footer().middle_crc
-	       << " " << m->get_footer().data_crc << ")"
-	       << " " << m << " con " << m->get_connection()
-	       << dendl;
+//  ldout(cct,1) << "<== " << m->get_source_inst()
+//	       << " " << m->get_seq()
+//	       << " ==== " << *m
+//	       << " ==== " << m->get_payload().length()
+//	       << "+" << m->get_middle().length()
+//	       << "+" << m->get_data().length()
+//	       << " (" << ceph_con_mode_name(m->get_connection()->get_con_mode())
+//	       << " " << m->get_footer().front_crc << " "
+//	       << m->get_footer().middle_crc
+//	       << " " << m->get_footer().data_crc << ")"
+//	       << " " << m << " con " << m->get_connection()
+//	       << dendl;
+  stringstream str_m;
+  stringstream str_source_inst;
+  str_m << *m;
+  str_source_inst << m->get_source_inst();
+  trace_pre_dispatch_info(1, dispatchqueue,
+    string, str_source_inst, str_source_inst.str(),
+    uint64_t, seq, m->get_seq(),
+    string, str_m, str_m.str(),
+    uint32_t, payload_len, m->get_payload().length(),
+    uint32_t, middle_len, m->get_middle().length(),
+    uint32_t, data_len, m->get_data().length(),
+    string, con_mode, ceph_con_mode_name(m->get_connection()->get_con_mode()),
+    uint32_t, front_crc, m->get_footer().front_crc,
+    uint32_t, middle_crc, m->get_footer().middle_crc,
+    uint32_t, data_crc, m->get_footer().data_crc,
+    "<== {} {} === {} +++ {} + {} + {} ({} {} {} {})");
   uint64_t msize = m->get_dispatch_throttle_size();
   m->set_dispatch_throttle_size(0); // clear it out, in case we requeue this message.
   return msize;

src/msg/Message.cc

@@ -285,6 +285,12 @@ void Message::dump(Formatter *f) const
   f->dump_string("summary", ss.str());
 }
 
+Message::operator std::string() const {
+  std::stringstream out;
+  out << *this;
+  return out.str();
+}
+
 Message *decode_message(CephContext *cct, int crcflags,
 			ceph_msg_header& header,
 			ceph_msg_footer& footer,

src/msg/Message.h

@@ -501,6 +501,7 @@ class Message : public RefCountedObject {
   virtual void dump(ceph::Formatter *f) const;
 
   void encode(uint64_t features, int crcflags, bool skip_header_crc = false);
+  operator std::string() const;
 };
 
 extern Message *decode_message(CephContext *cct, int crcflags,

src/msg/async/AsyncConnection.cc

@@ -47,6 +47,13 @@ ostream& AsyncConnection::_conn_prefix(std::ostream *_dout) {
                 << ").";
 }
 
+#ifdef WITH_LTTNG_LOGGING
+#include "include/tracing/asyncconnection_impl.h"
+#else
+#define trace(...)
+#define trace_error(...)
+#endif
+
 // Notes:
 // 1. Don't dispatch any event when closed! It may cause AsyncConnection alive even if AsyncMessenger dead
 
@@ -517,12 +524,20 @@ void AsyncConnection::accept(ConnectedSocket socket,
 int AsyncConnection::send_message(Message *m)
 {
   FUNCTRACE(async_msgr->cct);
-  lgeneric_subdout(async_msgr->cct, ms,
-		   1) << "-- " << async_msgr->get_myaddrs() << " --> "
-		      << get_peer_addrs() << " -- "
-		      << *m << " -- " << m << " con "
-		      << this
-		      << dendl;
+//  lgeneric_subdout(async_msgr->cct, ms,
+//		   1) << "-- " << async_msgr->get_myaddrs() << " --> "
+//		      << get_peer_addrs() << " -- "
+//		      << *m << " -- " << m << " con "
+//		      << this
+//		      << dendl;
+  trace_send_message(1, asyncconnection,
+    void*, cct, async_msgr->cct,
+    string, myaddrs, async_msgr->get_myaddrs(),
+    string, peer_addrs, get_peer_addrs(),
+    string, message, *m,
+    void*, m, m,
+    void*, this_, this,
+    "{} {} -- {} --> {} -- {} -- {} con {}");
 
   // optimistic think it's ok to encode(actually may broken now)
   if (!m->get_priority())