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.

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

[Question] - Getting occasional Net::ReadTimeout with #<TCPSocket:(closed) errors #120

Closed
cjilbert504 opened this issue Feb 7, 2022 · 10 comments
Labels
question Further information is requested stale Pull request or issue that has recieve no activity for a long time.

Comments

@cjilbert504
Copy link
Contributor

I am looking for any guidance around improving how we are querying on a model and its association. As it stands we occasionally see the error listed in the title and see a 500 error when it occurs. We believe that the reason for the timeout is the large amount of associated model attribute records that are indexed and being returned. For reference here is how the parent model is setup:

class ForumThread < ApplicationRecord
  extend Pagy::Meilisearch

  include MeiliSearch::Rails

  meilisearch unless: :is_spam? do
    attribute :title, :updated_at, :solved, :user_id
    attribute :forum_posts do
      forum_posts.clean.pluck(:body)
    end

    attribute :participants do
      forum_posts.clean.pluck(:user_id)
    end

    filterable_attributes [:solved, :user_id, :forum_posts, :participants]
    sortable_attributes [:updated_at]
  end

As a temporary fix we have updated our MeiliSearch::Rails.configuration as follows:

MeiliSearch::Rails.configuration = {
  meilisearch_host: 'http://127.0.0.1:7700',
  meilisearch_api_key: Rails.application.secrets.meilisearch_api_key,
  timeout: 3,
  max_retries: 2
}

This seems to have mostly addressed the issue but I'm curious as to whether you had any thoughts on how we could improve the querying here. One thought we had was to set the :forum_posts as a searched but not displayed attribute to see if that would help. The other thought we had is that instead of calling just forum_posts.clean.pluck(:body) which gives an array back to search through, instead join the bodies into one large string. Not sure if that would have any impact or not though.

Thanks for any and all help on this one! It is much appreciated.

@brunoocasali brunoocasali added the question Further information is requested label Feb 7, 2022
@brunoocasali
Copy link
Member

@cjilbert504 this timeout happens only during the indexing? Or does it happen during the search query as well?

@cjilbert504
Copy link
Contributor Author

@brunoocasali - Only during the search query.

@brunoocasali
Copy link
Member

Can you please share your stack trace with me? (this could help me to understand the slowness path of your search request).

Since we aim to respond to users below the 50ms (https://docs.meilisearch.com/learn/what_is_meilisearch/philosophy.html#simple-and-intuitive) we should definitely understand who are causing the slowdown on your request if it is related to the size of the body, the search engine, the ruby side - trying to deal with that -, or anything else.

Meanwhile, I think you had the right approach, by removing some of the data using the displayed_attributes since you will not use it to presentation and increasing your timeout limits.
This could improve your timings because all the data should be parsed somehow by ruby to be presented, if you have a lot of data to be parsed it will take more time.

@excid3
Copy link
Contributor

excid3 commented Feb 7, 2022

@brunoocasali This was happening in production, but also if we ran ms_search in the Rails console.

We're thinking it's because some of the ForumThreads we have indexed have 200-300 posts and we are indexing those as an array of strings on the ForumThread. All the other queries seem to be fine generally except those with massive results.

On the Ruby side, the stacktrace is pretty simple:

net-protocol-0.1.2/lib/net/protocol.rb:219→ rbuf_fill
net-protocol-0.1.2/lib/net/protocol.rb:193→ readuntil
net-protocol-0.1.2/lib/net/protocol.rb:203→ readline
/home/deploy/.rbenv/versions/3.0.3/lib/ruby/3.0.0/net/http/response.rb:42→ read_status_line
/home/deploy/.rbenv/versions/3.0.3/lib/ruby/3.0.0/net/http/response.rb:31→ read_new
/home/deploy/.rbenv/versions/3.0.3/lib/ruby/3.0.0/net/http.rb:1557→ block in transport_request
/home/deploy/.rbenv/versions/3.0.3/lib/ruby/3.0.0/net/http.rb:1548→ catch
/home/deploy/.rbenv/versions/3.0.3/lib/ruby/3.0.0/net/http.rb:1548→ transport_request
/home/deploy/.rbenv/versions/3.0.3/lib/ruby/3.0.0/net/http.rb:1521→ request
airbrake-11.0.3/lib/airbrake/rails/net_http.rb:11→ block in request
airbrake-11.0.3/lib/airbrake/rack.rb:28→ block in capture_timing
airbrake-ruby-5.2.1/lib/airbrake-ruby/timed_trace.rb:29→ span
airbrake-ruby-5.2.1/lib/airbrake-ruby/timed_trace.rb:18→ block in span
/<internal:kernel>:90→ tap
airbrake-ruby-5.2.1/lib/airbrake-ruby/timed_trace.rb:18→ span
airbrake-11.0.3/lib/airbrake/rack.rb:27→ capture_timing
airbrake-11.0.3/lib/airbrake/rails/net_http.rb:10→ request
/home/deploy/.rbenv/versions/3.0.3/lib/ruby/3.0.0/net/http.rb:1514→ block in request
/home/deploy/.rbenv/versions/3.0.3/lib/ruby/3.0.0/net/http.rb:960→ start
/home/deploy/.rbenv/versions/3.0.3/lib/ruby/3.0.0/net/http.rb:1512→ request
airbrake-11.0.3/lib/airbrake/rails/net_http.rb:11→ block in request
airbrake-11.0.3/lib/airbrake/rack.rb:28→ block in capture_timing
airbrake-ruby-5.2.1/lib/airbrake-ruby/timed_trace.rb:29→ span
airbrake-ruby-5.2.1/lib/airbrake-ruby/timed_trace.rb:18→ block in span
/<internal:kernel>:90→ tap
airbrake-ruby-5.2.1/lib/airbrake-ruby/timed_trace.rb:18→ span
airbrake-11.0.3/lib/airbrake/rack.rb:27→ capture_timing
airbrake-11.0.3/lib/airbrake/rails/net_http.rb:10→ request
httparty-0.20.0/lib/httparty/request.rb:152→ perform
httparty-0.20.0/lib/httparty.rb:613→ perform_request
httparty-0.20.0/lib/httparty.rb:543→ post
meilisearch-0.18.1/lib/meilisearch/http_request.rb:39→ block in http_post
meilisearch-0.18.1/lib/meilisearch/http_request.rb:105→ send_request
meilisearch-0.18.1/lib/meilisearch/http_request.rb:38→ http_post
meilisearch-0.18.1/lib/meilisearch/index.rb:191→ search
/GEM_ROOT/bundler/gems/meilisearch-rails-e7ff5841ebe8/lib/meilisearch-rails.rb:255→ block (3 levels) in <class:SafeIndex>
/GEM_ROOT/bundler/gems/meilisearch-rails-e7ff5841ebe8/lib/meilisearch-rails.rb:281→ log_or_throw

/GEM_ROOT/bundler/gems/meilisearch-rails-e7ff5841ebe8/lib/meilisearch-rails.rb:254→ block (2 levels) in <class:SafeIndex>
/GEM_ROOT/bundler/gems/meilisearch-rails-e7ff5841ebe8/lib/meilisearch-rails.rb:572→ ms_raw_search
/GEM_ROOT/bundler/gems/meilisearch-rails-e7ff5841ebe8/lib/meilisearch-rails.rb:612→ ms_search
pagy-5.10.1/lib/pagy/extras/meilisearch.rb:47→ pagy_meilisearch

Which is triggered by our controller action that just runs the query:

@forum_threads = ForumThread.pagy_search(params[:query], sort: ['created_at:desc'])
@pagy_forum_threads, @forum_threads = pagy_meilisearch(@forum_threads)

Since this happens with just a ms_search in the console, I know it's not with Pagy and given that it's a Net::HTTP error, it seems like meilisearch server is taking too long to respond.

That's why we're leaning towards it being an issue with the way we've indexed the forum threads and posts. Each of the documents here are going to be pretty large considering several forum threads are indexing the content of 200+ forum posts:

Screen Shot 2022-02-07 at 2 33 53 PM

Should we be looking for anything special in the Meilisearch server logs to better optimize this?

@brunoocasali
Copy link
Member

Hello everyone, I wasn't able to check this yet, but I promise I will! (I just haven't the time to dig into this we are upgrading the integrations to v0.26 😅). I'll come back to this soon!

@schappim
Copy link

I can confirm I'm seeing this on reindexing ~28K records.

@brunoocasali
Copy link
Member

First of all, sorry for this long waiting period!

I had a time, and I did a lot of experiments in the rails and the ruby gems. I had internal conversations, and I can answer most of the questions, which maybe raise other questions!

TL;DR:

  • Selecting only the fields you need will speed up the search especially when there are many fields. Defining searchable_attributes and attributes_to_retrieve is the first step to improve response time.
  • The way Meilisearch receives the attribute, an array, or a big string, doesn't matter.

Unfortunately, I could not reproduce the error (without creating flaky tests) to fix it with tests. If anyone has any ideas, let me know.

1st about the array or one string:

The other thought we had is that instead of calling just forum_posts.clean.pluck(:body) which gives an array back to search through, instead join the bodies into one large string. Not sure if that would have any impact or not though.

Having a large string or an array of strings does not matter for the Meilisearch server, since both ways will be tokenized internally, so, since you already have an array, you can keep it, then you will not need extra work to join it in a big string.

2nd about the displayedAttributes:
The Net::ReadTimeout is indeed caused by a large response from the Meilisearch side, but the real pain here is because rails need to handle a huge response.

But to prevent that behavior, we should improve the search usage with searchable_attributes/attributes_to_retrieve to have a smaller response (this is recommended by the core team) and definitely will enhance the performance.

I made some tests locally, and I came up with a huge difference, e.g., 4.366 hits had a response size of 3.5MB including all the attributes, and when I adequately configured the attributesToRetrieve in the search query, I was able to reduce it to 14Kb.

I created a small benchmark to help share the timing results with you, and here it is:

Benchmark.bm do |x|
  x.report("attrs: [id]") { 30.times { Restaurant.ms_search("bra", attributes_to_retrieve: ["id"], limit: 5000) } }
  x.report("attrs: [**]") { 30.times { Restaurant.ms_search("bra", limit: 5000) } }
  # to prevent some caching I inverted the order and ran again
end

image

Anyway, I give all this context to mention that I will generate an issue about a possible enhancement in the default search behavior of the rails gem. The idea is to use attributesToRetrieve with just the "id" by default whenever possible. It should reduce the work rails needed to process a Meilisearch response and reduce the timeout error you are seeing currently.

Since I keep you guys waiting for so long, @cjilbert504 and @excid3, did you come up with other solutions than this one?

@brunoocasali
Copy link
Member

By the way, @cjilbert504 the meilisearch instance is located in the same region of your app? Do you know how long it takes (on average) for meilisearch to answer your search requests?

@brunoocasali
Copy link
Member

@schappim about your situation, indexing is indeed something we need to enhance in our core. Still, I'm almost sure that this is not related to Meilisearch Rails directly unless you have some N+1 in your indexing process.
Can you share more information with me about that?

@brunoocasali brunoocasali added the stale Pull request or issue that has recieve no activity for a long time. label Aug 11, 2022
@brunoocasali
Copy link
Member

I'm closing this issue due to inactivity. Feel free to reopen it if needed!

Also, I've created this issue #193 that could help improve the perceived performance.

Thanks for using Meilisearch! :)

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
question Further information is requested stale Pull request or issue that has recieve no activity for a long time.
Projects
None yet
Development

No branches or pull requests

4 participants