prepared statement already exists

[Rob Sargent]

This is a cross-post to both pgbouncer and jooq lists, as I am unsure where in my stack I need to address this issue.

I am testing my throughput by intensionally swamping my systems.  The stack I am using consists of
- postgres 10
- pgbouncer 1.7.2 (running on db machine)
- collector (java Selector programme running on NOT db machine)
- clients (java analysis running on machine(s) NOT db NOT collector)

The clients are spawned from GNU parallel, one second delay each, 100 jobs with max 16 concurrent (hyper-threaded processor count) and last for about 10 seconds.  The clients all finish successfully and more quickly than I can perform the rest of the stack.  This is a temporary, testing situation - ultimately the clients will take much longer as I do a more realistic amount (one thousand fold more) of work per invocation.

Each client sends a payload to the collector; the collector has ThreadPoolExecutor transforming payload into db calls via jOOQ.

The payload inserts 6 new records (over three tables) and updates one record; the same record updated in all payloads.
I am NOT using PreparedStatment in my code.
pbBouncer is in "pool_mode = transaction"
The jOOQ transaction is

        ctx.transaction(ltx -> {
                startProcess(ctx); //three inserts, two tables
                writeSegments(ctx); //update single record by PK (repeated per client)
                finishProcess(ctx); //three inserts, one table
            });

If I correctly read the error message below (the fifth of 5 attempts for same payload) I must be reusing a pooled db connection for a second payload.  If so, is this pbbouncer failing to close connection after transaction; jooq not signaling end of transaction, an artifact of intentional overload; other?

2017-08-29T17:33:25-06:00 lonepeak9 [pool-1-thread-6] edu.utah.camplab.jx.AbstractPayload d3d3a62f-64cf-4ffe-b7f8-927943af5c3e: failed write attempt #5, SQL [insert into "process_input" ("id", "process_id", "input_type", "input_ref") values (?, ?, ?, ?)]; Batch entry 0 insert into "process_input" ("id", "process_id", "input_type", "input_ref") values ('11c0e3d1-59a5-469e-a77d-89dcc98f03e0'::uuid, '14271c8d-31ea-4cd7-bcba-62b2436a9c21'::uuid, 'pedfile', 'a3a1326a-cd40-4777-903f-546621028e9f') was aborted: ERROR: prepared statement "S_1" already exists  Call getNextException to see other errors in the batch.

[Omar Kilani]

Hi Rob,

Please see the pgbouncer FAQ:

https://pgbouncer.github.io/faq.html

Specifically:

"Disabling prepared statements in JDBC"

Hope this helps!

Regards,
Omar

> _______________________________________________
> Pgbouncer-general mailing list
> Pgbounce...@lists.pgfoundry.org
> http://lists.pgfoundry.org/mailman/listinfo/pgbouncer-general
>

[Rob Sargent]

Yes, I've seen that bit, but wonder how that impacts the code which is using/generating PreparedStatement calls? 

Btw, of the 100 runs of the client only went through all 5 attempts and ultimately failed, though many clients successfully resubmitted their payload.  You can see below (if you strectch your screen really wide) the first client (later runtime) failed once then succeeded.   (The emergency landing worked, dumping a the json version of the data)

[u0138544@syslog camp]$ zcat yesterday/lonepeak9/messages.gz | grep 14a99861-fb7c-4c45-bed0-c12d0bd4ae15
2017-08-29T21:44:50-06:00 lonepeak9 [pool-1-thread-5] edu.utah.camplab.server.PayloadThread Saving Private Ryan: 14a99861-fb7c-4c45-bed0-c12d0bd4ae15
2017-08-29T21:44:50-06:00 lonepeak9 [pool-1-thread-5] edu.utah.camplab.jx.AbstractPayload sending 14a99861-fb7c-4c45-bed0-c12d0bd4ae15
2017-08-29T21:44:50-06:00 lonepeak9 [pool-1-thread-5] edu.utah.camplab.jx.AbstractPayload 14a99861-fb7c-4c45-bed0-c12d0bd4ae15: start transaction
2017-08-29T21:44:50-06:00 lonepeak9 [pool-1-thread-5] edu.utah.camplab.jx.AbstractPayload 14a99861-fb7c-4c45-bed0-c12d0bd4ae15: failed write attempt #1, SQL [insert into "process_input" ("id", "process_id", "input_type", "input_ref") values (?, ?, ?, ?)]; Batch entry 0 insert into "process_input" ("id", "process_id", "input_type", "input_ref") values ('e8a8f8cb-4b84-43b6-8c0d-8081a672deca'::uuid, 'c2c13b27-bc8a-4ece-aab2-036b93180b2e'::uuid, 'pedfile', 'a3a1326a-cd40-4777-903f-546621028e9f') was aborted: ERROR: prepared statement "S_1" already exists  Call getNextException to see other errors in the batch.
2017-08-29T21:44:50-06:00 lonepeak9 [pool-1-thread-5] edu.utah.camplab.jx.AbstractPayload 14a99861-fb7c-4c45-bed0-c12d0bd4ae15: start transaction
2017-08-29T21:44:50-06:00 lonepeak9 [pool-1-thread-5] edu.utah.camplab.jx.AbstractPayload 14a99861-fb7c-4c45-bed0-c12d0bd4ae15: end transaction

[u0138544@syslog camp]$ zcat yesterday/lonepeak9/messages.gz | grep d3d3a62f-64cf-4ffe-b7f8-927943af5c3e
2017-08-29T17:33:25-06:00 lonepeak9 [pool-1-thread-6] edu.utah.camplab.server.PayloadThread Saving Private Ryan: d3d3a62f-64cf-4ffe-b7f8-927943af5c3e
2017-08-29T17:33:25-06:00 lonepeak9 [pool-1-thread-6] edu.utah.camplab.jx.AbstractPayload sending d3d3a62f-64cf-4ffe-b7f8-927943af5c3e
2017-08-29T17:33:25-06:00 lonepeak9 [pool-1-thread-6] edu.utah.camplab.jx.AbstractPayload d3d3a62f-64cf-4ffe-b7f8-927943af5c3e: failed write attempt #1, SQL [insert into "process_input" ("id", "process_id", "input_type", "input_ref") values (?, ?, ?, ?)]; Batch entry 0 insert into "process_input" ("id", "process_id", "input_type", "input_ref") values ('05f9c2b7-b2a1-441b-aabe-686ed48e84c2'::uuid, '40cd010d-804d-4963-ad06-eca57b795f74'::uuid, 'pedfile', 'a3a1326a-cd40-4777-903f-546621028e9f') was aborted: ERROR: prepared statement "S_1" already exists  Call getNextException to see other errors in the batch.
2017-08-29T17:33:25-06:00 lonepeak9 [pool-1-thread-6] edu.utah.camplab.jx.AbstractPayload d3d3a62f-64cf-4ffe-b7f8-927943af5c3e: failed write attempt #2, SQL [insert into "process_input" ("id", "process_id", "input_type", "input_ref") values (?, ?, ?, ?)]; Batch entry 0 insert into "process_input" ("id", "process_id", "input_type", "input_ref") values ('d29a39fd-e952-4c6b-a016-b6ca72f0a546'::uuid, '13083f28-a6c6-44a0-be14-e24f8add05f9'::uuid, 'pedfile', 'a3a1326a-cd40-4777-903f-546621028e9f') was aborted: ERROR: prepared statement "S_1" already exists  Call getNextException to see other errors in the batch.
2017-08-29T17:33:25-06:00 lonepeak9 [pool-1-thread-6] edu.utah.camplab.jx.AbstractPayload d3d3a62f-64cf-4ffe-b7f8-927943af5c3e: failed write attempt #3, SQL [insert into "process_input" ("id", "process_id", "input_type", "input_ref") values (?, ?, ?, ?)]; Batch entry 0 insert into "process_input" ("id", "process_id", "input_type", "input_ref") values ('25831dcc-2cfe-4a54-a6e6-b5a4efec08da'::uuid, 'f150d753-822e-4aa2-8745-fc1ce6e99041'::uuid, 'pedfile', 'a3a1326a-cd40-4777-903f-546621028e9f') was aborted: ERROR: prepared statement "S_1" already exists  Call getNextException to see other errors in the batch.
2017-08-29T17:33:25-06:00 lonepeak9 [pool-1-thread-6] edu.utah.camplab.jx.AbstractPayload d3d3a62f-64cf-4ffe-b7f8-927943af5c3e: failed write attempt #4, SQL [insert into "process_input" ("id", "process_id", "input_type", "input_ref") values (?, ?, ?, ?)]; Batch entry 0 insert into "process_input" ("id", "process_id", "input_type", "input_ref") values ('1ec5e560-35aa-4ea9-9c4b-22293a67b8bf'::uuid, '2d05a7a9-625e-4dfe-9e72-ec4671cdd67c'::uuid, 'pedfile', 'a3a1326a-cd40-4777-903f-546621028e9f') was aborted: ERROR: prepared statement "S_1" already exists  Call getNextException to see other errors in the batch.

2017-08-29T17:33:25-06:00 lonepeak9 [pool-1-thread-6] edu.utah.camplab.jx.AbstractPayload d3d3a62f-64cf-4ffe-b7f8-927943af5c3e: failed write attempt #5, SQL [insert into "process_input" ("id", "process_id", "input_type", "input_ref") values (?, ?, ?, ?)]; Batch entry 0 insert into "process_input" ("id", "process_id", "input_type", "input_ref") values ('11c0e3d1-59a5-469e-a77d-89dcc98f03e0'::uuid, '14271c8d-31ea-4cd7-bcba-62b2436a9c21'::uuid, 'pedfile', 'a3a1326a-cd40-4777-903f-546621028e9f') was aborted: ERROR: prepared statement "S_1" already exists  Call getNextException to see other errors in the batch.

2017-08-29T17:33:25-06:00 lonepeak9 [pool-1-thread-6] edu.utah.camplab.server.PayloadThread Write attempt failed for payload d3d3a62f-64cf-4ffe-b7f8-927943af5c3e. Trying emergency landing at /tmp/SGS.crashpad
2017-08-29T17:33:25-06:00 lonepeak9 [pool-1-thread-6] edu.utah.camplab.server.PayloadThread EMERGENCY LANDING: writing run d3d3a62f-64cf-4ffe-b7f8-927943af5c3e as json to /tmp/SGS.crashpad

[Omar Kilani]

Hi Rob,

It depends on the code -- if you're not explicitly using prepared
statements from other pgsql sessions it should be fine.

There's no way to use 'pool = transaction' without
'prepareThreshold=0'. Even with 'prepareThreshold=0', pgjdbc still
uses prepared statements. It just doesn't *reuse* them (which is where
the problem comes in with transaction pooling mode). The performance
improvement in high RPS environments from using transaction pooling
mode far outweighs any benefits of reusing prepared statements.

Otherwise you can switch to 'pool = session'.

Regards,
Omar

[Rob Sargent]

I have augmented the connection url in the client code as thus:

Connection dbconn = DriverManager.getConnection(url+"?prepareThreshold=0", ...);

but I still see the "already exists" message.  

I tried putting that on the pgbouncer database definition line as:

tsgs = host=<dbhost> port=5432 dbname=tsgs prepareThreshold=0

but that isn't valid and disrupted any attempt to login (saying dbname tsgs does not exist)

However, on the postgres site, https://jdbc.postgresql.org/documentation/head/server-prepare.html, I don't see that zero turns it off (it defaults to 5). Can you confirm that zero is the kill switch here?

Thanks

[Lukas Eder]

Hi Rob,

Thanks for the cross-post, that's a very interesting technique to share knowledge across communities.

I'm just going to briefly comment on the jOOQ part, inline:

2017-08-30 18:20 GMT+02:00 Rob Sargent <rob.s...@utah.edu>:

I am NOT using PreparedStatment in my code.

jOOQ by default uses PreparedStatements, not static statements, and from what can be seen in your logs, this is confirmed.

If you want to force jOOQ to send static statements to the server, you can specify

Settings.statementType = StatementType.STATIC_STATEMENT

This is documented here:

https://www.jooq.org/doc/latest/manual/sql-execution/statement-type

Hope this helps,

Lukas

[Rob Sargent]

Lukas,

I cross-posted as I was unsure as to where the solution may lay, and am still pretty much in the same boat.

I'm not in a hurry to over-ride the PreparedStatement usage. I will experiment as you've outlined but I'll have to weigh the injection risk.  Mainly I'm curious as to how this re-use is occurring and if there's any corrective action in my general scheme. An explicit closing of the db connection perhaps? (The suggestion to augment the connection url with "?prepareThreshold=0" does not appear to change the outcome.)

--
You received this message because you are subscribed to the Google Groups "jOOQ User Group" group.
To unsubscribe from this group and stop receiving emails from it, send an email to jooq-user+...@googlegroups.com.
For more options, visit https://groups.google.com/d/optout.

[Lukas Eder]

I'll have to weigh the injection risk.

jOOQ will inline the bind variables for you, escaping them appropriately depending on their types - so there's no additional injection risk from using StatementType.STATIC_STATEMENT.

 

  Mainly I'm curious as to how this re-use is occurring and if there's any corrective action in my general scheme. An explicit closing of the db connection perhaps?

I remember having seen a similar (but not identical) issue in the distant past when using PreparedStatement with ref cursor results. At the time, it had to do with transactions and the JDBC autocommit flag.

This is just thinking out loud, it's not the same issue, but the JDBC driver did have some issues with that...

[Rob Sargent]

Good news on the injection front. I ran with the Settings indicated and for the first time got 100% of my jobs saved properly. I have a second related client which has to store lists with 1k-10K entries.  Any guess as to the performance difference here with v. without PreparedStatement in play? In this scenario, the jobs are much less frequent.

Thanks, as always

[Lukas Eder]

Hi Rob,

My production experience with these kinds of tuning is mostly with Oracle, so I'm not 100% qualified to give you an answer on PostgreSQL - but the most important difference from a performance perspective between using (static) Statement and PreparedStatement is the simple fact that the latter more easily profits from your database's execution plan cache. This cache is used to store calculated execution plans for identical SQL strings. When you have two consecutive static statements like these:

    SELECT * FROM tab WHERE col = 1;

    SELECT * FROM tab WHERE col = 2;

Then the plan must be calculated for each query afresh, with all the overhead of finding the best plan, etc. If, however, you use a PreparedStatement

    SELECT * FROM tab WHERE col = ?;

    SELECT * FROM tab WHERE col = ?;

Then, the same plan can be reused at the price of a slight cardinality estimate error for the "col = ?" predicate, depending on how skewed the data in "col" is (the more skewed, the bigger the error).

In general, the error is acceptable and the improved performance achieved by this cache is very desireable. In Oracle, it is quite possible to kill a database server if you're not using PreparedStatements often enough, because there will be tons of concurrency on the execution plan cache for all those statements that can never be reused and must thus be purged from the non-infinite cache again to make room for new statements.

There are exceptions where constant literals can be parsed into bind variables by the server (e.g. Oracle and SQL Server can do this), but it is often not recommended to activate this feature.

Btw, looking for a PostgreSQL specific link, I found this:

http://use-the-index-luke.com/sql/explain-plan/postgres/concrete-planning

Note that the default setting is five, which means that the first four executions will actually use the bind parameters during prepare, the later ones not. That counter starts fresh for each PreparedStatement instance.

Which maybe also explains that limit of 5, you've encountered

Hope this helps,
Lukas

To unsubscribe from this group and stop receiving emails from it, send an email to jooq-user+unsubscribe@googlegroups.com.

For more options, visit https://groups.google.com/d/optout.

--
You received this message because you are subscribed to the Google Groups "jOOQ User Group" group.

To unsubscribe from this group and stop receiving emails from it, send an email to jooq-user+unsubscribe@googlegroups.com.

[Rob Sargent]

Since I'm running two separate JVMs for each of my tasks, I will try using Static for the simple update case we've been discussing and Prepared for the task which does bulk inserts (jOOQ "batch").

I've split this discussion between the two group.  Not sure if that was wise.

I still don't quite understand the collision (re-use of prep. statement); it appears to be transient; I have instances of several such failures then success from single client instance (the client connects; fires transaction, but no specific connection close; exit jvm.  Is that last bit the root of the problem?  I'll try adding one. ..fumles around.. Using

To unsubscribe from this group and stop receiving emails from it, send an email to jooq-user+...@googlegroups.com.

[Rob Sargent]

Sorry wrong keyboard

Using

while (i++ < 5) {

    try(DSLContext c = DriverManager.getConnection(...)) {

        write(ctx);

    }

    catch(SQLException e) {

        logger.error("attempt #{} failed: {}", e.getMessage(), e);

}

Through 100 (gnu parallel) invocations of the java program I get 98 attempt #1 failures, 96 #2s, 94 #3s, 2 #4s and a single #5 and indeed I updated the target 99 times. Maybe I should just do #6!

So it isn't the missing/(assumed) connection.close().  So I think I'll have to chase the other fork of this thread - the pgbouncer side.  I'll up-date here if I learn anything - but I'm a very old dog so chances aren't good.

On 09/01/2017 06:04 AM, Lukas Eder wrote:

To unsubscribe from this group and stop receiving emails from it, send an email to jooq-user+...@googlegroups.com.

[Lukas Eder]

I'm sorry - I don't know PostgreSQL well enough in this area. Please do update this list, I'm sure people might find it useful in the future.

[Rob Sargent]

Ah, using postgresql-42.1.4.jar, db_url+"?prepareThreshold=0" and NOT setting jOOQ StatementType.STATIC_STATEMENT I get no messages about 'prepared statement already exists' and no failures in 100 clients over 16 cores.

I think that sums it up! Use current tools is the lesson.

Thanks to both tool providers (this is bcc'd to jooq list at pgbouncer list squawks on plain cc)

rjs

On 09/07/2017 10:38 AM, Omar Kilani wrote:

Hi Rob,

I can confirm this as I wrote the original patch to pgjdbc. :)

It may be the case that you need to use a more recent pgjdbc build as the patch got integrated within the last year or so (IIRC).

Regards,
Omar

On Thu, Sep 7, 2017 at 9:36 AM Rob Sargent <rob.s...@utah.edu> wrote:

Omar,

My last message may have not gone through because I was attempting to
cross-post to the jOOQ list. (I got a message about it being reviewed
for some forgotten reason.)

Can you confirm that zero is the kill switch for re-using prepared
statements on the server.  And is it connection based? I have two
distinct modes of use and the other (not yet shown) makes heavy use of
jOOQ batch writing (sending lists of 1000s of items) which in turn uses
(quite sensibly) prepared statements.  I have never seen this list-based
usage generate the error, but I don't go through pgbouncer connections
when doing so - a two-tiered scenario.

In the problematic case, I can turn off prepared statements from the
jOOQ interface and all seems well.  I'm just trying to understand how
I'm hitting the 'already exists' error in the default world of
PreparedStatements under separate connections. Granted I am
intensionally flooding pgbouncer with requests: am I re-using pgbouncer
connections by repeated requests from same host/user thereby exposing a
client to re-using a prepared statement?

(I'll cross this back to the jOOQ list later)

Thanks