Fix timeout problems on test webhooks [RUN ALL RSPEC] [RUN AS-IF-FOSS] (!52646) · Merge requests · GitLab.org / GitLab

Luke Duncalfe requested to merge 290116-test-webhook-optimisations into master Jan 27, 2021

What does this MR do?

The Issues, Merge Requests and Notes test webhooks were susceptible to timeouts due to the oldest records being selected to be in the test webhook payload #290116 (closed). The timeouts would happen for projects with large amounts of these records.

Indexes on these tables seem to favour sorting newest to oldest, the difference between selecting the oldest Issue, Merge Request, or Note vs the newest for gitlab-org/gitlab is ~ 25 seconds (or sometimes more) on #database-lab (which is slower than production, but indicative) vs ~10 milliseconds.

This MR changes the test webhooks for Issues, Merge Requests and Notes to return the most recent record for the test webhook payload, rather than the oldest. This is a change to the product behaviour that the ~"group::ecosystem" Product Manager has agreed to #290116 (comment 490278275).

Note, future MRs will change all other test webhooks to use the most recent data for the their payloads also, for consistency. The changes are behind a feature flag in order to roll this change out in separate MRs. The feature flag will only be removed when all test webhooks have been converted to use the newest data for their payloads, and the changes are considered stable.

Finders are now used for all scoping to make the scoping even safer.

Issue: #290116 (closed)

Query comparisons

Issues

Old issues query

SELECT "issues".* FROM "issues" WHERE "issues"."project_id" = 278964 ORDER BY "issues"."id" ASC LIMIT 1

Explain:

 Limit  (cost=0.56..244.90 rows=1 width=1270) (actual time=152399.344..152399.346 rows=1 loops=1)
   Buffers: shared hit=45092 read=181251 dirtied=120
   I/O Timings: read=151189.550
   ->  Index Scan using issues_pkey on public.issues  (cost=0.56..16212151.90 rows=66351 width=1270) (actual time=152399.342..152399.342 rows=1 loops=1)
         Filter: (issues.project_id = 278964)
         Rows Removed by Filter: 287323
         Buffers: shared hit=45092 read=181251 dirtied=120
         I/O Timings: read=151189.550

Summary:

Time: 2.540 min
  - planning: 0.303 ms
  - execution: 2.540 min
    - I/O read: 2.520 min
    - I/O write: N/A

Shared buffers:
  - hits: 45092 (~352.30 MiB) from the buffer pool
  - reads: 181251 (~1.40 GiB) from the OS file cache, including disk I/O
  - dirtied: 120 (~960.00 KiB)
  - writes: 0

New issues query

SELECT "issues".* FROM "issues" WHERE "issues"."project_id" = 278964 ORDER BY "issues"."created_at" DESC, "issues"."id" DESC LIMIT 1

Explain:

 Limit  (cost=0.56..1.83 rows=1 width=1270) (actual time=8.284..8.286 rows=1 loops=1)
   Buffers: shared read=5 dirtied=1
   I/O Timings: read=8.227
   ->  Index Scan using idx_issues_on_project_id_and_created_at_and_id_and_state_id on public.issues  (cost=0.56..84126.17 rows=66351 width=1270) (actual time=8.282..8.283 rows=1 loops=1)
         Index Cond: (issues.project_id = 278964)
         Buffers: shared read=5 dirtied=1
         I/O Timings: read=8.227

Summary:

Time: 8.612 ms
  - planning: 0.290 ms
  - execution: 8.322 ms
    - I/O read: 8.227 ms
    - I/O write: N/A

Shared buffers:
  - hits: 0 from the buffer pool
  - reads: 5 (~40.00 KiB) from the OS file cache, including disk I/O
  - dirtied: 1 (~8.00 KiB)
  - writes: 0

Merge requests

Old merge requests query

SELECT "merge_requests".* FROM "merge_requests" WHERE "merge_requests"."target_project_id" = 278964 ORDER BY "merge_requests"."id" ASC LIMIT 1

Explain:

 Limit  (cost=0.57..364.18 rows=1 width=750) (actual time=26664.557..26664.559 rows=1 loops=1)
   Buffers: shared hit=11992 read=29232 dirtied=190
   I/O Timings: read=26425.458
   ->  Index Scan using merge_requests_pkey on public.merge_requests  (cost=0.57..16543419.93 rows=45497 width=750) (actual time=26664.555..26664.556 rows=1 loops=1)
         Filter: (merge_requests.target_project_id = 278964)
         Rows Removed by Filter: 68455
         Buffers: shared hit=11992 read=29232 dirtied=190
         I/O Timings: read=26425.458

Summary:

Time: 26.665 s
  - planning: 0.374 ms
  - execution: 26.665 s
    - I/O read: 26.425 s
    - I/O write: N/A

Shared buffers:
  - hits: 11992 (~93.70 MiB) from the buffer pool
  - reads: 29232 (~228.40 MiB) from the OS file cache, including disk I/O
  - dirtied: 190 (~1.50 MiB)
  - writes: 0

New merge requests query

SELECT "merge_requests".* FROM "merge_requests" WHERE "merge_requests"."target_project_id" = 278964 ORDER BY "merge_requests"."created_at" DESC, "merge_requests"."id" DESC LIMIT 1

Explain:

 Limit  (cost=0.57..1.84 rows=1 width=750) (actual time=7.964..7.966 rows=1 loops=1)
   Buffers: shared hit=1 read=4
   I/O Timings: read=7.874
   ->  Index Scan using index_merge_requests_on_target_project_id_and_created_at_and_id on public.merge_requests  (cost=0.57..57974.42 rows=45497 width=750) (actual time=7.962..7.962 rows=1 loops=1)
         Index Cond: (merge_requests.target_project_id = 278964)
         Buffers: shared hit=1 read=4
         I/O Timings: read=7.874

Summary:

Time: 8.515 ms
  - planning: 0.476 ms
  - execution: 8.039 ms
    - I/O read: 7.874 ms
    - I/O write: N/A

Shared buffers:
  - hits: 1 (~8.00 KiB) from the buffer pool
  - reads: 4 (~32.00 KiB) from the OS file cache, including disk I/O
  - dirtied: 0
  - writes: 0

Notes

Old notes query

SELECT "notes".* FROM "notes" WHERE "notes"."project_id" = 278964 ORDER BY "notes"."id" ASC LIMIT 1

Explain:

 Limit  (cost=0.57..46.73 rows=1 width=2603) (actual time=226110.343..226110.345 rows=1 loops=1)
   Buffers: shared hit=160556 read=253550 dirtied=2205
   I/O Timings: read=223908.529
   ->  Index Scan using notes_pkey on public.notes  (cost=0.57..137067040.21 rows=2969627 width=2603) (actual time=226110.341..226110.341 rows=1 loops=1)
         Filter: (notes.project_id = 278964)
         Rows Removed by Filter: 1070275
         Buffers: shared hit=160556 read=253550 dirtied=2205
         I/O Timings: read=223908.529

Summary:

Time: 3.769 min
  - planning: 0.214 ms
  - execution: 3.769 min
    - I/O read: 3.732 min
    - I/O write: N/A

Shared buffers:
  - hits: 160556 (~1.20 GiB) from the buffer pool
  - reads: 253550 (~1.90 GiB) from the OS file cache, including disk I/O
  - dirtied: 2205 (~17.20 MiB)
  - writes: 0

New notes query

SELECT "notes".* FROM "notes" WHERE "notes"."project_id" = 278964 ORDER BY "notes"."id" DESC LIMIT 1

Explain:

 Limit  (cost=0.57..44.45 rows=1 width=3098) (actual time=144.806..144.808 rows=1 loops=1)
   Buffers: shared hit=2 read=87 dirtied=83
   I/O Timings: read=142.463
   ->  Index Scan using notes_pkey on public.notes  (cost=0.57..139560193.40 rows=3180337 width=3098) (actual time=144.804..144.805 rows=1 loops=1)
         Filter: (notes.project_id = 278964)
         Rows Removed by Filter: 78
         Buffers: shared hit=2 read=87 dirtied=83
         I/O Timings: read=142.463

Summary:

Time: 145.092 ms
  - planning: 0.232 ms
  - execution: 144.860 ms
    - I/O read: 142.463 ms
    - I/O write: N/A

Shared buffers:
  - hits: 2 (~16.00 KiB) from the buffer pool
  - reads: 87 (~696.00 KiB) from the OS file cache, including disk I/O
  - dirtied: 83 (~664.00 KiB)
  - writes: 0

Does this MR meet the acceptance criteria?

Conformity

Availability and Testing

Review and add/update tests for this feature/bug. Consider all test levels. See the Test Planning Process.
[-] Tested in all supported browsers
[-] Informed Infrastructure department of a default or new setting change, if applicable per definition of done

Related to #290116 (closed)

Edited Feb 04, 2021 by 🤖 GitLab Bot 🤖

Fix timeout problems on test webhooks [RUN ALL RSPEC] [RUN AS-IF-FOSS]

What does this MR do?

Query comparisons

Issues

Old issues query

New issues query

Merge requests

Old merge requests query

New merge requests query

Notes

Old notes query

New notes query

Does this MR meet the acceptance criteria?

Conformity

Availability and Testing

Merge request reports