[Ruby] Increase in memory footprint in 3.15

[robertlaurin]

What version of protobuf and what language are you using?
Version: v3.15.1
Language: Ruby

What operating system (Linux, Windows, ...) and version?
macOS Big Sur Version 11.2.1

What runtime / compiler are you using (e.g., python version or gcc version)
ruby 2.5.3p105 (2018-10-18 revision 65156) [x86_64-darwin19]

What did you do?

Used a minimal script with opentelemetry-ruby to recreate what was observed in production, this script does require a collector running to demonstrate the issue.

require 'bundler/inline'

gemfile(true) do
  source 'https://rubygems.org'

  gem 'google-protobuf', ENV['GOOGLE_PROTOBUF_VERSION']
  gem 'heap-profiler'
  gem 'opentelemetry-api'
  gem 'opentelemetry-sdk'
  gem 'opentelemetry-exporter-otlp'
end

require 'heap-profiler'
require 'opentelemetry-api'
require 'opentelemetry-sdk'
require 'opentelemetry-exporter-otlp'

HeapProfiler.report("heap_output-protobuf-v-#{Gem.loaded_specs['google-protobuf'].version}") do
  span_processor = OpenTelemetry::SDK::Trace::Export::BatchSpanProcessor.new(
    OpenTelemetry::Exporter::OTLP::Exporter.new(
      endpoint: 'http://localhost:55681/v1/trace'
    ),
  )

  OpenTelemetry::SDK.configure do |c|
    c.service_name = 'protobuf-mem-usage'
    c.add_span_processor(span_processor)
  end

  TestTracer = OpenTelemetry.tracer_provider.tracer('protobuf-mem-usage')

  1..10_000.times do
    TestTracer.in_span('parent') do
      1..100.times { TestTracer.in_span('child') {} }
    end
  end
end

What did you expect to see
Using google-protobuf 3.14

heap-profiler heap_output-protobuf-v-3.14.0/
Total allocated: 2.32 GB (22915749 objects)
Total retained: 2.54 MB (17341 objects)

retained memory by class
-----------------------------------
   1.05 MB  Thread
 399.55 kB  OpenTelemetry::SDK::Trace::Span
 358.10 kB  Time
 203.60 kB  String
 166.56 kB  OpenTelemetry::Trace::SpanContext
 150.12 kB  Thread::Mutex
  94.21 kB  OpenTelemetry::SDK::Trace::SpanData
  87.26 kB  Hash
  22.44 kB  Array
   2.08 kB  <ment> (IMEMO)
  344.00 B  Net::HTTP
  280.00 B  Google::Protobuf::RepeatedField
  232.00 B  File
  160.00 B  Proc
  144.00 B  OpenTelemetry::SDK::Trace::Export::BatchSpanProcessor
  128.00 B  Enumerator
  120.00 B  URI::HTTP
  120.00 B  OpenTelemetry::SDK::Trace::TracerProvider
  120.00 B  OpenTelemetry::Exporter::OTLP::Exporter
  120.00 B  Net::HTTP::Post
  120.00 B  Logger::LogDevice
   88.00 B  Net::BufferedIO
   80.00 B  OpenTelemetry::SDK::Trace::Tracer
   80.00 B  OpenTelemetry::SDK::Resources::Resource
   80.00 B  Logger
   80.00 B  <env> (IMEMO)
   56.00 B  Thread::ConditionVariable
   40.00 B  OpenTelemetry::Trace::Span
   40.00 B  OpenTelemetry::SDK::Trace::TracerProvider::Key
   40.00 B  OpenTelemetry::SDK::Trace::NoopSpanProcessor
   40.00 B  OpenTelemetry::SDK::InstrumentationLibrary
   40.00 B  OpenTelemetry::SDK::Baggage::Manager
   40.00 B  OpenTelemetry::Context::Propagation::CompositePropagator
   40.00 B  OpenTelemetry::Context
   40.00 B  Logger::Formatter
   40.00 B  <svar> (IMEMO)

What did you see instead?
Using google-protobuf 3.15.1

heap-profiler heap_output-protobuf-v-3.15.1/
Total allocated: 2.30 GB (22584230 objects)
Total retained: 19.02 MB (356022 objects)

retained memory by class
-----------------------------------
   6.66 MB  Google::Protobuf::Internal::Arena
   4.56 MB  Opentelemetry::Proto::Trace::V1::Status
   4.56 MB  Opentelemetry::Proto::Trace::V1::Span
   1.05 MB  Thread
 396.78 kB  Hash
 393.22 kB  OpenTelemetry::SDK::Trace::Span
 352.43 kB  Time
 219.30 kB  String
 163.92 kB  OpenTelemetry::Trace::SpanContext
 147.74 kB  Thread::Mutex
 110.44 kB  Rational
  94.21 kB  OpenTelemetry::SDK::Trace::SpanData
  80.14 kB  Opentelemetry::Proto::Common::V1::KeyValue
  80.14 kB  Opentelemetry::Proto::Common::V1::AnyValue
  55.74 kB  Array
  36.88 kB  <ifunc> (IMEMO)
  18.40 kB  <memo> (IMEMO)
   8.90 kB  Opentelemetry::Proto::Trace::V1::ResourceSpans
   8.90 kB  Opentelemetry::Proto::Trace::V1::InstrumentationLibrarySpans
   8.90 kB  Opentelemetry::Proto::Resource::V1::Resource
   8.90 kB  Opentelemetry::Proto::Common::V1::InstrumentationLibrary
   8.90 kB  Opentelemetry::Proto::Collector::Trace::V1::ExportTraceServiceRequest
   2.08 kB  <ment> (IMEMO)
  344.00 B  Net::HTTP
  232.00 B  File
  160.00 B  Proc
  144.00 B  OpenTelemetry::SDK::Trace::Export::BatchSpanProcessor
  128.00 B  Enumerator
  120.00 B  URI::HTTP
  120.00 B  OpenTelemetry::SDK::Trace::TracerProvider
  120.00 B  OpenTelemetry::Exporter::OTLP::Exporter
  120.00 B  Net::HTTP::Post
  120.00 B  Logger::LogDevice
   88.00 B  Net::BufferedIO
   88.00 B  <select_set> (DATA)
   80.00 B  OpenTelemetry::SDK::Trace::Tracer
   80.00 B  OpenTelemetry::SDK::Resources::Resource
   80.00 B  Logger
   80.00 B  <throw_data> (IMEMO)
   80.00 B  <env> (IMEMO)
   56.00 B  Thread::ConditionVariable
   40.00 B  OpenTelemetry::Trace::Span
   40.00 B  OpenTelemetry::SDK::Trace::TracerProvider::Key
   40.00 B  OpenTelemetry::SDK::Trace::NoopSpanProcessor
   40.00 B  OpenTelemetry::SDK::InstrumentationLibrary
   40.00 B  OpenTelemetry::SDK::Baggage::Manager
   40.00 B  OpenTelemetry::Context::Propagation::CompositePropagator
   40.00 B  OpenTelemetry::Context
   40.00 B  Logger::Formatter

Anything else we should know about your project / environment
I have had multiple reports of application owners having to revert the google-protobuf gem from 3.15 to 3.14 after seeing their applications double their memory usage, and hitting their limits.

[haberman]

Thanks for the report and the self-contained repro.

This is a result of #8184, which should significantly increase performance, but also changes the memory management model.

I want to do more investigation to get a more detailed root cause. But for now I'll share an overview of the new memory management model, in case it gives you the info you need to fix the problem on your end.

• The old model was: every message is its own Ruby object, which is collected whenever Ruby GCs it.
• The new model is: messages are allocated in C-based arenas, and none of the messages in an arena are freed until the entire arena is GC'd. Any reference to any message in the arena will keep the whole arena alive.

To get a root cause for your issue, we should figure out why the arenas are growing so big. Messages end up in the same arena in a couple of ways:

• If you parse a payload, all of the parsed messages are in one big arena. Keeping even a single reference to any message in the tree will keep the whole tree alive.
• Whenever you assign msg.foo = msg2, then msg and msg2's arenas are joined, and none of the messages in either arena will be freed until all messages in both arenas are garbage.

You can't "break up" an existing arena, but you can use Google::Protobuf.deep_copy to copy messages out of an arena to a new, fresh arena that will contain only that message and its children. (Note: dup and clone won't work for this: since those are shallow copies, they contain references to the other arena still, so they must keep it alive).

I am hoping that a few well-placed Google::Protobuf.deep_copy calls will fix the problem you are experiencing.

[haberman]

For your repro, is it possible to reduce it further so that it is just protobuf operations?

[haberman]

Scratch everything I said before. It is all true, but I just noticed a detail that I think explains all of this better.

I see that you're using Ruby 2.5. Due to a shortcoming in the Ruby WeakMap class that was fixed in 2.7, protobuf 3.15 will retain more memory on pre-2.7 versions of Ruby.

Is it possible for you to upgrade Ruby to 2.7? I believe this will fix the problem you are seeing.

[haberman]

I will also investigate if there is a better way of allowing this collection to happen for Ruby <2.7.

[robertlaurin]

Thanks for the quick response and providing the above explanations. That is welcomed context to have about the changes in behaviour.

So regarding the ruby version, I did the same profiling using ruby 2.7.2 with much better results.

heap-profiler ruby-2.7.2-heap_output-protobuf-v-3.14.0/
Total allocated: 1.64 GB (19128990 objects)
Total retained: 2.54 MB (17218 objects)

retained memory by class
-----------------------------------
   1.05 MB  Thread
 393.22 kB  OpenTelemetry::SDK::Trace::Span
 352.34 kB  Time
 221.19 kB  String
 163.92 kB  OpenTelemetry::Trace::SpanContext
 147.74 kB  Thread::Mutex
  94.21 kB  OpenTelemetry::SDK::Trace::SpanData
  86.34 kB  Hash
  23.40 kB  Array
   2.54 kB  <ment> (IMEMO)
  672.00 B  MatchData
  400.00 B  <mapping_buffer> (DATA)
  360.00 B  Net::HTTP
  280.00 B  Google::Protobuf::RepeatedField
  280.00 B  <svar> (IMEMO)
  232.00 B  File
  176.00 B  <env> (IMEMO)
  160.00 B  Proc
  144.00 B  OpenTelemetry::SDK::Trace::Export::BatchSpanProcessor
  136.00 B  Enumerator
  120.00 B  URI::HTTP
  120.00 B  OpenTelemetry::SDK::Trace::TracerProvider
  120.00 B  OpenTelemetry::Exporter::OTLP::Exporter
  120.00 B  Net::HTTP::Post
  120.00 B  Logger::LogDevice
   96.00 B  Net::BufferedIO
   80.00 B  OpenTelemetry::SDK::Trace::Tracer
   80.00 B  OpenTelemetry::SDK::Resources::Resource
   80.00 B  Logger
   80.00 B  <throw_data> (IMEMO)
   80.00 B  <memo> (IMEMO)
   80.00 B  <ifunc> (IMEMO)
   64.00 B  Thread::ConditionVariable
   64.00 B  Monitor
   40.00 B  OpenTelemetry::Trace::Span
   40.00 B  OpenTelemetry::SDK::Trace::TracerProvider::Key
   40.00 B  OpenTelemetry::SDK::Trace::NoopSpanProcessor
   40.00 B  OpenTelemetry::SDK::InstrumentationLibrary
   40.00 B  OpenTelemetry::SDK::Baggage::Manager
   40.00 B  OpenTelemetry::Context::Propagation::CompositePropagator
   40.00 B  OpenTelemetry::Context
   40.00 B  Logger::Formatter

And with 3.15

heap-profiler ruby-2.7.2-heap_output-protobuf-v-3.15.0/
Total allocated: 1.63 GB (19114662 objects)
Total retained: 2.54 MB (17212 objects)

retained memory by class
-----------------------------------
   1.05 MB  Thread
 393.22 kB  OpenTelemetry::SDK::Trace::Span
 352.43 kB  Time
 221.18 kB  String
 163.92 kB  OpenTelemetry::Trace::SpanContext
 147.74 kB  Thread::Mutex
  94.21 kB  OpenTelemetry::SDK::Trace::SpanData
  86.34 kB  Hash
  23.40 kB  Array
   2.54 kB  <ment> (IMEMO)
  672.00 B  MatchData
  400.00 B  <mapping_buffer> (DATA)
  360.00 B  Net::HTTP
  280.00 B  <svar> (IMEMO)
  232.00 B  File
  176.00 B  <env> (IMEMO)
  160.00 B  Proc
  144.00 B  OpenTelemetry::SDK::Trace::Export::BatchSpanProcessor
  136.00 B  Enumerator
  120.00 B  URI::HTTP
  120.00 B  OpenTelemetry::SDK::Trace::TracerProvider
  120.00 B  OpenTelemetry::Exporter::OTLP::Exporter
  120.00 B  Net::HTTP::Post
  120.00 B  Logger::LogDevice
   96.00 B  Net::BufferedIO
   80.00 B  OpenTelemetry::SDK::Trace::Tracer
   80.00 B  OpenTelemetry::SDK::Resources::Resource
   80.00 B  Logger
   80.00 B  <throw_data> (IMEMO)
   80.00 B  <memo> (IMEMO)
   80.00 B  <ifunc> (IMEMO)
   64.00 B  Thread::ConditionVariable
   64.00 B  Monitor
   40.00 B  OpenTelemetry::Trace::Span
   40.00 B  OpenTelemetry::SDK::Trace::TracerProvider::Key
   40.00 B  OpenTelemetry::SDK::Trace::NoopSpanProcessor
   40.00 B  OpenTelemetry::SDK::InstrumentationLibrary
   40.00 B  OpenTelemetry::SDK::Baggage::Manager
   40.00 B  OpenTelemetry::Context::Propagation::CompositePropagator
   40.00 B  OpenTelemetry::Context
   40.00 B  Logger::Formatter

Unfortunately (for me) this is still a bit of a problem for applications on ruby <2.7

[byroot]

Pre-2.7 you can implement a sketchy WeakMap using https://ruby-doc.org/core-2.5.3/ObjectSpace.html#method-c-_id2ref

[haberman]

@byroot thanks for the lead. What is the behavior of #_id2ref if the object with that ID has been collected? Is it guaranteed to fail, or does the caller have to protect against this by promising never to pass an ID of a collected object?

[byroot]

>> id = Object.new.object_id
=> 70330182748900
>> 4.times { GC.start }
=> 4
>> ObjectSpace._id2ref(id)
RangeError (0x00003ff7058f4ae4 is recycled object)

However I suspect the address might be re-used at some point, so it might weird to weird stuff. I'll have to consult with some people who knows the GC better than me.

Another possibility is to use a mutable proxy object as identifier, as to comply with pre 2.7 WeakMap, but I'll have to dig in the source a bit more, I've only followed the discussion, so not sure what it would be possible to do.

[byroot]

One other thing to consider IMHO, is to just not do Arenas in pre 2.7.

[byroot]

Ah I finally found the code I saw doing this sketchy object_id based weakref: https://github.com/ruby-concurrency/ref/blob/7a3991fea598edfe41d4e3a9e37b344bc7b7570d/lib/ref/weak_reference/pure_ruby.rb

[haberman]

However I suspect the address might be re-used at some point

Yes I was worried about that.

One other thing to consider IMHO, is to just not do Arenas in pre 2.7.

Having two different memory management models co-existing in the code would dramatically complicate the C extension.

PR #8184 (which changed from the old model to the new model) had a line count of +14,071 −23,328. If we left the old memory management model in, it would be more like +14,071 −0.

Ah I finally found the code I saw doing this sketchy object_id based weakref

Ah looks like it is depending on finalizers to remove collected objects from the weak map?

[haberman]

I think I'll try making the cache a regular Hash and relying on the finalizer of each Message object remove the cache entry.

[byroot]

Having two different memory management models co-existing in the code would dramatically complicate the C extension.

That's understandable. Again I've only glanced at the code so I'm a bit clueless at what it does, so until I get the chance to dig into it don't take my suggestions as more than stabs in the dark 😉

Ah looks like it is depending on finalizers to remove collected objects from the weak map?

Yes, just like Ruby's WeakMap, it use the finalizer to remove the Hash entry. But note that this code was written for the MRI 1.8 / 1.9 days. And I just got the confirmation that object_id can be re-used (they're pretty much a pointer to the object slot), so it's not really a reliable method on 2.x.

So the only solution I can see is to find a light mutable object to serve as WeakMap key.

[haberman]

So the only solution I can see is to find a light mutable object to serve as WeakMap key.

How would that work? My WeakMap is { void* -> VALUE }. How would I look up the light mutable object for the C void*?