Bug: 40 min. omero.delete.ids on nightshade

[jamoore]

From a dataset delete with thousands of images:

2010-10-21 12:53:46,482 INFO  [                 org.perf4j.TimingLogger] (3-thread-5) start[1287659502620] time[2523862] tag[omero.delete.ids]

[jmoore]

(In [8381]) Increasing stop watch logging for delete (See #3163)

[jmoore]

(In [8397]) Added hprof target for icegridnode deploy (See #3163)

[jmoore]

(In [8401]) Significant speed increase for omero.delete.ids (See #3163)

The use of java.util.HashSet for large numbers of Integers
is definitely prohibitive. Sorting all the lists first is
orders of magnitude faster.

[jmoore]

(In [8404]) Minor improvement on DeleteState.Tables.load (See #3163)

Testing the delete of a dataset with 15K images, server
hung at line 185 "continue LOOP" of load(). This may help
but probably won't fix the problem. It may be related to
memory exhaustion.

[jmoore]

(In [8410]) Moving to lower memory long[][]s for table storage (See #3163)

[jmoore]

(In [8411]) DeleteState.Tables.load() now executes less with fewer object creations (See #3163)

[jmoore]

(In [8412]) Refactoring DeleteState.Tables to use a single offset value (See #3163)

[jmoore]

(In [8414]) Fixing DeleteSpecUnitTest compile issue post-r8410 (See #3163)

[jmoore]

omero.delete.ids phase is now quite short:

2010-10-27 10:22:09,378 INFO  [                 org.perf4j.TimingLogger] (3-thread-1) start[1288171269918] time[59460] tag[omero.delete.ids.274319]

or one minute for 275K items.

On average, 10K delete steps take about a minute. A dataset with 15K+ images consists of about 270K delete steps each, or roughly 30 minutes delete time with the latest server:

omero@howe:~/OMERO-CURRENT$ bin/omero -s mike@localhost hql -q "select d.id, count(dil) from Dataset d join d.imageLinks dil group by d.id"
Previously logged in to localhost as mike
Password:
Created session 84332076-88a6-4398-9261-9827ca7ca547 (mike@localhost). Idle timeout: 10.0 min. Current group: Swedlow Lab
#  | Col1 | Col2
----+------+-------
...
20 | 600  | 15360
21 | 618  | 77
22 | 626  | 15360
23 | 648  | 1
24 | 655  | 10
(25 rows)
omero@howe:~/OMERO-CURRENT$ time bin/omero delete /Dataset:600
Using session 84332076-88a6-4398-9261-9827ca7ca547 (mike@localhost). Idle timeout: 10.0 min. Current group: Swedlow Lab
Deleting /Dataset 600... ok

real    32m29.207s
user    0m2.180s
sys     0m0.770s

omero@howe:~/OMERO-CURRENT$ tail -n 500000 var/log/Blitz-0.log | perl -ne 'print if /omero.delete.step.\d+0000\]/'
2010-10-27 10:41:47,382 INFO  [                 org.perf4j.TimingLogger] (3-thread-1) start[1288172507381] time[1] tag[omero.delete.step.180000]
2010-10-27 10:43:01,948 INFO  [                 org.perf4j.TimingLogger] (3-thread-1) start[1288172581947] time[1] tag[omero.delete.step.190000]
2010-10-27 10:44:19,389 INFO  [                 org.perf4j.TimingLogger] (3-thread-1) start[1288172659388] time[1] tag[omero.delete.step.200000]
2010-10-27 10:45:34,224 INFO  [                 org.perf4j.TimingLogger] (3-thread-1) start[1288172734223] time[1] tag[omero.delete.step.210000]
2010-10-27 10:46:48,890 INFO  [                 org.perf4j.TimingLogger] (3-thread-1) start[1288172808889] time[1] tag[omero.delete.step.220000]
2010-10-27 10:48:04,126 INFO  [                 org.perf4j.TimingLogger] (3-thread-1) start[1288172884125] time[1] tag[omero.delete.step.230000]
2010-10-27 10:49:19,016 INFO  [                 org.perf4j.TimingLogger] (3-thread-1) start[1288172959015] time[1] tag[omero.delete.step.240000]
2010-10-27 10:50:34,640 INFO  [                 org.perf4j.TimingLogger] (3-thread-1) start[1288173034639] time[1] tag[omero.delete.step.250000]
2010-10-27 10:51:49,835 INFO  [                 org.perf4j.TimingLogger] (3-thread-1) start[1288173109833] time[2] tag[omero.delete.step.260000]
2010-10-27 10:53:05,468 INFO  [                 org.perf4j.TimingLogger] (3-thread-1) start[1288173185467] time[1] tag[omero.delete.step.270000]

Closing this. Other optimizations may be necessary later.