Warning: Can't synchronize with repository "(default)" (/home/git/ome.git does not appear to be a Git repository.). Look in the Trac log for more information.
Notice: In order to edit this ticket you need to be either: a Product Owner, The owner or the reporter of the ticket, or, in case of a Task not yet assigned, a team_member"

Task #2998 (new)

Opened 14 years ago

Last modified 14 years ago

IMetadata.count & load SpecifiedAnnotations is quite slow with 8 million annotations

Reported by: jamoore Owned by:
Priority: major Milestone: Unscheduled
Component: Performance Version: n.a.
Keywords: n.a. Cc: jburel
Resources: n.a. Referenced By: n.a.
References: n.a. Remaining Time: n.a.
Sprint: n.a.

Description

See logs below

Change History (4)

comment:1 Changed 14 years ago by jmoore 

2010-10-06 09:54:47,916 INFO  [        ome.services.util.ServiceHandler] (l.Server-5)  Meth:	interface ome.api.IMetadata.loadSpecifiedAnnotations
2010-10-06 09:54:47,917 INFO  [        ome.services.util.ServiceHandler] (l.Server-5)  Args:	[class ome.model.annotations.FileAnnotation, (openmicroscopy.org/omero/editor/protocol), (), ome.parameters.Parameters@2f71033d]
2010-10-06 09:54:47,918 INFO  [         ome.security.basic.EventHandler] (l.Server-5)  Auth:	user=23053,group=18703,event=null(User),sess=93f90426-3d92-443c-9902-eb016c63618b
2010-10-06 09:54:47,919 DEBUG [                       org.hibernate.SQL] (l.Server-5) select annotation0_.id as id13_0_, event1_.id as id117_1_, experiment2_.id as id114_2_, annotation0_.description as descript3_13_0_, annotation0_.creation_id as creation13_13_0_, annotation0_.external_id as external14_13_0_, annotation0_.group_id as group15_13_0_, annotation0_.owner_id as owner16_13_0_, annotation0_.permissions as permissi4_13_0_, annotation0_.update_id as update17_13_0_, annotation0_.ns as ns13_0_, annotation0_.version as version13_0_, annotation0_.timeValue as timeValue13_0_, annotation0_.textValue as textValue13_0_, annotation0_.boolValue as boolValue13_0_, annotation0_.termValue as termValue13_0_, annotation0_.file as file13_0_, annotation0_.longValue as longValue13_0_, annotation0_.doubleValue as doubleV12_13_0_, annotation0_.discriminator as discrimi1_13_0_, event1_.containingEvent as containi5_117_1_, event1_.external_id as external6_117_1_, event1_.permissions as permissi2_117_1_, event1_.experimenter as experime7_117_1_, event1_.experimenterGroup as experime8_117_1_, event1_.session as session117_1_, event1_.status as status117_1_, event1_.time as time117_1_, event1_.type as type117_1_, experiment2_.external_id as external10_114_2_, experiment2_.permissions as permissi2_114_2_, experiment2_.email as email114_2_, experiment2_.firstName as firstName114_2_, experiment2_.institution as institut5_114_2_, experiment2_.lastName as lastName114_2_, experiment2_.middleName as middleName114_2_, experiment2_.omeName as omeName114_2_, experiment2_.version as version114_2_
 from annotation annotation0_ left outer join event event1_ on annotation0_.creation_id=event1_.id left outer join experimenter experiment2_ on annotation0_.owner_id=experiment2_.id
 where (

  ( annotation0_.group_id = ? AND 
     ( ? OR 
       ? OR 
       annotation0_.owner_id = ?
     )
  ) OR
  annotation0_.group_id = 1 OR 
 ?
) and (annotation0_.id in (select fileannota3_.id
 from annotation fileannota3_
 where (

  ( fileannota3_.group_id = ? AND 
     ( ? OR 
       ? OR 
       fileannota3_.owner_id = ?
     )
  ) OR
  fileannota3_.group_id = 1 OR 
 ?
)
 and fileannota3_.discriminator='/type/OriginalFile/')) and annotation0_.owner_id=? and (annotation0_.ns is not null) and (annotation0_.ns in (?)) limit ?
2010-10-06 09:54:59,012 DEBUG [                       org.hibernate.SQL] (l.Server-5) select originalfi0_.id as id79_, originalfi0_.atime as atime79_, originalfi0_.ctime as ctime79_, originalfi0_.creation_id as creation12_79_, originalfi0_.external_id as external13_79_, originalfi0_.group_id as group14_79_, originalfi0_.owner_id as owner15_79_, originalfi0_.permissions as permissi4_79_, originalfi0_.update_id as update16_79_, originalfi0_.mimetype as mimetype79_, originalfi0_.mtime as mtime79_, originalfi0_.name as name79_, originalfi0_.path as path79_, originalfi0_.sha1 as sha9_79_, originalfi0_.size as size79_, originalfi0_.version as version79_
 from originalfile originalfi0_
 where (

  ( originalfi0_.group_id = ? AND 
     ( ? OR 
       ? OR 
       originalfi0_.owner_id = ?
     )
  ) OR
  originalfi0_.group_id = 1 OR 
 ?
) and originalfi0_.id=? limit ?
2010-10-06 09:54:59,014 INFO  [                 org.perf4j.TimingLogger] (l.Server-5) start[1286351687917] time[11097] tag[omero.call.success.ome.logic.MetadataImpl.loadSpecifiedAnnotations]
2010-10-06 09:54:59,014 INFO  [        ome.services.util.ServiceHandler] (l.Server-5)  Rslt:	(ome.model.annotations.FileAnnotation:Id_8497966)
2010-10-06 09:54:59,015 WARN  [        ome.services.util.ServiceHandler] (l.Server-5) Method interface ome.api.IMetadata.loadSpecifiedAnnotations invocation took 11097

2010-10-06 09:54:59,017 INFO  [        ome.services.util.ServiceHandler] (l.Server-9)  Meth:	interface ome.api.IMetadata.loadSpecifiedAnnotations
2010-10-06 09:54:59,018 INFO  [        ome.services.util.ServiceHandler] (l.Server-9)  Args:	[class ome.model.annotations.FileAnnotation, (openmicroscopy.org/omero/editor/experiment), (), ome.parameters.Parameters@771f6032]
2010-10-06 09:54:59,018 INFO  [         ome.security.basic.EventHandler] (l.Server-9)  Auth:	user=23053,group=18703,event=null(User),sess=93f90426-3d92-443c-9902-eb016c63618b
2010-10-06 09:54:59,019 DEBUG [                       org.hibernate.SQL] (l.Server-9) select annotation0_.id as id13_0_, event1_.id as id117_1_, experiment2_.id as id114_2_, annotation0_.description as descript3_13_0_, annotation0_.creation_id as creation13_13_0_, annotation0_.external_id as external14_13_0_, annotation0_.group_id as group15_13_0_, annotation0_.owner_id as owner16_13_0_, annotation0_.permissions as permissi4_13_0_, annotation0_.update_id as update17_13_0_, annotation0_.ns as ns13_0_, annotation0_.version as version13_0_, annotation0_.timeValue as timeValue13_0_, annotation0_.textValue as textValue13_0_, annotation0_.boolValue as boolValue13_0_, annotation0_.termValue as termValue13_0_, annotation0_.file as file13_0_, annotation0_.longValue as longValue13_0_, annotation0_.doubleValue as doubleV12_13_0_, annotation0_.discriminator as discrimi1_13_0_, event1_.containingEvent as containi5_117_1_, event1_.external_id as external6_117_1_, event1_.permissions as permissi2_117_1_, event1_.experimenter as experime7_117_1_, event1_.experimenterGroup as experime8_117_1_, event1_.session as session117_1_, event1_.status as status117_1_, event1_.time as time117_1_, event1_.type as type117_1_, experiment2_.external_id as external10_114_2_, experiment2_.permissions as permissi2_114_2_, experiment2_.email as email114_2_, experiment2_.firstName as firstName114_2_, experiment2_.institution as institut5_114_2_, experiment2_.lastName as lastName114_2_, experiment2_.middleName as middleName114_2_, experiment2_.omeName as omeName114_2_, experiment2_.version as version114_2_
 from annotation annotation0_ left outer join event event1_ on annotation0_.creation_id=event1_.id left outer join experimenter experiment2_ on annotation0_.owner_id=experiment2_.id
 where (

  ( annotation0_.group_id = ? AND 
     ( ? OR 
       ? OR 
       annotation0_.owner_id = ?
     )
  ) OR
  annotation0_.group_id = 1 OR 
 ?
) and (annotation0_.id in (select fileannota3_.id
 from annotation fileannota3_
 where (

  ( fileannota3_.group_id = ? AND 
     ( ? OR 
       ? OR 
       fileannota3_.owner_id = ?
     )
  ) OR
  fileannota3_.group_id = 1 OR 
 ?
)
 and fileannota3_.discriminator='/type/OriginalFile/')) and annotation0_.owner_id=? and (annotation0_.ns is not null) and (annotation0_.ns in (?)) limit ?
2010-10-06 09:55:10,505 INFO  [                 org.perf4j.TimingLogger] (l.Server-9) start[1286351699018] time[11487] tag[omero.call.success.ome.logic.MetadataImpl.loadSpecifiedAnnotations]
2010-10-06 09:55:10,505 INFO  [        ome.services.util.ServiceHandler] (l.Server-9)  Rslt:	()
2010-10-06 09:55:10,505 WARN  [        ome.services.util.ServiceHandler] (l.Server-9) Method interface ome.api.IMetadata.loadSpecifiedAnnotations invocation took 11487

comment:2 Changed 14 years ago by jmoore 

/tmp $ psql OMERO4.2__0 < ann.sql 
                                                                                                    QUERY PLAN                                                                                                    
------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
 Nested Loop Left Join  (cost=240386.32..240412.37 rows=1 width=8) (actual time=10419.807..10419.807 rows=0 loops=1)
   ->  Nested Loop Left Join  (cost=240386.32..240404.07 rows=1 width=16) (actual time=10419.805..10419.805 rows=0 loops=1)
         Join Filter: (annotation0_.owner_id = experiment2_.id)
         ->  Nested Loop  (cost=240386.32..240395.79 rows=1 width=24) (actual time=10419.805..10419.805 rows=0 loops=1)
               ->  HashAggregate  (cost=240386.32..240386.33 rows=1 width=8) (actual time=10419.804..10419.804 rows=0 loops=1)
                     ->  Seq Scan on annotation fileannota3_  (cost=0.00..240386.32 rows=1 width=8) (actual time=10419.801..10419.801 rows=0 loops=1)
                           Filter: ((group_id = 1) AND ((discriminator)::text = '/type/OriginalFile/'::text))
               ->  Index Scan using annotation_pkey on annotation annotation0_  (cost=0.00..9.45 rows=1 width=24) (never executed)
                     Index Cond: (annotation0_.id = fileannota3_.id)
                     Filter: ((annotation0_.ns IS NOT NULL) AND (annotation0_.group_id = 1) AND (annotation0_.owner_id = 23053) AND ((annotation0_.ns)::text = 'openmicroscopy.org/omero/editor/protocol'::text))
         ->  Index Scan using experimenter_pkey on experimenter experiment2_  (cost=0.00..8.27 rows=1 width=8) (never executed)
               Index Cond: (experiment2_.id = 23053)
   ->  Index Scan using event_pkey on event event1_  (cost=0.00..8.29 rows=1 width=8) (never executed)
         Index Cond: (annotation0_.creation_id = event1_.id)
 Total runtime: 10420.036 ms
(15 rows)


/tmp $ cat ann.sql 
explain analyze select annotation0_.id
 from annotation annotation0_ left outer join event event1_ on annotation0_.creation_id=event1_.id left outer join experimenter experiment2_ on annotation0_.owner_id=experiment2_.id
 where (

  annotation0_.group_id = 1
  and (annotation0_.id in (select fileannota3_.id
 from annotation fileannota3_
 where (

  fileannota3_.group_id = 1
  and fileannota3_.discriminator='/type/OriginalFile/'))
  and annotation0_.owner_id=23053
  and (annotation0_.ns is not null)
  and (annotation0_.ns in ('openmicroscopy.org/omero/editor/protocol'))));

comment:3 Changed 14 years ago by jmoore 

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

comment:4 Changed 14 years ago by jmoore 

OMERO4.2__0=# explain analyze select count(*) from annotation;
                                                          QUERY PLAN                                                           
-------------------------------------------------------------------------------------------------------------------------------
 Aggregate  (cost=219193.27..219193.28 rows=1 width=0) (actual time=13040.930..13040.930 rows=1 loops=1)
   ->  Seq Scan on annotation  (cost=0.00..198000.21 rows=8477221 width=0) (actual time=0.040..12299.122 rows=8477102 loops=1)
 Total runtime: 13040.997 ms
(3 rows)

OMERO4.2__0=# explain analyze select count(*) from annotation;
                                                          QUERY PLAN                                                          
------------------------------------------------------------------------------------------------------------------------------
 Aggregate  (cost=219193.27..219193.28 rows=1 width=0) (actual time=5433.525..5433.525 rows=1 loops=1)
   ->  Seq Scan on annotation  (cost=0.00..198000.21 rows=8477221 width=0) (actual time=0.031..4735.412 rows=8477102 loops=1)
 Total runtime: 5433.777 ms
(3 rows)

OMERO4.2__0=# explain analyze select count(*) from annotation;
                                                          QUERY PLAN                                                          
------------------------------------------------------------------------------------------------------------------------------
 Aggregate  (cost=219193.27..219193.28 rows=1 width=0) (actual time=2139.698..2139.698 rows=1 loops=1)
   ->  Seq Scan on annotation  (cost=0.00..198000.21 rows=8477221 width=0) (actual time=0.045..1450.908 rows=8477102 loops=1)
 Total runtime: 2139.770 ms
(3 rows)

OMERO4.2__0=# vacuum annotation;
VACUUM
OMERO4.2__0=# explain analyze select count(*) from annotation;
                                                          QUERY PLAN                                                          
------------------------------------------------------------------------------------------------------------------------------
 Aggregate  (cost=219191.78..219191.79 rows=1 width=0) (actual time=4518.881..4518.881 rows=1 loops=1)
   ->  Seq Scan on annotation  (cost=0.00..197999.02 rows=8477102 width=0) (actual time=0.018..3840.226 rows=8477102 loops=1)
 Total runtime: 4518.930 ms
(3 rows)

OMERO4.2__0=# explain analyze select count(*) from annotation;
                                                          QUERY PLAN                                                          
------------------------------------------------------------------------------------------------------------------------------
 Aggregate  (cost=219191.78..219191.79 rows=1 width=0) (actual time=1904.879..1904.879 rows=1 loops=1)
   ->  Seq Scan on annotation  (cost=0.00..197999.02 rows=8477102 width=0) (actual time=0.031..1260.611 rows=8477102 loops=1)
 Total runtime: 1904.939 ms
(3 rows)

OMERO4.2__0=# vacuum analyze annotation;
VACUUM
OMERO4.2__0=# explain analyze select count(*) from annotation;
                                                          QUERY PLAN                                                          
------------------------------------------------------------------------------------------------------------------------------
 Aggregate  (cost=219217.34..219217.35 rows=1 width=0) (actual time=1769.329..1769.330 rows=1 loops=1)
   ->  Seq Scan on annotation  (cost=0.00..198019.47 rows=8479147 width=0) (actual time=0.025..1161.017 rows=8477102 loops=1)
 Total runtime: 1769.395 ms
(3 rows)

OMERO4.2__0=# explain analyze select count(*) from annotation;
                                                          QUERY PLAN                                                          
------------------------------------------------------------------------------------------------------------------------------
 Aggregate  (cost=219217.34..219217.35 rows=1 width=0) (actual time=1771.802..1771.802 rows=1 loops=1)
   ->  Seq Scan on annotation  (cost=0.00..198019.47 rows=8479147 width=0) (actual time=0.028..1162.214 rows=8477102 loops=1)
 Total runtime: 1771.855 ms
(3 rows)


OMERO4.2__0=# vacuum full annotation;
VACUUM
OMERO4.2__0=# explain analyze select count(*) from annotation;
                                                          QUERY PLAN                                                          
------------------------------------------------------------------------------------------------------------------------------
 Aggregate  (cost=219012.78..219012.79 rows=1 width=0) (actual time=2029.477..2029.477 rows=1 loops=1)
   ->  Seq Scan on annotation  (cost=0.00..197820.02 rows=8477102 width=0) (actual time=0.013..1346.337 rows=8477102 loops=1)
 Total runtime: 2029.525 ms
(3 rows)

OMERO4.2__0=# explain analyze select count(*) from annotation;
                                                          QUERY PLAN                                                          
------------------------------------------------------------------------------------------------------------------------------
 Aggregate  (cost=219012.78..219012.79 rows=1 width=0) (actual time=1980.364..1980.364 rows=1 loops=1)
   ->  Seq Scan on annotation  (cost=0.00..197820.02 rows=8477102 width=0) (actual time=0.021..1308.429 rows=8477102 loops=1)
 Total runtime: 1980.414 ms
(3 rows)

OMERO4.2__0=# vacuum full freeze verbose analyze annotation;
INFO:  vacuuming "public.annotation"
INFO:  "annotation": found 0 removable, 8477102 nonremovable row versions in 113049 pages
DETAIL:  0 dead row versions cannot be removed yet.
Nonremovable row versions range from 96 to 1880 bytes long.
There were 1928 unused item pointers.
Total free space (including removable row versions) is 7691216 bytes.
0 pages are or will become empty, including 0 at the end of the table.
11 pages containing 8144 free bytes are potential move destinations.
CPU 8.52s/6.01u sec elapsed 92.26 sec.
INFO:  index "annotation_pkey" now contains 8477102 row versions in 29467 pages
DETAIL:  0 index row versions were removed.
0 index pages have been deleted, 0 are currently reusable.
CPU 0.21s/0.43u sec elapsed 5.25 sec.
INFO:  index "annotation_external_id_key" now contains 8477102 row versions in 29497 pages
DETAIL:  0 index row versions were removed.
48 index pages have been deleted, 48 are currently reusable.
CPU 0.21s/0.50u sec elapsed 8.23 sec.
INFO:  index "annotation_file" now contains 8477102 row versions in 23292 pages
DETAIL:  0 index row versions were removed.
33 index pages have been deleted, 33 are currently reusable.
CPU 0.17s/0.51u sec elapsed 6.94 sec.
INFO:  "annotation": moved 0 row versions, truncated 113049 to 113049 pages
DETAIL:  CPU 0.00s/0.00u sec elapsed 0.05 sec.
INFO:  vacuuming "pg_toast.pg_toast_1346912"
INFO:  "pg_toast_1346912": found 0 removable, 0 nonremovable row versions in 0 pages
DETAIL:  0 dead row versions cannot be removed yet.
Nonremovable row versions range from 0 to 0 bytes long.
There were 0 unused item pointers.
Total free space (including removable row versions) is 0 bytes.
0 pages are or will become empty, including 0 at the end of the table.
0 pages containing 0 free bytes are potential move destinations.
CPU 0.00s/0.00u sec elapsed 0.00 sec.
INFO:  index "pg_toast_1346912_index" now contains 0 row versions in 1 pages
DETAIL:  0 index pages have been deleted, 0 are currently reusable.
CPU 0.00s/0.00u sec elapsed 0.00 sec.
INFO:  analyzing "public.annotation"
INFO:  "annotation": scanned 30000 of 113049 pages, containing 2249526 live rows and 0 dead rows; 30000 rows in sample, 8476889 estimated total rows
VACUUM
OMERO4.2__0=# explain analyze select count(*) from annotation;
                                                          QUERY PLAN                                                          
------------------------------------------------------------------------------------------------------------------------------
 Aggregate  (cost=219010.12..219010.13 rows=1 width=0) (actual time=2334.848..2334.848 rows=1 loops=1)
   ->  Seq Scan on annotation  (cost=0.00..197817.89 rows=8476889 width=0) (actual time=0.013..1569.404 rows=8477102 loops=1)
 Total runtime: 2334.894 ms
(3 rows)
Note: See TracTickets for help on using tickets. You may also have a look at Agilo extensions to the ticket.

1.3.13-PRO © 2008-2011 Agilo Software all rights reserved (this page was served in: 0.66498 sec.)

© 2000-2014 University of Dundee & Open Microscopy Environment. Creative Commons Attribution 3.0 Unported License
OME source code is available under the GNU General public license or through commercial license from Glencoe Software

We're Hiring!