Pages domain verification seems to be struggling to scale to GitLab.com levels

Three problems reported in the #production channel last night:

• Many instances of https://gitlab.com/gitlab-org/gitlab-ce/issues/43794
• Large numbers of enqueued PagesDomainVerificationWorker jobs
• "Sequential scans on pages_domains"

A fix for the first has been written and is going through review. It should help with the second by allowing a subset of domains to become verified, reducing the frequency with which they're scheduled from every 15 minutes to every 4 days or so.

The second two point to problems with the scheduler (probably) that might need some more work. It's currently very simple: https://gitlab.com/gitlab-org/gitlab-ee/blob/master/app/workers/pages_domain_verification_cron_worker.rb

/cc @northrup

Looking more at the seq scan issue. Here's the worker:

class PagesDomainVerificationCronWorker
  include ApplicationWorker
  include CronjobQueue

  def perform
    PagesDomain.needs_verification.find_each do |domain|
      PagesDomainVerificationWorker.perform_async(domain.id)
    end
  end
end

The needs_verification scope:

  VERIFICATION_THRESHOLD = 3.days.freeze

  scope :needs_verification, -> do
    verified_at = arel_table[:verified_at]
    enabled_until = arel_table[:enabled_until]
    threshold = Time.now + VERIFICATION_THRESHOLD

    where(verified_at.eq(nil).or(enabled_until.eq(nil).or(enabled_until.lt(threshold))))
  end

And the indexes:

  add_index "pages_domains", ["domain"], name: "index_pages_domains_on_domain", unique: true, using: :btree
  add_index "pages_domains", ["project_id", "enabled_until"], name: "index_pages_domains_on_project_id_and_enabled_until", using: :btree
  add_index "pages_domains", ["project_id"], name: "index_pages_domains_on_project_id", using: :btree
  add_index "pages_domains", ["verified_at", "enabled_until"], name: "index_pages_domains_on_verified_at_and_enabled_until", using: :btree
  add_index "pages_domains", ["verified_at"], name: "index_pages_domains_on_verified_at", using: :btree

The explain of needs_verification on GitLab.com:

EXPLAIN for: SELECT "pages_domains".* FROM "pages_domains" WHERE ("pages_domains"."verified_at" IS NULL OR ("pages_domains"."enabled_until" IS NULL OR "pages_domains"."enabled_until" < '2018-03-30 10:21:47.547930'))
                                                                 QUERY PLAN
--------------------------------------------------------------------------------------------------------------------------------------------
 Seq Scan on pages_domains  (cost=0.00..689.21 rows=14411 width=137)
   Filter: ((verified_at IS NULL) OR (enabled_until IS NULL) OR (enabled_until < '2018-03-30 10:21:47.54793+00'::timestamp with time zone))
(2 rows)

(find_each just calls this scope successively with id-based LIMIT and OFFSET parameters).

So.... why's it doing a seq scan? What's missing? Adding a bare enabled_until index doesn't change things.

/cc @_stark

For the large number of enqueued jobs, I think we need to introduce some form of backoff. Retrying every 15 minutes forever isn't a good solution. I suggest:

• Retry every fifteen minutes for the first 6 hours
• Go to hourly retries for the next 18
• Go to daily retries after that

We can reset this every time a state change happens (e.g., verified -> unverified, enabled -> disabled, or vice-versa).

Once verified, a domain is exempted from retries for four straight days, but it seems we have large numbers of domains that are disabled, and there's no incentive to remove them from the database at present.

So that could be an alternative - a cleanup worker that removes them if they're disabled for more than a week.

We currently have 11,759 domains in the needs_verification scope. 10,438 of them have enabled_until: nil, indicating that they're currently disabled...

changed the description

added ~2278654 typebug bugperformance labels

Since there's < 20,000 rows in the pages_domains table, PagesDomain.needs_verification is super-fast for me. Perhaps the planner simply disdains the indexes because of the size of the dataset?

The cleanup worker has a pleasing characteristic in that if someone tries to take control of a domain they don't own, this prevents them from keeping control of it (in the sense of it being associated to their gitlab project) indefinitely. Removal would be associated with an email and a log entry, as disablement currently is; we'd probably have to add a remove_at field to drive it.

WDYT @bikebilly?

@nick.thomas It's probably doing a sequence scan because WHERE x IS NULL can't use an index (unless you have a partial index on WHERE x IS NULL. enabled_until is at the end of a composite index, which also means PostgreSQL can't use it.

The verified_at part is something I don't see us being able to optimise because there are no other conditionals to AND on top of it. The enabled_until column is also hard to optimise. If we end up always using a WHERE on id for pagination purposes you could add an index like id WHERE verified_at IS NULL, but I'm not sure how beneficial this would be in this case.

In both cases a simple "hack" would be to use a date far in the past (e.g. 01-01-1900) instead of NULL values. This would allow us to re-use the regular indexes.

With the time hack you'd end up with something like this:

SELECT pages_domains.* 
FROM pages_domains 
WHERE pages_domains.verified_at = '1900-01-01' 
OR pages_domains.enabled_until < '2018-03-30 10:21:47.547930'

This produces:

Seq Scan on pages_domains  (cost=0.00..749.49 rows=1461 width=137) (actual time=0.015..6.459 rows=1307 loops=1)
  Filter: ((verified_at = '1900-01-01 00:00:00+00'::timestamp with time zone) OR (enabled_until < '2018-03-30 10:21:47.54793+00'::timestamp with time zone))
  Rows Removed by Filter: 14957
  Buffers: shared hit=486
Planning time: 0.133 ms
Execution time: 6.608 ms

This is still not ideal though. Using a UNION means we have this query:

SELECT pages_domains.* 
FROM pages_domains 
WHERE pages_domains.verified_at = '1900-01-01' 
UNION 
SELECT pages_domains.* 
FROM pages_domains 
WHERE pages_domains.enabled_until < '2018-03-30 10:21:47.547930'

This produces:

HashAggregate  (cost=761.02..775.63 rows=1461 width=216) (actual time=337.856..338.705 rows=1307 loops=1)
  Group Key: pages_domains.id, pages_domains.project_id, pages_domains.certificate, pages_domains.encrypted_key, pages_domains.encrypted_key_iv, pages_domains.encrypted_key_salt, pages_domains.domain, pages_domains.verified_at, pages_domains.verification_code, pages_domains.enabled_until
  Buffers: shared hit=8224 read=956
  ->  Append  (cost=0.29..724.49 rows=1461 width=216) (actual time=0.147..26.771 rows=1307 loops=1)
        Buffers: shared hit=486 read=2
        ->  Index Scan using index_pages_domains_on_verified_at_and_enabled_until on pages_domains  (cost=0.29..4.30 rows=1 width=137) (actual time=0.110..0.110 rows=0 loops=1)
              Index Cond: (verified_at = '1900-01-01 00:00:00+00'::timestamp with time zone)
              Buffers: shared read=2
        ->  Seq Scan on pages_domains pages_domains_1  (cost=0.00..705.58 rows=1460 width=137) (actual time=0.035..26.227 rows=1307 loops=1)
              Filter: (enabled_until < '2018-03-30 10:21:47.54793+00'::timestamp with time zone)
              Rows Removed by Filter: 14957
              Buffers: shared hit=486
Planning time: 1.669 ms
Execution time: 339.141 ms

Which is even worse.

So in short this may help:

1. Index enabled_until separately
2. Use some kind of sentinel value that is not NULL as this allows the use of regular indexes and removes the need for an additional OR

I don't think this is a case where UNION is actually helpful. Postgres is clever enough to use two different indexes on the same table and union the results using a BitmapOr plan node. (It's not clever enough to do a join for one side of the union but in this case all the information it needs is in indexes on this table).

I think there just isn't an index available that can handle the second half of that OR at all. Or if there is Postgres is deciding that too large a portion of the table is going to be read and it'll be quicker to do a sequential scan.

It's probably doing a sequence scan because WHERE x IS NULL can't use an index (unless you have a partial index on WHERE x IS NULL.

This is not true. Postgres can use indexes to satisfy IS NULL and will if it thinks it's a small enough portion of the table. It was true once (sometime back around 7.3 or so) but it definitely isn't any more:

stark=# explain select * from words where t is null;
┌─────────────────────────────────────────────────────────────────┐
│                           QUERY PLAN                            │
├─────────────────────────────────────────────────────────────────┤
│ Index Scan using wt on words  (cost=0.42..4.44 rows=1 width=14) │
│   Index Cond: (t IS NULL)                                       │
└─────────────────────────────────────────────────────────────────┘
(2 rows)

enabled_until is at the end of a composite index, which also means PostgreSQL can't use it.

I think this is the real problem.

It's also possible that there is an index it can use but due to the other problems with the code Postgres just thinks too large a portion of the table needs to be read and it will be quicker to read it in a sequential scan. If that's a common situation then planning to page through all the ids in the table may be a more scalable approach. In which case you don't need any indexes other than id.

@_stark adding a separate index just on enabled_until didn't cause postgresql to switch from seq scan, so I suspect it's just that the query planner is happy with the table size.

I'm all for not bothering to address it at present and focusing on the second (non-database-related) bullet point if you're happy with the current queries and plans?

The cleanup worker has a pleasing characteristic in that if someone tries to take control of a domain they don't own, this prevents them from keeping control of it (in the sense of it being associated to their gitlab project) indefinitely. Removal would be associated with an email and a log entry, as disablement currently is; we'd probably have to add a remove_at field to drive it.

@nick.thomas it sounds good to me, we can set this to a reasonable value and avoid "infinite" waits.

@bikebilly awesome, can this be scheduled via usual means? I've got a couple of ~Geo issues that really need my immediate attention. I'm not sure how much pain the current behaviour is causing GitLab.com at present - can you comment @northrup?

@nick.thomas sure, let's figure out which is the priority for that and then I'll schedule.

Do we need to expose the parameter somewhere in the UI to allow configuration, or can we just pick up a default value?

added devopsrelease [DEPRECATED] label

changed milestone to %Awaiting further demand

This item has been automatically determined to have 4 or fewer upvotes and is, for now, being marked as awaiting further demand. If you feel this is incorrect, please comment on the issue and I'll be happy to take a look.

Since this is a bug, I'm actually going to move this directly to the backlog for prioritization.

changed milestone to %Backlog

@jlenny one thing noticed during a GCP Migration production dry run is that the sidekiq jobs for verification can take up to 10 minutes to execute. This is much longer than I ever expected, and probably part of the problem.

@erushton any thoughts on why @nick.thomas' comment above may be the case?

Not a clue. That's much more in-depth that my understanding of how things work at the moment. @grzesiek can you help out here?

They're doing DNS queries, so the most likely explanation is that requests are being rate-limited by our DNS service, whatever that is.

I guess it's likely to change when we switch over to GCP.

Just checking the differences between the two environments - we mostly use 8.8.8.8 and 8.8.4.4 on both environments (there's one other IP that differs between the two) so there shouldn't be a change.

added [deprecated] Accepting merge requests label

added 1 deleted label and removed 1 deleted label

mentioned in issue #53807 (closed)

added priority2 severity3 labels

Cross-reference slack discussion: https://gitlab.slack.com/archives/CB3LSMEJV/p1549966982080400

I noticed this when looking into various performance/latency issues with Unicorn.

This cron job with no randomized duration or rate limiting causes spikes of 5-10k sidekiq requests in a 30 second window. This is mostly hitting the best effort queue, so it's not big problem, but it would make sense to spread this work out over time.

changed milestone to %11.10

@jlenny @bjk-gitlab I think https://gitlab.com/gitlab-org/gitlab-ce/issues/44696#note_65301303 (from ten months ago ) still make sense, particularly:

Once verified, a domain is exempted from retries for four straight days, but it seems we have large numbers of domains that are disabled, and there's no incentive to remove them from the database at present.

So that could be an alternative - a cleanup worker that removes them if they're disabled for more than a week.

We currently have 11,759 domains in the needs_verification scope. 10,438 of them have enabled_until: nil, indicating that they're currently disabled...

The numbers are still broadly accurate:

irb(main):001:0> PagesDomain.needs_verification.count
=> 11467
irb(main):002:0> PagesDomain.needs_verification.where(enabled_until: nil).count
=> 11443

Deleting custom domains that match the second query when they've not been updated for over a week should be quite simple to add to the existing worker, and will reduce the volume of verification attempts to somewhere much closer to zero.

We could remove them directly on GitLab.com if this is causing us capacity or other issues.

@darbyfrey what do you think? I'm not sure how big this is, or how urgent, but if needed to bring forward I'm totally open to the conversation.

This doesn't feel like a large amount of work. @jlenny what are the product/support implications in deleting custom domains that users have added? It seems like if a domain can't be verified for a week then the user doesn't care about it anymore, but I could be wrong.

We should deprecate it asap. I'm going to add to the 11.8 blog post, mentioning we'll be deprecating this in %11.10. Please ping me if I should not do that.

Notice added, feel free to offer suggestions if it needs to be made more clear: gitlab-com/www-gitlab-com!18225 (d5deeab4)

@jlenny good call, thanks for doing that. We should schedule this change for %11.10 then, correct?

@darbyfrey that's right (it already is.)

added Deliverable label

assigned to @vshushlin

removed [deprecated] Accepting merge requests label

mentioned in merge request !26178 (merged)

mentioned in merge request !26212 (merged)

mentioned in merge request !26227 (merged)

changed the description

added workflowin dev label

This issue has passed the feature freeze date and considered a missed-deliverable. Adding missed:11.10.

@vshushlin is this one still being worked on for %11.10?

Yes, I hope to get it done and merge under feature flag.

added missed-deliverable missed:11.10 labels

removed missed-deliverable missed:11.10 labels

This issue has passed the feature freeze date and considered a missed-deliverable. Adding missed:11.10.

added missed-deliverable missed:11.10 labels

This has missed %11.10 for sure, moving to %11.11.

fyi: this is mostly merged, we need to wait till release will get to production, check if domains are being marked for removal properly, enable feature flag, and then remove feature flag.

changed milestone to %11.11

This appears to have missed the %11.11 release, moving to %12.0 since it is still a priority. Please let me know if this is incorrect.

changed milestone to %12.0

added missed:11.11 label

created merge request !28408 (merged) to address this issue

mentioned in merge request !28408 (merged)

https://gitlab.com/gitlab-org/gitlab-ce/issues/44696#note_140483922

New graph with 30 sec resolution hasn't changed much(only 2 times better): https://thanos-query.ops.gitlab.net/graph?g0.range_input=1d&g0.end_input=2019-05-17%2013%3A14&g0.step_input=30&g0.expr=sum(increase(gitlab_transaction_duration_seconds_count%7Bcontroller%3D%22PagesDomainVerificationWorker%22%7D%5B30s%5D))&g0.tab=0&g1.range_input=1h&g1.expr=&g1.tab=1

But with 300 sec resolution it looks much better: https://thanos-query.ops.gitlab.net/graph?g0.range_input=1d&g0.end_input=2019-05-17%2013%3A14&g0.step_input=300&g0.stacked=0&g0.expr=sum(increase(gitlab_transaction_duration_seconds_count%7Bcontroller%3D%22PagesDomainVerificationWorker%22%7D%5B30s%5D))&g0.tab=0&g1.range_input=1h&g1.expr=&g1.tab=1

@bjk-gitlab can you look at this metrics and tell if situation become tolerable or it still causes problems?

I also found this exception in sentry: https://sentry.gitlab.net/gitlab/gitlabcom/issues/739867/, it shouldn't be related to changes from this issue, but looks super suspicious, I'll ask in slack and create/link issue.

https://gitlab.com/gitlab-org/gitlab-ce/merge_requests/28408 will close issue, feel free to reopen it if situation didn't become tolerable.

Exception in sentry is caused by not fully configured secondary GEO node. Slack thread: https://gitlab.slack.com/archives/C8HG8D9MY/p1558099937016600 GEO issue: https://gitlab.com/gitlab-com/gl-infra/infrastructure/issues/5468#note_172331663

closed via merge request !28408 (merged)

mentioned in commit f1456594