10 Replies Latest reply: Aug 12, 2013 4:35 PM by dsurber RSS

    Universal Connection Pool (UCP) causes thread contention when using validate connection

    982811

      Hi,

       

      I'm using UCP (11.2.0.3.0) and Oracle Driver JDBC (11.2.0.3).

       

      My pool configuration is:

       

      <url>....</url>
      <user>...</user>
      <password>...</password>
      <minPoolSize>50</minPoolSize>
      <maxPoolSize>300</maxPoolSize>
      <initialPoolSize>50</initialPoolSize>
      <inactiveConnectionTimeout>600</inactiveConnectionTimeout>
      <timeToLiveConnectionTimeout>60</timeToLiveConnectionTimeout>
      <abandonedConnectionTimeout>30</abandonedConnectionTimeout>
      <connectionWaitTimeout>5</connectionWaitTimeout>
      <timeoutCheckInterval>10</timeoutCheckInterval>
      <validateConnectionOnBorrow>true</validateConnectionOnBorrow>
      <maxConnectionReuseTime>0</maxConnectionReuseTime>
      <maxConnectionReuseCount>10000000</maxConnectionReuseCount>
      
      

       

      My system uses the connections often and when validation is enabled it is possible to observe a high contention in method "getConnection".

       

       

       

      An operation that takes 1 ms on average without validation. With the validation passes to more than 30 ms.

       

       

       

      This bug is known? Does anyone know how to solve?

       

       

       

      PS. Setting property "sqlForValidateConnection" has same effect.

       

      Thanks!

        • 1. Re: Universal Connection Pool (UCP) causes thread contention when using validate connection
          Joe Weinstein-Oracle

          By 'contention' do you mean you have thread dumps showing lots of threads blocked on one thread?

          Or do you really just mean that it takes a lot longer to get a connection when you configure validation?

          • 2. Re: Universal Connection Pool (UCP) causes thread contention when using validate connection
            982811

            Threads blocked by one thread.

             

            I think the UCP method that get and validates the connection is synchronized. And this is causing the contention of threads.

            • 3. Re: Universal Connection Pool (UCP) causes thread contention when using validate connection
              Joe Weinstein-Oracle

              Show the blocking thread and one blocked thread. I would seem unnecessary to synchronize while validating a connection...

              • 4. Re: Universal Connection Pool (UCP) causes thread contention when using validate connection
                982811

                I think that method should be like this:

                 

                {code}

                ...

                public Connection getConnection() {

                     Connection conn = null;

                     synchronized(this) {  // threads are blocked here

                          while(getNumConnectionsAvailable() > 0) {

                               conn = getConnectionFromPool(); // Recovery connection from pool, if necessary also creates

                               if (validateConnectionOnBorrow) { // When is false, no contention occurs.

                                    if (validateConnection(conn)) { // this operation must be very slow

                                         return conn;

                                    } else {

                                         removeConnectionFromPool(conn);

                                    }

                               } else {

                                    return conn;

                               }

                          }

                     }

                    throw new ConnectionsNotAvailable();

                }

                ...

                {code}

                • 5. Re: Universal Connection Pool (UCP) causes thread contention when using validate connection
                  Joe Weinstein-Oracle

                  Well, the same code is being called whether there is validation going on or not, so what

                  you are primarily suffering is that the getConnection() method takes a long time to validate

                  a connection, compounded by the fact that it is done in an over-synchronized block.

                  Are you using the latest version of UCP?

                  • 6. Re: Universal Connection Pool (UCP) causes thread contention when using validate connection
                    982811

                    Folows thread dump info:

                     

                    Validate Enable, one thread in RUNNABLE State and others BLOCKED (Part of thread dump):

                     

                    "Thread-52" prio=6 tid=0x0000000007c98800 nid=0x1c9c waiting for monitor entry [0x000000000c93f000]

                       java.lang.Thread.State: BLOCKED (on object monitor)

                      at oracle.ucp.common.UniversalConnectionPoolImpl.borrowConnectionWithoutCountingRequests(UniversalConnectionPoolImpl.java:335)

                      - waiting to lock <0x00000000c3516348> (a oracle.ucp.jdbc.oracle.OracleConnectionConnectionPool)

                      at oracle.ucp.common.UniversalConnectionPoolImpl.borrowConnection(UniversalConnectionPoolImpl.java:142)

                      at oracle.ucp.jdbc.JDBCConnectionPool.borrowConnection(JDBCConnectionPool.java:157)

                      at oracle.ucp.jdbc.PoolDataSourceImpl.getConnection(PoolDataSourceImpl.java:916)

                      at oracle.ucp.jdbc.PoolDataSourceImpl.getConnection(PoolDataSourceImpl.java:863)

                      at oracle.ucp.jdbc.PoolDataSourceImpl.getConnection(PoolDataSourceImpl.java:855)

                      at myorg.oracle.jdbc.test.Main$1.run(Main.java:84)

                      at java.lang.Thread.run(Thread.java:662)

                     

                       Locked ownable synchronizers:

                      - None

                     

                    "Thread-51" prio=6 tid=0x0000000007c97800 nid=0x22ec runnable [0x000000000c83e000]

                       java.lang.Thread.State: RUNNABLE

                      at java.net.SocketInputStream.socketRead0(Native Method)

                      at java.net.SocketInputStream.read(SocketInputStream.java:129)

                      at oracle.net.ns.Packet.receive(Unknown Source)

                      at oracle.net.ns.DataPacket.receive(Unknown Source)

                      at oracle.net.ns.NetInputStream.getNextPacket(Unknown Source)

                      at oracle.net.ns.NetInputStream.read(Unknown Source)

                      at oracle.net.ns.NetInputStream.read(Unknown Source)

                      at oracle.net.ns.NetInputStream.read(Unknown Source)

                      at oracle.jdbc.driver.T4CMAREngine.unmarshalUB1(T4CMAREngine.java:1104)

                      at oracle.jdbc.driver.T4CMAREngine.unmarshalSB1(T4CMAREngine.java:1075)

                      at oracle.jdbc.driver.T4C8Oall.receive(T4C8Oall.java:480)

                      at oracle.jdbc.driver.T4CPreparedStatement.doOall8(T4CPreparedStatement.java:216)

                      at oracle.jdbc.driver.T4CPreparedStatement.executeForRows(T4CPreparedStatement.java:966)

                      at oracle.jdbc.driver.OracleStatement.doExecuteWithTimeout(OracleStatement.java:1170)

                      at oracle.jdbc.driver.OraclePreparedStatement.executeInternal(OraclePreparedStatement.java:3339)

                      at oracle.jdbc.driver.OraclePreparedStatement.execute(OraclePreparedStatement.java:3445)

                      - locked <0x00000000ebfa3be8> (a oracle.jdbc.driver.T4CPreparedStatement)

                      - locked <0x00000000ef8749a8> (a oracle.jdbc.driver.T4CConnection)

                      at sun.reflect.GeneratedMethodAccessor34.invoke(Unknown Source)

                      at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)

                      at java.lang.reflect.Method.invoke(Method.java:597)

                      at oracle.ucp.jdbc.proxy.StatementProxyFactory.invoke(StatementProxyFactory.java:230)

                      at oracle.ucp.jdbc.proxy.PreparedStatementProxyFactory.invoke(PreparedStatementProxyFactory.java:124)

                      at oracle.jdbc.driver.$Proxy17.execute(Unknown Source)

                      at myorg.oracle.jdbc.test.Main$1.run(Main.java:84)

                      at java.lang.Thread.run(Thread.java:662)

                     

                       Locked ownable synchronizers:

                      - None

                     

                    "Thread-50" prio=6 tid=0x0000000007c97000 nid=0x1468 waiting for monitor entry [0x000000000c73f000]

                       java.lang.Thread.State: BLOCKED (on object monitor)

                      at oracle.ucp.common.UniversalConnectionPoolImpl.returnConnection(UniversalConnectionPoolImpl.java:547)

                      - waiting to lock <0x00000000c3516348> (a oracle.ucp.jdbc.oracle.OracleConnectionConnectionPool)

                      at oracle.ucp.jdbc.proxy.JDBCConnectionProxyFactory.invoke(JDBCConnectionProxyFactory.java:235)

                      - locked <0x00000000ebce2908> (a java.lang.Boolean)

                      at com.sun.proxy.$Proxy16.close(Unknown Source)

                      at myorg.oracle.jdbc.test.Main$1.run(Main.java:87)

                      at java.lang.Thread.run(Thread.java:662)

                     

                       Locked ownable synchronizers:

                      - None

                     

                    "Thread-49" prio=6 tid=0x0000000007c96000 nid=0x1ee8 waiting for monitor entry [0x000000000c63f000]

                       java.lang.Thread.State: BLOCKED (on object monitor)

                      at oracle.ucp.common.UniversalConnectionPoolImpl.returnConnection(UniversalConnectionPoolImpl.java:547)

                      - waiting to lock <0x00000000c3516348> (a oracle.ucp.jdbc.oracle.OracleConnectionConnectionPool)

                      at oracle.ucp.jdbc.proxy.JDBCConnectionProxyFactory.invoke(JDBCConnectionProxyFactory.java:235)

                      - locked <0x00000000ebd9f000> (a java.lang.Boolean)

                      at com.sun.proxy.$Proxy16.close(Unknown Source)

                      at myorg.oracle.jdbc.test.Main$1.run(Main.java:87)

                      at java.lang.Thread.run(Thread.java:662)

                     

                       Locked ownable synchronizers:

                      - None

                     

                     

                    Validate Disable, All threads in RUNNABLE State (part of thread dump):

                     

                    "Thread-53" prio=6 tid=0x0000000007bc6800 nid=0x217c runnable [0x000000000baee000]

                       java.lang.Thread.State: RUNNABLE

                      at java.net.SocketInputStream.socketRead0(Native Method)

                      at java.net.SocketInputStream.read(SocketInputStream.java:129)

                      at oracle.net.ns.Packet.receive(Unknown Source)

                      at oracle.net.ns.DataPacket.receive(Unknown Source)

                      at oracle.net.ns.NetInputStream.getNextPacket(Unknown Source)

                      at oracle.net.ns.NetInputStream.read(Unknown Source)

                      at oracle.net.ns.NetInputStream.read(Unknown Source)

                      at oracle.net.ns.NetInputStream.read(Unknown Source)

                      at oracle.jdbc.driver.T4CMAREngine.unmarshalUB1(T4CMAREngine.java:1104)

                      at oracle.jdbc.driver.T4CMAREngine.unmarshalSB1(T4CMAREngine.java:1075)

                      at oracle.jdbc.driver.T4C8Oall.receive(T4C8Oall.java:480)

                      at oracle.jdbc.driver.T4CPreparedStatement.doOall8(T4CPreparedStatement.java:216)

                      at oracle.jdbc.driver.T4CPreparedStatement.executeForRows(T4CPreparedStatement.java:966)

                      at oracle.jdbc.driver.OracleStatement.doExecuteWithTimeout(OracleStatement.java:1170)

                      at oracle.jdbc.driver.OraclePreparedStatement.executeInternal(OraclePreparedStatement.java:3339)

                      at oracle.jdbc.driver.OraclePreparedStatement.execute(OraclePreparedStatement.java:3445)

                      - locked <0x00000000ebde6bb0> (a oracle.jdbc.driver.T4CPreparedStatement)

                      - locked <0x00000000eca64e70> (a oracle.jdbc.driver.T4CConnection)

                      at sun.reflect.GeneratedMethodAccessor36.invoke(Unknown Source)

                      at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)

                      at java.lang.reflect.Method.invoke(Method.java:597)

                      at oracle.ucp.jdbc.proxy.StatementProxyFactory.invoke(StatementProxyFactory.java:230)

                      at oracle.ucp.jdbc.proxy.PreparedStatementProxyFactory.invoke(PreparedStatementProxyFactory.java:124)

                      at oracle.jdbc.driver.$Proxy17.execute(Unknown Source)

                      at myorg.oracle.jdbc.test.Main$1.run(Main.java:86)

                      at java.lang.Thread.run(Thread.java:662)

                     

                       Locked ownable synchronizers:

                      - None

                     

                    "Thread-52" prio=6 tid=0x0000000007bc5800 nid=0x1a5c runnable [0x000000000b9ee000]

                       java.lang.Thread.State: RUNNABLE

                      at java.net.SocketInputStream.socketRead0(Native Method)

                      at java.net.SocketInputStream.read(SocketInputStream.java:129)

                      at oracle.net.ns.Packet.receive(Unknown Source)

                      at oracle.net.ns.DataPacket.receive(Unknown Source)

                      at oracle.net.ns.NetInputStream.getNextPacket(Unknown Source)

                      at oracle.net.ns.NetInputStream.read(Unknown Source)

                      at oracle.net.ns.NetInputStream.read(Unknown Source)

                      at oracle.net.ns.NetInputStream.read(Unknown Source)

                      at oracle.jdbc.driver.T4CMAREngine.unmarshalUB1(T4CMAREngine.java:1104)

                      at oracle.jdbc.driver.T4CMAREngine.unmarshalSB1(T4CMAREngine.java:1075)

                      at oracle.jdbc.driver.T4C8Oall.receive(T4C8Oall.java:480)

                      at oracle.jdbc.driver.T4CPreparedStatement.doOall8(T4CPreparedStatement.java:216)

                      at oracle.jdbc.driver.T4CPreparedStatement.executeForRows(T4CPreparedStatement.java:966)

                      at oracle.jdbc.driver.OracleStatement.doExecuteWithTimeout(OracleStatement.java:1170)

                      at oracle.jdbc.driver.OraclePreparedStatement.executeInternal(OraclePreparedStatement.java:3339)

                      at oracle.jdbc.driver.OraclePreparedStatement.execute(OraclePreparedStatement.java:3445)

                      - locked <0x00000000ebe41630> (a oracle.jdbc.driver.T4CPreparedStatement)

                      - locked <0x00000000ecc9bae8> (a oracle.jdbc.driver.T4CConnection)

                      at sun.reflect.GeneratedMethodAccessor36.invoke(Unknown Source)

                      at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)

                      at java.lang.reflect.Method.invoke(Method.java:597)

                      at oracle.ucp.jdbc.proxy.StatementProxyFactory.invoke(StatementProxyFactory.java:230)

                      at oracle.ucp.jdbc.proxy.PreparedStatementProxyFactory.invoke(PreparedStatementProxyFactory.java:124)

                      at oracle.jdbc.driver.$Proxy17.execute(Unknown Source)

                      at myorg.oracle.jdbc.test.Main$1.run(Main.java:86)

                      at java.lang.Thread.run(Thread.java:662)

                     

                       Locked ownable synchronizers:

                      - None

                     

                    "Thread-51" prio=6 tid=0x0000000007bc5000 nid=0x1ffc runnable [0x000000000b8ee000]

                       java.lang.Thread.State: RUNNABLE

                      at java.net.SocketInputStream.socketRead0(Native Method)

                      at java.net.SocketInputStream.read(SocketInputStream.java:129)

                      at oracle.net.ns.Packet.receive(Unknown Source)

                      at oracle.net.ns.DataPacket.receive(Unknown Source)

                      at oracle.net.ns.NetInputStream.getNextPacket(Unknown Source)

                      at oracle.net.ns.NetInputStream.read(Unknown Source)

                      at oracle.net.ns.NetInputStream.read(Unknown Source)

                      at oracle.net.ns.NetInputStream.read(Unknown Source)

                      at oracle.jdbc.driver.T4CMAREngine.unmarshalUB1(T4CMAREngine.java:1104)

                      at oracle.jdbc.driver.T4CMAREngine.unmarshalSB1(T4CMAREngine.java:1075)

                      at oracle.jdbc.driver.T4C8Oall.receive(T4C8Oall.java:480)

                      at oracle.jdbc.driver.T4CPreparedStatement.doOall8(T4CPreparedStatement.java:216)

                      at oracle.jdbc.driver.T4CPreparedStatement.executeForRows(T4CPreparedStatement.java:966)

                      at oracle.jdbc.driver.OracleStatement.doExecuteWithTimeout(OracleStatement.java:1170)

                      at oracle.jdbc.driver.OraclePreparedStatement.executeInternal(OraclePreparedStatement.java:3339)

                      at oracle.jdbc.driver.OraclePreparedStatement.execute(OraclePreparedStatement.java:3445)

                      - locked <0x00000000ebdf99a0> (a oracle.jdbc.driver.T4CPreparedStatement)

                      - locked <0x00000000eccb89d8> (a oracle.jdbc.driver.T4CConnection)

                      at sun.reflect.GeneratedMethodAccessor36.invoke(Unknown Source)

                      at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)

                      at java.lang.reflect.Method.invoke(Method.java:597)

                      at oracle.ucp.jdbc.proxy.StatementProxyFactory.invoke(StatementProxyFactory.java:230)

                      at oracle.ucp.jdbc.proxy.PreparedStatementProxyFactory.invoke(PreparedStatementProxyFactory.java:124)

                      at oracle.jdbc.driver.$Proxy17.execute(Unknown Source)

                      at myorg.oracle.jdbc.test.Main$1.run(Main.java:86)

                      at java.lang.Thread.run(Thread.java:662)

                     

                     

                       Locked ownable synchronizers:

                      - None

                     

                    "Thread-50" prio=6 tid=0x0000000007bc4000 nid=0x1010 runnable [0x000000000b7ef000]

                       java.lang.Thread.State: RUNNABLE

                      at java.net.SocketInputStream.socketRead0(Native Method)

                      at java.net.SocketInputStream.read(SocketInputStream.java:129)

                      at oracle.net.ns.Packet.receive(Unknown Source)

                      at oracle.net.ns.DataPacket.receive(Unknown Source)

                      at oracle.net.ns.NetInputStream.getNextPacket(Unknown Source)

                      at oracle.net.ns.NetInputStream.read(Unknown Source)

                      at oracle.net.ns.NetInputStream.read(Unknown Source)

                      at oracle.net.ns.NetInputStream.read(Unknown Source)

                      at oracle.jdbc.driver.T4CMAREngine.unmarshalUB1(T4CMAREngine.java:1104)

                      at oracle.jdbc.driver.T4CMAREngine.unmarshalSB1(T4CMAREngine.java:1075)

                      at oracle.jdbc.driver.T4C8Oall.receive(T4C8Oall.java:480)

                      at oracle.jdbc.driver.T4CPreparedStatement.doOall8(T4CPreparedStatement.java:216)

                      at oracle.jdbc.driver.T4CPreparedStatement.executeForRows(T4CPreparedStatement.java:966)

                      at oracle.jdbc.driver.OracleStatement.doExecuteWithTimeout(OracleStatement.java:1170)

                      at oracle.jdbc.driver.OraclePreparedStatement.executeInternal(OraclePreparedStatement.java:3339)

                      at oracle.jdbc.driver.OraclePreparedStatement.execute(OraclePreparedStatement.java:3445)

                      - locked <0x00000000ebdc8298> (a oracle.jdbc.driver.T4CPreparedStatement)

                      - locked <0x00000000ec9e1278> (a oracle.jdbc.driver.T4CConnection)

                      at sun.reflect.GeneratedMethodAccessor36.invoke(Unknown Source)

                      at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)

                      at java.lang.reflect.Method.invoke(Method.java:597)

                      at oracle.ucp.jdbc.proxy.StatementProxyFactory.invoke(StatementProxyFactory.java:230)

                      at oracle.ucp.jdbc.proxy.PreparedStatementProxyFactory.invoke(PreparedStatementProxyFactory.java:124)

                      at oracle.jdbc.driver.$Proxy17.execute(Unknown Source)

                      at myorg.oracle.jdbc.test.Main$1.run(Main.java:86)

                      at java.lang.Thread.run(Thread.java:662)

                     

                     

                       Locked ownable synchronizers:

                      - None

                     

                    "Thread-49" prio=6 tid=0x0000000007b1f800 nid=0x19c8 runnable [0x000000000b6ee000]

                       java.lang.Thread.State: RUNNABLE

                      at java.net.SocketInputStream.socketRead0(Native Method)

                      at java.net.SocketInputStream.read(SocketInputStream.java:129)

                      at oracle.net.ns.Packet.receive(Unknown Source)

                      at oracle.net.ns.DataPacket.receive(Unknown Source)

                      at oracle.net.ns.NetInputStream.getNextPacket(Unknown Source)

                      at oracle.net.ns.NetInputStream.read(Unknown Source)

                      at oracle.net.ns.NetInputStream.read(Unknown Source)

                      at oracle.net.ns.NetInputStream.read(Unknown Source)

                      at oracle.jdbc.driver.T4CMAREngine.unmarshalUB1(T4CMAREngine.java:1104)

                      at oracle.jdbc.driver.T4CMAREngine.unmarshalSB1(T4CMAREngine.java:1075)

                      at oracle.jdbc.driver.T4C8Oall.receive(T4C8Oall.java:480)

                      at oracle.jdbc.driver.T4CPreparedStatement.doOall8(T4CPreparedStatement.java:216)

                      at oracle.jdbc.driver.T4CPreparedStatement.executeForRows(T4CPreparedStatement.java:966)

                      at oracle.jdbc.driver.OracleStatement.doExecuteWithTimeout(OracleStatement.java:1170)

                      at oracle.jdbc.driver.OraclePreparedStatement.executeInternal(OraclePreparedStatement.java:3339)

                      at oracle.jdbc.driver.OraclePreparedStatement.execute(OraclePreparedStatement.java:3445)

                      - locked <0x00000000ebf0bf48> (a oracle.jdbc.driver.T4CPreparedStatement)

                      - locked <0x00000000ecc245c8> (a oracle.jdbc.driver.T4CConnection)

                      at sun.reflect.GeneratedMethodAccessor36.invoke(Unknown Source)

                      at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)

                      at java.lang.reflect.Method.invoke(Method.java:597)

                      at oracle.ucp.jdbc.proxy.StatementProxyFactory.invoke(StatementProxyFactory.java:230)

                      at oracle.ucp.jdbc.proxy.PreparedStatementProxyFactory.invoke(PreparedStatementProxyFactory.java:124)

                      at oracle.jdbc.driver.$Proxy17.execute(Unknown Source)

                      at myorg.oracle.jdbc.test.Main$1.run(Main.java:86)

                      at java.lang.Thread.run(Thread.java:662)

                     

                       Locked ownable synchronizers:

                      - None

                    • 7. Re: Universal Connection Pool (UCP) causes thread contention when using validate connection
                      982811

                      I'm using the UCP version 11.2.0.3.

                      My Oracle Database is 11g.


                      I have not tested the version 12.1.0.1.0 for Oracle 12c.

                      • 8. Re: Universal Connection Pool (UCP) causes thread contention when using validate connection
                        Joe Weinstein-Oracle

                        Try the latest one and see if they've fixed it yet.

                        • 9. Re: Universal Connection Pool (UCP) causes thread contention when using validate connection
                          Joe Weinstein-Oracle

                          Also, your partial thread dump has several threads waiting to lock the pool:- waiting to lock <0x00000000c3516348> (a oracle.ucp.jdbc.oracle.OracleConnectionConnectionPool)

                           

                          but you didn't include the thread that is holding that lock...

                          • 10. Re: Universal Connection Pool (UCP) causes thread contention when using validate connection
                            dsurber

                            This issue still exists in 12.1.0.1.0. The fix is large. We plan to include it in a future 12c patch set but when that will be released I don't know.