Delete of OriginalFile is very slow.

[jamoore]

Deleting just the original file can take 20+ seconds. Something is very strange.

[jmoore]

The most likely cause is the large number of annotations on my system:

OMERO4.2__0=# select count(id) from annotation;
  count  
---------
 8476696
(1 row)

OMERO4.2__0=# select count(id) from annotation where file is null;
  count  
---------
 8473811
(1 row)

In Blitz-0.log, the times for deletes are:

omero.delete.FileAnnotation.8496604                      2.0           2           2         0.0           1
omero.delete.FileAnnotation.8496607                     10.0          10          10         0.0           1
omero.delete.FileAnnotation.8496616                      1.0           1           1         0.0           1
omero.delete.FileAnnotation.8496619                      4.0           4           4         0.0           1
omero.delete.FileAnnotation.8496622                      5.0           5           5         0.0           1
omero.delete.Image.24627                                 4.0           4           4         0.0           1
omero.delete.Image.24628                                 2.0           2           2         0.0           1
omero.delete.Image.24629                                 2.0           2           2         0.0           1
omero.delete.OriginalFile.21948                       1549.0        1549        1549         0.0           1
omero.delete.OriginalFile.21949                       1333.0        1333        1333         0.0           1
omero.delete.OriginalFile.21950                          1.0           1           1         0.0           1
omero.delete.OriginalFile.21951                        134.0         134         134         0.0           1
omero.delete.OriginalFile.21952                       1471.0        1471        1471         0.0           1
omero.delete.OriginalFile.21953                       1470.0        1470        1470         0.0           1
omero.delete.OriginalFile.21954                       1552.0        1552        1552         0.0           1
omero.delete.Plate.8632                                  3.0           3           3         0.0           1
omero.delete.Plate.8633                                  0.0           0           0         0.0           1
omero.delete.Plate.8634                                  1.0           1           1         0.0           1
omero.delete.PlateAcquisition.2508                       1.0           1           1         0.0           1
omero.delete.PlateAcquisitionAnnotationLink.1657         1.0           1           1         0.0           1
omero.delete.PlateAcquisitionAnnotationLink.1658         2.0           2           2         0.0           1
omero.delete.PlateAcquisitionAnnotationLink.1659         2.0           2           2         0.0           1
omero.delete.TagAnnotation.8496602                       2.0           2           2         0.0           1
omero.delete.TagAnnotation.8496605                       4.0           4           4         0.0           1
omero.delete.TagAnnotation.8496614                       2.0           2           2         0.0           1
omero.delete.TagAnnotation.8496617                       3.0           3           3         0.0           1
omero.delete.TagAnnotation.8496620                       2.0           2           2         0.0           1

and using EXPLAIN ANALYZE:

OMERO4.2__0=# explain analyze delete from annotation where file = 21964;
                                                 QUERY PLAN                                                 
------------------------------------------------------------------------------------------------------------
 Seq Scan on annotation  (cost=0.00..217857.89 rows=1 width=6) (actual time=0.073..1236.276 rows=1 loops=1)
   Filter: (file = 21964)
 Trigger for constraint fkannotationannotationlink_child_annotation: time=0.812 calls=1
 Trigger for constraint fkannotationannotationlink_parent_annotation: time=0.394 calls=1
 Trigger for constraint fkchannelannotationlink_child_annotation: time=0.626 calls=1
 Trigger for constraint fkdatasetannotationlink_child_annotation: time=0.619 calls=1
 Trigger for constraint fkexperimenterannotationlink_child_annotation: time=0.533 calls=1
 Trigger for constraint fkexperimentergroupannotationlink_child_annotation: time=0.607 calls=1
 Trigger for constraint fkimageannotationlink_child_annotation: time=0.932 calls=1
 Trigger for constraint fknamespaceannotationlink_child_annotation: time=0.519 calls=1
 Trigger for constraint fknodeannotationlink_child_annotation: time=0.435 calls=1
 Trigger for constraint fkoriginalfileannotationlink_child_annotation: time=0.465 calls=1
 Trigger for constraint fkpixelsannotationlink_child_annotation: time=0.521 calls=1
 Trigger for constraint fkplaneinfoannotationlink_child_annotation: time=0.579 calls=1
 Trigger for constraint fkplateacquisitionannotationlink_child_annotation: time=0.482 calls=1
 Trigger for constraint fkplateannotationlink_child_annotation: time=0.555 calls=1
 Trigger for constraint fkprojectannotationlink_child_annotation: time=0.485 calls=1
 Trigger for constraint fkreagentannotationlink_child_annotation: time=0.498 calls=1
 Trigger for constraint fkroiannotationlink_child_annotation: time=0.507 calls=1
 Trigger for constraint fkscreenannotationlink_child_annotation: time=0.459 calls=1
 Trigger for constraint fksessionannotationlink_child_annotation: time=0.516 calls=1
 Trigger for constraint fkwellannotationlink_child_annotation: time=0.476 calls=1
 Trigger for constraint fkwellsampleannotationlink_child_annotation: time=0.452 calls=1
 Total runtime: 1247.836 ms
(24 rows)

OMERO4.2__0=# explain analyze delete from originalfile where id = 21964;
                                                           QUERY PLAN                                                           
--------------------------------------------------------------------------------------------------------------------------------
 Index Scan using originalfile_pkey on originalfile  (cost=0.00..8.27 rows=1 width=6) (actual time=0.058..0.059 rows=1 loops=1)
   Index Cond: (id = 21964)
 Trigger for constraint fkfileannotation_file_originalfile: time=1299.557 calls=1
 Trigger for constraint fkjoboriginalfilelink_child_originalfile: time=1.081 calls=1
 Trigger for constraint fkoriginalfileannotationlink_parent_originalfile: time=0.260 calls=1
 Trigger for constraint fkpixelsoriginalfilemap_parent_originalfile: time=0.463 calls=1
 Trigger for constraint fkroi_source_originalfile: time=0.868 calls=1
 Total runtime: 1302.362 ms
(8 rows)

After creating an index on file:

create index annotation_file on annotation (file);

                                                         QUERY PLAN                                                         
----------------------------------------------------------------------------------------------------------------------------
 Index Scan using annotation_file on annotation  (cost=0.00..9.20 rows=1 width=6) (actual time=0.021..0.022 rows=1 loops=1)
   Index Cond: (file = 21963)
 Trigger for constraint fkannotationannotationlink_child_annotation: time=0.301 calls=1
 Trigger for constraint fkannotationannotationlink_parent_annotation: time=0.187 calls=1
 Trigger for constraint fkchannelannotationlink_child_annotation: time=0.158 calls=1
 Trigger for constraint fkdatasetannotationlink_child_annotation: time=0.218 calls=1
 Trigger for constraint fkexperimenterannotationlink_child_annotation: time=0.228 calls=1
 Trigger for constraint fkexperimentergroupannotationlink_child_annotation: time=0.261 calls=1
 Trigger for constraint fkimageannotationlink_child_annotation: time=0.850 calls=1
 Trigger for constraint fknamespaceannotationlink_child_annotation: time=0.429 calls=1
 Trigger for constraint fknodeannotationlink_child_annotation: time=0.147 calls=1
 Trigger for constraint fkoriginalfileannotationlink_child_annotation: time=0.166 calls=1
 Trigger for constraint fkpixelsannotationlink_child_annotation: time=0.173 calls=1
 Trigger for constraint fkplaneinfoannotationlink_child_annotation: time=0.139 calls=1
 Trigger for constraint fkplateacquisitionannotationlink_child_annotation: time=0.136 calls=1
 Trigger for constraint fkplateannotationlink_child_annotation: time=0.276 calls=1
 Trigger for constraint fkprojectannotationlink_child_annotation: time=0.179 calls=1
 Trigger for constraint fkreagentannotationlink_child_annotation: time=0.134 calls=1
 Trigger for constraint fkroiannotationlink_child_annotation: time=0.129 calls=1
 Trigger for constraint fkscreenannotationlink_child_annotation: time=0.174 calls=1
 Trigger for constraint fksessionannotationlink_child_annotation: time=0.159 calls=1
 Trigger for constraint fkwellannotationlink_child_annotation: time=0.163 calls=1
 Trigger for constraint fkwellsampleannotationlink_child_annotation: time=0.150 calls=1
 Total runtime: 4.844 ms
(24 rows)

OMERO4.2__0=# explain analyze delete from originalfile where id = 21963;
                                                           QUERY PLAN                                                           
--------------------------------------------------------------------------------------------------------------------------------
 Index Scan using originalfile_pkey on originalfile  (cost=0.00..8.27 rows=1 width=6) (actual time=0.021..0.022 rows=1 loops=1)
   Index Cond: (id = 21963)
 Trigger for constraint fkfileannotation_file_originalfile: time=0.072 calls=1
 Trigger for constraint fkjoboriginalfilelink_child_originalfile: time=0.460 calls=1
 Trigger for constraint fkoriginalfileannotationlink_parent_originalfile: time=0.054 calls=1
 Trigger for constraint fkpixelsoriginalfilemap_parent_originalfile: time=0.056 calls=1
 Trigger for constraint fkroi_source_originalfile: time=1.007 calls=1
 Total runtime: 1.723 ms
(8 rows)

[jmoore]

(In [8182]) Testing of slow original file delete (See #2956)

[jmoore]

Closing in favor of #2957.