common: extend lttng tracing infrastructure

New function and oid lttng tracing enhancements that provide function
and oid level latency breakdown. Requires WITH_EVENTTRACE=ON option to enable.

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

diff --git a/CMakeLists.txt b/CMakeLists.txt
index 46f99d02568d7e7382b14ba8ce123349a0320a73..207c82e61b871695716bbd37779f9d3db1088b01 100644 (file)
--- a/CMakeLists.txt
+++ b/CMakeLists.txt
@@ -413,6 +413,9 @@ set(HAVE_LIBROCKSDB 1)
 # -lz link into kv
 find_package(ZLIB REQUIRED)
 
+#option for EventTrace
+option(WITH_EVENTTRACE "Event tracing support" OFF)
+
 #option for LTTng
 option(WITH_LTTNG "LTTng tracing is enabled" ON)
 if(${WITH_LTTNG})

diff --git a/src/CMakeLists.txt b/src/CMakeLists.txt
index 409981e575d1756f9bcc07fbd2b850cb5142480b..9cfdfcf63cce52280282f24dcc5b8925fe5befc3 100644 (file)
--- a/src/CMakeLists.txt
+++ b/src/CMakeLists.txt
@@ -516,6 +516,12 @@ elseif(FREEBSD OR APPLE)
   message(STATUS " Using EventKqueue for events.")
 endif(LINUX)
 
+if(WITH_LTTNG AND WITH_EVENTTRACE)
+  message(STATUS " Using EventTrace class.")
+  add_definitions("-DWITH_EVENTTRACE")
+  list(APPEND libcommon_files common/EventTrace.cc)
+endif()
+
 set(mon_common_files
   auth/AuthSessionHandler.cc
   auth/cephx/CephxSessionHandler.cc

diff --git a/src/common/EventTrace.cc b/src/common/EventTrace.cc
new file mode 100644 (file)
index 0000000..5a39089
--- /dev/null
+++ b/src/common/EventTrace.cc
@@ -0,0 +1,131 @@
+// -*- mode:C++; tab-width:8; c-basic-offset:2; indent-tabs-mode:t -*-
+// vim: ts=8 sw=2 smarttab
+/*
+ * Ceph - scalable distributed file system
+ *
+ * Copyright (C) Intel Corporation.
+ * All rights reserved.
+ *
+ * Author: Anjaneya Chagam <anjaneya.chagam@intel.com>
+ *
+ * This is free software; you can redistribute it and/or
+ * modify it under the terms of the GNU Lesser General Public
+ * License version 2.1, as published by the Free Software
+ * Foundation.  See file COPYING.
+ *
+ */
+
+#include "common/EventTrace.h"
+#include "common/dout.h"
+#include "common/TracepointProvider.h"
+#include "messages/MOSDOp.h"
+#include "messages/MOSDOpReply.h"
+#include <iostream>
+#include <string>
+
+#ifdef WITH_LTTNG
+#define TRACEPOINT_DEFINE
+#define TRACEPOINT_PROBE_DYNAMIC_LINKAGE
+#include "tracing/eventtrace.h"
+#undef TRACEPOINT_PROBE_DYNAMIC_LINKAGE
+#undef TRACEPOINT_DEFINE
+#else
+#define tracepoint(...)
+#endif
+
+TracepointProvider::Traits event_tracepoint_traits("libeventtrace_tp.so", "event_tracing");
+bool EventTrace::tpinit = false;
+
+void EventTrace::init_tp(CephContext *_ctx)
+{
+  if (unlikely(!_ctx))
+    return;
+
+  if (unlikely(!tpinit)) {
+    TracepointProvider::initialize<event_tracepoint_traits>(_ctx);
+    tpinit = true;
+  }
+}
+
+void EventTrace::set_message_attrs(Message *m, string& oid, string& context, bool incl_oid)
+{
+  // arg1 = oid, arg2 = message type, arg3 = source!source_addr!tid!sequence
+  if (m && (m->get_type() == CEPH_MSG_OSD_OP || m->get_type() == CEPH_MSG_OSD_OPREPLY)) {
+    if (incl_oid) {
+      if (m->get_type() == CEPH_MSG_OSD_OP)
+        oid = ((MOSDOp *)m)->get_oid().name;
+      else
+        oid = ((MOSDOpReply *)m)->get_oid().name;
+    }
+
+    ostringstream buf;
+    buf << m->get_source() << "!" << m->get_source_addr() << "!"
+        << m->get_tid() << "!" << m->get_seq() << "!" << m->get_type();;
+    context = buf.str();
+  }
+}
+
+EventTrace::EventTrace(CephContext *_ctx, const char *_file, const char *_func, int _line) :
+  ctx(_ctx),
+  file(_file),
+  func(_func),
+  line(_line)
+{
+  if (unlikely(!ctx)) 
+    return;
+  last_ts = ceph_clock_now();
+  init_tp(ctx);
+
+  lsubdout(ctx, eventtrace, LOG_LEVEL) << "ENTRY (" <<  func << ") " << file << ":" << line << dendl;
+  tracepoint(eventtrace, func_enter, file.c_str(), func.c_str(), line);
+}
+
+EventTrace::~EventTrace()
+{
+  if (unlikely(!ctx)) 
+    return;
+  lsubdout(ctx, eventtrace, LOG_LEVEL) << "EXIT (" << func << ") " << file << dendl;
+  tracepoint(eventtrace, func_exit, file.c_str(), func.c_str());
+}
+
+void EventTrace::log_event_latency(const char *event)
+{
+  utime_t now = ceph_clock_now();
+  double usecs = (now.to_nsec()-last_ts.to_nsec())/1000;
+  OID_ELAPSED("", usecs, event);
+  last_ts = now;
+}
+
+void EventTrace::trace_oid_event(const char *oid, const char *event, const char *context,
+  const char *file, const char *func, int line)
+{
+  if (unlikely(!g_ceph_context))
+    return;
+  init_tp(g_ceph_context);
+  tracepoint(eventtrace, oid_event, oid, event, context, file, func, line);
+}
+
+void EventTrace::trace_oid_event(Message *m, const char *event, const char *file,
+  const char *func, int line, bool incl_oid)
+{
+  string oid, context;
+  set_message_attrs(m, oid, context, incl_oid);
+  trace_oid_event(oid.c_str(), event, context.c_str(), file, func, line);
+}
+
+void EventTrace::trace_oid_elapsed(const char *oid, const char *event, const char *context,
+  double elapsed, const char *file, const char *func, int line)
+{
+  if (unlikely(!g_ceph_context))
+    return;
+  init_tp(g_ceph_context);
+  tracepoint(eventtrace, oid_elapsed, oid, event, context, elapsed, file, func, line);
+}
+
+void EventTrace::trace_oid_elapsed(Message *m, const char *event, double elapsed, 
+  const char *file, const char *func, int line, bool incl_oid)
+{
+  string oid, context;
+  set_message_attrs(m, oid, context, incl_oid);
+  trace_oid_elapsed(oid.c_str(), event, context.c_str(), elapsed, file, func, line);
+}

diff --git a/src/common/EventTrace.h b/src/common/EventTrace.h
new file mode 100644 (file)
index 0000000..2d9f106
--- /dev/null
+++ b/src/common/EventTrace.h
@@ -0,0 +1,81 @@
+// -*- mode:C++; tab-width:8; c-basic-offset:2; indent-tabs-mode:t -*-
+// vim: ts=8 sw=2 smarttab
+/*
+ * Ceph - scalable distributed file system
+ *
+ * Copyright (C) 2016 Intel Corporation.
+ * All rights reserved.
+ *
+ * Author: Anjaneya Chagam <anjaneya.chagam@intel.com>
+ *
+ * This is free software; you can redistribute it and/or
+ * modify it under the terms of the GNU Lesser General Public
+ * License version 2.1, as published by the Free Software
+ * Foundation.  See file COPYING.
+ *
+ */
+
+#ifndef _EventTrace_h_
+#define _EventTrace_h_
+
+#include <string>
+#include "msg/Message.h"
+#include "common/ceph_context.h"
+
+#if defined(WITH_LTTNG) && defined(WITH_EVENTTRACE)
+
+#define OID_EVENT_TRACE(oid, event) \
+  EventTrace::trace_oid_event(oid, event, "", __FILE__, __func__, __LINE__)
+#define OID_EVENT_TRACE_WITH_MSG(msg, event, incl_oid) \
+  EventTrace::trace_oid_event(msg, event, __FILE__, __func__, __LINE__, incl_oid)
+#define OID_ELAPSED(oid, elapsed, event) \
+  EventTrace::trace_oid_elapsed(oid, event, "", elapsed, __FILE__, __func__, __LINE__)
+#define OID_ELAPSED_WITH_MSG(m, elapsed, event, incl_oid) \
+  EventTrace::trace_oid_elapsed(m, event, elapsed, __FILE__, __func__, __LINE__, incl_oid)
+#define FUNCTRACE() EventTrace _t1(g_ceph_context, __FILE__, __func__, __LINE__)
+#define OID_ELAPSED_FUNC_EVENT(event) _t1.log_event_latency(event)
+
+#else
+
+#define OID_EVENT_TRACE(oid, event)
+#define OID_EVENT_TRACE_WITH_MSG(msg, event, incl_oid)
+#define OID_ELAPSED(oid, elapsed, event)
+#define OID_ELAPSED_WITH_MSG(m, elapsed, event, incl_oid)
+#define FUNCTRACE()
+#define OID_ELAPSED_FUNC_EVENT(event)
+
+#endif
+
+#define LOG_LEVEL 1
+
+class EventTrace {
+private:
+  CephContext *ctx;
+  string file;
+  string func;
+  int line;
+  utime_t last_ts;
+
+  static bool tpinit;
+
+  static void init_tp(CephContext *_ctx);
+  static void set_message_attrs(Message *m, string& oid, string& context, bool incl_oid);
+
+public:
+
+  EventTrace(CephContext *_ctx, const char *_file, const char *_func, int line);
+  ~EventTrace();
+  void log_event_latency(const char *tag);
+
+  static void trace_oid_event(const char *oid, const char *event, const char *context,
+    const char *file, const char *func, int line);
+  static void trace_oid_event(Message *m, const char *event, const char *file,
+    const char *func, int line, bool incl_oid);
+
+  static void trace_oid_elapsed(const char *oid, const char *event, const char *context,
+    double elapsed, const char *file, const char *func, int line);
+  static void trace_oid_elapsed(Message *m, const char *event, double elapsed, 
+    const char *file, const char *func, int line, bool incl_oid);
+  
+};
+#endif

diff --git a/src/common/config_opts.h b/src/common/config_opts.h
index 04338d2ce7ff050fd7da3c20ee1aa4e3fa212547..b6053f98ecc49a5d13692ba9cbd1185c5ddc1b32 100644 (file)
--- a/src/common/config_opts.h
+++ b/src/common/config_opts.h
@@ -165,6 +165,7 @@ SUBSYS(fuse, 1, 5)
 SUBSYS(mgr, 1, 5)
 SUBSYS(mgrc, 1, 5)
 SUBSYS(dpdk, 1, 5)
+SUBSYS(eventtrace, 1, 5)
 
 OPTION(key, OPT_STR, "")
 OPTION(keyfile, OPT_STR, "")
@@ -1613,6 +1614,8 @@ OPTION(rgw_torrent_encoding, OPT_STR, "")    // torrent field encoding
 OPTION(rgw_torrent_origin, OPT_STR, "")    // torrent origin
 OPTION(rgw_torrent_sha_unit, OPT_INT, 512*1024)    // torrent field piece length 512K
 
+OPTION(event_tracing, OPT_BOOL, false) // true if LTTng-UST tracepoints should be enabled
+
 // This will be set to true when it is safe to start threads.
 // Once it is true, it will never change.
 OPTION(internal_safe_to_start_threads, OPT_BOOL, false)

diff --git a/src/tracing/CMakeLists.txt b/src/tracing/CMakeLists.txt
index 8b153935ec25929e385c2ce5b46d4387f390bd59..734056675acf99c7b777630d488e9152508412bd 100644 (file)
--- a/src/tracing/CMakeLists.txt
+++ b/src/tracing/CMakeLists.txt
@@ -44,4 +44,8 @@ add_tracing_library(rbd_tp librbd.tp 1.0.0)
 add_tracing_library(os_tp objectstore.tp 1.0.0)
 
 install(TARGETS rados_tp osd_tp rbd_tp os_tp DESTINATION ${CMAKE_INSTALL_LIBDIR})
+if(WITH_LTTNG AND WITH_EVENTTRACE)
+  add_tracing_library(eventtrace_tp eventtrace.tp 1.0.0)
+  install(TARGETS eventtrace_tp DESTINATION ${CMAKE_INSTALL_LIBDIR})
+endif()
 

diff --git a/src/tracing/eventtrace.c b/src/tracing/eventtrace.c
new file mode 100644 (file)
index 0000000..54ebae0
--- /dev/null
+++ b/src/tracing/eventtrace.c
@@ -0,0 +1,5 @@
+#define TRACEPOINT_CREATE_PROBES
+/*
+ * The header containing our TRACEPOINT_EVENTs.
+ */
+#include "tracing/eventtrace.h"

diff --git a/src/tracing/eventtrace.tp b/src/tracing/eventtrace.tp
new file mode 100644 (file)
index 0000000..f28ded1
--- /dev/null
+++ b/src/tracing/eventtrace.tp
@@ -0,0 +1,61 @@
+#include "include/int_types.h"
+
+TRACEPOINT_EVENT(eventtrace, func_enter,
+    TP_ARGS(
+        const char*, file,
+        const char*, func,
+        uint32_t, line),
+    TP_FIELDS(
+        ctf_string(file, file)
+        ctf_string(func, func)
+        ctf_integer(uint32_t, line, line)
+    )
+)
+
+TRACEPOINT_EVENT(eventtrace, func_exit,
+    TP_ARGS(
+        const char*, file,
+        const char*, func),
+    TP_FIELDS(
+        ctf_string(file, file)
+        ctf_string(func, func)
+    )
+)
+
+TRACEPOINT_EVENT(eventtrace, oid_event,
+    TP_ARGS(
+        const char*, oid,
+        const char*, event,
+        const char*, context,
+        const char*, file,
+        const char*, func,
+        uint32_t, line),
+    TP_FIELDS(
+        ctf_string(oid, oid)
+        ctf_string(event, event)
+        ctf_string(context, context)
+        ctf_string(file, file)
+        ctf_string(func, func)
+        ctf_integer(uint32_t, line, line)
+    )
+)
+
+TRACEPOINT_EVENT(eventtrace, oid_elapsed,
+    TP_ARGS(
+        const char*, oid,
+        const char*, event,
+        const char*, context,
+        double, elapsed,
+        const char*, file,
+        const char*, func,
+        uint32_t, line),
+    TP_FIELDS(
+        ctf_string(oid, oid)
+        ctf_string(event, event)
+        ctf_string(context, context)
+        ctf_float(double, elapsed, elapsed)
+        ctf_string(file, file)
+        ctf_string(func, func)
+        ctf_integer(uint32_t, line, line)
+    )
+)