Prepared statements, parameters and logging

Hi all,

I have a system (postgres 8.1) which was until now running with JDBC
parameter prepareThreshold=1 so it is always using server side prepares
(we had some trouble in the past if not setting it so). Now we are
prepared to set this to 0, meaning no server side prepares by default...

The problem is that I did the switch and I still see queries which are
presumably server side prepared (marked with <unnamed> in the log - I
enabled reporting queries longer than 2 seconds)...

The question is how do I tell for sure from the DB log if a query is
server side prepared or not ? I was presuming that <unnamed> in the log
means server side prepare, some name like 'C_xyz' means client side
prepared statement. Is this correct ?

Thanks,
Csaba.

Csaba,

They will all be prepared. The threshold is whether to re-use the
prepared statement.

What you are seeing is the use of unnamed statements.

If you really want them turned off use protocolVersion=2

Dave
On 25-Jun-07, at 6:47 AM, Csaba Nagy wrote:

> Hi all,
>
> I have a system (postgres 8.1) which was until now running with JDBC
> parameter prepareThreshold=1 so it is always using server side
> prepares
> (we had some trouble in the past if not setting it so). Now we are
> prepared to set this to 0, meaning no server side prepares by
> default...
>
> The problem is that I did the switch and I still see queries which are
> presumably server side prepared (marked with <unnamed> in the log - I
> enabled reporting queries longer than 2 seconds)...
>
> The question is how do I tell for sure from the DB log if a query is
> server side prepared or not ? I was presuming that <unnamed> in the
> log
> means server side prepare, some name like 'C_xyz' means client side
> prepared statement. Is this correct ?
>
> Thanks,
> Csaba.
>
>
>
> ---------------------------(end of
> broadcast)---------------------------
> TIP 3: Have you checked our extensive FAQ?
>
> http://www.postgresql.org/docs/faq

Actually what I'm interested in is to give the server the parameter
values for planning or not... before I wanted generic queries so I
didn't want the server to see the parameters, and now I want the server
to see them before creating the execution plan... am I turning the right
knob for this ?

Thanks,
Csaba.

On Mon, 2007-06-25 at 12:54, Dave Cramer wrote:
> Csaba,
>
> They will all be prepared. The threshold is whether to re-use the
> prepared statement.
>
> What you are seeing is the use of unnamed statements.
>
> If you really want them turned off use protocolVersion=2
>
> Dave
> On 25-Jun-07, at 6:47 AM, Csaba Nagy wrote:
>
> > Hi all,
> >
> > I have a system (postgres 8.1) which was until now running with JDBC
> > parameter prepareThreshold=1 so it is always using server side
> > prepares
> > (we had some trouble in the past if not setting it so). Now we are
> > prepared to set this to 0, meaning no server side prepares by
> > default...
> >
> > The problem is that I did the switch and I still see queries which are
> > presumably server side prepared (marked with <unnamed> in the log - I
> > enabled reporting queries longer than 2 seconds)...
> >
> > The question is how do I tell for sure from the DB log if a query is
> > server side prepared or not ? I was presuming that <unnamed> in the
> > log
> > means server side prepare, some name like 'C_xyz' means client side
> > prepared statement. Is this correct ?
> >
> > Thanks,
> > Csaba.
> >
> >
> >
> > ---------------------------(end of
> > broadcast)---------------------------
> > TIP 3: Have you checked our extensive FAQ?
> >
> > http://www.postgresql.org/docs/faq
>

As far as I know you can't have both. In version 3 protocol,
everything is a server side prepared statement without parameters.

Dave
On 25-Jun-07, at 7:13 AM, Csaba Nagy wrote:

> Actually what I'm interested in is to give the server the parameter
> values for planning or not... before I wanted generic queries so I
> didn't want the server to see the parameters, and now I want the
> server
> to see them before creating the execution plan... am I turning the
> right
> knob for this ?
>
> Thanks,
> Csaba.
>
> On Mon, 2007-06-25 at 12:54, Dave Cramer wrote:
>> Csaba,
>>
>> They will all be prepared. The threshold is whether to re-use the
>> prepared statement.
>>
>> What you are seeing is the use of unnamed statements.
>>
>> If you really want them turned off use protocolVersion=2
>>
>> Dave
>> On 25-Jun-07, at 6:47 AM, Csaba Nagy wrote:
>>
>>> Hi all,
>>>
>>> I have a system (postgres 8.1) which was until now running with JDBC
>>> parameter prepareThreshold=1 so it is always using server side
>>> prepares
>>> (we had some trouble in the past if not setting it so). Now we are
>>> prepared to set this to 0, meaning no server side prepares by
>>> default...
>>>
>>> The problem is that I did the switch and I still see queries
>>> which are
>>> presumably server side prepared (marked with <unnamed> in the log
>>> - I
>>> enabled reporting queries longer than 2 seconds)...
>>>
>>> The question is how do I tell for sure from the DB log if a query is
>>> server side prepared or not ? I was presuming that <unnamed> in the
>>> log
>>> means server side prepare, some name like 'C_xyz' means client side
>>> prepared statement. Is this correct ?
>>>
>>> Thanks,
>>> Csaba.
>>>
>>>
>>>
>>> ---------------------------(end of
>>> broadcast)---------------------------
>>> TIP 3: Have you checked our extensive FAQ?
>>>
>>> http://www.postgresql.org/docs/faq
>>
>
>
> ---------------------------(end of
> broadcast)---------------------------
> TIP 5: don't forget to increase your free space map settings

Dave,

If I read [1] correctly, the prepareThreshold parameter should actually
do what I want in protocol version 3... or am I misreading something ?

[1] http://jdbc.postgresql.org/documentation/81/server-prepare.html

Cheers,
Csaba.

On Mon, 2007-06-25 at 13:24, Dave Cramer wrote:
> As far as I know you can't have both. In version 3 protocol,
> everything is a server side prepared statement without parameters.

I think the text should be specifying that once you exceed
preparedThreshold executions the driver uses a named prepared
statement, and can re-use it. Otherwise it uses unnamed prepared
statements which need to be prepared for each execution.

Dave
On 25-Jun-07, at 8:42 AM, Csaba Nagy wrote:

> Dave,
>
> If I read [1] correctly, the prepareThreshold parameter should
> actually
> do what I want in protocol version 3... or am I misreading something ?
>
> [1] http://jdbc.postgresql.org/documentation/81/server-prepare.html
>
> Cheers,
> Csaba.
>
> On Mon, 2007-06-25 at 13:24, Dave Cramer wrote:
>> As far as I know you can't have both. In version 3 protocol,
>> everything is a server side prepared statement without parameters.
>
>
>
> ---------------------------(end of
> broadcast)---------------------------
> TIP 5: don't forget to increase your free space map settings

On Mon, 2007-06-25 at 15:11, Dave Cramer wrote:
> I think the text should be specifying that once you exceed
> preparedThreshold executions the driver uses a named prepared
> statement, and can re-use it. Otherwise it uses unnamed prepared
> statements which need to be prepared for each execution.

OK, but I also thought that the value 0 means no reuse at all, i.e. it
should always prepare for each execution... and 1 should mean always
reuse, from the first statement on.

Before I was using prepareThreshold='1', and I was seeing only such
entries in the server log:

duration: 5437.499 ms statement: EXECUTE <unnamed> [PREPARE: SELECT
... ]

Note the <unnamed> in the log entry, it was always there for each
statement.

After setting prepareThreshold='0', I started getting 2 kinds of log
entries, the ones like above, and the likes:

duration: 2200.570 ms statement: EXECUTE C_220047 [PREPARE: SELECT
... ]

Note the C_220047, that's what's changed...

I distinctly remember discussing this issue some time ago on this list,
back then I needed the opposite action, to disable the one-time-prepare
by default... now I just need the opposite, to enable it by default even
for repetitive queries... is that possible ?

Cheers,
Csaba.

Csaba Nagy wrote:

> Before I was using prepareThreshold='1', and I was seeing only such
> entries in the server log:
>
> duration: 5437.499 ms statement: EXECUTE <unnamed> [PREPARE: SELECT
> ... ]
>
> Note the <unnamed> in the log entry, it was always there for each
> statement.

I believe that's logging execution of an unnamed portal, not an unnamed
statement. I'm not sure whether the current server logging actually lets
you tell whether a named statement was used/reused or not (at least that
was one of my complaints about early versions of it -- haven't checked
what current versions do).

If the statement name is logged, it'd be something like "S_12345".

> After setting prepareThreshold='0', I started getting 2 kinds of log
> entries, the ones like above, and the likes:
>
> duration: 2200.570 ms statement: EXECUTE C_220047 [PREPARE: SELECT
> ... ]
>
> Note the C_220047, that's what's changed...

C_.... are portals ("cursors")

If you're using setFetchSize() to avoid pulling in the whole resultset
at once, the driver has to use a named statement and named portal
regardless of the prepare-threshold setting (because portals are closed
when their creating statement is closed, and the unnamed statement gets
closed when reused)

-O

Csaba Nagy wrote:

(before:)

> duration: 5437.499 ms statement: EXECUTE <unnamed> [PREPARE: SELECT
> ... ]

(after:)

> duration: 2200.570 ms statement: EXECUTE C_220047 [PREPARE: SELECT
> ... ]

Also.. as to why you see the behaviour change, I'd guess that you're
using log_min_duration and the plans for the queries where you are using
setFetchSize() have changed from one with low startup cost to one with
high startup cost due to switching from named to unnamed statements. The
high startup cost plan means the very first portal execution takes
longer and gets logged.. the low startup cost plan might be more
expensive overall but the cost is spread out across all the portal
executions, so no one execution takes long enough to get logged.

-O

On Mon, 2007-06-25 at 23:40, Oliver Jowett wrote:
> I believe that's logging execution of an unnamed portal, not an unnamed
> statement. I'm not sure whether the current server logging actually lets
> you tell whether a named statement was used/reused or not (at least that
> was one of my complaints about early versions of it -- haven't checked
> what current versions do).
>
> If the statement name is logged, it'd be something like "S_12345".

Thanks Oliver for your answer.

My real question is: am I turning the right knob with
"prepareThreshold=0" ? I want all queries to be planned taking into
account the parameter values by default. I can turn this off on special
cases by setting the prepare threashold on the statement level - if the
prepareThreshold is affecting at all the fact that parameters are sent
for planning or not... is it ?

I was supposing it is, but I could not figure it out from the logging -
and the results in query execution time seem to contradict what I get by
explain on a PREPARE (which suck the same as my production system) vs.
on direct sql with parameters included (which seems to yield the correct
plan). The actual case is a query including a table which has one id
value which has very skewed cardinality compared to the average, and the
generic plan sucks badly for this one id.

Thanks,
Csaba.

Csaba Nagy wrote:

> My real question is: am I turning the right knob with
> "prepareThreshold=0" ? I want all queries to be planned taking into
> account the parameter values by default. I can turn this off on special
> cases by setting the prepare threashold on the statement level - if the
> prepareThreshold is affecting at all the fact that parameters are sent
> for planning or not... is it ?

Short answer: yes, prepareThreshold=0 is the right knob. (with one
exception, see below)

Long answer:

The parameters are always sent out-of-line from the query when using
protocol version 3.

When the driver decides to use a "server prepared statement" (i.e. when
prepareThreshold > 0 and you've reused the same PreparedStatement
enough) it parses the query into a named statement at the protocol
level. Otherwise, it parses it into the unnamed statement.

When a named statement is parsed, the server also generates a generic
plan immediately.

When an unnamed statement is parsed, the parse phase is done but query
planning is not done. Later, when actual parameter values are bound,
planning is done using those actual parameter values for selectivity
purposes.

So the issue is not so much "how are the parameters sent?" but "is a
named statement being used or not?"

If you set prepareThreshold=0 then an unnamed statement should always be
used (& therefore actual parameter values should be taken into account
when planning), with one exception: the setFetchSize() case I described
in my earlier email. In that case the driver simply can't use the
unnamed statement because it needs the statement and portal to survive
for longer than using the unnamed statement would allow. Ideally the
protocol would let clients specify when to defer planning on a
per-statement basis, but the current situation is a result of wanting to
avoid exactly that sort of protocol change.. it's a bit of a compromise.

If you set logLevel=2 on the driver, you should be able to see the
differences in the protocol flow in more detail than the server logging
lets you see.

-O

Oliver,

Now this was enlightening... now I finally understand the behavior I
see.

> If you set prepareThreshold=0 then an unnamed statement should always be
> used (& therefore actual parameter values should be taken into account
> when planning), with one exception: the setFetchSize() case I described
> in my earlier email.

The setFetchSize must be the cause I see the unnamed statements (I have
it automatically added to all of our select statements). For a query
with limit on it (the case of my problem-query), the fetch size is not
very useful, I'll get rid of it...

> If you set logLevel=2 on the driver, you should be able to see the
> differences in the protocol flow in more detail than the server logging
> lets you see.

Thanks for the tip, I'll do that too next time... for the current
situation your explanation is more then enough.

Thanks,
Csaba.