Thread: 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
Attachment
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
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@ejurka.com> wrote:
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.
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.
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)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.We use PostgreSQL 8.4, and JDBC 8.4-702.
Kris Jurka
--
Sent via pgsql-jdbc mailing list (pgsql-jdbc@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-jdbc
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@ejurka.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@postgresql.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:
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@ejurka.com> wrote: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.
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.
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)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.We use PostgreSQL 8.4, and JDBC 8.4-702.
Kris Jurka
--
Sent via pgsql-jdbc mailing list (pgsql-jdbc@postgresql.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
On 2010-09-14 09:14, Kim Bisgaard wrote:
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@ejurka.com> wrote: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.
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.
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)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.We use PostgreSQL 8.4, and JDBC 8.4-702.
Kris Jurka
--
Sent via pgsql-jdbc mailing list (pgsql-jdbc@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-jdbc