Sidekiq is slow on deployed instance

Viewed 416

I know there are tons of questions out there about sidekiq and speed related concerns, so I will try to be as specific as possible.

I have been using Sidekiq for a long time without any major issues and it has been working great for all our needs in our production Ruby on Rails web app which handles lots of data pulled from APIs. Recently we have been working on an update that greatly increases the amount of data we need to pull, so I thought no problem, I'll just upgrade the server, but now even after doing that, my Sidekiq strangely processes jobs about 5 times faster on my localhost than on my deployed staging version. Up until this code update it has always been the other way around, MUCH faster on deployed instances than localhost. As if that wasn't bad enough, I am now running into memory leak issues, only taking place in deployment.

Here are a few more details about my local configuration.

My computer has 16GB RAM.

I am running sidekiq in my terminal through bundle exec sidekiq and redis server as a service with the command service redis-server start.

The job I am running processes data in a given time range. It takes about 1 minute to process 1 month of data and about 15 minutes to process 1 year of data.

In staging deployment I am using a Lightsail ubuntu instance running an nginx server with 16GB RAM & 4 CPUs.

I am running sidekiq & redis-server both as services.

Here it takes about 5 minutes to process 1 month of data and 1+ hour to process 1 year of data.

Here are my configuration files:

config/sidekiq.yml

---
:verbose: false
:logfile: ./log/sidekiq.log
:pidfile: ./tmp/pids/sidekiq.pid
:concurrency: 5
staging:
  :concurrency: 10
production:
  :concurrency: 10
:queues:
  - default
  - active_storage_analysis
  - active_storage_purge

config/initializers/sidekiq.rb

Sidekiq.configure_server do |config|
    # Load our super duper secrets
    env_file = File.join(Rails.root, 'config', 'local_env.yml')
    YAML.load(File.open(env_file)).each do |key, value|
        ENV[key.to_s] = value
    end if File.exists?(env_file)

    config.client_middleware do |chain|
        chain.add SidekiqUniqueJobs::Middleware::Client
    end

    config.server_middleware do |chain|
        chain.add SidekiqUniqueJobs::Middleware::Server
    end

    SidekiqUniqueJobs::Server.configure(config)
end

Sidekiq.configure_client do |config|
    config.client_middleware do |chain|
        chain.add SidekiqUniqueJobs::Middleware::Client
    end
end

config/cable.yml

development:
  adapter: async

test:
  adapter: async

staging:
  adapter: redis
  url: <%= ENV.fetch("REDIS_URL") { "redis://localhost:6379/1" } %>
  channel_prefix: test_production

production:
  adapter: redis
  url: <%= ENV.fetch("REDIS_URL") { "redis://localhost:6379/1" } %>
  channel_prefix: test_production

config/database.yml

development: &default_settings
  adapter: postgresql
  port: 5432
  pool: 5
  host: localhost
  encoding: unicode
  database: development
  username: ***
  password: ***
  min_messages: warning

test:
  adapter: postgresql
  port: 5432
  pool: 5
  host: localhost
  encoding: unicode
  database: test
  username: ***
  password: ***

staging:
  adapter: postgresql
  port: 5432
  pool: 10
  host: localhost
  encoding: unicode
  database: production
  username: ***
  password: ***

production:
  adapter: postgresql
  port: 5432
  pool: 10
  host: ***
  encoding: unicode
  database: production
  username: ***
  password: ***

sidekiq.service unit file

[Unit]
Description=sidekiq
# start us only once the network and logging subsystems are available,
# consider adding redis-server.service if Redis is local and systemd-managed.
After=syslog.target network.target redis-server.service

# See these pages for lots of options:
# http://0pointer.de/public/systemd-man/systemd.service.html
# http://0pointer.de/public/systemd-man/systemd.exec.html
[Service]
Type=simple
WorkingDirectory=/var/www/apps/my-app
PIDFile=/var/www/apps/my-app/tmp/pids/sidekiq.pid
# If you use rbenv:
ExecStart=/home/ubuntu/.rbenv/shims/bundle exec sidekiq -e staging
# If you use the system's ruby:
#ExecStart=/usr/local/bin/bundle exec sidekiq -e production
User=ubuntu
Group=ubuntu
UMask=0002

# Greatly reduce Ruby memory fragmentation and heap usage
# https://www.mikeperham.com/2018/04/25/taming-rails-memory-bloat/
Environment=MALLOC_ARENA_MAX=2

# if we crash, restart
RestartSec=1
Restart=on-failure

# output goes to /var/log/syslog
StandardOutput=syslog
StandardError=syslog

# This will default to "bundler" if we don't specify it
SyslogIdentifier=sidekiq

[Install]
WantedBy=multi-user.target

redis-server.service unit file

[Unit]
Description=Advanced key-value store
After=network.target
Documentation=http://redis.io/documentation, man:redis-server(1)

[Service]
Type=forking
ExecStart=/usr/bin/redis-server /etc/redis/redis.conf
ExecStop=/bin/kill -s TERM $MAINPID
PIDFile=/var/run/redis/redis-server.pid
TimeoutStopSec=0
Restart=always
User=redis
Group=redis
RuntimeDirectory=redis
RuntimeDirectoryMode=2755

UMask=007
PrivateTmp=yes
LimitNOFILE=65535
PrivateDevices=yes
ProtectHome=yes
ReadOnlyDirectories=/
ReadWriteDirectories=-/var/lib/redis
ReadWriteDirectories=-/var/log/redis
ReadWriteDirectories=-/var/run/redis

NoNewPrivileges=true
CapabilityBoundingSet=CAP_SETGID CAP_SETUID CAP_SYS_RESOURCE
MemoryDenyWriteExecute=true
ProtectKernelModules=true
ProtectKernelTunables=true
ProtectControlGroups=true
RestrictRealtime=true
RestrictNamespaces=true
RestrictAddressFamilies=AF_INET AF_INET6 AF_UNIX

# redis-server can write to its own config file when in cluster mode so we
# permit writing there by default. If you are not using this feature, it is
# recommended that you replace the following lines with "ProtectSystem=full".
ProtectSystem=true
ReadWriteDirectories=-/etc/redis

[Install]
WantedBy=multi-user.target
Alias=redis.service

The worker I am running

class SearchCcDataWorker
  include Sidekiq::Worker
  include MetricsHelper
  sidekiq_options retry: 0
  sidekiq_options backtrace: true
  sidekiq_options lock: :while_executing, unique_args: ->(args) { [ args.first ] }
  sidekiq_options on_conflict: :reschedule

  def perform(search_section_id, start_date, end_date)
    ActiveRecord::Base.uncached do
      start_date = start_date.to_date
      end_date = end_date.to_date
      original_start_date = start_date
      search_section = SearchSection.find(search_section_id)
      campaign_groups = search_section.campaign_groups
      ppc_section = search_section.client_account.ppc_section
      
      SearchCcDatum.transaction do
        SearchCcDatum.where(dashboard_id: search_section_id, dashboard_type: "SearchSection", date: start_date.beginning_of_month..end_date.end_of_month).destroy_all
        SearchCcDatum.where(dashboard_id: search_section.campaign_groups.map{|g| g.id}, dashboard_type: "CampaignGroup", date: start_date.beginning_of_month..end_date.end_of_month).destroy_all
        while start_date.beginning_of_month <= end_date.end_of_month
          dr = start_date.beginning_of_month..start_date.end_of_month
          lydr = start_date.advance(years: -1).beginning_of_month..start_date.advance(years: -1).end_of_month
          campaign_groups.map{|g| g.id}.prepend("overall").each do |dashboard|
            dashboard_obj = dashboard == "overall" ? search_section : CampaignGroup.find(dashboard)
            record = SearchCcDatum.new
            record.dashboard = dashboard_obj
            record.date = start_date.beginning_of_month 
            dashboard = dashboard.to_s
            [
              :spend,
              :impressions, 
              :search_impressions_share, 
              :clicks,
              :cpc,
              :ctr,
              :phone_calls,
              :in_store_visits, 
              :cpsv,
              :click_conversions_uninflated, 
              :click_conversions,
              :cvr_uninflated,
              :cvr,
              :click_cpa_uninflated,
              :click_cpa,
              :click_revenue_uninflated,
              :click_revenue,
              :click_roas_uninflated,
              :click_roas,
              :click_aov_uninflated,
              :click_aov
            ].each do |metric|
              metric_name = "#{metric}"
              puts "Basic: #{metric} #{dashboard}"
              raw = search_section.public_send(metric_name, dr, dashboard) 
              projected = start_date >= Date.today.beginning_of_month ? search_section.project(metric, dashboard) : raw
              record[metric_name] = {raw: raw, projected: projected, projected_yy: yy(projected, search_section.public_send(metric_name, lydr, dashboard))}
            end

            puts "Starting spend allocation"

            record.metrics_by_platform = search_section.metrics_by_platform(dr, dashboard)
            record.metrics_by_gender = search_section.metrics_by_segment(dr, "gender", dashboard)
            record.metrics_by_device = search_section.metrics_by_segment(dr, "device", dashboard)
            record.metrics_by_age = search_section.metrics_by_segment(dr, "age", dashboard)
            record.metrics_by_state = search_section.metrics_by_segment(dr, "state", dashboard)
            record.metrics_by_hour = search_section.metrics_by_segment(dr, "hour", dashboard)
            record.metrics_by_day = search_section.metrics_by_day(dr, dashboard)

            puts "Finished spend allocation"

            search_primary_kpi_metrics = ["spend", "clicks", "click_conversions", "click_revenue", "click_roas", "click_cpa", "cpc", "ctr", "cvr", "click_aov", "phone_calls", "impressions", "impressions_top_rate", "impressions_abs_top_rate", "search_impressions_share", "in_store_visits"]
            search_primary_kpi_metrics.each do |metric| 
              puts "Metric tables: #{metric} #{dashboard}"
              record.metrics_2_years[metric] = {}
              record.metrics_by_months[metric] = {}

              if start_date.month == Date.today.month && start_date.year == Date.today.year
                # split_metric_by_month parameters are: metric, date, dashboard = "overall", projected_metric = false, is_current_year = false
                  record.metrics_by_months[metric] = [search_section.split_metric_by_month(metric.to_sym, start_date.beginning_of_month, dashboard, record[metric] ? record[metric]["projected"] : 0.0, true), search_section.split_metric_by_month(metric.to_sym, start_date.advance(years: -1).beginning_of_month, dashboard)]  
              else
                record.metrics_by_months[metric] = [search_section.split_metric_by_month(metric.to_sym, start_date.beginning_of_month, dashboard, false, true), search_section.split_metric_by_month(metric.to_sym, start_date.advance(years: -1).beginning_of_month, dashboard)]
              end
            end

            puts "Metric 2 years table"

            record.metrics_2_years = generate_2_year_table(search_section, record.metrics_2_years, start_date, dashboard)

            puts "Record save"

            record.save!      
          end

          start_date = start_date.advance(months: 1)
        end
      end
    end
  end
end

So somehow my deployed version is taking much longer to process the same data. Also I noticed that when running just the one worker, if I check memory usage using this command ps -eo pcpu,pid,user,args | sort -r -k1 | less I see:

on deployment (this number keeps rising):

%CPU   PID USER     COMMAND
90.3 18785 ubuntu   sidekiq 6.2.2 [1 of 10 busy]

on localhost (this number remains stable):

%CPU   PID USER     COMMAND
60.7 18785 ubuntu   sidekiq 6.2.2 [1 of 10 busy]

So clearly there is a problem, even though both computers have the same amount of RAM, I must have messed something up in the configuration that didn't become apparent until now as I am trying to pull a larger data set than historically.

Here is what I have tried so far:

  • disable Transparent Huge Pages in rc.local
  • remove unused sidekiq queues
  • lower concurrency
  • configure Ruby to use jemalloc
  • set MALLOC_MAX_ARENA=2
  • removing transaction blocks from worker
  • disable active record cache in worker
  • set eager_load to false in staging environment (trying to match settings with dev)
  • set cache_classes to false in staging environment (trying to match settings with dev)

Needless to say, none of the above worked or I wouldn't be here begging for your help. I am at my wits end with this so if you have any ideas to point me in the right direction please let me know, I would be very grateful!

EDIT:

I ran perf on the dev environment and recorded the memory usage during execution. Output was as follows:

Overhead  Command    Shared Object       Symbol
   9.27%  processor  libc-2.31.so        [.] malloc_usable_size                                                                                                                                                                             ◆
   9.16%  processor  parser.so           [.] JSON_parse_value                                                                                                                                                                               ▒
   6.09%  processor  libc-2.31.so        [.] malloc                                                                                                                                                                                         ▒
   3.20%  processor  libruby.so.2.7.2    [.] method_entry_get                                                                                                                                                                               ▒
   2.95%  processor  libruby.so.2.7.2    [.] ruby_xfree                                                                                                                                                                                     ▒
   2.93%  processor  libruby.so.2.7.2    [.] objspace_malloc_increase.isra.0                                                                                                                                                                ▒
   2.78%  processor  libruby.so.2.7.2    [.] ruby_strtod                                                                                                                                                                                    ▒
   2.34%  processor  parser.so           [.] JSON_parse_string                                                                                                                                                                              ▒
   1.95%  processor  libruby.so.2.7.2    [.] ruby_sip_hash13                                                                                                                                                                                ▒
   1.83%  processor  libc-2.31.so        [.] 0x0000000000099dc8                                                                                                                                                                             ▒
   1.77%  processor  libruby.so.2.7.2    [.] str_buf_cat                                                                                                                                                                                    ▒
   1.64%  processor  libruby.so.2.7.2    [.] vm_exec_core                                                                                                                                                                                   ▒
   1.62%  processor  libruby.so.2.7.2    [.] gc_sweep_step                                                                                                                                                                                  ▒
   1.61%  processor  libruby.so.2.7.2    [.] rb_obj_respond_to                                                                                                                                                                              ▒
   1.40%  processor  libruby.so.2.7.2    [.] coderange_scan                                                                                                                                                                                 ▒
   1.27%  processor  libruby.so.2.7.2    [.] rb_enc_from_index                                                                                                                                                                              ▒
   1.26%  processor  libruby.so.2.7.2    [.] rb_wb_protected_newobj_of                                                                                                                                                                      ▒
   1.24%  processor  libruby.so.2.7.2    [.] rb_st_update                                                                                                                                                                                   ▒
   1.20%  processor  libruby.so.2.7.2    [.] ar_update                                                                                                                                                                                      ▒
   1.05%  processor  libruby.so.2.7.2    [.] rb_enc_associate_index                                                                                                                                                                         ▒
   1.05%  processor  libruby.so.2.7.2    [.] rebuild_table                                                                                                                                                                                  ▒
   1.03%  processor  libruby.so.2.7.2    [.] rb_hash_aset                                                                                                                                                                                   ▒
   1.02%  processor  libruby.so.2.7.2    [.] rb_freeze_singleton_class                                                                                                                                                                      ▒
   0.99%  processor  libruby.so.2.7.2    [.] gc_mark_ptr                                                                                                                                                                                    ▒
   0.99%  processor  libruby.so.2.7.2    [.] tbl_update                                                                                                                                                                                     ▒
   0.96%  processor  libruby.so.2.7.2    [.] find_table_bin_ind                                                                                                                                                                             ▒
   0.92%  processor  libruby.so.2.7.2    [.] basic_obj_respond_to_missing                                                                                                                                                                   ▒
   0.92%  processor  libc-2.31.so        [.] 0x0000000000098b56                                                                                                                                                                             ▒
   0.89%  processor  libruby.so.2.7.2    [.] rb_enc_str_coderange                                                                                                                                                                           ▒
   0.89%  processor  libruby.so.2.7.2    [.] rb_enc_get_index                                                                                                                                                                               ▒
   0.85%  processor  libruby.so.2.7.2    [.] vm_respond_to                                                                                                                                                                                  ▒
   0.82%  processor  libruby.so.2.7.2    [.] rb_int_parse_cstr                                                                                                                                                                              ▒
   0.72%  processor  libruby.so.2.7.2    [.] hash_aset_str_insert                                                                                                                                                                           ▒
   0.69%  processor  libruby.so.2.7.2    [.] rb_gc_writebarrier                                                                                                                                                                             ▒
   0.64%  processor  libruby.so.2.7.2    [.] rb_str_hash                                                                                                                                                                                    ▒
   0.63%  processor  libruby.so.2.7.2    [.] rb_cstr_to_dbl_raise.part.0                                                                                                                                                                    ▒
   0.63%  processor  libruby.so.2.7.2    [.] gc_mark_children                                                                                                                                                                               ▒
   0.59%  processor  libruby.so.2.7.2    [.] ruby_xmalloc2                                                                                                                                                                                  ▒
   0.55%  processor  libruby.so.2.7.2    [.] rb_str_free                                                                                                                                                                                    ▒
   0.53%  processor  libruby.so.2.7.2    [.] must_encindex                                                                                                                                                                                  ▒
   0.52%  processor  libruby.so.2.7.2    [.] rb_str_buf_new
0 Answers
Related