Re: prepareThreshold=1 and statement.executeBatch() ??

Hi,

I have a connection that is created with "prepareThreshold=1" in the
connection string. I use a prepared statement that I fill with
addbatch() and that I execute with executeBatch() (for full source: see
"application.java" attachment).

Tracing all statements in my PostgreSQL logs I see (for the full log:
see "postgresql.log" attachement):

LOG: statement: PREPARE S_2 AS update prototype.customers set title=
$1 , defaultcurrency=$2, defaulttermsofdelivery=$3 ,
defaulttermsofpayment=$4 where customernumber=$5
LOG: statement: <BIND>
LOG: statement: EXECUTE <unnamed> [PREPARE: update
prototype.customers set title=$1 , defaultcurrency=$2, defaultter
msofdelivery=$3, defaulttermsofpayment=$4 where customernumber=$5]
LOG: duration: 773.841 ms
LOG: statement: <BIND>
LOG: statement: EXECUTE <unnamed> [PREPARE: update
prototype.customers set title=$1 , defaultcurrency=$2, defaultter
msofdelivery=$3, defaulttermsofpayment=$4 where customernumber=$5]
LOG: duration: 377.981 ms

Does this output mean that the prepared statement with the name "S_2" is
not used in the following 2 EXECUTE statements and that therefor each
execute statement is planned again?

BTW: I used PostgreSQL 8.1 and PostgreSQL-8.1-404.jdbc3.jar.

TIA

--
Groeten,

Joost Kraaijeveld
Askesis B.V.
Molukkenstraat 14
6524NB Nijmegen
tel: 024-3888063 / 06-51855277
fax: 024-3608416
e-mail: J(dot)Kraaijeveld(at)Askesis(dot)nl
web: www.askesis.nl

On Sun, 13 Nov 2005, Joost Kraaijeveld wrote:

> I have a connection that is created with "prepareThreshold=1" in the
> connection string. I use a prepared statement that I fill with
> addbatch() and that I execute with executeBatch() (for full source: see
> "application.java" attachment).
>
> LOG: statement: PREPARE S_2 AS update prototype.customers set title=
> $1 , defaultcurrency=$2, defaulttermsofdelivery=$3 ,
> defaulttermsofpayment=$4 where customernumber=$5
> LOG: statement: <BIND>
> LOG: statement: EXECUTE <unnamed> [PREPARE: update
> prototype.customers set title=$1 , defaultcurrency=$2, defaultter
> msofdelivery=$3, defaulttermsofpayment=$4 where customernumber=$5]
> LOG: duration: 773.841 ms
> LOG: statement: <BIND>
> LOG: statement: EXECUTE <unnamed> [PREPARE: update
> prototype.customers set title=$1 , defaultcurrency=$2, defaultter
> msofdelivery=$3, defaulttermsofpayment=$4 where customernumber=$5]
> LOG: duration: 377.981 ms
>
> Does this output mean that the prepared statement with the name "S_2" is
> not used in the following 2 EXECUTE statements and that therefor each
> execute statement is planned again?
>

No, this actually looks like a bug in the server side logging. The JDBC
driver issues:

FE=> Parse(stmt=S_1,query="INSERT INTO tt VALUES ($1)",oids={23})
FE=> Bind(stmt=S_1,portal=null,$1=<1>)
FE=> Describe(portal=null)
FE=> Execute(portal=null,limit=1)
FE=> Bind(stmt=S_1,portal=null,$1=<2>)
FE=> Describe(portal=null)
FE=> Execute(portal=null,limit=1)
FE=> Sync

I assume the server side logging code is getting confused because it uses
a named statement, but the unnamed portal.

Kris Jurka

> On Sun, 13 Nov 2005, Joost Kraaijeveld wrote:
>
>> I have a connection that is created with "prepareThreshold=1" in the
>> connection string. I use a prepared statement that I fill with
>> addbatch() and that I execute with executeBatch() (for full source: see
>> "application.java" attachment).
>>
>> LOG: statement: PREPARE S_2 AS update prototype.customers set title=
>> $1 , defaultcurrency=$2, defaulttermsofdelivery=$3 ,
>> defaulttermsofpayment=$4 where customernumber=$5
>> LOG: statement: <BIND>
>> LOG: statement: EXECUTE <unnamed> [PREPARE: update
>> prototype.customers set title=$1 , defaultcurrency=$2, defaultter
>> msofdelivery=$3, defaulttermsofpayment=$4 where customernumber=$5]
>> LOG: duration: 773.841 ms
>> LOG: statement: <BIND>
>> LOG: statement: EXECUTE <unnamed> [PREPARE: update
>> prototype.customers set title=$1 , defaultcurrency=$2, defaultter
>> msofdelivery=$3, defaulttermsofpayment=$4 where customernumber=$5]
>> LOG: duration: 377.981 ms
>>
>> Does this output mean that the prepared statement with the name "S_2" is
>> not used in the following 2 EXECUTE statements and that therefor each
>> execute statement is planned again?

The driver does not actually issue PREPARE or EXECUTE statements; the
server is pretending that the protocol-level Prepare/Bind/Execute
messages are actually something issuing PREPARE/EXECUTE at the SQL level
(but in reality, nothing is issuing precisely the queries that are being
logged -- the query that is submitted is just your plain "update ..."
query).

The PREPARE S_2 AS .. logs that a Prepare message was processed (for the
query "update ..."). This does parsing/planning work and creates a named
prepared statement called S_2 on the server.

The <BIND> means that some previously prepared statement (you can't tell
which statement from what is logged! -- but it's S_2 in this case) is
being bound to parameter values via a Bind message, creating an unnamed
portal.

The EXECUTE <unnamed> means the unnamed portal is being executed via an
Execute message. It also logs the underlying statement at that point,
but not the statement name (!).

So if I read the logs right, the single prepared statement S_2 *is*
being reused in the case above.

Yes, it's a horribly confusing way for the server to log things. I
raised it on -hackers earlier in the 8.1 cycle, but I've not had time to
work on it myself.

-O

Oliver Jowett <oliver(at)opencloud(dot)com> writes:
> The driver does not actually issue PREPARE or EXECUTE statements; the
> server is pretending that the protocol-level Prepare/Bind/Execute
> messages are actually something issuing PREPARE/EXECUTE at the SQL level

I had not realized that the logging code recently added to Parse/Bind/Execute
deliberately obscures the difference between a Parse message and an SQL
PREPARE (etc). This is a terrible decision IMHO and needs to be fixed
forthwith.

regards, tom lane

Tom Lane wrote:
> Oliver Jowett <oliver(at)opencloud(dot)com> writes:
> > The driver does not actually issue PREPARE or EXECUTE statements; the
> > server is pretending that the protocol-level Prepare/Bind/Execute
> > messages are actually something issuing PREPARE/EXECUTE at the SQL level
>
> I had not realized that the logging code recently added to Parse/Bind/Execute
> deliberately obscures the difference between a Parse message and an SQL
> PREPARE (etc). This is a terrible decision IMHO and needs to be fixed
> forthwith.

The output does look slightly different and was approved by the folks
using this feature. I don't understand the panic about it.

If people using the feature want to submit a patch to modify it, that
seems fine.

--
Bruce Momjian | http://candle.pha.pa.us
pgman(at)candle(dot)pha(dot)pa(dot)us | (610) 359-1001
+ If your life is a hard drive, | 13 Roberts Road
+ Christ can be your backup. | Newtown Square, Pennsylvania 19073