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 #1254 (closed)

Opened 16 years ago

Closed 13 years ago

Periodic database locks increase under high usage due to <IDLE> in transaction

Reported by: jamoore Owned by: jamoore
Priority: critical Milestone: OMERO-4.4
Component: Performance Version: 3.0-M1
Keywords: n.a. Cc: atarkowska, cxallan, jrswedlow
Resources: n.a. Referenced By: n.a.
References: n.a. Remaining Time: n.a.
Sprint: n.a.

Description (last modified by jmoore)

Possible influences:

  • indexing currently being readOnly = false (turning off the indexer prevents the blips)
  • readOnly = false during checkPassword
  • multiple transactions in createSession

See also #1218 & #1257

​http://hudson.openmicroscopy.org.uk/job/omero-stress-test/20/console:

. . . . . . . . . . . . . . . . . . . . . . . . . . . . . . . . . . . . . . . . . . . . . . . . . .    12600  at  Thu Mar 19 13:18:23 2009 (14/ 2 per sec)
. . . . . . . . . . . . . . . . . . . . . . . . . . . . . . . . . . . . . . . . . . . . . . . . . .    12650  at  Thu Mar 19 13:18:27 2009 (13/ 2 per sec)
. . . . . . . . . . . . . . . . . . . . . . . . . . . . . . . . . . . . . . . . . 2 . . . . . . . .    12700  at  Thu Mar 19 13:22:21 2009 ( 0/ 2 per sec)
. . . . . . . . . . . . . . . . . . . . . . . . . . . . . . . . . . . . . . . . . . . . . . . . . .    12750  at  Thu Mar 19 13:22:24 2009 (15/ 2 per sec)
. . . . . . . . . . . . . . . . . . . . . . . . . . . . . . . . . . . . . . . . . . . . . . . . . .    12800  at  Thu Mar 19 13:22:28 2009 (15/ 2 per sec)
. . . . . . . . . . . . . . . . . . . . . . . . . . . . . 2 . . . . . . . . . . . . . . . . . . . .    12850  at  Thu Mar 19 13:26:22 2009 ( 0/ 2 per sec)
. . . . . . . . . . . . . . . . . . . . . . . . . . . . . . . . . . . . . . . . . . . . . . . . . .    12900  at  Thu Mar 19 13:26:25 2009 (15/ 2 per sec)
. . . . . . . . . . . . . . . . . . . . . . . . . . . . . . . . . . . . . . . . . . . . . . . . . .    12950  at  Thu Mar 19 13:26:28 2009 (15/ 2 per sec)

shows periodic hangs during calls to PermissionsVerifier:

"Blitz-0-Ice.ThreadPool.Server-4" prio=10 tid=0x00002aaacf3a7c00 nid=0x5799 runnable [0x000000004274e000..0x000000004274fb10]
   java.lang.Thread.State: RUNNABLE
        at java.net.SocketInputStream.socketRead0(Native Method)
        at java.net.SocketInputStream.read(SocketInputStream.java:129)
        at org.postgresql.core.VisibleBufferedInputStream.readMore(VisibleBufferedInputStream.java:135)
        at org.postgresql.core.VisibleBufferedInputStream.ensureBytes(VisibleBufferedInputStream.java:104)
        at org.postgresql.core.VisibleBufferedInputStream.read(VisibleBufferedInputStream.java:73)
        at org.postgresql.core.PGStream.ReceiveChar(PGStream.java:259)
        at org.postgresql.core.v3.QueryExecutorImpl.processResults(QueryExecutorImpl.java:1182)
        at org.postgresql.core.v3.QueryExecutorImpl.execute(QueryExecutorImpl.java:194)
        - locked <0x00002aaab42c7590> (a org.postgresql.core.v3.QueryExecutorImpl)
        at org.postgresql.jdbc2.AbstractJdbc2Statement.execute(AbstractJdbc2Statement.java:451)
        at org.postgresql.jdbc2.AbstractJdbc2Statement.executeWithFlags(AbstractJdbc2Statement.java:350)
        at org.postgresql.jdbc2.AbstractJdbc2Statement.executeUpdate(AbstractJdbc2Statement.java:304)
        at org.hibernate.jdbc.NonBatchingBatcher.addToBatch(NonBatchingBatcher.java:23)
        at org.hibernate.persister.entity.AbstractEntityPersister.insert(AbstractEntityPersister.java:2252)
        at org.hibernate.persister.entity.AbstractEntityPersister.insert(AbstractEntityPersister.java:2665)
        at org.hibernate.action.EntityInsertAction.execute(EntityInsertAction.java:60)
        at org.hibernate.engine.ActionQueue.execute(ActionQueue.java:279)
        at org.hibernate.engine.ActionQueue.executeActions(ActionQueue.java:263)
        at org.hibernate.engine.ActionQueue.executeActions(ActionQueue.java:167)
        at org.hibernate.event.def.AbstractFlushingEventListener.performExecutions(AbstractFlushingEventListener.java:298)
        at org.hibernate.event.def.DefaultFlushEventListener.onFlush(DefaultFlushEventListener.java:27)
        at org.hibernate.impl.SessionImpl.flush(SessionImpl.java:1000)
        at ome.logic.UpdateImpl.afterUpdate(UpdateImpl.java:292)
        at ome.logic.UpdateImpl.doAction(UpdateImpl.java:304)
        at ome.logic.UpdateImpl.saveAndReturnObject(UpdateImpl.java:118)
        at ome.security.basic.BasicSecuritySystem.loadEventContext(BasicSecuritySystem.java:340)
        at ome.security.basic.EventHandler.invoke(EventHandler.java:91)
        at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:171)
        at org.springframework.orm.hibernate3.HibernateInterceptor.invoke(HibernateInterceptor.java:111)
        at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:171)
        at org.springframework.transaction.interceptor.TransactionInterceptor.invoke(TransactionInterceptor.java:106)
        at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:171)
        at ome.tools.hibernate.ProxyCleanupFilter$Interceptor.invoke(ProxyCleanupFilter.java:169)
        at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:171)
        at ome.services.util.ServiceHandler.invoke(ServiceHandler.java:97)
        at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:171)
        at org.springframework.aop.framework.JdkDynamicAopProxy.invoke(JdkDynamicAopProxy.java:204)
        at $Proxy55.doWork(Unknown Source)
        at ome.services.util.Executor$Impl.execute(Executor.java:307)
        at ome.services.sessions.SessionManagerImpl.executeCheckPassword(SessionManagerImpl.java:807)
        at ome.services.sessions.SessionManagerImpl.executePasswordCheck(SessionManagerImpl.java:782)
        at ome.services.blitz.fire.PermissionsVerifierI.checkPermissions(PermissionsVerifierI.java:49)
        at Glacier2._PermissionsVerifierDisp.___checkPermissions(_PermissionsVerifierDisp.java:90)

Change History (12)

comment:1 Changed 16 years ago by jmoore

After clearing the password block by first attempting a readOnly=false executeCheckPassword() the next one is:

       at java.net.SocketInputStream.socketRead0(Native Method)
        at java.net.SocketInputStream.read(SocketInputStream.java:129)
        at org.postgresql.core.VisibleBufferedInputStream.readMore(VisibleBufferedInputStream.java:135)
        at org.postgresql.core.VisibleBufferedInputStream.ensureBytes(VisibleBufferedInputStream.java:104)
        at org.postgresql.core.VisibleBufferedInputStream.read(VisibleBufferedInputStream.java:73)
        at org.postgresql.core.PGStream.ReceiveChar(PGStream.java:259)
        at org.postgresql.core.v3.QueryExecutorImpl.processResults(QueryExecutorImpl.java:1182)
        at org.postgresql.core.v3.QueryExecutorImpl.execute(QueryExecutorImpl.java:194)
        - locked <0x00002aaab43c00d0> (a org.postgresql.core.v3.QueryExecutorImpl)
        at org.postgresql.jdbc2.AbstractJdbc2Statement.execute(AbstractJdbc2Statement.java:451)
        at org.postgresql.jdbc2.AbstractJdbc2Statement.executeWithFlags(AbstractJdbc2Statement.java:350)
        at org.postgresql.jdbc2.AbstractJdbc2Statement.executeUpdate(AbstractJdbc2Statement.java:304)
        at org.hibernate.jdbc.NonBatchingBatcher.addToBatch(NonBatchingBatcher.java:23)
        at org.hibernate.persister.entity.AbstractEntityPersister.insert(AbstractEntityPersister.java:2252)
        at org.hibernate.persister.entity.AbstractEntityPersister.insert(AbstractEntityPersister.java:2665)
        at org.hibernate.action.EntityInsertAction.execute(EntityInsertAction.java:60)
        at org.hibernate.engine.ActionQueue.execute(ActionQueue.java:279)
        at org.hibernate.engine.ActionQueue.executeActions(ActionQueue.java:263)
        at org.hibernate.engine.ActionQueue.executeActions(ActionQueue.java:167)
        at org.hibernate.event.def.AbstractFlushingEventListener.performExecutions(AbstractFlushingEventListener.java:298)
        at org.hibernate.event.def.DefaultFlushEventListener.onFlush(DefaultFlushEventListener.java:27)
        at org.hibernate.impl.SessionImpl.flush(SessionImpl.java:1000)
        at ome.logic.UpdateImpl.afterUpdate(UpdateImpl.java:292)
        at ome.logic.UpdateImpl.doAction(UpdateImpl.java:304)
        at ome.logic.UpdateImpl.saveAndReturnObject(UpdateImpl.java:118)
        at ome.security.basic.BasicSecuritySystem.loadEventContext(BasicSecuritySystem.java:340)
        at ome.security.basic.EventHandler.invoke(EventHandler.java:91)
        at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:171)
        at org.springframework.orm.hibernate3.HibernateInterceptor.invoke(HibernateInterceptor.java:111)
        at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:171)
        at org.springframework.transaction.interceptor.TransactionInterceptor.invoke(TransactionInterceptor.java:106)
        at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:171)
        at ome.tools.hibernate.ProxyCleanupFilter$Interceptor.invoke(ProxyCleanupFilter.java:169)
        at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:171)
        at ome.services.util.ServiceHandler.invoke(ServiceHandler.java:97)
        at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:171)
        at org.springframework.aop.framework.JdkDynamicAopProxy.invoke(JdkDynamicAopProxy.java:204)
        at $Proxy55.doWork(Unknown Source)
        at ome.services.util.Executor$Impl.execute(Executor.java:307)
        at ome.services.sessions.SessionManagerImpl.executeUpdate(SessionManagerImpl.java:787)
        at ome.services.sessions.SessionManagerImpl.createSession(SessionManagerImpl.java:270)
        at ome.services.sessions.SessionManagerImpl.create(SessionManagerImpl.java:240)
        at ome.services.blitz.fire.SessionManagerI.create(SessionManagerI.java:140)
        at Glacier2._SessionManagerDisp.___create(_SessionManagerDisp.java:92)

comment:2 Changed 16 years ago by jmoore

  • Description modified (diff)
  • Priority changed from major to critical
  • Summary changed from readOnly = false during checkPassword may be causing periodic DB locks to Periodic database locks high increase under high usage

comment:3 Changed 16 years ago by jmoore

r4094 / r4095 made changes to improve this situation, but lock ups were still occuring as soon as indexing was turned on. The next solution probably will be:

                Statement s = session.connection().createStatement();
                s.execute("set statement_timeout=10000");
                s.execute("set constraints all deferred;");

comment:4 Changed 16 years ago by jmoore

r4110 tried to prevent blocking calls to SessionCache from the indexer, but that was insufficient. r4112 added the constraint deferrable which seems to be working.

comment:5 Changed 16 years ago by jmoore

Various attempts were made to correct this:

  • moving all calls in SessionManagerImpl to single implementations (
  • slowing down the indexer (r4094)
  • moving to deferred constraints (r4117)

Some of these have been rolled back (r4116), since they lead to their own deadlocks. The only solution which can be shown to prevent "Timed out while waiting on exception" is to solve #1266 (<IDLE> in transaction).

comment:6 Changed 16 years ago by jmoore

  • Milestone changed from OMERO-Beta4 to OMERO-Beta4.0.1
  • Summary changed from Periodic database locks high increase under high usage to Periodic database locks increase under high usage due to <IDLE> in transaction

Pushing the COMMIT;BEGIN change to 4.0.1

comment:7 Changed 16 years ago by jmoore

  • Milestone changed from OMERO-Beta4.0.1 to OMERO-Beta4

r4127 commited for testing in 4.0 since more regular usage than stress test was running into the same situation.

comment:8 Changed 16 years ago by jmoore

  • Milestone changed from OMERO-Beta4 to OMERO-Beta4.0.2

Possibly source of warnings:

WARNING:  there is already a transaction in progress
WARNING:  there is already a transaction in progress
WARNING:  there is already a transaction in progress
WARNING:  there is already a transaction in progress
WARNING:  there is already a transaction in progress
WARNING:  there is already a transaction in progress
WARNING:  there is already a transaction in progress
WARNING:  there is already a transaction in progress
WARNING:  there is already a transaction in progress
WARNING:  there is already a transaction in progress
WARNING:  there is already a transaction in progress
WARNING:  there is already a transaction in progress
WARNING:  there is already a transaction in progress
WARNING:  there is already a transaction in progress
...

Need to review.

comment:9 Changed 16 years ago by jmoore

  • Milestone changed from OMERO-Beta4.0.2 to OMERO-Beta4.1

comment:10 Changed 15 years ago by jmoore

Definitely the source of the warnings. After a manual call to "COMMIT", pg automatically inserts a new "BEGIN".

comment:11 Changed 14 years ago by jmoore

r4095 was also related.

comment:12 Changed 13 years ago by jmoore

  • Milestone changed from Unscheduled to OMERO-Beta4.4
  • Resolution set to worksforme
  • Status changed from new to closed

I personally haven't seen any of these issues since probably 4.2. I'm going to close it as "worksforme", though there was obviously a time when it was very much a problem.

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.68638 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!