Обсуждение: 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

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