Bug report: TCP deadlock between JDBC & Postgres

From: Royce Ausburn <royce(at)inomial(dot)com>
To: pgsql-jdbc(at)postgresql(dot)org
Subject: Bug report: TCP deadlock between JDBC & Postgres
Date: 2015-04-09 02:30:25
Message-ID: F0785602-CD9D-4DA2-830D-5074CEE3E02E@inomial.com
Views: Raw Message | Whole Thread | Download mbox | Resend email
Thread:
Lists: pgsql-jdbc

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(at)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

Responses

Browse pgsql-jdbc by date

  From Date Subject
Next Message Craig Ringer 2015-04-09 14:52:44 Re: Resurrected thread: Speed improvement - Group batch Insert - Rewrite the INSERT at the driver level (using a parameter)
Previous Message Dave Cramer 2015-04-07 21:15:17 Re: Binary transfer not working