Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

fix: Reduce allocations on GraphQL hot paths #1544

Merged
merged 4 commits into from
Nov 23, 2023
Merged

fix: Reduce allocations on GraphQL hot paths #1544

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
4 commits
Select commit Hold shift + click to select a range
6bf380a
Reduce allocations on GraphQL hot paths
rmosolgo Nov 21, 2023
2432c70
Update sdk/lib/opentelemetry/sdk/internal.rb
rmosolgo Nov 21, 2023
2c819f3
Update sdk/lib/opentelemetry/sdk/internal.rb
rmosolgo Nov 21, 2023
2f48c4d
Appease the cop
fbogsany Nov 22, 2023
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
10 changes: 5 additions & 5 deletions sdk/lib/opentelemetry/sdk/internal.rb
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -49,17 +49,17 @@ def valid_value?(value)
end

def valid_attributes?(owner, kind, attrs)
attrs.nil? || attrs.all? do |k, v|
Copy link
Contributor Author

@rmosolgo rmosolgo Nov 21, 2023 •
edited
Loading

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I don't exactly understand it, but this was the top allocating location in my benchmark. By switching to each (presumably, a simpler implementation under the hood?), the allocation was removed:

  allocated objects by location
  -----------------------------------
-     1941  /Users/rmosolgo/.rbenv/versions/3.2.2/lib/ruby/gems/3.2.0/gems/opentelemetry-sdk-1.3.1/lib/opentelemetry/sdk/internal.rb:52
      1568  /Users/rmosolgo/.rbenv/versions/3.2.2/lib/ruby/gems/3.2.0/gems/opentelemetry-sdk-1.3.1/lib/opentelemetry/sdk/trace/tracer_provider.rb:143
       803  /Users/rmosolgo/.rbenv/versions/3.2.2/lib/ruby/gems/3.2.0/gems/graphql-2.1.6/lib/graphql/execution/lazy.rb:21
       784  /Users/rmosolgo/.rbenv/versions/3.2.2/lib/ruby/gems/3.2.0/gems/opentelemetry-api-1.2.3/lib/opentelemetry/context.rb:151
       784  /Users/rmosolgo/.rbenv/versions/3.2.2/lib/ruby/gems/3.2.0/gems/opentelemetry-api-1.2.3/lib/opentelemetry/context.rb:153
       784  /Users/rmosolgo/.rbenv/versions/3.2.2/lib/ruby/gems/3.2.0/gems/opentelemetry-api-1.2.3/lib/opentelemetry/trace.rb:39

Looking at the breakdown by class, I'm guessing that Ruby makes an Array in there, somewhere:

  allocated objects by class
  -----------------------------------
-     6230  Hash
+     5453  Hash
-     2395  Array
      1188  Proc
-      871  String
+      875  String
       785  Thread::Mutex
       784  OpenTelemetry::Context

(The difference in Hash allocations is probably best explained by the other part of this PR.)

Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Weirdly, this is failing CI. I'll have to think through the logic, but we're keeping some Event attributes that we should drop.

attrs.nil? || attrs.each do |k, v|
if !valid_key?(k)
OpenTelemetry.handle_error(message: "invalid #{kind} attribute key type #{k.class} on span '#{owner}'")
false
return false
elsif !valid_value?(v)
OpenTelemetry.handle_error(message: "invalid #{kind} attribute value type #{v.class} for key '#{k}' on span '#{owner}'")
false
else
true
return false
end
end

true
end
end
end
Expand Down
12 changes: 6 additions & 6 deletions sdk/lib/opentelemetry/sdk/trace/span.rb
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -282,7 +282,7 @@ def to_span_data
end

# @api private
def initialize(context, parent_context, parent_span, name, kind, parent_span_id, span_limits, span_processors, attributes, links, start_timestamp, resource, instrumentation_scope) # rubocop:disable Metrics/CyclomaticComplexity, Metrics/MethodLength, Metrics/PerceivedComplexity
def initialize(context, parent_context, parent_span, name, kind, parent_span_id, span_limits, span_processors, attributes, links, start_timestamp, resource, instrumentation_scope) # rubocop:disable Metrics/MethodLength, Metrics/PerceivedComplexity
super(span_context: context)
@mutex = Mutex.new
@name = name
Expand All @@ -297,7 +297,7 @@ def initialize(context, parent_context, parent_span, name, kind, parent_span_id,
@total_recorded_events = 0
@total_recorded_links = links&.size || 0
@total_recorded_attributes = attributes&.size || 0
@attributes = attributes.nil? ? nil : Hash[attributes] # We need a mutable copy of attributes.
@attributes = attributes
Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Sometimes, this line was calling an already-duped Hash, which had been created by attributes.merge(result.attributes). Instead of duping it here, I added a .dup call to the calling code in tracer_provider.rb. That way, we'd only create new Hashes when we really needed them.

I didn't find any other callers to this class -- was that a safe substitution?

trim_span_attributes(@attributes)
@events = nil
@links = trim_links(links, span_limits.link_count_limit, span_limits.link_attribute_count_limit)
Expand All @@ -317,7 +317,7 @@ def initialize(context, parent_context, parent_span, name, kind, parent_span_id,
# SpanData.
@monotonic_start_timestamp = monotonic_now
@realtime_start_timestamp = if parent_span.recording?
relative_realtime(parent_span.realtime_start_timestamp, parent_span.monotonic_start_timestamp)
relative_realtime(parent_span.realtime_start_timestamp, parent_span.monotonic_start_timestamp, @monotonic_start_timestamp)
Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Here, every Span#initialize was calling Process.clock_gettime twice: once to initialize @monotonic_start_timestamp, and another time in the implementation of relative_realtime. I noticed that, by passing a time in to that method, we might save that second call out to the system function.

Another use of relative_realtime had to be updated below, it calls monotonic_now directly and passes the result.

else
realtime_now
end
Expand Down Expand Up @@ -419,15 +419,15 @@ def append_event(events, event) # rubocop:disable Metrics/CyclomaticComplexity,
def relative_timestamp(timestamp)
return time_in_nanoseconds(timestamp) unless timestamp.nil?

relative_realtime(realtime_start_timestamp, monotonic_start_timestamp)
relative_realtime(realtime_start_timestamp, monotonic_start_timestamp, monotonic_now)
end

def time_in_nanoseconds(timestamp)
(timestamp.to_r * 1_000_000_000).to_i
end

def relative_realtime(realtime_base, monotonic_base)
realtime_base + (monotonic_now - monotonic_base)
def relative_realtime(realtime_base, monotonic_base, now)
realtime_base + (now - monotonic_base)
end

def realtime_now
Expand Down
2 changes: 1 addition & 1 deletion sdk/lib/opentelemetry/sdk/trace/tracer_provider.rb
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -141,7 +141,7 @@ def internal_start_span(name, kind, attributes, links, start_timestamp, parent_c
if result.recording? && !@stopped
trace_flags = result.sampled? ? OpenTelemetry::Trace::TraceFlags::SAMPLED : OpenTelemetry::Trace::TraceFlags::DEFAULT
context = OpenTelemetry::Trace::SpanContext.new(trace_id: trace_id, span_id: span_id, trace_flags: trace_flags, tracestate: result.tracestate)
attributes = attributes&.merge(result.attributes) || result.attributes
attributes = attributes&.merge(result.attributes) || result.attributes.dup
Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Previously, this hash was duped inside Span.new (described above), but it isn't anymore, so it's dup'ed here instead.

Span.new(
context,
parent_context,
Expand Down
Loading