Web hook edit page timeouts if associated web hook logs are very large
Request fails with a 500 error message.
The logs show SQL timeout PG::QueryCanceled: ERROR: canceling statement due to statement timeout
Backtrace:
lib/gitlab/database/load_balancing/connection_proxy.rb:54:in `select_all'
app/views/shared/hook_logs/_recent_deliveries_table.html.haml:26
... # irrelevant: elided
lib/gitlab/middleware/release_env.rb:13:in `call'
Logs in kibana: https://log.gprd.gitlab.net/goto/3b375a70-94a9-11ec-a649-b7cbb8e4f62e
The query is:
-- application:web,correlation_id:01FWKAG3CQNE8EF4JVDKDPYY5N,endpoint_id:Projects::HooksController#edit,db_config_name:main_replica
SELECT COUNT(*) FROM "web_hook_logs" WHERE "web_hook_logs"."web_hook_id" = ? AND (created_at >= ?)
I think we might need to review indices on the webhooks logs table, since we can see from the query plans below that there is no index on web_hook_logs.created_at
.
Query plan:
Aggregate (cost=1264.76..1264.77 rows=1 width=8) (actual time=2.914..2.916 rows=1 loops=1)
Buffers: shared hit=12 read=4
I/O Timings: read=2.812 write=0.000
-> Append (cost=0.57..1263.83 rows=371 width=0) (actual time=2.909..2.910 rows=0 loops=1)
Buffers: shared hit=12 read=4
I/O Timings: read=2.812 write=0.000
-> Index Scan using web_hook_logs_202202_web_hook_id_idx on gitlab_partitions_dynamic.web_hook_logs_202202 (cost=0.57..1242.99 rows=365 width=0) (actual time=2.845..2.846 rows=0 loops=1)
Index Cond: (web_hook_logs_202202.web_hook_id = 12345)
Filter: (web_hook_logs_202202.created_at >= '2022-02-14 00:00:00'::timestamp without time zone)
Rows Removed by Filter: 0
Buffers: shared read=4
I/O Timings: read=2.812 write=0.000
-> Index Scan using web_hook_logs_202203_web_hook_id_idx on gitlab_partitions_dynamic.web_hook_logs_202203 (cost=0.14..3.17 rows=1 width=0) (actual time=0.018..0.018 rows=0 loops=1)
Index Cond: (web_hook_logs_202203.web_hook_id = 12345)
Filter: (web_hook_logs_202203.created_at >= '2022-02-14 00:00:00'::timestamp without time zone)
Rows Removed by Filter: 0
Buffers: shared hit=2
I/O Timings: read=0.000 write=0.000
-> Index Scan using web_hook_logs_202204_web_hook_id_idx on gitlab_partitions_dynamic.web_hook_logs_202204 (cost=0.14..3.17 rows=1 width=0) (actual time=0.007..0.007 rows=0 loops=1)
Index Cond: (web_hook_logs_202204.web_hook_id = 12345)
Filter: (web_hook_logs_202204.created_at >= '2022-02-14 00:00:00'::timestamp without time zone)
Rows Removed by Filter: 0
Buffers: shared hit=2
I/O Timings: read=0.000 write=0.000
-> Index Scan using web_hook_logs_202205_web_hook_id_idx on gitlab_partitions_dynamic.web_hook_logs_202205 (cost=0.14..3.17 rows=1 width=0) (actual time=0.013..0.013 rows=0 loops=1)
Index Cond: (web_hook_logs_202205.web_hook_id = 12345)
Filter: (web_hook_logs_202205.created_at >= '2022-02-14 00:00:00'::timestamp without time zone)
Rows Removed by Filter: 0
Buffers: shared hit=2
I/O Timings: read=0.000 write=0.000
-> Index Scan using web_hook_logs_202206_web_hook_id_idx on gitlab_partitions_dynamic.web_hook_logs_202206 (cost=0.14..3.17 rows=1 width=0) (actual time=0.007..0.007 rows=0 loops=1)
Index Cond: (web_hook_logs_202206.web_hook_id = 12345)
Filter: (web_hook_logs_202206.created_at >= '2022-02-14 00:00:00'::timestamp without time zone)
Rows Removed by Filter: 0
Buffers: shared hit=2
I/O Timings: read=0.000 write=0.000
-> Index Scan using web_hook_logs_202207_web_hook_id_idx on gitlab_partitions_dynamic.web_hook_logs_202207 (cost=0.14..3.17 rows=1 width=0) (actual time=0.008..0.008 rows=0 loops=1)
Index Cond: (web_hook_logs_202207.web_hook_id = 12345)
Filter: (web_hook_logs_202207.created_at >= '2022-02-14 00:00:00'::timestamp without time zone)
Rows Removed by Filter: 0
Buffers: shared hit=2
I/O Timings: read=0.000 write=0.000
-> Index Scan using web_hook_logs_202208_web_hook_id_idx on gitlab_partitions_dynamic.web_hook_logs_202208 (cost=0.14..3.17 rows=1 width=0) (actual time=0.007..0.007 rows=0 loops=1)
Index Cond: (web_hook_logs_202208.web_hook_id = 12345)
Filter: (web_hook_logs_202208.created_at >= '2022-02-14 00:00:00'::timestamp without time zone)
Rows Removed by Filter: 0
Buffers: shared hit=2
I/O Timings: read=0.000 write=0.000
/cc @arturoherrero