[ome-devel] OMERO 5 deletion performance
Yanling Liu
vrnova at gmail.com
Tue Jun 3 18:28:00 BST 2014
Made mistake in outputting Blitz-0.log file. Here is what I found:
2014-06-03 08:43:19,924 WARN [ o.h.h.ast.exec.MultiTableDeleteExecutor]
(2-thread-3) unable to drop temporary id table after use [ERROR: current
transaction is aborted, commands ignored until end of transaction block]
2014-06-03 08:43:19,927 ERROR [ ome.services.delete.Deletion]
(2-thread-3) Failure during DeleteHandle.steps :
org.hibernate.exception.GenericJDBCException: could not insert/select ids
for bulk delete
at
org.hibernate.exception.SQLStateConverter.handledNonSpecificException(SQLStateConverter.java:140)
~[hibernate-core.jar:na]
at
org.hibernate.exception.SQLStateConverter.convert(SQLStateConverter.java:128)
~[hibernate-core.jar:na]
at
org.hibernate.exception.JDBCExceptionHelper.convert(JDBCExceptionHelper.java:66)
~[hibernate-core.jar:na]
at
org.hibernate.hql.ast.exec.MultiTableDeleteExecutor.execute(MultiTableDeleteExecutor.java:125)
~[hibernate-core.jar:na]
at
org.hibernate.hql.ast.QueryTranslatorImpl.executeUpdate(QueryTranslatorImpl.java:421)
~[hibernate-core.jar:na]
at
org.hibernate.engine.query.HQLQueryPlan.performExecuteUpdate(HQLQueryPlan.java:283)
~[hibernate-core.jar:na]
at org.hibernate.impl.SessionImpl.executeUpdate(SessionImpl.java:1280)
~[hibernate-core.jar:na]
at org.hibernate.impl.QueryImpl.executeUpdate(QueryImpl.java:117)
~[hibernate-core.jar:na]
at ome.services.delete.DeleteStep.action(DeleteStep.java:97)
~[server.jar:na]
at ome.services.graphs.GraphState.perform(GraphState.java:410)
~[server.jar:na]
at ome.services.graphs.GraphState.execute(GraphState.java:334)
~[server.jar:na]
at ome.services.delete.Deletion.execute(Deletion.java:304)
~[server.jar:na]
at omero.cmd.graphs.DeleteI.step(DeleteI.java:120) ~[blitz.jar:na]
at omero.cmd.basic.DoAllI$X.step(DoAllI.java:107) ~[blitz.jar:na]
at omero.cmd.basic.DoAllI.step(DoAllI.java:319) ~[blitz.jar:na]
at omero.cmd.HandleI.steps(HandleI.java:435) ~[blitz.jar:na]
at omero.cmd.HandleI$1.doWork(HandleI.java:365) ~[blitz.jar:na]
at omero.cmd.HandleI$1.doWork(HandleI.java:361) ~[blitz.jar:na]
at sun.reflect.GeneratedMethodAccessor272.invoke(Unknown Source)
~[na:na]
at
sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
~[na:1.6.0_30]
at java.lang.reflect.Method.invoke(Method.java:622) ~[na:1.6.0_30]
at
org.springframework.aop.support.AopUtils.invokeJoinpointUsingReflection(AopUtils.java:307)
~[org.springframework.aop.jar:3.0.1.RELEASE-A]
at
org.springframework.aop.framework.ReflectiveMethodInvocation.invokeJoinpoint(ReflectiveMethodInvocation.java:183)
~[org.springframework.aop.jar:3.0.1.RELEASE-A]
at
org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:150)
~[org.springframework.aop.jar:3.0.1.RELEASE-A]
at
ome.services.util.Executor$Impl$Interceptor.invoke(Executor.java:576)
~[server.jar:na]
at
org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:172)
~[org.springframework.aop.jar:3.0.1.RELEASE-A]
at ome.security.basic.EventHandler.invoke(EventHandler.java:154)
~[server.jar:na]
at
org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:172)
~[org.springframework.aop.jar:3.0.1.RELEASE-A]
at
org.springframework.orm.hibernate3.HibernateInterceptor.invoke(HibernateInterceptor.java:111)
~[org.springframework.orm.jar:3.0.1.RELEASE-A]
at
org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:172)
~[org.springframework.aop.jar:3.0.1.RELEASE-A]
at
org.springframework.transaction.interceptor.TransactionInterceptor.invoke(TransactionInterceptor.java:108)
~[org.springframework.transaction.jar:3.0.1.RELEASE-A]
at
org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:172)
~[org.springframework.aop.jar:3.0.1.RELEASE-A]
at
ome.tools.hibernate.ProxyCleanupFilter$Interceptor.invoke(ProxyCleanupFilter.java:241)
~[server.jar:na]
at
org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:172)
~[org.springframework.aop.jar:3.0.1.RELEASE-A]
at ome.services.util.ServiceHandler.invoke(ServiceHandler.java:116)
~[server.jar:na]
at
org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:172)
~[org.springframework.aop.jar:3.0.1.RELEASE-A]
at
org.springframework.aop.framework.JdkDynamicAopProxy.invoke(JdkDynamicAopProxy.java:202)
~[org.springframework.aop.jar:3.0.1.RELEASE-A]
at com.sun.proxy.$Proxy66.doWork(Unknown Source) ~[na:na]
at ome.services.util.Executor$Impl.execute(Executor.java:457)
~[server.jar:na]
at omero.cmd.HandleI.run(HandleI.java:359) ~[blitz.jar:na]
at
java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:471)
~[na:1.6.0_30]
at ome.services.util.Executor$Impl$1.call(Executor.java:498)
~[server.jar:na]
at java.util.concurrent.FutureTask$Sync.innerRun(FutureTask.java:334)
~[na:1.6.0_30]
at java.util.concurrent.FutureTask.run(FutureTask.java:166)
~[na:1.6.0_30]
at
java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1146)
~[na:1.6.0_30]
at
java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
~[na:1.6.0_30]
at java.lang.Thread.run(Thread.java:701) ~[na:1.6.0_30]
Caused by: org.postgresql.util.PSQLException: ERROR: current transaction is
aborted, commands ignored until end of transaction block
at
org.postgresql.core.v3.QueryExecutorImpl.receiveErrorResponse(QueryExecutorImpl.java:2103)
~[postgresql.jar:na]
at
org.postgresql.core.v3.QueryExecutorImpl.processResults(QueryExecutorImpl.java:1836)
~[postgresql.jar:na]
at
org.postgresql.core.v3.QueryExecutorImpl.execute(QueryExecutorImpl.java:257)
~[postgresql.jar:na]
at
org.postgresql.jdbc2.AbstractJdbc2Statement.execute(AbstractJdbc2Statement.java:512)
~[postgresql.jar:na]
at
org.postgresql.jdbc2.AbstractJdbc2Statement.executeWithFlags(AbstractJdbc2Statement.java:388)
~[postgresql.jar:na]
at
org.postgresql.jdbc2.AbstractJdbc2Statement.executeUpdate(AbstractJdbc2Statement.java:334)
~[postgresql.jar:na]
at sun.reflect.GeneratedMethodAccessor256.invoke(Unknown Source)
~[na:na]
at
sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
~[na:1.6.0_30]
at java.lang.reflect.Method.invoke(Method.java:622) ~[na:1.6.0_30]
at
bitronix.tm.resource.jdbc.BaseProxyHandlerClass.invoke(BaseProxyHandlerClass.java:64)
~[btm.jar:2.1.3]
at com.sun.proxy.$Proxy9.executeUpdate(Unknown Source) ~[na:na]
at
org.hibernate.hql.ast.exec.MultiTableDeleteExecutor.execute(MultiTableDeleteExecutor.java:116)
~[hibernate-core.jar:na]
... 43 common frames omitted
>From my limited knowledge about java and postgres, this looks like a
postgres issue. Shall I change max_locks_per_transaction? If so what would
be optimal value?
Many thanks,
Yanling
On Tue, Jun 3, 2014 at 9:29 AM, Yanling Liu <vrnova at gmail.com> wrote:
> Hi, Josh
>
> This is the log information from Blitz-0.log file:
>
> 2014-06-03 07:56:43,460 INFO [ ome.security.basic.EventHandler]
> (2-thread-4) Auth:
> user=0,group=0,event=null(Sessions),sess=82f64ba5-c6f4-40e1-b10b-3803eea50634
> 2014-06-03 07:56:43,462 INFO [ org.perf4j.TimingLogger]
> (2-thread-4) start[1401796603460] time[2]
> tag[omero.call.success.ome.services.sessions.SessionManagerImpl$6.doWork]
> 2014-06-03 07:56:43,462 INFO [ ome.services.util.ServiceHandler]
> (2-thread-4) Rslt: (ome.model.meta.Experimenter:Id_52,
> ome.model.meta.ExperimenterGroup:Id_3, (3, 1), ... 4 more)
> 2014-06-03 07:56:43,462 INFO [ org.perf4j.TimingLogger]
> (2-thread-4) start[1401796603432] time[30]
> tag[omero.sessions.synchronization]
> 2014-06-03 07:56:43,463 INFO [ome.services.sessions.state.SessionCache]
> (2-thread-4) Synchronization took 30 ms.
> 2014-06-03 07:57:00,012 INFO [ ome.services.blitz.fire.SessionManagerI]
> (2-thread-1) Performing requestHeartbeats
> 2014-06-03 07:57:41,128 INFO [ ome.services.blitz.fire.SessionManagerI]
> (.Server-19) Found session locally: a040dd26-7e10-4ce4-bb18-5f8497f4d7b7
> 2014-06-03 07:57:41,130 INFO [ ome.services.blitz.fire.SessionManagerI]
> (.Server-19) Rejoining session
> ServiceFactoryI(session-8817f9ad-0541-438b-ac7f-9b82695a2a8e/a040dd26-7e10-4ce4-bb18-5f8497f4d7b7)
> (agent=OMERO.web)
> 2014-06-03 07:57:41,134 INFO [o.services.sessions.SessionContext$Count]
> (.Server-19) -Reference count: a040dd26-7e10-4ce4-bb18-5f8497f4d7b7=0
> 2014-06-03 07:57:41,134 INFO [ omero.cmd.SessionI]
> (.Server-19)
> cleanupSelf(ServiceFactoryI(session-8817f9ad-0541-438b-ac7f-9b82695a2a8e/a040dd26-7e10-4ce4-bb18-5f8497f4d7b7)).
> omero at fr-s-ivg-mia-d2:~/omero/OMERO.server$ tail var/log/Blitz-0.log
> 2014-06-03 09:16:43,450 INFO [ ome.security.basic.EventHandler]
> (2-thread-2) Auth:
> user=0,group=0,event=null(Sessions),sess=82f64ba5-c6f4-40e1-b10b-3803eea50634
> 2014-06-03 09:16:43,452 INFO [ org.perf4j.TimingLogger]
> (2-thread-2) start[1401801403450] time[2]
> tag[omero.call.success.ome.services.sessions.SessionManagerImpl$6.doWork]
> 2014-06-03 09:16:43,452 INFO [ ome.services.util.ServiceHandler]
> (2-thread-2) Rslt: (ome.model.meta.Experimenter:Id_0,
> ome.model.meta.ExperimenterGroup:Id_0, (0, 1, 3, ... 1 more), ... 4 more)
> 2014-06-03 09:16:43,452 INFO [ org.perf4j.TimingLogger]
> (2-thread-2) start[1401801403426] time[26]
> tag[omero.sessions.synchronization]
> 2014-06-03 09:16:43,453 INFO [ome.services.sessions.state.SessionCache]
> (2-thread-2) Synchronization took 26 ms.
> 2014-06-03 09:17:13,151 INFO [ ome.services.blitz.fire.SessionManagerI]
> (.Server-19) Found session locally: 0f848c0a-c91e-403c-b49e-bb01496b821d
> 2014-06-03 09:17:13,152 INFO [ ome.services.blitz.fire.SessionManagerI]
> (.Server-19) Rejoining session
> ServiceFactoryI(session-8dae7d7e-a49e-4bca-9734-0ceddd7188de/0f848c0a-c91e-403c-b49e-bb01496b821d)
> (agent=OMERO.web)
> 2014-06-03 09:17:13,154 INFO [o.services.sessions.SessionContext$Count]
> (.Server-19) -Reference count: 0f848c0a-c91e-403c-b49e-bb01496b821d=0
> 2014-06-03 09:17:13,154 INFO [ omero.cmd.SessionI]
> (.Server-19)
> cleanupSelf(ServiceFactoryI(session-8dae7d7e-a49e-4bca-9734-0ceddd7188de/0f848c0a-c91e-403c-b49e-bb01496b821d)).
> 2014-06-03 09:18:00,012 INFO [ ome.services.blitz.fire.SessionManagerI]
> (2-thread-3) Performing requestHeartbeats
>
> Seems normal to me.
>
> But I do found something in postgres log file:
>
> 2014-06-03 08:43:19 EDT WARNING: out of shared memory
> 2014-06-03 08:43:19 EDT ERROR: out of shared memory
> 2014-06-03 08:43:19 EDT HINT: You might need to increase
> max_locks_per_transaction.
> 2014-06-03 08:43:19 EDT STATEMENT: create temporary table HT_job (id int8
> not null) on commit drop
> 2014-06-03 08:43:19 EDT ERROR: current transaction is aborted, commands
> ignored until end of transaction block
> 2014-06-03 08:43:19 EDT STATEMENT: insert into HT_job select job0_.id as
> id from job job0_ where
> (
> 1 = $1 OR
> 1 = $2 OR
> (group_id in ($3)) OR
> (owner_id = $4 AND (select (__g.permissions & 1024) = 1024 from
> experimentergroup __g where __g.id = group_id)) OR
> (group_id in ($5,$6) AND (select (__g.permissions & 64) = 64 from
> experimentergroup __g where __g.id = group_id)) OR
> ((select (__g.permissions & 4) = 4 from experimentergroup __g where
> __g.id = group_id))
> ) and id=$7 and owner_id=$8
> 2014-06-03 08:43:19 EDT ERROR: current transaction is aborted, commands
> ignored until end of transaction block
> 2014-06-03 08:43:19 EDT STATEMENT: drop table HT_job
>
> In postgresql.conf I have following settings:
>
> max_connections = 100
> #max_locks_per_transaction = 64 # min 10
>
> Mote the max_locks_per_transaction is commented out by default. I am not
> an expert on postgres and I would appreciate if you may provide some hints
> on how to set postgres parameters properly for OMERO.
>
> Thanks,
>
> On Tue, Jun 3, 2014 at 6:28 AM, Josh Moore <josh at glencoesoftware.com>
> wrote:
>
>> Hi Yanling,
>>
>> >> On Mon, Jun 2, 2014 at 10:02 AM, Yanling Liu <vrnova at gmail.com> wrote:
>> >>
>> >>> I have OMERO 5 installed on Ubuntu 12.04 64bit 8GB Mem, 4 Cores @
>> 3.47GHz
>> >>> and NFS mounted storage for OMERO data storage.
>> >>>
>> >>> When deleting couple hundred images (each at 1k x 1k pixels) through
>> >>> OMERO web, it took long time (> 10 minutes) to finish. In general
>> project
>> >>> and dataset deletion are very slow in OMERO web. I wonder if there's
>> any
>> >>> hint to tune the performance of OMERO.
>> >>>
>> >>> I have increased JVM memory usage based on OMERO documentation.
>>
>> Though there are further tunings you can try, Deletion performance is
>> quite poor at the moment, but it's something we're actively working on.
>>
>>
>> > On Mon, Jun 2, 2014 at 11:09 AM, Yanling Liu <vrnova at gmail.com> wrote:
>> >
>> >> By looking OMEROweb.log, deleting single file takes 5 good seconds. Is
>> >> this normal and expected? How could I find out if this because OMERO
>> >> itself, or postgres, or NFS storage access speed?
>> >>
>> >> Thanks ahead.....
>>
>> Could you send us the var/log/Blitz-0.log file for the time of the
>> deletion?
>>
>>
>>
>> On Jun 2, 2014, at 5:12 PM, Yanling Liu wrote:
>>
>> > Also I am getting this error:
>> >
>> > 2014-06-02 16:07:37,242 ERROR [ omeroweb.webclient.webclient_utils]
>> > (proc.20168) _formatReport:38 Format report: {'warning': '', 'error':
>> > 'Failure during DeleteHandle.steps
>> > :org.hibernate.exception.GenericJDBCException: could not insert/select
>> ids
>> > for bulk delete'}
>> >
>> > Anything wrong with postgres? Or is it because I selected too many files
>> > for bulk deletion?
>>
>> Possibly. Again, the log file would be the most helpful. There may be an
>> issue with your PG installation.
>>
>> Cheers,
>> ~Josh.
>
>
>
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://lists.openmicroscopy.org.uk/pipermail/ome-devel/attachments/20140603/cd4c3818/attachment-0001.html>
More information about the ome-devel
mailing list