From ab65be0bc1f3d7eb9a426b1751b8f2c81244dc62 Mon Sep 17 00:00:00 2001 From: David Li Date: Wed, 8 Dec 2021 12:10:58 -0500 Subject: [PATCH 01/15] WIP: [C++] Demonstrate C++ OTel instrumentation --- cpp/src/arrow/compute/exec/aggregate_node.cc | 13 +++++++++++++ cpp/src/arrow/compute/function.cc | 6 ++++++ cpp/src/arrow/util/tracing_internal.cc | 7 ++++--- cpp/src/arrow/util/tracing_internal.h | 1 + 4 files changed, 24 insertions(+), 3 deletions(-) diff --git a/cpp/src/arrow/compute/exec/aggregate_node.cc b/cpp/src/arrow/compute/exec/aggregate_node.cc index 59b2ff8b8af..48ed083d21b 100644 --- a/cpp/src/arrow/compute/exec/aggregate_node.cc +++ b/cpp/src/arrow/compute/exec/aggregate_node.cc @@ -32,6 +32,7 @@ #include "arrow/util/checked_cast.h" #include "arrow/util/logging.h" #include "arrow/util/thread_pool.h" +#include "arrow/util/tracing_internal.h" namespace arrow { @@ -379,6 +380,10 @@ class GroupByNode : public ExecNode { // Execute aggregate kernels for (size_t i = 0; i < agg_kernels_.size(); ++i) { +#ifdef ARROW_WITH_OPENTELEMETRY + auto span = arrow::internal::tracing::GetTracer()->StartSpan("GroupByNode::Consume", {{"function", aggs_[i].function}}); + auto scope = opentelemetry::trace::Scope(span); +#endif KernelContext kernel_ctx{ctx_}; kernel_ctx.SetState(state->agg_states[i].get()); @@ -406,6 +411,10 @@ class GroupByNode : public ExecNode { state->grouper.reset(); for (size_t i = 0; i < agg_kernels_.size(); ++i) { +#ifdef ARROW_WITH_OPENTELEMETRY + auto span = arrow::internal::tracing::GetTracer()->StartSpan("GroupByNode::Merge", {{"function", aggs_[i].function}}); + auto scope = opentelemetry::trace::Scope(span); +#endif KernelContext batch_ctx{ctx_}; DCHECK(state0->agg_states[i]); batch_ctx.SetState(state0->agg_states[i].get()); @@ -429,6 +438,10 @@ class GroupByNode : public ExecNode { // Aggregate fields come before key fields to match the behavior of GroupBy function for (size_t i = 0; i < agg_kernels_.size(); ++i) { +#ifdef ARROW_WITH_OPENTELEMETRY + auto span = arrow::internal::tracing::GetTracer()->StartSpan("GroupByNode::Finalize", {{"function", aggs_[i].function}}); + auto scope = opentelemetry::trace::Scope(span); +#endif KernelContext batch_ctx{ctx_}; batch_ctx.SetState(state->agg_states[i].get()); RETURN_NOT_OK(agg_kernels_[i]->finalize(&batch_ctx, &out_data.values[i])); diff --git a/cpp/src/arrow/compute/function.cc b/cpp/src/arrow/compute/function.cc index 0aecde11ba4..e3f2c5a28a1 100644 --- a/cpp/src/arrow/compute/function.cc +++ b/cpp/src/arrow/compute/function.cc @@ -31,6 +31,7 @@ #include "arrow/datum.h" #include "arrow/util/cpu_info.h" #include "arrow/util/logging.h" +#include "arrow/util/tracing_internal.h" namespace arrow { @@ -213,6 +214,11 @@ Result Function::Execute(const std::vector& args, return Execute(args, options, &default_ctx); } +#ifdef ARROW_WITH_OPENTELEMETRY + auto span = arrow::internal::tracing::GetTracer()->StartSpan("Function::Execute", {{"function", name()}}); + auto scope = opentelemetry::trace::Scope(span); +#endif + // type-check Datum arguments here. Really we'd like to avoid this as much as // possible RETURN_NOT_OK(detail::CheckAllValues(args)); diff --git a/cpp/src/arrow/util/tracing_internal.cc b/cpp/src/arrow/util/tracing_internal.cc index d39f95061c7..a194fdf2327 100644 --- a/cpp/src/arrow/util/tracing_internal.cc +++ b/cpp/src/arrow/util/tracing_internal.cc @@ -152,9 +152,10 @@ class FlushLog { explicit FlushLog(nostd::shared_ptr provider) : provider_(std::move(provider)) {} ~FlushLog() { - if (provider_) { - provider_->ForceFlush(std::chrono::microseconds(1000000)); - } + // TODO: ForceFlush apparently sends data that OTLP connector can't handle + // if (provider_) { + // provider_->ForceFlush(std::chrono::microseconds(1000000)); + // } } nostd::shared_ptr provider_; }; diff --git a/cpp/src/arrow/util/tracing_internal.h b/cpp/src/arrow/util/tracing_internal.h index f3ca5e5ce3d..285a0e883b2 100644 --- a/cpp/src/arrow/util/tracing_internal.h +++ b/cpp/src/arrow/util/tracing_internal.h @@ -28,6 +28,7 @@ #pragma warning(disable : 4522) #endif #include +#include #ifdef _MSC_VER #pragma warning(pop) #endif From 8244a230c2fc8c9369b19541a27a6a079fa89b17 Mon Sep 17 00:00:00 2001 From: Matthijs Brobbel Date: Tue, 4 Jan 2022 17:03:04 +0100 Subject: [PATCH 02/15] Instrument execution plans and nodes --- cpp/src/arrow/CMakeLists.txt | 1 + cpp/src/arrow/compute/exec/aggregate_node.cc | 125 ++++++++++++++++--- cpp/src/arrow/compute/exec/exec_plan.cc | 53 +++++++- cpp/src/arrow/compute/exec/exec_plan.h | 5 + cpp/src/arrow/compute/exec/filter_node.cc | 20 ++- cpp/src/arrow/compute/exec/hash_join.cc | 23 ++++ cpp/src/arrow/compute/exec/hash_join.h | 6 + cpp/src/arrow/compute/exec/hash_join_node.cc | 43 ++++++- cpp/src/arrow/compute/exec/options.cc | 43 +++++++ cpp/src/arrow/compute/exec/options.h | 12 +- cpp/src/arrow/compute/exec/project_node.cc | 19 ++- cpp/src/arrow/compute/exec/sink_node.cc | 46 +++++++ cpp/src/arrow/compute/exec/union_node.cc | 42 ++++++- cpp/src/arrow/compute/function.cc | 6 +- cpp/src/arrow/util/tracing_internal.cc | 2 +- 15 files changed, 409 insertions(+), 37 deletions(-) create mode 100644 cpp/src/arrow/compute/exec/options.cc diff --git a/cpp/src/arrow/CMakeLists.txt b/cpp/src/arrow/CMakeLists.txt index 5736c557bd0..1bf92161df9 100644 --- a/cpp/src/arrow/CMakeLists.txt +++ b/cpp/src/arrow/CMakeLists.txt @@ -389,6 +389,7 @@ if(ARROW_COMPUTE) compute/exec/key_encode.cc compute/exec/key_hash.cc compute/exec/key_map.cc + compute/exec/options.cc compute/exec/order_by_impl.cc compute/exec/project_node.cc compute/exec/sink_node.cc diff --git a/cpp/src/arrow/compute/exec/aggregate_node.cc b/cpp/src/arrow/compute/exec/aggregate_node.cc index 48ed083d21b..80bd37b896c 100644 --- a/cpp/src/arrow/compute/exec/aggregate_node.cc +++ b/cpp/src/arrow/compute/exec/aggregate_node.cc @@ -166,6 +166,14 @@ class ScalarAggregateNode : public ExecNode { const char* kind_name() const override { return "ScalarAggregateNode"; } Status DoConsume(const ExecBatch& batch, size_t thread_index) { +#ifdef ARROW_WITH_OPENTELEMETRY + auto tracer = arrow::internal::tracing::GetTracer(); + opentelemetry::trace::StartSpanOptions options; + options.parent = span->GetContext(); + auto span = tracer->StartSpan("ScalarAggregateNode::DoConsume", + {{"agg", ToStringExtra()}}, options); + auto scope = tracer->WithActiveSpan(span); +#endif for (size_t i = 0; i < kernels_.size(); ++i) { KernelContext batch_ctx{plan()->exec_context()}; batch_ctx.SetState(states_[i][thread_index].get()); @@ -177,6 +185,9 @@ class ScalarAggregateNode : public ExecNode { } void InputReceived(ExecNode* input, ExecBatch batch) override { +#ifdef ARROW_WITH_OPENTELEMETRY + span->AddEvent("InputReceived", {{"batch.length", batch.length}}); +#endif DCHECK_EQ(input, inputs_[0]); auto thread_index = get_thread_index_(); @@ -190,27 +201,45 @@ class ScalarAggregateNode : public ExecNode { void ErrorReceived(ExecNode* input, Status error) override { DCHECK_EQ(input, inputs_[0]); +#ifdef ARROW_WITH_OPENTELEMETRY + span->AddEvent("ErrorReceived", {{"error", error.message()}}); +#endif outputs_[0]->ErrorReceived(this, std::move(error)); } void InputFinished(ExecNode* input, int total_batches) override { +#ifdef ARROW_WITH_OPENTELEMETRY + span->AddEvent("InputFinished", {{"batches.length", total_batches}}); +#endif DCHECK_EQ(input, inputs_[0]); - if (input_counter_.SetTotal(total_batches)) { ErrorIfNotOk(Finish()); } } Status StartProducing() override { +#ifdef ARROW_WITH_OPENTELEMETRY + auto tracer = arrow::internal::tracing::GetTracer(); + span = tracer->StartSpan(kind_name(), {{"node", ToString()}}); + auto scope = tracer->WithActiveSpan(span); +#endif finished_ = Future<>::Make(); // Scalar aggregates will only output a single batch outputs_[0]->InputFinished(this, 1); return Status::OK(); } - void PauseProducing(ExecNode* output) override {} + void PauseProducing(ExecNode* output) override { +#ifdef ARROW_WITH_OPENTELEMETRY + span->AddEvent("PauseProducing"); +#endif + } - void ResumeProducing(ExecNode* output) override {} + void ResumeProducing(ExecNode* output) override { +#ifdef ARROW_WITH_OPENTELEMETRY + span->AddEvent("ResumeProducing"); +#endif + } void StopProducing(ExecNode* output) override { DCHECK_EQ(output, outputs_[0]); @@ -218,7 +247,13 @@ class ScalarAggregateNode : public ExecNode { } void StopProducing() override { +#ifdef ARROW_WITH_OPENTELEMETRY + span->AddEvent("StopProducing"); +#endif if (input_counter_.Cancel()) { +#ifdef ARROW_WITH_OPENTELEMETRY + span->End(); +#endif finished_.MarkFinished(); } inputs_[0]->StopProducing(this); @@ -247,6 +282,9 @@ class ScalarAggregateNode : public ExecNode { } outputs_[0]->InputReceived(this, std::move(batch)); +#ifdef ARROW_WITH_OPENTELEMETRY + span->End(); +#endif finished_.MarkFinished(); return Status::OK(); } @@ -359,6 +397,13 @@ class GroupByNode : public ExecNode { const char* kind_name() const override { return "GroupByNode"; } Status Consume(ExecBatch batch) { +#ifdef ARROW_WITH_OPENTELEMETRY + auto tracer = arrow::internal::tracing::GetTracer(); + opentelemetry::trace::StartSpanOptions options; + options.parent = span->GetContext(); + auto span = tracer->StartSpan("GroupByNode::Consume", options); + auto scope = tracer->WithActiveSpan(span); +#endif size_t thread_index = get_thread_index_(); if (thread_index >= local_states_.size()) { return Status::IndexError("thread index ", thread_index, " is out of range [0, ", @@ -380,10 +425,10 @@ class GroupByNode : public ExecNode { // Execute aggregate kernels for (size_t i = 0; i < agg_kernels_.size(); ++i) { -#ifdef ARROW_WITH_OPENTELEMETRY - auto span = arrow::internal::tracing::GetTracer()->StartSpan("GroupByNode::Consume", {{"function", aggs_[i].function}}); - auto scope = opentelemetry::trace::Scope(span); -#endif + // #ifdef ARROW_WITH_OPENTELEMETRY + // auto span = tracer->StartSpan("Aggregate", {{"function", + // aggs_[i].function}}); auto scope = tracer->WithActiveSpan(span); + // #endif KernelContext kernel_ctx{ctx_}; kernel_ctx.SetState(state->agg_states[i].get()); @@ -399,6 +444,13 @@ class GroupByNode : public ExecNode { } Status Merge() { +#ifdef ARROW_WITH_OPENTELEMETRY + auto tracer = arrow::internal::tracing::GetTracer(); + opentelemetry::trace::StartSpanOptions options; + options.parent = span->GetContext(); + auto span = tracer->StartSpan("GroupByNode::Merge", options); + auto scope = tracer->WithActiveSpan(span); +#endif ThreadLocalState* state0 = &local_states_[0]; for (size_t i = 1; i < local_states_.size(); ++i) { ThreadLocalState* state = &local_states_[i]; @@ -411,10 +463,10 @@ class GroupByNode : public ExecNode { state->grouper.reset(); for (size_t i = 0; i < agg_kernels_.size(); ++i) { -#ifdef ARROW_WITH_OPENTELEMETRY - auto span = arrow::internal::tracing::GetTracer()->StartSpan("GroupByNode::Merge", {{"function", aggs_[i].function}}); - auto scope = opentelemetry::trace::Scope(span); -#endif + // #ifdef ARROW_WITH_OPENTELEMETRY + // auto span = tracer->StartSpan("MergeKernel", {{"function", + // aggs_[i].function}}); auto scope = tracer->WithActiveSpan(span); + // #endif KernelContext batch_ctx{ctx_}; DCHECK(state0->agg_states[i]); batch_ctx.SetState(state0->agg_states[i].get()); @@ -429,6 +481,13 @@ class GroupByNode : public ExecNode { } Result Finalize() { +#ifdef ARROW_WITH_OPENTELEMETRY + auto tracer = arrow::internal::tracing::GetTracer(); + opentelemetry::trace::StartSpanOptions options; + options.parent = span->GetContext(); + auto span = tracer->StartSpan("GroupByNode::Finalize", options); + auto scope = tracer->WithActiveSpan(span); +#endif ThreadLocalState* state = &local_states_[0]; // If we never got any batches, then state won't have been initialized RETURN_NOT_OK(InitLocalStateIfNeeded(state)); @@ -438,10 +497,6 @@ class GroupByNode : public ExecNode { // Aggregate fields come before key fields to match the behavior of GroupBy function for (size_t i = 0; i < agg_kernels_.size(); ++i) { -#ifdef ARROW_WITH_OPENTELEMETRY - auto span = arrow::internal::tracing::GetTracer()->StartSpan("GroupByNode::Finalize", {{"function", aggs_[i].function}}); - auto scope = opentelemetry::trace::Scope(span); -#endif KernelContext batch_ctx{ctx_}; batch_ctx.SetState(state->agg_states[i].get()); RETURN_NOT_OK(agg_kernels_[i]->finalize(&batch_ctx, &out_data.values[i])); @@ -493,10 +548,18 @@ class GroupByNode : public ExecNode { } } +#ifdef ARROW_WITH_OPENTELEMETRY + span->End(); +#endif + return Status::OK(); } void InputReceived(ExecNode* input, ExecBatch batch) override { +#ifdef ARROW_WITH_OPENTELEMETRY + span->AddEvent("InputReceived", {{"batch.length", batch.length}}); +#endif + // bail if StopProducing was called if (finished_.is_finished()) return; @@ -512,10 +575,18 @@ class GroupByNode : public ExecNode { void ErrorReceived(ExecNode* input, Status error) override { DCHECK_EQ(input, inputs_[0]); +#ifdef ARROW_WITH_OPENTELEMETRY + span->AddEvent("ErrorReceived", {{"error", error.message()}}); +#endif + outputs_[0]->ErrorReceived(this, std::move(error)); } void InputFinished(ExecNode* input, int total_batches) override { +#ifdef ARROW_WITH_OPENTELEMETRY + span->AddEvent("InputFinished", {{"batches.length", total_batches}}); +#endif + // bail if StopProducing was called if (finished_.is_finished()) return; @@ -527,21 +598,41 @@ class GroupByNode : public ExecNode { } Status StartProducing() override { +#ifdef ARROW_WITH_OPENTELEMETRY + auto tracer = arrow::internal::tracing::GetTracer(); + span = tracer->StartSpan(kind_name(), {{"node", ToString()}}); + auto scope = tracer->WithActiveSpan(span); +#endif finished_ = Future<>::Make(); local_states_.resize(ThreadIndexer::Capacity()); return Status::OK(); } - void PauseProducing(ExecNode* output) override {} + void PauseProducing(ExecNode* output) override { +#ifdef ARROW_WITH_OPENTELEMETRY + span->AddEvent("PauseProducing"); +#endif + } - void ResumeProducing(ExecNode* output) override {} + void ResumeProducing(ExecNode* output) override { +#ifdef ARROW_WITH_OPENTELEMETRY + span->AddEvent("ResumeProducing"); +#endif + } void StopProducing(ExecNode* output) override { DCHECK_EQ(output, outputs_[0]); +#ifdef ARROW_WITH_OPENTELEMETRY + span->AddEvent("StopProducing"); +#endif + ARROW_UNUSED(input_counter_.Cancel()); if (output_counter_.Cancel()) { +#ifdef ARROW_WITH_OPENTELEMETRY + span->End(); +#endif finished_.MarkFinished(); } inputs_[0]->StopProducing(this); diff --git a/cpp/src/arrow/compute/exec/exec_plan.cc b/cpp/src/arrow/compute/exec/exec_plan.cc index 7cd3011b8ab..29e0ca1fa69 100644 --- a/cpp/src/arrow/compute/exec/exec_plan.cc +++ b/cpp/src/arrow/compute/exec/exec_plan.cc @@ -33,6 +33,7 @@ #include "arrow/util/checked_cast.h" #include "arrow/util/logging.h" #include "arrow/util/optional.h" +#include "arrow/util/tracing_internal.h" namespace arrow { @@ -78,6 +79,11 @@ struct ExecPlanImpl : public ExecPlan { } Status StartProducing() { +#ifdef ARROW_WITH_OPENTELEMETRY + auto tracer = arrow::internal::tracing::GetTracer(); + span = tracer->StartSpan("ExecPlan", {{"plan", ToString()}}); + auto scope = tracer->WithActiveSpan(span); +#endif if (started_) { return Status::Invalid("restarted ExecPlan"); } @@ -106,11 +112,21 @@ struct ExecPlanImpl : public ExecPlan { } finished_ = AllFinished(futures); +#ifdef ARROW_WITH_OPENTELEMETRY + finished_.AddCallback([this](const Status& st) { + arrow::internal::tracing::MarkSpan(st, span.get()); + span->End(); + }); +#endif return st; } void StopProducing() { DCHECK(started_) << "stopped an ExecPlan which never started"; +#ifdef ARROW_WITH_OPENTELEMETRY + // This segfaults when the ExecPlan never started. + span->AddEvent("StopProducing"); +#endif stopped_ = true; StopProducingImpl(sorted_nodes_.begin(), sorted_nodes_.end()); @@ -172,6 +188,9 @@ struct ExecPlanImpl : public ExecPlan { NodeVector sources_, sinks_; NodeVector sorted_nodes_; uint32_t auto_label_counter_ = 0; +#ifdef ARROW_WITH_OPENTELEMETRY + opentelemetry::nostd::shared_ptr span; +#endif }; ExecPlanImpl* ToDerived(ExecPlan* ptr) { return checked_cast(ptr); } @@ -316,22 +335,43 @@ MapNode::MapNode(ExecPlan* plan, std::vector inputs, void MapNode::ErrorReceived(ExecNode* input, Status error) { DCHECK_EQ(input, inputs_[0]); +#ifdef ARROW_WITH_OPENTELEMETRY + span->AddEvent("ErrorReceived", {{"error", error.message()}}); +#endif outputs_[0]->ErrorReceived(this, std::move(error)); } void MapNode::InputFinished(ExecNode* input, int total_batches) { DCHECK_EQ(input, inputs_[0]); +#ifdef ARROW_WITH_OPENTELEMETRY + span->AddEvent("InputFinished", {{"batches.length", total_batches}}); +#endif outputs_[0]->InputFinished(this, total_batches); if (input_counter_.SetTotal(total_batches)) { this->Finish(); } } -Status MapNode::StartProducing() { return Status::OK(); } +Status MapNode::StartProducing() { +#ifdef ARROW_WITH_OPENTELEMETRY + auto tracer = arrow::internal::tracing::GetTracer(); + span = tracer->StartSpan(kind_name(), {{"node", ToString()}}); + auto scope = tracer->WithActiveSpan(span); +#endif + return Status::OK(); +} -void MapNode::PauseProducing(ExecNode* output) {} +void MapNode::PauseProducing(ExecNode* output) { +#ifdef ARROW_WITH_OPENTELEMETRY + span->AddEvent("PauseProducing"); +#endif +} -void MapNode::ResumeProducing(ExecNode* output) {} +void MapNode::ResumeProducing(ExecNode* output) { +#ifdef ARROW_WITH_OPENTELEMETRY + span->AddEvent("ResumeProducing"); +#endif +} void MapNode::StopProducing(ExecNode* output) { DCHECK_EQ(output, outputs_[0]); @@ -339,6 +379,9 @@ void MapNode::StopProducing(ExecNode* output) { } void MapNode::StopProducing() { +#ifdef ARROW_WITH_OPENTELEMETRY + span->AddEvent("StopProducing"); +#endif if (executor_) { this->stop_source_.RequestStop(); } @@ -405,6 +448,10 @@ void MapNode::Finish(Status finish_st /*= Status::OK()*/) { } else { this->finished_.MarkFinished(finish_st); } +#ifdef ARROW_WITH_OPENTELEMETRY + arrow::internal::tracing::MarkSpan(finish_st, span.get()); + span->End(); +#endif } std::shared_ptr MakeGeneratorReader( diff --git a/cpp/src/arrow/compute/exec/exec_plan.h b/cpp/src/arrow/compute/exec/exec_plan.h index 4cb7fad009f..e0647501cd6 100644 --- a/cpp/src/arrow/compute/exec/exec_plan.h +++ b/cpp/src/arrow/compute/exec/exec_plan.h @@ -30,6 +30,7 @@ #include "arrow/util/cancel.h" #include "arrow/util/macros.h" #include "arrow/util/optional.h" +#include "arrow/util/tracing_internal.h" #include "arrow/util/visibility.h" namespace arrow { @@ -245,6 +246,10 @@ class ARROW_EXPORT ExecNode { std::shared_ptr output_schema_; int num_outputs_; NodeVector outputs_; + +#ifdef ARROW_WITH_OPENTELEMETRY + opentelemetry::nostd::shared_ptr span; +#endif }; /// \brief MapNode is an ExecNode type class which process a task like filter/project diff --git a/cpp/src/arrow/compute/exec/filter_node.cc b/cpp/src/arrow/compute/exec/filter_node.cc index 2e6d974dc13..63e7b4f020a 100644 --- a/cpp/src/arrow/compute/exec/filter_node.cc +++ b/cpp/src/arrow/compute/exec/filter_node.cc @@ -76,7 +76,6 @@ class FilterNode : public MapNode { if (mask_scalar.is_valid && mask_scalar.value) { return target; } - return target.Slice(0, 0); } @@ -93,8 +92,25 @@ class FilterNode : public MapNode { } void InputReceived(ExecNode* input, ExecBatch batch) override { +#ifdef ARROW_WITH_OPENTELEMETRY + span->AddEvent("InputReceived", {{"batch.length", batch.length}}); +#endif DCHECK_EQ(input, inputs_[0]); - auto func = [this](ExecBatch batch) { return DoFilter(std::move(batch)); }; + auto func = [this](ExecBatch batch) { +#ifdef ARROW_WITH_OPENTELEMETRY + auto tracer = arrow::internal::tracing::GetTracer(); + opentelemetry::trace::StartSpanOptions options; + options.parent = span->GetContext(); + auto span = tracer->StartSpan("FilterNode::DoFilter", options); + auto scope = tracer->WithActiveSpan(span); +#endif + auto result = DoFilter(std::move(batch)); +#ifdef ARROW_WITH_OPENTELEMETRY + arrow::internal::tracing::MarkSpan(result.status(), span.get()); + span->End(); +#endif + return result; + }; this->SubmitTask(std::move(func), std::move(batch)); } diff --git a/cpp/src/arrow/compute/exec/hash_join.cc b/cpp/src/arrow/compute/exec/hash_join.cc index 02f97dd6f86..6aa33c6fd95 100644 --- a/cpp/src/arrow/compute/exec/hash_join.cc +++ b/cpp/src/arrow/compute/exec/hash_join.cc @@ -42,6 +42,10 @@ class HashJoinBasicImpl : public HashJoinImpl { if (cancelled_) { return Status::Cancelled("Hash join cancelled"); } +#ifdef ARROW_WITH_OPENTELEMETRY + // Check parent span for details. + span->AddEvent("InputReceived"); +#endif if (QueueBatchIfNeeded(side, batch)) { return Status::OK(); } else { @@ -54,6 +58,9 @@ class HashJoinBasicImpl : public HashJoinImpl { if (cancelled_) { return Status::Cancelled("Hash join cancelled"); } +#ifdef ARROW_WITH_OPENTELEMETRY + span->AddEvent("InputFinished", {{"side", side}}); +#endif if (side == 0) { bool proceed; { @@ -86,6 +93,15 @@ class HashJoinBasicImpl : public HashJoinImpl { TaskScheduler::ScheduleImpl schedule_task_callback) override { num_threads = std::max(num_threads, static_cast(1)); +#ifdef ARROW_WITH_OPENTELEMETRY + auto tracer = arrow::internal::tracing::GetTracer(); + span = tracer->StartSpan("HashJoinBasicImpl", + {{"join_type", ToString(join_type)}, + {"expression", filter.ToString()}, + {"num_threads", static_cast(num_threads)}}); + auto scope = tracer->WithActiveSpan(span); +#endif + ctx_ = ctx; join_type_ = join_type; num_threads_ = num_threads; @@ -121,6 +137,10 @@ class HashJoinBasicImpl : public HashJoinImpl { } void Abort(TaskScheduler::AbortContinuationImpl pos_abort_callback) override { +#ifdef ARROW_WITH_OPENTELEMETRY + span->AddEvent("Abort"); + span->End(); +#endif cancelled_ = true; scheduler_->Abort(std::move(pos_abort_callback)); } @@ -774,6 +794,9 @@ class HashJoinBasicImpl : public HashJoinImpl { if (cancelled_) { return Status::Cancelled("Hash join cancelled"); } +#ifdef ARROW_WITH_OPENTELEMETRY + span->End(); +#endif finished_callback_(num_batches_produced_.load()); return Status::OK(); } diff --git a/cpp/src/arrow/compute/exec/hash_join.h b/cpp/src/arrow/compute/exec/hash_join.h index d52d7d980f9..a00406d40c2 100644 --- a/cpp/src/arrow/compute/exec/hash_join.h +++ b/cpp/src/arrow/compute/exec/hash_join.h @@ -27,6 +27,7 @@ #include "arrow/result.h" #include "arrow/status.h" #include "arrow/type.h" +#include "arrow/util/tracing_internal.h" namespace arrow { namespace compute { @@ -112,6 +113,11 @@ class HashJoinImpl { virtual void Abort(TaskScheduler::AbortContinuationImpl pos_abort_callback) = 0; static Result> MakeBasic(); + + protected: +#ifdef ARROW_WITH_OPENTELEMETRY + opentelemetry::nostd::shared_ptr span; +#endif }; } // namespace compute diff --git a/cpp/src/arrow/compute/exec/hash_join_node.cc b/cpp/src/arrow/compute/exec/hash_join_node.cc index 51e2e97cb1a..0694c5f3783 100644 --- a/cpp/src/arrow/compute/exec/hash_join_node.cc +++ b/cpp/src/arrow/compute/exec/hash_join_node.cc @@ -486,13 +486,17 @@ class HashJoinNode : public ExecNode { void InputReceived(ExecNode* input, ExecBatch batch) override { ARROW_DCHECK(std::find(inputs_.begin(), inputs_.end(), input) != inputs_.end()); - if (complete_.load()) { return; } size_t thread_index = thread_indexer_(); int side = (input == inputs_[0]) ? 0 : 1; + +#ifdef ARROW_WITH_OPENTELEMETRY + span->AddEvent("InputReceived", {{"batch.length", batch.length}, {"side", side}}); +#endif + { Status status = impl_->InputReceived(thread_index, side, std::move(batch)); if (!status.ok()) { @@ -512,6 +516,9 @@ class HashJoinNode : public ExecNode { } void ErrorReceived(ExecNode* input, Status error) override { +#ifdef ARROW_WITH_OPENTELEMETRY + span->AddEvent("ErrorReceived", {{"error", error.message()}}); +#endif DCHECK_EQ(input, inputs_[0]); StopProducing(); outputs_[0]->ErrorReceived(this, std::move(error)); @@ -523,6 +530,10 @@ class HashJoinNode : public ExecNode { size_t thread_index = thread_indexer_(); int side = (input == inputs_[0]) ? 0 : 1; +#ifdef ARROW_WITH_OPENTELEMETRY + span->AddEvent("InputFinished", {{"side", side}, {"batches.length", total_batches}}); +#endif + if (batch_count_[side].SetTotal(total_batches)) { Status status = impl_->InputFinished(thread_index, side); if (!status.ok()) { @@ -534,6 +545,11 @@ class HashJoinNode : public ExecNode { } Status StartProducing() override { +#ifdef ARROW_WITH_OPENTELEMETRY + auto tracer = arrow::internal::tracing::GetTracer(); + span = tracer->StartSpan(kind_name(), {{"node", ToString()}}); + auto scope = tracer->WithActiveSpan(span); +#endif finished_ = Future<>::Make(); bool use_sync_execution = !(plan_->exec_context()->executor()); @@ -550,9 +566,17 @@ class HashJoinNode : public ExecNode { return Status::OK(); } - void PauseProducing(ExecNode* output) override {} + void PauseProducing(ExecNode* output) override { +#ifdef ARROW_WITH_OPENTELEMETRY + span->AddEvent("PauseProducing"); +#endif + } - void ResumeProducing(ExecNode* output) override {} + void ResumeProducing(ExecNode* output) override { +#ifdef ARROW_WITH_OPENTELEMETRY + span->AddEvent("ResumeProducing"); +#endif + } void StopProducing(ExecNode* output) override { DCHECK_EQ(output, outputs_[0]); @@ -560,12 +584,20 @@ class HashJoinNode : public ExecNode { } void StopProducing() override { +#ifdef ARROW_WITH_OPENTELEMETRY + span->AddEvent("StopProducing"); +#endif bool expected = false; if (complete_.compare_exchange_strong(expected, true)) { for (auto&& input : inputs_) { input->StopProducing(this); } - impl_->Abort([this]() { finished_.MarkFinished(); }); + impl_->Abort([this]() { +#ifdef ARROW_WITH_OPENTELEMETRY + span->End(); +#endif + finished_.MarkFinished(); + }); } } @@ -580,6 +612,9 @@ class HashJoinNode : public ExecNode { bool expected = false; if (complete_.compare_exchange_strong(expected, true)) { outputs_[0]->InputFinished(this, static_cast(total_num_batches)); +#ifdef ARROW_WITH_OPENTELEMETRY + span->End(); +#endif finished_.MarkFinished(); } } diff --git a/cpp/src/arrow/compute/exec/options.cc b/cpp/src/arrow/compute/exec/options.cc new file mode 100644 index 00000000000..36345dfd7e1 --- /dev/null +++ b/cpp/src/arrow/compute/exec/options.cc @@ -0,0 +1,43 @@ +// Licensed to the Apache Software Foundation (ASF) under one +// or more contributor license agreements. See the NOTICE file +// distributed with this work for additional information +// regarding copyright ownership. The ASF licenses this file +// to you under the Apache License, Version 2.0 (the +// "License"); you may not use this file except in compliance +// with the License. You may obtain a copy of the License at +// +// http://www.apache.org/licenses/LICENSE-2.0 +// +// Unless required by applicable law or agreed to in writing, +// software distributed under the License is distributed on an +// "AS IS" BASIS, WITHOUT WARRANTIES OR CONDITIONS OF ANY +// KIND, either express or implied. See the License for the +// specific language governing permissions and limitations +// under the License. + +#include "arrow/compute/exec/options.h" + +namespace arrow { +namespace compute { +std::string ToString(JoinType t) { + switch (t) { + case JoinType::LEFT_SEMI: + return "LEFT_SEMI"; + case JoinType::RIGHT_SEMI: + return "RIGHT_SEMI"; + case JoinType::LEFT_ANTI: + return "LEFT_ANTI"; + case JoinType::RIGHT_ANTI: + return "RIGHT_ANTI"; + case JoinType::INNER: + return "INNER"; + case JoinType::LEFT_OUTER: + return "LEFT_OUTER"; + case JoinType::RIGHT_OUTER: + return "RIGHT_OUTER"; + case JoinType::FULL_OUTER: + return "FULL_OUTER"; + } +} +} // namespace compute +} // namespace arrow diff --git a/cpp/src/arrow/compute/exec/options.h b/cpp/src/arrow/compute/exec/options.h index 2723c4454c0..de51236dc85 100644 --- a/cpp/src/arrow/compute/exec/options.h +++ b/cpp/src/arrow/compute/exec/options.h @@ -164,6 +164,8 @@ enum class JoinType { FULL_OUTER }; +std::string ToString(JoinType t); + enum class JoinKeyCmp { EQ, IS }; /// \brief Make a node which implements join operation using hash join strategy. @@ -239,12 +241,12 @@ class ARROW_EXPORT HashJoinNodeOptions : public ExecNodeOptions { std::vector left_output; // output fields passed from right input std::vector right_output; - // key comparison function (determines whether a null key is equal another null key or - // not) + // key comparison function (determines whether a null key is equal another null + // key or not) std::vector key_cmp; - // prefix added to names of output fields coming from left input (used to distinguish, - // if necessary, between fields of the same name in left and right input and can be left - // empty if there are no name collisions) + // prefix added to names of output fields coming from left input (used to + // distinguish, if necessary, between fields of the same name in left and right + // input and can be left empty if there are no name collisions) std::string output_prefix_for_left; // prefix added to names of output fields coming from right input std::string output_prefix_for_right; diff --git a/cpp/src/arrow/compute/exec/project_node.cc b/cpp/src/arrow/compute/exec/project_node.cc index c675acb3d98..6036eab7261 100644 --- a/cpp/src/arrow/compute/exec/project_node.cc +++ b/cpp/src/arrow/compute/exec/project_node.cc @@ -89,8 +89,25 @@ class ProjectNode : public MapNode { } void InputReceived(ExecNode* input, ExecBatch batch) override { +#ifdef ARROW_WITH_OPENTELEMETRY + span->AddEvent("InputReceived", {{"batch.length", batch.length}}); +#endif DCHECK_EQ(input, inputs_[0]); - auto func = [this](ExecBatch batch) { return DoProject(std::move(batch)); }; + auto func = [this](ExecBatch batch) { +#ifdef ARROW_WITH_OPENTELEMETRY + auto tracer = arrow::internal::tracing::GetTracer(); + opentelemetry::trace::StartSpanOptions options; + options.parent = span->GetContext(); + auto span = tracer->StartSpan("ProjectNode::DoProject", options); + auto scope = tracer->WithActiveSpan(span); +#endif + auto result = DoProject(std::move(batch)); +#ifdef ARROW_WITH_OPENTELEMETRY + arrow::internal::tracing::MarkSpan(result.status(), span.get()); + span->End(); +#endif + return result; + }; this->SubmitTask(std::move(func), std::move(batch)); } diff --git a/cpp/src/arrow/compute/exec/sink_node.cc b/cpp/src/arrow/compute/exec/sink_node.cc index 1bb2680383c..b6127890f53 100644 --- a/cpp/src/arrow/compute/exec/sink_node.cc +++ b/cpp/src/arrow/compute/exec/sink_node.cc @@ -76,6 +76,12 @@ class SinkNode : public ExecNode { const char* kind_name() const override { return "SinkNode"; } Status StartProducing() override { +#ifdef ARROW_WITH_OPENTELEMETRY + auto tracer = arrow::internal::tracing::GetTracer(); + span = tracer->StartSpan(kind_name(), {{"node", ToString()}}); + auto scope = tracer->WithActiveSpan(span); +#endif + finished_ = Future<>::Make(); return Status::OK(); } @@ -89,6 +95,10 @@ class SinkNode : public ExecNode { [[noreturn]] void StopProducing(ExecNode* output) override { NoOutputs(); } void StopProducing() override { +#ifdef ARROW_WITH_OPENTELEMETRY + span->AddEvent("StopProducing"); +#endif + Finish(); inputs_[0]->StopProducing(this); } @@ -96,6 +106,9 @@ class SinkNode : public ExecNode { Future<> finished() override { return finished_; } void InputReceived(ExecNode* input, ExecBatch batch) override { +#ifdef ARROW_WITH_OPENTELEMETRY + span->AddEvent("InputReceived", {{"batch.length", batch.length}}); +#endif DCHECK_EQ(input, inputs_[0]); bool did_push = producer_.Push(std::move(batch)); @@ -107,6 +120,9 @@ class SinkNode : public ExecNode { } void ErrorReceived(ExecNode* input, Status error) override { +#ifdef ARROW_WITH_OPENTELEMETRY + span->AddEvent("ErrorReceived", {{"error", error.message()}}); +#endif DCHECK_EQ(input, inputs_[0]); producer_.Push(std::move(error)); @@ -118,6 +134,9 @@ class SinkNode : public ExecNode { } void InputFinished(ExecNode* input, int total_batches) override { +#ifdef ARROW_WITH_OPENTELEMETRY + span->AddEvent("InputFinished", {{"batches.length", total_batches}}); +#endif if (input_counter_.SetTotal(total_batches)) { Finish(); } @@ -125,6 +144,9 @@ class SinkNode : public ExecNode { protected: virtual void Finish() { +#ifdef ARROW_WITH_OPENTELEMETRY + span->End(); +#endif if (producer_.Close()) { finished_.MarkFinished(); } @@ -160,6 +182,11 @@ class ConsumingSinkNode : public ExecNode { const char* kind_name() const override { return "ConsumingSinkNode"; } Status StartProducing() override { +#ifdef ARROW_WITH_OPENTELEMETRY + auto tracer = arrow::internal::tracing::GetTracer(); + span = tracer->StartSpan(kind_name(), {{"node", ToString()}}); + auto scope = tracer->WithActiveSpan(span); +#endif finished_ = Future<>::Make(); return Status::OK(); } @@ -173,6 +200,9 @@ class ConsumingSinkNode : public ExecNode { [[noreturn]] void StopProducing(ExecNode* output) override { NoOutputs(); } void StopProducing() override { +#ifdef ARROW_WITH_OPENTELEMETRY + span->AddEvent("StopProducing"); +#endif Finish(Status::Invalid("ExecPlan was stopped early")); inputs_[0]->StopProducing(this); } @@ -180,6 +210,9 @@ class ConsumingSinkNode : public ExecNode { Future<> finished() override { return finished_; } void InputReceived(ExecNode* input, ExecBatch batch) override { +#ifdef ARROW_WITH_OPENTELEMETRY + span->AddEvent("InputReceived", {{"batch.length", batch.length}}); +#endif DCHECK_EQ(input, inputs_[0]); // This can happen if an error was received and the source hasn't yet stopped. Since @@ -203,6 +236,9 @@ class ConsumingSinkNode : public ExecNode { } void ErrorReceived(ExecNode* input, Status error) override { +#ifdef ARROW_WITH_OPENTELEMETRY + span->AddEvent("ErrorReceived", {{"error", error.message()}}); +#endif DCHECK_EQ(input, inputs_[0]); if (input_counter_.Cancel()) { @@ -213,6 +249,9 @@ class ConsumingSinkNode : public ExecNode { } void InputFinished(ExecNode* input, int total_batches) override { +#ifdef ARROW_WITH_OPENTELEMETRY + span->AddEvent("InputFinished", {{"batches.length", total_batches}}); +#endif if (input_counter_.SetTotal(total_batches)) { Finish(Status::OK()); } @@ -223,6 +262,10 @@ class ConsumingSinkNode : public ExecNode { consumer_->Finish().AddCallback([this, finish_st](const Status& st) { // Prefer the plan error over the consumer error Status final_status = finish_st & st; +#ifdef ARROW_WITH_OPENTELEMETRY + arrow::internal::tracing::MarkSpan(final_status, span.get()); + span->End(); +#endif finished_.MarkFinished(std::move(final_status)); }); } @@ -275,6 +318,9 @@ struct OrderBySinkNode final : public SinkNode { } void InputReceived(ExecNode* input, ExecBatch batch) override { +#ifdef ARROW_WITH_OPENTELEMETRY + span->AddEvent("InputReceived", {{"batch.length", batch.length}}); +#endif DCHECK_EQ(input, inputs_[0]); auto maybe_batch = batch.ToRecordBatch(inputs_[0]->output_schema(), diff --git a/cpp/src/arrow/compute/exec/union_node.cc b/cpp/src/arrow/compute/exec/union_node.cc index fef2f4e1866..a12fbd267aa 100644 --- a/cpp/src/arrow/compute/exec/union_node.cc +++ b/cpp/src/arrow/compute/exec/union_node.cc @@ -75,6 +75,9 @@ class UnionNode : public ExecNode { } void InputReceived(ExecNode* input, ExecBatch batch) override { +#ifdef ARROW_WITH_OPENTELEMETRY + span->AddEvent("InputReceived", {{"batch.length", batch.length}}); +#endif ARROW_DCHECK(std::find(inputs_.begin(), inputs_.end(), input) != inputs_.end()); if (finished_.is_finished()) { @@ -82,11 +85,17 @@ class UnionNode : public ExecNode { } outputs_[0]->InputReceived(this, std::move(batch)); if (batch_count_.Increment()) { +#ifdef ARROW_WITH_OPENTELEMETRY + span->End(); +#endif finished_.MarkFinished(); } } void ErrorReceived(ExecNode* input, Status error) override { +#ifdef ARROW_WITH_OPENTELEMETRY + span->AddEvent("ErrorReceived", {{"error", error.message()}}); +#endif DCHECK_EQ(input, inputs_[0]); outputs_[0]->ErrorReceived(this, std::move(error)); @@ -94,6 +103,10 @@ class UnionNode : public ExecNode { } void InputFinished(ExecNode* input, int total_batches) override { +#ifdef ARROW_WITH_OPENTELEMETRY + span->AddEvent("InputFinished", + {{"input", input_count_.count()}, {"batches.length", total_batches}}); +#endif ARROW_DCHECK(std::find(inputs_.begin(), inputs_.end(), input) != inputs_.end()); total_batches_.fetch_add(total_batches); @@ -101,23 +114,45 @@ class UnionNode : public ExecNode { if (input_count_.Increment()) { outputs_[0]->InputFinished(this, total_batches_.load()); if (batch_count_.SetTotal(total_batches_.load())) { +#ifdef ARROW_WITH_OPENTELEMETRY + span->End(); +#endif finished_.MarkFinished(); } } } Status StartProducing() override { +#ifdef ARROW_WITH_OPENTELEMETRY + auto tracer = arrow::internal::tracing::GetTracer(); + span = tracer->StartSpan(kind_name(), {{"node", ToString()}}); + auto scope = tracer->WithActiveSpan(span); +#endif finished_ = Future<>::Make(); return Status::OK(); } - void PauseProducing(ExecNode* output) override {} + void PauseProducing(ExecNode* output) override { +#ifdef ARROW_WITH_OPENTELEMETRY + span->AddEvent("PauseProducing"); +#endif + } - void ResumeProducing(ExecNode* output) override {} + void ResumeProducing(ExecNode* output) override { +#ifdef ARROW_WITH_OPENTELEMETRY + span->AddEvent("ResumeProducing"); +#endif + } void StopProducing(ExecNode* output) override { +#ifdef ARROW_WITH_OPENTELEMETRY + span->AddEvent("StopProducing"); +#endif DCHECK_EQ(output, outputs_[0]); if (batch_count_.Cancel()) { +#ifdef ARROW_WITH_OPENTELEMETRY + span->End(); +#endif finished_.MarkFinished(); } for (auto&& input : inputs_) { @@ -127,6 +162,9 @@ class UnionNode : public ExecNode { void StopProducing() override { if (batch_count_.Cancel()) { +#ifdef ARROW_WITH_OPENTELEMETRY + span->End(); +#endif finished_.MarkFinished(); } for (auto&& input : inputs_) { diff --git a/cpp/src/arrow/compute/function.cc b/cpp/src/arrow/compute/function.cc index e3f2c5a28a1..6adb456c2f8 100644 --- a/cpp/src/arrow/compute/function.cc +++ b/cpp/src/arrow/compute/function.cc @@ -215,8 +215,10 @@ Result Function::Execute(const std::vector& args, } #ifdef ARROW_WITH_OPENTELEMETRY - auto span = arrow::internal::tracing::GetTracer()->StartSpan("Function::Execute", {{"function", name()}}); - auto scope = opentelemetry::trace::Scope(span); + auto tracer = arrow::internal::tracing::GetTracer(); + auto span = tracer->StartSpan("Function::Execute", + {{"function", name()}, {"kind", kind()}, {"options", options->ToString()}}); + auto scope = tracer->WithActiveSpan(span); #endif // type-check Datum arguments here. Really we'd like to avoid this as much as diff --git a/cpp/src/arrow/util/tracing_internal.cc b/cpp/src/arrow/util/tracing_internal.cc index a194fdf2327..dc7dc49bfef 100644 --- a/cpp/src/arrow/util/tracing_internal.cc +++ b/cpp/src/arrow/util/tracing_internal.cc @@ -106,7 +106,7 @@ class ThreadIdSpanProcessor : public sdktrace::BatchSpanProcessor { void OnEnd(std::unique_ptr&& span) noexcept override { std::stringstream thread_id; thread_id << std::this_thread::get_id(); - span->SetAttribute("thread_id", thread_id.str()); + span->SetAttribute("thread.id", thread_id.str()); sdktrace::BatchSpanProcessor::OnEnd(std::move(span)); } }; From 8b54976194b5c2ab080f7977a30eb682a1723876 Mon Sep 17 00:00:00 2001 From: Matthijs Brobbel Date: Fri, 7 Jan 2022 21:56:48 +0100 Subject: [PATCH 03/15] Use pointer to implementation to allow span members on public types --- cpp/src/arrow/CMakeLists.txt | 1 + cpp/src/arrow/compute/exec/aggregate_node.cc | 139 +++++-------------- cpp/src/arrow/compute/exec/exec_plan.cc | 57 ++------ cpp/src/arrow/compute/exec/exec_plan.h | 6 +- cpp/src/arrow/compute/exec/filter_node.cc | 22 ++- cpp/src/arrow/compute/exec/hash_join.cc | 32 ++--- cpp/src/arrow/compute/exec/hash_join.h | 4 +- cpp/src/arrow/compute/exec/hash_join_node.cc | 43 ++---- cpp/src/arrow/compute/exec/project_node.cc | 20 +-- cpp/src/arrow/compute/exec/sink_node.cc | 60 ++------ cpp/src/arrow/compute/exec/union_node.cc | 53 ++----- cpp/src/arrow/compute/function.cc | 9 +- cpp/src/arrow/util/tracing.cc | 45 ++++++ cpp/src/arrow/util/tracing.h | 75 ++++++++++ cpp/src/arrow/util/tracing_internal.cc | 10 ++ cpp/src/arrow/util/tracing_internal.h | 48 ++++++- 16 files changed, 295 insertions(+), 329 deletions(-) create mode 100644 cpp/src/arrow/util/tracing.cc create mode 100644 cpp/src/arrow/util/tracing.h diff --git a/cpp/src/arrow/CMakeLists.txt b/cpp/src/arrow/CMakeLists.txt index 1bf92161df9..1181546b2e1 100644 --- a/cpp/src/arrow/CMakeLists.txt +++ b/cpp/src/arrow/CMakeLists.txt @@ -220,6 +220,7 @@ set(ARROW_SRCS util/tdigest.cc util/thread_pool.cc util/time.cc + util/tracing.cc util/trie.cc util/unreachable.cc util/uri.cc diff --git a/cpp/src/arrow/compute/exec/aggregate_node.cc b/cpp/src/arrow/compute/exec/aggregate_node.cc index 80bd37b896c..aea61cad55a 100644 --- a/cpp/src/arrow/compute/exec/aggregate_node.cc +++ b/cpp/src/arrow/compute/exec/aggregate_node.cc @@ -166,14 +166,10 @@ class ScalarAggregateNode : public ExecNode { const char* kind_name() const override { return "ScalarAggregateNode"; } Status DoConsume(const ExecBatch& batch, size_t thread_index) { -#ifdef ARROW_WITH_OPENTELEMETRY - auto tracer = arrow::internal::tracing::GetTracer(); - opentelemetry::trace::StartSpanOptions options; - options.parent = span->GetContext(); - auto span = tracer->StartSpan("ScalarAggregateNode::DoConsume", - {{"agg", ToStringExtra()}}, options); - auto scope = tracer->WithActiveSpan(span); -#endif + util::tracing::Span inner_span; + START_SPAN_WITH_PARENT(inner_span, span, "ScalarAggregateNode::DoConsume", + {{"agg", ToStringExtra()}}); + for (size_t i = 0; i < kernels_.size(); ++i) { KernelContext batch_ctx{plan()->exec_context()}; batch_ctx.SetState(states_[i][thread_index].get()); @@ -185,9 +181,7 @@ class ScalarAggregateNode : public ExecNode { } void InputReceived(ExecNode* input, ExecBatch batch) override { -#ifdef ARROW_WITH_OPENTELEMETRY - span->AddEvent("InputReceived", {{"batch.length", batch.length}}); -#endif + EVENT(span, "InputReceived", {{"batch.length", batch.length}}); DCHECK_EQ(input, inputs_[0]); auto thread_index = get_thread_index_(); @@ -200,17 +194,13 @@ class ScalarAggregateNode : public ExecNode { } void ErrorReceived(ExecNode* input, Status error) override { + EVENT(span, "ErrorReceived", {{"error", error.message()}}); DCHECK_EQ(input, inputs_[0]); -#ifdef ARROW_WITH_OPENTELEMETRY - span->AddEvent("ErrorReceived", {{"error", error.message()}}); -#endif outputs_[0]->ErrorReceived(this, std::move(error)); } void InputFinished(ExecNode* input, int total_batches) override { -#ifdef ARROW_WITH_OPENTELEMETRY - span->AddEvent("InputFinished", {{"batches.length", total_batches}}); -#endif + EVENT(span, "InputFinished", {{"batches.length", total_batches}}); DCHECK_EQ(input, inputs_[0]); if (input_counter_.SetTotal(total_batches)) { ErrorIfNotOk(Finish()); @@ -218,28 +208,16 @@ class ScalarAggregateNode : public ExecNode { } Status StartProducing() override { -#ifdef ARROW_WITH_OPENTELEMETRY - auto tracer = arrow::internal::tracing::GetTracer(); - span = tracer->StartSpan(kind_name(), {{"node", ToString()}}); - auto scope = tracer->WithActiveSpan(span); -#endif + START_SPAN(span, kind_name(), {{"node", ToString()}}); finished_ = Future<>::Make(); // Scalar aggregates will only output a single batch outputs_[0]->InputFinished(this, 1); return Status::OK(); } - void PauseProducing(ExecNode* output) override { -#ifdef ARROW_WITH_OPENTELEMETRY - span->AddEvent("PauseProducing"); -#endif - } + void PauseProducing(ExecNode* output) override { EVENT(span, "PauseProducing"); } - void ResumeProducing(ExecNode* output) override { -#ifdef ARROW_WITH_OPENTELEMETRY - span->AddEvent("ResumeProducing"); -#endif - } + void ResumeProducing(ExecNode* output) override { EVENT(span, "ResumeProducing"); } void StopProducing(ExecNode* output) override { DCHECK_EQ(output, outputs_[0]); @@ -247,13 +225,9 @@ class ScalarAggregateNode : public ExecNode { } void StopProducing() override { -#ifdef ARROW_WITH_OPENTELEMETRY - span->AddEvent("StopProducing"); -#endif + EVENT(span, "StopProducing"); if (input_counter_.Cancel()) { -#ifdef ARROW_WITH_OPENTELEMETRY - span->End(); -#endif + END_SPAN(span); finished_.MarkFinished(); } inputs_[0]->StopProducing(this); @@ -282,9 +256,7 @@ class ScalarAggregateNode : public ExecNode { } outputs_[0]->InputReceived(this, std::move(batch)); -#ifdef ARROW_WITH_OPENTELEMETRY - span->End(); -#endif + END_SPAN(span); finished_.MarkFinished(); return Status::OK(); } @@ -397,13 +369,8 @@ class GroupByNode : public ExecNode { const char* kind_name() const override { return "GroupByNode"; } Status Consume(ExecBatch batch) { -#ifdef ARROW_WITH_OPENTELEMETRY - auto tracer = arrow::internal::tracing::GetTracer(); - opentelemetry::trace::StartSpanOptions options; - options.parent = span->GetContext(); - auto span = tracer->StartSpan("GroupByNode::Consume", options); - auto scope = tracer->WithActiveSpan(span); -#endif + util::tracing::Span inner_span; + START_SPAN_WITH_PARENT(inner_span, span, "GroupByNode::Consume"); size_t thread_index = get_thread_index_(); if (thread_index >= local_states_.size()) { return Status::IndexError("thread index ", thread_index, " is out of range [0, ", @@ -425,10 +392,8 @@ class GroupByNode : public ExecNode { // Execute aggregate kernels for (size_t i = 0; i < agg_kernels_.size(); ++i) { - // #ifdef ARROW_WITH_OPENTELEMETRY - // auto span = tracer->StartSpan("Aggregate", {{"function", - // aggs_[i].function}}); auto scope = tracer->WithActiveSpan(span); - // #endif + util::tracing::Span span; + START_SPAN(span, "Aggregate", {{"function", aggs_[i].function}}); KernelContext kernel_ctx{ctx_}; kernel_ctx.SetState(state->agg_states[i].get()); @@ -444,13 +409,8 @@ class GroupByNode : public ExecNode { } Status Merge() { -#ifdef ARROW_WITH_OPENTELEMETRY - auto tracer = arrow::internal::tracing::GetTracer(); - opentelemetry::trace::StartSpanOptions options; - options.parent = span->GetContext(); - auto span = tracer->StartSpan("GroupByNode::Merge", options); - auto scope = tracer->WithActiveSpan(span); -#endif + util::tracing::Span inner_span; + START_SPAN_WITH_PARENT(inner_span, span, "GroupByNode::Merge"); ThreadLocalState* state0 = &local_states_[0]; for (size_t i = 1; i < local_states_.size(); ++i) { ThreadLocalState* state = &local_states_[i]; @@ -463,10 +423,8 @@ class GroupByNode : public ExecNode { state->grouper.reset(); for (size_t i = 0; i < agg_kernels_.size(); ++i) { - // #ifdef ARROW_WITH_OPENTELEMETRY - // auto span = tracer->StartSpan("MergeKernel", {{"function", - // aggs_[i].function}}); auto scope = tracer->WithActiveSpan(span); - // #endif + util::tracing::Span span; + START_SPAN(span, "MergeKernel", {{"function", aggs_[i].function}}); KernelContext batch_ctx{ctx_}; DCHECK(state0->agg_states[i]); batch_ctx.SetState(state0->agg_states[i].get()); @@ -481,13 +439,9 @@ class GroupByNode : public ExecNode { } Result Finalize() { -#ifdef ARROW_WITH_OPENTELEMETRY - auto tracer = arrow::internal::tracing::GetTracer(); - opentelemetry::trace::StartSpanOptions options; - options.parent = span->GetContext(); - auto span = tracer->StartSpan("GroupByNode::Finalize", options); - auto scope = tracer->WithActiveSpan(span); -#endif + util::tracing::Span inner_span; + START_SPAN_WITH_PARENT(inner_span, span, "GroupByNode::Finalize"); + ThreadLocalState* state = &local_states_[0]; // If we never got any batches, then state won't have been initialized RETURN_NOT_OK(InitLocalStateIfNeeded(state)); @@ -548,17 +502,13 @@ class GroupByNode : public ExecNode { } } -#ifdef ARROW_WITH_OPENTELEMETRY - span->End(); -#endif + END_SPAN(span); return Status::OK(); } void InputReceived(ExecNode* input, ExecBatch batch) override { -#ifdef ARROW_WITH_OPENTELEMETRY - span->AddEvent("InputReceived", {{"batch.length", batch.length}}); -#endif + EVENT(span, "InputReceived", {{"batch.length", batch.length}}); // bail if StopProducing was called if (finished_.is_finished()) return; @@ -573,19 +523,15 @@ class GroupByNode : public ExecNode { } void ErrorReceived(ExecNode* input, Status error) override { - DCHECK_EQ(input, inputs_[0]); + EVENT(span, "ErrorReceived", {{"error", error.message()}}); -#ifdef ARROW_WITH_OPENTELEMETRY - span->AddEvent("ErrorReceived", {{"error", error.message()}}); -#endif + DCHECK_EQ(input, inputs_[0]); outputs_[0]->ErrorReceived(this, std::move(error)); } void InputFinished(ExecNode* input, int total_batches) override { -#ifdef ARROW_WITH_OPENTELEMETRY - span->AddEvent("InputFinished", {{"batches.length", total_batches}}); -#endif + EVENT(span, "InputFinished", {{"batches.length", total_batches}}); // bail if StopProducing was called if (finished_.is_finished()) return; @@ -598,41 +544,26 @@ class GroupByNode : public ExecNode { } Status StartProducing() override { -#ifdef ARROW_WITH_OPENTELEMETRY - auto tracer = arrow::internal::tracing::GetTracer(); - span = tracer->StartSpan(kind_name(), {{"node", ToString()}}); - auto scope = tracer->WithActiveSpan(span); -#endif + START_SPAN(span, kind_name(), {{"node", ToString()}}); + finished_ = Future<>::Make(); local_states_.resize(ThreadIndexer::Capacity()); return Status::OK(); } - void PauseProducing(ExecNode* output) override { -#ifdef ARROW_WITH_OPENTELEMETRY - span->AddEvent("PauseProducing"); -#endif - } + void PauseProducing(ExecNode* output) override { EVENT(span, "PauseProducing"); } - void ResumeProducing(ExecNode* output) override { -#ifdef ARROW_WITH_OPENTELEMETRY - span->AddEvent("ResumeProducing"); -#endif - } + void ResumeProducing(ExecNode* output) override { EVENT(span, "ResumeProducing"); } void StopProducing(ExecNode* output) override { DCHECK_EQ(output, outputs_[0]); -#ifdef ARROW_WITH_OPENTELEMETRY - span->AddEvent("StopProducing"); -#endif + EVENT(span, "StopProducing"); ARROW_UNUSED(input_counter_.Cancel()); if (output_counter_.Cancel()) { -#ifdef ARROW_WITH_OPENTELEMETRY - span->End(); -#endif + END_SPAN(span); finished_.MarkFinished(); } inputs_[0]->StopProducing(this); diff --git a/cpp/src/arrow/compute/exec/exec_plan.cc b/cpp/src/arrow/compute/exec/exec_plan.cc index 29e0ca1fa69..66a1723318f 100644 --- a/cpp/src/arrow/compute/exec/exec_plan.cc +++ b/cpp/src/arrow/compute/exec/exec_plan.cc @@ -79,11 +79,8 @@ struct ExecPlanImpl : public ExecPlan { } Status StartProducing() { -#ifdef ARROW_WITH_OPENTELEMETRY - auto tracer = arrow::internal::tracing::GetTracer(); - span = tracer->StartSpan("ExecPlan", {{"plan", ToString()}}); - auto scope = tracer->WithActiveSpan(span); -#endif + START_SPAN(span, "ExecPlan", {{"plan", ToString()}}); + if (started_) { return Status::Invalid("restarted ExecPlan"); } @@ -114,19 +111,16 @@ struct ExecPlanImpl : public ExecPlan { finished_ = AllFinished(futures); #ifdef ARROW_WITH_OPENTELEMETRY finished_.AddCallback([this](const Status& st) { - arrow::internal::tracing::MarkSpan(st, span.get()); - span->End(); + MARK_SPAN(span, st); + END_SPAN(span); }); #endif return st; } void StopProducing() { + EVENT(span, "StopProducing"); DCHECK(started_) << "stopped an ExecPlan which never started"; -#ifdef ARROW_WITH_OPENTELEMETRY - // This segfaults when the ExecPlan never started. - span->AddEvent("StopProducing"); -#endif stopped_ = true; StopProducingImpl(sorted_nodes_.begin(), sorted_nodes_.end()); @@ -188,9 +182,8 @@ struct ExecPlanImpl : public ExecPlan { NodeVector sources_, sinks_; NodeVector sorted_nodes_; uint32_t auto_label_counter_ = 0; -#ifdef ARROW_WITH_OPENTELEMETRY - opentelemetry::nostd::shared_ptr span; -#endif + + util::tracing::Span span; }; ExecPlanImpl* ToDerived(ExecPlan* ptr) { return checked_cast(ptr); } @@ -334,18 +327,14 @@ MapNode::MapNode(ExecPlan* plan, std::vector inputs, } void MapNode::ErrorReceived(ExecNode* input, Status error) { + EVENT(span, "ErrorReceived", {{"error", error.message()}}); DCHECK_EQ(input, inputs_[0]); -#ifdef ARROW_WITH_OPENTELEMETRY - span->AddEvent("ErrorReceived", {{"error", error.message()}}); -#endif outputs_[0]->ErrorReceived(this, std::move(error)); } void MapNode::InputFinished(ExecNode* input, int total_batches) { + EVENT(span, "InputFinished", {{"batches.length", total_batches}}); DCHECK_EQ(input, inputs_[0]); -#ifdef ARROW_WITH_OPENTELEMETRY - span->AddEvent("InputFinished", {{"batches.length", total_batches}}); -#endif outputs_[0]->InputFinished(this, total_batches); if (input_counter_.SetTotal(total_batches)) { this->Finish(); @@ -353,25 +342,13 @@ void MapNode::InputFinished(ExecNode* input, int total_batches) { } Status MapNode::StartProducing() { -#ifdef ARROW_WITH_OPENTELEMETRY - auto tracer = arrow::internal::tracing::GetTracer(); - span = tracer->StartSpan(kind_name(), {{"node", ToString()}}); - auto scope = tracer->WithActiveSpan(span); -#endif + START_SPAN(span, kind_name(), {{"node", ToString()}}); return Status::OK(); } -void MapNode::PauseProducing(ExecNode* output) { -#ifdef ARROW_WITH_OPENTELEMETRY - span->AddEvent("PauseProducing"); -#endif -} +void MapNode::PauseProducing(ExecNode* output) { EVENT(span, "PauseProducing"); } -void MapNode::ResumeProducing(ExecNode* output) { -#ifdef ARROW_WITH_OPENTELEMETRY - span->AddEvent("ResumeProducing"); -#endif -} +void MapNode::ResumeProducing(ExecNode* output) { EVENT(span, "ResumeProducing"); } void MapNode::StopProducing(ExecNode* output) { DCHECK_EQ(output, outputs_[0]); @@ -379,9 +356,7 @@ void MapNode::StopProducing(ExecNode* output) { } void MapNode::StopProducing() { -#ifdef ARROW_WITH_OPENTELEMETRY - span->AddEvent("StopProducing"); -#endif + EVENT(span, "StopProducing"); if (executor_) { this->stop_source_.RequestStop(); } @@ -448,10 +423,8 @@ void MapNode::Finish(Status finish_st /*= Status::OK()*/) { } else { this->finished_.MarkFinished(finish_st); } -#ifdef ARROW_WITH_OPENTELEMETRY - arrow::internal::tracing::MarkSpan(finish_st, span.get()); - span->End(); -#endif + MARK_SPAN(span, finish_st); + END_SPAN(span); } std::shared_ptr MakeGeneratorReader( diff --git a/cpp/src/arrow/compute/exec/exec_plan.h b/cpp/src/arrow/compute/exec/exec_plan.h index e0647501cd6..00278a109e6 100644 --- a/cpp/src/arrow/compute/exec/exec_plan.h +++ b/cpp/src/arrow/compute/exec/exec_plan.h @@ -30,7 +30,7 @@ #include "arrow/util/cancel.h" #include "arrow/util/macros.h" #include "arrow/util/optional.h" -#include "arrow/util/tracing_internal.h" +#include "arrow/util/tracing.h" #include "arrow/util/visibility.h" namespace arrow { @@ -247,9 +247,7 @@ class ARROW_EXPORT ExecNode { int num_outputs_; NodeVector outputs_; -#ifdef ARROW_WITH_OPENTELEMETRY - opentelemetry::nostd::shared_ptr span; -#endif + util::tracing::Span span; }; /// \brief MapNode is an ExecNode type class which process a task like filter/project diff --git a/cpp/src/arrow/compute/exec/filter_node.cc b/cpp/src/arrow/compute/exec/filter_node.cc index 63e7b4f020a..c15aad4845b 100644 --- a/cpp/src/arrow/compute/exec/filter_node.cc +++ b/cpp/src/arrow/compute/exec/filter_node.cc @@ -26,6 +26,8 @@ #include "arrow/util/checked_cast.h" #include "arrow/util/future.h" #include "arrow/util/logging.h" +#include "arrow/util/tracing_internal.h" + namespace arrow { using internal::checked_cast; @@ -92,23 +94,15 @@ class FilterNode : public MapNode { } void InputReceived(ExecNode* input, ExecBatch batch) override { -#ifdef ARROW_WITH_OPENTELEMETRY - span->AddEvent("InputReceived", {{"batch.length", batch.length}}); -#endif + EVENT(span, "InputReceived", {{"batch.length", batch.length}}); + DCHECK_EQ(input, inputs_[0]); auto func = [this](ExecBatch batch) { -#ifdef ARROW_WITH_OPENTELEMETRY - auto tracer = arrow::internal::tracing::GetTracer(); - opentelemetry::trace::StartSpanOptions options; - options.parent = span->GetContext(); - auto span = tracer->StartSpan("FilterNode::DoFilter", options); - auto scope = tracer->WithActiveSpan(span); -#endif + util::tracing::Span inner_span; + START_SPAN_WITH_PARENT(inner_span, span, "FilterNode::DoFilter"); auto result = DoFilter(std::move(batch)); -#ifdef ARROW_WITH_OPENTELEMETRY - arrow::internal::tracing::MarkSpan(result.status(), span.get()); - span->End(); -#endif + MARK_SPAN(inner_span, result.status()); + END_SPAN(inner_span); return result; }; this->SubmitTask(std::move(func), std::move(batch)); diff --git a/cpp/src/arrow/compute/exec/hash_join.cc b/cpp/src/arrow/compute/exec/hash_join.cc index 6aa33c6fd95..3d8e1235320 100644 --- a/cpp/src/arrow/compute/exec/hash_join.cc +++ b/cpp/src/arrow/compute/exec/hash_join.cc @@ -42,10 +42,8 @@ class HashJoinBasicImpl : public HashJoinImpl { if (cancelled_) { return Status::Cancelled("Hash join cancelled"); } -#ifdef ARROW_WITH_OPENTELEMETRY - // Check parent span for details. - span->AddEvent("InputReceived"); -#endif + EVENT(span, "InputReceived"); + if (QueueBatchIfNeeded(side, batch)) { return Status::OK(); } else { @@ -58,9 +56,7 @@ class HashJoinBasicImpl : public HashJoinImpl { if (cancelled_) { return Status::Cancelled("Hash join cancelled"); } -#ifdef ARROW_WITH_OPENTELEMETRY - span->AddEvent("InputFinished", {{"side", side}}); -#endif + EVENT(span, "InputFinished", {{"side", side}}); if (side == 0) { bool proceed; { @@ -93,14 +89,10 @@ class HashJoinBasicImpl : public HashJoinImpl { TaskScheduler::ScheduleImpl schedule_task_callback) override { num_threads = std::max(num_threads, static_cast(1)); -#ifdef ARROW_WITH_OPENTELEMETRY - auto tracer = arrow::internal::tracing::GetTracer(); - span = tracer->StartSpan("HashJoinBasicImpl", - {{"join_type", ToString(join_type)}, - {"expression", filter.ToString()}, - {"num_threads", static_cast(num_threads)}}); - auto scope = tracer->WithActiveSpan(span); -#endif + START_SPAN(span, "HashJoinBasicImpl", + {{"join_type", ToString(join_type)}, + {"expression", filter.ToString()}, + {"num_threads", static_cast(num_threads)}}); ctx_ = ctx; join_type_ = join_type; @@ -137,10 +129,8 @@ class HashJoinBasicImpl : public HashJoinImpl { } void Abort(TaskScheduler::AbortContinuationImpl pos_abort_callback) override { -#ifdef ARROW_WITH_OPENTELEMETRY - span->AddEvent("Abort"); - span->End(); -#endif + EVENT(span, "Abort"); + END_SPAN(span); cancelled_ = true; scheduler_->Abort(std::move(pos_abort_callback)); } @@ -794,9 +784,7 @@ class HashJoinBasicImpl : public HashJoinImpl { if (cancelled_) { return Status::Cancelled("Hash join cancelled"); } -#ifdef ARROW_WITH_OPENTELEMETRY - span->End(); -#endif + END_SPAN(span); finished_callback_(num_batches_produced_.load()); return Status::OK(); } diff --git a/cpp/src/arrow/compute/exec/hash_join.h b/cpp/src/arrow/compute/exec/hash_join.h index a00406d40c2..9ee2980df4f 100644 --- a/cpp/src/arrow/compute/exec/hash_join.h +++ b/cpp/src/arrow/compute/exec/hash_join.h @@ -115,9 +115,7 @@ class HashJoinImpl { static Result> MakeBasic(); protected: -#ifdef ARROW_WITH_OPENTELEMETRY - opentelemetry::nostd::shared_ptr span; -#endif + util::tracing::Span span; }; } // namespace compute diff --git a/cpp/src/arrow/compute/exec/hash_join_node.cc b/cpp/src/arrow/compute/exec/hash_join_node.cc index 0694c5f3783..9334e287c8f 100644 --- a/cpp/src/arrow/compute/exec/hash_join_node.cc +++ b/cpp/src/arrow/compute/exec/hash_join_node.cc @@ -493,9 +493,7 @@ class HashJoinNode : public ExecNode { size_t thread_index = thread_indexer_(); int side = (input == inputs_[0]) ? 0 : 1; -#ifdef ARROW_WITH_OPENTELEMETRY - span->AddEvent("InputReceived", {{"batch.length", batch.length}, {"side", side}}); -#endif + EVENT(span, "InputReceived", {{"batch.length", batch.length}, {"side", side}}); { Status status = impl_->InputReceived(thread_index, side, std::move(batch)); @@ -516,9 +514,7 @@ class HashJoinNode : public ExecNode { } void ErrorReceived(ExecNode* input, Status error) override { -#ifdef ARROW_WITH_OPENTELEMETRY - span->AddEvent("ErrorReceived", {{"error", error.message()}}); -#endif + EVENT(span, "ErrorReceived", {{"error", error.message()}}); DCHECK_EQ(input, inputs_[0]); StopProducing(); outputs_[0]->ErrorReceived(this, std::move(error)); @@ -530,9 +526,7 @@ class HashJoinNode : public ExecNode { size_t thread_index = thread_indexer_(); int side = (input == inputs_[0]) ? 0 : 1; -#ifdef ARROW_WITH_OPENTELEMETRY - span->AddEvent("InputFinished", {{"side", side}, {"batches.length", total_batches}}); -#endif + EVENT(span, "InputFinished", {{"side", side}, {"batches.length", total_batches}}); if (batch_count_[side].SetTotal(total_batches)) { Status status = impl_->InputFinished(thread_index, side); @@ -545,11 +539,7 @@ class HashJoinNode : public ExecNode { } Status StartProducing() override { -#ifdef ARROW_WITH_OPENTELEMETRY - auto tracer = arrow::internal::tracing::GetTracer(); - span = tracer->StartSpan(kind_name(), {{"node", ToString()}}); - auto scope = tracer->WithActiveSpan(span); -#endif + START_SPAN(span, kind_name(), {{"node", ToString()}}); finished_ = Future<>::Make(); bool use_sync_execution = !(plan_->exec_context()->executor()); @@ -566,17 +556,9 @@ class HashJoinNode : public ExecNode { return Status::OK(); } - void PauseProducing(ExecNode* output) override { -#ifdef ARROW_WITH_OPENTELEMETRY - span->AddEvent("PauseProducing"); -#endif - } + void PauseProducing(ExecNode* output) override { EVENT(span, "PauseProducing"); } - void ResumeProducing(ExecNode* output) override { -#ifdef ARROW_WITH_OPENTELEMETRY - span->AddEvent("ResumeProducing"); -#endif - } + void ResumeProducing(ExecNode* output) override { EVENT(span, "ResumeProducing"); } void StopProducing(ExecNode* output) override { DCHECK_EQ(output, outputs_[0]); @@ -584,18 +566,14 @@ class HashJoinNode : public ExecNode { } void StopProducing() override { -#ifdef ARROW_WITH_OPENTELEMETRY - span->AddEvent("StopProducing"); -#endif + EVENT(span, "StopProducing"); bool expected = false; if (complete_.compare_exchange_strong(expected, true)) { for (auto&& input : inputs_) { input->StopProducing(this); } impl_->Abort([this]() { -#ifdef ARROW_WITH_OPENTELEMETRY - span->End(); -#endif + END_SPAN(span); finished_.MarkFinished(); }); } @@ -612,9 +590,7 @@ class HashJoinNode : public ExecNode { bool expected = false; if (complete_.compare_exchange_strong(expected, true)) { outputs_[0]->InputFinished(this, static_cast(total_num_batches)); -#ifdef ARROW_WITH_OPENTELEMETRY - span->End(); -#endif + END_SPAN(span); finished_.MarkFinished(); } } @@ -651,7 +627,6 @@ class HashJoinNode : public ExecNode { }; namespace internal { - void RegisterHashJoinNode(ExecFactoryRegistry* registry) { DCHECK_OK(registry->AddFactory("hashjoin", HashJoinNode::Make)); } diff --git a/cpp/src/arrow/compute/exec/project_node.cc b/cpp/src/arrow/compute/exec/project_node.cc index 6036eab7261..adfd2940510 100644 --- a/cpp/src/arrow/compute/exec/project_node.cc +++ b/cpp/src/arrow/compute/exec/project_node.cc @@ -29,6 +29,7 @@ #include "arrow/util/checked_cast.h" #include "arrow/util/future.h" #include "arrow/util/logging.h" +#include "arrow/util/tracing_internal.h" namespace arrow { @@ -89,23 +90,14 @@ class ProjectNode : public MapNode { } void InputReceived(ExecNode* input, ExecBatch batch) override { -#ifdef ARROW_WITH_OPENTELEMETRY - span->AddEvent("InputReceived", {{"batch.length", batch.length}}); -#endif + EVENT(span, "InputReceived", {{"batch.length", batch.length}}); DCHECK_EQ(input, inputs_[0]); auto func = [this](ExecBatch batch) { -#ifdef ARROW_WITH_OPENTELEMETRY - auto tracer = arrow::internal::tracing::GetTracer(); - opentelemetry::trace::StartSpanOptions options; - options.parent = span->GetContext(); - auto span = tracer->StartSpan("ProjectNode::DoProject", options); - auto scope = tracer->WithActiveSpan(span); -#endif + util::tracing::Span inner_span; + START_SPAN_WITH_PARENT(inner_span, span, "ProjectNode::DoProject"); auto result = DoProject(std::move(batch)); -#ifdef ARROW_WITH_OPENTELEMETRY - arrow::internal::tracing::MarkSpan(result.status(), span.get()); - span->End(); -#endif + MARK_SPAN(inner_span, result.status()); + END_SPAN(inner_span); return result; }; this->SubmitTask(std::move(func), std::move(batch)); diff --git a/cpp/src/arrow/compute/exec/sink_node.cc b/cpp/src/arrow/compute/exec/sink_node.cc index b6127890f53..e68f63801e2 100644 --- a/cpp/src/arrow/compute/exec/sink_node.cc +++ b/cpp/src/arrow/compute/exec/sink_node.cc @@ -37,6 +37,7 @@ #include "arrow/util/logging.h" #include "arrow/util/optional.h" #include "arrow/util/thread_pool.h" +#include "arrow/util/tracing_internal.h" #include "arrow/util/unreachable.h" namespace arrow { @@ -76,12 +77,7 @@ class SinkNode : public ExecNode { const char* kind_name() const override { return "SinkNode"; } Status StartProducing() override { -#ifdef ARROW_WITH_OPENTELEMETRY - auto tracer = arrow::internal::tracing::GetTracer(); - span = tracer->StartSpan(kind_name(), {{"node", ToString()}}); - auto scope = tracer->WithActiveSpan(span); -#endif - + START_SPAN(span, kind_name(), {{"node", ToString()}}); finished_ = Future<>::Make(); return Status::OK(); } @@ -95,9 +91,7 @@ class SinkNode : public ExecNode { [[noreturn]] void StopProducing(ExecNode* output) override { NoOutputs(); } void StopProducing() override { -#ifdef ARROW_WITH_OPENTELEMETRY - span->AddEvent("StopProducing"); -#endif + EVENT(span, "StopProducing"); Finish(); inputs_[0]->StopProducing(this); @@ -106,9 +100,7 @@ class SinkNode : public ExecNode { Future<> finished() override { return finished_; } void InputReceived(ExecNode* input, ExecBatch batch) override { -#ifdef ARROW_WITH_OPENTELEMETRY - span->AddEvent("InputReceived", {{"batch.length", batch.length}}); -#endif + EVENT(span, "InputReceived", {{"batch.length", batch.length}}); DCHECK_EQ(input, inputs_[0]); bool did_push = producer_.Push(std::move(batch)); @@ -120,9 +112,7 @@ class SinkNode : public ExecNode { } void ErrorReceived(ExecNode* input, Status error) override { -#ifdef ARROW_WITH_OPENTELEMETRY - span->AddEvent("ErrorReceived", {{"error", error.message()}}); -#endif + EVENT(span, "ErrorReceived", {{"error", error.message()}}); DCHECK_EQ(input, inputs_[0]); producer_.Push(std::move(error)); @@ -134,9 +124,7 @@ class SinkNode : public ExecNode { } void InputFinished(ExecNode* input, int total_batches) override { -#ifdef ARROW_WITH_OPENTELEMETRY - span->AddEvent("InputFinished", {{"batches.length", total_batches}}); -#endif + EVENT(span, "InputFinished", {{"batches.length", total_batches}}); if (input_counter_.SetTotal(total_batches)) { Finish(); } @@ -144,9 +132,7 @@ class SinkNode : public ExecNode { protected: virtual void Finish() { -#ifdef ARROW_WITH_OPENTELEMETRY - span->End(); -#endif + END_SPAN(span); if (producer_.Close()) { finished_.MarkFinished(); } @@ -182,11 +168,7 @@ class ConsumingSinkNode : public ExecNode { const char* kind_name() const override { return "ConsumingSinkNode"; } Status StartProducing() override { -#ifdef ARROW_WITH_OPENTELEMETRY - auto tracer = arrow::internal::tracing::GetTracer(); - span = tracer->StartSpan(kind_name(), {{"node", ToString()}}); - auto scope = tracer->WithActiveSpan(span); -#endif + START_SPAN(span, kind_name(), {{"node", ToString()}}); finished_ = Future<>::Make(); return Status::OK(); } @@ -200,9 +182,7 @@ class ConsumingSinkNode : public ExecNode { [[noreturn]] void StopProducing(ExecNode* output) override { NoOutputs(); } void StopProducing() override { -#ifdef ARROW_WITH_OPENTELEMETRY - span->AddEvent("StopProducing"); -#endif + EVENT(span, "StopProducing"); Finish(Status::Invalid("ExecPlan was stopped early")); inputs_[0]->StopProducing(this); } @@ -210,9 +190,7 @@ class ConsumingSinkNode : public ExecNode { Future<> finished() override { return finished_; } void InputReceived(ExecNode* input, ExecBatch batch) override { -#ifdef ARROW_WITH_OPENTELEMETRY - span->AddEvent("InputReceived", {{"batch.length", batch.length}}); -#endif + EVENT(span, "InputReceived", {{"batch.length", batch.length}}); DCHECK_EQ(input, inputs_[0]); // This can happen if an error was received and the source hasn't yet stopped. Since @@ -236,9 +214,7 @@ class ConsumingSinkNode : public ExecNode { } void ErrorReceived(ExecNode* input, Status error) override { -#ifdef ARROW_WITH_OPENTELEMETRY - span->AddEvent("ErrorReceived", {{"error", error.message()}}); -#endif + EVENT(span, "ErrorReceived", {{"error", error.message()}}); DCHECK_EQ(input, inputs_[0]); if (input_counter_.Cancel()) { @@ -249,9 +225,7 @@ class ConsumingSinkNode : public ExecNode { } void InputFinished(ExecNode* input, int total_batches) override { -#ifdef ARROW_WITH_OPENTELEMETRY - span->AddEvent("InputFinished", {{"batches.length", total_batches}}); -#endif + EVENT(span, "InputFinished", {{"batches.length", total_batches}}); if (input_counter_.SetTotal(total_batches)) { Finish(Status::OK()); } @@ -262,10 +236,8 @@ class ConsumingSinkNode : public ExecNode { consumer_->Finish().AddCallback([this, finish_st](const Status& st) { // Prefer the plan error over the consumer error Status final_status = finish_st & st; -#ifdef ARROW_WITH_OPENTELEMETRY - arrow::internal::tracing::MarkSpan(final_status, span.get()); - span->End(); -#endif + MARK_SPAN(span, final_status); + END_SPAN(span); finished_.MarkFinished(std::move(final_status)); }); } @@ -318,9 +290,7 @@ struct OrderBySinkNode final : public SinkNode { } void InputReceived(ExecNode* input, ExecBatch batch) override { -#ifdef ARROW_WITH_OPENTELEMETRY - span->AddEvent("InputReceived", {{"batch.length", batch.length}}); -#endif + EVENT(span, "InputReceived", {{"batch.length", batch.length}}); DCHECK_EQ(input, inputs_[0]); auto maybe_batch = batch.ToRecordBatch(inputs_[0]->output_schema(), diff --git a/cpp/src/arrow/compute/exec/union_node.cc b/cpp/src/arrow/compute/exec/union_node.cc index a12fbd267aa..87c8708f526 100644 --- a/cpp/src/arrow/compute/exec/union_node.cc +++ b/cpp/src/arrow/compute/exec/union_node.cc @@ -27,6 +27,7 @@ #include "arrow/util/future.h" #include "arrow/util/logging.h" #include "arrow/util/thread_pool.h" +#include "arrow/util/tracing_internal.h" namespace arrow { @@ -75,9 +76,7 @@ class UnionNode : public ExecNode { } void InputReceived(ExecNode* input, ExecBatch batch) override { -#ifdef ARROW_WITH_OPENTELEMETRY - span->AddEvent("InputReceived", {{"batch.length", batch.length}}); -#endif + EVENT(span, "InputReceived", {{"batch.length", batch.length}}); ARROW_DCHECK(std::find(inputs_.begin(), inputs_.end(), input) != inputs_.end()); if (finished_.is_finished()) { @@ -85,17 +84,13 @@ class UnionNode : public ExecNode { } outputs_[0]->InputReceived(this, std::move(batch)); if (batch_count_.Increment()) { -#ifdef ARROW_WITH_OPENTELEMETRY - span->End(); -#endif + END_SPAN(span); finished_.MarkFinished(); } } void ErrorReceived(ExecNode* input, Status error) override { -#ifdef ARROW_WITH_OPENTELEMETRY - span->AddEvent("ErrorReceived", {{"error", error.message()}}); -#endif + EVENT(span, "ErrorReceived", {{"error", error.message()}}); DCHECK_EQ(input, inputs_[0]); outputs_[0]->ErrorReceived(this, std::move(error)); @@ -103,10 +98,8 @@ class UnionNode : public ExecNode { } void InputFinished(ExecNode* input, int total_batches) override { -#ifdef ARROW_WITH_OPENTELEMETRY - span->AddEvent("InputFinished", - {{"input", input_count_.count()}, {"batches.length", total_batches}}); -#endif + EVENT(span, "InputFinished", + {{"input", input_count_.count()}, {"batches.length", total_batches}}); ARROW_DCHECK(std::find(inputs_.begin(), inputs_.end(), input) != inputs_.end()); total_batches_.fetch_add(total_batches); @@ -114,45 +107,27 @@ class UnionNode : public ExecNode { if (input_count_.Increment()) { outputs_[0]->InputFinished(this, total_batches_.load()); if (batch_count_.SetTotal(total_batches_.load())) { -#ifdef ARROW_WITH_OPENTELEMETRY - span->End(); -#endif + END_SPAN(span); finished_.MarkFinished(); } } } Status StartProducing() override { -#ifdef ARROW_WITH_OPENTELEMETRY - auto tracer = arrow::internal::tracing::GetTracer(); - span = tracer->StartSpan(kind_name(), {{"node", ToString()}}); - auto scope = tracer->WithActiveSpan(span); -#endif + START_SPAN(span, kind_name(), {{"node", ToString()}}); finished_ = Future<>::Make(); return Status::OK(); } - void PauseProducing(ExecNode* output) override { -#ifdef ARROW_WITH_OPENTELEMETRY - span->AddEvent("PauseProducing"); -#endif - } + void PauseProducing(ExecNode* output) override { EVENT(span, "PauseProducing"); } - void ResumeProducing(ExecNode* output) override { -#ifdef ARROW_WITH_OPENTELEMETRY - span->AddEvent("ResumeProducing"); -#endif - } + void ResumeProducing(ExecNode* output) override { EVENT(span, "ResumeProducing"); } void StopProducing(ExecNode* output) override { -#ifdef ARROW_WITH_OPENTELEMETRY - span->AddEvent("StopProducing"); -#endif + EVENT(span, "StopProducing"); DCHECK_EQ(output, outputs_[0]); if (batch_count_.Cancel()) { -#ifdef ARROW_WITH_OPENTELEMETRY - span->End(); -#endif + END_SPAN(span); finished_.MarkFinished(); } for (auto&& input : inputs_) { @@ -162,9 +137,7 @@ class UnionNode : public ExecNode { void StopProducing() override { if (batch_count_.Cancel()) { -#ifdef ARROW_WITH_OPENTELEMETRY - span->End(); -#endif + END_SPAN(span); finished_.MarkFinished(); } for (auto&& input : inputs_) { diff --git a/cpp/src/arrow/compute/function.cc b/cpp/src/arrow/compute/function.cc index 6adb456c2f8..da05c81e7c8 100644 --- a/cpp/src/arrow/compute/function.cc +++ b/cpp/src/arrow/compute/function.cc @@ -214,12 +214,9 @@ Result Function::Execute(const std::vector& args, return Execute(args, options, &default_ctx); } -#ifdef ARROW_WITH_OPENTELEMETRY - auto tracer = arrow::internal::tracing::GetTracer(); - auto span = tracer->StartSpan("Function::Execute", - {{"function", name()}, {"kind", kind()}, {"options", options->ToString()}}); - auto scope = tracer->WithActiveSpan(span); -#endif + util::tracing::Span span; + START_SPAN(span, "Function::Execute", + {{"function", name()}, {"kind", kind()}, {"options", options->ToString()}}); // type-check Datum arguments here. Really we'd like to avoid this as much as // possible diff --git a/cpp/src/arrow/util/tracing.cc b/cpp/src/arrow/util/tracing.cc new file mode 100644 index 00000000000..9bfd818a4a0 --- /dev/null +++ b/cpp/src/arrow/util/tracing.cc @@ -0,0 +1,45 @@ +// Licensed to the Apache Software Foundation (ASF) under one +// or more contributor license agreements. See the NOTICE file +// distributed with this work for additional information +// regarding copyright ownership. The ASF licenses this file +// to you under the Apache License, Version 2.0 (the +// "License"); you may not use this file except in compliance +// with the License. You may obtain a copy of the License at +// +// http://www.apache.org/licenses/LICENSE-2.0 +// +// Unless required by applicable law or agreed to in writing, +// software distributed under the License is distributed on an +// "AS IS" BASIS, WITHOUT WARRANTIES OR CONDITIONS OF ANY +// KIND, either express or implied. See the License for the +// specific language governing permissions and limitations +// under the License. + +#include "arrow/util/tracing.h" +#include "arrow/util/make_unique.h" +#include "arrow/util/tracing_internal.h" + +namespace arrow { +namespace util { +namespace tracing { + +#ifdef ARROW_WITH_OPENTELEMETRY + +Span::Impl& Span::set_impl(const Impl& impl) { + inner_impl.reset(new Impl(impl)); + return *inner_impl; +} + +Span::Impl& Span::set_impl(Impl&& impl) { + inner_impl.reset(new Impl(std::move(impl))); + return *inner_impl; +} + +#endif + +// Default destructor when impl type is complete. +Span::~Span() = default; + +} // namespace tracing +} // namespace util +} // namespace arrow diff --git a/cpp/src/arrow/util/tracing.h b/cpp/src/arrow/util/tracing.h new file mode 100644 index 00000000000..468134eecff --- /dev/null +++ b/cpp/src/arrow/util/tracing.h @@ -0,0 +1,75 @@ +// Licensed to the Apache Software Foundation (ASF) under one +// or more contributor license agreements. See the NOTICE file +// distributed with this work for additional information +// regarding copyright ownership. The ASF licenses this file +// to you under the Apache License, Version 2.0 (the +// "License"); you may not use this file except in compliance +// with the License. You may obtain a copy of the License at +// +// http://www.apache.org/licenses/LICENSE-2.0 +// +// Unless required by applicable law or agreed to in writing, +// software distributed under the License is distributed on an +// "AS IS" BASIS, WITHOUT WARRANTIES OR CONDITIONS OF ANY +// KIND, either express or implied. See the License for the +// specific language governing permissions and limitations +// under the License. + +#pragma once + +#include + +#include "arrow/util/logging.h" + +namespace arrow { + +namespace internal { +namespace tracing { + +// Forward declaration SpanImpl. +class SpanImpl; + +} // namespace tracing +} // namespace internal + +namespace util { +namespace tracing { + +class Span { + public: + using Impl = arrow::internal::tracing::SpanImpl; + + Span() = default; // Default constructor. The inner_impl is a nullptr. + ~Span(); // Destructor. Default destructor defined in tracing.cc where impl is a + // complete type. + + Impl& set_impl(const Impl&); + Impl& set_impl(Impl&&); + + const Impl& impl() const { + if (inner_impl) { + return *inner_impl; + } else { + ARROW_LOG(FATAL) << "Attempted to dereference a nullptr. Use Span::set_impl before " + "dereferencing."; + std::abort(); + } + } + + Impl& impl() { + if (inner_impl) { + return *inner_impl; + } else { + ARROW_LOG(FATAL) << "Attempted to dereference a nullptr. Use Span::set_impl before " + "dereferencing."; + std::abort(); + } + } + + private: + std::unique_ptr inner_impl; +}; + +} // namespace tracing +} // namespace util +} // namespace arrow diff --git a/cpp/src/arrow/util/tracing_internal.cc b/cpp/src/arrow/util/tracing_internal.cc index dc7dc49bfef..00ecaacfa4d 100644 --- a/cpp/src/arrow/util/tracing_internal.cc +++ b/cpp/src/arrow/util/tracing_internal.cc @@ -16,6 +16,7 @@ // under the License. #include "arrow/util/tracing_internal.h" +#include "arrow/util/tracing.h" #include #include @@ -183,6 +184,15 @@ opentelemetry::trace::Tracer* GetTracer() { return tracer.get(); } +#ifdef ARROW_WITH_OPENTELEMETRY +opentelemetry::trace::StartSpanOptions SpanOptionsWithParent( + const util::tracing::Span& parent_span) { + opentelemetry::trace::StartSpanOptions options; + options.parent = parent_span.impl().span->GetContext(); + return options; +} +#endif + } // namespace tracing } // namespace internal } // namespace arrow diff --git a/cpp/src/arrow/util/tracing_internal.h b/cpp/src/arrow/util/tracing_internal.h index 285a0e883b2..3c239149eb2 100644 --- a/cpp/src/arrow/util/tracing_internal.h +++ b/cpp/src/arrow/util/tracing_internal.h @@ -36,6 +36,8 @@ #include "arrow/util/async_generator.h" #include "arrow/util/iterator.h" +#include "arrow/util/make_unique.h" +#include "arrow/util/tracing.h" #include "arrow/util/visibility.h" namespace arrow { @@ -98,8 +100,52 @@ AsyncGenerator WrapAsyncGenerator(AsyncGenerator wrapped, return fut; }; } + +class SpanImpl { + public: + opentelemetry::nostd::shared_ptr span; +}; + +opentelemetry::trace::StartSpanOptions SpanOptionsWithParent( + const util::tracing::Span& parent_span); + +#define START_SPAN(target_span, ...) \ + auto opentelemetry_scope##__LINE__ = \ + ::arrow::internal::tracing::GetTracer()->WithActiveSpan( \ + target_span \ + .set_impl(::arrow::util::tracing::Span::Impl{ \ + ::arrow::internal::tracing::GetTracer()->StartSpan(__VA_ARGS__)}) \ + .span) + +#define START_SPAN_WITH_PARENT(target_span, parent_span, ...) \ + auto opentelemetry_scope##__LINE__ = \ + ::arrow::internal::tracing::GetTracer()->WithActiveSpan( \ + target_span \ + .set_impl(::arrow::util::tracing::Span::Impl{ \ + ::arrow::internal::tracing::GetTracer()->StartSpan( \ + __VA_ARGS__, \ + ::arrow::internal::tracing::SpanOptionsWithParent(parent_span))}) \ + .span) + +#define EVENT(target_span, ...) target_span.impl().span->AddEvent(__VA_ARGS__) + +#define MARK_SPAN(target_span, status) \ + ::arrow::internal::tracing::MarkSpan(status, target_span.impl().span.get()) + +#define END_SPAN(target_span) target_span.impl().span->End() + +#else + +class SpanImpl {}; + +#define START_SPAN(target_span, ...) +#define START_SPAN_WITH_PARENT(target_span, parent_span, ...) +#define MARK_SPAN(target_span, status) +#define EVENT(target_span, ...) +#define END_SPAN(target_span) + #endif } // namespace tracing } // namespace internal -} // namespace arrow +} // namespace arrow \ No newline at end of file From 635f825b889691f491fa833bdc9517f144dd8fb1 Mon Sep 17 00:00:00 2001 From: Matthijs Brobbel Date: Mon, 10 Jan 2022 16:00:10 +0100 Subject: [PATCH 04/15] Rename Span member functions to Set and Get --- cpp/src/arrow/util/tracing.cc | 4 ++-- cpp/src/arrow/util/tracing.h | 12 ++++++------ cpp/src/arrow/util/tracing_internal.cc | 2 +- cpp/src/arrow/util/tracing_internal.h | 12 ++++++------ 4 files changed, 15 insertions(+), 15 deletions(-) diff --git a/cpp/src/arrow/util/tracing.cc b/cpp/src/arrow/util/tracing.cc index 9bfd818a4a0..b8bddcd5052 100644 --- a/cpp/src/arrow/util/tracing.cc +++ b/cpp/src/arrow/util/tracing.cc @@ -25,12 +25,12 @@ namespace tracing { #ifdef ARROW_WITH_OPENTELEMETRY -Span::Impl& Span::set_impl(const Impl& impl) { +Span::Impl& Span::Set(const Impl& impl) { inner_impl.reset(new Impl(impl)); return *inner_impl; } -Span::Impl& Span::set_impl(Impl&& impl) { +Span::Impl& Span::Set(Impl&& impl) { inner_impl.reset(new Impl(std::move(impl))); return *inner_impl; } diff --git a/cpp/src/arrow/util/tracing.h b/cpp/src/arrow/util/tracing.h index 468134eecff..c972e6fd641 100644 --- a/cpp/src/arrow/util/tracing.h +++ b/cpp/src/arrow/util/tracing.h @@ -43,24 +43,24 @@ class Span { ~Span(); // Destructor. Default destructor defined in tracing.cc where impl is a // complete type. - Impl& set_impl(const Impl&); - Impl& set_impl(Impl&&); + Impl& Set(const Impl&); + Impl& Set(Impl&&); - const Impl& impl() const { + const Impl& Get() const { if (inner_impl) { return *inner_impl; } else { - ARROW_LOG(FATAL) << "Attempted to dereference a nullptr. Use Span::set_impl before " + ARROW_LOG(FATAL) << "Attempted to dereference a null pointer. Use Span::Set before " "dereferencing."; std::abort(); } } - Impl& impl() { + Impl& Get() { if (inner_impl) { return *inner_impl; } else { - ARROW_LOG(FATAL) << "Attempted to dereference a nullptr. Use Span::set_impl before " + ARROW_LOG(FATAL) << "Attempted to dereference a null pointer. Use Span::Set before " "dereferencing."; std::abort(); } diff --git a/cpp/src/arrow/util/tracing_internal.cc b/cpp/src/arrow/util/tracing_internal.cc index 00ecaacfa4d..5dbb0f345e4 100644 --- a/cpp/src/arrow/util/tracing_internal.cc +++ b/cpp/src/arrow/util/tracing_internal.cc @@ -188,7 +188,7 @@ opentelemetry::trace::Tracer* GetTracer() { opentelemetry::trace::StartSpanOptions SpanOptionsWithParent( const util::tracing::Span& parent_span) { opentelemetry::trace::StartSpanOptions options; - options.parent = parent_span.impl().span->GetContext(); + options.parent = parent_span.Get().span->GetContext(); return options; } #endif diff --git a/cpp/src/arrow/util/tracing_internal.h b/cpp/src/arrow/util/tracing_internal.h index 3c239149eb2..9d6c4e4218d 100644 --- a/cpp/src/arrow/util/tracing_internal.h +++ b/cpp/src/arrow/util/tracing_internal.h @@ -113,7 +113,7 @@ opentelemetry::trace::StartSpanOptions SpanOptionsWithParent( auto opentelemetry_scope##__LINE__ = \ ::arrow::internal::tracing::GetTracer()->WithActiveSpan( \ target_span \ - .set_impl(::arrow::util::tracing::Span::Impl{ \ + .Set(::arrow::util::tracing::Span::Impl{ \ ::arrow::internal::tracing::GetTracer()->StartSpan(__VA_ARGS__)}) \ .span) @@ -121,18 +121,18 @@ opentelemetry::trace::StartSpanOptions SpanOptionsWithParent( auto opentelemetry_scope##__LINE__ = \ ::arrow::internal::tracing::GetTracer()->WithActiveSpan( \ target_span \ - .set_impl(::arrow::util::tracing::Span::Impl{ \ + .Set(::arrow::util::tracing::Span::Impl{ \ ::arrow::internal::tracing::GetTracer()->StartSpan( \ __VA_ARGS__, \ ::arrow::internal::tracing::SpanOptionsWithParent(parent_span))}) \ .span) -#define EVENT(target_span, ...) target_span.impl().span->AddEvent(__VA_ARGS__) +#define EVENT(target_span, ...) target_span.Get().span->AddEvent(__VA_ARGS__) #define MARK_SPAN(target_span, status) \ - ::arrow::internal::tracing::MarkSpan(status, target_span.impl().span.get()) + ::arrow::internal::tracing::MarkSpan(status, target_span.Get().span.get()) -#define END_SPAN(target_span) target_span.impl().span->End() +#define END_SPAN(target_span) target_span.Get().span->End() #else @@ -148,4 +148,4 @@ class SpanImpl {}; } // namespace tracing } // namespace internal -} // namespace arrow \ No newline at end of file +} // namespace arrow From 31a31f708aa1d46c0c137386dbb60fac41b1eeae Mon Sep 17 00:00:00 2001 From: Matthijs Brobbel Date: Mon, 10 Jan 2022 16:00:49 +0100 Subject: [PATCH 05/15] Remove options from attributes in Function::Execute span --- cpp/src/arrow/compute/function.cc | 6 +++--- 1 file changed, 3 insertions(+), 3 deletions(-) diff --git a/cpp/src/arrow/compute/function.cc b/cpp/src/arrow/compute/function.cc index da05c81e7c8..57352a6b543 100644 --- a/cpp/src/arrow/compute/function.cc +++ b/cpp/src/arrow/compute/function.cc @@ -215,8 +215,9 @@ Result Function::Execute(const std::vector& args, } util::tracing::Span span; - START_SPAN(span, "Function::Execute", - {{"function", name()}, {"kind", kind()}, {"options", options->ToString()}}); + START_SPAN(span, "Function::Execute", {{"function", name()}, {"kind", kind()}}); + // todo(mb): add options to attributes. Requires fixing Option ToString impls for all + // option types. // type-check Datum arguments here. Really we'd like to avoid this as much as // possible @@ -259,7 +260,6 @@ Result Function::Execute(const std::vector& args, } namespace { - Status ValidateFunctionSummary(const std::string& s) { if (s.find('\n') != s.npos) { return Status::Invalid("summary contains a newline"); From 0e229e6e323ae30cc4bf3f3e22a78fafeda43326 Mon Sep 17 00:00:00 2001 From: Matthijs Brobbel Date: Mon, 10 Jan 2022 16:01:14 +0100 Subject: [PATCH 06/15] Handle invalid JoinType variants in ToString --- cpp/src/arrow/compute/exec/options.cc | 5 +++++ 1 file changed, 5 insertions(+) diff --git a/cpp/src/arrow/compute/exec/options.cc b/cpp/src/arrow/compute/exec/options.cc index 36345dfd7e1..585cc7a6a64 100644 --- a/cpp/src/arrow/compute/exec/options.cc +++ b/cpp/src/arrow/compute/exec/options.cc @@ -16,9 +16,11 @@ // under the License. #include "arrow/compute/exec/options.h" +#include "arrow/util/logging.h" namespace arrow { namespace compute { + std::string ToString(JoinType t) { switch (t) { case JoinType::LEFT_SEMI: @@ -38,6 +40,9 @@ std::string ToString(JoinType t) { case JoinType::FULL_OUTER: return "FULL_OUTER"; } + ARROW_LOG(FATAL) << "Invalid variant of arrow::compute::JoinType"; + std::abort(); } + } // namespace compute } // namespace arrow From 3fc407c97c2166aacfa014eaa7ab02a607dcc7e0 Mon Sep 17 00:00:00 2001 From: Matthijs Brobbel Date: Tue, 11 Jan 2022 20:47:26 +0100 Subject: [PATCH 07/15] Add ARROW_EXPORT to Span --- cpp/src/arrow/util/tracing.h | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/cpp/src/arrow/util/tracing.h b/cpp/src/arrow/util/tracing.h index c972e6fd641..56d9eb609b1 100644 --- a/cpp/src/arrow/util/tracing.h +++ b/cpp/src/arrow/util/tracing.h @@ -35,7 +35,7 @@ class SpanImpl; namespace util { namespace tracing { -class Span { +class ARROW_EXPORT Span { public: using Impl = arrow::internal::tracing::SpanImpl; From d6b5d0db4bc13ba0fc6f33bb50975733c630e08e Mon Sep 17 00:00:00 2001 From: Matthijs Brobbel Date: Tue, 11 Jan 2022 20:49:17 +0100 Subject: [PATCH 08/15] Handle nullptr in compute::internal::GenericToString(const std::shared_ptr&) --- cpp/src/arrow/compute/function_internal.h | 6 +++++- 1 file changed, 5 insertions(+), 1 deletion(-) diff --git a/cpp/src/arrow/compute/function_internal.h b/cpp/src/arrow/compute/function_internal.h index 926b95a9d56..f2303b87d90 100644 --- a/cpp/src/arrow/compute/function_internal.h +++ b/cpp/src/arrow/compute/function_internal.h @@ -125,7 +125,11 @@ static inline std::string GenericToString(const std::shared_ptr& value) { static inline std::string GenericToString(const std::shared_ptr& value) { std::stringstream ss; - ss << value->type->ToString() << ":" << value->ToString(); + if (value) { + ss << value->type->ToString() << ":" << value->ToString(); + } else { + ss << ""; + } return ss.str(); } From 68f9ec19acf42df49bc68f0866ab5a7c79798f00 Mon Sep 17 00:00:00 2001 From: Matthijs Brobbel Date: Tue, 11 Jan 2022 20:50:43 +0100 Subject: [PATCH 09/15] Modify Function::Execute span name and attributes --- cpp/src/arrow/compute/function.cc | 6 +++--- 1 file changed, 3 insertions(+), 3 deletions(-) diff --git a/cpp/src/arrow/compute/function.cc b/cpp/src/arrow/compute/function.cc index 57352a6b543..3ac6bced61c 100644 --- a/cpp/src/arrow/compute/function.cc +++ b/cpp/src/arrow/compute/function.cc @@ -215,9 +215,9 @@ Result Function::Execute(const std::vector& args, } util::tracing::Span span; - START_SPAN(span, "Function::Execute", {{"function", name()}, {"kind", kind()}}); - // todo(mb): add options to attributes. Requires fixing Option ToString impls for all - // option types. + START_SPAN(span, name(), + {{"detail", options ? options->ToString() : ""}, + {"function.kind", kind()}}); // type-check Datum arguments here. Really we'd like to avoid this as much as // possible From 881b533b17e3bf89536f010fd06543f8c37739c1 Mon Sep 17 00:00:00 2001 From: Matthijs Brobbel Date: Wed, 12 Jan 2022 21:17:41 +0100 Subject: [PATCH 10/15] Update spans and attributes --- cpp/src/arrow/compute/exec/aggregate_node.cc | 122 +++++++++++++------ cpp/src/arrow/compute/exec/exec_plan.cc | 39 +++--- cpp/src/arrow/compute/exec/exec_plan.h | 8 +- cpp/src/arrow/compute/exec/filter_node.cc | 20 ++- cpp/src/arrow/compute/exec/hash_join.cc | 18 +-- cpp/src/arrow/compute/exec/hash_join.h | 2 +- cpp/src/arrow/compute/exec/hash_join_node.cc | 33 +++-- cpp/src/arrow/compute/exec/project_node.cc | 18 ++- cpp/src/arrow/compute/exec/sink_node.cc | 57 ++++++--- cpp/src/arrow/compute/exec/source_node.cc | 14 ++- cpp/src/arrow/compute/exec/union_node.cc | 28 +++-- cpp/src/arrow/compute/function.cc | 12 +- cpp/src/arrow/util/tracing.h | 22 ++-- 13 files changed, 259 insertions(+), 134 deletions(-) diff --git a/cpp/src/arrow/compute/exec/aggregate_node.cc b/cpp/src/arrow/compute/exec/aggregate_node.cc index aea61cad55a..7dd33a980b9 100644 --- a/cpp/src/arrow/compute/exec/aggregate_node.cc +++ b/cpp/src/arrow/compute/exec/aggregate_node.cc @@ -166,11 +166,18 @@ class ScalarAggregateNode : public ExecNode { const char* kind_name() const override { return "ScalarAggregateNode"; } Status DoConsume(const ExecBatch& batch, size_t thread_index) { - util::tracing::Span inner_span; - START_SPAN_WITH_PARENT(inner_span, span, "ScalarAggregateNode::DoConsume", - {{"agg", ToStringExtra()}}); - + util::tracing::Span span; + START_SPAN(span, "Consume", + {{"aggregate", ToStringExtra()}, + {"node.label", label()}, + {"batch.length", batch.length}}); for (size_t i = 0; i < kernels_.size(); ++i) { + util::tracing::Span span; + START_SPAN(span, aggs_[i].function, + {{"function", aggs_[i].function}, + {"function.options", + aggs_[i].options ? aggs_[i].options->ToString() : ""}, + {"function.kind", "consume"}}); KernelContext batch_ctx{plan()->exec_context()}; batch_ctx.SetState(states_[i][thread_index].get()); @@ -181,7 +188,12 @@ class ScalarAggregateNode : public ExecNode { } void InputReceived(ExecNode* input, ExecBatch batch) override { - EVENT(span, "InputReceived", {{"batch.length", batch.length}}); + EVENT(span_, "InputReceived", {{"batch.length", batch.length}}); + util::tracing::Span span; + START_SPAN_WITH_PARENT(span, span_, "InputReceived", + {{"aggregate", ToStringExtra()}, + {"node.label", label()}, + {"batch.length", batch.length}}); DCHECK_EQ(input, inputs_[0]); auto thread_index = get_thread_index_(); @@ -194,13 +206,13 @@ class ScalarAggregateNode : public ExecNode { } void ErrorReceived(ExecNode* input, Status error) override { - EVENT(span, "ErrorReceived", {{"error", error.message()}}); + EVENT(span_, "ErrorReceived", {{"error", error.message()}}); DCHECK_EQ(input, inputs_[0]); outputs_[0]->ErrorReceived(this, std::move(error)); } void InputFinished(ExecNode* input, int total_batches) override { - EVENT(span, "InputFinished", {{"batches.length", total_batches}}); + EVENT(span_, "InputFinished", {{"batches.length", total_batches}}); DCHECK_EQ(input, inputs_[0]); if (input_counter_.SetTotal(total_batches)) { ErrorIfNotOk(Finish()); @@ -208,16 +220,25 @@ class ScalarAggregateNode : public ExecNode { } Status StartProducing() override { - START_SPAN(span, kind_name(), {{"node", ToString()}}); + START_SPAN(span_, std::string(kind_name()) + ":" + label(), + {{"node.label", label()}, + {"node.detail", ToString()}, + {"node.kind", kind_name()}}); finished_ = Future<>::Make(); +#ifdef ARROW_WITH_OPENTELEMETRY + finished_.AddCallback([this](const Status& st) { + MARK_SPAN(span_, st); + END_SPAN(span_); + }); +#endif // Scalar aggregates will only output a single batch outputs_[0]->InputFinished(this, 1); return Status::OK(); } - void PauseProducing(ExecNode* output) override { EVENT(span, "PauseProducing"); } + void PauseProducing(ExecNode* output) override { EVENT(span_, "PauseProducing"); } - void ResumeProducing(ExecNode* output) override { EVENT(span, "ResumeProducing"); } + void ResumeProducing(ExecNode* output) override { EVENT(span_, "ResumeProducing"); } void StopProducing(ExecNode* output) override { DCHECK_EQ(output, outputs_[0]); @@ -225,9 +246,8 @@ class ScalarAggregateNode : public ExecNode { } void StopProducing() override { - EVENT(span, "StopProducing"); + EVENT(span_, "StopProducing"); if (input_counter_.Cancel()) { - END_SPAN(span); finished_.MarkFinished(); } inputs_[0]->StopProducing(this); @@ -245,10 +265,18 @@ class ScalarAggregateNode : public ExecNode { private: Status Finish() { + util::tracing::Span span; + START_SPAN(span, "Finish", {{"aggregate", ToStringExtra()}, {"node.label", label()}}); ExecBatch batch{{}, 1}; batch.values.resize(kernels_.size()); for (size_t i = 0; i < kernels_.size(); ++i) { + util::tracing::Span span; + START_SPAN(span, aggs_[i].function, + {{"function", aggs_[i].function}, + {"function.options", + aggs_[i].options ? aggs_[i].options->ToString() : ""}, + {"function.kind", "finalize"}}); KernelContext ctx{plan()->exec_context()}; ARROW_ASSIGN_OR_RAISE(auto merged, ScalarAggregateKernel::MergeAll( kernels_[i], &ctx, std::move(states_[i]))); @@ -256,12 +284,10 @@ class ScalarAggregateNode : public ExecNode { } outputs_[0]->InputReceived(this, std::move(batch)); - END_SPAN(span); finished_.MarkFinished(); return Status::OK(); } - Future<> finished_ = Future<>::MakeFinished(); const std::vector target_field_ids_; const std::vector aggs_; const std::vector kernels_; @@ -369,8 +395,11 @@ class GroupByNode : public ExecNode { const char* kind_name() const override { return "GroupByNode"; } Status Consume(ExecBatch batch) { - util::tracing::Span inner_span; - START_SPAN_WITH_PARENT(inner_span, span, "GroupByNode::Consume"); + util::tracing::Span span; + START_SPAN(span, "Consume", + {{"group_by", ToStringExtra()}, + {"node.label", label()}, + {"batch.length", batch.length}}); size_t thread_index = get_thread_index_(); if (thread_index >= local_states_.size()) { return Status::IndexError("thread index ", thread_index, " is out of range [0, ", @@ -393,7 +422,11 @@ class GroupByNode : public ExecNode { // Execute aggregate kernels for (size_t i = 0; i < agg_kernels_.size(); ++i) { util::tracing::Span span; - START_SPAN(span, "Aggregate", {{"function", aggs_[i].function}}); + START_SPAN(span, aggs_[i].function, + {{"function", aggs_[i].function}, + {"function.options", + aggs_[i].options ? aggs_[i].options->ToString() : ""}, + {"function.kind", "consume"}}); KernelContext kernel_ctx{ctx_}; kernel_ctx.SetState(state->agg_states[i].get()); @@ -409,8 +442,8 @@ class GroupByNode : public ExecNode { } Status Merge() { - util::tracing::Span inner_span; - START_SPAN_WITH_PARENT(inner_span, span, "GroupByNode::Merge"); + util::tracing::Span span; + START_SPAN(span, "Merge", {{"group_by", ToStringExtra()}, {"node.label", label()}}); ThreadLocalState* state0 = &local_states_[0]; for (size_t i = 1; i < local_states_.size(); ++i) { ThreadLocalState* state = &local_states_[i]; @@ -424,7 +457,11 @@ class GroupByNode : public ExecNode { for (size_t i = 0; i < agg_kernels_.size(); ++i) { util::tracing::Span span; - START_SPAN(span, "MergeKernel", {{"function", aggs_[i].function}}); + START_SPAN(span, aggs_[i].function, + {{"function", aggs_[i].function}, + {"function.options", + aggs_[i].options ? aggs_[i].options->ToString() : ""}, + {"function.kind", "merge"}}); KernelContext batch_ctx{ctx_}; DCHECK(state0->agg_states[i]); batch_ctx.SetState(state0->agg_states[i].get()); @@ -439,8 +476,9 @@ class GroupByNode : public ExecNode { } Result Finalize() { - util::tracing::Span inner_span; - START_SPAN_WITH_PARENT(inner_span, span, "GroupByNode::Finalize"); + util::tracing::Span span; + START_SPAN(span, "Finalize", + {{"group_by", ToStringExtra()}, {"node.label", label()}}); ThreadLocalState* state = &local_states_[0]; // If we never got any batches, then state won't have been initialized @@ -451,6 +489,12 @@ class GroupByNode : public ExecNode { // Aggregate fields come before key fields to match the behavior of GroupBy function for (size_t i = 0; i < agg_kernels_.size(); ++i) { + util::tracing::Span span; + START_SPAN(span, aggs_[i].function, + {{"function", aggs_[i].function}, + {"function.options", + aggs_[i].options ? aggs_[i].options->ToString() : ""}, + {"function.kind", "finalize"}}); KernelContext batch_ctx{ctx_}; batch_ctx.SetState(state->agg_states[i].get()); RETURN_NOT_OK(agg_kernels_[i]->finalize(&batch_ctx, &out_data.values[i])); @@ -502,13 +546,16 @@ class GroupByNode : public ExecNode { } } - END_SPAN(span); - return Status::OK(); } void InputReceived(ExecNode* input, ExecBatch batch) override { - EVENT(span, "InputReceived", {{"batch.length", batch.length}}); + EVENT(span_, "InputReceived", {{"batch.length", batch.length}}); + util::tracing::Span span; + START_SPAN_WITH_PARENT(span, span_, "InputReceived", + {{"group_by", ToStringExtra()}, + {"node.label", label()}, + {"batch.length", batch.length}}); // bail if StopProducing was called if (finished_.is_finished()) return; @@ -523,7 +570,7 @@ class GroupByNode : public ExecNode { } void ErrorReceived(ExecNode* input, Status error) override { - EVENT(span, "ErrorReceived", {{"error", error.message()}}); + EVENT(span_, "ErrorReceived", {{"error", error.message()}}); DCHECK_EQ(input, inputs_[0]); @@ -531,7 +578,7 @@ class GroupByNode : public ExecNode { } void InputFinished(ExecNode* input, int total_batches) override { - EVENT(span, "InputFinished", {{"batches.length", total_batches}}); + EVENT(span_, "InputFinished", {{"batches.length", total_batches}}); // bail if StopProducing was called if (finished_.is_finished()) return; @@ -544,26 +591,32 @@ class GroupByNode : public ExecNode { } Status StartProducing() override { - START_SPAN(span, kind_name(), {{"node", ToString()}}); - + START_SPAN(span_, std::string(kind_name()) + ":" + label(), + {{"node.label", label()}, + {"node.detail", ToString()}, + {"node.kind", kind_name()}}); finished_ = Future<>::Make(); +#ifdef ARROW_WITH_OPENTELEMETRY + finished_.AddCallback([this](const Status& st) { + MARK_SPAN(span_, st); + END_SPAN(span_); + }); +#endif local_states_.resize(ThreadIndexer::Capacity()); return Status::OK(); } - void PauseProducing(ExecNode* output) override { EVENT(span, "PauseProducing"); } + void PauseProducing(ExecNode* output) override { EVENT(span_, "PauseProducing"); } - void ResumeProducing(ExecNode* output) override { EVENT(span, "ResumeProducing"); } + void ResumeProducing(ExecNode* output) override { EVENT(span_, "ResumeProducing"); } void StopProducing(ExecNode* output) override { + EVENT(span_, "StopProducing"); DCHECK_EQ(output, outputs_[0]); - EVENT(span, "StopProducing"); - ARROW_UNUSED(input_counter_.Cancel()); if (output_counter_.Cancel()) { - END_SPAN(span); finished_.MarkFinished(); } inputs_[0]->StopProducing(this); @@ -638,7 +691,6 @@ class GroupByNode : public ExecNode { } ExecContext* ctx_; - Future<> finished_ = Future<>::MakeFinished(); const std::vector key_field_ids_; const std::vector agg_src_field_ids_; diff --git a/cpp/src/arrow/compute/exec/exec_plan.cc b/cpp/src/arrow/compute/exec/exec_plan.cc index 66a1723318f..2780b7e23bb 100644 --- a/cpp/src/arrow/compute/exec/exec_plan.cc +++ b/cpp/src/arrow/compute/exec/exec_plan.cc @@ -79,7 +79,7 @@ struct ExecPlanImpl : public ExecPlan { } Status StartProducing() { - START_SPAN(span, "ExecPlan", {{"plan", ToString()}}); + START_SPAN(span_, "ExecPlan", {{"plan", ToString()}}); if (started_) { return Status::Invalid("restarted ExecPlan"); @@ -97,7 +97,10 @@ struct ExecPlanImpl : public ExecPlan { for (rev_it it(sorted_nodes_.end()), end(sorted_nodes_.begin()); it != end; ++it) { auto node = *it; + EVENT(span_, "StartProducing:" + node->label(), + {{"node.label", node->label()}, {"node.kind_name", node->kind_name()}}); st = node->StartProducing(); + EVENT(span_, "StartProducing:" + node->label(), {{"status", st.ToString()}}); if (!st.ok()) { // Stop nodes that successfully started, in reverse order stopped_ = true; @@ -111,16 +114,16 @@ struct ExecPlanImpl : public ExecPlan { finished_ = AllFinished(futures); #ifdef ARROW_WITH_OPENTELEMETRY finished_.AddCallback([this](const Status& st) { - MARK_SPAN(span, st); - END_SPAN(span); + MARK_SPAN(span_, st); + END_SPAN(span_); }); #endif return st; } void StopProducing() { - EVENT(span, "StopProducing"); DCHECK(started_) << "stopped an ExecPlan which never started"; + EVENT(span_, "StopProducing"); stopped_ = true; StopProducingImpl(sorted_nodes_.begin(), sorted_nodes_.end()); @@ -130,6 +133,8 @@ struct ExecPlanImpl : public ExecPlan { void StopProducingImpl(It begin, It end) { for (auto it = begin; it != end; ++it) { auto node = *it; + EVENT(span_, "StopProducing:" + node->label(), + {{"node.label", node->label()}, {"node.kind_name", node->kind_name()}}); node->StopProducing(); } } @@ -182,8 +187,7 @@ struct ExecPlanImpl : public ExecPlan { NodeVector sources_, sinks_; NodeVector sorted_nodes_; uint32_t auto_label_counter_ = 0; - - util::tracing::Span span; + util::tracing::Span span_; }; ExecPlanImpl* ToDerived(ExecPlan* ptr) { return checked_cast(ptr); } @@ -327,14 +331,14 @@ MapNode::MapNode(ExecPlan* plan, std::vector inputs, } void MapNode::ErrorReceived(ExecNode* input, Status error) { - EVENT(span, "ErrorReceived", {{"error", error.message()}}); DCHECK_EQ(input, inputs_[0]); + EVENT(span_, "ErrorReceived", {{"error.message", error.message()}}); outputs_[0]->ErrorReceived(this, std::move(error)); } void MapNode::InputFinished(ExecNode* input, int total_batches) { - EVENT(span, "InputFinished", {{"batches.length", total_batches}}); DCHECK_EQ(input, inputs_[0]); + EVENT(span_, "InputFinished", {{"batches.length", total_batches}}); outputs_[0]->InputFinished(this, total_batches); if (input_counter_.SetTotal(total_batches)) { this->Finish(); @@ -342,13 +346,22 @@ void MapNode::InputFinished(ExecNode* input, int total_batches) { } Status MapNode::StartProducing() { - START_SPAN(span, kind_name(), {{"node", ToString()}}); + START_SPAN( + span_, std::string(kind_name()) + ":" + label(), + {{"node.label", label()}, {"node.detail", ToString()}, {"node.kind", kind_name()}}); + finished_ = Future<>::Make(); +#ifdef ARROW_WITH_OPENTELEMETRY + finished_.AddCallback([this](const Status& st) { + MARK_SPAN(span_, st); + END_SPAN(span_); + }); +#endif return Status::OK(); } -void MapNode::PauseProducing(ExecNode* output) { EVENT(span, "PauseProducing"); } +void MapNode::PauseProducing(ExecNode* output) { EVENT(span_, "PauseProducing"); } -void MapNode::ResumeProducing(ExecNode* output) { EVENT(span, "ResumeProducing"); } +void MapNode::ResumeProducing(ExecNode* output) { EVENT(span_, "ResumeProducing"); } void MapNode::StopProducing(ExecNode* output) { DCHECK_EQ(output, outputs_[0]); @@ -356,7 +369,7 @@ void MapNode::StopProducing(ExecNode* output) { } void MapNode::StopProducing() { - EVENT(span, "StopProducing"); + EVENT(span_, "StopProducing"); if (executor_) { this->stop_source_.RequestStop(); } @@ -423,8 +436,6 @@ void MapNode::Finish(Status finish_st /*= Status::OK()*/) { } else { this->finished_.MarkFinished(finish_st); } - MARK_SPAN(span, finish_st); - END_SPAN(span); } std::shared_ptr MakeGeneratorReader( diff --git a/cpp/src/arrow/compute/exec/exec_plan.h b/cpp/src/arrow/compute/exec/exec_plan.h index 00278a109e6..ea9b6c72686 100644 --- a/cpp/src/arrow/compute/exec/exec_plan.h +++ b/cpp/src/arrow/compute/exec/exec_plan.h @@ -247,7 +247,10 @@ class ARROW_EXPORT ExecNode { int num_outputs_; NodeVector outputs_; - util::tracing::Span span; + // Future to sync finished + Future<> finished_ = Future<>::MakeFinished(); + + util::tracing::Span span_; }; /// \brief MapNode is an ExecNode type class which process a task like filter/project @@ -288,9 +291,6 @@ class MapNode : public ExecNode { // Counter for the number of batches received AtomicCounter input_counter_; - // Future to sync finished - Future<> finished_ = Future<>::Make(); - // The task group for the corresponding batches util::AsyncTaskGroup task_group_; diff --git a/cpp/src/arrow/compute/exec/filter_node.cc b/cpp/src/arrow/compute/exec/filter_node.cc index c15aad4845b..c6de5280a4c 100644 --- a/cpp/src/arrow/compute/exec/filter_node.cc +++ b/cpp/src/arrow/compute/exec/filter_node.cc @@ -70,6 +70,12 @@ class FilterNode : public MapNode { ARROW_ASSIGN_OR_RAISE(Expression simplified_filter, SimplifyWithGuarantee(filter_, target.guarantee)); + util::tracing::Span span; + START_SPAN(span, "Filter", + {{"filter.expression", ToStringExtra()}, + {"filter.expression.simplified", simplified_filter.ToString()}, + {"filter.length", target.length}}); + ARROW_ASSIGN_OR_RAISE(Datum mask, ExecuteScalarExpression(simplified_filter, target, plan()->exec_context())); @@ -94,15 +100,17 @@ class FilterNode : public MapNode { } void InputReceived(ExecNode* input, ExecBatch batch) override { - EVENT(span, "InputReceived", {{"batch.length", batch.length}}); - + EVENT(span_, "InputReceived", {{"batch.length", batch.length}}); DCHECK_EQ(input, inputs_[0]); auto func = [this](ExecBatch batch) { - util::tracing::Span inner_span; - START_SPAN_WITH_PARENT(inner_span, span, "FilterNode::DoFilter"); + util::tracing::Span span; + START_SPAN_WITH_PARENT(span, span_, "InputReceived", + {{"filter", ToStringExtra()}, + {"node.label", label()}, + {"batch.length", batch.length}}); auto result = DoFilter(std::move(batch)); - MARK_SPAN(inner_span, result.status()); - END_SPAN(inner_span); + MARK_SPAN(span, result.status()); + END_SPAN(span); return result; }; this->SubmitTask(std::move(func), std::move(batch)); diff --git a/cpp/src/arrow/compute/exec/hash_join.cc b/cpp/src/arrow/compute/exec/hash_join.cc index 3d8e1235320..a3adbb2d753 100644 --- a/cpp/src/arrow/compute/exec/hash_join.cc +++ b/cpp/src/arrow/compute/exec/hash_join.cc @@ -42,7 +42,7 @@ class HashJoinBasicImpl : public HashJoinImpl { if (cancelled_) { return Status::Cancelled("Hash join cancelled"); } - EVENT(span, "InputReceived"); + EVENT(span_, "InputReceived"); if (QueueBatchIfNeeded(side, batch)) { return Status::OK(); @@ -56,7 +56,7 @@ class HashJoinBasicImpl : public HashJoinImpl { if (cancelled_) { return Status::Cancelled("Hash join cancelled"); } - EVENT(span, "InputFinished", {{"side", side}}); + EVENT(span_, "InputFinished", {{"side", side}}); if (side == 0) { bool proceed; { @@ -89,10 +89,10 @@ class HashJoinBasicImpl : public HashJoinImpl { TaskScheduler::ScheduleImpl schedule_task_callback) override { num_threads = std::max(num_threads, static_cast(1)); - START_SPAN(span, "HashJoinBasicImpl", - {{"join_type", ToString(join_type)}, - {"expression", filter.ToString()}, - {"num_threads", static_cast(num_threads)}}); + START_SPAN(span_, "HashJoinBasicImpl", + {{"detail", filter.ToString()}, + {"join.kind", ToString(join_type)}, + {"join.threads", static_cast(num_threads)}}); ctx_ = ctx; join_type_ = join_type; @@ -129,8 +129,8 @@ class HashJoinBasicImpl : public HashJoinImpl { } void Abort(TaskScheduler::AbortContinuationImpl pos_abort_callback) override { - EVENT(span, "Abort"); - END_SPAN(span); + EVENT(span_, "Abort"); + END_SPAN(span_); cancelled_ = true; scheduler_->Abort(std::move(pos_abort_callback)); } @@ -784,7 +784,7 @@ class HashJoinBasicImpl : public HashJoinImpl { if (cancelled_) { return Status::Cancelled("Hash join cancelled"); } - END_SPAN(span); + END_SPAN(span_); finished_callback_(num_batches_produced_.load()); return Status::OK(); } diff --git a/cpp/src/arrow/compute/exec/hash_join.h b/cpp/src/arrow/compute/exec/hash_join.h index 9ee2980df4f..83ad4cb3f90 100644 --- a/cpp/src/arrow/compute/exec/hash_join.h +++ b/cpp/src/arrow/compute/exec/hash_join.h @@ -115,7 +115,7 @@ class HashJoinImpl { static Result> MakeBasic(); protected: - util::tracing::Span span; + util::tracing::Span span_; }; } // namespace compute diff --git a/cpp/src/arrow/compute/exec/hash_join_node.cc b/cpp/src/arrow/compute/exec/hash_join_node.cc index 9334e287c8f..bb658ba4eb0 100644 --- a/cpp/src/arrow/compute/exec/hash_join_node.cc +++ b/cpp/src/arrow/compute/exec/hash_join_node.cc @@ -493,7 +493,10 @@ class HashJoinNode : public ExecNode { size_t thread_index = thread_indexer_(); int side = (input == inputs_[0]) ? 0 : 1; - EVENT(span, "InputReceived", {{"batch.length", batch.length}, {"side", side}}); + EVENT(span_, "InputReceived", {{"batch.length", batch.length}, {"side", side}}); + util::tracing::Span span; + START_SPAN_WITH_PARENT(span, span_, "InputReceived", + {{"batch.length", batch.length}}); { Status status = impl_->InputReceived(thread_index, side, std::move(batch)); @@ -514,7 +517,7 @@ class HashJoinNode : public ExecNode { } void ErrorReceived(ExecNode* input, Status error) override { - EVENT(span, "ErrorReceived", {{"error", error.message()}}); + EVENT(span_, "ErrorReceived", {{"error", error.message()}}); DCHECK_EQ(input, inputs_[0]); StopProducing(); outputs_[0]->ErrorReceived(this, std::move(error)); @@ -526,7 +529,7 @@ class HashJoinNode : public ExecNode { size_t thread_index = thread_indexer_(); int side = (input == inputs_[0]) ? 0 : 1; - EVENT(span, "InputFinished", {{"side", side}, {"batches.length", total_batches}}); + EVENT(span_, "InputFinished", {{"side", side}, {"batches.length", total_batches}}); if (batch_count_[side].SetTotal(total_batches)) { Status status = impl_->InputFinished(thread_index, side); @@ -539,8 +542,17 @@ class HashJoinNode : public ExecNode { } Status StartProducing() override { - START_SPAN(span, kind_name(), {{"node", ToString()}}); + START_SPAN(span_, std::string(kind_name()) + ":" + label(), + {{"node.label", label()}, + {"node.detail", ToString()}, + {"node.kind", kind_name()}}); finished_ = Future<>::Make(); +#ifdef ARROW_WITH_OPENTELEMETRY + finished_.AddCallback([this](const Status& st) { + MARK_SPAN(span_, st); + END_SPAN(span_); + }); +#endif bool use_sync_execution = !(plan_->exec_context()->executor()); size_t num_threads = use_sync_execution ? 1 : thread_indexer_.Capacity(); @@ -556,9 +568,9 @@ class HashJoinNode : public ExecNode { return Status::OK(); } - void PauseProducing(ExecNode* output) override { EVENT(span, "PauseProducing"); } + void PauseProducing(ExecNode* output) override { EVENT(span_, "PauseProducing"); } - void ResumeProducing(ExecNode* output) override { EVENT(span, "ResumeProducing"); } + void ResumeProducing(ExecNode* output) override { EVENT(span_, "ResumeProducing"); } void StopProducing(ExecNode* output) override { DCHECK_EQ(output, outputs_[0]); @@ -566,16 +578,13 @@ class HashJoinNode : public ExecNode { } void StopProducing() override { - EVENT(span, "StopProducing"); + EVENT(span_, "StopProducing"); bool expected = false; if (complete_.compare_exchange_strong(expected, true)) { for (auto&& input : inputs_) { input->StopProducing(this); } - impl_->Abort([this]() { - END_SPAN(span); - finished_.MarkFinished(); - }); + impl_->Abort([this]() { finished_.MarkFinished(); }); } } @@ -590,7 +599,6 @@ class HashJoinNode : public ExecNode { bool expected = false; if (complete_.compare_exchange_strong(expected, true)) { outputs_[0]->InputFinished(this, static_cast(total_num_batches)); - END_SPAN(span); finished_.MarkFinished(); } } @@ -617,7 +625,6 @@ class HashJoinNode : public ExecNode { private: AtomicCounter batch_count_[2]; std::atomic complete_; - Future<> finished_ = Future<>::MakeFinished(); JoinType join_type_; std::vector key_cmp_; Expression filter_; diff --git a/cpp/src/arrow/compute/exec/project_node.cc b/cpp/src/arrow/compute/exec/project_node.cc index adfd2940510..69d9011d746 100644 --- a/cpp/src/arrow/compute/exec/project_node.cc +++ b/cpp/src/arrow/compute/exec/project_node.cc @@ -80,6 +80,11 @@ class ProjectNode : public MapNode { Result DoProject(const ExecBatch& target) { std::vector values{exprs_.size()}; for (size_t i = 0; i < exprs_.size(); ++i) { + util::tracing::Span span; + START_SPAN(span, "Project", + {{"project.descr", exprs_[i].descr().ToString()}, + {"project.length", target.length}, + {"project.expression", exprs_[i].ToString()}}); ARROW_ASSIGN_OR_RAISE(Expression simplified_expr, SimplifyWithGuarantee(exprs_[i], target.guarantee)); @@ -90,14 +95,17 @@ class ProjectNode : public MapNode { } void InputReceived(ExecNode* input, ExecBatch batch) override { - EVENT(span, "InputReceived", {{"batch.length", batch.length}}); + EVENT(span_, "InputReceived", {{"batch.length", batch.length}}); DCHECK_EQ(input, inputs_[0]); auto func = [this](ExecBatch batch) { - util::tracing::Span inner_span; - START_SPAN_WITH_PARENT(inner_span, span, "ProjectNode::DoProject"); + util::tracing::Span span; + START_SPAN_WITH_PARENT(span, span_, "InputReceived", + {{"project", ToStringExtra()}, + {"node.label", label()}, + {"batch.length", batch.length}}); auto result = DoProject(std::move(batch)); - MARK_SPAN(inner_span, result.status()); - END_SPAN(inner_span); + MARK_SPAN(span, result.status()); + END_SPAN(span); return result; }; this->SubmitTask(std::move(func), std::move(batch)); diff --git a/cpp/src/arrow/compute/exec/sink_node.cc b/cpp/src/arrow/compute/exec/sink_node.cc index e68f63801e2..ce2e969c9b2 100644 --- a/cpp/src/arrow/compute/exec/sink_node.cc +++ b/cpp/src/arrow/compute/exec/sink_node.cc @@ -77,8 +77,17 @@ class SinkNode : public ExecNode { const char* kind_name() const override { return "SinkNode"; } Status StartProducing() override { - START_SPAN(span, kind_name(), {{"node", ToString()}}); + START_SPAN(span_, std::string(kind_name()) + ":" + label(), + {{"node.label", label()}, + {"node.detail", ToString()}, + {"node.kind", kind_name()}}); finished_ = Future<>::Make(); +#ifdef ARROW_WITH_OPENTELEMETRY + finished_.AddCallback([this](const Status& st) { + MARK_SPAN(span_, st); + END_SPAN(span_); + }); +#endif return Status::OK(); } @@ -91,7 +100,7 @@ class SinkNode : public ExecNode { [[noreturn]] void StopProducing(ExecNode* output) override { NoOutputs(); } void StopProducing() override { - EVENT(span, "StopProducing"); + EVENT(span_, "StopProducing"); Finish(); inputs_[0]->StopProducing(this); @@ -100,7 +109,11 @@ class SinkNode : public ExecNode { Future<> finished() override { return finished_; } void InputReceived(ExecNode* input, ExecBatch batch) override { - EVENT(span, "InputReceived", {{"batch.length", batch.length}}); + EVENT(span_, "InputReceived", {{"batch.length", batch.length}}); + util::tracing::Span span; + START_SPAN_WITH_PARENT(span, span_, "InputReceived", + {{"node.label", label()}, {"batch.length", batch.length}}); + DCHECK_EQ(input, inputs_[0]); bool did_push = producer_.Push(std::move(batch)); @@ -112,7 +125,7 @@ class SinkNode : public ExecNode { } void ErrorReceived(ExecNode* input, Status error) override { - EVENT(span, "ErrorReceived", {{"error", error.message()}}); + EVENT(span_, "ErrorReceived", {{"error", error.message()}}); DCHECK_EQ(input, inputs_[0]); producer_.Push(std::move(error)); @@ -124,7 +137,7 @@ class SinkNode : public ExecNode { } void InputFinished(ExecNode* input, int total_batches) override { - EVENT(span, "InputFinished", {{"batches.length", total_batches}}); + EVENT(span_, "InputFinished", {{"batches.length", total_batches}}); if (input_counter_.SetTotal(total_batches)) { Finish(); } @@ -132,14 +145,12 @@ class SinkNode : public ExecNode { protected: virtual void Finish() { - END_SPAN(span); if (producer_.Close()) { finished_.MarkFinished(); } } AtomicCounter input_counter_; - Future<> finished_ = Future<>::MakeFinished(); PushGenerator>::Producer producer_; }; @@ -168,8 +179,17 @@ class ConsumingSinkNode : public ExecNode { const char* kind_name() const override { return "ConsumingSinkNode"; } Status StartProducing() override { - START_SPAN(span, kind_name(), {{"node", ToString()}}); + START_SPAN(span_, std::string(kind_name()) + ":" + label(), + {{"node.label", label()}, + {"node.detail", ToString()}, + {"node.kind", kind_name()}}); finished_ = Future<>::Make(); +#ifdef ARROW_WITH_OPENTELEMETRY + finished_.AddCallback([this](const Status& st) { + MARK_SPAN(span_, st); + END_SPAN(span_); + }); +#endif return Status::OK(); } @@ -182,7 +202,7 @@ class ConsumingSinkNode : public ExecNode { [[noreturn]] void StopProducing(ExecNode* output) override { NoOutputs(); } void StopProducing() override { - EVENT(span, "StopProducing"); + EVENT(span_, "StopProducing"); Finish(Status::Invalid("ExecPlan was stopped early")); inputs_[0]->StopProducing(this); } @@ -190,7 +210,11 @@ class ConsumingSinkNode : public ExecNode { Future<> finished() override { return finished_; } void InputReceived(ExecNode* input, ExecBatch batch) override { - EVENT(span, "InputReceived", {{"batch.length", batch.length}}); + EVENT(span_, "InputReceived", {{"batch.length", batch.length}}); + util::tracing::Span span; + START_SPAN_WITH_PARENT(span, span_, "InputReceived", + {{"node.label", label()}, {"batch.length", batch.length}}); + DCHECK_EQ(input, inputs_[0]); // This can happen if an error was received and the source hasn't yet stopped. Since @@ -214,7 +238,7 @@ class ConsumingSinkNode : public ExecNode { } void ErrorReceived(ExecNode* input, Status error) override { - EVENT(span, "ErrorReceived", {{"error", error.message()}}); + EVENT(span_, "ErrorReceived", {{"error", error.message()}}); DCHECK_EQ(input, inputs_[0]); if (input_counter_.Cancel()) { @@ -225,7 +249,7 @@ class ConsumingSinkNode : public ExecNode { } void InputFinished(ExecNode* input, int total_batches) override { - EVENT(span, "InputFinished", {{"batches.length", total_batches}}); + EVENT(span_, "InputFinished", {{"batches.length", total_batches}}); if (input_counter_.SetTotal(total_batches)) { Finish(Status::OK()); } @@ -236,15 +260,12 @@ class ConsumingSinkNode : public ExecNode { consumer_->Finish().AddCallback([this, finish_st](const Status& st) { // Prefer the plan error over the consumer error Status final_status = finish_st & st; - MARK_SPAN(span, final_status); - END_SPAN(span); finished_.MarkFinished(std::move(final_status)); }); } AtomicCounter input_counter_; - Future<> finished_ = Future<>::MakeFinished(); std::shared_ptr consumer_; }; @@ -290,7 +311,11 @@ struct OrderBySinkNode final : public SinkNode { } void InputReceived(ExecNode* input, ExecBatch batch) override { - EVENT(span, "InputReceived", {{"batch.length", batch.length}}); + EVENT(span_, "InputReceived", {{"batch.length", batch.length}}); + util::tracing::Span span; + START_SPAN_WITH_PARENT(span, span_, "InputReceived", + {{"node.label", label()}, {"batch.length", batch.length}}); + DCHECK_EQ(input, inputs_[0]); auto maybe_batch = batch.ToRecordBatch(inputs_[0]->output_schema(), diff --git a/cpp/src/arrow/compute/exec/source_node.cc b/cpp/src/arrow/compute/exec/source_node.cc index 46bba5609d4..d29365b628e 100644 --- a/cpp/src/arrow/compute/exec/source_node.cc +++ b/cpp/src/arrow/compute/exec/source_node.cc @@ -32,6 +32,7 @@ #include "arrow/util/logging.h" #include "arrow/util/optional.h" #include "arrow/util/thread_pool.h" +#include "arrow/util/tracing_internal.h" #include "arrow/util/unreachable.h" namespace arrow { @@ -66,6 +67,11 @@ struct SourceNode : ExecNode { [[noreturn]] void InputFinished(ExecNode*, int) override { NoInputs(); } Status StartProducing() override { + START_SPAN(span_, std::string(kind_name()) + ":" + label(), + {{"node.kind", kind_name()}, + {"node.label", label()}, + {"node.output_schema", output_schema()->ToString()}, + {"node.detail", ToString()}}); { // If another exec node encountered an error during its StartProducing call // it might have already called StopProducing on all of its inputs (including this @@ -140,7 +146,12 @@ struct SourceNode : ExecNode { outputs_[0]->InputFinished(this, total_batches); return task_group_.End(); }); - +#ifdef ARROW_WITH_OPENTELEMETRY + finished_.AddCallback([this](const Status& st) { + MARK_SPAN(span_, st); + END_SPAN(span_); + }); +#endif return Status::OK(); } @@ -164,7 +175,6 @@ struct SourceNode : ExecNode { std::mutex mutex_; bool stop_requested_{false}; int batch_count_{0}; - Future<> finished_ = Future<>::MakeFinished(); util::AsyncTaskGroup task_group_; AsyncGenerator> generator_; }; diff --git a/cpp/src/arrow/compute/exec/union_node.cc b/cpp/src/arrow/compute/exec/union_node.cc index 87c8708f526..9edf0a00cc8 100644 --- a/cpp/src/arrow/compute/exec/union_node.cc +++ b/cpp/src/arrow/compute/exec/union_node.cc @@ -76,7 +76,7 @@ class UnionNode : public ExecNode { } void InputReceived(ExecNode* input, ExecBatch batch) override { - EVENT(span, "InputReceived", {{"batch.length", batch.length}}); + EVENT(span_, "InputReceived", {{"batch.length", batch.length}}); ARROW_DCHECK(std::find(inputs_.begin(), inputs_.end(), input) != inputs_.end()); if (finished_.is_finished()) { @@ -84,13 +84,12 @@ class UnionNode : public ExecNode { } outputs_[0]->InputReceived(this, std::move(batch)); if (batch_count_.Increment()) { - END_SPAN(span); finished_.MarkFinished(); } } void ErrorReceived(ExecNode* input, Status error) override { - EVENT(span, "ErrorReceived", {{"error", error.message()}}); + EVENT(span_, "ErrorReceived", {{"error", error.message()}}); DCHECK_EQ(input, inputs_[0]); outputs_[0]->ErrorReceived(this, std::move(error)); @@ -98,7 +97,7 @@ class UnionNode : public ExecNode { } void InputFinished(ExecNode* input, int total_batches) override { - EVENT(span, "InputFinished", + EVENT(span_, "InputFinished", {{"input", input_count_.count()}, {"batches.length", total_batches}}); ARROW_DCHECK(std::find(inputs_.begin(), inputs_.end(), input) != inputs_.end()); @@ -107,27 +106,34 @@ class UnionNode : public ExecNode { if (input_count_.Increment()) { outputs_[0]->InputFinished(this, total_batches_.load()); if (batch_count_.SetTotal(total_batches_.load())) { - END_SPAN(span); finished_.MarkFinished(); } } } Status StartProducing() override { - START_SPAN(span, kind_name(), {{"node", ToString()}}); + START_SPAN(span_, std::string(kind_name()) + ":" + label(), + {{"node.label", label()}, + {"node.detail", ToString()}, + {"node.kind", kind_name()}}); finished_ = Future<>::Make(); +#ifdef ARROW_WITH_OPENTELEMETRY + finished_.AddCallback([this](const Status& st) { + MARK_SPAN(span_, st); + END_SPAN(span_); + }); +#endif return Status::OK(); } - void PauseProducing(ExecNode* output) override { EVENT(span, "PauseProducing"); } + void PauseProducing(ExecNode* output) override { EVENT(span_, "PauseProducing"); } - void ResumeProducing(ExecNode* output) override { EVENT(span, "ResumeProducing"); } + void ResumeProducing(ExecNode* output) override { EVENT(span_, "ResumeProducing"); } void StopProducing(ExecNode* output) override { - EVENT(span, "StopProducing"); + EVENT(span_, "StopProducing"); DCHECK_EQ(output, outputs_[0]); if (batch_count_.Cancel()) { - END_SPAN(span); finished_.MarkFinished(); } for (auto&& input : inputs_) { @@ -137,7 +143,6 @@ class UnionNode : public ExecNode { void StopProducing() override { if (batch_count_.Cancel()) { - END_SPAN(span); finished_.MarkFinished(); } for (auto&& input : inputs_) { @@ -151,7 +156,6 @@ class UnionNode : public ExecNode { AtomicCounter batch_count_; AtomicCounter input_count_; std::atomic total_batches_{0}; - Future<> finished_ = Future<>::MakeFinished(); }; namespace internal { diff --git a/cpp/src/arrow/compute/function.cc b/cpp/src/arrow/compute/function.cc index 3ac6bced61c..6328a31959b 100644 --- a/cpp/src/arrow/compute/function.cc +++ b/cpp/src/arrow/compute/function.cc @@ -215,9 +215,15 @@ Result Function::Execute(const std::vector& args, } util::tracing::Span span; - START_SPAN(span, name(), - {{"detail", options ? options->ToString() : ""}, - {"function.kind", kind()}}); + START_SPAN( + span, name(), + {{"function.args", std::accumulate(std::begin(args), std::end(args), std::string(), + [](std::string& ss, const Datum& d) { + return ss.empty() ? d.ToString() + : ss + "," + d.ToString(); + })}, + {"function.options", options ? options->ToString() : ""}, + {"function.kind", kind()}}); // type-check Datum arguments here. Really we'd like to avoid this as much as // possible diff --git a/cpp/src/arrow/util/tracing.h b/cpp/src/arrow/util/tracing.h index 56d9eb609b1..15f7fca1eee 100644 --- a/cpp/src/arrow/util/tracing.h +++ b/cpp/src/arrow/util/tracing.h @@ -47,23 +47,17 @@ class ARROW_EXPORT Span { Impl& Set(Impl&&); const Impl& Get() const { - if (inner_impl) { - return *inner_impl; - } else { - ARROW_LOG(FATAL) << "Attempted to dereference a null pointer. Use Span::Set before " - "dereferencing."; - std::abort(); - } + ARROW_CHECK(inner_impl) + << "Attempted to dereference a null pointer. Use Span::Set before " + "dereferencing."; + return *inner_impl; } Impl& Get() { - if (inner_impl) { - return *inner_impl; - } else { - ARROW_LOG(FATAL) << "Attempted to dereference a null pointer. Use Span::Set before " - "dereferencing."; - std::abort(); - } + ARROW_CHECK(inner_impl) + << "Attempted to dereference a null pointer. Use Span::Set before " + "dereferencing."; + return *inner_impl; } private: From 7085b84bacb7c9844e5102e3ef88019e72c3693e Mon Sep 17 00:00:00 2001 From: Matthijs Brobbel Date: Thu, 13 Jan 2022 11:33:42 +0100 Subject: [PATCH 11/15] Use Then continuation instead of callbacks to end spans on exec nodes and plans --- cpp/src/arrow/compute/exec/aggregate_node.cc | 39 ++++++-------------- cpp/src/arrow/compute/exec/exec_plan.cc | 14 +------ cpp/src/arrow/compute/exec/hash_join_node.cc | 7 +--- cpp/src/arrow/compute/exec/sink_node.cc | 15 ++------ cpp/src/arrow/compute/exec/source_node.cc | 7 +--- cpp/src/arrow/compute/exec/union_node.cc | 7 +--- cpp/src/arrow/compute/function.cc | 12 ++---- cpp/src/arrow/util/future.h | 6 +-- cpp/src/arrow/util/tracing_internal.h | 13 +++++++ 9 files changed, 39 insertions(+), 81 deletions(-) diff --git a/cpp/src/arrow/compute/exec/aggregate_node.cc b/cpp/src/arrow/compute/exec/aggregate_node.cc index 7dd33a980b9..17f5432aff1 100644 --- a/cpp/src/arrow/compute/exec/aggregate_node.cc +++ b/cpp/src/arrow/compute/exec/aggregate_node.cc @@ -174,10 +174,9 @@ class ScalarAggregateNode : public ExecNode { for (size_t i = 0; i < kernels_.size(); ++i) { util::tracing::Span span; START_SPAN(span, aggs_[i].function, - {{"function", aggs_[i].function}, - {"function.options", + {{"function.options", aggs_[i].options ? aggs_[i].options->ToString() : ""}, - {"function.kind", "consume"}}); + {"function.kind", std::string(kind_name()) + "::Consume"}}); KernelContext batch_ctx{plan()->exec_context()}; batch_ctx.SetState(states_[i][thread_index].get()); @@ -225,12 +224,7 @@ class ScalarAggregateNode : public ExecNode { {"node.detail", ToString()}, {"node.kind", kind_name()}}); finished_ = Future<>::Make(); -#ifdef ARROW_WITH_OPENTELEMETRY - finished_.AddCallback([this](const Status& st) { - MARK_SPAN(span_, st); - END_SPAN(span_); - }); -#endif + END_SPAN_ON_FUTURE_COMPLETION(span_, finished_, this); // Scalar aggregates will only output a single batch outputs_[0]->InputFinished(this, 1); return Status::OK(); @@ -273,10 +267,9 @@ class ScalarAggregateNode : public ExecNode { for (size_t i = 0; i < kernels_.size(); ++i) { util::tracing::Span span; START_SPAN(span, aggs_[i].function, - {{"function", aggs_[i].function}, - {"function.options", + {{"function.options", aggs_[i].options ? aggs_[i].options->ToString() : ""}, - {"function.kind", "finalize"}}); + {"function.kind", std::string(kind_name()) + "::Finalize"}}); KernelContext ctx{plan()->exec_context()}; ARROW_ASSIGN_OR_RAISE(auto merged, ScalarAggregateKernel::MergeAll( kernels_[i], &ctx, std::move(states_[i]))); @@ -423,10 +416,9 @@ class GroupByNode : public ExecNode { for (size_t i = 0; i < agg_kernels_.size(); ++i) { util::tracing::Span span; START_SPAN(span, aggs_[i].function, - {{"function", aggs_[i].function}, - {"function.options", + {{"function.options", aggs_[i].options ? aggs_[i].options->ToString() : ""}, - {"function.kind", "consume"}}); + {"function.kind", std::string(kind_name()) + "::Consume"}}); KernelContext kernel_ctx{ctx_}; kernel_ctx.SetState(state->agg_states[i].get()); @@ -458,10 +450,9 @@ class GroupByNode : public ExecNode { for (size_t i = 0; i < agg_kernels_.size(); ++i) { util::tracing::Span span; START_SPAN(span, aggs_[i].function, - {{"function", aggs_[i].function}, - {"function.options", + {{"function.options", aggs_[i].options ? aggs_[i].options->ToString() : ""}, - {"function.kind", "merge"}}); + {"function.kind", std::string(kind_name()) + "::Merge"}}); KernelContext batch_ctx{ctx_}; DCHECK(state0->agg_states[i]); batch_ctx.SetState(state0->agg_states[i].get()); @@ -491,10 +482,9 @@ class GroupByNode : public ExecNode { for (size_t i = 0; i < agg_kernels_.size(); ++i) { util::tracing::Span span; START_SPAN(span, aggs_[i].function, - {{"function", aggs_[i].function}, - {"function.options", + {{"function.options", aggs_[i].options ? aggs_[i].options->ToString() : ""}, - {"function.kind", "finalize"}}); + {"function.kind", std::string(kind_name()) + "::Finalize"}}); KernelContext batch_ctx{ctx_}; batch_ctx.SetState(state->agg_states[i].get()); RETURN_NOT_OK(agg_kernels_[i]->finalize(&batch_ctx, &out_data.values[i])); @@ -596,12 +586,7 @@ class GroupByNode : public ExecNode { {"node.detail", ToString()}, {"node.kind", kind_name()}}); finished_ = Future<>::Make(); -#ifdef ARROW_WITH_OPENTELEMETRY - finished_.AddCallback([this](const Status& st) { - MARK_SPAN(span_, st); - END_SPAN(span_); - }); -#endif + END_SPAN_ON_FUTURE_COMPLETION(span_, finished_, this); local_states_.resize(ThreadIndexer::Capacity()); return Status::OK(); diff --git a/cpp/src/arrow/compute/exec/exec_plan.cc b/cpp/src/arrow/compute/exec/exec_plan.cc index 2780b7e23bb..fc7f3e52c65 100644 --- a/cpp/src/arrow/compute/exec/exec_plan.cc +++ b/cpp/src/arrow/compute/exec/exec_plan.cc @@ -112,12 +112,7 @@ struct ExecPlanImpl : public ExecPlan { } finished_ = AllFinished(futures); -#ifdef ARROW_WITH_OPENTELEMETRY - finished_.AddCallback([this](const Status& st) { - MARK_SPAN(span_, st); - END_SPAN(span_); - }); -#endif + END_SPAN_ON_FUTURE_COMPLETION(span_, finished_, this); return st; } @@ -350,12 +345,7 @@ Status MapNode::StartProducing() { span_, std::string(kind_name()) + ":" + label(), {{"node.label", label()}, {"node.detail", ToString()}, {"node.kind", kind_name()}}); finished_ = Future<>::Make(); -#ifdef ARROW_WITH_OPENTELEMETRY - finished_.AddCallback([this](const Status& st) { - MARK_SPAN(span_, st); - END_SPAN(span_); - }); -#endif + END_SPAN_ON_FUTURE_COMPLETION(span_, finished_, this); return Status::OK(); } diff --git a/cpp/src/arrow/compute/exec/hash_join_node.cc b/cpp/src/arrow/compute/exec/hash_join_node.cc index bb658ba4eb0..9295b5aaf4d 100644 --- a/cpp/src/arrow/compute/exec/hash_join_node.cc +++ b/cpp/src/arrow/compute/exec/hash_join_node.cc @@ -547,12 +547,7 @@ class HashJoinNode : public ExecNode { {"node.detail", ToString()}, {"node.kind", kind_name()}}); finished_ = Future<>::Make(); -#ifdef ARROW_WITH_OPENTELEMETRY - finished_.AddCallback([this](const Status& st) { - MARK_SPAN(span_, st); - END_SPAN(span_); - }); -#endif + END_SPAN_ON_FUTURE_COMPLETION(span_, finished_, this); bool use_sync_execution = !(plan_->exec_context()->executor()); size_t num_threads = use_sync_execution ? 1 : thread_indexer_.Capacity(); diff --git a/cpp/src/arrow/compute/exec/sink_node.cc b/cpp/src/arrow/compute/exec/sink_node.cc index ce2e969c9b2..e29b6ce4c40 100644 --- a/cpp/src/arrow/compute/exec/sink_node.cc +++ b/cpp/src/arrow/compute/exec/sink_node.cc @@ -82,12 +82,8 @@ class SinkNode : public ExecNode { {"node.detail", ToString()}, {"node.kind", kind_name()}}); finished_ = Future<>::Make(); -#ifdef ARROW_WITH_OPENTELEMETRY - finished_.AddCallback([this](const Status& st) { - MARK_SPAN(span_, st); - END_SPAN(span_); - }); -#endif + END_SPAN_ON_FUTURE_COMPLETION(span_, finished_, this); + return Status::OK(); } @@ -184,12 +180,7 @@ class ConsumingSinkNode : public ExecNode { {"node.detail", ToString()}, {"node.kind", kind_name()}}); finished_ = Future<>::Make(); -#ifdef ARROW_WITH_OPENTELEMETRY - finished_.AddCallback([this](const Status& st) { - MARK_SPAN(span_, st); - END_SPAN(span_); - }); -#endif + END_SPAN_ON_FUTURE_COMPLETION(span_, finished_, this); return Status::OK(); } diff --git a/cpp/src/arrow/compute/exec/source_node.cc b/cpp/src/arrow/compute/exec/source_node.cc index d29365b628e..6d47609d2a2 100644 --- a/cpp/src/arrow/compute/exec/source_node.cc +++ b/cpp/src/arrow/compute/exec/source_node.cc @@ -146,12 +146,7 @@ struct SourceNode : ExecNode { outputs_[0]->InputFinished(this, total_batches); return task_group_.End(); }); -#ifdef ARROW_WITH_OPENTELEMETRY - finished_.AddCallback([this](const Status& st) { - MARK_SPAN(span_, st); - END_SPAN(span_); - }); -#endif + END_SPAN_ON_FUTURE_COMPLETION(span_, finished_, this); return Status::OK(); } diff --git a/cpp/src/arrow/compute/exec/union_node.cc b/cpp/src/arrow/compute/exec/union_node.cc index 9edf0a00cc8..9232516cc6d 100644 --- a/cpp/src/arrow/compute/exec/union_node.cc +++ b/cpp/src/arrow/compute/exec/union_node.cc @@ -117,12 +117,7 @@ class UnionNode : public ExecNode { {"node.detail", ToString()}, {"node.kind", kind_name()}}); finished_ = Future<>::Make(); -#ifdef ARROW_WITH_OPENTELEMETRY - finished_.AddCallback([this](const Status& st) { - MARK_SPAN(span_, st); - END_SPAN(span_); - }); -#endif + END_SPAN_ON_FUTURE_COMPLETION(span_, finished_, this); return Status::OK(); } diff --git a/cpp/src/arrow/compute/function.cc b/cpp/src/arrow/compute/function.cc index 6328a31959b..b0de0a1b907 100644 --- a/cpp/src/arrow/compute/function.cc +++ b/cpp/src/arrow/compute/function.cc @@ -215,15 +215,9 @@ Result Function::Execute(const std::vector& args, } util::tracing::Span span; - START_SPAN( - span, name(), - {{"function.args", std::accumulate(std::begin(args), std::end(args), std::string(), - [](std::string& ss, const Datum& d) { - return ss.empty() ? d.ToString() - : ss + "," + d.ToString(); - })}, - {"function.options", options ? options->ToString() : ""}, - {"function.kind", kind()}}); + START_SPAN(span, name(), + {{"function.options", options ? options->ToString() : ""}, + {"function.kind", kind()}}); // type-check Datum arguments here. Really we'd like to avoid this as much as // possible diff --git a/cpp/src/arrow/util/future.h b/cpp/src/arrow/util/future.h index 695ee9ff357..96bbe99abf4 100644 --- a/cpp/src/arrow/util/future.h +++ b/cpp/src/arrow/util/future.h @@ -626,14 +626,14 @@ class ARROW_MUST_USE_TYPE Future { /// returning the future. /// /// Two callbacks are supported: - /// - OnSuccess, called with the result (const ValueType&) on successul completion. + /// - OnSuccess, called with the result (const ValueType&) on successful completion. /// for an empty future this will be called with nothing () /// - OnFailure, called with the error (const Status&) on failed completion. /// This callback is optional and defaults to a passthru of any errors. /// /// Then() returns a Future whose ValueType is derived from the return type of the /// callbacks. If a callback returns: - /// - void, a Future<> will be returned which will completes successully as soon + /// - void, a Future<> will be returned which will completes successfully as soon /// as the callback runs. /// - Status, a Future<> will be returned which will complete with the returned Status /// as soon as the callback runs. @@ -645,7 +645,7 @@ class ARROW_MUST_USE_TYPE Future { /// /// The continued Future type must be the same for both callbacks. /// - /// Note that OnFailure can swallow errors, allowing continued Futures to successully + /// Note that OnFailure can swallow errors, allowing continued Futures to successfully /// complete even if this Future fails. /// /// If this future is already completed then the callback will be run immediately diff --git a/cpp/src/arrow/util/tracing_internal.h b/cpp/src/arrow/util/tracing_internal.h index 9d6c4e4218d..d4947ac88fe 100644 --- a/cpp/src/arrow/util/tracing_internal.h +++ b/cpp/src/arrow/util/tracing_internal.h @@ -134,6 +134,18 @@ opentelemetry::trace::StartSpanOptions SpanOptionsWithParent( #define END_SPAN(target_span) target_span.Get().span->End() +#define END_SPAN_ON_FUTURE_COMPLETION(target_span, target_future, target_capture) \ + target_future = target_future.Then( \ + [target_capture]() { \ + MARK_SPAN(target_span, Status::OK()); \ + END_SPAN(target_span); \ + }, \ + [target_capture](const Status& st) { \ + MARK_SPAN(target_span, st); \ + END_SPAN(target_span); \ + return st; \ + }) + #else class SpanImpl {}; @@ -143,6 +155,7 @@ class SpanImpl {}; #define MARK_SPAN(target_span, status) #define EVENT(target_span, ...) #define END_SPAN(target_span) +#define END_SPAN_ON_FUTURE_COMPLETION(target_span, target_future, target_capture) #endif From 9fc1543aa7bd7d341850e4b765353eddef17d942 Mon Sep 17 00:00:00 2001 From: Matthijs Brobbel Date: Mon, 17 Jan 2022 13:19:26 +0100 Subject: [PATCH 12/15] Add function.name attribute for function spans --- cpp/src/arrow/compute/exec/aggregate_node.cc | 15 ++++++++++----- cpp/src/arrow/compute/function.cc | 3 ++- 2 files changed, 12 insertions(+), 6 deletions(-) diff --git a/cpp/src/arrow/compute/exec/aggregate_node.cc b/cpp/src/arrow/compute/exec/aggregate_node.cc index 17f5432aff1..8e8e0ceebb0 100644 --- a/cpp/src/arrow/compute/exec/aggregate_node.cc +++ b/cpp/src/arrow/compute/exec/aggregate_node.cc @@ -174,7 +174,8 @@ class ScalarAggregateNode : public ExecNode { for (size_t i = 0; i < kernels_.size(); ++i) { util::tracing::Span span; START_SPAN(span, aggs_[i].function, - {{"function.options", + {{"function.name", aggs_[i].function}, + {"function.options", aggs_[i].options ? aggs_[i].options->ToString() : ""}, {"function.kind", std::string(kind_name()) + "::Consume"}}); KernelContext batch_ctx{plan()->exec_context()}; @@ -267,7 +268,8 @@ class ScalarAggregateNode : public ExecNode { for (size_t i = 0; i < kernels_.size(); ++i) { util::tracing::Span span; START_SPAN(span, aggs_[i].function, - {{"function.options", + {{"function.name", aggs_[i].function}, + {"function.options", aggs_[i].options ? aggs_[i].options->ToString() : ""}, {"function.kind", std::string(kind_name()) + "::Finalize"}}); KernelContext ctx{plan()->exec_context()}; @@ -416,7 +418,8 @@ class GroupByNode : public ExecNode { for (size_t i = 0; i < agg_kernels_.size(); ++i) { util::tracing::Span span; START_SPAN(span, aggs_[i].function, - {{"function.options", + {{"function.name", aggs_[i].function}, + {"function.options", aggs_[i].options ? aggs_[i].options->ToString() : ""}, {"function.kind", std::string(kind_name()) + "::Consume"}}); KernelContext kernel_ctx{ctx_}; @@ -450,7 +453,8 @@ class GroupByNode : public ExecNode { for (size_t i = 0; i < agg_kernels_.size(); ++i) { util::tracing::Span span; START_SPAN(span, aggs_[i].function, - {{"function.options", + {{"function.name", aggs_[i].function}, + {"function.options", aggs_[i].options ? aggs_[i].options->ToString() : ""}, {"function.kind", std::string(kind_name()) + "::Merge"}}); KernelContext batch_ctx{ctx_}; @@ -482,7 +486,8 @@ class GroupByNode : public ExecNode { for (size_t i = 0; i < agg_kernels_.size(); ++i) { util::tracing::Span span; START_SPAN(span, aggs_[i].function, - {{"function.options", + {{"function.name", aggs_[i].function}, + {"function.options", aggs_[i].options ? aggs_[i].options->ToString() : ""}, {"function.kind", std::string(kind_name()) + "::Finalize"}}); KernelContext batch_ctx{ctx_}; diff --git a/cpp/src/arrow/compute/function.cc b/cpp/src/arrow/compute/function.cc index b0de0a1b907..1a7f36862dd 100644 --- a/cpp/src/arrow/compute/function.cc +++ b/cpp/src/arrow/compute/function.cc @@ -216,7 +216,8 @@ Result Function::Execute(const std::vector& args, util::tracing::Span span; START_SPAN(span, name(), - {{"function.options", options ? options->ToString() : ""}, + {{"function.name", name()}, + {"function.options", options ? options->ToString() : ""}, {"function.kind", kind()}}); // type-check Datum arguments here. Really we'd like to avoid this as much as From b3395b2cbb888bafcbc953b21b8989ac8f762384 Mon Sep 17 00:00:00 2001 From: Matthijs Brobbel Date: Tue, 1 Feb 2022 12:27:19 +0100 Subject: [PATCH 13/15] Add metadata to ExecPlan --- cpp/src/arrow/compute/exec/exec_plan.cc | 16 +++++++++++++--- cpp/src/arrow/compute/exec/exec_plan.h | 10 +++++++++- 2 files changed, 22 insertions(+), 4 deletions(-) diff --git a/cpp/src/arrow/compute/exec/exec_plan.cc b/cpp/src/arrow/compute/exec/exec_plan.cc index fc7f3e52c65..90051aaa0e6 100644 --- a/cpp/src/arrow/compute/exec/exec_plan.cc +++ b/cpp/src/arrow/compute/exec/exec_plan.cc @@ -44,7 +44,9 @@ namespace compute { namespace { struct ExecPlanImpl : public ExecPlan { - explicit ExecPlanImpl(ExecContext* exec_context) : ExecPlan(exec_context) {} + explicit ExecPlanImpl(ExecContext* exec_context, + std::shared_ptr metadata = NULLPTR) + : ExecPlan(exec_context), metadata_(std::move(metadata)) {} ~ExecPlanImpl() override { if (started_ && !finished_.is_finished()) { @@ -183,6 +185,7 @@ struct ExecPlanImpl : public ExecPlan { NodeVector sorted_nodes_; uint32_t auto_label_counter_ = 0; util::tracing::Span span_; + std::shared_ptr metadata_; }; ExecPlanImpl* ToDerived(ExecPlan* ptr) { return checked_cast(ptr); } @@ -201,8 +204,9 @@ util::optional GetNodeIndex(const std::vector& nodes, } // namespace -Result> ExecPlan::Make(ExecContext* ctx) { - return std::shared_ptr(new ExecPlanImpl{ctx}); +Result> ExecPlan::Make( + ExecContext* ctx, std::shared_ptr metadata) { + return std::shared_ptr(new ExecPlanImpl{ctx, metadata}); } ExecNode* ExecPlan::AddNode(std::unique_ptr node) { @@ -223,6 +227,12 @@ void ExecPlan::StopProducing() { ToDerived(this)->StopProducing(); } Future<> ExecPlan::finished() { return ToDerived(this)->finished_; } +bool ExecPlan::HasMetadata() const { return !!(ToDerived(this)->metadata_); } + +std::shared_ptr ExecPlan::metadata() const { + return ToDerived(this)->metadata_; +} + std::string ExecPlan::ToString() const { return ToDerived(this)->ToString(); } ExecNode::ExecNode(ExecPlan* plan, NodeVector inputs, diff --git a/cpp/src/arrow/compute/exec/exec_plan.h b/cpp/src/arrow/compute/exec/exec_plan.h index ea9b6c72686..ff8f5f27531 100644 --- a/cpp/src/arrow/compute/exec/exec_plan.h +++ b/cpp/src/arrow/compute/exec/exec_plan.h @@ -46,7 +46,9 @@ class ARROW_EXPORT ExecPlan : public std::enable_shared_from_this { ExecContext* exec_context() const { return exec_context_; } /// Make an empty exec plan - static Result> Make(ExecContext* = default_exec_context()); + static Result> Make( + ExecContext* = default_exec_context(), + std::shared_ptr metadata = NULLPTR); ExecNode* AddNode(std::unique_ptr node); @@ -81,6 +83,12 @@ class ARROW_EXPORT ExecPlan : public std::enable_shared_from_this { /// \brief A future which will be marked finished when all nodes have stopped producing. Future<> finished(); + /// \brief Return whether the plan has non-empty metadata + bool HasMetadata() const; + + /// \brief Return the plan's attached metadata + std::shared_ptr metadata() const; + std::string ToString() const; protected: From 79dd6b628a555df73ca69235de136944f4f6236a Mon Sep 17 00:00:00 2001 From: Matthijs Brobbel Date: Wed, 2 Feb 2022 10:15:22 +0100 Subject: [PATCH 14/15] Add plan metadata as span attributes --- cpp/src/arrow/compute/exec/exec_plan.cc | 10 +++++++++- cpp/src/arrow/compute/exec/exec_plan.h | 1 + 2 files changed, 10 insertions(+), 1 deletion(-) diff --git a/cpp/src/arrow/compute/exec/exec_plan.cc b/cpp/src/arrow/compute/exec/exec_plan.cc index 90051aaa0e6..17d71a2cf04 100644 --- a/cpp/src/arrow/compute/exec/exec_plan.cc +++ b/cpp/src/arrow/compute/exec/exec_plan.cc @@ -82,7 +82,15 @@ struct ExecPlanImpl : public ExecPlan { Status StartProducing() { START_SPAN(span_, "ExecPlan", {{"plan", ToString()}}); - +#ifdef ARROW_WITH_OPENTELEMETRY + if (HasMetadata()) { + auto pairs = metadata().get()->sorted_pairs(); + std::for_each(std::begin(pairs), std::end(pairs), + [this](std::pair const& pair) { + span_.Get().span->SetAttribute(pair.first, pair.second); + }); + } +#endif if (started_) { return Status::Invalid("restarted ExecPlan"); } diff --git a/cpp/src/arrow/compute/exec/exec_plan.h b/cpp/src/arrow/compute/exec/exec_plan.h index ff8f5f27531..ac5996ed72e 100644 --- a/cpp/src/arrow/compute/exec/exec_plan.h +++ b/cpp/src/arrow/compute/exec/exec_plan.h @@ -28,6 +28,7 @@ #include "arrow/type_fwd.h" #include "arrow/util/async_util.h" #include "arrow/util/cancel.h" +#include "arrow/util/key_value_metadata.h" #include "arrow/util/macros.h" #include "arrow/util/optional.h" #include "arrow/util/tracing.h" From 4c0d944d8fda0575c10e659f354fd67098a4f84f Mon Sep 17 00:00:00 2001 From: Matthijs Brobbel Date: Wed, 2 Feb 2022 10:20:04 +0100 Subject: [PATCH 15/15] Instrument OrderBySinkNode::Finish --- cpp/src/arrow/compute/exec/sink_node.cc | 2 ++ 1 file changed, 2 insertions(+) diff --git a/cpp/src/arrow/compute/exec/sink_node.cc b/cpp/src/arrow/compute/exec/sink_node.cc index e29b6ce4c40..b95bbcf70d2 100644 --- a/cpp/src/arrow/compute/exec/sink_node.cc +++ b/cpp/src/arrow/compute/exec/sink_node.cc @@ -341,6 +341,8 @@ struct OrderBySinkNode final : public SinkNode { } void Finish() override { + util::tracing::Span span; + START_SPAN_WITH_PARENT(span, span_, "Finish", {{"node.label", label()}}); Status st = DoFinish(); if (ErrorIfNotOk(st)) { producer_.Push(std::move(st));