InfoGrab DocsInfoGrab Docs

Sidekiq 문제 해결

요약

Sidekiq은 GitLab이 작업을 비동기적으로 실행하는 데 사용하는 백그라운드 job 처리기입니다. GitLab 관리자와 사용자는 백트레이스를 GitLab 팀이 분석할 수 있도록 GitLab 지원팀과 함께 이러한 디버그 단계를 진행하는 것을 고려해야 합니다.

Sidekiq은 GitLab이 작업을 비동기적으로 실행하는 데 사용하는 백그라운드 job 처리기입니다. 문제가 발생하면 원인을 파악하기 어려울 수 있습니다. 프로덕션 시스템의 job 대기열이 가득 차고 있을 수 있어 이러한 상황은 높은 압박감을 주는 경향이 있습니다. 새 브랜치가 표시되지 않거나 머지 리퀘스트가 업데이트되지 않기 때문에 사용자는 이런 일이 발생하면 알아차립니다. 다음은 병목 현상을 진단하는 데 도움이 되는 몇 가지 문제 해결 단계입니다.

GitLab 관리자와 사용자는 백트레이스를 GitLab 팀이 분석할 수 있도록 GitLab 지원팀과 함께 이러한 디버그 단계를 진행하는 것을 고려해야 합니다. 이를 통해 GitLab의 버그나 필요한 개선 사항이 드러날 수 있습니다.

어떤 백트레이스에서든 모든 스레드가 데이터베이스나 Redis에서 대기하거나 뮤텍스 획득을 기다리는 것처럼 보이는 경우를 의심할 때는 주의합니다. 예를 들어 이는 데이터베이스에 경합이 있다는 뜻일 수 있지만, 나머지와 다른 하나의 스레드를 찾아봅니다. 이 다른 스레드가 가용한 모든 CPU를 사용하고 있거나, 다른 스레드가 계속 실행되지 못하게 하는 Ruby Global Interpreter Lock을 보유하고 있을 수 있습니다.

Sidekiq job에 전달된 인수 로깅#

Sidekiq job에 전달된 일부 인수는 기본적으로 로깅됩니다. 민감한 정보(예: 비밀번호 재설정 토큰)가 로깅되지 않도록 GitLab은 모든 워커에 대해 숫자 인수를 로깅하고, 인수가 민감하지 않은 일부 특정 워커에는 예외를 적용합니다.

로그 출력 예시:

{"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킬로바이트 텍스트로 제한되며, 이 제한을 넘는 인수는 삭제되고 "..." 문자열을 담은 단일 인수로 대체됩니다.

SIDEKIQ_LOG_ARGUMENTS 환경 변수를 0(false)으로 설정하여 인수 로깅을 비활성화할 수 있습니다.

예시:

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

Sidekiq 대기열 백로그 또는 느린 성능 조사#

Sidekiq 성능 저하의 증상에는 머지 리퀘스트 상태 업데이트 문제와 CI 파이프라인 실행 시작 전 지연이 있습니다.

잠재적 원인은 다음과 같습니다:

  • GitLab 인스턴스에 더 많은 Sidekiq 워커가 필요할 수 있습니다. 기본적으로 단일 노드 Linux 패키지 설치는 하나의 워커를 실행하여 Sidekiq job 실행을 최대 하나의 CPU 코어로 제한합니다. 여러 Sidekiq 워커 실행에 대해 자세히 알아봅니다.

  • 인스턴스에 더 많은 Sidekiq 워커가 구성되어 있지만, 추가 워커 대부분이 대기열에 있는 job을 실행하도록 구성되어 있지 않습니다. 인스턴스가 바쁠 때, 워커를 구성한 이후 몇 달이나 몇 년에 걸쳐 워크로드가 변경된 경우, 또는 GitLab 제품 변경의 결과로 job 백로그가 발생할 수 있습니다.

다음 Ruby 스크립트로 Sidekiq 워커 상태에 대한 데이터를 수집합니다.

  1. 스크립트를 생성합니다:

    cat > /var/opt/gitlab/sidekiqcheck.rb <
    
  2. 실행하고 출력을 캡처합니다:

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

    성능 문제가 간헐적으로 발생하는 경우:

    • 5분마다 크론 job으로 실행합니다. 충분한 공간이 있는 위치에 파일을 씁니다: 파일당 최소 500KB를 확보합니다.

      cat > /etc/cron.d/sidekiqcheck < /tmp/sidekiqcheck_$(date '+\%Y\%m\%d-\%H:\%M').out 2>&1
      EOF
      
    • 데이터를 다시 살펴보며 무엇이 잘못되었는지 확인합니다.

  3. 출력을 분석합니다. 다음 명령은 출력 파일이 담긴 디렉터리가 있다고 가정합니다.

    1. grep 'Busy: ' *는 실행 중이던 job 수를 보여줍니다. 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개의 job 백로그가 있었습니다.

      • 13개의 워커 프로세스 중 두 개만 바빴습니다.

      • 이는 다른 워커들이 너무 구체적으로 구성되어 있음을 나타냅니다.

      • 어떤 워커가 바빴는지 파악하려면 전체 출력을 확인합니다. gitlab.rb의 sidekiq_queues 구성과 연관 지어 살펴봅니다.

      • 과부하된 단일 워커 환경은 다음과 같이 나타날 수 있습니다:

        sidekiqcheck_20221024-14:00.out
               Busy: 25
           Enqueued: 363
        ---- Processes (1) ----
          Threads: 25 (25 busy)
        
    3. 출력 파일의 ---- Queues (xxx) ---- 섹션을 확인하여 그 시점에 어떤 job이 대기열에 쌓여 있었는지 파악합니다.

    4. 파일에는 그 시점의 Sidekiq 상태에 대한 낮은 수준의 세부 정보도 포함됩니다. 이는 워크로드 급증이 어디에서 오는지 식별하는 데 유용할 수 있습니다.

      • ----------- workers ----------- 섹션은 요약의 Busy 수를 구성하는 job을 자세히 설명합니다.
      • ----------- Queued Jobs ----------- 섹션은 Enqueued 상태인 job에 대한 세부 정보를 제공합니다.

스레드 덤프#

로그 파일에 스레드 백트레이스를 출력하려면 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 워커를 1분 동안 프로파일링하려면 다음을 실행합니다:

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에 의해 호출되는 것을 확인할 수 있습니다.

rbspy는 컨테이너화된 환경에서 추가 capabilities를 요구합니다. 최소한 SYS_PTRACE capability가 필요하며, 그렇지 않으면 permission denied 오류와 함께 종료됩니다.

securityContext:
  capabilities:
    add:
      - SYS_PTRACE
docker run --cap-add SYS_PTRACE [...]
services:
  ruby_container_name:
    # ...
    cap_add:
      - SYS_PTRACE

perf를 사용한 프로세스 프로파일링#

Linux에는 특정 프로세스가 CPU를 많이 소모할 때 유용한 perf라는 프로세스 프로파일링 도구가 있습니다. 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초 동안 실행한 다음 Control-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 리포트의 샘플 출력은 CPU의 97%가 Nokogiri와 xmlXPathNodeSetMergeAndClear 내부에서 소비되고 있음을 보여줍니다. 이처럼 명확한 경우라면 GitLab에서 Nokogiri와 XPath를 사용하는 job이 무엇인지 조사해야 합니다. TTIN 또는 gdb 출력과 결합하면 이런 일이 발생하는 해당 Ruby 코드를 확인할 수 있습니다.

GNU 프로젝트 디버거(gdb)#

gdb는 Sidekiq을 디버깅하는 또 다른 효과적인 도구입니다. 각 스레드를 살펴보고 무엇이 문제를 일으키는지 확인하는 조금 더 대화형인 방법을 제공합니다.

gdb로 프로세스에 연결하면 해당 프로세스의 표준 동작이 중단됩니다 (gdb가 연결된 동안 Sidekiq은 job을 처리하지 않습니다).

먼저 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이 job을 처리하는 속도가 너무 빨라서 데이터베이스 경합을 일으키는 경우가 있습니다. 앞에서 설명한 백트레이스에서 많은 스레드가 데이터베이스 어댑터에 멈춰 있는 것으로 나타나면 차단 쿼리를 확인합니다.

PostgreSQL 위키에는 차단 쿼리를 확인하기 위해 실행할 수 있는 쿼리의 세부 정보가 있습니다. 이 쿼리는 PostgreSQL 버전에 따라 다릅니다. 쿼리 세부 정보는 Lock Monitoring을 참고합니다.

Sidekiq 대기열 관리#

Sidekiq API를 사용하여 Sidekiq에서 여러 문제 해결 단계를 수행할 수 있습니다.

이 명령은 관리용 명령이며, 설치 규모 때문에 현재의 관리 인터페이스가 적합하지 않은 경우에만 사용해야 합니다.

이 명령은 모두 gitlab-rails console을 사용하여 실행해야 합니다.

대기열 크기 보기#

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

대기열에 추가된 모든 job 열거#

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

현재 실행 중인 job 열거#

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 job 제거(파괴적)#

조건에 따라 job을 종료하는 일반적인 방법은 다음 명령이며, 이 명령은 대기열에 있지만 시작되지 않은 job을 제거합니다. 실행 중인 job은 종료할 수 없습니다.

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

실행 중인 job 취소는 아래 섹션을 참고합니다.

앞에서 설명한 방법에서 <queue-name>은 삭제할 job이 들어 있는 대기열의 이름이고, <condition>은 어떤 job이 삭제될지 결정합니다.

일반적으로 <condition>은 job 인수를 참조하며, 이 인수는 해당 job의 유형에 따라 다릅니다. 특정 대기열의 인수를 찾으려면 관련 워커 파일의 perform 함수를 살펴볼 수 있으며, 이 파일은 보통 /app/workers/<queue-name>_worker.rb에 있습니다.

예를 들어 repository_import는 job 인수로 project_id를 가지고, update_merge_requests는 project_id, user_id, oldrev, newrev, ref를 가집니다.

job.args는 Sidekiq job에 제공된 모든 인수의 목록이므로, 인수는 job.args[<id>]를 사용해 순번 ID로 참조해야 합니다.

다음은 몇 가지 예시입니다:

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' }
# Canceling 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

특정 job ID 제거(파괴적)#

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

특정 워커의 Sidekiq job 제거(파괴적)#

queue = Sidekiq::Queue.new("default")

queue.each do |job|
  if job.klass == "TodosDestroyer::PrivateFeaturesWorker"
    # Uncomment the line below to actually delete jobs
    #job.delete
    puts "Deleted job ID #{job.jid}"
  end
end

실행 중인 job 취소(파괴적)#

이 작업은 매우 위험하므로 최후의 수단으로만 사용합니다. job이 실행 중간에 중단되고 트랜잭션이 올바르게 롤백되도록 구현되어 있다는 보장이 없으므로, 이 작업은 데이터 손상으로 이어질 수 있습니다.

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

이를 위해서는 Sidekiq을 SIDEKIQ_MONITOR_WORKER=1 환경 변수와 함께 실행해야 합니다.

중단을 수행하기 위해 Thread.raise를 사용하는데, 이 방식에는 Why Ruby's Timeout is dangerous (and Thread.raise is terrifying)에서 언급된 여러 단점이 있습니다.

크론 job 수동 트리거#

/admin/background_jobs를 방문하면 인스턴스에서 예약/실행/대기 중인 job을 확인할 수 있습니다.

UI에서 "Enqueue Now" 버튼을 선택하여 크론 job을 트리거할 수 있습니다. 프로그래밍 방식으로 크론 job을 트리거하려면 먼저 Rails 콘솔을 엽니다.

테스트할 크론 job을 찾으려면:

job = Sidekiq::Cron::Job.find('job-name')

# get status of job:
job.status

# enqueue job right now!
job.enque!

예를 들어 리포지터리 미러를 업데이트하는 update_all_mirrors_worker 크론 job을 트리거하려면:

irb(main):001:0> job = Sidekiq::Cron::Job.find('update_all_mirrors_worker')
=>
# job.status
=> "enabled"
irb(main):003:0> job.enque!
=> 257

사용 가능한 job 목록은 workers 디렉터리에서 찾을 수 있습니다.

Sidekiq job에 대한 자세한 내용은 Sidekiq-cron 문서를 참고합니다.

크론 job 비활성화#

Admin 영역의 Monitoring 섹션을 방문하여 Sidekiq 크론 job을 비활성화할 수 있습니다. 명령줄과 Rails Runner를 사용하여 동일한 작업을 수행할 수도 있습니다.

모든 크론 job을 비활성화하려면:

sudo gitlab-rails runner 'Sidekiq::Cron::Job.all.map(&:disable!)'

모든 크론 job을 활성화하려면:

sudo gitlab-rails runner 'Sidekiq::Cron::Job.all.map(&:enable!)'

한 번에 일부 job만 활성화하려면 이름 일치를 사용할 수 있습니다. 예를 들어 이름에 geo가 포함된 job만 활성화하려면:

 sudo gitlab-rails runner 'Sidekiq::Cron::Job.all.select{ |j| j.name.match("geo") }.map(&:disable!)'

Sidekiq job 중복 제거 멱등성 키 지우기#

실행될 것으로 예상되는 job(예: 크론 job)이 전혀 실행되지 않는 것으로 관찰되는 경우가 간혹 있습니다. 로그를 확인할 때 job이 "job_status": "deduplicated" 상태로 실행되지 않는 사례가 있을 수 있습니다.

이는 job이 실패했고 멱등성 키가 제대로 지워지지 않았을 때 발생할 수 있습니다. 예를 들어 Sidekiq을 중지하면 남아 있는 job이 25초 후에 모두 종료됩니다.

기본적으로 키는 6시간 후에 만료되지만, 멱등성 키를 즉시 지우려면 다음 단계를 따릅니다(제공된 예시는 Geo::VerificationBatchWorker에 대한 것입니다):

  1. Sidekiq 로그에서 job의 워커 클래스와 args를 찾습니다:

    { ... "class":"Geo::VerificationBatchWorker","args":["container_repository"] ... }
    
  2. Rails 콘솔 세션을 시작합니다.

  3. 다음 스니펫을 실행합니다:

    worker_class = Geo::VerificationBatchWorker
    args = ["container_repository"]
    dj = Gitlab::SidekiqMiddleware::DuplicateJobs::DuplicateJob.new({ 'class' => worker_class.name, 'args' => args }, worker_class.queue)
    dj.send(:idempotency_key)
    dj.delete!
    

Sidekiq BRPOP 호출로 인한 Redis CPU 포화#

Sidekiq BRPOP 호출은 Redis의 CPU 사용량을 증가시킬 수 있습니다. Redis의 CPU 사용량을 개선하려면 SIDEKIQ_SEMI_RELIABLE_FETCH_TIMEOUT 환경 변수를 늘립니다.

오류: OpenSSL::Cipher::CipherError#

다음과 같은 오류 메시지가 표시되는 경우:

"OpenSSL::Cipher::CipherError","exception.message":"","exception.backtrace":["encryptor (3.0.0) lib/encryptor.rb:98:in `final'","encryptor (3.0.0) lib/encryptor.rb:98:in `crypt'","encryptor (3.0.0) lib/encryptor.rb:49:in `decrypt'"

이 오류는 프로세스가 GitLab 데이터베이스에 저장된 암호화 데이터를 복호화할 수 없다는 뜻입니다. 이는 /etc/gitlab/gitlab-secrets.json 파일에 문제가 있음을 나타냅니다. 기본 GitLab 노드에서 Sidekiq 노드로 이 파일을 복사했는지 확인합니다.

관련 주제#

Sidekiq 문제 해결

GitLab v19.5
Tier: Free, Premium, Ultimate
Offering: GitLab Self-Managed
원문 보기

요약

Sidekiq은 GitLab이 작업을 비동기적으로 실행하는 데 사용하는 백그라운드 job 처리기입니다. GitLab 관리자와 사용자는 백트레이스를 GitLab 팀이 분석할 수 있도록 GitLab 지원팀과 함께 이러한 디버그 단계를 진행하는 것을 고려해야 합니다.

Sidekiq은 GitLab이 작업을 비동기적으로 실행하는 데 사용하는 백그라운드 job 처리기입니다. 문제가 발생하면 원인을 파악하기 어려울 수 있습니다. 프로덕션 시스템의 job 대기열이 가득 차고 있을 수 있어 이러한 상황은 높은 압박감을 주는 경향이 있습니다. 새 브랜치가 표시되지 않거나 머지 리퀘스트가 업데이트되지 않기 때문에 사용자는 이런 일이 발생하면 알아차립니다. 다음은 병목 현상을 진단하는 데 도움이 되는 몇 가지 문제 해결 단계입니다.

GitLab 관리자와 사용자는 백트레이스를 GitLab 팀이 분석할 수 있도록 GitLab 지원팀과 함께 이러한 디버그 단계를 진행하는 것을 고려해야 합니다. 이를 통해 GitLab의 버그나 필요한 개선 사항이 드러날 수 있습니다.

어떤 백트레이스에서든 모든 스레드가 데이터베이스나 Redis에서 대기하거나 뮤텍스 획득을 기다리는 것처럼 보이는 경우를 의심할 때는 주의합니다. 예를 들어 이는 데이터베이스에 경합이 있다는 뜻일 수 있지만, 나머지와 다른 하나의 스레드를 찾아봅니다. 이 다른 스레드가 가용한 모든 CPU를 사용하고 있거나, 다른 스레드가 계속 실행되지 못하게 하는 Ruby Global Interpreter Lock을 보유하고 있을 수 있습니다.

Sidekiq job에 전달된 인수 로깅#

Sidekiq job에 전달된 일부 인수는 기본적으로 로깅됩니다. 민감한 정보(예: 비밀번호 재설정 토큰)가 로깅되지 않도록 GitLab은 모든 워커에 대해 숫자 인수를 로깅하고, 인수가 민감하지 않은 일부 특정 워커에는 예외를 적용합니다.

로그 출력 예시:

{"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킬로바이트 텍스트로 제한되며, 이 제한을 넘는 인수는 삭제되고 "..." 문자열을 담은 단일 인수로 대체됩니다.

SIDEKIQ_LOG_ARGUMENTS 환경 변수를 0(false)으로 설정하여 인수 로깅을 비활성화할 수 있습니다.

예시:

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

Sidekiq 대기열 백로그 또는 느린 성능 조사#

Sidekiq 성능 저하의 증상에는 머지 리퀘스트 상태 업데이트 문제와 CI 파이프라인 실행 시작 전 지연이 있습니다.

잠재적 원인은 다음과 같습니다:

  • GitLab 인스턴스에 더 많은 Sidekiq 워커가 필요할 수 있습니다. 기본적으로 단일 노드 Linux 패키지 설치는 하나의 워커를 실행하여 Sidekiq job 실행을 최대 하나의 CPU 코어로 제한합니다. 여러 Sidekiq 워커 실행에 대해 자세히 알아봅니다.

  • 인스턴스에 더 많은 Sidekiq 워커가 구성되어 있지만, 추가 워커 대부분이 대기열에 있는 job을 실행하도록 구성되어 있지 않습니다. 인스턴스가 바쁠 때, 워커를 구성한 이후 몇 달이나 몇 년에 걸쳐 워크로드가 변경된 경우, 또는 GitLab 제품 변경의 결과로 job 백로그가 발생할 수 있습니다.

다음 Ruby 스크립트로 Sidekiq 워커 상태에 대한 데이터를 수집합니다.

  1. 스크립트를 생성합니다:

    cat > /var/opt/gitlab/sidekiqcheck.rb <
    
  2. 실행하고 출력을 캡처합니다:

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

    성능 문제가 간헐적으로 발생하는 경우:

    • 5분마다 크론 job으로 실행합니다. 충분한 공간이 있는 위치에 파일을 씁니다: 파일당 최소 500KB를 확보합니다.

      cat > /etc/cron.d/sidekiqcheck < /tmp/sidekiqcheck_$(date '+\%Y\%m\%d-\%H:\%M').out 2>&1
      EOF
      
    • 데이터를 다시 살펴보며 무엇이 잘못되었는지 확인합니다.

  3. 출력을 분석합니다. 다음 명령은 출력 파일이 담긴 디렉터리가 있다고 가정합니다.

    1. grep 'Busy: ' *는 실행 중이던 job 수를 보여줍니다. 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개의 job 백로그가 있었습니다.

      • 13개의 워커 프로세스 중 두 개만 바빴습니다.

      • 이는 다른 워커들이 너무 구체적으로 구성되어 있음을 나타냅니다.

      • 어떤 워커가 바빴는지 파악하려면 전체 출력을 확인합니다. gitlab.rb의 sidekiq_queues 구성과 연관 지어 살펴봅니다.

      • 과부하된 단일 워커 환경은 다음과 같이 나타날 수 있습니다:

        sidekiqcheck_20221024-14:00.out
               Busy: 25
           Enqueued: 363
        ---- Processes (1) ----
          Threads: 25 (25 busy)
        
    3. 출력 파일의 ---- Queues (xxx) ---- 섹션을 확인하여 그 시점에 어떤 job이 대기열에 쌓여 있었는지 파악합니다.

    4. 파일에는 그 시점의 Sidekiq 상태에 대한 낮은 수준의 세부 정보도 포함됩니다. 이는 워크로드 급증이 어디에서 오는지 식별하는 데 유용할 수 있습니다.

      • ----------- workers ----------- 섹션은 요약의 Busy 수를 구성하는 job을 자세히 설명합니다.
      • ----------- Queued Jobs ----------- 섹션은 Enqueued 상태인 job에 대한 세부 정보를 제공합니다.

스레드 덤프#

로그 파일에 스레드 백트레이스를 출력하려면 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 워커를 1분 동안 프로파일링하려면 다음을 실행합니다:

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에 의해 호출되는 것을 확인할 수 있습니다.

rbspy는 컨테이너화된 환경에서 추가 capabilities를 요구합니다. 최소한 SYS_PTRACE capability가 필요하며, 그렇지 않으면 permission denied 오류와 함께 종료됩니다.

securityContext:
  capabilities:
    add:
      - SYS_PTRACE
docker run --cap-add SYS_PTRACE [...]
services:
  ruby_container_name:
    # ...
    cap_add:
      - SYS_PTRACE

perf를 사용한 프로세스 프로파일링#

Linux에는 특정 프로세스가 CPU를 많이 소모할 때 유용한 perf라는 프로세스 프로파일링 도구가 있습니다. 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초 동안 실행한 다음 Control-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 리포트의 샘플 출력은 CPU의 97%가 Nokogiri와 xmlXPathNodeSetMergeAndClear 내부에서 소비되고 있음을 보여줍니다. 이처럼 명확한 경우라면 GitLab에서 Nokogiri와 XPath를 사용하는 job이 무엇인지 조사해야 합니다. TTIN 또는 gdb 출력과 결합하면 이런 일이 발생하는 해당 Ruby 코드를 확인할 수 있습니다.

GNU 프로젝트 디버거(gdb)#

gdb는 Sidekiq을 디버깅하는 또 다른 효과적인 도구입니다. 각 스레드를 살펴보고 무엇이 문제를 일으키는지 확인하는 조금 더 대화형인 방법을 제공합니다.

gdb로 프로세스에 연결하면 해당 프로세스의 표준 동작이 중단됩니다 (gdb가 연결된 동안 Sidekiq은 job을 처리하지 않습니다).

먼저 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이 job을 처리하는 속도가 너무 빨라서 데이터베이스 경합을 일으키는 경우가 있습니다. 앞에서 설명한 백트레이스에서 많은 스레드가 데이터베이스 어댑터에 멈춰 있는 것으로 나타나면 차단 쿼리를 확인합니다.

PostgreSQL 위키에는 차단 쿼리를 확인하기 위해 실행할 수 있는 쿼리의 세부 정보가 있습니다. 이 쿼리는 PostgreSQL 버전에 따라 다릅니다. 쿼리 세부 정보는 Lock Monitoring을 참고합니다.

Sidekiq 대기열 관리#

Sidekiq API를 사용하여 Sidekiq에서 여러 문제 해결 단계를 수행할 수 있습니다.

이 명령은 관리용 명령이며, 설치 규모 때문에 현재의 관리 인터페이스가 적합하지 않은 경우에만 사용해야 합니다.

이 명령은 모두 gitlab-rails console을 사용하여 실행해야 합니다.

대기열 크기 보기#

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

대기열에 추가된 모든 job 열거#

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

현재 실행 중인 job 열거#

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 job 제거(파괴적)#

조건에 따라 job을 종료하는 일반적인 방법은 다음 명령이며, 이 명령은 대기열에 있지만 시작되지 않은 job을 제거합니다. 실행 중인 job은 종료할 수 없습니다.

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

실행 중인 job 취소는 아래 섹션을 참고합니다.

앞에서 설명한 방법에서 <queue-name>은 삭제할 job이 들어 있는 대기열의 이름이고, <condition>은 어떤 job이 삭제될지 결정합니다.

일반적으로 <condition>은 job 인수를 참조하며, 이 인수는 해당 job의 유형에 따라 다릅니다. 특정 대기열의 인수를 찾으려면 관련 워커 파일의 perform 함수를 살펴볼 수 있으며, 이 파일은 보통 /app/workers/<queue-name>_worker.rb에 있습니다.

예를 들어 repository_import는 job 인수로 project_id를 가지고, update_merge_requests는 project_id, user_id, oldrev, newrev, ref를 가집니다.

job.args는 Sidekiq job에 제공된 모든 인수의 목록이므로, 인수는 job.args[<id>]를 사용해 순번 ID로 참조해야 합니다.

다음은 몇 가지 예시입니다:

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' }
# Canceling 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

특정 job ID 제거(파괴적)#

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

특정 워커의 Sidekiq job 제거(파괴적)#

queue = Sidekiq::Queue.new("default")

queue.each do |job|
  if job.klass == "TodosDestroyer::PrivateFeaturesWorker"
    # Uncomment the line below to actually delete jobs
    #job.delete
    puts "Deleted job ID #{job.jid}"
  end
end

실행 중인 job 취소(파괴적)#

이 작업은 매우 위험하므로 최후의 수단으로만 사용합니다. job이 실행 중간에 중단되고 트랜잭션이 올바르게 롤백되도록 구현되어 있다는 보장이 없으므로, 이 작업은 데이터 손상으로 이어질 수 있습니다.

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

이를 위해서는 Sidekiq을 SIDEKIQ_MONITOR_WORKER=1 환경 변수와 함께 실행해야 합니다.

중단을 수행하기 위해 Thread.raise를 사용하는데, 이 방식에는 Why Ruby's Timeout is dangerous (and Thread.raise is terrifying)에서 언급된 여러 단점이 있습니다.

크론 job 수동 트리거#

/admin/background_jobs를 방문하면 인스턴스에서 예약/실행/대기 중인 job을 확인할 수 있습니다.

UI에서 "Enqueue Now" 버튼을 선택하여 크론 job을 트리거할 수 있습니다. 프로그래밍 방식으로 크론 job을 트리거하려면 먼저 Rails 콘솔을 엽니다.

테스트할 크론 job을 찾으려면:

job = Sidekiq::Cron::Job.find('job-name')

# get status of job:
job.status

# enqueue job right now!
job.enque!

예를 들어 리포지터리 미러를 업데이트하는 update_all_mirrors_worker 크론 job을 트리거하려면:

irb(main):001:0> job = Sidekiq::Cron::Job.find('update_all_mirrors_worker')
=>
# job.status
=> "enabled"
irb(main):003:0> job.enque!
=> 257

사용 가능한 job 목록은 workers 디렉터리에서 찾을 수 있습니다.

Sidekiq job에 대한 자세한 내용은 Sidekiq-cron 문서를 참고합니다.

크론 job 비활성화#

Admin 영역의 Monitoring 섹션을 방문하여 Sidekiq 크론 job을 비활성화할 수 있습니다. 명령줄과 Rails Runner를 사용하여 동일한 작업을 수행할 수도 있습니다.

모든 크론 job을 비활성화하려면:

sudo gitlab-rails runner 'Sidekiq::Cron::Job.all.map(&:disable!)'

모든 크론 job을 활성화하려면:

sudo gitlab-rails runner 'Sidekiq::Cron::Job.all.map(&:enable!)'

한 번에 일부 job만 활성화하려면 이름 일치를 사용할 수 있습니다. 예를 들어 이름에 geo가 포함된 job만 활성화하려면:

 sudo gitlab-rails runner 'Sidekiq::Cron::Job.all.select{ |j| j.name.match("geo") }.map(&:disable!)'

Sidekiq job 중복 제거 멱등성 키 지우기#

실행될 것으로 예상되는 job(예: 크론 job)이 전혀 실행되지 않는 것으로 관찰되는 경우가 간혹 있습니다. 로그를 확인할 때 job이 "job_status": "deduplicated" 상태로 실행되지 않는 사례가 있을 수 있습니다.

이는 job이 실패했고 멱등성 키가 제대로 지워지지 않았을 때 발생할 수 있습니다. 예를 들어 Sidekiq을 중지하면 남아 있는 job이 25초 후에 모두 종료됩니다.

기본적으로 키는 6시간 후에 만료되지만, 멱등성 키를 즉시 지우려면 다음 단계를 따릅니다(제공된 예시는 Geo::VerificationBatchWorker에 대한 것입니다):

  1. Sidekiq 로그에서 job의 워커 클래스와 args를 찾습니다:

    { ... "class":"Geo::VerificationBatchWorker","args":["container_repository"] ... }
    
  2. Rails 콘솔 세션을 시작합니다.

  3. 다음 스니펫을 실행합니다:

    worker_class = Geo::VerificationBatchWorker
    args = ["container_repository"]
    dj = Gitlab::SidekiqMiddleware::DuplicateJobs::DuplicateJob.new({ 'class' => worker_class.name, 'args' => args }, worker_class.queue)
    dj.send(:idempotency_key)
    dj.delete!
    

Sidekiq BRPOP 호출로 인한 Redis CPU 포화#

Sidekiq BRPOP 호출은 Redis의 CPU 사용량을 증가시킬 수 있습니다. Redis의 CPU 사용량을 개선하려면 SIDEKIQ_SEMI_RELIABLE_FETCH_TIMEOUT 환경 변수를 늘립니다.

오류: OpenSSL::Cipher::CipherError#

다음과 같은 오류 메시지가 표시되는 경우:

"OpenSSL::Cipher::CipherError","exception.message":"","exception.backtrace":["encryptor (3.0.0) lib/encryptor.rb:98:in `final'","encryptor (3.0.0) lib/encryptor.rb:98:in `crypt'","encryptor (3.0.0) lib/encryptor.rb:49:in `decrypt'"

이 오류는 프로세스가 GitLab 데이터베이스에 저장된 암호화 데이터를 복호화할 수 없다는 뜻입니다. 이는 /etc/gitlab/gitlab-secrets.json 파일에 문제가 있음을 나타냅니다. 기본 GitLab 노드에서 Sidekiq 노드로 이 파일을 복사했는지 확인합니다.

관련 주제#