Skip to content

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