Ruby Sidekiq 异常重试时间间隔探讨疑问

wanglizheng · May 29, 2018 · Last by wanglizheng replied at May 30, 2018 · 2868 hits

Sidekiq 异常重试时间间隔

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 本身设计如此之类的。

欢迎大家来探讨这个问题

https://github.com/mperham/sidekiq/wiki/Error-Handling#automatic-job-retry

这个章节里面有个小三角,点开可以看到一组数据,应该可以解答你的疑问

首先明确一点,重试机制是用来给你『亡羊补牢』的,当你线上遇到 bug 时,让你有机会去修复它,它不是定时任务,不会去关心时间间隔是否严格

以任务开始时间来计算可不可以?可以,但是会增加很多不必要的麻烦,比如:

  1. 需要记录并读取任务开始执行的时间
  2. 计算出重试时间后,已经是一个过去的时间了,此时该跳过还是马上塞回队列呢?
  3. sidekiq 的 Scheduled Job 本身也不能保证一个任务是严格的按时执行的,因为队列还可能在排队

所以,我的结论是:

Sidekiq 的设计没毛病,而且很合理。

至于『导致追溯问题时间不精确』,为什么你要用时间去追溯问题?如果有两个基本完全相同的任务在交错的打 log 呢?如果有 1000 个这样的任务在打 log 呢?

当然,如果你是处女座或者患有不对齐会死强迫征,啊哈,那也有办法~

你可以在这个 job 上禁用掉 sidekiq 的重试,然后自己写个定时任务去检测任务执行情况,遇到出错的就立马重跑,记得是重跑,不是塞入队列,因为队列还可能在排队

昨天仔细又想了想,确实是这样,是我被问问题的人给带偏了😅

You need to Sign in before reply, if you don't have an account, please Sign up first.