Timeout for merge request event webhooks
Summary
Bronze customer reported 500 error
returns when testing a merge request event webhook:
https://gitlab.zendesk.com/agent/tickets/182193 (Internal)
After dicussion with @toupeira "the test hook uses the first merge request in the project, so this should be a very simple query but it's still running into timeouts sometimes. I tried a similar query in #database-lab and it took 24s there as well, so it looks like we could definitely optimize this:"
Database Lab Output & Sentry Log
Sentry log of postgres timeout when using merge request event for webhook: https://sentry.gitlab.net/gitlab/gitlabcom/issues/2382245/?query=correlation_id%3A01ERD0ZPRG6Y0TW9C7QBQN9FE8
Time: 24.470 s
- planning: 0.417 ms
- execution: 24.470 s
- I/O read: 24.080 s
- I/O write: 0.000 ms
Shared buffers:
- hits: 12109 (~94.60 MiB) from the buffer pool
- reads: 29861 (~233.30 MiB) from the OS file cache, including disk I/O
- dirtied: 154 (~1.20 MiB)
- writes: 0
Recommendations:
❗ Query processes too much data to return a relatively small number of rows. – Reduce data cardinality as early as possible during the execution, using one or several of the following techniques: new indexes, partitioning, query rewriting, denormalization. See the visualization of the plan to understand which plan nodes are the main bottlenecks. Show details❗ Specialized index needed – The index(es) currently used does not serve quite well for the needs of this query (notice Rows Removed by Filter: ..., meaning that the index fetched many non-target rows). Consider adding more specialized index(es). Show details
Limit (cost=0.56..415.70 rows=1 width=755)
-> Index Scan using merge_requests_pkey on merge_requests (cost=0.56..14738480.60 rows=35503 width=755)
Filter: (source_project_id = 278964)
Limit (cost=0.56..415.70 rows=1 width=755) (actual time=24469.627..24469.630 rows=1 loops=1)
Buffers: shared hit=12109 read=29861 dirtied=154
I/O Timings: read=24079.547
-> Index Scan using merge_requests_pkey on public.merge_requests (cost=0.56..14738480.60 rows=35503 width=755) (actual time=24469.623..24469.624 rows=1 loops=1)
Filter: (merge_requests.source_project_id = 278964)
Rows Removed by Filter: 69588
Buffers: shared hit=12109 read=29861 dirtied=154
I/O Timings: read=24079.547
[
{
"Plan": {
"Node Type": "Limit",
"Parallel Aware": false,
"Startup Cost": 0.56,
"Total Cost": 415.70,
"Plan Rows": 1,
"Plan Width": 755,
"Actual Startup Time": 24469.627,
"Actual Total Time": 24469.630,
"Actual Rows": 1,
"Actual Loops": 1,
"Output": ["id", "target_branch", "source_branch", "source_project_id", "author_id", "assignee_id", "title", "created_at", "updated_at", "milestone_id", "merge_status", "target_project_id", "iid", "description", "updated_by_id", "merge_error", "merge_params", "merge_when_pipeline_succeeds", "merge_user_id", "merge_commit_sha", "approvals_before_merge", "rebase_commit_sha", "in_progress_merge_commit_sha", "lock_version", "title_html", "description_html", "time_estimate", "squash", "cached_markdown_version", "last_edited_at", "last_edited_by_id", "head_pipeline_id", "merge_jid", "discussion_locked", "latest_merge_request_diff_id", "allow_maintainer_to_push", "state_id", "rebase_jid", "squash_commit_sha", "sprint_id", "merge_ref_sha"],
"Shared Hit Blocks": 12109,
"Shared Read Blocks": 29861,
"Shared Dirtied Blocks": 154,
"Shared Written Blocks": 0,
"Local Hit Blocks": 0,
"Local Read Blocks": 0,
"Local Dirtied Blocks": 0,
"Local Written Blocks": 0,
"Temp Read Blocks": 0,
"Temp Written Blocks": 0,
"I/O Read Time": 24079.547,
"I/O Write Time": 0.000,
"Plans": [
{
"Node Type": "Index Scan",
"Parent Relationship": "Outer",
"Parallel Aware": false,
"Scan Direction": "Forward",
"Index Name": "merge_requests_pkey",
"Relation Name": "merge_requests",
"Schema": "public",
"Alias": "merge_requests",
"Startup Cost": 0.56,
"Total Cost": 14738480.60,
"Plan Rows": 35503,
"Plan Width": 755,
"Actual Startup Time": 24469.623,
"Actual Total Time": 24469.624,
"Actual Rows": 1,
"Actual Loops": 1,
"Output": ["id", "target_branch", "source_branch", "source_project_id", "author_id", "assignee_id", "title", "created_at", "updated_at", "milestone_id", "merge_status", "target_project_id", "iid", "description", "updated_by_id", "merge_error", "merge_params", "merge_when_pipeline_succeeds", "merge_user_id", "merge_commit_sha", "approvals_before_merge", "rebase_commit_sha", "in_progress_merge_commit_sha", "lock_version", "title_html", "description_html", "time_estimate", "squash", "cached_markdown_version", "last_edited_at", "last_edited_by_id", "head_pipeline_id", "merge_jid", "discussion_locked", "latest_merge_request_diff_id", "allow_maintainer_to_push", "state_id", "rebase_jid", "squash_commit_sha", "sprint_id", "merge_ref_sha"],
"Filter": "(merge_requests.source_project_id = 278964)",
"Rows Removed by Filter": 69588,
"Shared Hit Blocks": 12109,
"Shared Read Blocks": 29861,
"Shared Dirtied Blocks": 154,
"Shared Written Blocks": 0,
"Local Hit Blocks": 0,
"Local Read Blocks": 0,
"Local Dirtied Blocks": 0,
"Local Written Blocks": 0,
"Temp Read Blocks": 0,
"Temp Written Blocks": 0,
"I/O Read Time": 24079.547,
"I/O Write Time": 0.000
}
]
},
"Planning Time": 0.417,
"Triggers": [
],
"Execution Time": 24469.696
}
]
Edited by Markus Koller