Thread: 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.Kraaijeveld@Askesis.nl web: www.askesis.nl
Attachment
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
Hi Kris,
You have tested this with an insert statement. Could you do that also for an update (or try to tell me how I can do
that)?I am getting very strange differences in running time between inserts and update ( 260000 inserts are measured in
seconds,260000 updates over 1 column in the same table are measured in minutes)
TIA
Groeten,
Joost Kraaijeveld
Askesis B.V.
Molukkenstraat 14
6524NB Nijmegen
tel: 024-3888063 / 06-51855277
fax: 024-3608416
e-mail: J.Kraaijeveld@Askesis.nl
web: www.askesis.nl
> -----Oorspronkelijk bericht-----
> Van: Kris Jurka [mailto:books@ejurka.com]
> Verzonden: zondag 13 november 2005 10:27
> Aan: Joost Kraaijeveld
> CC: pgsql-jdbc@postgresql.org; pgsql-hackers@postgresql.org
> Onderwerp: Re: [JDBC] prepareThreshold=1 and
> statement.executeBatch() ??
>
>
>
>
> 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@opencloud.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
On Sun, 13 Nov 2005, Joost Kraaijeveld wrote: > You have tested this with an insert statement. Could you do that also > for an update (or try to tell me how I can do that)? I am getting very > strange differences in running time between inserts and update ( 260000 > inserts are measured in seconds, 260000 updates over 1 column in the > same table are measured in minutes) > Certainly there are different costs associated with inserts vs. updates. An insert just needs to jam a new row in somewhere, but the update must first search the table to find the existing row. If you do not have an index this will take a while. If you update the same row every time this will also take a while because you'll be creating a whole bunch of dead rows in the table. Some more information on the table and type of updates could bring the update cost down, but comparing insert vs. update times is not a reasonable thing to do. Kris Jurka
Tom Lane wrote: > Oliver Jowett <oliver@opencloud.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@candle.pha.pa.us | (610) 359-1001 + If your life is a hard drive, | 13 Roberts Road + Christ can be your backup. | Newtown Square, Pennsylvania 19073