OGraphDatabasePool does not recover after Orientdb has been restarted

[RoarN]

Version:
orientdb-graphed-1.3.0 and orientdb-graphed-1.4.0-SNAPSHOT

Test:
20x Fetch connection from the OGraphDatabasePool and excute a command.
Stop and start Orientdb while the database pauses for 30 sec
20x Fetch connection from the OGraphDatabasePool and excute a command.

Expected result:
Should set up a new connection for each connection in the pool as soon as the disconnect is detected.

Actual result:
Continues to "re-acquire" a new connection for the same

2013-04-22 10:54:07,068 INFO main - start
2013-04-22 10:54:08,043 INFO main - #0 - 666652360
2013-04-22 10:54:08,064 INFO main - #1 - 666652360
...
2013-04-22 10:54:08,482 INFO main - #19 - 666652360
2013-04-22 10:54:08,497 INFO main - ***** sleeping for 30 sec, stop and start Orientdb now! *****
2013-04-22 10:54:38,499 INFO main - #0 - 666652360
22.apr.2013 10:54:39 com.orientechnologies.common.log.OLogManager log
WARNING: Connection re-acquired transparently after 677ms and 1 retries: no errors will be thrown at application level
2013-04-22 10:54:39,236 INFO main - #1 - 666652360
22.apr.2013 10:54:40 com.orientechnologies.common.log.OLogManager log
WARNING: Connection re-acquired transparently after 1010ms and 2 retries: no errors will be thrown at application level
...
2013-04-22 10:54:57,142 INFO main - #18 - 666652360
22.apr.2013 10:54:58 com.orientechnologies.common.log.OLogManager log
WARNING: Connection re-acquired transparently after 1009ms and 2 retries: no errors will be thrown at application level
2013-04-22 10:54:58,189 INFO main - #19 - 666652360
22.apr.2013 10:54:59 com.orientechnologies.common.log.OLogManager log
WARNING: Connection re-acquired transparently after 1011ms and 2 retries: no errors will be thrown at application level
2013-04-22 10:54:59,232 INFO main - done

[RoarN]

The Test Code:

public class PoolTester
{
static Logger logger = Logger.getLogger(PoolTester.class.getName());

public OGraphDatabase getConnection()
{
    String url = "remote:localhost/test";
    String user = "admin";
    String password = "admin";
    return OGraphDatabasePool.global().acquire(url, user, password);
}

public static void main(String[] args) throws InterruptedException
{
    PoolTester pt = new PoolTester();
    int runs = 20;

    logger.info("start");

    for (int i = 0; i < runs; i++)
    {
        pt.doStuff(i);
    }
    logger.info("***** sleeping for 30 sec, stop and start Orientdb now! *****");
    Thread.sleep(30*1000);
    for (int i = 0; i < runs; i++)
    {
        pt.doStuff(i);
    }       
    logger.info("done");
}

private void doStuff(int n)
{
    OGraphDatabase gdb = this.getConnection();
    logger.info("#" + n + " - " + gdb.hashCode());
    try
    {
        OSQLSynchQuery<ODocument> query = new OSQLSynchQuery<ODocument>("SELECT FROM V");
        List<ODocument> result = gdb.command(query).execute();
        if (result.size() > 0)
        {
            ODocument doc = result.get(0);
        }
    }
    catch (OException e)
    {
        logger.error("Query failed", e);
    }
    finally
    {
        gdb.close();
    }
}

}

[lvca]

Hey,
I've replaced the dbm.getConnection() -> this.getConnection() and works.

[RoarN]

I hope you realized that this was just a copy/paste issue from me compressing the test code and not the actual problem?

Did you run shutdown.bat and then server.bat halfway through the test (after ***** sleeping for 30 sec, stop and start Orientdb now! *****) without getting "WARNING: Connection re-acquired transparently after 1006ms and 2 ..." on every query thereafter?

This is a serious performance killer when you run in a back-end server environment!

[lvca]

Hi,
do you mean stop and restart the OrientDB server in the middle of the delay? If yes the message:

WARNING: Connection re-acquired transparently after ...

Is normal because probably you've multiple connection and the message happens per-connection. In production how many time you restart the OrientDB server?

[RoarN]

The answer is yes. And regarding restarting the OrientDB server in production; its enough if it happens once :P The back-end server should not have that kind of dependency to a database IMHO.

The test only uses one connection and runs all the requests sequential, and is still not able to recover after 20 OGraphDatabasePool.global().acquire calls.

I'm not that familiar with the internals of the pool but it looks to me like it is the same OGraphDatabase that is returned each time in the test. Shouldn't it have recovered after it encountered the error situation the first time?

If it is not possible for the client API to recover from this situation it should throw an exception so that the programmer could deal with the issue in some way.

[lvca]

This is fixed now. The output:

giu 03, 2013 4:42:57 PM com.orientechnologies.orient.test.database.auto.PoolTester main
INFO: ***** sleeping for 30 sec, stop and start Orientdb now! *****
giu 03, 2013 4:43:27 PM com.orientechnologies.orient.test.database.auto.PoolTester doStuff
INFO: #0 - 881049833
giu 03, 2013 4:43:27 PM com.orientechnologies.common.log.OLogManager log
WARNING: Connection re-acquired transparently after 751ms and 1 retries: no errors will be thrown at application level
giu 03, 2013 4:43:28 PM com.orientechnologies.orient.test.database.auto.PoolTester doStuff
INFO: #1 - 881049833
giu 03, 2013 4:43:28 PM com.orientechnologies.orient.test.database.auto.PoolTester doStuff
INFO: #2 - 881049833
giu 03, 2013 4:43:29 PM com.orientechnologies.orient.test.database.auto.PoolTester doStuff
INFO: #3 - 881049833
giu 03, 2013 4:43:29 PM com.orientechnologies.orient.test.database.auto.PoolTester doStuff
INFO: #4 - 881049833
giu 03, 2013 4:43:29 PM com.orientechnologies.orient.test.database.auto.PoolTester doStuff
INFO: #5 - 881049833
giu 03, 2013 4:43:29 PM com.orientechnologies.orient.test.database.auto.PoolTester doStuff
INFO: #6 - 881049833
giu 03, 2013 4:43:29 PM com.orientechnologies.orient.test.database.auto.PoolTester doStuff
INFO: #7 - 881049833
giu 03, 2013 4:43:30 PM com.orientechnologies.orient.test.database.auto.PoolTester doStuff
INFO: #8 - 881049833
giu 03, 2013 4:43:30 PM com.orientechnologies.orient.test.database.auto.PoolTester doStuff
INFO: #9 - 881049833
giu 03, 2013 4:43:30 PM com.orientechnologies.orient.test.database.auto.PoolTester doStuff
INFO: #10 - 881049833
giu 03, 2013 4:43:30 PM com.orientechnologies.orient.test.database.auto.PoolTester doStuff
INFO: #11 - 881049833
giu 03, 2013 4:43:30 PM com.orientechnologies.orient.test.database.auto.PoolTester doStuff
INFO: #12 - 881049833
giu 03, 2013 4:43:30 PM com.orientechnologies.orient.test.database.auto.PoolTester doStuff
INFO: #13 - 881049833
giu 03, 2013 4:43:30 PM com.orientechnologies.orient.test.database.auto.PoolTester doStuff
INFO: #14 - 881049833
giu 03, 2013 4:43:30 PM com.orientechnologies.orient.test.database.auto.PoolTester doStuff
INFO: #15 - 881049833
giu 03, 2013 4:43:30 PM com.orientechnologies.orient.test.database.auto.PoolTester doStuff
INFO: #16 - 881049833
giu 03, 2013 4:43:30 PM com.orientechnologies.orient.test.database.auto.PoolTester doStuff
INFO: #17 - 881049833
giu 03, 2013 4:43:30 PM com.orientechnologies.orient.test.database.auto.PoolTester doStuff
INFO: #18 - 881049833
giu 03, 2013 4:43:30 PM com.orientechnologies.orient.test.database.auto.PoolTester doStuff
INFO: #19 - 881049833
giu 03, 2013 4:43:30 PM com.orientechnologies.orient.test.database.auto.PoolTester main
INFO: done