Performance degradation when upgrading from Mongoid '7.1.11' to '7.2.6'

[sosolidkk]

Hello. I've been trying to upgrade the application Mongoid version in my current Job to the latest release available version 7x. We're planning to go through each minor release in order.

When we upgraded from Mongoid 7.1.11 to 7.2.6, it was noticed a huge performance issue with our application response time. Fortunately, it was possible to roll back to the previous version. While investigating, we did not notice any obvious issues. I researched and looked for similar cases as ours, but could not find any. The only discussion I've found about a performance issue was this one: #5783.

The response time from our application has gone from a mean of ~3.5s to ~12s with spikes up to ~16s! You can look in more detail in the graph below.

So looking at our profiling tool, it seems that it was a general degradation of performance. Every one of our controller actions that use Mongoid models became at least twice slower, especially the ones with embedded objects related. I've run a few simple benchmarks on the Rails console to confirm this and those are the results:

Benchmark.bm do |x|
  x.report { 100.times { Product.find('<id>') } }
end

# Mongoid 7.1.11
[#<Benchmark::Tms:0x000055ef70546f18
  @cstime=0.0,
  @cutime=0.0,
  @label="",
  @real=1.0872369608841836,
  @stime=0.031953000000000564,
  @total=0.9286830000000004,
  @utime=0.8967299999999998>]

# Mongoid 7.2.6 - 0,7s slower
[#<Benchmark::Tms:0x0000562c9a06d138
  @cstime=0.0,
  @cutime=0.0,
  @label="",
  @real=1.7621171199716628,
  @stime=0.16086199999999984,
  @total=1.448364999999999,
  @utime=1.2875029999999992>]

Benchmark.bm do |x|
  # The price is an embedded model object of the product
  x.report { 100.times { Product.find('<id>').base_price_on('<country>')) } }
end

# Mongoid 7.1.11
[#<Benchmark::Tms:0x000055c2246d3148
  @cstime=0.0,
  @cutime=0.0,
  @label="",
  @real=4.413711405126378,
  @stime=0.09963099999999958,
  @total=3.9625319999999986,
  @utime=3.862900999999999>]

# Mongoid 7.2.6 - 5,6s slower
[#<Benchmark::Tms:0x0000562c9d3faaa0
  @cstime=0.0,
  @cutime=0.0,
  @label="",
  @real=10.144380155019462,
  @stime=0.0,
  @total=9.393400000000002,
  @utime=9.393400000000002>]

As you can see, the performance hit is huge. Another thing I did was to run a profiler on the find method to see if there was any difference due to the updates. One interesting to notice about the profiler is that as a single find operation, when it ran from version 7.2.6 it was faster than the one in version 7.1.11. But when I ran a lot of those operations in the benchmark, there was this performance issue.

The main 3 points I did notice looking at the profiling result were:

• Increased Activity in Methods:
  • In Mongoid 7.2.6, methods related to session handling and connection pool operations show activity that wasn't as prominent in the 7.1.11 profile. Specifically, there are calls to methods like Mongo::Session::SessionPool#prune!, Mongo::Server::ConnectionPool#closed?, and related session methods.
• Additional Method Calls:
  • The presence of calls to Mongo::Operation::Executable#build_message and Mongo::Operation::Context#server_api in the 7.2.6 profile indicates additional layers of processing, possibly related to changes in how operations are constructed and executed.
• Time Spent in System Calls:
  • The profile for 7.2.6 shows increased time spent in system calls like Mongo::Socket#read_from_socket and associated operations, suggesting more overhead in network communication.

These differences suggest that the increase in CPU time could be due to more complex session and connection management, possibly including additional security or validation steps. Additionally, network-related overhead might have increased, contributing to the slower performance.

But I'm not sure how to proceed further or what to do with this information, to be honest. Is there anything I'm missing or overlooking?

I'll attach the profile text files. I've used the ruby-prof gem. In case any other information is needed, please let me know.

• mongoid_7.2.6_#find.txt
• mongoid_7.1.11_#find.txt

Things I've also tried

• Enable the new query cache driver:
  • While this change reduced the throughput extensively and increase the general application memory usage, it did not solve the performance issue. The response time remained the same.

Throughput

Memory usage

• Upgrade to another minor:
  • I've also tried to upgrade to 7.5.4 directly, but the performance issue still persists.

---

Ruby version: 3.0.7
Rails version: 6.1.7.8
Mongo engine version: 5.0.28

[jamis]

Hello, I've created a Jira ticket for this here: https://jira.mongodb.org/browse/MONGOID-5805

Please feel free to follow that ticket. The team will discuss it early next week and decide how to proceed at that point. Thank you very much for the detailed benchmarks, graphs, and analysis!

[sosolidkk]

Hey everyone,

I have an update for you. I focused on upgrading one of our projects and successfully bumped it to Mongoid version 8.1.5.

After running the same benchmark as before, the performance remains consistent with the original benchmark conducted on version 7.2.6. This suggests that the issue might be related to changes in the embedded matchers in this specific version, potentially indicating a modeling problem too.

Here are the samples:

Benchmark.bmbm do |x|
  x.report { 100.times { Product.find('<id>').base_price_on(Store.by_country('<country-code>')) } }
  x.report { 200.times { Product.find('<id>').base_price_on(Store.by_country('<country-code>')) } }
  x.report { 500.times { Product.find('<id>').base_price_on(Store.by_country('<country-code>')) } }
  x.report { 1000.times { Product.find('<id>').base_price_on(Store.by_country('<country-code>')) } }
end

# mongoid: 7.1.11
Rehearsal ------------------------------------
   3.415295   0.044251   3.459546 (  3.595859)
   6.869250   0.018667   6.887917 (  7.164126)
  17.598962   0.150385  17.749347 ( 18.450457)
  33.913179   0.311032  34.224211 ( 35.674705)
-------------------------- total: 62.321021sec

       user     system      total        real
   3.360374   0.024743   3.385117 (  3.511917)
   6.937873   0.058673   6.996546 (  7.333657)
  15.778529   0.031532  15.810061 ( 16.615579)
  33.721884   0.262641  33.984525 ( 35.529535)

# mongoid: 7.2.6
Rehearsal ------------------------------------
   5.593185   0.135029   5.728214 (  6.180509)
  10.975738   0.031681  11.007419 ( 11.278245)
  28.003974   0.175000  28.178974 ( 28.862600)
  56.053998   0.247771  56.301769 ( 57.688526)
------------------------- total: 101.216376sec

       user     system      total        real
   5.639344   0.030238   5.669582 (  5.812369)
  11.449731   0.059208  11.508939 ( 11.777033)
  28.993665   0.162767  29.156432 ( 29.874103)
  52.370326   0.241265  52.611591 ( 53.984646)

# mongoid: 8.1.5
Rehearsal ------------------------------------
   5.075983   0.036961   5.112944 (  5.240725)
  11.487779   0.111030  11.598809 ( 11.857581)
  24.957660   0.178570  25.136230 ( 25.781198)
  50.967528   0.271955  51.239483 ( 52.527773)
-------------------------- total: 93.087466sec

       user     system      total        real
   5.249386   0.042039   5.291425 (  5.418534)
  10.153218   0.065160  10.218378 ( 10.475583)
  25.483591   0.141079  25.624670 ( 26.308400)
  55.789831   0.387546  56.177377 ( 57.524497)

[jamis]

❤️ Thank you very, very much for your thorough investigation, and for comparing the performance on Mongoid 8.1. We'll discuss this as a team on Monday and decide how to go about investigating it on our end.

[sosolidkk]

Hey @jamis ,

After a few more attempts, I managed to reproduce the slowness in the development environment and identify the root cause.

To replicate the issue in development, I needed the production database dump. Since we use separate databases, it was easy to dump only the product-related data.

With the dump restored in the development environment, I ran the same benchmarks as before, and the performance issue became very noticeable. Here's the benchmark results just for reference:

# mongoid 7.1.11 (prod-dump)
Rehearsal ------------------------------------
  1.244071   0.142323   1.386394 (  1.439709)
   2.362377   0.003044   2.365421 (  2.455422)
   6.164951   0.092651   6.257602 (  6.483721)
  11.957102   0.076804  12.033906 ( 12.495759)
-------------------------- total: 22.043323sec

       user     system      total        real
   1.013919   0.000000   1.013919 (  1.061322)
   2.023460   0.029319   2.052779 (  2.145133)
   5.254368   0.020189   5.274557 (  5.506099)
  10.316356   0.150333  10.466689 ( 10.928981)

# mongoid 7.2.6 (prod-dump)
Rehearsal ------------------------------------
   1.862465   0.020555   1.883020 (  1.932803)
   3.656338   0.051307   3.707645 (  3.801279)
   9.394554   0.110287   9.504841 (  9.737704)
  18.668987   0.089358  18.758345 ( 19.216921)
-------------------------- total: 33.853851sec

       user     system      total        real
   2.091008   0.000096   2.091104 (  2.134195)
   4.144467   0.020035   4.164502 (  4.252782)
   9.654838   0.041099   9.695937 (  9.931751)
  19.482770   0.099986  19.582756 ( 20.044871)

By narrowing down the profiling method to analyze only the base_price_on function and the preceding steps needed to find the Product and Store objects, disabling query cache, I was able to create a smaller profile sample, which I'll share with you all.

Analyzing the profile results, it seems the issue is related to the extract_attribute method refactor. The use of the BSON gem significantly increased the number of newly allocated objects. The method, which previously accounted for only 1.57% of the execution time, now takes up 17.40%, which is a significant hit to performance. A method that was originally executed in 0.03s now runs in 0.1s. In production, it's even worse because the production machine is less powerful than my development machine. The execution time increased from 0.2s to 1.1s, and it worsened as the number of embedded prices in the product model grew. You can see in the callstack images below (the dark red line):

• Mongoid v7.1.11

• Mongoid v7.2.6

• https://github.com/mongodb/mongoid/blob/v7.1.11/lib/mongoid/matchable.rb#L153
• https://github.com/mongodb/mongoid/blob/v7.2.6/lib/mongoid/matcher.rb#L38

Another thing noticed was that some new files created after the release of version 7.2.6 don't have the # frozen_string_literal: true comment on the top of it. Looks unnecessary, but I've edited the local gem folder and added it to all the ruby files that didn't have it already, and ran the same benchmarks as above. Just this simple addition managed to decrease the execution time by 4s (from ~33s to ~29s). Since Mongoid deals with lots of dynamic allocations and string manipulation, it seems necessary to add it back. Here's the same benchmark result:

# mongoid 7.2.6 (prod-dump) with `# frozen_string_literal: true` comment on all `*.rb` files
Rehearsal ------------------------------------
  1.868181   0.046287   1.914468 (  1.973465)
   3.307160   0.004710   3.311870 (  3.406259)
   7.938517   0.021538   7.960055 (  8.178090)
  16.661393   0.098848  16.760241 ( 17.183419)
-------------------------- total: 29.946634sec

       user     system      total        real
   1.530141   0.029377   1.559518 (  1.601373)
   3.185603   0.019200   3.204803 (  3.283713)
   8.310201   0.029361   8.339562 (  8.559034)
  16.426911   0.119703  16.546614 ( 16.998979)

Finally, I'll try to create a simple dummy app that can reproduce the issue above. Can't promise that I'll succeed, but in the next few days, I'll update this thread again with it or with more information on how we'll also tackle this issue on our side. Unfortunately, I could not test this on a newer Mongoid version like 8.1.5. But since the issue persisted as informed in another comment, I believe that the culprit would probably be the same. Please let me know if you guys have any other questions, need more information to tackle this issue and if my explanation makes sense.

Files

Rename the *call_stack.txt files to *call_stack.html. Github don't support upload of HTML files. The flat ones can remain as a .txt

mongoid_7.2.6_call_stack.txt
mongoid_7.1.11_call_stack.txt
mongoid_7.1.11_flat.txt
mongoid_7.2.6_flat.txt

[jamis]

Fantastic investigation, thank you so much for digging in and reporting this. This gives us quite a bit to investigate on our end, and some concrete things to experiment with. Amazing job!

[sosolidkk]

Hey Everyone,

I wanted to share a quick update with you. As discussed, I've created a reproducible Rails app that demonstrates the performance issue we've been discussing:

Nuuvem GitHub Repository - Dummy Mongoid

The results found here and in the README are related to the benchmark executed on my machine.

Feel free to take a look and ask anything if needed!

Edit #1

One thing to note is that the difference in execution time between the dummy app and our application's benchmarks may seem almost unnoticeable in a production environment. This is because the example models in the dummy app are simplified versions of the models we currently use in our project. The Product model has more embedded relations, and the Price model contains more fields and its own relationships as well.

While in the dummy app, I needed to add 300 embedded Price records to a Product instance before noticing a significant difference. However, in our application, just 50 embedded prices are enough to make a very noticeable impact. The issue becomes even more pronounced in products that have 100 or 150 prices.

However, both models suffer from the same issue: unlimited/unchecked growth and the unnecessary loading of excessive data when retrieving a Product. So as the number of embed documents grow, so do the execution time of the code.

[johnnyshields]

@sosolidkk from a cursory look at the diff, a likely culprit is the change to the Mongoid::Matcher::extract_attribute method. The 7.2.6 version introduced logic to create (seemingly unnecessary) intermediate BSON::Document objects (== extra object allocations), and it looks like it's called in a nested/recursive fashion when walking the input query hash.

As far as I can see the other Matcher stuff looks pretty benign, it's all module functions which mostly didn't change (despite namespace rename) and should be performant.

Can you try porting/monkey patching Mongoid::Matcher::extract_attribute with the 7.1.11 version and see if it makes a difference? This patch should work:

# 7.1.1 version of the method, ported to 7.2.6
module Mongoid
  module Matcher
    module_function def extract_attribute(document, key)
      if (key_string = key.to_s) =~ /.+\..+/
        key_string.split('.').inject(document.send(:as_attributes)) do |_attribs, _key|
          if _attribs.is_a?(::Array)
            if _key =~ /\A\d+\z/ && _attribs.none? {|doc| doc.is_a?(Hash)}
              _attribs.try(:[], _key.to_i)
            else
              _attribs.map { |doc| doc.try(:[], _key) }
            end
          else
            _attribs.try(:[], _key)
          end
        end
      else
        if document.is_a?(Hash)
          document[key_string]
        else
          document.attributes[key_string]
        end
      end
    end
  end
end

[sosolidkk]

Hey @johnnyshields, I ran a quick test, and it seems to have caused another issue:

 (irb):3:in `block (3 levels) in <top (required)>': undefined method `length' for 2022-06-09 20:34:30.159 UTC:Time (NoMethodError)
        from (irb):3:in `times'
        from (irb):3:in `block (2 levels) in <top (required)>'
        from (irb):2:in `<main>'

I can't provide a more detailed trace right now, but I'll review this monkey patch next week. Thanks for your help!

[johnnyshields]

OK sure, well this was a very naive attempt at swapping the methods 1-for-1, guess more work is needed.

[jamis]

I took a bit of time to look at this, and it seems like the biggest win comes from re-introducing the short circuit that existed in 7.1.11 -- if the key does not look like it includes any dot notation, don't worry about getting the attributes hash or splitting the key on dot characters, just fetch the corresponding attribute. This will be the most common case anyway, and gets the time back down to pre-7.2 speeds for that common case.

That's the good news.

The bad news is that the 7.x series is no longer being updated. We'll look at making this change and backporting it to the 8.0 branch, but you'll probably need to resort to monkey-patching to add this to 7.x. Maybe something like:

module ShortCircuitExtractAttribute
  def self.included(base)
    base.alias_method :extract_attribute_original, :extract_attribute
    base.alias_method :extract_attribute, :extract_attribute_short_circuited

    base.send :module_function, :extract_attribute_original
    base.send :module_function, :extract_attribute
  end

  def extract_attribute_short_circuited(doc, key)
    return doc.attributes[key] unless key.include?('.')
    extract_attribute_original(doc, key)
  end
end

Mongoid::Matcher.include ShortCircuitExtractAttribute

In my (unscientific) tests, the above actually performs nearly twice as fast in the common case, versus the original (in 7.1.11), mostly because I'm just checking for the existence of a dot, and not for a syntactically-accurate dot. It'll all fall through to the full version anyway, if the simple case doesn't match.

Can you try the above and see how it fares for you? Assuming this helps the situation, we'll see about adding this to Mongoid 8+.

[johnnyshields]

Jamis thanks for this!

Whats the plan to avoid similar performance regressions (ie not related to functional tests) in the future?

[sosolidkk]

Hey @jamis, thanks for the update!

I've implemented the Monkey Patch in the app and reran the benchmarks, but it looks like the same issue that was found in the @johnnyshields suggestion thread occurred again. Fortunately, this time I have a more detailed trace:

undefined method `length' for 2014-08-29 18:28:27.016 UTC:Time
/usr/local/bundle/gems/mongoid-7.2.6/lib/mongoid/matcher/expression.rb:19:in `block in matches?'
/usr/local/bundle/gems/mongoid-7.2.6/lib/mongoid/matcher/expression.rb:13:in `each'
/usr/local/bundle/gems/mongoid-7.2.6/lib/mongoid/matcher/expression.rb:13:in `all?'
/usr/local/bundle/gems/mongoid-7.2.6/lib/mongoid/matcher/expression.rb:13:in `matches?'
/usr/local/bundle/gems/mongoid-7.2.6/lib/mongoid/matcher/or.rb:16:in `block in matches?'
/usr/local/bundle/gems/mongoid-7.2.6/lib/mongoid/matcher/or.rb:15:in `any?'
/usr/local/bundle/gems/mongoid-7.2.6/lib/mongoid/matcher/or.rb:15:in `matches?'
/usr/local/bundle/gems/mongoid-7.2.6/lib/mongoid/matcher/expression.rb:16:in `block in matches?'
/usr/local/bundle/gems/mongoid-7.2.6/lib/mongoid/matcher/expression.rb:13:in `each'
/usr/local/bundle/gems/mongoid-7.2.6/lib/mongoid/matcher/expression.rb:13:in `all?'
/usr/local/bundle/gems/mongoid-7.2.6/lib/mongoid/matcher/expression.rb:13:in `matches?'
/usr/local/bundle/gems/mongoid-7.2.6/lib/mongoid/matchable.rb:25:in `_matches?'
/usr/local/bundle/gems/mongoid-7.2.6/lib/mongoid/contextual/memory.rb:154:in `block in initialize'
/usr/local/bundle/gems/mongoid-7.2.6/lib/mongoid/contextual/memory.rb:151:in `select'
/usr/local/bundle/gems/mongoid-7.2.6/lib/mongoid/contextual/memory.rb:151:in `initialize'
/usr/local/bundle/gems/mongoid-7.2.6/lib/mongoid/contextual.rb:56:in `new'
/usr/local/bundle/gems/mongoid-7.2.6/lib/mongoid/contextual.rb:56:in `create_context'
/usr/local/bundle/gems/mongoid-7.2.6/lib/mongoid/contextual.rb:38:in `context'
/usr/local/lib/ruby/3.0.0/forwardable.rb:232:in `first'

The issue seems to be occurring here, so we'll likely need to Monkey Patch a few more things.

We should consider making this change and backporting it to the 8.0 branch.

If this works, we might upgrade to version 8, as it would be easier than maintaining a Monkey Patch.

[jamis]

@johnnyshields -- we've had https://jira.mongodb.org/browse/MONGOID-5741 in the backlog for a while. Other issues have taken priority.

@sosolidkk -- that's really odd. I don't understand the patch I proposed would trigger that error; it should (?) be returning the same type of value as the original. I'll update the ticket to take a closer look, but it might be a few weeks until we can clear our plates to dig into it deeper.

[sosolidkk]

@jamis @johnnyshields great news! It seems that the Monkey Patch works. I did a quick investigation based on the stack trace result and I've figured out that the returned object was missing a []. So this version of the Monkey Patch works:

# frozen_string_literal: true

module MonkeyPatches
  module ShortCircuitExtractAttribute
    def self.included(base)
      base.alias_method :extract_attribute_original, :extract_attribute
      base.alias_method :extract_attribute, :extract_attribute_short_circuited

      base.send :module_function, :extract_attribute_original
      base.send :module_function, :extract_attribute
    end

    def extract_attribute_short_circuited(doc, key)
      # The return must be an Enumerable/Iterable object
      return [doc.attributes[key]] unless key.include?('.')

      extract_attribute_original(doc, key)
    end
  end
end

Here's the graphic of our response time in production. The fire emoji below is a marker indicating the deploy change to use Mongoid 7.2.6.

I've also executed benchmarks using the same snippet above and here are the results:

# mongoid 7.1.11
Rehearsal ------------------------------------
   3.395436   0.000000   3.395436 (  3.924541)
   8.400087   0.001835   8.401922 (  8.699161)
  15.803796   0.000000  15.803796 ( 16.498614)
  41.755830   0.402051  42.157881 ( 43.588013)
-------------------------- total: 69.759035sec

       user     system      total        real
   3.702150   0.020934   3.723084 (  3.874658)
   6.667085   0.011053   6.678138 (  6.968800)
  18.747047   0.126761  18.873808 ( 19.596759)
  35.386821   0.150632  35.537453 ( 36.892385)

# mongoid 7.2.6 (with monkey patch)
Rehearsal ------------------------------------
   2.966058   0.031866   2.997924 (  3.137352)
   6.272267   0.053009   6.325276 (  6.616166)
  18.844018   0.161597  19.005615 ( 19.708248)
  36.486952   0.300003  36.786955 ( 38.197743)
-------------------------- total: 65.115770sec

       user     system      total        real
   3.160237   0.018037   3.178274 (  3.309532)
   6.676277   0.038973   6.715250 (  6.990774)
  18.189625   0.153963  18.343588 ( 19.032983)
  35.515784   0.307725  35.823509 ( 37.249091)

# mongoid 7.2.6 (without monkey patch)
Rehearsal ------------------------------------
   5.358170   0.161767   5.519937 (  6.202185)
   8.947108   0.000000   8.947108 (  9.221585)
  26.761631   0.233316  26.994947 ( 27.667144)
  53.553877   0.236932  53.790809 ( 55.142505)
-------------------------- total: 95.252801sec

       user     system      total        real
   5.580162   0.031833   5.611995 (  5.741021)
  10.002560   0.052549  10.055109 ( 10.315065)
  26.719314   0.193647  26.912961 ( 27.582100)
  53.189969   0.304232  53.494201 ( 54.874855)

Even though there's a subtle variation in the benchmarks, the result was the same when compared to the version 7.1.11 execution.

On our end, we'll probably ship our application with this patch up to the latest stable version of Mongoid 7.5 or 8. And when the patch is available by default in Mongoid, we'll upgrade again and remove it.

[jamis]

That's great news! Thanks for persevering and figuring out the bug in my code. I'm so glad it works and that the performance is now comparable. We'll get some time scheduled to implement that patch in 8+.

[jamis]

We've committed this change, and it will be released with Mongoid 9.0.3 and Mongoid 8.1.7 (perhaps in the next two or three weeks). The final solution had to take into account a few more considerations in order to satisfy the tests, but the performance improvement ought to still be significant. (See PR #5868.)

Thank you for all your amazing research here, @sosolidkk! It was immensely helpful.

[sosolidkk]

Thank you for the update and help throughout this whole investigation @jamis! I appreciate the effort that went into this change, and I’m glad to hear it will be included in Mongoid future releases.

We've been running the monkey patch version since last month and didn't encounter any performance issues. In some aspects, it's even better.