Re: jdbc PGCopyOutputStream close() v. endCopy()

Hi Rob,

Interesting. I've not looked too much into the copy implementation.
The JDBC list or the jdbc github repo https://github.com/pgjdbc/pgjdbc
might be a better place to report this. I know Lukas Edar monitors it as
well

Dave Cramer

davec(at)postgresintl(dot)com
www.postgresintl.com

On Tue, 8 Jan 2019 at 16:29, Rob Sargent <robjsargent(at)gmail(dot)com> wrote:

> As is often the case, I'm unsure of which of these methods to use, or if
> I'm using them correctly.
>
> PG10.5, jooq-3.10.8, postgresql-42.1.4, linux (redhat 6.9) and logback to
> a file.
>
> I have been using close() for a while but thought I would make use of
> either the returned long from endCopy() or perhaps getHandledRowCount().
>
> Both work perfectly, but when I use endCopy() I always get the exception
> shown near the bottom of this log excerpt. The COPY is on its own thread
> from the same connection as the direct jooq writes also listed. Again, the
> data is all saved but I am worried that I'm not closing properly even if I
> use close(). The data here doesn't warrent bulk copy but it's just a quick
> example to repeat.
>
> 13:32:55.785 [pool-1-thread-1] DEBUG edu.utah.camplab.jx.PayloadFromMux -
> STAGING TABLE CREATED: bulk."flk_g16-forcing very long name to trigger
> truncation_22_8045c0"
> 13:32:55.786 [pool-1-thread-1] INFO edu.utah.camplab.jx.PayloadFromMux -
> 8045c057-99ec-490b-90c1-85875269afee: started COPY work at 1546979575786
> 13:32:55.789 [pool-1-thread-1] INFO edu.utah.camplab.jx.PayloadFromMux -
> 8045c057-99ec-490b-90c1-85875269afee: Total segment save took 22 ms
> 13:32:55.790 [pool-1-thread-1] INFO edu.utah.camplab.jx.AbstractPayload -
> 8045c057-99ec-490b-90c1-85875269afee: closing process
> 8045c057-99ec-490b-90c1-85875269afee
> 13:32:55.790 [8045c057-99ec-490b-90c1-85875269afee] INFO
> e.u.camplab.jx.PayloadWriterThread - bulk."flk_g16-forcing very long name
> to trigger truncation_22_8045c0": Begin bulk copy segment
> 13:32:55.793 [8045c057-99ec-490b-90c1-85875269afee] INFO
> e.u.camplab.jx.PayloadWriterThread - bulked up to 89, maybe?
> 13:32:55.793 [pool-1-thread-1] DEBUG org.jooq.tools.LoggerListener -
> Executing batch query : insert into "process_input" ("id", "process_id",
> "input_type", "input_ref") values (?, ?, ?, ?)
> 13:32:55.795 [8045c057-99ec-490b-90c1-85875269afee] INFO
> e.u.camplab.jx.PayloadWriterThread - bulked up to 197, maybe?
> 13:32:55.797 [8045c057-99ec-490b-90c1-85875269afee] INFO
> e.u.camplab.jx.PayloadWriterThread - bulked up to 318, maybe?
> 13:32:55.798 [8045c057-99ec-490b-90c1-85875269afee] INFO
> e.u.camplab.jx.PayloadWriterThread - bulked up to 393, maybe?
> 13:32:55.799 [8045c057-99ec-490b-90c1-85875269afee] INFO
> e.u.camplab.jx.PayloadWriterThread - 393/393 segments delivered in 9 ms
> 13:32:55.799 [8045c057-99ec-490b-90c1-85875269afee] DEBUG
> e.u.camplab.jx.PayloadWriterThread - staged in 9 ms
> 13:32:55.800 [pool-1-thread-1] DEBUG org.jooq.tools.LoggerListener -
> Executing batch query : insert into "process_output" ("id",
> "process_id", "output_type", "output_ref") values (?, ?, ?, ?)
> 13:32:55.805 [8045c057-99ec-490b-90c1-85875269afee] ERROR
> e.u.camplab.jx.PayloadWriterThread - bulk."flk_g16-forcing very long name
> to trigger truncation_22_8045c0": i/o trouble
> java.io.IOException: Ending write to copy failed.
> at
> org.postgresql.copy.PGCopyOutputStream.close(PGCopyOutputStream.java:107)
> ~[postgresql-42.1.4.jar:42.1.4]
> at
> edu.utah.camplab.jx.PayloadWriterThread.run(PayloadWriterThread.java:75)
> ~[transport/:na]
> Caused by: org.postgresql.util.PSQLException: Tried to write to an
> inactive copy operation
> at
> org.postgresql.core.v3.QueryExecutorImpl.writeToCopy(QueryExecutorImpl.java:978)
> ~[postgresql-42.1.4.jar:42.1.4]
> at org.postgresql.core.v3.CopyInImpl.writeToCopy(CopyInImpl.java:35)
> ~[postgresql-42.1.4.jar:42.1.4]
> at
> org.postgresql.copy.PGCopyOutputStream.endCopy(PGCopyOutputStream.java:166)
> ~[postgresql-42.1.4.jar:42.1.4]
> at
> org.postgresql.copy.PGCopyOutputStream.close(PGCopyOutputStream.java:105)
> ~[postgresql-42.1.4.jar:42.1.4]
> ... 1 common frames omitted
> 13:32:55.810 [pool-1-thread-1] DEBUG org.jooq.tools.LoggerListener -
> Executing batch query : insert into "process_arg" ("id", "process_id",
> "argname", "argvalue_int", "argvalue_float", "argvalue_text") values (?, ?,
> ?, ?, ?, ?)
>
> The class doing the bulk work, PayloadWriterThread extends Thread, the
> thread name is set from the caller and the critical parts are as follows:
>
> @Override
> public void run() {
> try (PGCopyOutputStream writer = new PGCopyOutputStream(copyIn)) {
> long startAt = System.currentTimeMillis();
> deliverSegments(writer);
> long postDeliver = System.currentTimeMillis();
> logger.debug("staged in {} ms", postDeliver - startAt);
> }
> catch (SQLException sqle) {
> sqle.printStackTrace();
> logger.error("{}: sql trouble", tableName, sqle);
> throw new RuntimeException("Bulk copy failed on sql", sqle);
> }
> catch (IOException ioe) {
> ioe.printStackTrace();
> logger.error("{}: i/o trouble", tableName, ioe);
> throw new RuntimeException("Bulk copy failed on i/o", ioe);
> }
> }
> private void deliverSegments(PGCopyOutputStream writer) throws
> IOException, SQLException {
> logger.info("{}: Begin bulk copy segment", tableName);
>
> long counter = 0;
> long copied = 0;
> //These had better end up the same number
> long st = System.currentTimeMillis();
> for (Map.Entry<String, List<Segment>> seglistME :
> segmentListMap.entrySet()) {
> String pbsCSV = seglistME.getKey();
> UUID currentPbsId = probandsetIdMap.get(pbsCSV);
> if (currentPbsId == null) {
> throw new RuntimeException("Could not find pbsId by " +
> pbsCSV);
> }
> counter += seglistME.getValue().size();
> for (Segment segment : seglistME.getValue()) {
> String segmentCSV = makeCSV(segment, currentPbsId);
> writer.write(segmentCSV.getBytes());
> }
> logger.info("bulked up to {}, maybe?", counter);
> }
> copied = writer.endCopy();
> logger.info("{}/{} segments delivered in {} ms", copied, counter,
> System.currentTimeMillis() - st);
> }
>
> Also, the stack trace always references the line of the closing brace of
> the try-with-resources and not on the call to endCopy. Because it's a
> caught exception? Or it's closing a closed writer?
>
>
>