From: Deepika Upadhyay Date: Fri, 25 Sep 2020 06:55:13 +0000 (+0530) Subject: core: tracing basic i/o path for OSD X-Git-Tag: v16.1.0~250^2~4 X-Git-Url: http://git-server-git.apps.pok.os.sepia.ceph.com/?a=commitdiff_plain;h=01997e76fed578cd667084bf5e2f0adace0c852a;p=ceph.git core: tracing basic i/o path for OSD * add tracing header files { common/tracer.{h/cc} } Signed-off-by: Deepika Upadhyay --- diff --git a/src/CMakeLists.txt b/src/CMakeLists.txt index 061b1927bff8..dd2312cfe964 100644 --- a/src/CMakeLists.txt +++ b/src/CMakeLists.txt @@ -383,6 +383,9 @@ set(libcommon_files osdc/error_code.cc librbd/Features.cc ${mds_files}) +if(WITH_JAEGER) + list(APPEND libcommon_files common/tracer.cc) +endif() set_source_files_properties(ceph_ver.c APPEND PROPERTY OBJECT_DEPENDS ${CMAKE_BINARY_DIR}/src/include/ceph_ver.h) add_library(common-objs OBJECT ${libcommon_files}) @@ -628,6 +631,9 @@ set(ceph_osd_srcs osd/objclass.cc objclass/class_api.cc ceph_osd.cc) +if(WITH_JAEGER) + list(APPEND ceph_osd_srcs common/tracer.cc) +endif() add_executable(ceph-osd ${ceph_osd_srcs}) add_dependencies(ceph-osd erasure_code_plugins) target_link_libraries(ceph-osd osd os global-static common diff --git a/src/common/tracer.cc b/src/common/tracer.cc new file mode 100644 index 000000000000..d3a1afffa91e --- /dev/null +++ b/src/common/tracer.cc @@ -0,0 +1,86 @@ +// -*- mode:C++; tab-width:8; c-basic-offset:2; indent-tabs-mode:t -*- +// vim: ts=8 sw=2 smarttab + +#include "tracer.h" +#include +#include +#ifdef __linux__ +#include +#else +typedef int64_t __s64; +#endif + +#include "common/debug.h" + +#define dout_context g_ceph_context +#define dout_subsys ceph_subsys_osd +#undef dout_prefix +#define dout_prefix *_dout << "jaeger_tracing " + +namespace jaeger_tracing { + + std::shared_ptr tracer = nullptr; + + void init_tracer(const char* tracer_name) { + if (!tracer) { + YAML::Node yaml; + try{ + yaml = YAML::LoadFile("../src/jaegertracing/config.yml"); + dout(3) << "yaml loaded" << yaml << dendl; + } + catch(std::exception &e) { + dout(3) << "failed to load yaml file using default config" << dendl; + auto yaml_config = R"cfg( +disabled: false +reporter: + logSpans: false + queueSize: 100 + bufferFlushInterval: 10 +sampler: + type: const + param: 1 +headers: + jaegerDebugHeader: debug-id + jaegerBaggageHeader: baggage + TraceContextHeaderName: trace-id +baggage_restrictions: + denyBaggageOnInitializationFailure: false + refreshInterval: 60 +)cfg"; + yaml = YAML::Load(yaml_config); + dout(3) << "yaml loaded" << yaml << dendl; + } + static auto configuration = jaegertracing::Config::parse(yaml); + tracer = jaegertracing::Tracer::make( tracer_name, configuration, + jaegertracing::logging::consoleLogger()); + dout(3) << "tracer_jaeger init successful" << dendl; + } + //incase of stale tracer, configure with a new global tracer + if (opentracing::Tracer::Global() != tracer) { + opentracing::Tracer::InitGlobal( + std::static_pointer_cast(tracer)); + } + } + + jspan new_span(const char* span_name) { + return opentracing::Tracer::Global()->StartSpan(span_name); + } + + jspan child_span(const char* span_name, const jspan& parent_span) { + //no parent check if parent not found span will still be constructed + return opentracing::Tracer::Global()->StartSpan(span_name, + {opentracing::ChildOf(&parent_span->context())}); + } + + void finish_span(const jspan& span) { + if (span) { + span->Finish(); + } + } + + void set_span_tag(const jspan& span, const char* key, const char* value) { + if (span) { + span->SetTag(key, value); + } + } +} diff --git a/src/common/tracer.h b/src/common/tracer.h new file mode 100644 index 000000000000..028ea04d8319 --- /dev/null +++ b/src/common/tracer.h @@ -0,0 +1,32 @@ +// -*- mode:C++; tab-width:8; c-basic-offset:2; indent-tabs-mode:t -*- +// vim: ts=8 sw=2 smarttab + +#ifndef TRACER_H_ +#define TRACER_H_ + +#define SIGNED_RIGHT_SHIFT_IS 1 +#define ARITHMETIC_RIGHT_SHIFT 1 + +#include + +typedef std::unique_ptr jspan; + +namespace jaeger_tracing { + + extern std::shared_ptr tracer; + + void init_tracer(const char* tracer_name); + + //create a root jspan + jspan new_span(const char*); + + //create a child_span used given parent_span + jspan child_span(const char*, const jspan&); + + //finish tracing of a single jspan + void finish_span(const jspan&); + + //setting tags in sundefined reference topans + void set_span_tag(const jspan&, const char*, const char*); +} +#endif // TRACER_H_ diff --git a/src/include/int_types.h b/src/include/int_types.h index 3435cbcbe2ae..a704ba71d2b3 100644 --- a/src/include/int_types.h +++ b/src/include/int_types.h @@ -5,7 +5,7 @@ #include -#ifdef HAVE_LINUX_TYPES_H +#ifdef __linux__ #include #else #ifndef HAVE___U8 diff --git a/src/jaegertracing/config.yml b/src/jaegertracing/config.yml new file mode 100644 index 000000000000..340eb511031e --- /dev/null +++ b/src/jaegertracing/config.yml @@ -0,0 +1,6 @@ +disabled: false +reporter: + logSpans: true +sampler: + type: const + param: 1 diff --git a/src/osd/ECBackend.cc b/src/osd/ECBackend.cc index 3e6e9587a856..b5c334386a77 100644 --- a/src/osd/ECBackend.cc +++ b/src/osd/ECBackend.cc @@ -940,6 +940,11 @@ void ECBackend::handle_sub_write( if (msg) msg->mark_event("sub_op_started"); trace.event("handle_sub_write"); +#ifdef HAVE_JAEGER + if (msg->osd_parent_span) { + auto ec_sub_trans = jaeger_tracing::child_span(__func__, msg->osd_parent_span); + } +#endif if (!get_parent()->pgb_is_primary()) get_parent()->update_stats(op.stats); ObjectStore::Transaction localt; @@ -1529,7 +1534,12 @@ void ECBackend::submit_transaction( op->client_op = client_op; if (client_op) op->trace = client_op->pg_trace; - + +#ifdef HAVE_JAEGER + if (client_op->osd_parent_span) { + auto ec_sub_trans = jaeger_tracing::child_span("ECBackend::submit_transaction", client_op->osd_parent_span); + } +#endif dout(10) << __func__ << ": op " << *op << " starting" << dendl; start_rmw(op, std::move(t)); } @@ -2098,6 +2108,12 @@ bool ECBackend::try_reads_to_commit() messages.push_back(std::make_pair(i->osd, r)); } } + +#ifdef HAVE_JAEGER + if (op->client_op->osd_parent_span) { + auto sub_write_span = jaeger_tracing::child_span("EC sub write", op->client_op->osd_parent_span); + } +#endif if (!messages.empty()) { get_parent()->send_message_osd_cluster(messages, get_osdmap_epoch()); } diff --git a/src/osd/OSD.cc b/src/osd/OSD.cc index db3ce3ce5929..335e64759978 100644 --- a/src/osd/OSD.cc +++ b/src/osd/OSD.cc @@ -173,6 +173,9 @@ #else #define tracepoint(...) #endif +#ifdef HAVE_JAEGER +#include "common/tracer.h" +#endif #define dout_context cct #define dout_subsys ceph_subsys_osd @@ -7017,6 +7020,12 @@ void OSD::dispatch_session_waiting(const ceph::ref_t& session, OSDMapRe void OSD::ms_fast_dispatch(Message *m) { + +#ifdef HAVE_JAEGER + jaeger_tracing::init_tracer("osd-services-reinit"); + dout(10) << "jaeger tracer after " << opentracing::Tracer::Global() << dendl; + auto dispatch_span = jaeger_tracing::new_span(__func__); +#endif FUNCTRACE(cct); if (service.is_stopping()) { m->put(); @@ -7077,7 +7086,13 @@ void OSD::ms_fast_dispatch(Message *m) tracepoint(osd, ms_fast_dispatch, reqid.name._type, reqid.name._num, reqid.tid, reqid.inc); } - +#ifdef HAVE_JAEGER + op->set_osd_parent_span(dispatch_span); + if (op->osd_parent_span) { + auto op_req_span = jaeger_tracing::child_span("op-request-created", op->osd_parent_span); + op->set_osd_parent_span(op_req_span); + } +#endif if (m->trace) op->osd_trace.init("osd op", &trace_endpoint, &m->trace); @@ -9627,6 +9642,18 @@ void OSD::enqueue_op(spg_t pg, OpRequestRef&& op, epoch_t epoch) op->osd_trace.event("enqueue op"); op->osd_trace.keyval("priority", priority); op->osd_trace.keyval("cost", cost); +#ifdef HAVE_JAEGER + if (op->osd_parent_span) { + auto enqueue_span = jaeger_tracing::child_span(__func__, op->osd_parent_span); + enqueue_span->Log({ + {"priority", priority}, + {"cost", cost}, + {"epoch", epoch}, + {"owner", owner}, + {"type", type} + }); + } +#endif op->mark_queued_for_pg(); logger->tinc(l_osd_op_before_queue_op_lat, latency); if (type == MSG_OSD_PG_PUSH || diff --git a/src/osd/OpRequest.h b/src/osd/OpRequest.h index dc5b5e34b1f2..0a03a85ac271 100644 --- a/src/osd/OpRequest.h +++ b/src/osd/OpRequest.h @@ -17,6 +17,9 @@ #include "osd/osd_op_util.h" #include "osd/osd_types.h" #include "common/TrackedOp.h" +#ifdef HAVE_JAEGER +#include "common/tracer.h" +#endif /** * The OpRequest takes in a Message* and takes over a single reference @@ -88,7 +91,17 @@ public: epoch_t min_epoch = 0; ///< min epoch needed to handle this msg bool hitset_inserted; - +#ifdef HAVE_JAEGER + jspan osd_parent_span = nullptr; + void set_osd_parent_span(jspan& span) { + if(osd_parent_span){ + jaeger_tracing::finish_span(osd_parent_span); + } + osd_parent_span = move(span); + } +#else + void set_osd_parent_span(...) {} +#endif template const T* get_req() const { return static_cast(request); } diff --git a/src/osd/PrimaryLogPG.cc b/src/osd/PrimaryLogPG.cc index 156da3b0a386..45dfb0651599 100644 --- a/src/osd/PrimaryLogPG.cc +++ b/src/osd/PrimaryLogPG.cc @@ -70,6 +70,9 @@ #include #include +#ifdef HAVE_JAEGER +#include "common/tracer.h" +#endif MEMPOOL_DEFINE_OBJECT_FACTORY(PrimaryLogPG, replicatedpg, osd); @@ -1660,7 +1663,12 @@ void PrimaryLogPG::do_request( op->pg_trace.init("pg op", &trace_endpoint, &op->osd_trace); op->pg_trace.event("do request"); } - // make sure we have a new enough map +#ifdef HAVE_JAEGER + if (op->osd_parent_span) { + auto do_req_span = jaeger_tracing::child_span(__func__, op->osd_parent_span); + } +#endif +// make sure we have a new enough map auto p = waiting_for_map.find(op->get_source()); if (p != waiting_for_map.end()) { // preserve ordering @@ -1690,7 +1698,6 @@ void PrimaryLogPG::do_request( auto session = ceph::ref_cast(m->get_connection()->get_priv()); if (!session) return; // drop it. - if (msg_type == CEPH_MSG_OSD_OP) { if (session->check_backoff(cct, info.pgid, info.pgid.pgid.get_hobj_start(), m)) { @@ -2019,6 +2026,11 @@ void PrimaryLogPG::do_op(OpRequestRef& op) << " flags " << ceph_osd_flag_string(m->get_flags()) << dendl; +#ifdef HAVE_JAEGER + if (op->osd_parent_span) { + auto do_op_span = jaeger_tracing::child_span(__func__, op->osd_parent_span); + } +#endif // missing object? if (is_unreadable_object(head)) { if (!is_primary()) { @@ -3849,6 +3861,11 @@ void PrimaryLogPG::execute_ctx(OpContext *ctx) tracepoint(osd, prepare_tx_enter, reqid.name._type, reqid.name._num, reqid.tid, reqid.inc); } +#ifdef HAVE_JAEGER + if (ctx->op->osd_parent_span) { + auto execute_span = jaeger_tracing::child_span(__func__, ctx->op->osd_parent_span); + } +#endif int result = prepare_transaction(ctx); @@ -5615,6 +5632,11 @@ int PrimaryLogPG::do_osd_ops(OpContext *ctx, vector& ops) PGTransaction* t = ctx->op_t.get(); dout(10) << "do_osd_op " << soid << " " << ops << dendl; +#ifdef HAVE_JAEGER + if (ctx->op->osd_parent_span) { + auto do_osd_op_span = jaeger_tracing::child_span(__func__, ctx->op->osd_parent_span); + } +#endif ctx->current_osd_subop_num = 0; for (auto p = ops.begin(); p != ops.end(); ++p, ctx->current_osd_subop_num++, ctx->processed_subop_count++) { @@ -8496,6 +8518,11 @@ void PrimaryLogPG::finish_ctx(OpContext *ctx, int log_op_type, int result) << dendl; utime_t now = ceph_clock_now(); +#ifdef HAVE_JAEGER + if (ctx->op->osd_parent_span) { + auto finish_ctx_span = jaeger_tracing::child_span(__func__, ctx->op->osd_parent_span); + } +#endif // Drop the reference if deduped chunk is modified if (ctx->new_obs.oi.is_dirty() && (ctx->obs->oi.has_manifest() && ctx->obs->oi.manifest.is_chunked()) && @@ -10498,6 +10525,11 @@ void PrimaryLogPG::op_applied(const eversion_t &applied_version) void PrimaryLogPG::eval_repop(RepGather *repop) { + #ifdef HAVE_JAEGER + if (repop->op->osd_parent_span) { + auto eval_span = jaeger_tracing::child_span(__func__, repop->op->osd_parent_span); + } + #endif dout(10) << "eval_repop " << *repop << (repop->op && repop->op->get_req() ? "" : " (no op)") << dendl; @@ -10552,6 +10584,11 @@ void PrimaryLogPG::issue_repop(RepGather *repop, OpContext *ctx) dout(7) << "issue_repop rep_tid " << repop->rep_tid << " o " << soid << dendl; +#ifdef HAVE_JAEGER + if (ctx->op->osd_parent_span) { + auto issue_repop_span = jaeger_tracing::child_span(__func__, ctx->op->osd_parent_span); + } +#endif repop->v = ctx->at_version; diff --git a/src/osd/ReplicatedBackend.cc b/src/osd/ReplicatedBackend.cc index d7ffc0533958..06f98b2c814f 100644 --- a/src/osd/ReplicatedBackend.cc +++ b/src/osd/ReplicatedBackend.cc @@ -502,6 +502,9 @@ void ReplicatedBackend::submit_transaction( ceph_assert(insert_res.second); InProgressOp &op = *insert_res.first->second; +#ifdef HAVE_JAEGER + auto rep_sub_trans = jaeger_tracing::child_span("ReplicatedBackend::submit_transaction", orig_op->osd_parent_span); +#endif op.waiting_for_commit.insert( parent->get_acting_recovery_backfill_shards().begin(), parent->get_acting_recovery_backfill_shards().end()); @@ -1057,6 +1060,10 @@ void ReplicatedBackend::do_repop(OpRequestRef op) << " " << m->logbl.length() << dendl; +#ifdef HAVE_JAEGER + auto do_repop_span = jaeger_tracing::child_span(__func__, op->osd_parent_span); +#endif + // sanity checks ceph_assert(m->map_epoch >= get_info().history.same_interval_since); diff --git a/src/osd/scheduler/OpSchedulerItem.cc b/src/osd/scheduler/OpSchedulerItem.cc index 66308dcc0e6d..9d57f202cc41 100644 --- a/src/osd/scheduler/OpSchedulerItem.cc +++ b/src/osd/scheduler/OpSchedulerItem.cc @@ -14,6 +14,9 @@ #include "osd/scheduler/OpSchedulerItem.h" #include "osd/OSD.h" +#ifdef HAVE_JAEGER +#include "common/tracer.h" +#endif namespace ceph::osd::scheduler { @@ -23,6 +26,9 @@ void PGOpItem::run( PGRef& pg, ThreadPool::TPHandle &handle) { +#ifdef HAVE_JAEGER + auto PGOpItem_span = jaeger_tracing::child_span("PGOpItem::run", op->osd_parent_span); +#endif osd->dequeue_op(pg, op, handle); pg->unlock(); }