Re: Bug report: TCP deadlock between JDBC & Postgres

Hi all,

We've managed to trip a deadlock between a JDBC client and postgres similar to what's described in github issue #194 (https://github.com/pgjdbc/pgjdbc/issues/194) and #195 (https://github.com/pgjdbc/pgjdbc/issues/195).

Here's a typical stack trace:

"http-thread-pool-17580(4)" daemon prio=10 tid=0x00007f8224059000 nid=0x66c8 runnable [0x00007f828670f000]

   java.lang.Thread.State: RUNNABLE

        at java.net.SocketOutputStream.socketWrite0(Native Method)

        at java.net.SocketOutputStream.socketWrite(SocketOutputStream.java:113)

        at java.net.SocketOutputStream.write(SocketOutputStream.java:159)

        at java.io.BufferedOutputStream.flushBuffer(BufferedOutputStream.java:82)

        at java.io.BufferedOutputStream.write(BufferedOutputStream.java:126)

        - locked <0x00000006a40789a8> (a java.io.BufferedOutputStream)

        at java.io.FilterOutputStream.write(FilterOutputStream.java:97)

        at org.postgresql.core.PGStream.SendInteger4(PGStream.java:197)

        at org.postgresql.core.v3.QueryExecutorImpl.sendCloseStatement(QueryExecutorImpl.java:1596)

        at org.postgresql.core.v3.QueryExecutorImpl.processDeadParsedQueries(QueryExecutorImpl.java:1741)

        at org.postgresql.core.v3.QueryExecutorImpl.sendQueryPreamble(QueryExecutorImpl.java:436)

        at org.postgresql.core.v3.QueryExecutorImpl.execute(QueryExecutorImpl.java:251)

        - locked <0x00000006a4078b68> (a org.postgresql.core.v3.QueryExecutorImpl)

        at org.postgresql.jdbc2.AbstractJdbc2Statement.execute(AbstractJdbc2Statement.java:570)

        at org.postgresql.jdbc2.AbstractJdbc2Statement.executeWithFlags(AbstractJdbc2Statement.java:420)

        at org.postgresql.jdbc2.AbstractJdbc2Statement.executeQuery(AbstractJdbc2Statement.java:305)

An strace on the postgres server process end revealed the thread was blocked sending data to the socket too.

Netstat on both ends had bytes in the send-Q

[royce@smile-test-db ~]$ netstat -an | grep 36563

tcp    57878  20016 10.20.18.204:5432       10.20.18.203:36563      ESTABLISHED

(sorry, I've lost the other end but it was nearly 64k of send-Q bytes, believe me!)

The issue emerged just after we've bumped the max JVM heap size significantly and during a heavy running migration/data transformation process with lots of jdbc queries.

The issue appears to be in how processDeadParsedQueries() works - if there're a lot of recently GC'd parsed statements then there'll be a lot of statements to close which manages to fill the send buffer on our end while the corresponding postgres process on the server end is busy filling its send buffer with responses from the close statement requests.  

We believe that reducing the heap size will mean there're more frequent GCs which will mean there'll be fewer statements to purge in any given invocation of processDeadParsedQueries() so we can hopefully work around this issue easily.

--Royce