btm 2.1.x blocks on unregisterUncachedStatement

classic Classic list List threaded Threaded
4 messages Options
Reply | Threaded
Open this post in threaded view
|  
Report Content as Inappropriate

btm 2.1.x blocks on unregisterUncachedStatement

Josh Moore
Background info:
  JDK 1.6.0_24 with -Xmx3072M -XX:MaxPermSize:128m
  BTM 2.1.0 & 2.1.3
  PostgreSQL 8.4.12
  CentOS 6.3

Has anyone ever seen or know perhaps why btm would block on close:


"pool-3-thread-2" prio=10 tid=0x00007fa6f400a000 nid=0x1544 runnable [0x00007fa72c7c8000]
   java.lang.Thread.State: RUNNABLE
        at java.util.ArrayList.remove(ArrayList.java:448)
        at java.util.Collections$SynchronizedCollection.remove(Collections.java:1596)
        - locked <0x00000007e3c37948> (a java.util.Collections$SynchronizedRandomAccessList)
        at bitronix.tm.resource.jdbc.JdbcPooledConnection.unregisterUncachedStatement(JdbcPooledConnection.java:387)
        at bitronix.tm.resource.jdbc.JdbcUncachedPreparedStatementHandle.close(JdbcUncachedPreparedStatementHandle.java:59)
        at sun.reflect.GeneratedMethodAccessor36.invoke(Unknown Source)
        at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
        at java.lang.reflect.Method.invoke(Method.java:616)
        at bitronix.tm.resource.jdbc.BaseProxyHandlerClass.invoke(BaseProxyHandlerClass.java:64)
        at $Proxy57.close(Unknown Source)
        at org.hibernate.jdbc.AbstractBatcher.closePreparedStatement(AbstractBatcher.java:563)
        at org.hibernate.jdbc.AbstractBatcher.closeStatement(AbstractBatcher.java:291)
        at org.hibernate.jdbc.AbstractBatcher.closeQueryStatement(AbstractBatcher.java:307)
        at org.hibernate.jdbc.AbstractBatcher.closeQueryStatement(AbstractBatcher.java:234)
        at org.hibernate.loader.Loader.doQuery(Loader.java:770)
        at org.hibernate.loader.Loader.doQueryAndInitializeNonLazyCollections(Loader.java:270)
        at org.hibernate.loader.Loader.doList(Loader.java:2449)
        at org.hibernate.loader.Loader.listIgnoreQueryCache(Loader.java:2192)
        at org.hibernate.loader.Loader.list(Loader.java:2187)
        at org.hibernate.loader.hql.QueryLoader.list(QueryLoader.java:452)
        at org.hibernate.hql.ast.QueryTranslatorImpl.list(QueryTranslatorImpl.java:363)
        at org.hibernate.engine.query.HQLQueryPlan.performList(HQLQueryPlan.java:196)
        at org.hibernate.impl.SessionImpl.list(SessionImpl.java:1260)
        at org.hibernate.impl.QueryImpl.list(QueryImpl.java:102)
        at ome.services.delete.DeleteStep.findImproperIncomingLinks(DeleteStep.java:129)
        at ome.services.graphs.GraphStep.graphValidation(GraphStep.java:375)
        at ome.services.delete.DeleteStep.action(DeleteStep.java:73)
        at ome.services.graphs.GraphState.execute(GraphState.java:351)
        at ome.services.delete.Deletion.execute(Deletion.java:299)
        at omero.cmd.graphs.DeleteI.step(DeleteI.java:106)
        at omero.cmd.HandleI.steps(HandleI.java:435)
        at omero.cmd.HandleI$1.doWork(HandleI.java:365)
        at omero.cmd.HandleI$1.doWork(HandleI.java:363)
        at sun.reflect.GeneratedMethodAccessor235.invoke(U


This is caused in our server (openmicroscopy.org) when performing a fairly intensive search&delete (on different rows) from 2 separate threads. Once the non-blocked process completes and sufficient time passes (??) the given process will eventually continue and complete.

A typical stacktrace for the other thread might be:

"pool-3-thread-5" prio=10 tid=0x00007fa6f401d800 nid=0x158c runnable [0x00007fa72c3c4000]
   java.lang.Thread.State: RUNNABLE
        at java.net.SocketInputStream.socketRead0(Native Method)
        at java.net.SocketInputStream.read(SocketInputStream.java:146)
        at org.postgresql.core.VisibleBufferedInputStream.readMore(VisibleBufferedInputStream.java:145)
        at org.postgresql.core.VisibleBufferedInputStream.ensureBytes(VisibleBufferedInputStream.java:114)
        at org.postgresql.core.VisibleBufferedInputStream.read(VisibleBufferedInputStream.java:73)
        at org.postgresql.core.PGStream.ReceiveChar(PGStream.java:274)
        at org.postgresql.core.v3.QueryExecutorImpl.processResults(QueryExecutorImpl.java:1661)
        at org.postgresql.core.v3.QueryExecutorImpl.execute(QueryExecutorImpl.java:257)
        - locked <0x00000007e39be018> (a org.postgresql.core.v3.QueryExecutorImpl)
        at org.postgresql.jdbc2.AbstractJdbc2Statement.execute(AbstractJdbc2Statement.java:512)
        at org.postgresql.jdbc2.AbstractJdbc2Statement.executeWithFlags(AbstractJdbc2Statement.java:388)
        at org.postgresql.jdbc2.AbstractJdbc2Statement.executeUpdate(AbstractJdbc2Statement.java:334)
        at sun.reflect.GeneratedMethodAccessor247.invoke(Unknown Source)
        at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
        at java.lang.reflect.Method.invoke(Method.java:616)
        at bitronix.tm.resource.jdbc.BaseProxyHandlerClass.invoke(BaseProxyHandlerClass.java:64)
        at $Proxy57.executeUpdate(Unknown Source)
        at org.hibernate.hql.ast.exec.BasicExecutor.execute(BasicExecutor.java:101)
        at org.hibernate.hql.ast.QueryTranslatorImpl.executeUpdate(QueryTranslatorImpl.java:421)
        at org.hibernate.engine.query.HQLQueryPlan.performExecuteUpdate(HQLQueryPlan.java:283)
        at org.hibernate.impl.SessionImpl.executeUpdate(SessionImpl.java:1280)
        at org.hibernate.impl.QueryImpl.executeUpdate(QueryImpl.java:117)
        at ome.services.delete.DeleteStep.action(DeleteStep.java:79)
        at ome.services.graphs.GraphState.execute(GraphState.java:351)
        at ome.services.delete.Deletion.execute(Deletion.java:299)
        at omero.cmd.graphs.DeleteI.step(DeleteI.java:106)

No other threads are active. The bitronix thread is in TIMED_WAITING:

"bitronix-task-scheduler" daemon prio=10 tid=0x00007fa740fb6800 nid=0x14cc sleeping[0x00007fa72e65d000]
   java.lang.Thread.State: TIMED_WAITING (sleeping)
        at java.lang.Thread.sleep(Native Method)
        at bitronix.tm.timer.TaskScheduler.run(TaskScheduler.java:245)

   Locked ownable synchronizers:
        - None


Cheers & thanks in advanced,
~Josh
---------------------------------------------------------------------
To unsubscribe from this list, please visit:

    http://xircles.codehaus.org/manage_email


Reply | Threaded
Open this post in threaded view
|  
Report Content as Inappropriate

Re: btm 2.1.x blocks on unregisterUncachedStatement

Brett Wooldridge-2
Hi Josh,

Looking at the stacktraces you provided, I can say that BTM is not actually blocked per se.  In the first thread's case, the thread is in the RUNNABLE state, indicating that it is in fact running and not blocked.  What this thread is doing is removing a Statement from an ArrayList.  Removal of an element from an ArrayList requires iteration of the list starting from the first element and proceeding until the element is found or the end of the list is reached.  The relevant code from the JDK ArrayList class is:

             for (int index = 0; index < sizeindex++)
                 if (o.equals(elementData[index])) {
                     fastRemove(index);
                     return true;
                 }

If BTM is actually spending any significant time in this code, the CPU utilization should be extremely high (on one core) because basically it is an unthrottled loop.  And more significantly spending time in this loop would imply that the number of Statements executed on this connection is huge (thousands or tens of thousands).  In your code is this possible?  Is the same connection used to execute thousands of Statements between commits?  If so, I would suggest either 1) enable the BTM prepared statement cache, or 2) commit the transaction every hundred statements or so.

The second thread is also RUNNABLE, and not blocked, and is executing an update statement of some kind (a DELETE as you said), it appears to be waiting to read the result of the delete operation over the wire and is not blocked by anything in BTM.

When you say "after sufficient time passes" it completes.  How much time?  While it is "waiting" can you take three stack dumps, say 1 or 2 seconds apart?  I would be curious to know if the first thread is really constantly looping in the ArrayList.remove() or if it is running through other code paths as well.

Brett



On Tue, Jun 4, 2013 at 5:59 AM, Josh Moore <[hidden email]> wrote:
Background info:
  JDK 1.6.0_24 with -Xmx3072M -XX:MaxPermSize:128m
  BTM 2.1.0 & 2.1.3
  PostgreSQL 8.4.12
  CentOS 6.3

Has anyone ever seen or know perhaps why btm would block on close:


"pool-3-thread-2" prio=10 tid=0x00007fa6f400a000 nid=0x1544 runnable [0x00007fa72c7c8000]
   java.lang.Thread.State: RUNNABLE
        at java.util.ArrayList.remove(ArrayList.java:448)
        at java.util.Collections$SynchronizedCollection.remove(Collections.java:1596)
        - locked <0x00000007e3c37948> (a java.util.Collections$SynchronizedRandomAccessList)
        at bitronix.tm.resource.jdbc.JdbcPooledConnection.unregisterUncachedStatement(JdbcPooledConnection.java:387)
        at bitronix.tm.resource.jdbc.JdbcUncachedPreparedStatementHandle.close(JdbcUncachedPreparedStatementHandle.java:59)
        at sun.reflect.GeneratedMethodAccessor36.invoke(Unknown Source)
        at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
        at java.lang.reflect.Method.invoke(Method.java:616)
        at bitronix.tm.resource.jdbc.BaseProxyHandlerClass.invoke(BaseProxyHandlerClass.java:64)
        at $Proxy57.close(Unknown Source)
        at org.hibernate.jdbc.AbstractBatcher.closePreparedStatement(AbstractBatcher.java:563)
        at org.hibernate.jdbc.AbstractBatcher.closeStatement(AbstractBatcher.java:291)
        at org.hibernate.jdbc.AbstractBatcher.closeQueryStatement(AbstractBatcher.java:307)
        at org.hibernate.jdbc.AbstractBatcher.closeQueryStatement(AbstractBatcher.java:234)
        at org.hibernate.loader.Loader.doQuery(Loader.java:770)
        at org.hibernate.loader.Loader.doQueryAndInitializeNonLazyCollections(Loader.java:270)
        at org.hibernate.loader.Loader.doList(Loader.java:2449)
        at org.hibernate.loader.Loader.listIgnoreQueryCache(Loader.java:2192)
        at org.hibernate.loader.Loader.list(Loader.java:2187)
        at org.hibernate.loader.hql.QueryLoader.list(QueryLoader.java:452)
        at org.hibernate.hql.ast.QueryTranslatorImpl.list(QueryTranslatorImpl.java:363)
        at org.hibernate.engine.query.HQLQueryPlan.performList(HQLQueryPlan.java:196)
        at org.hibernate.impl.SessionImpl.list(SessionImpl.java:1260)
        at org.hibernate.impl.QueryImpl.list(QueryImpl.java:102)
        at ome.services.delete.DeleteStep.findImproperIncomingLinks(DeleteStep.java:129)
        at ome.services.graphs.GraphStep.graphValidation(GraphStep.java:375)
        at ome.services.delete.DeleteStep.action(DeleteStep.java:73)
        at ome.services.graphs.GraphState.execute(GraphState.java:351)
        at ome.services.delete.Deletion.execute(Deletion.java:299)
        at omero.cmd.graphs.DeleteI.step(DeleteI.java:106)
        at omero.cmd.HandleI.steps(HandleI.java:435)
        at omero.cmd.HandleI$1.doWork(HandleI.java:365)
        at omero.cmd.HandleI$1.doWork(HandleI.java:363)
        at sun.reflect.GeneratedMethodAccessor235.invoke(U


This is caused in our server (openmicroscopy.org) when performing a fairly intensive search&delete (on different rows) from 2 separate threads. Once the non-blocked process completes and sufficient time passes (??) the given process will eventually continue and complete.

A typical stacktrace for the other thread might be:

"pool-3-thread-5" prio=10 tid=0x00007fa6f401d800 nid=0x158c runnable [0x00007fa72c3c4000]
   java.lang.Thread.State: RUNNABLE
        at java.net.SocketInputStream.socketRead0(Native Method)
        at java.net.SocketInputStream.read(SocketInputStream.java:146)
        at org.postgresql.core.VisibleBufferedInputStream.readMore(VisibleBufferedInputStream.java:145)
        at org.postgresql.core.VisibleBufferedInputStream.ensureBytes(VisibleBufferedInputStream.java:114)
        at org.postgresql.core.VisibleBufferedInputStream.read(VisibleBufferedInputStream.java:73)
        at org.postgresql.core.PGStream.ReceiveChar(PGStream.java:274)
        at org.postgresql.core.v3.QueryExecutorImpl.processResults(QueryExecutorImpl.java:1661)
        at org.postgresql.core.v3.QueryExecutorImpl.execute(QueryExecutorImpl.java:257)
        - locked <0x00000007e39be018> (a org.postgresql.core.v3.QueryExecutorImpl)
        at org.postgresql.jdbc2.AbstractJdbc2Statement.execute(AbstractJdbc2Statement.java:512)
        at org.postgresql.jdbc2.AbstractJdbc2Statement.executeWithFlags(AbstractJdbc2Statement.java:388)
        at org.postgresql.jdbc2.AbstractJdbc2Statement.executeUpdate(AbstractJdbc2Statement.java:334)
        at sun.reflect.GeneratedMethodAccessor247.invoke(Unknown Source)
        at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
        at java.lang.reflect.Method.invoke(Method.java:616)
        at bitronix.tm.resource.jdbc.BaseProxyHandlerClass.invoke(BaseProxyHandlerClass.java:64)
        at $Proxy57.executeUpdate(Unknown Source)
        at org.hibernate.hql.ast.exec.BasicExecutor.execute(BasicExecutor.java:101)
        at org.hibernate.hql.ast.QueryTranslatorImpl.executeUpdate(QueryTranslatorImpl.java:421)
        at org.hibernate.engine.query.HQLQueryPlan.performExecuteUpdate(HQLQueryPlan.java:283)
        at org.hibernate.impl.SessionImpl.executeUpdate(SessionImpl.java:1280)
        at org.hibernate.impl.QueryImpl.executeUpdate(QueryImpl.java:117)
        at ome.services.delete.DeleteStep.action(DeleteStep.java:79)
        at ome.services.graphs.GraphState.execute(GraphState.java:351)
        at ome.services.delete.Deletion.execute(Deletion.java:299)
        at omero.cmd.graphs.DeleteI.step(DeleteI.java:106)

No other threads are active. The bitronix thread is in TIMED_WAITING:

"bitronix-task-scheduler" daemon prio=10 tid=0x00007fa740fb6800 nid=0x14cc sleeping[0x00007fa72e65d000]
   java.lang.Thread.State: TIMED_WAITING (sleeping)
        at java.lang.Thread.sleep(Native Method)
        at bitronix.tm.timer.TaskScheduler.run(TaskScheduler.java:245)

   Locked ownable synchronizers:
        - None


Cheers & thanks in advanced,
~Josh
---------------------------------------------------------------------
To unsubscribe from this list, please visit:

    http://xircles.codehaus.org/manage_email



Reply | Threaded
Open this post in threaded view
|  
Report Content as Inappropriate

Re: btm 2.1.x blocks on unregisterUncachedStatement

Josh Moore

On Jun 4, 2013, at 3:21 AM, Brett Wooldridge wrote:

> Hi Josh,

Hi Brett,

tl;dr: Suggestion worked. Thanks!


> Looking at the stacktraces you provided, I can say that BTM is not actually
> blocked per se.  In the first thread's case, the thread is in the RUNNABLE
> state, indicating that it is in fact running and not blocked.

Sorry, yes. "Spending ton of time" is what I should have said.


> What this
> thread is doing is removing a Statement from an ArrayList.  Removal of an
> element from an ArrayList requires iteration of the list starting from the
> first element and proceeding until the element is found or the end of the
> list is reached.

...

> If BTM is actually spending any significant time in this code, the CPU
> utilization should be extremely high (on one core) because basically it is
> an unthrottled loop.

Matches observations.


> And more significantly spending time in this loop
> would imply that the number of Statements executed on this connection is
> huge (thousands or tens of thousands).  In your code is this possible? Is
> the same connection used to execute thousands of Statements between
> commits?

Definitely.


> If so, I would suggest either 1) enable the BTM prepared
> statement cache, or 2) commit the transaction every hundred statements or
> so.


Unfortunately, committing isn't possible because we're performing rollbacks throughout the procedure. I enabled the BTM statement cache which seems to have solved the issue:

  https://github.com/openmicroscopy/openmicroscopy/pull/1243


> ...
>
> When you say "after sufficient time passes" it completes.  How much time?
> While it is "waiting" can you take three stack dumps, say 1 or 2 seconds
> apart?  I would be curious to know if the first thread is really constantly
> looping in the ArrayList.remove() or if it is running through other code
> paths as well.

In poor-man's-profiling via jstack, I couldn't catch any other activity. If it's of use, I'm happy to revert, reproduce and check for any given behavior.


> Brett

Again many thanks,
~J.


P.S. Are there any general guidelines on the limits to preparedStatementCacheSize? For Oracle, I read one connection was held per statement. Any similar limit for PostgreSQL?


> On Tue, Jun 4, 2013 at 5:59 AM, Josh Moore <[hidden email]> wrote:
>
>> Background info:
>>  JDK 1.6.0_24 with -Xmx3072M -XX:MaxPermSize:128m
>>  BTM 2.1.0 & 2.1.3
>>  PostgreSQL 8.4.12
>>  CentOS 6.3
>>
>> Has anyone ever seen or know perhaps why btm would block on close:
>>
>>
>> "pool-3-thread-2" prio=10 tid=0x00007fa6f400a000 nid=0x1544 runnable
>> [0x00007fa72c7c8000]
>>   java.lang.Thread.State: RUNNABLE
>>        at java.util.ArrayList.remove(ArrayList.java:448)
>>        at
>> java.util.Collections$SynchronizedCollection.remove(Collections.java:1596)
>>        - locked <0x00000007e3c37948> (a
>> java.util.Collections$SynchronizedRandomAccessList)
>>
...

>>
>>
>> This is caused in our server (openmicroscopy.org) when performing a
>> fairly intensive search&delete (on different rows) from 2 separate threads.
>> Once the non-blocked process completes and sufficient time passes (??) the
>> given process will eventually continue and complete.
>>
>> A typical stacktrace for the other thread might be:
>>
>> "pool-3-thread-5" prio=10 tid=0x00007fa6f401d800 nid=0x158c runnable
>> [0x00007fa72c3c4000]
>>   java.lang.Thread.State: RUNNABLE
>>        at java.net.SocketInputStream.socketRead0(Native Method)
>>
>> Cheers & thanks in advanced,
>> ~Josh


---------------------------------------------------------------------
To unsubscribe from this list, please visit:

    http://xircles.codehaus.org/manage_email


Reply | Threaded
Open this post in threaded view
|  
Report Content as Inappropriate

Re: btm 2.1.x blocks on unregisterUncachedStatement

Brett Wooldridge-2
Hi Josh,

>Are there any general guidelines on the limits to preparedStatementCacheSize? For Oracle, I read one
>connection was held per statement. Any similar limit for PostgreSQL?

In Oracle (and Apache Derby, for example), prepared statements are held in a shared pool across DB connections.  In PostgreSQL, prepared statements are cached per-connection, and discarded when the connection is closed -- or when the statement itself is closed.  There is actually [a little] more work to do with PostgreSQL to enable prepared statement caching ...
see here:


Slightly more complex, but advised if you do encounter performance issues is PostgreSQL Query Cache:


However, because connections are pooled in BTM, and statements can be cached (are never really closed unless the connections closes or cache overflows), if you configure the standard caching you should be fine.

Regards,
Brett



On Mon, Jun 10, 2013 at 11:42 PM, Josh Moore <[hidden email]> wrote:

On Jun 4, 2013, at 3:21 AM, Brett Wooldridge wrote:

> Hi Josh,

Hi Brett,

tl;dr: Suggestion worked. Thanks!


> Looking at the stacktraces you provided, I can say that BTM is not actually
> blocked per se.  In the first thread's case, the thread is in the RUNNABLE
> state, indicating that it is in fact running and not blocked.

Sorry, yes. "Spending ton of time" is what I should have said.


> What this
> thread is doing is removing a Statement from an ArrayList.  Removal of an
> element from an ArrayList requires iteration of the list starting from the
> first element and proceeding until the element is found or the end of the
> list is reached.

...

> If BTM is actually spending any significant time in this code, the CPU
> utilization should be extremely high (on one core) because basically it is
> an unthrottled loop.

Matches observations.


> And more significantly spending time in this loop
> would imply that the number of Statements executed on this connection is
> huge (thousands or tens of thousands).  In your code is this possible? Is
> the same connection used to execute thousands of Statements between
> commits?

Definitely.


> If so, I would suggest either 1) enable the BTM prepared
> statement cache, or 2) commit the transaction every hundred statements or
> so.


Unfortunately, committing isn't possible because we're performing rollbacks throughout the procedure. I enabled the BTM statement cache which seems to have solved the issue:

  https://github.com/openmicroscopy/openmicroscopy/pull/1243


> ...
>
> When you say "after sufficient time passes" it completes.  How much time?
> While it is "waiting" can you take three stack dumps, say 1 or 2 seconds
> apart?  I would be curious to know if the first thread is really constantly
> looping in the ArrayList.remove() or if it is running through other code
> paths as well.

In poor-man's-profiling via jstack, I couldn't catch any other activity. If it's of use, I'm happy to revert, reproduce and check for any given behavior.


> Brett

Again many thanks,
~J.


P.S. Are there any general guidelines on the limits to preparedStatementCacheSize? For Oracle, I read one connection was held per statement. Any similar limit for PostgreSQL?


> On Tue, Jun 4, 2013 at 5:59 AM, Josh Moore <[hidden email]> wrote:
>
>> Background info:
>>  JDK 1.6.0_24 with -Xmx3072M -XX:MaxPermSize:128m
>>  BTM 2.1.0 & 2.1.3
>>  PostgreSQL 8.4.12
>>  CentOS 6.3
>>
>> Has anyone ever seen or know perhaps why btm would block on close:
>>
>>
>> "pool-3-thread-2" prio=10 tid=0x00007fa6f400a000 nid=0x1544 runnable
>> [0x00007fa72c7c8000]
>>   java.lang.Thread.State: RUNNABLE
>>        at java.util.ArrayList.remove(ArrayList.java:448)
>>        at
>> java.util.Collections$SynchronizedCollection.remove(Collections.java:1596)
>>        - locked <0x00000007e3c37948> (a
>> java.util.Collections$SynchronizedRandomAccessList)
>>
...
>>
>>
>> This is caused in our server (openmicroscopy.org) when performing a
>> fairly intensive search&delete (on different rows) from 2 separate threads.
>> Once the non-blocked process completes and sufficient time passes (??) the
>> given process will eventually continue and complete.
>>
>> A typical stacktrace for the other thread might be:
>>
>> "pool-3-thread-5" prio=10 tid=0x00007fa6f401d800 nid=0x158c runnable
>> [0x00007fa72c3c4000]
>>   java.lang.Thread.State: RUNNABLE
>>        at java.net.SocketInputStream.socketRead0(Native Method)
>>
>> Cheers & thanks in advanced,
>> ~Josh


---------------------------------------------------------------------
To unsubscribe from this list, please visit:

    http://xircles.codehaus.org/manage_email



Loading...