ARROW-15067: [C++] Add tracing spans to the scanner #12609

joosthooz · 2022-03-11T13:19:00Z

Continuing #12328 and #11964.
The tracing spans were not propagated through all the asynchronous constructs, causing some spans to become disconnected from the trace. This PR aims to address this.
Some things left to do:

Possibly add some attributes to the read_column span
fix parent/sibling relationships (some of the new spans should probably become a child)
Do something about all the #ifdefs
Wrap around a Future
Wrap Executor
Check if tracing now works properly for all of the file types, not just parquet
lidavidm mentioned some memory leaks that should be investigated
The FragmentToBatches span seems to be active way too long

github-actions · 2022-03-11T13:19:22Z

https://issues.apache.org/jira/browse/ARROW-15067

lidavidm

In general the original PR was done before we had the nice utilities in tracing_internal.h so things here can be cleaned up using those helpers, IMO. But otherwise things look good.

lidavidm · 2022-03-14T20:11:59Z

cpp/build-support/lsan-suppressions.txt

+
+# OpenTelemetry. These seem like false positives and go away if the
+# CPU thread pool is manually shut down before exit.
+# Note that ASan has trouble backtracing these and may not be able to
+# without LSAN_OPTIONS=fast_unwind_on_malloc=0:malloc_context_size=100
+leak:opentelemetry::v1::context::ThreadLocalContextStorage::GetStack
+leak:opentelemetry::v1::context::ThreadLocalContextStorage::Stack::Resize


We should probably test and ensure we don't get issues anymore once the new version of OTel comes out.

cpp/src/arrow/dataset/file_base.cc

cpp/src/arrow/dataset/file_csv.cc

westonpace

Thanks for looking into this. I think this is probably more accurate than what we had before but I do think we should probably address a more general solution too. This is getting pretty confusing.

I'm not sure it would require changes to Future but rather to Executor. Here is what I'm thinking (though I'm usually missing some key detail on these kinds of things 😆 )

When a span is created it is made the active span automatically (perhaps there can be an exception where we don't want this but I'm not aware of one)
When a span is created the parent should always be set to the active span
In Executor::Spawn and Executor::Submit we should wrap tasks. For example:

  template <typename Function>
  Status Spawn(Function&& func) {
    const auto& span = GetActiveSpan();
    struct CallWrapper {
        void operator()() {
            SetActiveSpan(span);
            func();
            ClearActiveSpan();
        }
        Function func;
        Span span;
    };
    CallWrapper wrapped{std::forward(func), span};
    return SpawnReal(TaskHints{}, std::move(wrapped), StopToken::Unstoppable(),
                     StopCallback{});
  }

westonpace · 2022-03-15T02:10:20Z

cpp/src/arrow/util/tracing_internal.h

+#define GET_CURRENT_SPAN(span) \
+  auto span = ::arrow::internal::tracing::GetTracer()->GetCurrentSpan()
+
+#define SET_SPAN_SCOPE(scope, span) \
+  auto scope = ::arrow::internal::tracing::GetTracer()->WithActiveSpan(span)
+
+#define TIE_SPAN_TO_GENERATOR(generator) \
+        generator = ::arrow::internal::tracing::TieSpanToAsyncGenerator(generator)
+
+#define PROPAGATE_SPAN_TO_GENERATOR(generator) \
+        generator = \
+            ::arrow::internal::tracing::PropagateSpanThroughAsyncGenerator(generator)
+


These macros seem more like aliases. I'm not sure they help more than they obfuscate.

Their purpose is to have blank versions when compiling without opentelemetry

#ifdef ARROW_WITH_OPENTELEMETRY #define GET_CURRENT_SPAN(span) \ auto span = ::arrow::internal::tracing::GetTracer()->GetCurrentSpan() ... #else #define START_SPAN(target_span, ...)

So if I remove them, I need to guard all of the calls to these functions with #ifdef ARROW_WITH_OPENTELEMETRY

westonpace · 2022-03-15T02:15:13Z

cpp/src/parquet/arrow/reader.cc

+    auto span = ::arrow::internal::tracing::GetTracer()->GetCurrentSpan();
+    ::arrow::util::tracing::Span childspan;
+    ::arrow::util::tracing::Span parentspan;
+    parentspan.Set(::arrow::util::tracing::Span::Impl{span});


This is a confusing way to create a parent span. Why does GetCurrentSpan() not return something we can use? Why do we need parentspan?

Looking at this again, it seems superfluous. I'll remove it and just start a span the normal way. That should already take care of setting the current span as the parent automatically.

westonpace · 2022-03-15T02:16:27Z

cpp/src/parquet/arrow/reader.cc

    if (cpu_executor_) ready = cpu_executor_->TransferAlways(ready);
-    return ready.Then([=]() -> ::arrow::Future<RecordBatchGenerator> {
+
+    GET_CURRENT_SPAN(span);


This is a confusing use of macros. At the very least I'd want to see something like GET_CURRENT_SPAN(&span)

I agree that would be better, but then the span object declaration is not guarded with the #ifdef ARROW_WITH_OPENTELEMETRY (that was the reason I did it like this). But I'll try it and see if it works.

westonpace · 2022-03-15T02:44:35Z

cpp/src/arrow/dataset/file_parquet.cc

      [=](const std::shared_ptr<parquet::arrow::FileReader>& reader) mutable
      -> Result<RecordBatchGenerator> {
+#ifdef ARROW_WITH_OPENTELEMETRY
+    auto scope = ::arrow::internal::tracing::GetTracer()->WithActiveSpan(span);


Is this needed? What call is accessing this scope? By the time we get to line 427 I think this scope has been destroyed.

The span is automatically ended when the scope is destroyed, so that is what we want. I tried to create a generic wrapper that can wrap this lambda like we do with the AsyncGenerators etc, but I couldn't manage to figure it out so I dropped it for now. Do you think such an approach is possible?

lidavidm · 2022-03-15T12:17:16Z

Ah, I was thinking we could also have a Future carry a Span that it would activate when running callbacks/continuations. But yes, we would also want to instrument Executor as well. (And maybe instead of putting Span on Future, it should be attached to the callback itself.)

westonpace · 2022-03-16T08:06:12Z

And maybe instead of putting Span on Future, it should be attached to the callback itself.

This could work as well. So every time we add a callback we (while adding the callback) grab the active span. We then wrap the callback function like...

auto activeSpan = GetCurrentSpan();
auto wrapped = [activeSpan, callback] {
  SetCurrentSpan(activeSpan);
  callback();
};

(although you'd have to do an actual struct wrapper because callback should be move-only and we don't have move lambda captures yet)

I think that's basically the same thing as what I was suggesting on the thread pool but it would only affect futures. Given most of our thread tasks are futures I think this would probably be acceptable but I think I'd still lean towards implementing this in the executor if I were going to tackle it myself.

lidavidm · 2022-03-16T12:15:39Z

With the thread pool, if the future isn't complete, then we don't call into the thread pool/spawn any tasks right? So it won't have a chance to capture the correct current span?

westonpace · 2022-03-16T20:41:09Z

If no thread task is spawned then the thread local storage of the current span should be sufficient.

lidavidm · 2022-03-16T20:42:44Z

Sorry, I might be misunderstanding, but what I mean is: if we have fut.Then(callback, options);

That may not run the callback immediately, right? And/or, we have no idea what thread the callback will get run on in general (it's up to the future, or possibly options). So instrumenting the executor isn't enough, we have to instrument the future or the callback itself.

lidavidm · 2022-03-16T20:44:11Z

Ah, I guess if you instrument the executor, the resulting future will presumably be in the right context…but to me, from looking just at local code, that seems like a less obvious property (and what if there's a generator or something else in the chain?)

westonpace · 2022-03-16T20:51:21Z

Ah, yes, good point. I had kind of forgotten that task submission was deferred. The callback will inherit the active span from the completing thread and not the thread that called Then/AddCallback. Ok, I agree that capturing the span in Then/AddCallback is more intuitive.

…out opentelemetry

joosthooz · 2022-03-18T14:35:19Z

I pushed some code trying to do what Weston suggested, but it doesn't compile. The (first!) problem is apparently that when including tracing_internal.h, the Future class becomes incomplete. It causes many errors like incomplete type 'class arrow::Future<>',

arrow/cpp/src/arrow/util/async_generator.h:1531:14: error: 'task_finished' has incomplete type
 1531 |     Future<> task_finished;
      |              ^~~~~~~~~~~~~

lidavidm

LGTM, thanks

lidavidm · 2022-03-30T13:12:47Z

(By the way: please mark this ready for review if you think it's good)

westonpace

This looks much better, thank you for taking the time to figure it out.

westonpace · 2022-03-31T16:21:43Z

cpp/src/arrow/dataset/file_csv.cc

  ARROW_ASSIGN_OR_RAISE(auto reader_options, GetReadOptions(format, scan_options));

  ARROW_ASSIGN_OR_RAISE(auto input, source.OpenCompressed());
+  auto path = source.path();


Suggested change

auto path = source.path();

const auto& path = source.path();

westonpace · 2022-03-31T16:27:02Z

cpp/src/arrow/util/tracing_internal.h

                                     const std::string& span_name) {
  return [=]() mutable -> Future<T> {
-    auto span = GetTracer()->StartSpan(span_name);
+    auto span = GetTracer()->StartSpan(span_name, {}, options);


Can we do StartSpan(span_name, options)? If not, then let's do StartSpan(span_name, /*attributes=*/{}, options)

westonpace · 2022-03-31T16:27:02Z

cpp/src/arrow/util/tracing_internal.h

                                     const std::string& span_name) {
  return [=]() mutable -> Future<T> {
-    auto span = GetTracer()->StartSpan(span_name);
+    auto span = GetTracer()->StartSpan(span_name, {}, options);


Can we do StartSpan(span_name, options)? If not, then let's do StartSpan(span_name, /*attributes=*/{}, options)

I've refactored this a little bit in f32fda8; options has been removed here

westonpace · 2022-03-31T16:35:07Z

cpp/src/arrow/util/tracing_internal.h

 AsyncGenerator<T> WrapAsyncGenerator(AsyncGenerator<T> wrapped,
+                                     opentelemetry::trace::StartSpanOptions options,
                                     const std::string& span_name) {


Nit: It's not obvious to me at a glance that I'd be bypassing the normal process of assigning a parent by using this overload. I'm not certain we want to do this but if the overload was...

AsyncGenerator<T> WrapAsyncGenerator(AsyncGenerator<T> wrapped, const std::string& span_name, nostd::variant<SpanContext, opentelemetry::context::Context> parent = SpanContext::GetInvalid())

It would be more obvious to me:

Why someone would supply options

By supplying options, I am bypassing the normal process of assigning the parent

Do we call this overload anywhere? If not, can we get rid of it?

westonpace · 2022-03-31T16:35:07Z

cpp/src/arrow/util/tracing_internal.h

 AsyncGenerator<T> WrapAsyncGenerator(AsyncGenerator<T> wrapped,
+                                     opentelemetry::trace::StartSpanOptions options,
                                     const std::string& span_name) {


Nit: It's not obvious to me at a glance that I'd be bypassing the normal process of assigning a parent by using this overload. I'm not certain we want to do this but if the overload was...

AsyncGenerator<T> WrapAsyncGenerator(AsyncGenerator<T> wrapped, const std::string& span_name, nostd::variant<SpanContext, opentelemetry::context::Context> parent = SpanContext::GetInvalid())

It would be more obvious to me:

Why someone would supply options

By supplying options, I am bypassing the normal process of assigning the parent

Do we call this overload anywhere? If not, can we get rid of it?

I've refactored this a little bit in f32fda8, it doesn't pass options anymore, instead it just gets the current span in the function itself.

westonpace · 2022-03-31T16:39:41Z

cpp/src/arrow/util/tracing_internal.h

+  if (!span->GetContext().IsValid()) return wrapped;
+  return PropagateSpanThroughAsyncGenerator(std::move(wrapped), std::move(span));
+}
+


The distinction between PropagateSpanThroughAsyncGenerator, TieSpanToAsyncGenerator, and WrapAsyncGenerator are subtle. Would it be possible to add a short block of comment prose above these methods describing "why" you pick one or the other?

Agreed; they are so very similar that I've merged 2 of them into 1. The behavior is then switched with an argument. I'd love to hear your opinion on that: 71f6989
I've also written an addition comment block.

Yes, looks much better, thank you. So if I understand correctly:

Wrap -> The generator "is the activity"
Propagate -> The generator "is a part of a larger activity"

cpp/src/arrow/util/tracing_internal.h

westonpace · 2022-03-31T16:44:47Z

cpp/src/arrow/util/tracing_internal.h

+#define GET_CURRENT_SPAN(lhs) \
+  lhs = ::arrow::internal::tracing::GetTracer()->GetCurrentSpan()
+
+#define SET_SPAN_SCOPE(lhs, span) \
+  lhs = ::arrow::internal::tracing::GetTracer()->WithActiveSpan(span)
+
+#define TIE_SPAN_TO_GENERATOR(generator) \
+  generator = ::arrow::internal::tracing::TieSpanToAsyncGenerator(std::move(generator))
+
+#define PROPAGATE_SPAN_TO_GENERATOR(generator)                                \
+  generator = ::arrow::internal::tracing::PropagateSpanThroughAsyncGenerator( \
+      std::move(generator))
+
+#define WRAP_ASYNC_GENERATOR(generator, name) \
+  generator = ::arrow::internal::tracing::WrapAsyncGenerator(std::move(generator), name)
+


What do we gain making these macros instead of static methods? If the namespaces are troublesome then lets just put the methods in the arrow namespace. That seems a better compromise than introducing a macro.

namespace arrow { nostd::shared_ptr<Span> GetCurrentSpan() { return ::arrow::internal::tracing::GetTracer()->GetCurrentSpan(); } }

This was discussed earlier; this was my response:
Their purpose is to have blank versions when compiling without opentelemetry

#ifdef ARROW_WITH_OPENTELEMETRY #define GET_CURRENT_SPAN(span) \ auto span = ::arrow::internal::tracing::GetTracer()->GetCurrentSpan() ... #else #define START_SPAN(target_span, ...)

So if I remove them, I need to guard all of the calls to these functions with #ifdef ARROW_WITH_OPENTELEMETRY

cpp/src/arrow/dataset/file_ipc.cc

westonpace · 2022-03-31T16:46:20Z

cpp/src/arrow/dataset/file_ipc.cc

+#ifdef ARROW_WITH_OPENTELEMETRY
+    opentelemetry::trace::StartSpanOptions span_options;
+    span_options.parent = parent_span->GetContext();
+    generator = arrow::internal::tracing::WrapAsyncGenerator(


Why do I need to manually specify the parent here? Can we add a comment explaining?

It seems to be unnecessary - I've removed it

…some comments

cpp/src/arrow/util/tracing_internal.h

cpp/src/arrow/dataset/file_ipc.cc

westonpace

Thanks for creating all of this. I'll have to get back to profiling soon so I can play with the results.

cpp/src/arrow/dataset/file_csv.cc

westonpace · 2022-04-01T21:08:44Z

cpp/src/arrow/util/tracing_internal.h

+  if (!span->GetContext().IsValid()) return wrapped;
+  return PropagateSpanThroughAsyncGenerator(std::move(wrapped), std::move(span));
+}
+


Yes, looks much better, thank you. So if I understand correctly:

Wrap -> The generator "is the activity"
Propagate -> The generator "is a part of a larger activity"

westonpace · 2022-04-01T21:10:29Z

cpp/src/arrow/util/tracing_internal.h

        return st;                                                                \
      })

+#define PROPAGATE_SPAN_TO_GENERATOR(generator)                                \


I accept your rationale for these macros but could we add a brief comment with that rationale above these one-liner macros? Otherwise I'm afraid I'll end up asking you yet again 😆

Propagate -> The generator "is a part of a larger activity"

Yes, in this case, the span is not ended when the generator finishes. It is just needed so that any spans created in the asynchronously running code (possibly in other threads) do not end up becoming orphan spans in a separate trace.

I added a comment here 567fa30

lidavidm · 2022-04-06T13:12:04Z

@joosthooz @westonpace is there anything left to do here? (I see one thing listed in the PR description, was that already checked?)

joosthooz · 2022-04-07T08:45:00Z

I've checked parquet and feather, still need to check csv but that didn't work from arrowbench. I'll try to get some test up and running for it. Besides that I'm happy with the current state.

lidavidm · 2022-04-07T11:55:14Z

Ok, sounds good. We can keep this open until you get a chance to test CSV

joosthooz · 2022-04-07T12:39:31Z

I just ran all the ctests with the otlp trace exporter enabled, and had a look at the traces for parquet, feather, and csv. As far as I can tell from looking at a couple of traces, they seem to behave consistent.

lidavidm · 2022-04-07T12:48:53Z

Merged, thanks for carrying this through!

ursabot · 2022-04-08T04:31:13Z

Benchmark runs are scheduled for baseline = 542158f and contender = 8ea2c93. 8ea2c93 is a master commit associated with this PR. Results will be available as each benchmark for each run completes.
Conbench compare runs links:
[Finished ⬇️0.0% ⬆️0.0%] ec2-t3-xlarge-us-east-2
[Finished ⬇️0.33% ⬆️0.0%] test-mac-arm
[Finished ⬇️1.07% ⬆️0.0%] ursa-i9-9960x
[Finished ⬇️0.21% ⬆️0.0%] ursa-thinkcentre-m75q
Buildkite builds:
[Finished] <https://buildkite.com/apache-arrow/arrow-bci-benchmark-on-ec2-t3-xlarge-us-east-2/builds/465| 8ea2c931 ec2-t3-xlarge-us-east-2>
[Finished] <https://buildkite.com/apache-arrow/arrow-bci-benchmark-on-test-mac-arm/builds/450| 8ea2c931 test-mac-arm>
[Finished] <https://buildkite.com/apache-arrow/arrow-bci-benchmark-on-ursa-i9-9960x/builds/451| 8ea2c931 ursa-i9-9960x>
[Finished] <https://buildkite.com/apache-arrow/arrow-bci-benchmark-on-ursa-thinkcentre-m75q/builds/460| 8ea2c931 ursa-thinkcentre-m75q>
[Finished] <https://buildkite.com/apache-arrow/arrow-bci-benchmark-on-ec2-t3-xlarge-us-east-2/builds/464| 542158fa ec2-t3-xlarge-us-east-2>
[Finished] <https://buildkite.com/apache-arrow/arrow-bci-benchmark-on-test-mac-arm/builds/449| 542158fa test-mac-arm>
[Finished] <https://buildkite.com/apache-arrow/arrow-bci-benchmark-on-ursa-i9-9960x/builds/450| 542158fa ursa-i9-9960x>
[Finished] <https://buildkite.com/apache-arrow/arrow-bci-benchmark-on-ursa-thinkcentre-m75q/builds/459| 542158fa ursa-thinkcentre-m75q>
Supported benchmarks:
ec2-t3-xlarge-us-east-2: Supported benchmark langs: Python, R. Runs only benchmarks with cloud = True
test-mac-arm: Supported benchmark langs: C++, Python, R
ursa-i9-9960x: Supported benchmark langs: Python, R, JavaScript
ursa-thinkcentre-m75q: Supported benchmark langs: C++, Java

lidavidm and others added 7 commits March 11, 2022 14:09

ARROW-15067: [C++] Add tracing spans to the scanner

c78f0cf

ARROW-15067: [C++] Add ASAN suppressions for OTel

18dd557

ARROW-15067: [C++] Add Valgrind suppressions for OTel

12abf3b

ARROW-15067: [C++] Ensure spans propagate through call to scanner

d962563

ARROW-15044: [C++] Use Then()

7385c96

Fix rebase. Scanner::Scan was removed in ARROW-13554.

26d41e6

Propagating spans to asynchronous parquet reader

c5805e0

github-actions bot added Component: C++ Component: Parquet labels Mar 11, 2022

joosthooz added 5 commits March 11, 2022 15:59

Removed a span layer from scanner, added some config ifdefs

f74b77e

Code formatting

e4fa2c9

Added some attributes to parquet column reader span

6f97ba5

TieSpanToAsyncGenerator now ending span when asyncgen finishes

3e00a5f

Added some tracing macros to replace the prolific #ifdefs

8a16e2d

westonpace self-requested a review March 14, 2022 20:08

lidavidm reviewed Mar 14, 2022

View reviewed changes

westonpace reviewed Mar 15, 2022

View reviewed changes

joosthooz added 2 commits March 18, 2022 13:13

Processed review comments

25e654d

Changed lambda capture list to = to prevent errors when building with…

837d56e

…out opentelemetry

joosthooz marked this pull request as draft March 18, 2022 14:19

Attempt at creating a struct wrapper for Future

e742035

joosthooz added 3 commits March 30, 2022 14:56

Reverted some unneeded changes

d3cd60b

Added another guarded macro

b8f6c2f

Formatting

78e528f

lidavidm approved these changes Mar 30, 2022

View reviewed changes

Moving the generators when wrapping them

42798cc

joosthooz marked this pull request as ready for review March 30, 2022 13:25

Formatting

9abf327

westonpace reviewed Mar 31, 2022

View reviewed changes

joosthooz added 6 commits April 1, 2022 15:26

Manually setting the current span as parent is not needed

b1d4689

Removed some helper functions that were too similar in nature

f32fda8

Merged similar tracing functions regarding generators, updated/added …

71f6989

…some comments

Addressed review comment

4a82a7a

Formatting

90e2768

Updated macros for when opentelemetry is disabled

3e24f54

lidavidm reviewed Apr 1, 2022

View reviewed changes

cpp/src/arrow/util/tracing_internal.h Outdated Show resolved Hide resolved

cpp/src/arrow/dataset/file_ipc.cc Outdated Show resolved Hide resolved

westonpace approved these changes Apr 1, 2022

View reviewed changes

joosthooz added 3 commits April 4, 2022 17:24

Removed some left-over code

7330f14

Small updates to otel helper function documentation

df2a6be

Adding a comment about the use of macros for helper functions

567fa30

lidavidm approved these changes Apr 4, 2022

View reviewed changes

lidavidm closed this in 8ea2c93 Apr 7, 2022

asfimport mentioned this pull request Apr 8, 2022

[C++] Add OT spans for the scanner #30581

Closed

ARROW-15067: [C++] Add tracing spans to the scanner #12609

ARROW-15067: [C++] Add tracing spans to the scanner #12609

Uh oh!

Conversation

joosthooz commented Mar 11, 2022 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

github-actions bot commented Mar 11, 2022

Uh oh!

lidavidm left a comment

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Uh oh!

Uh oh!

Uh oh!

Uh oh!

westonpace left a comment

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

lidavidm commented Mar 15, 2022 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

westonpace commented Mar 16, 2022

Uh oh!

lidavidm commented Mar 16, 2022

Uh oh!

westonpace commented Mar 16, 2022

Uh oh!

lidavidm commented Mar 16, 2022

Uh oh!

lidavidm commented Mar 16, 2022

Uh oh!

westonpace commented Mar 16, 2022

Uh oh!

joosthooz commented Mar 18, 2022

Uh oh!

lidavidm left a comment

Choose a reason for hiding this comment

Uh oh!

lidavidm commented Mar 30, 2022

Uh oh!

westonpace left a comment

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

joosthooz Apr 1, 2022 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

joosthooz commented Mar 11, 2022 •

edited

Loading

lidavidm commented Mar 15, 2022 •

edited

Loading

joosthooz Apr 1, 2022 •

edited

Loading

joosthooz Apr 1, 2022 •

edited

Loading

joosthooz Apr 1, 2022 •

edited

Loading

joosthooz Apr 4, 2022 •

edited

Loading