fix: Reduce allocations on GraphQL hot paths

[rmosolgo]

👋 I was investigating memory consumption from a GraphQL perspective and I found a few places I thought might be improved. In my benchmark, this improved the total memory consumption by 11% (17% of objects):

- Total allocated: 1809805 bytes (15888 objects)
+ Total allocated: 1601789 bytes (13174 objects)
  Total retained:  0 bytes (0 objects)

  allocated memory by gem
  -----------------------------------
-  1003824  opentelemetry-sdk-1.3.1
+   795648  opentelemetry-sdk-1.3.1
    381029  graphql-2.1.6
    194512  opentelemetry-api-1.2.3
    189656  opentelemetry-instrumentation-graphql-0.26.7
     35952  other
      4288  racc-1.7.3
       368  logger
       136  monitor
        40  set

otel_bench.rb

require "bundler/inline"

gemfile(false) do
  source "https://rubygems.org"
  gem "graphql", "2.1.6"
  gem "opentelemetry-sdk" # , path: "~/code/opentelemetry-ruby/sdk"
  gem "opentelemetry-api" # , path: "~/code/opentelemetry-ruby/api"
  gem "opentelemetry-instrumentation-graphql" # , path: "~/code/opentelemetry-ruby-contrib/instrumentation/graphql"
  gem "benchmark-ips"
  gem "memory_profiler"
  gem "stackprof"
end

class MySchema < GraphQL::Schema
  DATA = {
    "5" => {
      name: "Beatrix Potter",
    },
    "6" => {
      name: "J.R.R. Tolkien"
    },
    "10" => {
      title: "The Tale of Squirrel Nutkin",
      author_id: "5",
      recommended_book_ids: ["11", "12"],
    },
    "11" => {
      title: "The Tale of Ginger and Pickles",
      author_id: "5",
      recommended_book_ids: ["10", "12"],
    },
    "12" => {
      title: "The Tale of Mr. Tod",
      author_id: "5",
      recommended_book_ids: ["11", "10"],
    },
    "21" => {
      title: "The Hobbit",
      author_id: "6",
      recommended_book_ids: ["22", "23", "24", "25", "26", "27"],
    },
    "22" => {
      title: "The Fellowship of the Ring",
      author_id: "6",
      recommended_book_ids: ["21", "23", "24", "25", "26", "27"],
    },
    "23" => {
      title: "The Two Towers",
      author_id: "6",
      recommended_book_ids: ["22", "21", "24", "25", "26", "27"],
    },
    "24" => {
      title: "The Return of the King",
      author_id: "6",
      recommended_book_ids: ["22", "23", "21", "25", "26", "27"],
    },
    "25" => {
      title: "The Silmarillion",
      author_id: "6",
      recommended_book_ids: ["22", "23", "24", "21", "26", "27"],
    },
    "26" => {
      title: "The Adventures of Tom Bombadil",
      author_id: "6",
      recommended_book_ids: ["21", "22", "23", "24", "25", "27"]
    },
    "27" => {
      title: "Leaf by Niggle",
      author_id: "6",
      recommended_book_ids: ["21", "22", "23", "24", "25", "26"]
    }
  }

  module Node
    include GraphQL::Schema::Interface
    field :id, ID
  end

  class Author < GraphQL::Schema::Object
    def self.authorized?(obj, ctx)
      -> { true }
    end
    implements Node
    field :name, String
    field :books, ["MySchema::Book"]

    def books
      author_id = DATA.find { |(id, auth)| auth == object }.first
      DATA.each_value.select { |d| d[:author_id] == author_id }
    end
  end

  class Book < GraphQL::Schema::Object
    implements Node
    field :title, String
    field :author, Author
    field :recommended_books, [Book]

    def author
      DATA[object[:author_id]]
    end

    def recommended_books
      object[:recommended_book_ids].map { |id| -> { DATA[id] } }
    end
  end

  class Query < GraphQL::Schema::Object
    field :node, Node do
      argument :id, ID
    end

    def node(id:)
      DATA[id]
    end
  end

  query(Query)

  orphan_types(Book, Author)

  def self.resolve_type(type, obj, ctx)
    if obj.key?(:name)
      Author
    elsif obj.key?(:title)
      Book
    else
      raise "Unknown object: #{obj.inspect}"
    end
  end

  lazy_resolve(Proc, :call)
end

OpenTelemetry::SDK.configure do |c|
  c.use 'OpenTelemetry::Instrumentation::GraphQL', {
    schemas: [MySchema],
    # enable_platform_field maps to the execute_field and execute_field_lazy keys
    enable_platform_field: true,
    # enable_platform_authorized maps to the authorized and authorized_lazy keys
    enable_platform_authorized: true,
    # enable_platform_resolve_type maps to the resolve_type and resolve_type_lazy keys
    enable_platform_resolve_type: true,
  }
end


# puts MySchema.to_definition

small_query_str = <<-GRAPHQL
query {
  node(id: "10") {
    __typename
    ... on Book {
      title
      author {
        __typename
        name
      }
      recommendedBooks {
        __typename
        title
      }
    }
  }
}
GRAPHQL

large_query_str = <<-GRAPHQL
{
  node(id: "6") {
    ... on Author {
      name
      books {
        title
        recommendedBooks {
          title
          author { name }
          recommendedBooks { title }
        }
      }
    }
  }
}
GRAPHQL

# pp MySchema.execute(small_query_str).to_h
# pp MySchema.execute(large_query_str).to_h

Benchmark.ips do |x|
  x.report("small query") { MySchema.execute(small_query_str) }
  x.report("large query") { MySchema.execute(large_query_str) }
end

query_str = large_query_str

puts "\n\n\n"

result = StackProf.run(mode: :wall, interval: 1) do
  MySchema.execute(query_str)
end
report = StackProf::Report.new(result)
File.open("tmp/otel_query.dump", "wb+") { |f| report.print_dump(f) }
report.print_text

report = MemoryProfiler.report do
  MySchema.execute(query_str)
end
puts "\n\n\n"
report.pretty_print

[rmosolgo]

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.)

[fbogsany]

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

[rmosolgo]

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.

[rmosolgo]

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?

[rmosolgo]

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

[fbogsany]

LGTM, thanks!

[fbogsany]

Blocking while we debug the CI failures.

[rmosolgo]

Good call on break to return, thanks!