Обсуждение: PGStatement#setPrepareThreshold

Hi all,

Question: will PGStatement.setPrepareThreshold(1) cause server side
prepare to be used already on the first execution, or only after the
second one ?

The problem: I want to force server side prepare at least for some of
the queries on my system, as the query plan is completely bad if the
server knows the parameters when planning (due to null values in IN
list, nothing to be fixed in my application unless I completely rewrite
some parts of it).

I couldn't figure out this from the log files... postgres logs the
queries as <unnamed>, but that doesn't tell me too much.

Is there a way to force server side prepare from the first query ?

Thanks,
Csaba.

Csaba Nagy wrote:
> Hi all,
>
> Question: will PGStatement.setPrepareThreshold(1) cause server side
> prepare to be used already on the first execution, or only after the
> second one ?

It should cause it to be used on the first execution (at least that was
the intent)

The logic looks like:
- On statement creation set count=0
- On each execution:
   - If this statement is a PreparedStatement, increment count
   - If threshold == 0 or count < threshold, make this execution "oneshot"
   - Execute query

"oneshot" queries use the unnamed statement (with one exception: queries
that will be backed by a portal use a named statement)

> I couldn't figure out this from the log files... postgres logs the
> queries as <unnamed>, but that doesn't tell me too much.

If you're seeing <unnamed> then those queries aren't using server-side
prepare (the unnamed statement is also special as it's the trigger for
the planner behaviour that you are trying to avoid..) .. so it seems
that you are not managing to trigger server-side prepare for some
reason. Maybe you are using a plain Statement?

-O

Oliver,

Thanks for your answer.

> The logic looks like:
> - On statement creation set count=0
> - On each execution:
>    - If this statement is a PreparedStatement, increment count
>    - If threshold == 0 or count < threshold, make this execution "oneshot"
>    - Execute query

OK, I've checked the sources. I'm using postgresql-jdbc-8.1dev-400.
The relevant piece of code looks to me to be in
AbstractJdbc2Statement#execute(Query,ParameterList,int):

        // Only use named statements after we hit the threshold
        if (preparedQuery != null)
        {
            ++m_useCount; // We used this statement once more.
            if (m_prepareThreshold == 0 || m_useCount <
m_prepareThreshold)
                flags |= QueryExecutor.QUERY_ONESHOT;
        }

So if preparedQuery is not null for prepared statements, it should work
as you said...

> "oneshot" queries use the unnamed statement (with one exception: queries
> that will be backed by a portal use a named statement)
>
> > I couldn't figure out this from the log files... postgres logs the
> > queries as <unnamed>, but that doesn't tell me too much.
>
> If you're seeing <unnamed> then those queries aren't using server-side
> prepare (the unnamed statement is also special as it's the trigger for
> the planner behaviour that you are trying to avoid..) .. so it seems
> that you are not managing to trigger server-side prepare for some
> reason. Maybe you are using a plain Statement?

No, I definitely use a prepared statement, I have lots of parameters in
the IN clause... that's part of the problem. And I checked again, and it
is logged as <unnamed> in the postgres logs.

So the only remaining suspect is that the threshold is not really set to
1. This is somewhat strange, as I use a connection pool and set it to 1
on each connection, and only set it to 0 on specific statements where I
do want the parameter values to be taken into account (I know, I'll have
to change this, but it was the easiest way to get the system stable
after switching from Oracle to postgres).

I will have to investigate what is the real problem.

Thanks,
Csaba.

Csaba,

Actually I was debugging some other code and noticed that it doesn't
really get set, this just confirms my suspicions. I'll try to get
something out in a few hours

Dave
On 3-Aug-06, at 5:17 AM, Csaba Nagy wrote:

> Oliver,
>
> Thanks for your answer.
>
>> The logic looks like:
>> - On statement creation set count=0
>> - On each execution:
>>    - If this statement is a PreparedStatement, increment count
>>    - If threshold == 0 or count < threshold, make this execution
>> "oneshot"
>>    - Execute query
>
> OK, I've checked the sources. I'm using postgresql-jdbc-8.1dev-400.
> The relevant piece of code looks to me to be in
> AbstractJdbc2Statement#execute(Query,ParameterList,int):
>
>         // Only use named statements after we hit the threshold
>         if (preparedQuery != null)
>         {
>             ++m_useCount; // We used this statement once more.
>             if (m_prepareThreshold == 0 || m_useCount <
> m_prepareThreshold)
>                 flags |= QueryExecutor.QUERY_ONESHOT;
>         }
>
> So if preparedQuery is not null for prepared statements, it should
> work
> as you said...
>
>> "oneshot" queries use the unnamed statement (with one exception:
>> queries
>> that will be backed by a portal use a named statement)
>>
>>> I couldn't figure out this from the log files... postgres logs the
>>> queries as <unnamed>, but that doesn't tell me too much.
>>
>> If you're seeing <unnamed> then those queries aren't using server-
>> side
>> prepare (the unnamed statement is also special as it's the trigger
>> for
>> the planner behaviour that you are trying to avoid..) .. so it seems
>> that you are not managing to trigger server-side prepare for some
>> reason. Maybe you are using a plain Statement?
>
> No, I definitely use a prepared statement, I have lots of
> parameters in
> the IN clause... that's part of the problem. And I checked again,
> and it
> is logged as <unnamed> in the postgres logs.
>
> So the only remaining suspect is that the threshold is not really
> set to
> 1. This is somewhat strange, as I use a connection pool and set it
> to 1
> on each connection, and only set it to 0 on specific statements
> where I
> do want the parameter values to be taken into account (I know, I'll
> have
> to change this, but it was the easiest way to get the system stable
> after switching from Oracle to postgres).
>
> I will have to investigate what is the real problem.
>
> Thanks,
> Csaba.
>
>
>
>
>
> ---------------------------(end of
> broadcast)---------------------------
> TIP 2: Don't 'kill -9' the postmaster
>

Ok, further investigation shows that it does work

However I'm still puzzled by these backend logs

<test test>LOG:  statement: PREPARE S_3 AS INSERT INTO texttable (te)
VALUES ($1)
<test test>LOG:  statement: <BIND>
<test test>LOG:  statement: EXECUTE <unnamed>  [PREPARE:  INSERT INTO
texttable (te) VALUES ($1)]

We see the prepare to a named statement, but then the execute is
unnamed ?

Dave

On 3-Aug-06, at 7:53 AM, Dave Cramer wrote:

> Csaba,
>
> Actually I was debugging some other code and noticed that it
> doesn't really get set, this just confirms my suspicions. I'll try
> to get something out in a few hours
>
> Dave
> On 3-Aug-06, at 5:17 AM, Csaba Nagy wrote:
>
>> Oliver,
>>
>> Thanks for your answer.
>>
>>> The logic looks like:
>>> - On statement creation set count=0
>>> - On each execution:
>>>    - If this statement is a PreparedStatement, increment count
>>>    - If threshold == 0 or count < threshold, make this execution
>>> "oneshot"
>>>    - Execute query
>>
>> OK, I've checked the sources. I'm using postgresql-jdbc-8.1dev-400.
>> The relevant piece of code looks to me to be in
>> AbstractJdbc2Statement#execute(Query,ParameterList,int):
>>
>>         // Only use named statements after we hit the threshold
>>         if (preparedQuery != null)
>>         {
>>             ++m_useCount; // We used this statement once more.
>>             if (m_prepareThreshold == 0 || m_useCount <
>> m_prepareThreshold)
>>                 flags |= QueryExecutor.QUERY_ONESHOT;
>>         }
>>
>> So if preparedQuery is not null for prepared statements, it should
>> work
>> as you said...
>>
>>> "oneshot" queries use the unnamed statement (with one exception:
>>> queries
>>> that will be backed by a portal use a named statement)
>>>
>>>> I couldn't figure out this from the log files... postgres logs the
>>>> queries as <unnamed>, but that doesn't tell me too much.
>>>
>>> If you're seeing <unnamed> then those queries aren't using server-
>>> side
>>> prepare (the unnamed statement is also special as it's the
>>> trigger for
>>> the planner behaviour that you are trying to avoid..) .. so it seems
>>> that you are not managing to trigger server-side prepare for some
>>> reason. Maybe you are using a plain Statement?
>>
>> No, I definitely use a prepared statement, I have lots of
>> parameters in
>> the IN clause... that's part of the problem. And I checked again,
>> and it
>> is logged as <unnamed> in the postgres logs.
>>
>> So the only remaining suspect is that the threshold is not really
>> set to
>> 1. This is somewhat strange, as I use a connection pool and set it
>> to 1
>> on each connection, and only set it to 0 on specific statements
>> where I
>> do want the parameter values to be taken into account (I know,
>> I'll have
>> to change this, but it was the easiest way to get the system stable
>> after switching from Oracle to postgres).
>>
>> I will have to investigate what is the real problem.
>>
>> Thanks,
>> Csaba.
>>
>>
>>
>>
>>
>> ---------------------------(end of
>> broadcast)---------------------------
>> TIP 2: Don't 'kill -9' the postmaster
>>
>
>
> ---------------------------(end of
> broadcast)---------------------------
> TIP 2: Don't 'kill -9' the postmaster
>

Dave Cramer <pg@fastcrypt.com> writes:
> However I'm still puzzled by these backend logs

> <test test>LOG:  statement: PREPARE S_3 AS INSERT INTO texttable (te)
> VALUES ($1)
> <test test>LOG:  statement: <BIND>
> <test test>LOG:  statement: EXECUTE <unnamed>  [PREPARE:  INSERT INTO
> texttable (te) VALUES ($1)]

> We see the prepare to a named statement, but then the execute is
> unnamed ?

What it's showing you there is the name of the protocol-level portal;
evidently you're using the unnamed portal to execute the INSERT.

This does demonstrate once again that the current approach to logging
parse/bind/execute operations is entirely wrongheaded, because it
deliberately confuses the protocol and SQL levels.  I see that Bruce
has changed CVS tip so that the message is

<test test>LOG:  statement: [protocol] EXECUTE <unnamed>  [PREPARE:  INSERT INTO
texttable (te) VALUES ($1)]

but I hardly think that's going to be enough to de-confuse people.
All those brackets just serve to make things *more* confusing IMHO.

What I'd like to see is something like this:

Simple Query produces

    LOG: statement: ...statement text here...

Parse produces

    LOG: parse statement-name: ...statement text here...

Bind produces

    LOG: bind portal-name to statement-name (someday print arguments here)

Execute produces

    LOG: execute portal-name: ...statement text here...

No brackets, no pretending that an Execute message is the same thing
as a SQL EXECUTE command or that Parse is the same as PREPARE.

            regards, tom lane

On 3-Aug-06, at 3:59 PM, Tom Lane wrote:

> Dave Cramer <pg@fastcrypt.com> writes:
>> However I'm still puzzled by these backend logs
>
>> <test test>LOG:  statement: PREPARE S_3 AS INSERT INTO texttable (te)
>> VALUES ($1)
>> <test test>LOG:  statement: <BIND>
>> <test test>LOG:  statement: EXECUTE <unnamed>  [PREPARE:  INSERT INTO
>> texttable (te) VALUES ($1)]
>
>> We see the prepare to a named statement, but then the execute is
>> unnamed ?
>
> What it's showing you there is the name of the protocol-level portal;
> evidently you're using the unnamed portal to execute the INSERT.

If that's the case then the driver is not doing what it's supposed to
be doing. It should be using the named portal (S_3) to do the insert.

Dave
>
> This does demonstrate once again that the current approach to logging
> parse/bind/execute operations is entirely wrongheaded, because it
> deliberately confuses the protocol and SQL levels.  I see that Bruce
> has changed CVS tip so that the message is
>
> <test test>LOG:  statement: [protocol] EXECUTE <unnamed>
> [PREPARE:  INSERT INTO
> texttable (te) VALUES ($1)]
>
> but I hardly think that's going to be enough to de-confuse people.
> All those brackets just serve to make things *more* confusing IMHO.
>
> What I'd like to see is something like this:
>
> Simple Query produces
>
>     LOG: statement: ...statement text here...
>
> Parse produces
>
>     LOG: parse statement-name: ...statement text here...
>
> Bind produces
>
>     LOG: bind portal-name to statement-name (someday print arguments
> here)
>
> Execute produces
>
>     LOG: execute portal-name: ...statement text here...
>
> No brackets, no pretending that an Execute message is the same thing
> as a SQL EXECUTE command or that Parse is the same as PREPARE.
>
>             regards, tom lane
>
> ---------------------------(end of
> broadcast)---------------------------
> TIP 5: don't forget to increase your free space map settings
>

Dave Cramer wrote:

> If that's the case then the driver is not doing what it's supposed to be
> doing. It should be using the named portal (S_3) to do the insert.

No, the driver is fine. It is using a named statement (S_3) but an
unnamed portal (because it is going to fetch all the data in one go and
doesn't need to retain the portal after execution)

If your query met the conditions for using a portal-based ResultSet,
you'd see it use a named portal as well as a named statement.

-O

On 3-Aug-06, at 6:14 PM, Oliver Jowett wrote:

> Dave Cramer wrote:
>
>> If that's the case then the driver is not doing what it's supposed
>> to be doing. It should be using the named portal (S_3) to do the
>> insert.
>
> No, the driver is fine. It is using a named statement (S_3) but an
> unnamed portal (because it is going to fetch all the data in one go
> and doesn't need to retain the portal after execution)
>
> If your query met the conditions for using a portal-based
> ResultSet, you'd see it use a named portal as well as a named
> statement.

Thanks for clarifying that Oliver, the logs are still misleading in
that they don't name the statement used in the bind message.

--dc--
>
> -O
>

Dave Cramer <pg@fastcrypt.com> writes:
> Thanks for clarifying that Oliver, the logs are still misleading in
> that they don't name the statement used in the bind message.

Pretty much exactly my point.  The distinction between statement name
and portal name is critical at the protocol level and has no real
counterpart at the SQL level (prepared statement name vs cursor name
is similar but I think not exactly the same namespaces).  The logging
code is not getting this right.

            regards, tom lane

Dave Cramer wrote:
>
> On 3-Aug-06, at 6:14 PM, Oliver Jowett wrote:
>
> > Dave Cramer wrote:
> >
> >> If that's the case then the driver is not doing what it's supposed
> >> to be doing. It should be using the named portal (S_3) to do the
> >> insert.
> >
> > No, the driver is fine. It is using a named statement (S_3) but an
> > unnamed portal (because it is going to fetch all the data in one go
> > and doesn't need to retain the portal after execution)
> >
> > If your query met the conditions for using a portal-based
> > ResultSet, you'd see it use a named portal as well as a named
> > statement.
>
> Thanks for clarifying that Oliver, the logs are still misleading in
> that they don't name the statement used in the bind message.

Current CVS has:

     (errmsg("statement: [protocol] <BIND> %s", portal_name)));

--
  Bruce Momjian   bruce@momjian.us
  EnterpriseDB    http://www.enterprisedb.com

  + If your life is a hard drive, Christ can be your backup. +

One complexity of changing the prefix to not use "statement:" is that
log_statement does control this output.  Changing that might cause
confusion, especially for scripts that process the logs.  How do you
like "statement:  <protocol execute>"?

---------------------------------------------------------------------------

Tom Lane wrote:
> Dave Cramer <pg@fastcrypt.com> writes:
> > However I'm still puzzled by these backend logs
>
> > <test test>LOG:  statement: PREPARE S_3 AS INSERT INTO texttable (te)
> > VALUES ($1)
> > <test test>LOG:  statement: <BIND>
> > <test test>LOG:  statement: EXECUTE <unnamed>  [PREPARE:  INSERT INTO
> > texttable (te) VALUES ($1)]
>
> > We see the prepare to a named statement, but then the execute is
> > unnamed ?
>
> What it's showing you there is the name of the protocol-level portal;
> evidently you're using the unnamed portal to execute the INSERT.
>
> This does demonstrate once again that the current approach to logging
> parse/bind/execute operations is entirely wrongheaded, because it
> deliberately confuses the protocol and SQL levels.  I see that Bruce
> has changed CVS tip so that the message is
>
> <test test>LOG:  statement: [protocol] EXECUTE <unnamed>  [PREPARE:  INSERT INTO
> texttable (te) VALUES ($1)]
>
> but I hardly think that's going to be enough to de-confuse people.
> All those brackets just serve to make things *more* confusing IMHO.
>
> What I'd like to see is something like this:
>
> Simple Query produces
>
>     LOG: statement: ...statement text here...
>
> Parse produces
>
>     LOG: parse statement-name: ...statement text here...
>
> Bind produces
>
>     LOG: bind portal-name to statement-name (someday print arguments here)
>
> Execute produces
>
>     LOG: execute portal-name: ...statement text here...
>
> No brackets, no pretending that an Execute message is the same thing
> as a SQL EXECUTE command or that Parse is the same as PREPARE.
>
>             regards, tom lane

--
  Bruce Momjian   bruce@momjian.us
  EnterpriseDB    http://www.enterprisedb.com

  + If your life is a hard drive, Christ can be your backup. +

On 3-Aug-06, at 11:55 PM, Bruce Momjian wrote:

> Dave Cramer wrote:
>>
>> On 3-Aug-06, at 6:14 PM, Oliver Jowett wrote:
>>
>>> Dave Cramer wrote:
>>>
>>>> If that's the case then the driver is not doing what it's supposed
>>>> to be doing. It should be using the named portal (S_3) to do the
>>>> insert.
>>>
>>> No, the driver is fine. It is using a named statement (S_3) but an
>>> unnamed portal (because it is going to fetch all the data in one go
>>> and doesn't need to retain the portal after execution)
>>>
>>> If your query met the conditions for using a portal-based
>>> ResultSet, you'd see it use a named portal as well as a named
>>> statement.
>>
>> Thanks for clarifying that Oliver, the logs are still misleading in
>> that they don't name the statement used in the bind message.
>
> Current CVS has:
>
>      (errmsg("statement: [protocol] <BIND> %s", portal_name)));

Bind also has a statement name, as well as a portal name ?

Ideally I'd like to see the parameters which were bound and the
types, but I suspect I'm reaching here.
>
> --
>   Bruce Momjian   bruce@momjian.us
>   EnterpriseDB    http://www.enterprisedb.com
>
>   + If your life is a hard drive, Christ can be your backup. +
>
> ---------------------------(end of
> broadcast)---------------------------
> TIP 5: don't forget to increase your free space map settings
>

Dave Cramer wrote:
>
> On 3-Aug-06, at 11:55 PM, Bruce Momjian wrote:
>
> > Dave Cramer wrote:
> >>
> >> On 3-Aug-06, at 6:14 PM, Oliver Jowett wrote:
> >>
> >>> Dave Cramer wrote:
> >>>
> >>>> If that's the case then the driver is not doing what it's supposed
> >>>> to be doing. It should be using the named portal (S_3) to do the
> >>>> insert.
> >>>
> >>> No, the driver is fine. It is using a named statement (S_3) but an
> >>> unnamed portal (because it is going to fetch all the data in one go
> >>> and doesn't need to retain the portal after execution)
> >>>
> >>> If your query met the conditions for using a portal-based
> >>> ResultSet, you'd see it use a named portal as well as a named
> >>> statement.
> >>
> >> Thanks for clarifying that Oliver, the logs are still misleading in
> >> that they don't name the statement used in the bind message.
> >
> > Current CVS has:
> >
> >      (errmsg("statement: [protocol] <BIND> %s", portal_name)));
>
> Bind also has a statement name, as well as a portal name ?
>
> Ideally I'd like to see the parameters which were bound and the
> types, but I suspect I'm reaching here.

Right, but do we want to repeat the statement for every bind case?

The bind parameter printing is on the TODO list.

--
  Bruce Momjian   bruce@momjian.us
  EnterpriseDB    http://www.enterprisedb.com

  + If your life is a hard drive, Christ can be your backup. +

Bruce Momjian <bruce@momjian.us> writes:
> Dave Cramer wrote:
>> Bind also has a statement name, as well as a portal name ?
>>
>> Ideally I'd like to see the parameters which were bound and the
>> types, but I suspect I'm reaching here.

> Right, but do we want to repeat the statement for every bind case?

My upthread proposal was to print the statement and portal names
at bind time.  The current printout is very clearly inadequate.

> The bind parameter printing is on the TODO list.

Yeah, that one's a bit harder to fix :-(  It would be relatively
easy for the case of parameters supplied in text form, but I'm
not sure about binary values.  Is JDBC doing anything with binary
parameter transmission yet?

            regards, tom lane

Tom Lane wrote:
> Bruce Momjian <bruce@momjian.us> writes:
> > Dave Cramer wrote:
> >> Bind also has a statement name, as well as a portal name ?
> >>
> >> Ideally I'd like to see the parameters which were bound and the
> >> types, but I suspect I'm reaching here.
>
> > Right, but do we want to repeat the statement for every bind case?
>
> My upthread proposal was to print the statement and portal names
> at bind time.  The current printout is very clearly inadequate.

Sure, I can do that.

Did you like my idea of?

    statement:  <protocol execute> ...

You didn't reply.  I want to keep the "statement:" prefix for scripts
that process our log files, and because it is output by log_statement,
which controls protocol output as well.

> > The bind parameter printing is on the TODO list.
>
> Yeah, that one's a bit harder to fix :-(  It would be relatively
> easy for the case of parameters supplied in text form, but I'm
> not sure about binary values.  Is JDBC doing anything with binary
> parameter transmission yet?

Should we just output text if we have it?  How do we know if they
parameters are text?  The data type?

--
  Bruce Momjian   bruce@momjian.us
  EnterpriseDB    http://www.enterprisedb.com

  + If your life is a hard drive, Christ can be your backup. +

> Right, but do we want to repeat the statement for every bind case?

I'm talking only for myself, but printing the parameter values alone
would be already a huge win. I enable the printing of IP+port in the
logs, so I can easily trace back the parameters to the statement if the
statement is logged too...

On the other hand, I usually only enable statement logging with
log_min_duration_statement, and there I would like to see both statemnt
and params... would that work ?

Thanks,
Csaba.

On 4-Aug-06, at 12:19 PM, Tom Lane wrote:

> Bruce Momjian <bruce@momjian.us> writes:
>> Dave Cramer wrote:
>>> Bind also has a statement name, as well as a portal name ?
>>>
>>> Ideally I'd like to see the parameters which were bound and the
>>> types, but I suspect I'm reaching here.
>
>> Right, but do we want to repeat the statement for every bind case?
>
> My upthread proposal was to print the statement and portal names
> at bind time.  The current printout is very clearly inadequate.
>
>> The bind parameter printing is on the TODO list.
>
> Yeah, that one's a bit harder to fix :-(  It would be relatively
> easy for the case of parameters supplied in text form, but I'm
> not sure about binary values.  Is JDBC doing anything with binary
> parameter transmission yet?
No we aren't, even if we were, just printing the text values would be
a huge step forward.

Dave
>
>             regards, tom lane
>

On Fri, 4 Aug 2006, Dave Cramer wrote:

> On 4-Aug-06, at 12:19 PM, Tom Lane wrote:
>
>> Yeah, that one's a bit harder to fix :-(  It would be relatively
>> easy for the case of parameters supplied in text form, but I'm
>> not sure about binary values.  Is JDBC doing anything with binary
>> parameter transmission yet?
>
> No we aren't, even if we were, just printing the text values would be a
> huge step forward.
>

Actually bytea parameters are sent as binary to the server in prepared
statements.  For fastpath calls integer, oid, and bytea parameters are
sent in binary form.

Kris Jurka

bruce wrote:
> Tom Lane wrote:
> > Bruce Momjian <bruce@momjian.us> writes:
> > > Dave Cramer wrote:
> > >> Bind also has a statement name, as well as a portal name ?
> > >>
> > >> Ideally I'd like to see the parameters which were bound and the
> > >> types, but I suspect I'm reaching here.
> >
> > > Right, but do we want to repeat the statement for every bind case?
> >
> > My upthread proposal was to print the statement and portal names
> > at bind time.  The current printout is very clearly inadequate.
>
> Sure, I can do that.
>
> Did you like my idea of?
>
>     statement:  <protocol execute> ...
>
> You didn't reply.  I want to keep the "statement:" prefix for scripts
> that process our log files, and because it is output by log_statement,
> which controls protocol output as well.

I have applied this patch to output the statemented referenced by BIND.
I also changed the "[protocol]" string to "<protocol>" for clarity.  I
am ready to pull PREPARE|BIND|EXECUTED into the "protocol" bracket too
if someone says that is a good idea.

--
  Bruce Momjian   bruce@momjian.us
  EnterpriseDB    http://www.enterprisedb.com

  + If your life is a hard drive, Christ can be your backup. +
Index: src/backend/tcop/postgres.c
===================================================================
RCS file: /cvsroot/pgsql/src/backend/tcop/postgres.c,v
retrieving revision 1.493
diff -c -c -r1.493 postgres.c
*** src/backend/tcop/postgres.c    29 Jul 2006 03:02:56 -0000    1.493
--- src/backend/tcop/postgres.c    4 Aug 2006 18:50:59 -0000
***************
*** 1146,1153 ****

      if (log_statement == LOGSTMT_ALL)
          ereport(LOG,
!                 (errmsg("statement: [protocol] PREPARE %s AS %s",
!                         (*stmt_name != '\0') ? stmt_name : "<unnamed>",
                          query_string)));

      /*
--- 1146,1153 ----

      if (log_statement == LOGSTMT_ALL)
          ereport(LOG,
!                 (errmsg("statement: <protocol> PREPARE %s AS %s",
!                         *stmt_name ? stmt_name : "<unnamed>",
                          query_string)));

      /*
***************
*** 1452,1458 ****
      /* We need to output the parameter values someday */
      if (log_statement == LOGSTMT_ALL)
          ereport(LOG,
!                 (errmsg("statement: [protocol] <BIND> %s", portal_name)));

      /*
       * Fetch parameters, if any, and store in the portal's memory context.
--- 1452,1460 ----
      /* We need to output the parameter values someday */
      if (log_statement == LOGSTMT_ALL)
          ereport(LOG,
!                 (errmsg("statement: <protocol> <BIND> %s  [PREPARE:  %s]",
!                         *portal_name ? portal_name : "<unnamed>",
!                         portal->sourceText ? portal->sourceText : "")));

      /*
       * Fetch parameters, if any, and store in the portal's memory context.
***************
*** 1718,1726 ****
      if (log_statement == LOGSTMT_ALL)
          /* We have the portal, so output the source query. */
          ereport(LOG,
!                 (errmsg("statement: [protocol] %sEXECUTE %s  [PREPARE:  %s]",
                          execute_is_fetch ? "FETCH from " : "",
!                         (*portal_name) ? portal_name : "<unnamed>",
                          portal->sourceText ? portal->sourceText : "")));

      BeginCommand(portal->commandTag, dest);
--- 1720,1728 ----
      if (log_statement == LOGSTMT_ALL)
          /* We have the portal, so output the source query. */
          ereport(LOG,
!                 (errmsg("statement: <protocol> %sEXECUTE %s  [PREPARE:  %s]",
                          execute_is_fetch ? "FETCH from " : "",
!                         *portal_name ? portal_name : "<unnamed>",
                          portal->sourceText ? portal->sourceText : "")));

      BeginCommand(portal->commandTag, dest);
***************
*** 1826,1836 ****
                                  secs, msecs)));
              else
                  ereport(LOG,
!                         (errmsg("duration: %ld.%03d ms  statement: [protocol] %sEXECUTE %s  [PREPARE:  %s]",
                                  secs, msecs,
                                  execute_is_fetch ? "FETCH from " : "",
!                                 (*portal_name) ? portal_name : "<unnamed>",
!                             portal->sourceText ? portal->sourceText : "")));
          }
      }

--- 1828,1838 ----
                                  secs, msecs)));
              else
                  ereport(LOG,
!                         (errmsg("duration: %ld.%03d ms  statement: <protocol> %sEXECUTE %s  [PREPARE:  %s]",
                                  secs, msecs,
                                  execute_is_fetch ? "FETCH from " : "",
!                                 *portal_name ? portal_name : "<unnamed>",
!                                 portal->sourceText ? portal->sourceText : "")));
          }
      }

Bruce Momjian <bruce@momjian.us> writes:
> Did you like my idea of?
>     statement:  <protocol execute> ...

No.

> I want to keep the "statement:" prefix for scripts
> that process our log files, and because it is output by log_statement,
> which controls protocol output as well.

I think that's an irrelevant consideration, but it's driving you
to insist on unnecessarily complicated, confusing output.  What's
wrong with "parse:", "bind:", and "execute:"?  If you really must
have the word "statement" in there, then let's do "parse statement:"
"bind statement:" and "execute statement:".  In any case we've got
to drop all the brackets and braces, they look too much like they might
be part of the statement string.

            regards, tom lane

Bruce,

Doesn't it make more sense to use the statement name ?

If I prepare S_3 as "select * from foo"

then the bind log is going to show me "select * from foo" not S_3

I think in the case of named statements I'd prefer "S_3" however as I
think about this in the case of unnamed statements I'd prefer the
"select * from foo"

Comments ?

Dave
On 4-Aug-06, at 2:56 PM, Bruce Momjian wrote:

> bruce wrote:
>> Tom Lane wrote:
>>> Bruce Momjian <bruce@momjian.us> writes:
>>>> Dave Cramer wrote:
>>>>> Bind also has a statement name, as well as a portal name ?
>>>>>
>>>>> Ideally I'd like to see the parameters which were bound and the
>>>>> types, but I suspect I'm reaching here.
>>>
>>>> Right, but do we want to repeat the statement for every bind case?
>>>
>>> My upthread proposal was to print the statement and portal names
>>> at bind time.  The current printout is very clearly inadequate.
>>
>> Sure, I can do that.
>>
>> Did you like my idea of?
>>
>>     statement:  <protocol execute> ...
>>
>> You didn't reply.  I want to keep the "statement:" prefix for scripts
>> that process our log files, and because it is output by
>> log_statement,
>> which controls protocol output as well.
>
> I have applied this patch to output the statemented referenced by
> BIND.
> I also changed the "[protocol]" string to "<protocol>" for clarity.  I
> am ready to pull PREPARE|BIND|EXECUTED into the "protocol" bracket too
> if someone says that is a good idea.
>
> --
>   Bruce Momjian   bruce@momjian.us
>   EnterpriseDB    http://www.enterprisedb.com
>
>   + If your life is a hard drive, Christ can be your backup. +
> Index: src/backend/tcop/postgres.c
> ===================================================================
> RCS file: /cvsroot/pgsql/src/backend/tcop/postgres.c,v
> retrieving revision 1.493
> diff -c -c -r1.493 postgres.c
> *** src/backend/tcop/postgres.c    29 Jul 2006 03:02:56 -0000    1.493
> --- src/backend/tcop/postgres.c    4 Aug 2006 18:50:59 -0000
> ***************
> *** 1146,1153 ****
>
>       if (log_statement == LOGSTMT_ALL)
>           ereport(LOG,
> !                 (errmsg("statement: [protocol] PREPARE %s AS %s",
> !                         (*stmt_name != '\0') ? stmt_name : "<unnamed>",
>                           query_string)));
>
>       /*
> --- 1146,1153 ----
>
>       if (log_statement == LOGSTMT_ALL)
>           ereport(LOG,
> !                 (errmsg("statement: <protocol> PREPARE %s AS %s",
> !                         *stmt_name ? stmt_name : "<unnamed>",
>                           query_string)));
>
>       /*
> ***************
> *** 1452,1458 ****
>       /* We need to output the parameter values someday */
>       if (log_statement == LOGSTMT_ALL)
>           ereport(LOG,
> !                 (errmsg("statement: [protocol] <BIND> %s", portal_name)));
>
>       /*
>        * Fetch parameters, if any, and store in the portal's memory
> context.
> --- 1452,1460 ----
>       /* We need to output the parameter values someday */
>       if (log_statement == LOGSTMT_ALL)
>           ereport(LOG,
> !                 (errmsg("statement: <protocol> <BIND> %s  [PREPARE:  %s]",
> !                         *portal_name ? portal_name : "<unnamed>",
> !                         portal->sourceText ? portal->sourceText : "")));
>
>       /*
>        * Fetch parameters, if any, and store in the portal's memory
> context.
> ***************
> *** 1718,1726 ****
>       if (log_statement == LOGSTMT_ALL)
>           /* We have the portal, so output the source query. */
>           ereport(LOG,
> !                 (errmsg("statement: [protocol] %sEXECUTE %s  [PREPARE:  %s]",
>                           execute_is_fetch ? "FETCH from " : "",
> !                         (*portal_name) ? portal_name : "<unnamed>",
>                           portal->sourceText ? portal->sourceText : "")));
>
>       BeginCommand(portal->commandTag, dest);
> --- 1720,1728 ----
>       if (log_statement == LOGSTMT_ALL)
>           /* We have the portal, so output the source query. */
>           ereport(LOG,
> !                 (errmsg("statement: <protocol> %sEXECUTE %s  [PREPARE:  %s]",
>                           execute_is_fetch ? "FETCH from " : "",
> !                         *portal_name ? portal_name : "<unnamed>",
>                           portal->sourceText ? portal->sourceText : "")));
>
>       BeginCommand(portal->commandTag, dest);
> ***************
> *** 1826,1836 ****
>                                   secs, msecs)));
>               else
>                   ereport(LOG,
> !                         (errmsg("duration: %ld.%03d ms  statement: [protocol] %
> sEXECUTE %s  [PREPARE:  %s]",
>                                   secs, msecs,
>                                   execute_is_fetch ? "FETCH from " : "",
> !                                 (*portal_name) ? portal_name : "<unnamed>",
> !                             portal->sourceText ? portal->sourceText : "")));
>           }
>       }
>
> --- 1828,1838 ----
>                                   secs, msecs)));
>               else
>                   ereport(LOG,
> !                         (errmsg("duration: %ld.%03d ms  statement: <protocol> %
> sEXECUTE %s  [PREPARE:  %s]",
>                                   secs, msecs,
>                                   execute_is_fetch ? "FETCH from " : "",
> !                                 *portal_name ? portal_name : "<unnamed>",
> !                                 portal->sourceText ? portal->sourceText : "")));
>           }
>       }
>

Dave Cramer wrote:
> Bruce,
>
> Doesn't it make more sense to use the statement name ?
>
> If I prepare S_3 as "select * from foo"
>
> then the bind log is going to show me "select * from foo" not S_3
>
> I think in the case of named statements I'd prefer "S_3" however as I
> think about this in the case of unnamed statements I'd prefer the
> "select * from foo"

The bind shows:

     (errmsg("statement: <protocol> <BIND> %s  [PREPARE:  %s]",

The first %s is the statement name, and the second %s is the query.

--
  Bruce Momjian   bruce@momjian.us
  EnterpriseDB    http://www.enterprisedb.com

  + If your life is a hard drive, Christ can be your backup. +

Bruce Momjian <bruce@momjian.us> writes:
> !                 (errmsg("statement: [protocol] <BIND> %s", portal_name)));

> --- 1452,1460 ----
> !                 (errmsg("statement: <protocol> <BIND> %s  [PREPARE:  %s]",
> !                         *portal_name ? portal_name : "<unnamed>",
> !                         portal->sourceText ? portal->sourceText : "")));

This is getting less readable not more so; and you still haven't got the
prepared statement's name in there, let alone any place to put the
parameter values.

Perhaps we should give up on the idea that this can all fit on one log
line?  Maybe

    LOG:  parse: <statement-name>
    DETAIL:  statement: <source-text>

    LOG:  bind: <portal-name> to <statement-name>
    DETAIL:  statement: <source-text>
    parameter 1: <parameter value>
    parameter 2: <parameter value>
    ...

    LOG:  execute: <portal-name>
    DETAIL:  statement: <source-text>

The $64 question here is whether we want to repeat the source-text
in all three messages (parse, bind, execute) or try to reduce the
verbosity.

            regards, tom lane

Tom Lane wrote:
> Bruce Momjian <bruce@momjian.us> writes:
> > !                 (errmsg("statement: [protocol] <BIND> %s", portal_name)));
>
> > --- 1452,1460 ----
> > !                 (errmsg("statement: <protocol> <BIND> %s  [PREPARE:  %s]",
> > !                         *portal_name ? portal_name : "<unnamed>",
> > !                         portal->sourceText ? portal->sourceText : "")));
>
> This is getting less readable not more so; and you still haven't got the
> prepared statement's name in there, let alone any place to put the
> parameter values.

I thought the portal name was the statement name.  Seems I was wrong.

> Perhaps we should give up on the idea that this can all fit on one log
> line?  Maybe
>
>     LOG:  parse: <statement-name>
>     DETAIL:  statement: <source-text>
>
>     LOG:  bind: <portal-name> to <statement-name>
>     DETAIL:  statement: <source-text>
>     parameter 1: <parameter value>
>     parameter 2: <parameter value>
>     ...
>
>     LOG:  execute: <portal-name>
>     DETAIL:  statement: <source-text>
>
> The $64 question here is whether we want to repeat the source-text
> in all three messages (parse, bind, execute) or try to reduce the
> verbosity.

We don't print DETAIL in the logs, do we?

Does anyone have C code that uses these features so I can test?

--
  Bruce Momjian   bruce@momjian.us
  EnterpriseDB    http://www.enterprisedb.com

  + If your life is a hard drive, Christ can be your backup. +

bruce wrote:
> > The $64 question here is whether we want to repeat the source-text
> > in all three messages (parse, bind, execute) or try to reduce the
> > verbosity.
>
> We don't print DETAIL in the logs, do we?
>
> Does anyone have C code that uses these features so I can test?

I made a libpq test program and will work on improving the log output.

--
  Bruce Momjian   bruce@momjian.us
  EnterpriseDB    http://www.enterprisedb.com

  + If your life is a hard drive, Christ can be your backup. +

Bruce Momjian <bruce@momjian.us> writes:
> The bind shows:
>      (errmsg("statement: <protocol> <BIND> %s  [PREPARE:  %s]",
> The first %s is the statement name, and the second %s is the query.

No, it's the portal name.  There's a difference.

            regards, tom lane

Bruce Momjian <bruce@momjian.us> writes:
> We don't print DETAIL in the logs, do we?

Yes, we do, unless you've set log_error_verbosity to less than the
default.

            regards, tom lane