Sidekiq 版本 4.2.10 一个项目使用 Sidekiq 异步进行相关业务操作,由于三方接口异常,导致接口调用大量异常重试,通过排查项目代码发现是重试完全失败时没有做任何处理;但同时发现重试时间间隔和自定义重试间隔时间有较大差异,通过查看相关源码,有一些疑问。
sidekiq_options retry: 10
sidekiq_retry_in { |count|
10 * (count + 1)
}
def perform
Rails.logger.info "-----------------> #{Time.now}"
raise '测试重试时间间隔问题'
end
通过调用后直接抛出异常重试来大概统计下两次重试间隔时间:
第一次:2018-05-29 17:11:40 +0800 第二次:2018-05-29 17:12:02 +0800 第三次:2018-05-29 17:12:29 +0800 第四次:2018-05-29 17:13:10 +0800 ......
发现时间间隔是大于预期的配置,通过查找源码发现,Sidekiq 的相关重试间隔时间不是按照异常失败的时间开始或者上次任务开始时间计算,而是根据 Sidekiq 实际执行时间开始计算,然后加上自定义配置的时间间隔。
retry_jobs.rb:
if count < max_retry_attempts
delay = delay_for(worker, count, exception)
logger.debug { "Failure! Retry #{count} in #{delay} seconds" }
# delay 自定义配置时间间隔
retry_at = Time.now.to_f + delay
payload = Sidekiq.dump_json(msg)
Sidekiq.redis do |conn|
conn.zadd('retry', retry_at.to_s, payload)
end
else
# Goodbye dear message, you (re)tried your best I'm sure.
retries_exhausted(worker, msg, exception)
end
入队列时的一些时间参数(转换后数据,相差的仅仅小数位):
def atomic_push(conn, payloads)
if payloads.first['at']
conn.zadd('schedule'.freeze, payloads.map do |hash|
at = hash.delete('at'.freeze).to_s
[at, Sidekiq.dump_json(hash)]
end)
else
q = payloads.first['queue']
now = Time.now.to_f
to_push = payloads.map do |entry|
entry['enqueued_at'.freeze] = now
Sidekiq.dump_json(entry)
end
conn.sadd('queues'.freeze, q)
conn.lpush("queue:#{q}", to_push)
temp_to_push = JSON.parse to_push[0]
# 自己添加格式化代码
puts "created_at : " + (temp_to_push["created_at"] && Time.at(temp_to_push["created_at"])).to_s
puts "enqueued_at : " + (temp_to_push["enqueued_at"] && Time.at(temp_to_push["enqueued_at"])).to_s
puts "failed_at : " + (temp_to_push["failed_at"] && Time.at(temp_to_push["failed_at"])).to_s
puts "retried_at : " + (temp_to_push['retried_at'] && Time.at(temp_to_push['retried_at'])).to_s
end
created_at : 2018-05-29 17:11:30 +0800
enqueued_at : 2018-05-29 17:17:18 +0800
failed_at : 2018-05-29 17:11:40 +0800
retried_at : 2018-05-29 17:15:54 +0800
created_at : 2018-05-29 17:11:30 +0800
enqueued_at : 2018-05-29 17:18:46 +0800
failed_at : 2018-05-29 17:11:40 +0800
retried_at : 2018-05-29 17:17:18 +0800
created_at : 2018-05-29 17:11:30 +0800
enqueued_at : 2018-05-29 17:20:23 +0800
failed_at : 2018-05-29 17:11:40 +0800
retried_at : 2018-05-29 17:18:46 +0800
created_at : 2018-05-29 17:11:30 +0800
enqueued_at : 2018-05-29 17:22:19 +0800
failed_at : 2018-05-29 17:11:40 +0800
retried_at : 2018-05-29 17:20:23 +0800
通过结果查看时间间隔也是按照代码执行的当前时间来处理的,所以有了一些疑问,这样会不会导致时间间隔并不是按照失败重试时间点来执行重试,其中时间有些误差,导致追溯问题时间不精确或者其他的一些问题;或者说从根源上也做不到很精确的时间之类的;或者是 Sidekiq 本身设计如此之类的。
欢迎大家来探讨这个问题