This discussion is archived
1 2 Previous Next 17 Replies Latest reply: Dec 3, 2012 11:52 AM by jschellSomeoneStoleMyAlias RSS

UCP problem: connections time out but can still be used

657334 Explorer
Currently Being Moderated
We've been using the old OracleDataSource for connection pooling, but since that usage is deprecated, I'm trying to switch over to Universal Connection Pooling.

As far as I can tell I am setting everything up just as it outlines in the UCP documentation. And it mostly works. The problem is the abandoned connection timeout. This worked fine with OracleDataSource, but now it doesn't - I have a unit test which abandons a requested connection (by sleeping) and then tries to use it. It can be used just fine.

My first thought was that the timeout wasn't being checked properly for some reason, but I turned on FINEST level tracing for UCP and it sure looks as if the pool is handling it properly - except that my test code still has a handle to it and can use it.

Here's a simple test case that shows the problem:
import java.sql.Connection;
import java.sql.Statement;
import java.sql.ResultSet;

import oracle.ucp.jdbc.PoolDataSourceFactory;
import oracle.ucp.jdbc.PoolDataSource;


public class ConnectionTest
{
    ConnectionTest() {
        /* empty */
    }

    public static void main(String args[])
    {
        try {
            String jdbcURL = args[0];
            if (jdbcURL == null) {
                throw new IllegalArgumentException("jdbcURL is null");
            }

            int atPos = jdbcURL.indexOf('@');
            String credentials = jdbcURL.substring((jdbcURL.lastIndexOf(':', atPos) + 1), atPos);
            String userName = credentials.substring(0, credentials.indexOf('/'));
            String password = credentials.substring((credentials.indexOf('/') + 1));

            PoolDataSource dataSource = PoolDataSourceFactory.getPoolDataSource();
            dataSource.setConnectionFactoryClassName("oracle.jdbc.pool.OracleDataSource");

            dataSource.setURL(jdbcURL);
            dataSource.setUser(userName);
            dataSource.setPassword(password);

            dataSource.setTimeoutCheckInterval(2);
            dataSource.setAbandonedConnectionTimeout(2);

            Connection conn = dataSource.getConnection();
            Thread.sleep(4100);
            Statement st = conn.createStatement();
            ResultSet rs = st.executeQuery("select count(*) from user_objects");
            rs.next();
            int result = rs.getInt(1);
            rs.close();

            System.out.println("Connection still usable after timeout: " + result);
            System.exit(1);

        } catch (Exception e) {
            System.out.println("Exception: " + e.getMessage());
            System.exit(0);
        }
    }
}
Here's the relevant section of the log. Note that the createStatement() call clearly comes after the timeout bits:
2012-11-28T02:47:11.665-0500 UCP FINEST seq-108,thread-11 oracle.ucp.common.UniversalConnectionPoolBase.processAbandonedConnections processing abandoned connections
2012-11-28T02:47:11.666-0500 UCP FINEST seq-109,thread-11 oracle.ucp.common.UniversalConnectionPoolBase.processAbandonedConnections abandoned connections processed
2012-11-28T02:47:11.666-0500 UCP FINEST seq-110,thread-14 oracle.ucp.common.UniversalConnectionPoolImpl$UniversalConnectionPoolInternal.getInUseConnectionsArrayInternal in use connections: 1
2012-11-28T02:47:11.667-0500 UCP FINEST seq-111,thread-14 oracle.ucp.jdbc.oracle.OracleJDBCConnectionPool.processTimedOutConnection UniversalPooledConnection: Instance Name: orcl, DBUniq Name: orcl, Host Name: e-oracle-02, Service Name: orcl.bbn.com
2012-11-28T02:47:11.667-0500 UCP FINEST seq-112,thread-14 oracle.ucp.jdbc.JDBCUniversalPooledConnection.getSQLConnection physicalConnection: oracle.jdbc.driver.T4CConnection@546c585a
2012-11-28T02:47:11.667-0500 UCP FINEST seq-113,thread-14 oracle.ucp.jdbc.oracle.FailoverablePooledConnectionHelper.cancelOnOracleConnection conn cancelled successfully
2012-11-28T02:47:11.667-0500 UCP FINEST seq-114,thread-14 oracle.ucp.common.UniversalPooledConnectionImpl.removeConnectionHarvestingCallback connection harvesting callback removed
2012-11-28T02:47:11.668-0500 UCP FINEST seq-115,thread-14 oracle.ucp.common.AvailableConnectionsManyCollections.createAvailableConnectionsCollection available connections collection created
2012-11-28T02:47:11.668-0500 UCP FINEST seq-116,thread-14 oracle.ucp.common.AvailableConnectionsManyCollections.addAvailableConnection available connection added
2012-11-28T02:47:11.668-0500 UCP FINEST seq-117,thread-14 oracle.ucp.common.UniversalPooledConnectionImpl.setAvailableStartTime availableStartTime: 1354132031668
2012-11-28T02:47:12.107-0500 UCP FINEST seq-118,thread-10 oracle.ucp.jdbc.proxy.StatementProxyFactory.setStatementPooling statementObj=oracle.jdbc.driver.OracleStatementWrapper@2f87c55c, poolable=false
2012-11-28T02:47:12.117-0500 UCP FINEST seq-119,thread-10 oracle.ucp.jdbc.proxy.StatementProxyFactory.createStatementProxy returns $Proxy1@f593af
2012-11-28T02:47:12.243-0500 UCP FINEST seq-120,thread-10 oracle.ucp.jdbc.proxy.ResultSetProxyFactory.createResultSetProxy returns $Proxy2@558352d8
So - what am I doing wrong?

Edited by: Dan Blum on Nov 28, 2012 3:00 PM
  • 1. Re: UCP problem: connections time out but can still be used
    jschellSomeoneStoleMyAlias Expert
    Currently Being Moderated
    As a guess maybe you are not waiting long enough.

    Or per the docs....

    +"Sets the maximum time that a connection can remain unused before the connection is closed and _returned to the cache_"+

    Maybe it isn't really closing the proxy connection you have but it is still returning it to the cache.
  • 2. Re: UCP problem: connections time out but can still be used
    657334 Explorer
    Currently Being Moderated
    That would be a serious bug, if so. If the connection is returned to the cache without being closed, it can be handed to another thread. Then both threads can use the same connection. That is going to cause problems, particularly if one of then calls close() on it. (I saw a similar bug with the old connection cache classes - if the Java code accidentally called close() twice on the same connection, the second call will work and might fire after the connection has been handed to another thread, thus cancelling whatever it is doing.)
  • 3. Re: UCP problem: connections time out but can still be used
    657334 Explorer
    Currently Being Moderated
    Furthermore, it doesn't appear to matter how long I wait. If I set the sleep() call to 20.1 seconds instead of 4.1 seconds, the result is the same.
  • 4. Re: UCP problem: connections time out but can still be used
    rp0428 Guru
    Currently Being Moderated
    >
    We've been using the old OracleDataSource for connection pooling, but since that usage is deprecated, I'm trying to switch over to Universal Connection Pooling.

    As far as I can tell I am setting everything up just as it outlines in the UCP documentation. And it mostly works. The problem is the abandoned connection timeout. This worked fine with OracleDataSource, but now it doesn't - I have a unit test which abandons a requested connection (by sleeping) and then tries to use it. It can be used just fine.
    >
    This could be a bug. You don't say if this behaviour will actually cause you a problem or if you are just reporting an anomoly.

    I was able to reproduce what you reported and was also able to produce the behaviour I think you expected.

    The code below reproduces what you reported.
                System.out.println("Getting first connection.");
                Connection conn = dataSource.getConnection();
                System.out.println("Got first connection.");
                Thread.sleep(4100);
                System.out.println("Calling isClosed for first connection after 4100 delay.");
                System.out.println("isClosed returns: " + conn.isClosed());
    //            System.out.println("Calling isValid(0) for first connection after 4100 delay.");
    //            System.out.println("isValid(0) returns: " + conn.isValid(0));
                System.out.println("Creating first statement.");
                Statement st = conn.createStatement();
                System.out.println("Created first statement.");
                System.out.println("Executing first query.");
                ResultSet rs = st.executeQuery("select count(*) from user_objects");
                System.out.println("Executed first query.");
                rs.next();
                int result = rs.getInt(1);
                rs.close();
    
                System.out.println("Connection still usable after timeout: " + result);
                System.exit(1);
    
    run:
    Getting first connection.
    Got first connection.
    Calling isClosed for first connection after 4100 delay.
    isClosed returns: false
    Creating first statement.
    Created first statement.
    Executing first query.
    Executed first query.
    Connection still usable after timeout: 1153
    Java Result: 1
    BUILD SUCCESSFUL (total time: 5 seconds)
    If you uncomment the two lines for isValid the code then produces what you expected.
    run:
    Getting first connection.
    Got first connection.
    Calling isClosed for first connection after 4100 delay.
    isClosed returns: false
    Calling isValid(0) for first connection after 4100 delay.
    isValid(0) returns: false
    Creating first statement.
    Exception: The connection is closed: The connection is closed
    BUILD SUCCESSFUL (total time: 5 seconds)
    Note that 'isValid' reports FALSE and in both cases 'isClosed' reports FALSE also. It appears that the 'isValid' call is affecting the results and that the reason your code works the way you posted is because the connection itself is still open.

    If you have a support contract I would open a SOR for this and report it. You may use my sample code with the 'isValid' test if you want.
  • 5. Re: UCP problem: connections time out but can still be used
    657334 Explorer
    Currently Being Moderated
    This is definitely a bug as far as I'm concerned. If the pool hands this connection to another requestor, they will be able to use it at the same time, which I have seen cause problems before.

    The isValid() call is not actually doing the right thing, at least in my environment. It does close the connection, but it does it just the same BEFORE the sleep() call. Turning on logging reveals it is actually failing:
    2012-11-29T05:48:23.429-0500 UCP FINEST seq-105,thread-10 oracle.ucp.common.UniversalPooledConnectionImpl.isValid Connection validation timed out or hit an error:
    Task manager Exception: java.util.concurrent.TimeoutException
            at oracle.ucp.util.UCPTaskManagerImpl$3.get(UCPTaskManagerImpl.java:144)
            at oracle.ucp.common.UniversalPooledConnectionImpl.isValid(UniversalPooledConnectionImpl.java:222)
            at oracle.ucp.jdbc.proxy.JDBCConnectionProxyFactory.invoke(JDBCConnectionProxyFactory.java:266)
            at $Proxy0.isValid(Unknown Source)
            at ConnectionTest.main(ConnectionTest.java:41)
    Caused by: java.util.concurrent.TimeoutException
            at java.util.concurrent.FutureTask$Sync.innerGet(FutureTask.java:228)
            at java.util.concurrent.FutureTask.get(FutureTask.java:91)
            at oracle.ucp.util.UCPTaskManagerImpl$3.get(UCPTaskManagerImpl.java:140)
            ... 4 more
    It did not actually time out, since it only takes 1-2 milliseconds for the isValid() call.
  • 6. Re: UCP problem: connections time out but can still be used
    657334 Explorer
    Currently Being Moderated
    OK, I see what is wrong with the isValid() call. Although the javadoc for Connection.isValid() says you can call it with 0 to not have it time out, by decompiling ucp.jar I can see that UniversalPooledConnectionImpl does not actually respect that - it just multiplies the timeout by 1000 and sends it to UCPTaskManagerImpl, which in turn always calls FutureTask.get() with the timeout without checking it. This is incorrect behavior - FutureTask has an alternate get() method that takes no arguments and doesn't time out, and this should be used here.

    Using isValid(1) works, but unfortunately returns true both before and after the sleep() call, so it doesn't help. (Nor does using an OracleConnection instead and calling isUsable(), since I tried that.)

    I will open an SR on this, but I posted here first because I can't imagine that I am the first person to test the timeouts with UCP - I assumed that by now lots of people would be using UCP.
  • 7. Re: UCP problem: connections time out but can still be used
    657334 Explorer
    Currently Being Moderated
    I also tried ValidConnection.isValid() (since that's the shiny new UCP way of checking things). It too always returns true.
  • 8. Re: UCP problem: connections time out but can still be used
    jschellSomeoneStoleMyAlias Expert
    Currently Being Moderated
    Dan Blum wrote:
    So - what am I doing wrong?
    So you probably have a bug in the driver.

    However what you are doing wrong is relying on this behavior in the first place. The only effective way to manage connections is to close them when you are done using them.
  • 9. Re: UCP problem: connections time out but can still be used
    rp0428 Guru
    Currently Being Moderated
    >
    However what you are doing wrong is relying on this behavior in the first place. The only effective way to manage connections is to close them when you are done using them.
    >
    Of course you should close connections when you are done with them.

    But any supplied functionality, like setAbandonedConnectionTimeout, should work properly and you should be able to rely on it working properly.

    I don't think there is enough information to say that OP is wrong to rely on the behavior. Whether OPs app is wrong for relying on the behavior depends on what the app is designed to do.

    There are at least three major causes of 'unused' or 'idle' connections (substitute your own term here). An app that either doesn't close connections when done using them, an app that goes haywire and just hangs or otherwise leaves connections dangling and database problems (especially with RAC systems) where the database is unresponsive or in a state where the connection CANNOT be used appropriately anymore.

    The new UCP functionality was split off specifically to provide more robust solutions to the 3rd cause. Applications are not in a good position to try to detect and/or deal with database related issues that cause connection failure or non-response. The UCP functionality is designed to centralize that and offload that work from the applications.

    If OPs app is designed to take advantage of that centralization of responsibility then the app should be able to rely on it working properly because it can definitely cause serious problems if it doesn't.
  • 10. Re: UCP problem: connections time out but can still be used
    657334 Explorer
    Currently Being Moderated
    We do close connections when we're done with them. However, with the old OracleDataSource, an "abandoned" connection could be one executing a long-running SQL statement - it only issued a heartbeat when actually calling an execute method. There's no way the application can close the connection itself until it actually finishes executing what it was asked to, barring running a monitor thread. We could run a monitor thread, but the connection pool classes are supposed to handle this stuff themselves.
  • 11. Re: UCP problem: connections time out but can still be used
    jschellSomeoneStoleMyAlias Expert
    Currently Being Moderated
    rp0428 wrote:
    >
    However what you are doing wrong is relying on this behavior in the first place. The only effective way to manage connections is to close them when you are done using them.
    >
    Of course you should close connections when you are done with them.

    But any supplied functionality, like setAbandonedConnectionTimeout, should work properly and you should be able to rely on it working properly.

    I don't think there is enough information to say that OP is wrong to rely on the behavior. Whether OPs app is wrong for relying on the behavior depends on what the app is designed to do.

    There are at least three major causes of 'unused' or 'idle' connections (substitute your own term here).
    As best I can tell you are mixing the proxy object that the pool uses with the real database connection. The feature under discussion attempts to provide a way to allow detection of unused proxy objects. It has nothing to do with actual connections.
    An app that either doesn't close connections when done using them,
    It should. The system has a bug and relying on another feature to fix that bug can be problematic because it relies on a sliding window which might not meet the needs of the application at non-deterministic times. Thus causing failures that one might not associate with the real cause.
    an app that goes haywire and just hangs or otherwise leaves connections dangling
    There would be known and unknown reasons for that.

    A known reason would be a programming idiom that doesn't use finally or in some other way allows the connection proxy (or associated jdbc objects) to escape their known scope. In that case it is a programming bug and I refer to the previous case.

    The VM can blow up or some sub library can blow up. In cases like that one might see the application exit completely or in some unknown way become hung. The feature provides a bandaid but one which is only applicable to client apps and doesn't insure that it will work (because the failure might impact the feature as well.) For a failed server in such a state re-starting is the only known immediate fix and the feature has nothing to do with that.
    and database problems (especially with RAC systems) where the database is unresponsive or in a state where the connection CANNOT be used appropriately anymore.
    You would need to explain how that helps to me. You are referring to a problem involving the actual connection and not the proxy. Returning the proxy to the pool might lead to it being cleared up but how it gets to to pool has nothing to do with whether it gets fixed or not.
  • 12. Re: UCP problem: connections time out but can still be used
    jschellSomeoneStoleMyAlias Expert
    Currently Being Moderated
    Dan Blum wrote:
    There's no way the application can close the connection itself until it actually finishes executing what it was asked to, barring running a monitor thread.
    I don't see anything it the documentation that suggests that the feature you are looking at would fix that. If it is running a query it would still be considered active.

    However there should be a timeout feature of the driver that specifically addresses that problem.
  • 13. Re: UCP problem: connections time out but can still be used
    rp0428 Guru
    Currently Being Moderated
    >
    I don't see anything it the documentation that suggests that the feature you are looking at would fix that. If it is running a query it would still be considered active.
    >
    It is in the section 'Setting the Abandon Connection Timeout'
    http://docs.oracle.com/cd/B28359_01/java.111/e10788/optimize.htm
    >
    Abandonment is determined by monitoring calls to the database
    >
    After the initial call to execute a long-running query there would be no more calls so the UCP driver will detect those connections as abandoned after the requisite time.
  • 14. Re: UCP problem: connections time out but can still be used
    jschellSomeoneStoleMyAlias Expert
    Currently Being Moderated
    rp0428 wrote:
    >
    I don't see anything it the documentation that suggests that the feature you are looking at would fix that. If it is running a query it would still be considered active.
    >
    It is in the section 'Setting the Abandon Connection Timeout'
    http://docs.oracle.com/cd/B28359_01/java.111/e10788/optimize.htm
    Huh?

    That section says +"after a connection has not been used for a specific amount of time"+ and +"that are no longer in use."+

    The OP suggested that the connections will be in use because they are going to be running a request that takes a long time. Running a request means it is still in use - at least to me.
    >
    Abandonment is determined by monitoring calls to the database
    >
    After the initial call to execute a long-running query there would be no more calls so the UCP driver will detect those connections as abandoned after the requisite time.
    I don't understand the logic in that statement.

    Say I want to run a query that takes a half an hour. This is what I would do.
    1. Open connection.
    2. Run statement.
    3. Block on return from that statement.
    4. Time passes....
    5. Statement completes and returns thus unblocking 3.

    Now exactly what would you do differently in the above with that connection/scenario such that you would be using ("call") the connection while 4 was in process?
1 2 Previous Next

Legend

  • Correct Answers - 10 points
  • Helpful Answers - 5 points