Fix timeout problems on test webhooks [RUN ALL RSPEC] [RUN AS-IF-FOSS]
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
- [-] Changelog entry
- [-] Documentation (if required)
-
Code review guidelines -
Merge request performance guidelines -
Style guides - [-] Database guides
-
Separation of EE specific content
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)