<div dir="ltr"><div><div>Made mistake in outputting Blitz-0.log file. Here is what I found:<br><br>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]<br>
2014-06-03 08:43:19,927 ERROR [ ome.services.delete.Deletion] (2-thread-3) Failure during DeleteHandle.steps :<br>org.hibernate.exception.GenericJDBCException: could not insert/select ids for bulk delete<br> at org.hibernate.exception.SQLStateConverter.handledNonSpecificException(SQLStateConverter.java:140) ~[hibernate-core.jar:na]<br>
at org.hibernate.exception.SQLStateConverter.convert(SQLStateConverter.java:128) ~[hibernate-core.jar:na]<br> at org.hibernate.exception.JDBCExceptionHelper.convert(JDBCExceptionHelper.java:66) ~[hibernate-core.jar:na]<br>
at org.hibernate.hql.ast.exec.MultiTableDeleteExecutor.execute(MultiTableDeleteExecutor.java:125) ~[hibernate-core.jar:na]<br> at org.hibernate.hql.ast.QueryTranslatorImpl.executeUpdate(QueryTranslatorImpl.java:421) ~[hibernate-core.jar:na]<br>
at org.hibernate.engine.query.HQLQueryPlan.performExecuteUpdate(HQLQueryPlan.java:283) ~[hibernate-core.jar:na]<br> at org.hibernate.impl.SessionImpl.executeUpdate(SessionImpl.java:1280) ~[hibernate-core.jar:na]<br>
at org.hibernate.impl.QueryImpl.executeUpdate(QueryImpl.java:117) ~[hibernate-core.jar:na]<br> at ome.services.delete.DeleteStep.action(DeleteStep.java:97) ~[server.jar:na]<br> at ome.services.graphs.GraphState.perform(GraphState.java:410) ~[server.jar:na]<br>
at ome.services.graphs.GraphState.execute(GraphState.java:334) ~[server.jar:na]<br> at ome.services.delete.Deletion.execute(Deletion.java:304) ~[server.jar:na]<br> at omero.cmd.graphs.DeleteI.step(DeleteI.java:120) ~[blitz.jar:na]<br>
at omero.cmd.basic.DoAllI$X.step(DoAllI.java:107) ~[blitz.jar:na]<br> at omero.cmd.basic.DoAllI.step(DoAllI.java:319) ~[blitz.jar:na]<br> at omero.cmd.HandleI.steps(HandleI.java:435) ~[blitz.jar:na]<br> at omero.cmd.HandleI$1.doWork(HandleI.java:365) ~[blitz.jar:na]<br>
at omero.cmd.HandleI$1.doWork(HandleI.java:361) ~[blitz.jar:na]<br> at sun.reflect.GeneratedMethodAccessor272.invoke(Unknown Source) ~[na:na]<br> at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[na:1.6.0_30]<br>
at java.lang.reflect.Method.invoke(Method.java:622) ~[na:1.6.0_30]<br> at org.springframework.aop.support.AopUtils.invokeJoinpointUsingReflection(AopUtils.java:307) ~[org.springframework.aop.jar:3.0.1.RELEASE-A]<br>
at org.springframework.aop.framework.ReflectiveMethodInvocation.invokeJoinpoint(ReflectiveMethodInvocation.java:183) ~[org.springframework.aop.jar:3.0.1.RELEASE-A]<br> at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:150) ~[org.springframework.aop.jar:3.0.1.RELEASE-A]<br>
at ome.services.util.Executor$Impl$Interceptor.invoke(Executor.java:576) ~[server.jar:na]<br> at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:172) ~[org.springframework.aop.jar:3.0.1.RELEASE-A]<br>
at ome.security.basic.EventHandler.invoke(EventHandler.java:154) ~[server.jar:na]<br> at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:172) ~[org.springframework.aop.jar:3.0.1.RELEASE-A]<br>
at org.springframework.orm.hibernate3.HibernateInterceptor.invoke(HibernateInterceptor.java:111) ~[org.springframework.orm.jar:3.0.1.RELEASE-A]<br> at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:172) ~[org.springframework.aop.jar:3.0.1.RELEASE-A]<br>
at org.springframework.transaction.interceptor.TransactionInterceptor.invoke(TransactionInterceptor.java:108) ~[org.springframework.transaction.jar:3.0.1.RELEASE-A]<br> at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:172) ~[org.springframework.aop.jar:3.0.1.RELEASE-A]<br>
at ome.tools.hibernate.ProxyCleanupFilter$Interceptor.invoke(ProxyCleanupFilter.java:241) ~[server.jar:na]<br> at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:172) ~[org.springframework.aop.jar:3.0.1.RELEASE-A]<br>
at ome.services.util.ServiceHandler.invoke(ServiceHandler.java:116) ~[server.jar:na]<br> at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:172) ~[org.springframework.aop.jar:3.0.1.RELEASE-A]<br>
at org.springframework.aop.framework.JdkDynamicAopProxy.invoke(JdkDynamicAopProxy.java:202) ~[org.springframework.aop.jar:3.0.1.RELEASE-A]<br> at com.sun.proxy.$Proxy66.doWork(Unknown Source) ~[na:na]<br> at ome.services.util.Executor$Impl.execute(Executor.java:457) ~[server.jar:na]<br>
at omero.cmd.HandleI.run(HandleI.java:359) ~[blitz.jar:na]<br> at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:471) ~[na:1.6.0_30]<br> at ome.services.util.Executor$Impl$1.call(Executor.java:498) ~[server.jar:na]<br>
at java.util.concurrent.FutureTask$Sync.innerRun(FutureTask.java:334) ~[na:1.6.0_30]<br> at java.util.concurrent.FutureTask.run(FutureTask.java:166) ~[na:1.6.0_30]<br> at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1146) ~[na:1.6.0_30]<br>
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615) ~[na:1.6.0_30]<br> at java.lang.Thread.run(Thread.java:701) ~[na:1.6.0_30]<br>Caused by: org.postgresql.util.PSQLException: ERROR: current transaction is aborted, commands ignored until end of transaction block<br>
at org.postgresql.core.v3.QueryExecutorImpl.receiveErrorResponse(QueryExecutorImpl.java:2103) ~[postgresql.jar:na]<br> at org.postgresql.core.v3.QueryExecutorImpl.processResults(QueryExecutorImpl.java:1836) ~[postgresql.jar:na]<br>
at org.postgresql.core.v3.QueryExecutorImpl.execute(QueryExecutorImpl.java:257) ~[postgresql.jar:na]<br> at org.postgresql.jdbc2.AbstractJdbc2Statement.execute(AbstractJdbc2Statement.java:512) ~[postgresql.jar:na]<br>
at org.postgresql.jdbc2.AbstractJdbc2Statement.executeWithFlags(AbstractJdbc2Statement.java:388) ~[postgresql.jar:na]<br> at org.postgresql.jdbc2.AbstractJdbc2Statement.executeUpdate(AbstractJdbc2Statement.java:334) ~[postgresql.jar:na]<br>
at sun.reflect.GeneratedMethodAccessor256.invoke(Unknown Source) ~[na:na]<br> at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[na:1.6.0_30]<br> at java.lang.reflect.Method.invoke(Method.java:622) ~[na:1.6.0_30]<br>
at bitronix.tm.resource.jdbc.BaseProxyHandlerClass.invoke(BaseProxyHandlerClass.java:64) ~[btm.jar:2.1.3]<br> at com.sun.proxy.$Proxy9.executeUpdate(Unknown Source) ~[na:na]<br> at org.hibernate.hql.ast.exec.MultiTableDeleteExecutor.execute(MultiTableDeleteExecutor.java:116) ~[hibernate-core.jar:na]<br>
... 43 common frames omitted<br><br><br></div>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?<br><br></div>
Many thanks,<br>Yanling<br></div><div class="gmail_extra"><br><br><div class="gmail_quote">On Tue, Jun 3, 2014 at 9:29 AM, Yanling Liu <span dir="ltr"><<a href="mailto:vrnova@gmail.com" target="_blank">vrnova@gmail.com</a>></span> wrote:<br>
<blockquote class="gmail_quote" style="margin:0 0 0 .8ex;border-left:1px #ccc solid;padding-left:1ex"><div dir="ltr"><div><div>Hi, Josh<br><br></div>This is the log information from Blitz-0.log file:<br><br>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<br>
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]<br>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)<br>
2014-06-03 07:56:43,462 INFO [ org.perf4j.TimingLogger] (2-thread-4) start[1401796603432] time[30] tag[omero.sessions.synchronization]<br>2014-06-03 07:56:43,463 INFO [ome.services.sessions.state.SessionCache] (2-thread-4) Synchronization took 30 ms.<br>
2014-06-03 07:57:00,012 INFO [ ome.services.blitz.fire.SessionManagerI] (2-thread-1) Performing requestHeartbeats<br>2014-06-03 07:57:41,128 INFO [ ome.services.blitz.fire.SessionManagerI] (.Server-19) Found session locally: a040dd26-7e10-4ce4-bb18-5f8497f4d7b7<br>
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)<br>
2014-06-03 07:57:41,134 INFO [o.services.sessions.SessionContext$Count] (.Server-19) -Reference count: a040dd26-7e10-4ce4-bb18-5f8497f4d7b7=0<br>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)).<br>
omero@fr-s-ivg-mia-d2:~/omero/OMERO.server$ tail var/log/Blitz-0.log<br>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<br>
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]<br>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)<br>
2014-06-03 09:16:43,452 INFO [ org.perf4j.TimingLogger] (2-thread-2) start[1401801403426] time[26] tag[omero.sessions.synchronization]<br>2014-06-03 09:16:43,453 INFO [ome.services.sessions.state.SessionCache] (2-thread-2) Synchronization took 26 ms.<br>
2014-06-03 09:17:13,151 INFO [ ome.services.blitz.fire.SessionManagerI] (.Server-19) Found session locally: 0f848c0a-c91e-403c-b49e-bb01496b821d<br>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)<br>
2014-06-03 09:17:13,154 INFO [o.services.sessions.SessionContext$Count] (.Server-19) -Reference count: 0f848c0a-c91e-403c-b49e-bb01496b821d=0<br>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)).<br>
2014-06-03 09:18:00,012 INFO [ ome.services.blitz.fire.SessionManagerI] (2-thread-3) Performing requestHeartbeats<br><br></div>Seems normal to me.<br><br>But I do found something in postgres log file:<br><br>2014-06-03 08:43:19 EDT WARNING: out of shared memory<br>
2014-06-03 08:43:19 EDT ERROR: out of shared memory<br>2014-06-03 08:43:19 EDT HINT: You might need to increase max_locks_per_transaction.<br>2014-06-03 08:43:19 EDT STATEMENT: create temporary table HT_job (id int8 not null) on commit drop<br>
2014-06-03 08:43:19 EDT ERROR: current transaction is aborted, commands ignored until end of transaction block<br>2014-06-03 08:43:19 EDT STATEMENT: insert into HT_job select job0_.id as id from job job0_ where <br> ( <br>
1 = $1 OR <br> 1 = $2 OR <br> (group_id in ($3)) OR <br> (owner_id = $4 AND (select (__g.permissions & 1024) = 1024 from experimentergroup __g where __<a href="http://g.id" target="_blank">g.id</a> = group_id)) OR <br>
(group_id in ($5,$6) AND (select (__g.permissions & 64) = 64 from experimentergroup __g where __<a href="http://g.id" target="_blank">g.id</a> = group_id)) OR <br> ((select (__g.permissions & 4) = 4 from experimentergroup __g where __<a href="http://g.id" target="_blank">g.id</a> = group_id)) <br>
) and id=$7 and owner_id=$8<br>2014-06-03 08:43:19 EDT ERROR: current transaction is aborted, commands ignored until end of transaction block<br>2014-06-03 08:43:19 EDT STATEMENT: drop table HT_job<br><br><div><div>
<div><div><div class="gmail_extra">In postgresql.conf I have following settings:<br><br>max_connections = 100<br>#max_locks_per_transaction = 64 # min 10<br><br></div><div class="gmail_extra">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.<br>
<br>Thanks,<br></div><div><div class="h5"><div class="gmail_extra"><br><div class="gmail_quote">On Tue, Jun 3, 2014 at 6:28 AM, Josh Moore <span dir="ltr"><<a href="mailto:josh@glencoesoftware.com" target="_blank">josh@glencoesoftware.com</a>></span> wrote:<br>
<blockquote class="gmail_quote" style="margin:0px 0px 0px 0.8ex;border-left:1px solid rgb(204,204,204);padding-left:1ex">Hi Yanling,<br>
<div><br>
>> On Mon, Jun 2, 2014 at 10:02 AM, Yanling Liu <<a href="mailto:vrnova@gmail.com" target="_blank">vrnova@gmail.com</a>> wrote:<br>
>><br>
</div><div>>>> I have OMERO 5 installed on Ubuntu 12.04 64bit 8GB Mem, 4 Cores @ 3.47GHz<br>
>>> and NFS mounted storage for OMERO data storage.<br>
>>><br>
>>> When deleting couple hundred images (each at 1k x 1k pixels) through<br>
>>> OMERO web, it took long time (> 10 minutes) to finish. In general project<br>
>>> and dataset deletion are very slow in OMERO web. I wonder if there's any<br>
>>> hint to tune the performance of OMERO.<br>
>>><br>
>>> I have increased JVM memory usage based on OMERO documentation.<br>
<br>
</div>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.<br>
<div><br>
<br>
> On Mon, Jun 2, 2014 at 11:09 AM, Yanling Liu <<a href="mailto:vrnova@gmail.com" target="_blank">vrnova@gmail.com</a>> wrote:<br>
><br>
>> By looking OMEROweb.log, deleting single file takes 5 good seconds. Is<br>
>> this normal and expected? How could I find out if this because OMERO<br>
>> itself, or postgres, or NFS storage access speed?<br>
>><br>
>> Thanks ahead.....<br>
<br>
</div>Could you send us the var/log/Blitz-0.log file for the time of the deletion?<br>
<div><br>
<br>
<br>
On Jun 2, 2014, at 5:12 PM, Yanling Liu wrote:<br>
<br>
> Also I am getting this error:<br>
><br>
> 2014-06-02 16:07:37,242 ERROR [ omeroweb.webclient.webclient_utils]<br>
> (proc.20168) _formatReport:38 Format report: {'warning': '', 'error':<br>
> 'Failure during DeleteHandle.steps<br>
> :org.hibernate.exception.GenericJDBCException: could not insert/select ids<br>
> for bulk delete'}<br>
><br>
> Anything wrong with postgres? Or is it because I selected too many files<br>
> for bulk deletion?<br>
<br>
</div>Possibly. Again, the log file would be the most helpful. There may be an issue with your PG installation.<br>
<br>
Cheers,<br>
~Josh.</blockquote></div><br></div></div></div></div></div></div></div></div>
</blockquote></div><br></div>