[SDK] Trace StartSpan - do not call GetCurrentSpan() unless needed

[Hailios]

Fixes # (issue)
it turns out that calling GetCurrentSpan() is not a very cheap operation. it is not uncommon to have that single call take ~10% of the functions total time. Calling it without using the result seems to cause needless slowdown of the user application.

Changes

opentelemetry-cpp/sdk/src/trace/tracer.cc StartSpan used to call GetCurrentSpan() regardless if the caller came with a parent context or not, causing work to be performed that would be thrown away in the if statements right after.

I am using opentelemetry-cpp via conan. The issue was observed with version 1.24.0 (https://conan.io/center/recipes/opentelemetry-cpp?version=1.24.0) currently the latest available on conan center.
I am unable to link the application to a local version of opentelemtry-cpp, and I am therefore unable to verify this change with the application that found the issue.

please make edits as you see fit.

Here is a picture of a trace that illustrates the issue. Time flows left to right, stacks go top to bottom. The marked box on the left is GetCurrentSpan(), a couple of boxes to the right are related such as calling GetContext() on the span, destroying, and deleting a DefaultSpan. in this particular instance GetCurrentSpan() took 2.4us while the entire StartSpan() took 16us.

[linux-foundation-easycla]

The committers listed above are authorized under a signed CLA.

• ✅ login: Hailios / name: Jakob Lövhall (59a386b, 6d86590)

[codecov]

Codecov Report

✅ All modified and coverable lines are covered by tests.
✅ Project coverage is 90.03%. Comparing base (c8c96d4) to head (59a386b).
⚠️ Report is 1 commits behind head on main.

Additional details and impacted files

@@            Coverage Diff             @@
##             main    #3888      +/-   ##
==========================================
- Coverage   90.04%   90.03%   -0.00%     
==========================================
  Files         226      226              
  Lines        7195     7200       +5     
==========================================
+ Hits         6478     6482       +4     
- Misses        717      718       +1     

Files with missing lines	Coverage Δ
sdk/src/trace/tracer.cc	85.08% <100.00%> (+1.21%)	⬆️

... and 1 file with indirect coverage changes

🚀 New features to boost your workflow:

• ❄️ Test Analytics: Detect flaky tests, report on failures, and find test suite problems.

[marcalff]

/easycla

[marcalff]

@Hailios

Thanks for contributing this.

Could you share how to collect profiling data and generate flame graphs in details ? This will be handy for performance investigations in general.

Looking at the flame graph, the next target is likely to be the removal of MultiSpanProcessor when there is only one processor anyway.

[marcalff]

LGTM.

Thanks for the performance analysis and improvement.

[Hailios]

Hi @marcalff,

thanks for the quick actions on this.

for this analysis I used magic-trace, it is a Linux only and Intel only software that integrates with the 'intel_pt' feature of intel cpus. It can with that track exact execution with nanosecond accuracy, quite handy at times.

what it does not do, is to produce traditional flame graphs, it instead produces an exact trace of the execution. that is, it does not do any grouping. it is therefore more useful to understand what happened or went wrong in a specific call that one wants to analyse.

github link for magic-trace https://github.com/janestreet/magic-trace
here is the GUI https://magic-trace.org/ you run the magic-trace collection on your target app/process first to produce a trace file and drag and drop it to the gui to view.

what I did was to run my app, make it have frequent interaction with opentelementry-cpp, and then I ran magic-trace attach -snapshot-size 4M -p <pid> for a few seconds. sometimes sudo helps. and then (after potentially changing ownership of the trace file if ran with sudo) I simply drag the trace file into the gui to view. I zoom into a location where anything happened (a lot of waiting on network is done at this resolution), and found that StartSpan takes quite a while, and specifically GetCurrentSpan takes time even though I know that I am providing a parent span already.

hope it helps :)