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:
1. Pagination headers in the API.
1. Counting forks of a project
Even with reasonable parameters that exclude the offset/page number, such as:
```json
{
"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:
```sql
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:
```sql
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`:
```sql
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:
```sql
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:
```sql
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 :
```sql
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:
```sql
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)
```
issue