Deleting jobsets is extremely slow

[grahamc]

Much of this slowdown is from interacting with builds and jobsetevalmembers tables.

Deleting a jobset is a multi-query event:

LOG:  execute <unnamed>: DELETE FROM jobsetevals WHERE ( jobset_id = $1 )
DETAIL:  parameters: $1 = '6'
LOG:  execute <unnamed>: DELETE FROM builds WHERE ( jobset_id = $1 )
DETAIL:  parameters: $1 = '6'
LOG:  execute <unnamed>: DELETE FROM jobsets WHERE ( ( name = $1 AND project = $2 ) )
DETAIL:  parameters: $1 = 'eououe', $2 = 'nthnth'

DELETE FROM builds WHERE ( jobset_id = $1 )

Starting with the builds query, I see we're able to delete about 2 rows per second:

hydra=> explain analyze DELETE FROM builds WHERE id IN (SELECT id FROM builds WHERE jobset_id = 23 FOR UPDATE SKIP LOCKED LIMIT 10);
                                                                                          QUERY PLAN                                                                                           
-----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
 Delete on builds  (cost=39.17..124.56 rows=10 width=34) (actual time=0.209..0.210 rows=0 loops=1)
   ->  Nested Loop  (cost=39.17..124.56 rows=10 width=34) (actual time=0.153..0.180 rows=10 loops=1)
         ->  HashAggregate  (cost=38.61..38.71 rows=10 width=32) (actual time=0.131..0.134 rows=10 loops=1)
               Group Key: "ANY_subquery".id
               ->  Subquery Scan on "ANY_subquery"  (cost=0.69..38.58 rows=10 width=32) (actual time=0.077..0.125 rows=10 loops=1)
                     ->  Limit  (cost=0.69..38.48 rows=10 width=10) (actual time=0.072..0.117 rows=10 loops=1)
                           ->  LockRows  (cost=0.69..75190.87 rows=19897 width=10) (actual time=0.071..0.115 rows=10 loops=1)
                                 ->  Index Scan using indexbuildsonjobsetidfinishedid on builds builds_1  (cost=0.69..74991.90 rows=19897 width=10) (actual time=0.066..0.103 rows=10 loops=1)
                                       Index Cond: (jobset_id = 23)
         ->  Index Scan using builds_pkey on builds  (cost=0.57..8.59 rows=1 width=10) (actual time=0.004..0.004 rows=1 loops=10)
               Index Cond: (id = "ANY_subquery".id)
 Planning Time: 0.316 ms
 Trigger for constraint aggregatemembers_aggregate_fkey on builds: time=0.227 calls=10
 Trigger for constraint aggregatemembers_member_fkey on builds: time=1738.112 calls=10
 Trigger for constraint buildinputs_dependency_fkey on builds: time=16.056 calls=10
 Trigger for constraint buildmetrics_build_fkey on builds: time=0.223 calls=10
 Trigger for constraint buildoutputs_build_fkey on builds: time=3.977 calls=10
 Trigger for constraint buildstepoutputs_build_fkey on builds: time=4.423 calls=10
 Trigger for constraint buildsteps_propagatedfrom_fkey on builds: time=0.617 calls=10
 Trigger for constraint fk1 on builds: time=1.569 calls=10
 Trigger for constraint fk1 on builds: time=1.182 calls=10
 Trigger for constraint fk1 on builds: time=7.721 calls=10
 Trigger for constraint jobsetevalinputs_dependency_fkey on builds: time=2637.088 calls=10
 Trigger for constraint jobsetevalmembers_build_fkey on builds: time=16.229 calls=10
 Trigger for constraint releasemembers_build_fkey on builds: time=0.394 calls=10
 Trigger buildsdeleted on builds: time=0.010 calls=1
 Trigger nrbuildsfinished on builds: time=0.491 calls=10
 Trigger for constraint buildstepoutputs_build_fkey1 on buildsteps: time=0.110 calls=10
 Execution Time: 4428.743 ms
(29 rows)

We can identify a couple hotspots:

 Trigger for constraint aggregatemembers_member_fkey on builds: time=1738.112 calls=10
 Trigger for constraint jobsetevalinputs_dependency_fkey on builds: time=2637.088 calls=10

jobsetevalinputs.dependency

Starting with Trigger for constraint jobsetevalinputs_dependency_fkey on builds: time=2637.088 calls=10 I noticed JobsetEvalInputs doesn't have an index on the dependency column, which is a foreign key involved in this delete:

hydra=> \dS+ JobsetEvalInputs;
                                Table "public.jobsetevalinputs"
   Column   |  Type   | Collation | Nullable | Default | Storage  | Stats target | Description 
------------+---------+-----------+----------+---------+----------+--------------+-------------
 eval       | integer |           | not null |         | plain    |              | 
 name       | text    |           | not null |         | extended |              | 
 altnr      | integer |           | not null |         | plain    |              | 
 type       | text    |           | not null |         | extended |              | 
 uri        | text    |           |          |         | extended |              | 
 revision   | text    |           |          |         | extended |              | 
 value      | text    |           |          |         | extended |              | 
 dependency | integer |           |          |         | plain    |              | 
 path       | text    |           |          |         | extended |              | 
 sha256hash | text    |           |          |         | extended |              | 
Indexes:
    "jobsetevalinputs_pkey" PRIMARY KEY, btree (eval, name, altnr)
Foreign-key constraints:
    "jobsetevalinputs_dependency_fkey" FOREIGN KEY (dependency) REFERENCES builds(id)
    "jobsetevalinputs_eval_fkey" FOREIGN KEY (eval) REFERENCES jobsetevals(id) ON DELETE CASCADE
Access method: heap

If we add an index on dependency via:

create index IndexJobsetEvalInputsDependency on JobsetEvalInputs(dependency);

our delete of 10 rows is reduced from 4,428ms down to 1,670ms and this specific step is reduced significantly:

- Trigger for constraint jobsetevalinputs_dependency_fkey on builds: time=2637.088 calls=10
+ Trigger for constraint jobsetevalinputs_dependency_fkey on builds: time=0.865 calls=10

AggregateConstituents.constituent

AggregateConstituents is the name of at able that used to be called AggregateMembers. We'll need to handle this potential name discrepancy in any migration we write. We should probably rename the old ones to the new name, also.

Given

Trigger for constraint aggregatemembers_member_fkey on builds: time=1621.509 calls=10

I saw again AggregateConstituents is a similar story: it doesn't have an index on the constituent field, which is again involved ni this delete via FK:

hydra=> \dS+ AggregateConstituents;
                             Table "public.aggregateconstituents"
   Column    |  Type   | Collation | Nullable | Default | Storage | Stats target | Description 
-------------+---------+-----------+----------+---------+---------+--------------+-------------
 aggregate   | integer |           | not null |         | plain   |              | 
 constituent | integer |           | not null |         | plain   |              | 
Indexes:
    "aggregatemembers_pkey" PRIMARY KEY, btree (aggregate, constituent)
Foreign-key constraints:
    "aggregatemembers_aggregate_fkey" FOREIGN KEY (aggregate) REFERENCES builds(id) ON DELETE CASCADE
    "aggregatemembers_member_fkey" FOREIGN KEY (constituent) REFERENCES builds(id) ON DELETE CASCADE
Access method: heap

By adding the following index on constintuents:

create index IndexAggregateConstituentsConstituent on AggregateConstituents(constituent);

the deletion time fell from 1,670ms down to 31.820ms and this specific step reduced significantly:

- Trigger for constraint aggregatemembers_member_fkey on builds: time=1621.509 calls=10
+ Trigger for constraint aggregatemembers_member_fkey on builds: time=0.286 calls=10

Deleting More Rows

This concluded the useful work I could do based on a deletion of 10 rows. I increased the limit to 10,000 and identified another hotspot:

hydra=> explain analyze DELETE FROM builds WHERE id IN (SELECT id FROM builds WHERE jobset_id = 23 FOR UPDATE SKIP LOCKED LIMIT 10000);
                                                                                            QUERY PLAN                                                                                             
---------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
 Delete on builds  (cost=37915.96..123609.40 rows=10000 width=34) (actual time=567.369..567.372 rows=0 loops=1)
   ->  Nested Loop  (cost=37915.96..123609.40 rows=10000 width=34) (actual time=508.922..548.402 rows=10000 loops=1)
         ->  HashAggregate  (cost=37915.40..38015.40 rows=10000 width=32) (actual time=508.899..511.262 rows=10000 loops=1)
               Group Key: "ANY_subquery".id
               ->  Subquery Scan on "ANY_subquery"  (cost=0.69..37890.40 rows=10000 width=32) (actual time=0.120..501.165 rows=10000 loops=1)
                     ->  Limit  (cost=0.69..37790.40 rows=10000 width=10) (actual time=0.116..495.914 rows=10000 loops=1)
                           ->  LockRows  (cost=0.69..75190.87 rows=19897 width=10) (actual time=0.115..494.368 rows=10000 loops=1)
                                 ->  Index Scan using indexbuildsonjobsetidfinishedid on builds builds_1  (cost=0.69..74991.90 rows=19897 width=10) (actual time=0.108..49.908 rows=10000 loops=1)
                                       Index Cond: (jobset_id = 23)
         ->  Index Scan using builds_pkey on builds  (cost=0.57..8.56 rows=1 width=10) (actual time=0.003..0.003 rows=1 loops=10000)
               Index Cond: (id = "ANY_subquery".id)
 Planning Time: 0.355 ms
 Trigger for constraint aggregatemembers_aggregate_fkey on builds: time=219.194 calls=10000
 Trigger for constraint aggregatemembers_member_fkey on builds: time=133.250 calls=10000
 Trigger for constraint buildinputs_dependency_fkey on builds: time=386.073 calls=10000
 Trigger for constraint buildmetrics_build_fkey on builds: time=132.720 calls=10000
 Trigger for constraint buildoutputs_build_fkey on builds: time=879.720 calls=10000
 Trigger for constraint buildstepoutputs_build_fkey on builds: time=1733.168 calls=10000
 Trigger for constraint buildsteps_propagatedfrom_fkey on builds: time=510.101 calls=10000
 Trigger for constraint fk1 on builds: time=445.347 calls=10000
 Trigger for constraint fk1 on builds: time=1289.362 calls=10000
 Trigger for constraint fk1 on builds: time=1896.513 calls=10000
 Trigger for constraint jobsetevalinputs_dependency_fkey on builds: time=572.176 calls=10000
 Trigger for constraint jobsetevalmembers_build_fkey on builds: time=1301.950 calls=10000
 Trigger for constraint releasemembers_build_fkey on builds: time=191.583 calls=10000
 Trigger buildsdeleted on builds: time=0.009 calls=1
 Trigger nrbuildsfinished on builds: time=1507.823 calls=10000
 Trigger for constraint buildstepoutputs_build_fkey1 on buildsteps: time=132.513 calls=16079
 Execution Time: 11920.733 ms

Specifically:

 Trigger for constraint buildstepoutputs_build_fkey on builds: time=1733.168 calls=10000

by creating a new index here as well:

create index IndexBuildStepOutputsBuild on BuildStepOutputs(build);

the 11920ms deletion was reduced to 7901.316ms:

hydra=> explain analyze DELETE FROM builds WHERE id IN (SELECT id FROM builds WHERE jobset_id = 23 FOR UPDATE SKIP LOCKED LIMIT 10000);
                                                                                              QUERY PLAN                                                                                               
-------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
 Delete on builds  (cost=37915.96..123609.40 rows=10000 width=34) (actual time=1368.393..1368.396 rows=0 loops=1)
   ->  Nested Loop  (cost=37915.96..123609.40 rows=10000 width=34) (actual time=1304.543..1349.133 rows=10000 loops=1)
         ->  HashAggregate  (cost=37915.40..38015.40 rows=10000 width=32) (actual time=1304.527..1306.677 rows=10000 loops=1)
               Group Key: "ANY_subquery".id
               ->  Subquery Scan on "ANY_subquery"  (cost=0.69..37890.40 rows=10000 width=32) (actual time=123.359..1298.275 rows=10000 loops=1)
                     ->  Limit  (cost=0.69..37790.40 rows=10000 width=10) (actual time=123.352..1293.906 rows=10000 loops=1)
                           ->  LockRows  (cost=0.69..75190.87 rows=19897 width=10) (actual time=123.351..1292.854 rows=10000 loops=1)
                                 ->  Index Scan using indexbuildsonjobsetidfinishedid on builds builds_1  (cost=0.69..74991.90 rows=19897 width=10) (actual time=123.325..1217.483 rows=10000 loops=1)
                                       Index Cond: (jobset_id = 23)
         ->  Index Scan using builds_pkey on builds  (cost=0.57..8.56 rows=1 width=10) (actual time=0.004..0.004 rows=1 loops=10000)
               Index Cond: (id = "ANY_subquery".id)
 Planning Time: 0.334 ms
 Trigger for constraint aggregatemembers_aggregate_fkey on builds: time=108.195 calls=10000
 Trigger for constraint aggregatemembers_member_fkey on builds: time=80.277 calls=10000
 Trigger for constraint buildinputs_dependency_fkey on builds: time=318.291 calls=10000
 Trigger for constraint buildmetrics_build_fkey on builds: time=82.654 calls=10000
 Trigger for constraint buildoutputs_build_fkey on builds: time=179.850 calls=10000
 Trigger for constraint buildstepoutputs_build_fkey on builds: time=1153.740 calls=10000
 Trigger for constraint buildsteps_propagatedfrom_fkey on builds: time=384.229 calls=10000
 Trigger for constraint fk1 on builds: time=201.240 calls=10000
 Trigger for constraint fk1 on builds: time=646.488 calls=10000
 Trigger for constraint fk1 on builds: time=1137.187 calls=10000
 Trigger for constraint jobsetevalinputs_dependency_fkey on builds: time=476.039 calls=10000
 Trigger for constraint jobsetevalmembers_build_fkey on builds: time=199.558 calls=10000
 Trigger for constraint releasemembers_build_fkey on builds: time=144.730 calls=10000
 Trigger buildsdeleted on builds: time=0.008 calls=1
 Trigger nrbuildsfinished on builds: time=1261.951 calls=10000
 Trigger for constraint buildstepoutputs_build_fkey1 on buildsteps: time=138.991 calls=15459
 Execution Time: 7901.316 ms

Impact on the system

Before I started, the database took a good bit of space on disk:

Apparent size:	728G	/hydra/scratch/haumea-hack/target
On disk size:	242G	/hydra/scratch/haumea-hack/target

I then ran create index IndexJobsetEvalInputsDependency on JobsetEvalInputs(dependency); and it took 1,231.977 ms and made no noticable impact on disk usage:

Apparent size:	728G	/hydra/scratch/haumea-hack/target
On disk size:	242G	/hydra/scratch/haumea-hack/target

Then I ran the second, create index IndexAggregateConstituentsConstituent on AggregateConstituents(constituent);taking 1,021.946 ms, and again no change in disk:

Apparent size:	728G	/hydra/scratch/haumea-hack/target
On disk size:	242G	/hydra/scratch/haumea-hack/target

Then the third, create index IndexBuildStepOutputsBuild on BuildStepOutputs(build);. This took 81,023.279 ms run and did have a noticable impact on disk:

Apparent size:	732G	/hydra/scratch/haumea-hack/target
On disk size:	243G	/hydra/scratch/haumea-hack/target

I am not sure if this third index is going to be used very many places, and it has the highest cost and a not significantly high payoff in the delete performance. I'm a bit mixed on it.

DELETE FROM jobsetevals WHERE ( jobset_id = $1 )

This one is trickier.

hydra=> explain analyze  DELETE FROM jobsetevals WHERE ( jobset_id = 355 );
                                                        QUERY PLAN                                                         
---------------------------------------------------------------------------------------------------------------------------
 Delete on jobsetevals  (cost=0.00..111974.30 rows=20712 width=6) (actual time=1829.712..1829.713 rows=0 loops=1)
   ->  Seq Scan on jobsetevals  (cost=0.00..111974.30 rows=20712 width=6) (actual time=0.171..1762.985 rows=20499 loops=1)
         Filter: (jobset_id = 355)
         Rows Removed by Filter: 1513821
 Planning Time: 0.064 ms
 Trigger for constraint jobsetevalinputs_eval_fkey: time=8651.245 calls=20499
 Trigger for constraint jobsetevalmembers_eval_fkey: time=1045154.007 calls=20499
 Execution Time: 1055654.250 ms
(8 rows)

both of these deletes triggered constraints are well indexed. The slowest one, jobsetevalmembers, has 1.5 billion rows and is just slow to operate on. Whats more is it takes a big lock to do it.

I would send a PR for the index creation I've already worked on, but I'm not sure it is significantly worthwhile without fixing this jobseteval query at the same time.

---

Proposal

Back in 2018 Eelco disabled the delete button for jobsets after it locked up the database for seven hours. I think this was the right choice at the time, but I think it is time to revisit.

To be able to make these deletes faster, we need to avoid touching the very largest tables (builds, jobsetevalmembers) in the actual web request. Practically speaking we'll never be able to atomically delete all of the rows in a reasonable amount of time.

I think a better approach here would be to nibble away the rows in separate transactions, like running a smaller delete in a loop:

DELETE FROM builds WHERE id IN (SELECT id FROM builds WHERE jobset_id = ? FOR UPDATE SKIP LOCKED LIMIT 10000);

and something similar for jobsetevalmembers. However even though this reduces the impact on the larger system, it will still take a significant amount of time to complete. We can't do it in a web request.

Therefor, I think we need to be using soft deletes on the project and jobset level. Specifically:

1. Add a deleted_at column to both of those tables. The web request will only mark those columns and move on and send a NOTIFY deleted_project/deleted_jobset IDNUMBER event through postgres.
2. Web requests listing and displaying projects and jobsets would filter out rows with a set deleted_at column. These records will not be returned in API requests, either.
3. hydra-notify's event loop can be used to execute the real deletion

Changes to hydra-notify:

1. On startup, list jobsets and projects marked for deletion
2. Send itself a NOTIFY event for each row identified
3. When it receives a NOTIFY event for a deletion, execute a single DELETE batch limited to 10,000 rows and re-NOTIFY itself.
4. Once all dependent records for the jobset or project are deleted, actually delete the corresponding row from the table.

Limiting delete batches to 10,000 means each batch will be a few seconds long, minimizing impact to other tasks hydra-notify is processing.

This work has been sponsored by Flox.

[aanderse]

@grahamc is there still motivation/sponsorship to proceed with this work?