Skip to content
Snippets Groups Projects

Redis switchover causing increased rate of sidekiq errors

    • Closed Incident created by John Skarbek @skarbek

    Summary

    • When redis switches masters, our sidekiqs are having issues completing jobs.
    • Please see this issue where much discussion related to this has already happened
    Edited

    Child items ...

    • Activity

    • John Skarbek changed title from Incident Redis switchover causing increased rate of sidekiq errors to Redis switchover causing increased rate of sidekiq errors

      changed title from Incident Redis switchover causing increased rate of sidekiq errors to Redis switchover causing increased rate of sidekiq errors

    • John Skarbek added incident label

      added incident label

    • John Skarbek
      John Skarbek @skarbek
      Author Owner

      https://dashboards.gitlab.net/d/mRwmXrImz/imported-redis-stats?orgId=1&var-environment=gprd&var-prometheus=prometheus-01-inf-gprd

    • Andrew Newdigate
      Andrew Newdigate @andrewn
      Owner

      I suggested we enable LATENCY DOCTOR metrics as latency could be the cause of this issue:

      https://redis.io/topics/latency-monitor

      Will follow with a set of commands to do this.

    • Andrew Newdigate
      Andrew Newdigate @andrewn
      Owner

      To enable:

      $ REDIS_MASTER_AUTH=$(sudo grep ^masterauth /var/opt/gitlab/redis/redis.conf|cut -d\" -f2)
$ /opt/gitlab/embedded/bin/redis-cli -a $REDIS_MASTER_AUTH CONFIG SET latency-monitor-threshold 100

      To disable

      $ REDIS_MASTER_AUTH=$(sudo grep ^masterauth /var/opt/gitlab/redis/redis.conf|cut -d\" -f2)
$ /opt/gitlab/embedded/bin/redis-cli -a $REDIS_MASTER_AUTH CONFIG SET latency-monitor-threshold 0

      While it's enabled:

      $ REDIS_MASTER_AUTH=$(sudo grep ^masterauth /var/opt/gitlab/redis/redis.conf|cut -d\" -f2)
$ /opt/gitlab/embedded/bin/redis-cli -a $REDIS_MASTER_AUTH latency doctor
    • Andrew Newdigate
      Andrew Newdigate @andrewn
      Owner

      enalbed on the current master (redis-01). After a few seconds:

      latency doctor
Dave, no latency spike was observed during the lifetime of this Redis instance, not in the slightest bit. I honestly think you ought to sit down calmly, take a stress pill, and think things over.
      Edited by Andrew Newdigate
    • Andrew Newdigate
      Andrew Newdigate @andrewn
      Owner

      Currently the slowlog is set to 10seconds.

      CONFIG GET slowlog-log-slower-than
1) "slowlog-log-slower-than"
2) "10000"

      What's interesting is that it's got a fair bit of slow log entry in it, even at that high latency value...

      127.0.0.1:6379> slowlog get 10
 1) 1) (integer) 10
    2) (integer) 1534872680
    3) (integer) 36177
    4) 1) "latency"
       2) "doctor"
 2) 1) (integer) 9
    2) (integer) 1534872646
    3) (integer) 36472
    4) 1) "latency"
       2) "doctor"
 3) 1) (integer) 8
    2) (integer) 1534866407
    3) (integer) 33115
    4) 1) "lpush"
       2) "resque:gitlab:queue:email_receiver"
       3) "{\"class\":\"EmailReceiverWorker\",\"args\":[\"Delivered-To: XXXXX\\r\\nReceiv... (28276559 more bytes)"
 4) 1) (integer) 7
    2) (integer) 1534865788
    3) (integer) 33846
    4) 1) "lpush"
       2) "resque:gitlab:queue:email_receiver"
       3) "{\"class\":\"EmailReceiverWorker\",\"args\":[\"Delivered-To: XXXXX\\r\\nReceiv... (32979148 more bytes)"
 5) 1) (integer) 6
    2) (integer) 1534860277
    3) (integer) 30848
    4) 1) "lpush"
       2) "resque:gitlab:queue:system_hook_push"
       3) "{\"class\":\"SystemHookPushWorker\",\"args\":[{\"object_kind\":\"push\",\"event_name\":\"push\",\"before\":\"718f16563eac2c7ee77f4c1c1626617125f1... (35191437 more bytes)"
 6) 1) (integer) 5
    2) (integer) 1534851898
    3) (integer) 61354
    4) 1) "CLIENT"
       2) "KILL"
       3) "TYPE"
       4) "normal"
 7) 1) (integer) 4
    2) (integer) 1534851898
    3) (integer) 164034
    4) 1) "SLAVEOF"
       2) "10.217.2.102"
       3) "6379"
 8) 1) (integer) 3
    2) (integer) 1534851319
    3) (integer) 169333
    4) 1) "lpush"
       2) "resque:gitlab:queue:system_hook_push"
       3) "{\"class\":\"SystemHookPushWorker\",\"args\":[{\"object_kind\":\"push\",\"event_name\":\"push\",\"before\":\"8cf94d0a510890d02d28cd75d94ad98eef11... (161276865 more bytes)"
 9) 1) (integer) 2
    2) (integer) 1534849416
    3) (integer) 13803
    4) 1) "lpush"
       2) "resque:gitlab:queue:system_hook_push"
       3) "{\"class\":\"SystemHookPushWorker\",\"args\":[{\"object_kind\":\"push\",\"event_name\":\"push\",\"before\":\"bd3bd072c9210703c8c74775e01969d49a67... (15129764 more bytes)"
10) 1) (integer) 1
    2) (integer) 1534848814
    3) (integer) 55858
    4) 1) "PSYNC"
       2) "?"
       3) "-1"
    • Andrew Newdigate
      Andrew Newdigate @andrewn
      Owner

      These slowlog entries are pretty strange.

      • The timestamps are all today. (mostly around 10 UTC)
      • lpush is a O(1) operation in Redis, so it should be really fast, yet we're seeing some (lpush resque:gitlab:queue:system_hook_push) taking up to 170ms
      • The queues in question (resque:gitlab:queue:system_hook_push and resque:gitlab:queue:email_receiver) both currently have a length of zero (not that this will make a difference for a O(1) operation)
      • Staging does not have the same sort of entries. It's slowlog does not have anything in the past week.

      Could the lpush operations just be random commands that are in-progress when the machine randomly freezes up?

      Another observation: considering the size of these machines, and especially how much bigger they are than their Azure counterparts, I'm quite surprised at how much CPU Redis is consuming ~60% of one core. It would be worth investigating usage in Azure from before the failover.

      Current Plan

      1. @skarbek to await another failover and run LATENCY DOCTOR and SLOWLOG 10 post failover on the ex-master (redis-01) and see what comes up.
      2. We need to keep in mind that the command that appears in the log may be an "innocent bystander" rather than the cause of the latency, if the latency is external.
      3. It would also be worth investigating whether Redis is spawning a child for BGSAVE persistence using copy-on-write at the time of the latency spike: why? http://antirez.com/news/84
      Edited by Andrew Newdigate
    • Andrew Newdigate
      Andrew Newdigate @andrewn
      Owner

      Looks like the issue is due to the size of these payloads - up to 160MB!

      @stanhu pointed out that there is an issue for this: https://gitlab.com/gitlab-org/gitlab-ce/issues/32369, and Salvatore pointed this out too https://gitlab.com/gitlab-com/infrastructure/issues/1802#note_29782628

      Edited by Andrew Newdigate
    • Stan Hu
      Stan Hu @stanhu
      Maintainer

      On GitLab.com, we have two system hooks, but neither of them handle the push event. If we can't figure out how to limit the payload in https://gitlab.com/gitlab-org/gitlab-ce/issues/32369, we may just want to avoid pushing this payload if we have no listeners for this event.

    • John Skarbek
      John Skarbek @skarbek
      Author Owner

      So, in watching things today, node 01 almost failed us. One of the servers indicated it had gone into a subjective down, but he remained master. I figured now would be a good time to collect a bit of data. From the slow log:

      127.0.0.1:6379> slowlog get 10
 1) 1) (integer) 14
    2) (integer) 1534883404
    3) (integer) 37554
    4) 1) "latency"
       2) "doctor"
 2) 1) (integer) 13
    2) (integer) 1534877184
    3) (integer) 40525
    4) 1) "latency"
       2) "doctor"
 3) 1) (integer) 12
    2) (integer) 1534873680
    3) (integer) 38248
    4) 1) "latency"
       2) "doctor"
 4) 1) (integer) 11
    2) (integer) 1534873396
    3) (integer) 39480
    4) 1) "latency"
       2) "doctor"
 5) 1) (integer) 10
    2) (integer) 1534872680
    3) (integer) 36177
    4) 1) "latency"
       2) "doctor"
 6) 1) (integer) 9
    2) (integer) 1534872646
    3) (integer) 36472
    4) 1) "latency"
       2) "doctor"
 7) 1) (integer) 8
    2) (integer) 1534866407
    3) (integer) 33115
    4) 1) "lpush"
       2) "resque:gitlab:queue:email_receiver"
       3) "{\"class\":\"EmailReceiverWorker\",\"args\":[\"Delivered-To: redacted\\r\\nReceiv... (28276559 more bytes)"
 8) 1) (integer) 7
    2) (integer) 1534865788
    3) (integer) 33846
    4) 1) "lpush"
       2) "resque:gitlab:queue:email_receiver"
       3) "{\"class\":\"EmailReceiverWorker\",\"args\":[\"Delivered-To: redacted\\r\\nReceiv... (32979148 more bytes)"
 9) 1) (integer) 6
    2) (integer) 1534860277
    3) (integer) 30848
    4) 1) "lpush"
       2) "resque:gitlab:queue:system_hook_push"
       3) "{\"class\":\"SystemHookPushWorker\",\"args\":[{\"object_kind\":\"push\",\"event_name\":\"push\",\"before\":\"718f16563eac2c7ee77f4c1c1626617125f1... (35191437 more bytes)"
10) 1) (integer) 5
    2) (integer) 1534851898
    3) (integer) 61354
    4) 1) "CLIENT"
       2) "KILL"
       3) "TYPE"
       4) "normal"

      And then latency doctor told me to take a stress pill.

    • Stan Hu
      Stan Hu @stanhu
      Maintainer

      Ok, while trying to fix this bug, I found an even dumber bug (https://gitlab.com/gitlab-org/gitlab-ce/issues/50549). https://gitlab.com/gitlab-org/gitlab-ce/merge_requests/21337 squashes both of these issues.

    • John Skarbek assigned to @skarbek

      assigned to @skarbek

    • John Skarbek added priority4 severity4 labels

      added priority4 severity4 labels

    • John Skarbek
      John Skarbek @skarbek
      Author Owner

      A failover happened at approximage 10:28 UTC

      127.0.0.1:6379> slowlog get 10
 1) 1) (integer) 31
    2) (integer) 1534933451
    3) (integer) 79720
    4) 1) "CLIENT"
       2) "KILL"
       3) "TYPE"
       4) "normal"
 2) 1) (integer) 30
    2) (integer) 1534933451
    3) (integer) 682213
    4) 1) "SLAVEOF"
       2) "10.217.2.101"
       3) "6379"
 3) 1) (integer) 29
    2) (integer) 1534931300
    3) (integer) 17777
    4) 1) "lpush"
       2) "resque:gitlab:queue:system_hook_push"
       3) "{\"class\":\"SystemHookPushWorker\",\"args\":[{\"object_kind\":\"push\",\"event_name\":\"push\",\"before\":\"38dc4c9d22b0ff23c7620de60f42123ef4a9... (17699823 more bytes)"
 4) 1) (integer) 28
    2) (integer) 1534930953
    3) (integer) 11557
    4) 1) "lpush"
       2) "resque:gitlab:queue:system_hook_push"
       3) "{\"class\":\"SystemHookPushWorker\",\"args\":[{\"object_kind\":\"push\",\"event_name\":\"push\",\"before\":\"c43e57d1022d8f8c0b78a7ae8e71d3bc3e35... (12068348 more bytes)"
 5) 1) (integer) 27
    2) (integer) 1534927560
    3) (integer) 10406
    4)  1) "brpop"
        2) "resque:gitlab:queue:repository_check:repository_check_clear"
        3) "resque:gitlab:queue:cronjob:geo_scheduler_primary_per_shard_scheduler"
        4) "resque:gitlab:queue:gcp_cluster:cluster_wait_for_app_update"
        5) "resque:gitlab:queue:repository_check:repository_check_batch"
        6) "resque:gitlab:queue:cronjob:remove_unreferenced_lfs_objects"
        7) "resque:gitlab:queue:cronjob:ci_archive_traces_cron"
        8) "resque:gitlab:queue:github_importer:github_import_import_issue"
        9) "resque:gitlab:queue:storage_migrator"
       10) "resque:gitlab:queue:cronjob:remove_old_web_hook_logs"
       11) "resque:gitlab:queue:cronjob:geo_metrics_update"
       12) "resque:gitlab:queue:pages_domain_verification"
       13) "resque:gitlab:queue:todos_destroyer:todos_destroyer_group_private"
       14) "resque:gitlab:queue:cronjob:geo_file_download_dispatch"
       15) "resque:gitlab:queue:default"
       16) "resque:gitlab:queue:rebase"
       17) "resque:gitlab:queue:geo_file_download"
       18) "resque:gitlab:queue:create_gpg_signature"
       19) "resque:gitlab:queue:chat_notification"
       20) "resque:gitlab:queue:cronjob:ldap_sync"
       21) "resque:gitlab:queue:todos_destroyer:todos_destroyer_project_private"
       22) "resque:gitlab:queue:github_importer:github_import_import_note"
       23) "resque:gitlab:queue:github_importer:github_import_stage_import_base_data"
       24) "resque:gitlab:queue:create_github_webhook"
       25) "resque:gitlab:queue:repository_check:repository_check_single_repository"
       26) "resque:gitlab:queue:cronjob:stuck_import_jobs"
       27) "resque:gitlab:queue:cronjob:expire_build_artifacts"
       28) "resque:gitlab:queue:geo_project_sync"
       29) "resque:gitlab:queue:cronjob:prune_web_hook_logs"
       30) "resque:gitlab:queue:pipeline_background:ci_build_trace_chunk_flush"
       31) "resque:gitlab:queue:github_importer:github_import_stage_finish_import"
       32) "... (66 more arguments)"
 6) 1) (integer) 26
    2) (integer) 1534924592
    3) (integer) 34402
    4) 1) "lpush"
       2) "resque:gitlab:queue:system_hook_push"
       3) "{\"class\":\"SystemHookPushWorker\",\"args\":[{\"object_kind\":\"push\",\"event_name\":\"push\",\"before\":\"000000000000000000000000000000000000... (34644517 more bytes)"
 7) 1) (integer) 25
    2) (integer) 1534922957
    3) (integer) 23082
    4) 1) "lpush"
       2) "resque:gitlab:queue:system_hook_push"
       3) "{\"class\":\"SystemHookPushWorker\",\"args\":[{\"object_kind\":\"push\",\"event_name\":\"push\",\"before\":\"d4d587533cc987669cecd095cf2c34c484f0... (21725096 more bytes)"
 8) 1) (integer) 24
    2) (integer) 1534921446
    3) (integer) 18112
    4)  1) "brpop"
        2) "resque:gitlab:queue:github_importer:github_import_stage_import_issues_and_diff_notes"
        3) "resque:gitlab:queue:cronjob:ldap_sync"
        4) "resque:gitlab:queue:github_importer:github_import_refresh_import_jid"
        5) "resque:gitlab:queue:todos_destroyer:todos_destroyer_group_private"
        6) "resque:gitlab:queue:gcp_cluster:cluster_install_app"
        7) "resque:gitlab:queue:cronjob:pseudonymizer"
        8) "resque:gitlab:queue:irker"
        9) "resque:gitlab:queue:upload_checksum"
       10) "resque:gitlab:queue:cronjob:stuck_merge_jobs"
       11) "resque:gitlab:queue:github_importer:github_import_stage_import_base_data"
       12) "resque:gitlab:queue:gcp_cluster:cluster_wait_for_ingress_ip_address"
       13) "resque:gitlab:queue:todos_destroyer:todos_destroyer_project_private"
       14) "resque:gitlab:queue:github_importer:github_import_stage_finish_import"
       15) "resque:gitlab:queue:project_cache"
       16) "resque:gitlab:queue:gcp_cluster:cluster_wait_for_app_update"
       17) "resque:gitlab:queue:chat_notification"
       18) "resque:gitlab:queue:cronjob:expire_build_artifacts"
       19) "resque:gitlab:queue:cronjob:geo_migrated_local_files_clean_up"
       20) "resque:gitlab:queue:github_importer:github_import_stage_import_pull_requests"
       21) "resque:gitlab:queue:rebase"
       22) "resque:gitlab:queue:cronjob:remove_unreferenced_lfs_objects"
       23) "resque:gitlab:queue:mailers"
       24) "resque:gitlab:queue:cronjob:geo_repository_verification_secondary_shard"
       25) "resque:gitlab:queue:repository_check:repository_check_batch"
       26) "resque:gitlab:queue:cronjob:stuck_ci_jobs"
       27) "resque:gitlab:queue:pages_domain_verification"
       28) "resque:gitlab:queue:cronjob:geo_scheduler_per_shard_scheduler"
       29) "resque:gitlab:queue:geo_project_sync"
       30) "resque:gitlab:queue:default"
       31) "resque:gitlab:queue:github_importer:github_import_import_note"
       32) "... (66 more arguments)"
 9) 1) (integer) 23
    2) (integer) 1534920432
    3) (integer) 13170
    4) 1) "lpush"
       2) "resque:gitlab:queue:system_hook_push"
       3) "{\"class\":\"SystemHookPushWorker\",\"args\":[{\"object_kind\":\"push\",\"event_name\":\"push\",\"before\":\"278ae9b68cb4db008b32682727e9b8fbb13a... (13040850 more bytes)"
10) 1) (integer) 22
    2) (integer) 1534918981
    3) (integer) 12728
    4) 1) "lpush"
       2) "resque:gitlab:queue:system_hook_push"
       3) "{\"class\":\"SystemHookPushWorker\",\"args\":[{\"object_kind\":\"push\",\"event_name\":\"push\",\"before\":\"278ae9b68cb4db008b32682727e9b8fbb13a... (13041073 more bytes)"
    • Andrew Newdigate
      Andrew Newdigate @andrewn
      Owner

      @jarv @reprazent @skarbek @mrjkc and I had a call and came up with the following plan:

      1. @reprazent and @mrjkc will skip the "deploy to production" step of the deploy. It is exactly the same as the current RC and without a full staff around, and with the current instability, it's not worth the risk to do a full deploy just to increment a version number
      2. @smcgivern to review and give approval on change https://gitlab.com/gitlab-org/gitlab-ce/merge_requests/21337
      3. @reprazent to create a patch
      4. @skarbek to apply the patch and monitor Redis and the Sidekiq fleet for OOM errors
      5. The patch will mean that we send fewer 160MB payloads to Sidekiq, but we will still be sending them
      6. Hopefully this will mean less OOM errors in Sidekiq and less Redis failovers (without making them go away all together)
      7. If this doesn't reduce the Sidekiq OOM errors, we'll do a rolling upgrade of the realtime sidekiq fleet to scale them up vertically. @jarv will prepare the change for this.

      @ahmadsherif @alejandro please could you be on hand to assist @skarbek with his with patch deployment, in case he needs assistance.

      cc @glopezfernandez @dawsmith @marin @stanhu

      Edited by Andrew Newdigate
    • Andrew Newdigate
      Andrew Newdigate @andrewn
      Owner

      @jarv's Sidekiq capacity MR is https://gitlab.com/gitlab-com/gitlab-com-infrastructure/merge_requests/516

    • Sean McGivern
      Sean McGivern @smcgivern

      I've merged https://gitlab.com/gitlab-org/gitlab-ce/merge_requests/21337 now. The comments I had were minor and only applied to the specs.

    • Loading
    • Loading
    • Loading
    • Loading
    • Loading
    • Loading
    • Loading
    • Loading
    • Loading
    • Loading
    Please register or sign in to reply