Re: Synchronisation problems in COPY IN

Hi,

We are occasionally experiencing problems with our JDBC implementation
of COPY IN.

We have cut our program down to the attached example.

Guessing from the error messages it looks like jdbc is overwriting the
buffer sent to the server before it is done. We are writing the data in
CSV format, with integer(serial),date(now),float format, so it is easy
to see if the buffer is garbled. Here is an example:
INFO: ERROR: extra data after last expected column
Where: COPY temporary_wind_speed_50_m_3, line 175:
"60000179,2010-09-07 00:00:00,60001043,2010-09-07
00:00:00,10.032084733490484"
org.postgresql.util.PSQLException: ERROR: extra data after last expected
column
Where: COPY temporary_wind_speed_50_m_3, line 175:
"60000179,2010-09-07 00:00:00,60001043,2010-09-07
00:00:00,10.032084733490484"
at
org.postgresql.core.v3.QueryExecutorImpl.receiveErrorResponse(QueryExecutorImpl.java:2062)
at
org.postgresql.core.v3.QueryExecutorImpl.processCopyResults(QueryExecutorImpl.java:929)
at
org.postgresql.core.v3.QueryExecutorImpl.writeToCopy(QueryExecutorImpl.java:838)
at
org.postgresql.core.v3.CopyInImpl.writeToCopy(CopyInImpl.java:53)
at org.postgresql.copy.CopyManager.copyIn(CopyManager.java:179)
at org.postgresql.copy.CopyManager.copyIn(CopyManager.java:161)
at dk.dmi.appl.evejrfeeder.EvejrDBCopy.run(Unknown Source)
at java.lang.Thread.run(Thread.java:595)

It thus looks like a synchronisation problem (locking problem), but we
are using Piped(Input/Output)Stream, which must be properly
synchronised, and CopyManager.CopyIn, where there is nowhere to add
synchronisation.

To us it looks like a problem in CopyManager.CopyIn, or alternatively we
are not doing something we where expected to do?

We use PostgreSQL 8.4, and JDBC 8.4-702.

Thanks in advance!

Kim

On Mon, 13 Sep 2010, Kim Bisgaard wrote:

> We are occasionally experiencing problems with our JDBC implementation of
> COPY IN.
>
> We have cut our program down to the attached example.

Do you get the failure you've shown from this example? I get another
failure from the connection being close before the last copy thread can
complete its write operation. This seems like an expected failure, but I
can't reproduce yours.

org.postgresql.util.PSQLException: Database connection failed when
canceling copy operation
at
org.postgresql.core.v3.QueryExecutorImpl.cancelCopy(QueryExecutorImpl.java:796)
at
org.postgresql.core.v3.CopyOperationImpl.cancelCopy(CopyOperationImpl.java:32)
at org.postgresql.copy.CopyManager.copyIn(CopyManager.java:150)
at org.postgresql.copy.CopyManager.copyIn(CopyManager.java:126)
at EvejrDBCopy.run(EvejrDBCopy.java:34)

> We use PostgreSQL 8.4, and JDBC 8.4-702.
>

Your stacktrace shows that you are using 8.4-701, not 702. 702 had some
fixes to the copy code when using a Reader, but your code shows you are
using an InputStream, so those changes shouldn't be relevent.

Kris Jurka

There is some moderately bogus behavior with respect to closing a
connection while doing a COPY (see list archives). I wonder if that
could be involved?

If memory serves, the issue was that a Terminate message (sent on
Connection.close() to indicate that the client wants to end the
protocol connection) is *not* synchronized relative to COPY protocol
operations. This means that *theoretically*, your Terminate message
could be shimmed right into the middle of a CopyData message. In
practice, I've only ever seen an error from the server complaining
about an unexpected message type (Terminate) during COPY, since the
client is *supposed* to send CopyDone or CopyFail before a Terminate
while a COPY is in effect. Still, I think it might be possible to get
message contents munged.

I think your code *might* be susceptible to that, since you kick off a
bunch of COPY operations in separate threads and then call
Connection.close() in the main thread, without waiting for the COPY
threads to finish if I'm reading that right--should that if
(t.isAlive) {} be something while (t.isAlive()) {}?

Can you capture (e.g., tcpdump) the data stream that gets sent to the
server? It'd be interesting to see if Terminate actually is getting
munged into the COPY data or if we're looking at another issue
entirely.

For what it's worth, I investigated a fix, but (1) it's a pain in the
ass to get the logic right without Java 5's synchronization primitives
(in fact, if we do this again, it might be worth just implementing a
ReadWriteLock unless JDBC is planning to drop 1.4 support) and (2)
based on preliminary testing, there was an unacceptable performance
regression in doing the locking right. I can try to revisit the patch
(or dig it out and post it as is), but we may need to rethink this
entirely.

First of all, though, it'd be nice to figure out if this is actually
the problem affecting you. If the problem I described is still just
theoretical, I wouldn't worry about it. Since it involves the client
closing the Connection while having active COPY operations in other
threads, this is wonky *application* behavior any (well, almost any)
way you look at it.

---
Maciek Sakrejda | System Architect | Truviso

1065 E. Hillsdale Blvd., Suite 215
Foster City, CA 94404
(650) 242-3500 Main
www.truviso.com

On Mon, Sep 13, 2010 at 7:17 AM, Kris Jurka <books(at)ejurka(dot)com> wrote:
>
>
> On Mon, 13 Sep 2010, Kim Bisgaard wrote:
>
>> We are occasionally experiencing problems with our JDBC implementation of
>> COPY IN.
>>
>> We have cut our program down to the attached example.
>
> Do you get the failure you've shown from this example?  I get another
> failure from the connection being close before the last copy thread can
> complete its write operation.  This seems like an expected failure, but I
> can't reproduce yours.
>
> org.postgresql.util.PSQLException: Database connection failed when canceling
> copy operation
>        at
> org.postgresql.core.v3.QueryExecutorImpl.cancelCopy(QueryExecutorImpl.java:796)
>        at
> org.postgresql.core.v3.CopyOperationImpl.cancelCopy(CopyOperationImpl.java:32)
>        at org.postgresql.copy.CopyManager.copyIn(CopyManager.java:150)
>        at org.postgresql.copy.CopyManager.copyIn(CopyManager.java:126)
>        at EvejrDBCopy.run(EvejrDBCopy.java:34)
>
>> We use PostgreSQL 8.4, and JDBC 8.4-702.
>>
>
> Your stacktrace shows that you are using 8.4-701, not 702.  702 had some
> fixes to the copy code when using a Reader, but your code shows you are
> using an InputStream, so those changes shouldn't be relevent.
>
> Kris Jurka
>
> --
> Sent via pgsql-jdbc mailing list (pgsql-jdbc(at)postgresql(dot)org)
> To make changes to your subscription:
> http://www.postgresql.org/mailpref/pgsql-jdbc
>

Your error sure looks exactly like the problem that existed when using a
Reader instead of InputStream with the older driver (701), though your
description implies a different problem.

On Mon, Sep 13, 2010 at 7:17 AM, Kris Jurka <books(at)ejurka(dot)com> wrote:

>
>
> On Mon, 13 Sep 2010, Kim Bisgaard wrote:
>
> We are occasionally experiencing problems with our JDBC implementation of
>> COPY IN.
>>
>> We have cut our program down to the attached example.
>>
>
> Do you get the failure you've shown from this example? I get another
> failure from the connection being close before the last copy thread can
> complete its write operation. This seems like an expected failure, but I
> can't reproduce yours.
>
> org.postgresql.util.PSQLException: Database connection failed when
> canceling copy operation
> at
> org.postgresql.core.v3.QueryExecutorImpl.cancelCopy(QueryExecutorImpl.java:796)
> at
> org.postgresql.core.v3.CopyOperationImpl.cancelCopy(CopyOperationImpl.java:32)
> at org.postgresql.copy.CopyManager.copyIn(CopyManager.java:150)
> at org.postgresql.copy.CopyManager.copyIn(CopyManager.java:126)
> at EvejrDBCopy.run(EvejrDBCopy.java:34)
>
>
> We use PostgreSQL 8.4, and JDBC 8.4-702.
>>
>>
> Your stacktrace shows that you are using 8.4-701, not 702. 702 had some
> fixes to the copy code when using a Reader, but your code shows you are
> using an InputStream, so those changes shouldn't be relevent.
>
> Kris Jurka
>
> --
> Sent via pgsql-jdbc mailing list (pgsql-jdbc(at)postgresql(dot)org)
> To make changes to your subscription:
> http://www.postgresql.org/mailpref/pgsql-jdbc
>

Thanks everybody!

Yes it was tried with the 701 build (I am almost sure that we also tried
with cvs-head as of 2 weeks back - will check up on that)

We will correct the connection.close() problem - thanks for pointing
that out!

And probably (if we still get problems) try the new build 800 driver.

Thanks again,
Kim

On 2010-09-13 19:27, Samuel Gendler wrote:
> Your error sure looks exactly like the problem that existed when using
> a Reader instead of InputStream with the older driver (701), though
> your description implies a different problem.
>
> On Mon, Sep 13, 2010 at 7:17 AM, Kris Jurka <books(at)ejurka(dot)com
> <mailto:books(at)ejurka(dot)com>> wrote:
>
>
>
> On Mon, 13 Sep 2010, Kim Bisgaard wrote:
>
> We are occasionally experiencing problems with our JDBC
> implementation of COPY IN.
>
> We have cut our program down to the attached example.
>
>
> Do you get the failure you've shown from this example? I get
> another failure from the connection being close before the last
> copy thread can complete its write operation. This seems like an
> expected failure, but I can't reproduce yours.
>
> org.postgresql.util.PSQLException: Database connection failed when
> canceling copy operation
> at
> org.postgresql.core.v3.QueryExecutorImpl.cancelCopy(QueryExecutorImpl.java:796)
> at
> org.postgresql.core.v3.CopyOperationImpl.cancelCopy(CopyOperationImpl.java:32)
> at org.postgresql.copy.CopyManager.copyIn(CopyManager.java:150)
> at org.postgresql.copy.CopyManager.copyIn(CopyManager.java:126)
> at EvejrDBCopy.run(EvejrDBCopy.java:34)
>
>
> We use PostgreSQL 8.4, and JDBC 8.4-702.
>
>
> Your stacktrace shows that you are using 8.4-701, not 702. 702
> had some fixes to the copy code when using a Reader, but your code
> shows you are using an InputStream, so those changes shouldn't be
> relevent.
>
> Kris Jurka
>
> --
> Sent via pgsql-jdbc mailing list (pgsql-jdbc(at)postgresql(dot)org
> <mailto:pgsql-jdbc(at)postgresql(dot)org>)
> To make changes to your subscription:
> http://www.postgresql.org/mailpref/pgsql-jdbc
>
>

Hi again,

We have corrected to program to wait for the thread to die before
closing the db-connection - see attached source.

But we still see problems related to overwritten data buffer. See below
for errors using build 800 or 900 driver - the webpage is a bit
uncertain ;-)

Any ideas?

Thanks in advance!
Kim

Sep 15, 2010 6:31:40 PM dk.dmi.appl.evejrfeeder.EvejrDB writeIndexedPointData
INFO: Inserting data in temporary_temperature_over_sea_2_m_3 at valid time 2010-09-15 12:00:00 for 38882 gridpoints
Sep 15, 2010 6:31:40 PM dk.dmi.appl.evejrfeeder.EvejrDBCopy run
INFO: ERROR: extra data after last expected column
Where: COPY temporary_temperature_over_sea_2_m_3, line 186: "60000187,2010-09-15 12:00:00,288.10498046860000746,2010-09-15 12:00:00,287.8037109375"
Sep 15, 2010 6:31:40 PM dk.dmi.appl.evejrfeeder.EvejrDBCopy run
INFO: ERROR: extra data after last expected column
Where: COPY temporary_temperature_over_sea_2_m_3, line 186: "60000187,2010-09-15 12:00:00,288.10498046860000746,2010-09-15 12:00:00,287.8037109375"
org.postgresql.util.PSQLException: ERROR: extra data after last expected column
Where: COPY temporary_temperature_over_sea_2_m_3, line 186: "60000187,2010-09-15 12:00:00,288.10498046860000746,2010-09-15 12:00:00,287.8037109375"
at org.postgresql.core.v3.QueryExecutorImpl.receiveErrorResponse(QueryExecutorImpl.java:2062)
at org.postgresql.core.v3.QueryExecutorImpl.processCopyResults(QueryExecutorImpl.java:929)
at org.postgresql.core.v3.QueryExecutorImpl.writeToCopy(QueryExecutorImpl.java:838)
at org.postgresql.core.v3.CopyInImpl.writeToCopy(CopyInImpl.java:53)
at org.postgresql.copy.CopyManager.copyIn(CopyManager.java:179)
at org.postgresql.copy.CopyManager.copyIn(CopyManager.java:161)
at dk.dmi.appl.evejrfeeder.EvejrDBCopy.run(Unknown Source)
at java.lang.Thread.run(Thread.java:619)
Sep 15, 2010 6:31:43 PM dk.dmi.appl.evejrfeeder.EvejrDB writeIndexedPointData

Sep 15, 2010 6:52:21 PM dk.dmi.appl.evejrfeeder.EvejrDB writeIndexedPointData
INFO: Inserting data in temporary_wind_speed_150_m_3 at valid time 2010-09-15 12:00:00 for 38882 gridpoints
Sep 15, 2010 6:52:21 PM dk.dmi.appl.evejrfeeder.EvejrDBCopy run
INFO: ERROR: missing data for column "wind_speed_150_m"
Where: COPY temporary_wind_speed_150_m_3, line 173: "60000188,2010-09-15 12:00:00"
Sep 15, 2010 6:52:21 PM dk.dmi.appl.evejrfeeder.EvejrDBCopy run
INFO: ERROR: missing data for column "wind_speed_150_m"
Where: COPY temporary_wind_speed_150_m_3, line 173: "60000188,2010-09-15 12:00:00"
org.postgresql.util.PSQLException: ERROR: missing data for column "wind_speed_150_m"
Where: COPY temporary_wind_speed_150_m_3, line 173: "60000188,2010-09-15 12:00:00"
at org.postgresql.core.v3.QueryExecutorImpl.receiveErrorResponse(QueryExecutorImpl.java:2062)
at org.postgresql.core.v3.QueryExecutorImpl.processCopyResults(QueryExecutorImpl.java:929)
at org.postgresql.core.v3.QueryExecutorImpl.writeToCopy(QueryExecutorImpl.java:838)
at org.postgresql.core.v3.CopyInImpl.writeToCopy(CopyInImpl.java:53)
at org.postgresql.copy.CopyManager.copyIn(CopyManager.java:179)
at org.postgresql.copy.CopyManager.copyIn(CopyManager.java:161)
at dk.dmi.appl.evejrfeeder.EvejrDBCopy.run(Unknown Source)
at java.lang.Thread.run(Thread.java:619)
Sep 15, 2010 6:52:24 PM dk.dmi.appl.evejrfeeder.EvejrDB writeIndexedPointDataSep 15, 2010 6:52:21 PM dk.dmi.appl.evejrfeeder.EvejrDB writeIndexedPointData
INFO: Inserting data in temporary_wind_speed_150_m_3 at valid time 2010-09-15 12:00:00 for 38882 gridpoints

Sep 15, 2010 6:56:47 PM dk.dmi.appl.evejrfeeder.EvejrDB writeIndexedPointData
INFO: Inserting data in temporary_relative_humidity_3 at valid time 2010-09-15 12:00:00 for 38882 gridpoints
Sep 15, 2010 6:56:47 PM dk.dmi.appl.evejrfeeder.EvejrDBCopy run
INFO: ERROR: invalid input syntax for type timestamp: "2010-09-"
Where: COPY temporary_relative_humidity_3, line 173, column valid_at: "2010-09-"
Sep 15, 2010 6:56:47 PM dk.dmi.appl.evejrfeeder.EvejrDBCopy run
INFO: ERROR: invalid input syntax for type timestamp: "2010-09-"
Where: COPY temporary_relative_humidity_3, line 173, column valid_at: "2010-09-"
org.postgresql.util.PSQLException: ERROR: invalid input syntax for type timestamp: "2010-09-"
Where: COPY temporary_relative_humidity_3, line 173, column valid_at: "2010-09-"
at org.postgresql.core.v3.QueryExecutorImpl.receiveErrorResponse(QueryExecutorImpl.java:2062)
at org.postgresql.core.v3.QueryExecutorImpl.processCopyResults(QueryExecutorImpl.java:929)
at org.postgresql.core.v3.QueryExecutorImpl.writeToCopy(QueryExecutorImpl.java:838)
at org.postgresql.core.v3.CopyInImpl.writeToCopy(CopyInImpl.java:53)
at org.postgresql.copy.CopyManager.copyIn(CopyManager.java:179)
at org.postgresql.copy.CopyManager.copyIn(CopyManager.java:161)
at dk.dmi.appl.evejrfeeder.EvejrDBCopy.run(Unknown Source)
at java.lang.Thread.run(Thread.java:619)
Sep 15, 2010 6:56:51 PM dk.dmi.appl.evejrfeeder.EvejrDB writeIndexedPointData

On 2010-09-14 09:14, Kim Bisgaard wrote:
> Thanks everybody!
>
> Yes it was tried with the 701 build (I am almost sure that we also
> tried with cvs-head as of 2 weeks back - will check up on that)
>
> We will correct the connection.close() problem - thanks for pointing
> that out!
>
> And probably (if we still get problems) try the new build 800 driver.
>
> Thanks again,
> Kim
>
>
> On 2010-09-13 19:27, Samuel Gendler wrote:
>> Your error sure looks exactly like the problem that existed when
>> using a Reader instead of InputStream with the older driver (701),
>> though your description implies a different problem.
>>
>> On Mon, Sep 13, 2010 at 7:17 AM, Kris Jurka <books(at)ejurka(dot)com
>> <mailto:books(at)ejurka(dot)com>> wrote:
>>
>>
>>
>> On Mon, 13 Sep 2010, Kim Bisgaard wrote:
>>
>> We are occasionally experiencing problems with our JDBC
>> implementation of COPY IN.
>>
>> We have cut our program down to the attached example.
>>
>>
>> Do you get the failure you've shown from this example? I get
>> another failure from the connection being close before the last
>> copy thread can complete its write operation. This seems like an
>> expected failure, but I can't reproduce yours.
>>
>> org.postgresql.util.PSQLException: Database connection failed
>> when canceling copy operation
>> at
>> org.postgresql.core.v3.QueryExecutorImpl.cancelCopy(QueryExecutorImpl.java:796)
>> at
>> org.postgresql.core.v3.CopyOperationImpl.cancelCopy(CopyOperationImpl.java:32)
>> at
>> org.postgresql.copy.CopyManager.copyIn(CopyManager.java:150)
>> at
>> org.postgresql.copy.CopyManager.copyIn(CopyManager.java:126)
>> at EvejrDBCopy.run(EvejrDBCopy.java:34)
>>
>>
>> We use PostgreSQL 8.4, and JDBC 8.4-702.
>>
>>
>> Your stacktrace shows that you are using 8.4-701, not 702. 702
>> had some fixes to the copy code when using a Reader, but your
>> code shows you are using an InputStream, so those changes
>> shouldn't be relevent.
>>
>> Kris Jurka
>>
>> --
>> Sent via pgsql-jdbc mailing list (pgsql-jdbc(at)postgresql(dot)org
>> <mailto:pgsql-jdbc(at)postgresql(dot)org>)
>> To make changes to your subscription:
>> http://www.postgresql.org/mailpref/pgsql-jdbc
>>
>>