Slow database queries in /api/v4/projects

/api/v4/projects is the worst API endpoint we have at the moment as seen in https://gitlab.com/gitlab-com/gl-infra/infrastructure/issues/6441#note_153112998, and I suspect it's causing a lot of slowness on GitLab.com via HTTP queuing delays. It seems to have gotten worse in the last week:

The slowness is due to two factors:

Pagination headers in the API.
Counting forks of a project

Even with reasonable parameters that exclude the offset/page number, such as:

{
  "key": "order_by",
  "value": "last_activity_at"
},
{
  "key": "per_page",
  "value": "20"
},
{
  "key": "visibility",
  "value": "private"
}

We see this results in the following slow queries:

D, [2019-03-22T05:53:09.204384 #29307] DEBUG -- :    (14248.0ms)  SELECT COUNT(count_column) FROM (SELECT  1 AS count_column FROM "projects" WHERE (EXISTS (SELECT 1 FROM "project_authorizations" WHERE "project_authorizations"."user_id" = 2085863 AND (project_authorizations.project_id = projects.id)) OR projects.visibility_level IN (10,20)) AND "projects"."visibility_level" = 0 AND "projects"."pending_delete" = 'f' LIMIT 10001) subquery_for_count
D, [2019-03-22T05:53:09.208186 #29307] DEBUG -- :   ↳ lib/api/helpers/pagination.rb:206:in `paginate_with_limit_optimization'
D, [2019-03-22T05:53:09.208334 #29307] DEBUG -- :   ↳ lib/api/helpers/pagination.rb:194:in `paginate'
D, [2019-03-22T05:53:09.208400 #29307] DEBUG -- :   ↳ lib/api/helpers/pagination.rb:13:in `paginate'
D, [2019-03-22T05:53:09.208458 #29307] DEBUG -- :   ↳ lib/api/projects.rb:117:in `present_projects'
D, [2019-03-22T05:53:09.208504 #29307] DEBUG -- :   ↳ lib/api/projects.rb:169:in `block (2 levels) in <class:Projects>'
D, [2019-03-22T05:53:09.208552 #29307] DEBUG -- :   ↳ ee/lib/omni_auth/strategies/group_saml.rb:35:in `other_phase'
D, [2019-03-22T05:53:09.208608 #29307] DEBUG -- :   ↳ ee/lib/gitlab/jira/middleware.rb:17:in `call'
D, [2019-03-22T05:53:09.208658 #29307] DEBUG -- :   ↳ lib/gitlab/correlation_id.rb:15:in `use_id'
D, [2019-03-22T05:53:09.208705 #29307] DEBUG -- :   ↳ (irb):21:in `irb_binding'
D, [2019-03-22T05:53:22.630776 #29307] DEBUG -- :   Project Load (13408.7ms)  SELECT  "projects".* FROM "projects" WHERE (EXISTS (SELECT 1 FROM "project_authorizations" WHERE "project_authorizations"."user_id" = 2085863 AND (project_authorizations.project_id = projects.id)) OR projects.visibility_level IN (10,20)) AND "projects"."visibility_level" = 0 AND "projects"."pending_delete" = 'f' ORDER BY "projects"."last_activity_at" DESC, "projects"."id" DESC LIMIT 20 OFFSET 0
D, [2019-03-22T05:53:22.634617 #29307] DEBUG -- :   ↳ lib/api/entities.rb:292:in `forks_counting_projects'
D, [2019-03-22T05:53:22.634769 #29307] DEBUG -- :   ↳ lib/api/projects_relation_builder.rb:23:in `batch_forks_counting'
D, [2019-03-22T05:53:22.634830 #29307] DEBUG -- :   ↳ lib/api/projects_relation_builder.rb:31:in `execute_batch_counting'
D, [2019-03-22T05:53:22.634903 #29307] DEBUG -- :   ↳ lib/api/projects_relation_builder.rb:10:in `prepare_relation'
D, [2019-03-22T05:53:22.634952 #29307] DEBUG -- :   ↳ lib/api/projects.rb:128:in `present_projects'
D, [2019-03-22T05:53:22.634998 #29307] DEBUG -- :   ↳ lib/api/projects.rb:169:in `block (2 levels) in <class:Projects>'
D, [2019-03-22T05:53:22.635048 #29307] DEBUG -- :   ↳ ee/lib/omni_auth/strategies/group_saml.rb:35:in `other_phase'
D, [2019-03-22T05:53:22.635094 #29307] DEBUG -- :   ↳ ee/lib/gitlab/jira/middleware.rb:17:in `call'
D, [2019-03-22T05:53:22.635161 #29307] DEBUG -- :   ↳ lib/gitlab/correlation_id.rb:15:in `use_id'
D, [2019-03-22T05:53:22.635210 #29307] DEBUG -- :   ↳ (irb):21:in `irb_binding'

EXPLAIN:

gitlabhq_production=# explain analyze SELECT COUNT(count_column) FROM (SELECT  1 AS count_column FROM "projects" WHERE (EXISTS (SELECT 1 FROM "project_authorizations" WHERE "project_authorizations"."user_id" = 2085863 AND (project_authorizations.project_id = projects.id)) OR projects.visibility_level IN (10,20)) AND "projects"."visibility_level" = 0 AND "projects"."pending_delete" = 'f' LIMIT 10001) subquery_for_count;                                                                                                          QUERY PLAN
---------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
 Aggregate  (cost=68963.32..68963.33 rows=1 width=8) (actual time=13784.510..13784.511 rows=1 loops=1)
   ->  Limit  (cost=0.56..68838.31 rows=10001 width=4) (actual time=120.886..13784.419 rows=123 loops=1)
         ->  Index Scan using index_projects_on_visibility_level on projects  (cost=0.56..28071919.99 rows=4078391 width=4) (actual time=120.884..13784.335 rows=123 loops=1)
               Index Cond: (visibility_level = 0)
               Filter: ((NOT pending_delete) AND ((alternatives: SubPlan 1 or hashed SubPlan 2) OR (visibility_level = ANY ('{10,20}'::integer[]))))
               Rows Removed by Filter: 7182775
               SubPlan 1
                 ->  Index Only Scan using index_project_authorizations_on_user_id_project_id_access_level on project_authorizations  (cost=0.56..3.58 rows=1 width=0) (never executed)
                       Index Cond: ((user_id = 2085863) AND (project_id = projects.id))
                       Heap Fetches: 0
               SubPlan 2
                 ->  Index Only Scan using index_project_authorizations_on_user_id_project_id_access_level on project_authorizations project_authorizations_1  (cost=0.56..4.59 rows=59 width=4) (actual time=0.035..0.254 rows=124 loops=1)
                       Index Cond: (user_id = 2085863)
                       Heap Fetches: 32
 Planning time: 0.359 ms
 Execution time: 13784.594 ms

The second query is hampered by the extra ORDER BY:

gitlabhq_production=# explain analyze sELECT  "projects".* FROM "projects" WHERE (EXISTS (SELECT 1 FROM "project_authorizations" WHERE "project_authorizations"."user_id" = 2085863 AND (project_authorizations.project_id = projects.id)) OR projects.visibility_level IN (10,20)) AND "projects"."visibility_level" = 0 AND "projects"."pending_delete" = 'f' ORDER BY "projects"."last_activity_at" DESC, "projects"."id" DESC LIMIT 20 OFFSET 0
                                                                                                                 QUERY PLAN
---------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
 Limit  (cost=28180444.51..28180444.56 rows=20 width=822) (actual time=13701.334..13701.343 rows=20 loops=1)
   ->  Sort  (cost=28180444.51..28190640.49 rows=4078391 width=822) (actual time=13701.334..13701.339 rows=20 loops=1)
         Sort Key: projects.last_activity_at DESC, projects.id DESC
         Sort Method: top-N heapsort  Memory: 35kB
         ->  Index Scan using index_projects_on_visibility_level on projects  (cost=0.56..28071919.99 rows=4078391 width=822) (actual time=112.753..13700.827 rows=123 loops=1)
               Index Cond: (visibility_level = 0)
               Filter: ((NOT pending_delete) AND ((alternatives: SubPlan 1 or hashed SubPlan 2) OR (visibility_level = ANY ('{10,20}'::integer[]))))
               Rows Removed by Filter: 7182780
               SubPlan 1
                 ->  Index Only Scan using index_project_authorizations_on_user_id_project_id_access_level on project_authorizations  (cost=0.56..3.58 rows=1 width=0) (never executed)
                       Index Cond: ((user_id = 2085863) AND (project_id = projects.id))
                       Heap Fetches: 0
               SubPlan 2
                 ->  Index Only Scan using index_project_authorizations_on_user_id_project_id_access_level on project_authorizations project_authorizations_1  (cost=0.56..4.59 rows=59 width=4) (actual time=0.022..0.086 rows=124 loops=1)
                       Index Cond: (user_id = 2085863)
                       Heap Fetches: 32
 Planning time: 0.496 ms
 Execution time: 13701.419 ms
(18 rows)

I also noticed that @rostrander's admin account was also generating slow queries, so I profiled an admin account with just the default parameters:

http://profiler.gitlap.com/20190322/9c9cec9d-b828-43ba-ade2-eefaf016e45d.txt.gz

You can see these two queries being slow:

D, [2019-03-22T04:02:23.774143 #7634] DEBUG -- :   Project Load (13170.8ms)  SELECT  "projects".* FROM "projects" WHERE (EXISTS (SELECT 1 FROM "project_authorizations" WHERE "project_authorizations"."user_id" = 615747 AND (project_authorizations.project_id = projects.id)) OR projects.visibility_level IN (0,10,20)) AND "projects"."pending_delete" = 'f' ORDER BY "projects"."created_at" DESC, "projects"."id" DESC LIMIT 21 OFFSET 0
D, [2019-03-22T04:02:23.776331 #7634] DEBUG -- :   ↳ lib/api/helpers/pagination.rb:225:in `add_pagination_headers'
D, [2019-03-22T04:02:23.776486 #7634] DEBUG -- :   ↳ lib/api/helpers/pagination.rb:195:in `block in paginate'
D, [2019-03-22T04:02:23.776556 #7634] DEBUG -- :   ↳ lib/api/helpers/pagination.rb:194:in `tap'
D, [2019-03-22T04:02:23.776654 #7634] DEBUG -- :   ↳ lib/api/helpers/pagination.rb:194:in `paginate'
D, [2019-03-22T04:02:23.776719 #7634] DEBUG -- :   ↳ lib/api/helpers/pagination.rb:13:in `paginate'
D, [2019-03-22T04:02:23.776780 #7634] DEBUG -- :   ↳ lib/api/projects.rb:117:in `present_projects'
D, [2019-03-22T04:02:23.776855 #7634] DEBUG -- :   ↳ lib/api/projects.rb:169:in `block (2 levels) in <class:Projects>'

The following query looks identical, except it originates from counting forks for a project:

D, [2019-03-22T04:02:36.539473 #7634] DEBUG -- :   Project Load (12679.7ms)  SELECT  "projects".* FROM "projects" WHERE (EXISTS (SELECT 1 FROM "project_authorizations" WHERE "project_authorizations"."user_id" = 615747 AND (project_authorizations.project_id = projects.id)) OR projects.visibility_level IN (0,10,20)) AND "projects"."pending_delete" = 'f' ORDER BY "projects"."created_at" DESC, "projects"."id" DESC LIMIT 21 OFFSET 0
D, [2019-03-22T04:02:36.541694 #7634] DEBUG -- :   ↳ lib/api/entities.rb:292:in `forks_counting_projects'
D, [2019-03-22T04:02:36.541843 #7634] DEBUG -- :   ↳ lib/api/projects_relation_builder.rb:23:in `batch_forks_counting'
D, [2019-03-22T04:02:36.541920 #7634] DEBUG -- :   ↳ lib/api/projects_relation_builder.rb:31:in `execute_batch_counting'
D, [2019-03-22T04:02:36.541984 #7634] DEBUG -- :   ↳ lib/api/projects_relation_builder.rb:10:in `prepare_relation'
D, [2019-03-22T04:02:36.542051 #7634] DEBUG -- :   ↳ lib/api/projects.rb:128:in `present_projects'
D, [2019-03-22T04:02:36.542131 #7634] DEBUG -- :   ↳ lib/api/projects.rb:169:in `block (2 levels) in <class:Projects>'
D, [2019-03-22T04:02:36.542196 #7634] DEBUG -- :   ↳ ee/lib/omni_auth/strategies/group_saml.rb:35:in `other_phase'
D, [2019-03-22T04:02:36.542449 #7634] DEBUG -- :   ↳ ee/lib/gitlab/jira/middleware.rb:17:in `call'
D, [2019-03-22T04:02:36.542599 #7634] DEBUG -- :   ↳ lib/gitlab/correlation_id.rb:15:in `use_id'

In sum, that's 25 seconds of just counting!

The EXPLAIN output for this query shows a sequential scan :

gitlabhq_production=# explain analyze SELECT  "projects".* FROM "projects" WHERE (EXISTS (SELECT 1 FROM "project_authorizations" WHERE "project_authorizations"."user_id" = 615747 AND (project_authorizations.project_id = projects.id)) OR projects.visibility_level IN (0,10,20)) AND "projects"."pending_delete" = 'f' ORDER BY "projects"."created_at" DESC, "projects"."id" DESC LIMIT 21 OFFSET 0;
                                                                                                                 QUERY PLAN
--------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
 Limit  (cost=31493454.22..31493454.27 rows=21 width=833) (actual time=13199.291..13199.302 rows=21 loops=1)
   ->  Sort  (cost=31493454.22..31514226.93 rows=8309082 width=833) (actual time=13199.291..13199.297 rows=21 loops=1)
         Sort Key: projects.created_at DESC, projects.id DESC
         Sort Method: top-N heapsort  Memory: 32kB
         ->  Seq Scan on projects  (cost=0.00..31269428.18 rows=8309082 width=833) (actual time=0.044..7725.662 rows=8309509 loops=1)
               Filter: ((NOT pending_delete) AND ((alternatives: SubPlan 1 or hashed SubPlan 2) OR (visibility_level = ANY ('{0,10,20}'::integer[]))))
               Rows Removed by Filter: 289
               SubPlan 1
                 ->  Index Only Scan using index_project_authorizations_on_user_id_project_id_access_level on project_authorizations  (cost=0.56..3.58 rows=1 width=0) (never executed)
                       Index Cond: ((user_id = 615747) AND (project_id = projects.id))
                       Heap Fetches: 0
               SubPlan 2
                 ->  Index Only Scan using index_project_authorizations_on_user_id_project_id_access_level on project_authorizations project_authorizations_1  (cost=0.56..4.59 rows=59 width=4) (actual time=0.020..0.027 rows=13 loops=1)
                       Index Cond: (user_id = 615747)
                       Heap Fetches: 0
 Planning time: 0.407 ms
 Execution time: 13199.387 ms
(17 rows)

In both cases, if we remove the ORDER BY projects.created_at, things are much faster:

gitlabhq_production=# explain analyze SELECT  "projects".* FROM "projects" WHERE (EXISTS (SELECT 1 FROM "project_authorizations" WHERE "project_authorizations"."user_id" = 615747 AND (project_authorizations.project_id = projects.id)) OR projects.visibility_level IN (0,10,20)) AND "projects"."pending_delete" = 'f' ORDER BY  "projects"."id" DESC LIMIT 21 OFFSET 0;
                                                                                                              QUERY PLAN
--------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
 Limit  (cost=0.43..77.73 rows=21 width=833) (actual time=0.047..0.096 rows=21 loops=1)
   ->  Index Scan using projects_pkey on projects  (cost=0.43..30584851.96 rows=8309130 width=833) (actual time=0.046..0.093 rows=21 loops=1)
         Filter: ((NOT pending_delete) AND ((alternatives: SubPlan 1 or hashed SubPlan 2) OR (visibility_level = ANY ('{0,10,20}'::integer[]))))
         SubPlan 1
           ->  Index Only Scan using index_project_authorizations_on_user_id_project_id_access_level on project_authorizations  (cost=0.56..3.58 rows=1 width=0) (never executed)
                 Index Cond: ((user_id = 615747) AND (project_id = projects.id))
                 Heap Fetches: 0
         SubPlan 2
           ->  Index Only Scan using index_project_authorizations_on_user_id_project_id_access_level on project_authorizations project_authorizations_1  (cost=0.56..4.59 rows=59 width=4) (actual time=0.017..0.023 rows=13 loops=1)
                 Index Cond: (user_id = 615747)
                 Heap Fetches: 0
 Planning time: 0.434 ms
 Execution time: 0.185 ms
(13 rows)

Edited Mar 22, 2019 by Stan Hu