Mongoid 8 slow insertions?

Working with Data Drivers
,
1

Hi,
We are testing Mongoid 8.0.3 using MongoDB 6 Community. We noticed that database insertions using rspec are happening multitudes slower. It’s really odd. The older version Mongoid 7.5 inserts 150 records in 0.550355 seconds but Mongoid 8.0.3 would take over 2 seconds.
QueryCache is disabled in both cases.
Anyone else noticing this issue?

2

Hi netwire,

This sounds very serious! We’ll try to reproduce the issue; it would be helpful if you can provide us with some additional info:

  • What is your deployment setup - standalone, replica set, sharded cluster?
  • Is it possible to provide us with some code snippets of your tests? Or can you describe operations that are now slower?
  • How do you measure the query duration?
3

Hi @Dmitry_Rybakov, sorry for the very delayed reply. We were hoping version updates would’ve helped but it hasn’t.

We just tried Mongoid v8.1.4 and it’s still very slow.

Here’s the setup:

mongoid community 7 on mac os
ruby 3.2.2
rails 6.1.7.6
mongoid 8.1.4

Here’s the rspec code

time_started = Time.now
create_list(:orders, 500)
puts "Finished create_list in #{Time.now - time_started} seconds."

With Mongoid 7.5.4, output: Finished create_list in 0.521735 seconds.
With Mongoid 8.1.4 (everything else the same), output: Finished create_list in 57.659705 seconds.

4

Hi @netwire,

Would you be able to share a self-contained reproduction (including a Gemfile/Gemfile.lock) that we could use to verify this issue? We continue to work on improving the performance of the products so if there’s a significant regression such as what you’ve described we’d like to investigate it more thoroughly.

If you are able to share a link to a GitHub repository that reproduces the behavior you’ve described it would put us in a better position to investigate further.

5

Hi @alexbevi

Here’s what I did:

  1. created new project per Getting Started (Rails) — Mongoid Manual 7.1
  2. created a new model:
# frozen_string_literal: true

class Account
  include Mongoid::Document
  include Mongoid::Timestamps

  field :email, type: String

end
  1. Run rails c with
Account.delete_all
time_started = Time.now
(1..500).each do |i|
Account.create(email: "test#{i}@test.com")
end
puts "Finished creating items in #{Time.now - time_started} seconds."

Result:
Mongoid: 7.5.4: Finished creating items in 0.248197 seconds.

Mongoid: 8.1.4: Finished creating items in 1.228574 seconds.

Is there a way I can PM you the Git repository? I cannot upload Gemfile and Gemfile.lock

6

@netwire I adapter your example as follows:

# frozen_string_literal: true
#
# filename: test.rb
#
require 'bundler/inline'

gemfile do
  source 'https://rubygems.org'

  gem 'mongoid', '7.5.4'
  #gem 'mongoid', '8.1.4'
end

local_conn = "mongodb://localhost:27017/test"
atlas_conn = "mongodb+srv://USER:PASS@cluster0.abcde.mongodb.net"

Mongoid.configure do |config|
  config.clients.default = {
   uri: local_conn
  }
end

class Account
  include Mongoid::Document
  include Mongoid::Timestamps

  field :email, type: String
end

time_started = Time.now
Account.delete_all
(1..500).each do |i|
  Account.create(email: "test#{i}@test.com")
end
puts "[Mongoid #{Mongoid::VERSION}] Finished creating items in #{Time.now - time_started} seconds."

I tried running the above script against both a local standalone and an M10 in Atlas and got the following:

# Atlas M10
[Mongoid 7.5.4] Finished creating items in 18.134892 seconds.
[Mongoid 7.5.4] Finished creating items in 18.107205 seconds.
[Mongoid 7.5.4] Finished creating items in 18.149107 seconds.

[Mongoid 8.1.4] Finished creating items in 19.223129 seconds.
[Mongoid 8.1.4] Finished creating items in 18.696247 seconds.
[Mongoid 8.1.4] Finished creating items in 18.44864 seconds.

# Local standalone
[Mongoid 7.5.4] Finished creating items in 0.343445 seconds.
[Mongoid 7.5.4] Finished creating items in 0.360401 seconds.
[Mongoid 7.5.4] Finished creating items in 0.342929 seconds.

[Mongoid 8.1.4] Finished creating items in 0.394659 seconds.
[Mongoid 8.1.4] Finished creating items in 0.39666 seconds.
[Mongoid 8.1.4] Finished creating items in 0.360032 seconds.

While it does seem that 8.x is “slower” than 7.x it does not appear to be by a meaningful amount.

Can you try the above script and let me know if you’re seeing significantly different results?

7

Honestly, we just upgraded from 7.5.4 to 8.1.4. It took a few weeks to iron out the changes, it worked seemingly fine in development and testing. When we got to production we took a massive performance hit. I wouldn’t say this is limited to creating records either, we found report pages that were reading only that previously took just 5 seconds to load (which isn’t great anyway), went to 40 - 60 seconds

We have had to revert our entire upgrade save a few performance gains we found along the way which is disappointing.

Happy to help find the cause of this but at the moment we are at a loss.

RobL

8

Hello!

We have similar issue with mongoid 8. We have a test to insert 1000 documents using factory_bot. With mongoid 7.5.4 it takes about 9 seconds. With mongoid 8.1.4 it takes 780 seconds (13 minutes). We observe, that each new document insertion takes more time than previous one.

Please, find our sample code below:

class First
  include Mongoid::Document
  include Mongoid::Timestamps::Short

  field :name, type: String

  has_many :seconds, :dependent => :destroy
  has_many :thirds, dependent: :destroy
  
  validates_uniqueness_of :name
  validates_presence_of :name

end

class Second
  include Mongoid::Document
  include Mongoid::Timestamps::Short

  field :name, type: String

  belongs_to :first
  has_and_belongs_to_many :thirds
end

class Third
  include Mongoid::Document
  include Mongoid::Timestamps::Short

  field :name, type: String

  validates_presence_of :name
  validates_format_of :name, without: /\/|\\|\&|\?|\s/
  
  has_and_belongs_to_many :seconds
  belongs_to :first
end

Test factories for factory_bot:

FactoryBot.define do
  factory :first do
    sequence(:name){ |i| "First name_#{i}" }
  end
end

FactoryBot.define do
  factory :second do
    sequence(:name){ |i| "Second name_#{i}" }
  end
 end

FactoryBot.define do
  factory :third do
    sequence(:name){ |i| "Third name_#{i}" }
  end
end

And test:

let(:first) { create(:first) }
let(:second_1) { create(:second, first: first) }
let(:second_2) { create(:second, first: first) }
let(:thirds_1000) { create_list(:third, 1000, first: first, seconds: [second_1, second_2]) }

it 'checks 1000 thirds insertion' do
  start_time = Time.now.utc
  thirds_1000
  puts "Time spent: #{Time.now.utc - start_time} seconds"  
end

Output for mongoid 7.5.4:
Time spent: 8.92853051 seconds

Output for mongoid 8.1.4:
Time spent: 780.104147085 seconds

Best Regards,
Ilya Starovoytov

9

Hello @Ilya_Starovoytov, thank you for sharing your results and some code to reproduce them. This is very helpful.

I’ve taken the code you provided and put it in a single script—I believe it all does the same thing yours does, and I do see a performance regression going from 7.5.4 to 8.1.4. However, in my case, it’s only about 6x slower, rather than ~100x slower.

This is still significant, and we intend to investigate it, but I want to make sure that I’m investigating the same behavior you’re seeing. Can you take the script I’m using (copied below) and confirm the same performance you reported?

require 'mongoid'
require 'factory_bot'
require 'rspec/autorun'

Mongoid.connect_to 'mongoid-5740'
Mongoid.purge!

class First
  include Mongoid::Document
  include Mongoid::Timestamps::Short

  field :name, type: String

  has_many :seconds, dependent: :destroy
  has_many :thirds, dependent: :destroy

  validates_uniqueness_of :name
  validates_presence_of :name

end

class Second
  include Mongoid::Document
  include Mongoid::Timestamps::Short

  field :name, type: String

  belongs_to :first
  has_and_belongs_to_many :thirds
end

class Third
  include Mongoid::Document
  include Mongoid::Timestamps::Short

  field :name, type: String

  validates_presence_of :name
  validates_format_of :name, without: /\/|\\|\&|\?|\s/

  has_and_belongs_to_many :seconds
  belongs_to :first
end

FactoryBot.define do
  factory :first do
    sequence(:name){ |i| "First_name_#{i}" }
  end
end

FactoryBot.define do
  factory :second do
    sequence(:name){ |i| "Second_name_#{i}" }
  end
 end

FactoryBot.define do
  factory :third do
    sequence(:name){ |i| "Third_name_#{i}" }
  end
end

RSpec.describe 'insert performance' do
  include FactoryBot::Syntax::Methods

  let(:first) { create(:first) }
  let(:second_1) { create(:second, first: first) }
  let(:second_2) { create(:second, first: first) }
  let(:thirds_1000) { create_list(:third, 1000, first: first, seconds: [second_1, second_2]) }

  it 'checks 1000 thirds insertion' do
    start_time = Time.now.utc
    thirds_1000
    puts "[#{Mongoid::VERSION}]: #{Time.now.utc - start_time} seconds"
  end
end

When I run this against 7.5.4, 8.0.7, 8.1.4, and the master branch (9.0.0-alpha), I get the following timings (on my M1 Macbook, against MongoDB 7.0.5 running locally in a sharded configuration):

[7.5.4]: 33.691952 seconds
[8.0.7]: 186.871009 seconds
[8.1.4]: 186.438292 seconds
[9.0.0.alpha]: 173.630884 seconds

The performance regression I’m seeing here seems to be related to belongs_to associations enforcing validations all the way up the association chain, on save. When I set Mongoid.belongs_to_required_by_default = false and re-run the test, I get the following timings:

[8.0.7]: 31.389694 seconds
[8.1.4]: 29.274998 seconds
[9.0.0.alpha]: 35.607121 seconds

Which, as you can see, puts the results back into the same ballpark as 7.5.4. We are currently tracking this particular regression in the following tickets:

I’m hoping that you’re encountering this same regression, rather than something new, but please let me know what you see when you run this script. Thank you again!

  • Jamis
10

Hello Jamis,

Thank you for quick response. I have tested your script and got following results:

[7.5.4]: 4.758970024 seconds
[8.1.4]: 261.87339748 seconds

With Mongoid.belongs_to_required_by_default = false :
[8.1.4]: 4.759053657 seconds

Best Regards,
Ilya Starovoytov

11

Thank you Ilya, this does sound like the belongs_to issue that we’re aware of. We’ve discussed some options internally for mitigating this. Stay tuned!

  • Jamis
12

We monkey patched this in our app just to move us forward.

# HACK: not ready to validates_associated everywhere
# @owner_class.validates_associated(name) if validate? || require_association?
@owner_class.validates_associated(name) if validate?

But this was not the only performance issue we found. So it can’t be limited to just inserts. But this is still a big deal.

13

Mongoid 8.0.8 and 8.1.5 are available now, addressing this performance regression.

14

Hello Jamis,

Thank you for fixes! I have tested latest releases with following results:

[7.5.4]: 4.715095119 seconds
[8.0.8]: 4.201214244 seconds
[8.1.5]: 4.272109324 seconds

With Mongoid.belongs_to_required_by_default = false
[8.0.8]: 4.305470905 seconds
[8.1.5]: 4.303597519 seconds

Best Regards,
Ilya Starovoytov

1 Like
15

Thank you everyone. Seems like Version 8.1.5 did the trick.

1 Like
16

Hi! We wanted inform you that we have made a change to the previous performance regression fix ( MONGOID-5704 ). In the previous fix, we only validated associations that were currently in-memory and unpersisted or modified. We are removing the check for unpersistence/modification as we were encountering issues with incorrect validation for associations dependent on the parent state if the parent updates without the child updating. However, since we are still only checking associations that are currently in-memory, this change should not result in a drastic performance regression. Wanted to reach out and make sure you were aware of this as it will be included in the next release.

17

Hi! Thank you for this info. I will test performance in next release.