Thread: executeQuery Locked

People, I am having a very anoying problem:

I am issuing this:

        boolean result = false;
        Statement stm = null;
        ResultSet rs = null;
        try
        {
            stm = conn.createStatement( ResultSet.TYPE_FORWARD_ONLY, ResultSet.CONCUR_READ_ONLY );
            stm.setQueryTimeout( timeout );           
            rs = stm.executeQuery( sql );  <- the proccess is stopped here for more than half an hour
            result = rs.next();
        }
        finally
        {
            DbUtils.closeQuietly( rs );
            DbUtils.closeQuietly( stm );
        }
        return result;


sql is a simple select that returns one row (if I take it and send to pgsql it works fine)
timeout = 120 (seconds) / I am using a DBCP pool / I use one or more connection per thread (I get it inside the method and release inside the method)

If I get my debbuger and interrupt the thread I see it stopped in some point of execution of stm.executeQuery (it seems to be waitng a response from the postgres server) but at the same time I go to the server and does not find the query itself runnning.

It seems to me that for some (weird) reason, the query timeout is bein achieved without throwing any error or the postgresql driver detecting that.

This is some know issue?
It is possible that the backend is cancelling the connection by timeout and the driver does not notice and continues waiting for it?

the driver I am using is postgresql-8.2dev-503.jdbc3.jar (and it happens the same thing with the 8.0 driver)

and the stack trace of one of such locked proccess:

Thread [zzzzzzz:12] (Suspended)
    SocketInputStream.socketRead0(FileDescriptor, byte[], int, int, int) line: not available [native method]
    SocketInputStream.read(byte[], int, int) line: not available
    BufferedInputStream.fill() line: not available
    BufferedInputStream.read() line: not available
    PGStream.ReceiveChar() line: 256
    QueryExecutorImpl.processResults(ResultHandler, int) line: 1164
    QueryExecutorImpl.execute(Query, ParameterList, ResultHandler, int, int, int) line: 190
    Jdbc3Statement(AbstractJdbc2Statement).execute(Query, ParameterList, int) line: 452
    Jdbc3Statement(AbstractJdbc2Statement).executeWithFlags(String, int) line: 340
    Jdbc3Statement(AbstractJdbc2Statement).executeQuery(String) line: 239
    DelegatingStatement.executeQuery(String) line: 205
    xxxx() line: 580 <- this is the line in the code I sent.
    xxxx(int) line: 504
    xxxx(int) line: 523
    xxxx() line: 156
    NativeMethodAccessorImpl.invoke0(Method, Object, Object[]) line: not available [native method]
    NativeMethodAccessorImpl.invoke(Object, Object[]) line: not available
    DelegatingMethodAccessorImpl.invoke (Object, Object[]) line: not available
    Method.invoke(Object, Object...) line: not available
    ScheduleTaskRunner.run() line: 139
    Thread.run() line: not available

Has anyone seen this kind of situation before?

It could possibly be a bug in the driver, but much more likely it's just
the server waiting on some normal condition.

What exactly is the query in question?  Are you running with autocommit
on or off?

-- Mark Lewis

On Tue, 2006-07-11 at 13:29 -0300, Lucas Sousa wrote:
> People, I am having a very anoying problem:
>
> I am issuing this:
>
>         boolean result = false;
>         Statement stm = null;
>         ResultSet rs = null;
>         try
>         {
>             stm = conn.createStatement( ResultSet.TYPE_FORWARD_ONLY,
> ResultSet.CONCUR_READ_ONLY );
>             stm.setQueryTimeout( timeout );
>             rs = stm.executeQuery( sql );  <- the proccess is stopped
> here for more than half an hour
>             result = rs.next();
>         }
>         finally
>         {
>             DbUtils.closeQuietly( rs );
>             DbUtils.closeQuietly( stm );
>         }
>         return result;
>
>
> sql is a simple select that returns one row (if I take it and send to
> pgsql it works fine)
> timeout = 120 (seconds) / I am using a DBCP pool / I use one or more
> connection per thread (I get it inside the method and release inside
> the method)
>
> If I get my debbuger and interrupt the thread I see it stopped in some
> point of execution of stm.executeQuery (it seems to be waitng a
> response from the postgres server) but at the same time I go to the
> server and does not find the query itself runnning.
>
> It seems to me that for some (weird) reason, the query timeout is bein
> achieved without throwing any error or the postgresql driver detecting
> that.
>
> This is some know issue?
> It is possible that the backend is cancelling the connection by
> timeout and the driver does not notice and continues waiting for it?
>
> the driver I am using is postgresql-8.2dev-503.jdbc3.jar (and it
> happens the same thing with the 8.0 driver)
>
> and the stack trace of one of such locked proccess:
>
> Thread [zzzzzzz:12] (Suspended)
>     SocketInputStream.socketRead0(FileDescriptor, byte[], int, int,
> int) line: not available [native method]
>     SocketInputStream.read(byte[], int, int) line: not available
>     BufferedInputStream.fill() line: not available
>     BufferedInputStream.read() line: not available
>     PGStream.ReceiveChar() line: 256
>     QueryExecutorImpl.processResults(ResultHandler, int) line: 1164
>     QueryExecutorImpl.execute(Query, ParameterList, ResultHandler,
> int, int, int) line: 190
>     Jdbc3Statement(AbstractJdbc2Statement).execute(Query,
> ParameterList, int) line: 452
>     Jdbc3Statement(AbstractJdbc2Statement).executeWithFlags(String,
> int) line: 340
>     Jdbc3Statement(AbstractJdbc2Statement).executeQuery(String) line:
> 239
>     DelegatingStatement.executeQuery(String) line: 205
>     xxxx() line: 580 <- this is the line in the code I sent.
>     xxxx(int) line: 504
>     xxxx(int) line: 523
>     xxxx() line: 156
>     NativeMethodAccessorImpl.invoke0(Method, Object, Object[]) line:
> not available [native method]
>     NativeMethodAccessorImpl.invoke(Object, Object[]) line: not
> available
>     DelegatingMethodAccessorImpl.invoke (Object, Object[]) line: not
> available
>     Method.invoke(Object, Object...) line: not available
>     ScheduleTaskRunner.run() line: 139
>     Thread.run() line: not available
>
> Has anyone seen this kind of situation before?
>
>

Please remember to CC the list on any emails.  This one is beyond my
skill, so hopefully somebody else can help you out.

-- Mark Lewis

On Tue, 2006-07-11 at 15:23 -0300, Lucas Sousa wrote:
> I think that has something to do with the PhantomReferences
>
> The problem seem to be related with the garbage collector...
>
> My application force the garbage collector to run periodically. I
> stopped that for testing purposes and that locking problem does not
> happened for the last hour and a half.
>
>
>
> On 7/11/06, Lucas Sousa <lucas75@gmail.com> wrote:
>         autocommit is off
>
>         the query is a plain "select 1 from tb_1 where a=b and b=c and
>         c=d"
>
>         where a=b and b=c and c=d is the primary key of the table
>         it should not last more than millisseconds (in fact doesn't)
>         but sometimes one of the threads that is executing that sql
>         seems to stop rigth there waiting for the result. That is why
>         I set the queryTimeout for 120 seconds, but seems that the
>         query timeout is not working at all.
>
>
>
>         On 7/11/06, Mark Lewis <mark.lewis@mir3.com> wrote:
>                 It could possibly be a bug in the driver, but much
>                 more likely it's just
>                 the server waiting on some normal condition.
>
>                 What exactly is the query in question?  Are you
>                 running with autocommit
>                 on or off?
>
>                 -- Mark Lewis
>
>                 On Tue, 2006-07-11 at 13:29 -0300, Lucas Sousa wrote:
>                 > People, I am having a very anoying problem:
>                 >
>                 > I am issuing this:
>                 >
>                 >         boolean result = false;
>                 >         Statement stm = null;
>                 >         ResultSet rs = null;
>                 >         try
>                 >         {
>                 >             stm = conn.createStatement
>                 ( ResultSet.TYPE_FORWARD_ONLY,
>                 > ResultSet.CONCUR_READ_ONLY );
>                 >             stm.setQueryTimeout ( timeout );
>                 >             rs = stm.executeQuery( sql );  <- the
>                 proccess is stopped
>                 > here for more than half an hour
>                 >             result = rs.next();
>                 >         }
>                 >         finally
>                 >         {
>                 >             DbUtils.closeQuietly( rs );
>                 >             DbUtils.closeQuietly( stm );
>                 >         }
>                 >         return result;
>                 >
>                 >
>                 > sql is a simple select that returns one row (if I
>                 take it and send to
>                 > pgsql it works fine)
>                 > timeout = 120 (seconds) / I am using a DBCP pool / I
>                 use one or more
>                 > connection per thread (I get it inside the method
>                 and release inside
>                 > the method)
>                 >
>                 > If I get my debbuger and interrupt the thread I see
>                 it stopped in some
>                 > point of execution of stm.executeQuery (it seems to
>                 be waitng a
>                 > response from the postgres server) but at the same
>                 time I go to the
>                 > server and does not find the query itself runnning.
>                 >
>                 > It seems to me that for some (weird) reason, the
>                 query timeout is bein
>                 > achieved without throwing any error or the
>                 postgresql driver detecting
>                 > that.
>                 >
>                 > This is some know issue?
>                 > It is possible that the backend is cancelling the
>                 connection by
>                 > timeout and the driver does not notice and continues
>                 waiting for it?
>                 >
>                 > the driver I am using is
>                 postgresql-8.2dev-503.jdbc3.jar (and it
>                 > happens the same thing with the 8.0 driver)
>                 >
>                 > and the stack trace of one of such locked proccess:
>                 >
>                 > Thread [zzzzzzz:12] (Suspended)
>                 >     SocketInputStream.socketRead0(FileDescriptor,
>                 byte[], int, int,
>                 > int) line: not available [native method]
>                 >     SocketInputStream.read(byte[], int, int) line:
>                 not available
>                 >     BufferedInputStream.fill () line: not available
>                 >     BufferedInputStream.read() line: not available
>                 >     PGStream.ReceiveChar() line: 256
>                 >     QueryExecutorImpl.processResults(ResultHandler,
>                 int) line: 1164
>                 >     QueryExecutorImpl.execute (Query, ParameterList,
>                 ResultHandler,
>                 > int, int, int) line: 190
>                 >     Jdbc3Statement(AbstractJdbc2Statement).execute
>                 (Query,
>                 > ParameterList, int) line: 452
>                 >     Jdbc3Statement
>                 (AbstractJdbc2Statement).executeWithFlags(String,
>                 > int) line: 340
>                 >     Jdbc3Statement
>                 (AbstractJdbc2Statement).executeQuery(String) line:
>                 > 239
>                 >     DelegatingStatement.executeQuery(String) line:
>                 205
>                 >     xxxx() line: 580 <- this is the line in the code
>                 I sent.
>                 >     xxxx(int) line: 504
>                 >     xxxx(int) line: 523
>                 >     xxxx() line: 156
>                 >     NativeMethodAccessorImpl.invoke0(Method, Object,
>                 Object[]) line:
>                 > not available [native method]
>                 >     NativeMethodAccessorImpl.invoke(Object, Object
>                 []) line: not
>                 > available
>                 >     DelegatingMethodAccessorImpl.invoke (Object,
>                 Object[]) line: not
>                 > available
>                 >     Method.invoke(Object, Object...) line: not
>                 available
>                 >     ScheduleTaskRunner.run() line: 139
>                 >     Thread.run() line: not available
>                 >
>                 > Has anyone seen this kind of situation before?
>                 >
>                 >
>
>
>

Lucas Sousa wrote:

>             stm.setQueryTimeout( timeout );

> It seems to me that for some (weird) reason, the query timeout is bein
> achieved without throwing any error or the postgresql driver detecting
> that.
>
> This is some know issue?

Unfortunately setQueryTimeout() is currently a no-op. As a workaround,
set the server's statement_timeout variable.

> Thread [zzzzzzz:12] (Suspended)
>     SocketInputStream.socketRead0(FileDescriptor, byte[], int, int, int)
> line: not available [native method]
>     SocketInputStream.read(byte[], int, int) line: not available
>     BufferedInputStream.fill() line: not available
>     BufferedInputStream.read() line: not available
>     PGStream.ReceiveChar() line: 256
>     QueryExecutorImpl.processResults(ResultHandler, int) line: 1164

The driver is waiting for results from the server. Either the query is
still running or something has got confused about what's happening at
the protocol level.

Can you reproduce this with loglevel=2 set (as a URL parameter, see the
driver docs)? Or a tcpdump/snoop/ethereal capture of the connection with
the server when it gets stuck would also be useful. Also, if you could
attach to the corresponding backend via gdb or similar and get a stack
trace that may help.

-O

I am debugging the driver myself, I am looking into the PhantomReferences that I think may be the cause of the problem (the problem seems to me loosely related with the garbage collector frequency)

If I do the "set statement_timeout = 60000" on that connection I suppose that after I release this connection back to the pool and another thread fetches it the statement timeout will remain set ... is it not?

But it is good to know that I am not crazy....

Lucas Sousa wrote:
> I am debugging the driver myself, I am looking into the
> PhantomReferences that I think may be the cause of the problem (the
> problem seems to me loosely related with the garbage collector frequency)

Well, if you collect a trace of the communication between driver and
server as I suggested, it will let you work out whether it really is the
driver at fault, and what it did around the time of the failure.

The PhantomReference stuff is used to free up old server-side prepared
statements where the corresponding Java objects have gone away. In
theory it shouldn't affect query execution..

> If I do the "set statement_timeout = 60000" on that connection I suppose
> that after I release this connection back to the pool and another thread
> fetches it the statement timeout will remain set ... is it not?

That's right. You could always explicitly set statement_timeout after
getting a new connection from the pool, I suppose.

-O