Sidekiq 故障排除

Sidekiq 是极狐GitLab 用于异步运行任务的后台作业处理器。当出现问题时，可能很难排除故障。这些情况也往往是高压的，因为生产系统作业队列可能会被填满。用户会注意到这种情况何时发生，因为新分支可能不会出现并且合并请求可能不会更新。以下是一些故障排除步骤，可帮助您诊断瓶颈。

极狐GitLab 管理员/用户应考虑使用极狐GitLab 支持完成这些调试步骤，以便可以分析回溯。它可能会揭示极狐GitLab 中的错误或必要的改进。

在任何回溯中，要警惕每个线程似乎都在数据库、Redis 中等待，或等待获取互斥锁的可疑情况。例如，这可能意味着数据库中存在争用，但要寻找一个与其他线程不同的线程。这个其他线程可能正在使用所有可用的 CPU，或者具有 Ruby Global Interpreter Lock，从而阻止其他线程继续运行。

将参数记录到 Sidekiq 作业

在 13.6 及更高版本中，默认情况下会记录传递给 Sidekiq 作业的一些参数。 为了避免记录敏感信息（例如，密码重置令牌），极狐GitLab 会记录所有 worker 的数字参数，并覆盖一些参数不敏感的特定 worker。

日志输出示例： 

{"severity":"INFO","time":"2020-06-08T14:37:37.892Z","class":"AdminEmailsWorker","args":["[FILTERED]","[FILTERED]","[FILTERED]"],"retry":3,"queue":"admin_emails","backtrace":true,"jid":"9e35e2674ac7b12d123e13cc","created_at":"2020-06-08T14:37:37.373Z","meta.user":"root","meta.caller_id":"Admin::EmailsController#create","correlation_id":"37D3lArJmT1","uber-trace-id":"2d942cc98cc1b561:6dc94409cfdd4d77:9fbe19bdee865293:1","enqueued_at":"2020-06-08T14:37:37.410Z","pid":65011,"message":"AdminEmailsWorker JID-9e35e2674ac7b12d123e13cc: done: 0.48085 sec","job_status":"done","scheduling_latency_s":0.001012,"redis_calls":9,"redis_duration_s":0.004608,"redis_read_bytes":696,"redis_write_bytes":6141,"duration_s":0.48085,"cpu_s":0.308849,"completed_at":"2020-06-08T14:37:37.892Z","db_duration_s":0.010742}
{"severity":"INFO","time":"2020-06-08T14:37:37.894Z","class":"ActiveJob::QueueAdapters::SidekiqAdapter::JobWrapper","wrapped":"ActionMailer::MailDeliveryJob","queue":"mailers","args":["[FILTERED]"],"retry":3,"backtrace":true,"jid":"e47a4f6793d475378432e3c8","created_at":"2020-06-08T14:37:37.884Z","meta.user":"root","meta.caller_id":"AdminEmailsWorker","correlation_id":"37D3lArJmT1","uber-trace-id":"2d942cc98cc1b561:29344de0f966446d:5c3b0e0e1bef987b:1","enqueued_at":"2020-06-08T14:37:37.885Z","pid":65011,"message":"ActiveJob::QueueAdapters::SidekiqAdapter::JobWrapper JID-e47a4f6793d475378432e3c8: start","job_status":"start","scheduling_latency_s":0.009473}
{"severity":"INFO","time":"2020-06-08T14:39:50.648Z","class":"NewIssueWorker","args":["455","1"],"retry":3,"queue":"new_issue","backtrace":true,"jid":"a24af71f96fd129ec47f5d1e","created_at":"2020-06-08T14:39:50.643Z","meta.user":"root","meta.project":"h5bp/html5-boilerplate","meta.root_namespace":"h5bp","meta.caller_id":"Projects::IssuesController#create","correlation_id":"f9UCZHqhuP7","uber-trace-id":"28f65730f99f55a3:a5d2b62dec38dffc:48ddd092707fa1b7:1","enqueued_at":"2020-06-08T14:39:50.646Z","pid":65011,"message":"NewIssueWorker JID-a24af71f96fd129ec47f5d1e: start","job_status":"start","scheduling_latency_s":0.001144}

使用 Sidekiq JSON 日志记录时，参数日志的最大大小限制为 10 KB 文本；此限制之后的任何参数都将被丢弃并替换为包含字符串 “...” 的单个参数。

您可以将 SIDEKIQ_LOG_ARGUMENTS 环境变量 设置为 0 (false) 以禁用参数记录。

示例： 

gitlab_rails['env'] = {"SIDEKIQ_LOG_ARGUMENTS" => "0"}

在 13.5 及更早版本中，将 SIDEKIQ_LOG_ARGUMENTS 设置为 1 以开始记录传递给 Sidekiq 的参数。

调查 Sidekiq 队列积压或性能低下

Sidekiq 性能缓慢的症状包括合并请求状态更新议题，以及 CI 流水线开始运行之前的延迟。

潜在原因包括：

  • 极狐GitLab 实例可能需要更多 Sidekiq worker。默认情况下，单节点 Omnibus GitLab 运行一个 worker，将 Sidekiq 作业的执行限制为最多一个 CPU 内核。阅读更多关于运行多个 Sidekiq worker 的信息。

  • 该实例配置了更多的 Sidekiq worker，但大多数额外的 worker 未配置为运行任何排队的作业。当实例繁忙时，如果工作负载在配置 worker 后的几个月或几年内发生变化，或者由于极狐GitLab 产品更改，可能会导致工作积压。

使用以下 Ruby 脚本收集有关 Sidekiq worker 状态的数据。

  1. 创建脚本： 

    cat > /var/opt/gitlab/sidekiqcheck.rb <<EOF
require 'sidekiq/monitor'
Sidekiq::Monitor::Status.new.display('overview')
Sidekiq::Monitor::Status.new.display('processes'); nil
Sidekiq::Monitor::Status.new.display('queues'); nil
puts "----------- workers ----------- "
workers = Sidekiq::Workers.new
workers.each do |_process_id, _thread_id, work|
  pp work
end
puts "----------- Queued Jobs ----------- "
Sidekiq::Queue.all.each do |queue|
  queue.each do |job|
    pp job
  end
end ;nil
puts "----------- done! ----------- "
EOF

  2. 执行并捕获输出： 

    sudo gitlab-rails runner /var/opt/gitlab/sidekiqcheck.rb > /tmp/sidekiqcheck_$(date '+%Y%m%d-%H:%M').out

    如果性能问题是间歇性的：

    • 每五分钟在 cron 作业中运行一次。将文件写入具有足够空间的位置：允许每个文件 500 KB。
    • 返回查看数据，查看问题出在哪里。

  3. 分析输出。以下命令假定您有一个输出文件目录。

    1. grep 'Busy: ' * 显示正在运行的作业数。grep 'Enqueued: ' * 显示当时积压的工作。

    2. 在 Sidekiq 处于负载下的样本中，查看繁忙线程数： 

      ls | while read f ; do if grep -q 'Enqueued: 0' $f; then :
  else echo $f; egrep 'Busy:|Enqueued:|---- Processes' $f
  grep 'Threads:' $f ; fi
done | more

      输出示例： 

      sidekiqcheck_20221024-14:00.out
       Busy: 47
   Enqueued: 363
---- Processes (13) ----
  Threads: 30 (0 busy)
  Threads: 30 (0 busy)
  Threads: 30 (0 busy)
  Threads: 30 (0 busy)
  Threads: 23 (0 busy)
  Threads: 30 (0 busy)
  Threads: 30 (0 busy)
  Threads: 30 (0 busy)
  Threads: 30 (0 busy)
  Threads: 30 (0 busy)
  Threads: 30 (0 busy)
  Threads: 30 (24 busy)
  Threads: 30 (23 busy)
      • 在这个输出文件中，有 47 个进程处于忙碌状态，积压了 363 个作业。
      • 在 13 个 worker 进程中，只有两个处于忙碌状态。
      • 这表明其他 worker 的配置过于具体。
      • 查看完整输出，确定哪些 worker 正忙。与 gitlab.rb 中的 sidekiq_queues 配置相关联。

      • 超载的单个 worker 环境可能如下所示： 

        sidekiqcheck_20221024-14:00.out
       Busy: 25
   Enqueued: 363
---- Processes (1) ----
  Threads: 25 (25 busy)

    3. 查看输出文件的 ---- Queues (xxx) ---- 部分，确定当时排队的作业。

    4. 这些文件还包括当时 Sidekiq 状态的底层详细信息，可能有助于确定工作负载峰值的来源。

      • ------------ workers ------------ 部分详细说明了构成摘要中的 Busy 计数的作业。
      • ----------- Queued Jobs ----------- 部分提供了有关 Enqueued 作业的详细信息。

线程回溯

向 Sidekiq 进程 ID 发送 TTIN 信号以在日志文件中输出线程回溯。 

kill -TTIN <sidekiq_pid>

检查 /var/log/gitlab/sidekiq/current 或 $GITLAB_HOME/log/sidekiq.log 以获取回溯输出。回溯很长，通常以几条 WARN 级别的消息开头。下面是一个单线程回溯的例子： 

2016-04-13T06:21:20.022Z 31517 TID-orn4urby0 WARN: ActiveRecord::RecordNotFound: Couldn't find Note with 'id'=3375386
2016-04-13T06:21:20.022Z 31517 TID-orn4urby0 WARN: /opt/gitlab/embedded/service/gem/ruby/2.1.0/gems/activerecord-4.2.5.2/lib/active_record/core.rb:155:in `find'
/opt/gitlab/embedded/service/gitlab-rails/app/workers/new_note_worker.rb:7:in `perform'
/opt/gitlab/embedded/service/gem/ruby/2.1.0/gems/sidekiq-4.0.1/lib/sidekiq/processor.rb:150:in `execute_job'
/opt/gitlab/embedded/service/gem/ruby/2.1.0/gems/sidekiq-4.0.1/lib/sidekiq/processor.rb:132:in `block (2 levels) in process'
/opt/gitlab/embedded/service/gem/ruby/2.1.0/gems/sidekiq-4.0.1/lib/sidekiq/middleware/chain.rb:127:in `block in invoke'
/opt/gitlab/embedded/service/gitlab-rails/lib/gitlab/sidekiq_middleware/memory_killer.rb:17:in `call'
/opt/gitlab/embedded/service/gem/ruby/2.1.0/gems/sidekiq-4.0.1/lib/sidekiq/middleware/chain.rb:129:in `block in invoke'
/opt/gitlab/embedded/service/gitlab-rails/lib/gitlab/sidekiq_middleware/arguments_logger.rb:6:in `call'
...

在某些情况下，Sidekiq 可能会挂起并且无法响应 TTIN 信号。 如果发生这种情况，请继续使用其他故障排除方法。

使用 rbspy 进行 Ruby 分析

rbspy 是一个易于使用且开销低的 Ruby 分析器，可用于创建 Ruby 进程 CPU 使用情况的火焰图样式图表。

使用它不需要对极狐GitLab 进行任何更改，并且它没有依赖项。安装步骤：

  1. 从 rbspy 发布页面下载二进制文件。
  2. 使二进制文件可执行。

要分析 Sidekiq worker 一分钟，请运行： 

sudo ./rbspy record --pid <sidekiq_pid> --duration 60 --file /tmp/sidekiq_profile.svg

Example rbspy flamegraph

在这个由 rbspy 生成的火焰图示例中，几乎所有 Sidekiq 进程的时间都花在了 Rugged 中的原生 C 函数 rev_parse 中。在堆栈中，我们可以看到 rev_parse 正在被 ExpirePipelineCacheWorker 调用。

使用 perf 进行进程分析

Linux 有一个名为 perf 的进程分析工具，当某个进程占用大量 CPU 时，该工具很有帮助。如果您看到 CPU 使用率很高并且 Sidekiq 没有响应 TTIN 信号，那么这是一个很好的进展。

如果您的系统上没有安装 perf，请使用 apt-get 或 yum 安装它： 

# Debian
sudo apt-get install linux-tools

# Ubuntu (may require these additional Kernel packages)
sudo apt-get install linux-tools-common linux-tools-generic linux-tools-`uname -r`

# Red Hat/CentOS
sudo yum install perf

对 Sidekiq PID 运行 perf： 

sudo perf record -p <sidekiq_pid>

让它运行 30-60 秒，然后按 Ctrl-C。然后查看 perf 报告： 

$ sudo perf report

# Sample output
Samples: 348K of event 'cycles', Event count (approx.): 280908431073
 97.69%            ruby  nokogiri.so         [.] xmlXPathNodeSetMergeAndClear
  0.18%            ruby  libruby.so.2.1.0    [.] objspace_malloc_increase
  0.12%            ruby  libc-2.12.so        [.] _int_malloc
  0.10%            ruby  libc-2.12.so        [.] _int_free

在上面，您可以看到 perf 报告的示例输出。它显示 97% 的 CPU 用于 Nokogiri 和 xmlXPathNodeSetMergeAndClear。此时，您应该去调查极狐GitLab 中的哪些作业会使用 Nokogiri 和 XPath。结合 TTIN 或 gdb 输出以显示发生这种情况的相应 Ruby 代码。

GNU 项目调试器 (gdb)

gdb 是调试 Sidekiq 的另一个有效工具。它为您提供了一种更具交互性的方式来查看每个线程并查看导致问题的原因。

使用 gdb 附加到进程会暂停进程的正常运行（附加了 gdb 时 Sidekiq 不会处理作业）。

首先附加到 Sidekiq PID： 

gdb -p <sidekiq_pid>

然后收集所有线程的信息： 

info threads

# Example output
30 Thread 0x7fe5fbd63700 (LWP 26060) 0x0000003f7cadf113 in poll () from /lib64/libc.so.6
29 Thread 0x7fe5f2b3b700 (LWP 26533) 0x0000003f7ce0b68c in pthread_cond_wait@@GLIBC_2.3.2 () from /lib64/libpthread.so.0
28 Thread 0x7fe5f2a3a700 (LWP 26534) 0x0000003f7ce0ba5e in pthread_cond_timedwait@@GLIBC_2.3.2 () from /lib64/libpthread.so.0
27 Thread 0x7fe5f2939700 (LWP 26535) 0x0000003f7ce0b68c in pthread_cond_wait@@GLIBC_2.3.2 () from /lib64/libpthread.so.0
26 Thread 0x7fe5f2838700 (LWP 26537) 0x0000003f7ce0b68c in pthread_cond_wait@@GLIBC_2.3.2 () from /lib64/libpthread.so.0
25 Thread 0x7fe5f2737700 (LWP 26538) 0x0000003f7ce0b68c in pthread_cond_wait@@GLIBC_2.3.2 () from /lib64/libpthread.so.0
24 Thread 0x7fe5f2535700 (LWP 26540) 0x0000003f7ce0b68c in pthread_cond_wait@@GLIBC_2.3.2 () from /lib64/libpthread.so.0
23 Thread 0x7fe5f2434700 (LWP 26541) 0x0000003f7ce0b68c in pthread_cond_wait@@GLIBC_2.3.2 () from /lib64/libpthread.so.0
22 Thread 0x7fe5f2232700 (LWP 26543) 0x0000003f7ce0b68c in pthread_cond_wait@@GLIBC_2.3.2 () from /lib64/libpthread.so.0
21 Thread 0x7fe5f2131700 (LWP 26544) 0x00007fe5f7b570f0 in xmlXPathNodeSetMergeAndClear ()
from /opt/gitlab/embedded/service/gem/ruby/2.1.0/gems/nokogiri-1.6.7.2/lib/nokogiri/nokogiri.so
...

如果您看到可疑线程，例如上面的 Nokogiri 线程，您可能希望获得更多信息： 

thread 21
bt

# Example output
#0  0x00007ff0d6afe111 in xmlXPathNodeSetMergeAndClear () from /opt/gitlab/embedded/service/gem/ruby/2.1.0/gems/nokogiri-1.6.7.2/lib/nokogiri/nokogiri.so
#1  0x00007ff0d6b0b836 in xmlXPathNodeCollectAndTest () from /opt/gitlab/embedded/service/gem/ruby/2.1.0/gems/nokogiri-1.6.7.2/lib/nokogiri/nokogiri.so
#2  0x00007ff0d6b09037 in xmlXPathCompOpEval () from /opt/gitlab/embedded/service/gem/ruby/2.1.0/gems/nokogiri-1.6.7.2/lib/nokogiri/nokogiri.so
#3  0x00007ff0d6b09017 in xmlXPathCompOpEval () from /opt/gitlab/embedded/service/gem/ruby/2.1.0/gems/nokogiri-1.6.7.2/lib/nokogiri/nokogiri.so
#4  0x00007ff0d6b092e0 in xmlXPathCompOpEval () from /opt/gitlab/embedded/service/gem/ruby/2.1.0/gems/nokogiri-1.6.7.2/lib/nokogiri/nokogiri.so
#5  0x00007ff0d6b0bc37 in xmlXPathRunEval () from /opt/gitlab/embedded/service/gem/ruby/2.1.0/gems/nokogiri-1.6.7.2/lib/nokogiri/nokogiri.so
#6  0x00007ff0d6b0be5f in xmlXPathEvalExpression () from /opt/gitlab/embedded/service/gem/ruby/2.1.0/gems/nokogiri-1.6.7.2/lib/nokogiri/nokogiri.so
#7  0x00007ff0d6a97dc3 in evaluate (argc=2, argv=0x1022d058, self=<value optimized out>) at xml_xpath_context.c:221
#8  0x00007ff0daeab0ea in vm_call_cfunc_with_frame (th=0x1022a4f0, reg_cfp=0x1032b810, ci=<value optimized out>) at vm_insnhelper.c:1510

一次从所有线程输出回溯： 

set pagination off
thread apply all bt

使用 gdb 完成调试后，请务必从进程中分离并退出： 

detach
exit

Sidekiq 终止信号

TTIN 被描述为打印回溯记录的信号，但是 Sidekiq 也响应其他信号。例如，TSTP 和 TERM 可用于正常关闭 Sidekiq，请参阅 Sidekiq Signals 文档。

检查阻塞查询

有时 Sidekiq 处理作业的速度可能非常快，以至于可能导致数据库争用。当上面的回溯显示许多线程卡在数据库适配器中时，检查阻塞查询。

PostgreSQL wiki 提供了有关可以运行以查看阻塞查询的查询的详细信息。查询因 PostgreSQL 版本而异。查询详情见锁监控文档。

管理 Sidekiq 队列

可以使用 Sidekiq API 在 Sidekiq 上执行一些故障排除步骤。

这些是管理命令，只有在当前管理界面由于安装规模而不适合时才应使用。

所有这些命令都应该使用 gitlab-rails console 运行。

查看队列大小 

Sidekiq::Queue.new("pipeline_processing:build_queue").size

枚举所有排队的作业 

queue = Sidekiq::Queue.new("chaos:chaos_sleep")
queue.each do |job|
  # job.klass # => 'MyWorker'
  # job.args # => [1, 2, 3]
  # job.jid # => jid
  # job.queue # => chaos:chaos_sleep
  # job["retry"] # => 3
  # job.item # => {
  #   "class"=>"Chaos::SleepWorker",
  #   "args"=>[1000],
  #   "retry"=>3,
  #   "queue"=>"chaos:chaos_sleep",
  #   "backtrace"=>true,
  #   "queue_namespace"=>"chaos",
  #   "jid"=>"39bc482b823cceaf07213523",
  #   "created_at"=>1566317076.266069,
  #   "correlation_id"=>"c323b832-a857-4858-b695-672de6f0e1af",
  #   "enqueued_at"=>1566317076.26761},
  # }

  # job.delete if job.jid == 'abcdef1234567890'
end

枚举当前正在运行的作业 

workers = Sidekiq::Workers.new
workers.each do |process_id, thread_id, work|
  # process_id is a unique identifier per Sidekiq process
  # thread_id is a unique identifier per thread
  # work is a Hash which looks like:
  # {"queue"=>"chaos:chaos_sleep",
  #  "payload"=>
  #  { "class"=>"Chaos::SleepWorker",
  #    "args"=>[1000],
  #    "retry"=>3,
  #    "queue"=>"chaos:chaos_sleep",
  #    "backtrace"=>true,
  #    "queue_namespace"=>"chaos",
  #    "jid"=>"b2a31e3eac7b1a99ff235869",
  #    "created_at"=>1566316974.9215662,
  #    "correlation_id"=>"e484fb26-7576-45f9-bf21-b99389e1c53c",
  #    "enqueued_at"=>1566316974.9229589},
  #  "run_at"=>1566316974}],
end

删除给定参数的 Sidekiq 作业（破坏性）

有条件地终止作业的一般方法是以下命令，该命令删除排队但未启动的作业。正在运行的作业不能被杀死。 

queue = Sidekiq::Queue.new('<queue name>')
queue.each { |job| job.delete if <condition>}

查看以下部分，取消正在运行的作业。

在上面的方法中，<queue-name> 是包含要删除的作业的队列的名称，<condition> 决定删除哪些作业。

通常，<condition> 引用作业参数，这取决于相关作业的类型。要查找特定队列的参数，您可以查看相关 worker 文件的 perform 函数，该文件通常位于 /app/workers/<queue-name>_worker.rb。

例如，repository_import 有 project_id 作为作业参数，而 update_merge_requests 有 project_id, user_id, oldrev, newrev, ref。

需要使用 job.args[<id>] 通过其序列 ID 引用参数，因为 job.args 是提供给 Sidekiq 作业的所有参数的列表。

示例如下： 

queue = Sidekiq::Queue.new('update_merge_requests')
# In this example, we want to remove any update_merge_requests jobs
# for the Project with ID 125 and ref `ref/heads/my_branch`
queue.each { |job| job.delete if job.args[0] == 125 and job.args[4] == 'ref/heads/my_branch' }

# Cancelling jobs like: `RepositoryImportWorker.new.perform_async(100)`
id_list = [100]

queue = Sidekiq::Queue.new('repository_import')
queue.each do |job|
  job.delete if id_list.include?(job.args[0])
end

删除特定的作业 ID（破坏性） 

queue = Sidekiq::Queue.new('repository_import')
queue.each do |job|
  job.delete if job.jid == 'my-job-id'
end

取消正在运行的作业（破坏性）

这是高风险的操作，并将其用作最后的手段。 这样做可能会导致数据损坏，因为作业在执行过程中被中断，并且不能保证正确回滚事务。 

Gitlab::SidekiqDaemon::Monitor.cancel_job('job-id')

需要使用 SIDEKIQ_MONITOR_WORKER=1 环境变量运行 Sidekiq。

为了执行中断，我们使用 Thread.raise，它有很多缺点，参考 Why Ruby’s Timeout is dangerous (and Thread.raise is terrifying)。