Strange behavior of Sidekiq Pro's Reliability feature #2120

mkaschenko · 2015-01-07T12:20:57Z

Hello, @mperham. Thank you for the gem!

I face strange behavior of Sidekiq Pro's Reliability feature [1].

I have TestWorker [2]. Also I use 'weighted random' fetch algorithm [3].
I run sidekiq the same way as in [3] and push the worker (TestWorker.perform_async).
I kill the sidekiq process (kill -9 pid).
I run sidekiq again.

And now 2 TestWorkers run instead of 1.
If I change the weight sidekiq ... -q default,2 ... to sidekiq ... -q default,5 ..., then 5 TestWorkers run and so on.

What do you think about it?

[1] https://github.com/mperham/sidekiq/wiki/Reliability
[2] https://gist.github.com/mkaschenko/24da18c795962da3c970
[3] https://github.com/mperham/sidekiq/wiki/Reliability#weighted-random-algorithm

The text was updated successfully, but these errors were encountered:

mperham · 2015-01-07T17:31:14Z

Wow, good catch! You're right, this is a bug.

jonhyman · 2015-01-07T17:39:12Z

Wow. Thanks for reporting and thanks for fixing, @mperham!

Sent from my mobile device
On Jan 7, 2015 12:36 PM, "Mike Perham" notifications@github.com wrote:

Closed #2120 #2120 via
d1191ca3b3c62982f32d02c4c5b80ecf2269fb2c.

Reply to this email directly or view it on GitHub
#2120 (comment).

mperham · 2015-01-07T19:24:10Z

Thank you for the great report, 1.9.2 has been released.

mkaschenko · 2015-01-08T05:27:28Z

👍

parhamr · 2015-02-13T00:18:35Z

@mperham I appreciate this change! Since upgrading from 1.9.1 to 1.9.2 I have seen a significant performance regression. Do you have tests that can check this or would you like some diagnostic data?

mperham · 2015-02-13T00:27:26Z

Can you give more versions: Ruby, sidekiq, sidekiq pro? Ruby 1.9 support is pretty frozen at this point, any possibility of upgrading Ruby and sidekiq?

On Feb 12, 2015, at 16:18, Reid Parham notifications@github.com wrote:

@mperham I appreciate this change! Since upgrading from 1.9.1 to 1.9.2 I have seen a significant performance regression. Do you have tests that can check this or would you like some diagnostic data?

—
Reply to this email directly or view it on GitHub.

parhamr · 2015-02-13T00:29:31Z

Sorry, I was unclear: it was an upgrade from sidekiq-pro 1.9.1 to sidekiq-pro 1.9.2.

Ruby version: 2.1.5 x86_64-linux 2014-11-13
Rails version: 3.2.21
Current Sidekiq versions in Gemfile.lock:

    sidekiq (3.2.6)
      celluloid (= 0.15.2)
      connection_pool (>= 2.0.0)
      json
      redis (>= 3.0.6)
      redis-namespace (>= 1.3.1)
    sidekiq-pro (1.9.2)
      sidekiq (>= 3.2.3)

Redis version: 2.8.17

$ uname -ro
2.6.32-349-ec2 GNU/Linux

mperham · 2015-02-13T00:35:16Z

show us your queue configuration.

On Feb 12, 2015, at 16:29, Reid Parham notifications@github.com wrote:

Sorry, I was unclear: it was an upgrade from sidekiq-pro 1.9.1 to sidekiq-pro 1.9.2.

Ruby version: 2.1.5 x86_64-linux 2014-11-13
Rails version: 3.2.21
Current Sidekiq versions in Gemfile.lock:
sidekiq (3.2.6)
  celluloid (= 0.15.2)
  connection_pool (>= 2.0.0)
  json
  redis (>= 3.0.6)
  redis-namespace (>= 1.3.1)
sidekiq-pro (1.9.2)
  sidekiq (>= 3.2.3)
—
Reply to this email directly or view it on GitHub.

parhamr · 2015-02-13T00:38:04Z

Configurations…

config/sidekiq.yml

background:
  :verbose: false
  :environment: background
  :concurrency: 8
  # NOTE: timeout deprecated as it has architectural flaws; kept here for process signaling integrations
  # timeout must be less than the time bluepill waits to kill (pause after USR1)
  :timeout: 85
  :queues:
    - [default, 3]
    - [mailer, 7]
    - [serializers, 1]
    - [admin, 5]
    - [reports, 1]
    - [messages, 3]
  :redis:
    url: redis://10.54.164.133:6379/2

config/initializers/sidekiq.rb

sidekiq_yml = 'config/sidekiq' + (ENV['SIDEKIQ_YAML'].blank? ? '' : ('_' + ENV['SIDEKIQ_YAML'])) + '.yml'

# https://github.com/mperham/sidekiq/wiki/Reliability
require 'sidekiq/pro/reliable_push'

Sidekiq.configure_server do |config|
  require 'sidekiq/pro/reliable_fetch'
  sidekiq_config = AppName::Utils.load_environment_config_file(Rails.root.join(sidekiq_yml))
  config.options[:verbose]      = sidekiq_config[:verbose]
  config.options[:environment]  = sidekiq_config[:environment] || 'background'
  config.options[:concurrency]  = sidekiq_config[:concurrency] || 10
  config.options[:logfile]      = sidekiq_config[:logfile]
  config.options[:pidfile]      = sidekiq_config[:pidfile]
  # timeout must be less than the time bluepill waits to kill (pause after USR1)
  config.options[:timeout]      = sidekiq_config[:timeout] || 90
  config.redis                  = sidekiq_config[:redis].merge(namespace: 'sidekiq')

  config.server_middleware do |chain|
    chain.add Kiqstand::Middleware
    chain.add Sidekiq::Middleware::Server::Batch
  end
  config.client_middleware do |chain|
    chain.add Sidekiq::Middleware::Client::Batch
  end
end
Sidekiq.configure_client do |config|
  sidekiq_config = AppName::Utils.load_environment_config_file(Rails.root.join(sidekiq_yml))
  # namespace must be defined here, per @mperham
  config.redis   = sidekiq_config[:redis].merge(namespace: 'sidekiq')
  config.client_middleware do |chain|
    chain.add Sidekiq::Middleware::Client::Batch
  end
end

parhamr · 2015-02-13T00:40:02Z

STDOUT content during startup:

2015-02-13T00:24:03.109Z 8429 TID-40ftc INFO: [Sidetiq] Sidetiq v0.6.3 - Copyright (c) 2012-2013, Tobias Svensson <tob@tobiassvensson.co.uk>
2015-02-13T00:24:03.109Z 8429 TID-40ftc INFO: [Sidetiq] Sidetiq is covered by the 3-clause BSD license.
2015-02-13T00:24:03.109Z 8429 TID-40ftc INFO: [Sidetiq] See LICENSE and http://opensource.org/licenses/BSD-3-Clause for licensing details.
2015-02-13T00:24:03.109Z 8429 TID-40ftc INFO: [Sidetiq] Sidetiq::Supervisor start
2015-02-13T00:24:03.122Z 8429 TID-nwmnk INFO: [Sidetiq] Sidetiq::Actor::Clock id: 40155160 initialize
2015-02-13T00:24:03.142Z 8429 TID-nvfd8 INFO: [Sidetiq] Sidetiq::Actor::Handler id: 40113740 initialize
2015-02-13T00:24:03.152Z 8429 TID-nurlo INFO: [Sidetiq] Sidetiq::Actor::Handler id: 40077280 initialize
[["default", 3], ["mailer", 7], ["serializers", 1], ["admin", 5], ["reports", 1], ["messages", 3]]
2015-02-13T00:24:05.185Z 8429 TID-40ftc INFO: Booting Sidekiq 3.2.6 with redis options {:url=>"redis://10.54.164.133:6379/2", :namespace=>"sidekiq"}
2015-02-13T00:24:08.664Z 8429 TID-40ftc INFO: Running in ruby 2.1.5p273 (2014-11-13 revision 48405) [x86_64-linux]
2015-02-13T00:24:08.664Z 8429 TID-40ftc INFO: Sidekiq Pro 1.9.2, commercially licensed.  Thanks for your support!
2015-02-13T00:24:08.664Z 8429 TID-40ftc INFO: Starting processing, hit Ctrl-C to stop
2015-02-13T00:24:08.812Z 8429 TID-da6ro INFO: ReliableFetch activated
2015-02-13T00:24:08.825Z 8429 TID-da6ro WARN: ReliableFetch: recovering work on 7 messages

STDOUT from Sidekiq Pro 1.9.1, note the job timings:

2015-01-16T22:20:49.898Z 13211 TID-i6kjc Admin::SingleUsePromoCodeWorker JID-55ddd8a3aca2ace23ec899f4 INFO: start
2015-01-16T22:20:49.900Z 13211 TID-1lwppg Admin::SingleUsePromoCodeWorker JID-63040c810ec2be1e5815ac9f INFO: start
2015-01-16T22:20:49.905Z 13211 TID-1m8rck Admin::SingleUsePromoCodeWorker JID-3d6e0e8b7ab1d20a61d0cf30 INFO: start
2015-01-16T22:20:49.915Z 13211 TID-hyzrw Admin::SingleUsePromoCodeWorker JID-e295a7d044b01f49db4b8314 INFO: done: 0.085 sec
2015-01-16T22:20:49.925Z 13211 TID-cvh64 Admin::SingleUsePromoCodeWorker JID-80de5ccc0993c4f94252b3fb INFO: done: 0.075 sec
2015-01-16T22:20:49.926Z 13211 TID-1lg9sk Admin::SingleUsePromoCodeWorker JID-cbdacf54662d6c23a777c877 INFO: start
2015-01-16T22:20:49.943Z 13211 TID-ikr0k Admin::SingleUsePromoCodeWorker JID-5db65300ce942bac6df656a0 INFO: done: 0.07 sec
2015-01-16T22:20:49.948Z 13211 TID-1lwppg Admin::SingleUsePromoCodeWorker JID-63040c810ec2be1e5815ac9f INFO: done: 0.048 sec
2015-01-16T22:20:49.952Z 13211 TID-i6kjc Admin::SingleUsePromoCodeWorker JID-55ddd8a3aca2ace23ec899f4 INFO: done: 0.054 sec
2015-01-16T22:20:49.965Z 13211 TID-1lg9sk Admin::SingleUsePromoCodeWorker JID-cbdacf54662d6c23a777c877 INFO: done: 0.039 sec
2015-01-16T22:20:49.968Z 13211 TID-1m8rck Admin::SingleUsePromoCodeWorker JID-3d6e0e8b7ab1d20a61d0cf30 INFO: done: 0.063 sec

STDOUT from Sidekiq Pro 1.9.2, these jobs are slower:

2015-02-13T00:44:23.689Z 8429 TID-22z4h0 Admin::SingleUsePromoCodeWorker JID-31cbcda44e9219021bbd85a9 INFO: done: 1.804 sec
2015-02-13T00:44:23.931Z 8429 TID-22z4h0 Admin::SingleUsePromoCodeWorker JID-b73ecded436f70035d440d8b INFO: start
2015-02-13T00:44:25.895Z 8429 TID-22z4h0 Admin::SingleUsePromoCodeWorker JID-b73ecded436f70035d440d8b INFO: done: 1.965 sec
2015-02-13T00:44:26.459Z 8429 TID-22z4h0 Admin::SingleUsePromoCodeWorker JID-5959e6a7698e3182312c778a INFO: start
2015-02-13T00:44:27.226Z 8429 TID-22z4h0 Admin::SingleUsePromoCodeWorker JID-5959e6a7698e3182312c778a INFO: done: 0.767 sec
2015-02-13T00:44:27.367Z 8429 TID-22z4h0 Admin::SingleUsePromoCodeWorker JID-e2c83cdb6945cbe3dadfd4fb INFO: start
2015-02-13T00:44:29.472Z 8429 TID-22z4h0 Admin::SingleUsePromoCodeWorker JID-e2c83cdb6945cbe3dadfd4fb INFO: done: 2.104 sec
2015-02-13T00:44:29.862Z 8429 TID-22z4h0 Admin::SingleUsePromoCodeWorker JID-4bdb72f5a3c039803ec8a72b INFO: start
2015-02-13T00:44:31.604Z 8429 TID-22z4h0 Admin::SingleUsePromoCodeWorker JID-4bdb72f5a3c039803ec8a72b INFO: done: 1.742 sec
2015-02-13T00:44:32.714Z 8429 TID-22z4h0 Admin::SingleUsePromoCodeWorker JID-512c1c7ec0fa6bb7c3dd6bf9 INFO: start
2015-02-13T00:44:34.186Z 8429 TID-22z4h0 Admin::SingleUsePromoCodeWorker JID-512c1c7ec0fa6bb7c3dd6bf9 INFO: done: 1.473 sec
2015-02-13T00:44:34.222Z 8429 TID-22z4h0 Admin::SingleUsePromoCodeWorker JID-1ed1e87a47f6933c5dfce92a INFO: start
2015-02-13T00:44:34.337Z 8429 TID-22z4h0 Admin::SingleUsePromoCodeWorker JID-1ed1e87a47f6933c5dfce92a INFO: done: 0.116 sec
2015-02-13T00:44:34.507Z 8429 TID-22z4h0 Admin::SingleUsePromoCodeWorker JID-0430e8a289b2480d7e29e92c INFO: start
2015-02-13T00:44:35.727Z 8429 TID-22z4h0 Admin::SingleUsePromoCodeWorker JID-0430e8a289b2480d7e29e92c INFO: done: 1.22 sec

parhamr · 2015-02-13T00:49:41Z

If it further helps, here’s a New Relic comparison of the same, unchanged worker class behaviors…

Sidekiq Pro 1.9.1, captured on Jan 16, 2015:

New Relic thread tracing allocates 57 percent of the execution time to vendor/bundle/ruby/2.1.0/gems/celluloid-0.15.2/lib/celluloid/mailbox.rb.sleep:69

Sidekiq Pro 1.9.2, captured on Feb 12, 2015:

FYI: this isn’t an urgent issue… enjoy the wonderful weather! 😎

mperham · 2015-02-13T01:42:24Z

There's no change that should increase worker runtime. The only fix to 1.9.2 changes Sidekiq Pro's startup, not runtime. I suspect you've got another change which caused the problem. Did you upgrade other gems at the same time?

parhamr · 2015-02-13T01:46:34Z

Yes, I did upgrade other gems. I'll check them out for the regression source. Thanks for confirming!

mperham closed this as completed Jan 7, 2015

mperham added a commit that referenced this issue Jan 7, 2015

Note #2120

fbc22f9

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Strange behavior of Sidekiq Pro's Reliability feature #2120

Strange behavior of Sidekiq Pro's Reliability feature #2120

mkaschenko commented Jan 7, 2015

mperham commented Jan 7, 2015

jonhyman commented Jan 7, 2015

mperham commented Jan 7, 2015

mkaschenko commented Jan 8, 2015

parhamr commented Feb 13, 2015

mperham commented Feb 13, 2015

parhamr commented Feb 13, 2015

mperham commented Feb 13, 2015

parhamr commented Feb 13, 2015

parhamr commented Feb 13, 2015

parhamr commented Feb 13, 2015

mperham commented Feb 13, 2015

parhamr commented Feb 13, 2015

Strange behavior of Sidekiq Pro's Reliability feature #2120

Strange behavior of Sidekiq Pro's Reliability feature #2120

Comments

mkaschenko commented Jan 7, 2015

mperham commented Jan 7, 2015

jonhyman commented Jan 7, 2015

mperham commented Jan 7, 2015

mkaschenko commented Jan 8, 2015

parhamr commented Feb 13, 2015

mperham commented Feb 13, 2015

parhamr commented Feb 13, 2015

mperham commented Feb 13, 2015

parhamr commented Feb 13, 2015

parhamr commented Feb 13, 2015

parhamr commented Feb 13, 2015

mperham commented Feb 13, 2015

parhamr commented Feb 13, 2015