Thread: Re: [HACKERS] statement logging / extended query protocol issues

Re: [HACKERS] statement logging / extended query protocol issues

From
Bruce Momjian
Date:
Here are comments on this posting and the patch (it is long):

Simon Riggs wrote:
> On Thu, 2005-09-08 at 13:14 +1200, Oliver Jowett wrote:
> > Simon Riggs wrote:
> > > Oliver, would it be possible to show a simplified call sequence and what
> > > you would like to see logged for each call?
>
> These are good: Maybe it should even be in the docs for the driver?
> It would be good if it could be written as a test within the driver, so
> we can expand it and test the logging.
>
> > The JDBC driver generates one of these sequences:
> >
> > (1)
> >   Parse (unnamed statement) "SELECT 1"
> >   Bind (unnamed statement -> unnamed portal)
> >   Execute (unnamed portal, no row limit)
> >
> > (2)
> >   Parse (named statement S_1) "SELECT 1"
> >   repeatedly:
> >     Bind (named statement S_1 -> unnamed portal)
> >     Execute (unnamed portal, no row limit)
> >
> > (3)
> >   Parse (named statement S_2) "SELECT 1"
> >   repeatedly:
> >     Bind (named statement S_2 -> named portal C_2)
> >     repeatedly:
> >       Execute (named portal C_2, row limit 42)
>
> Are we sure there is just 3 cases?
>
> > Ideal output is:
> >
> > (1)  LOG: statement: SELECT 1
> >
> > (2)  LOG: statement: SELECT 1
> >      LOG: statement: SELECT 1
> >      LOG: statement: SELECT 1
> >
> > (3)  LOG: statement: SELECT 1
> >      LOG: statement: SELECT 1
> >      LOG: statement: SELECT 1
> >
> > In case (3), that's one log line per repeat of the outer loop,
> > regardless of how many Executes are sent in the inner loop.
>
> > Note that case (1) is the most common case for application queries via
> > the JDBC driver, and case (2) is the most common for internally
> > generated statements like BEGIN.
>
> Even if case (3) is not that common, I still want to know it is
> occurring, to see what effect or overhead it has.

Agreed.

> > As you can see from the output I'd like, I don't think that synthesizing
> > FETCH / EXECUTE queries that don't actually exist [is a]
> > useful thing to do, at least at the Joe Average User
> > level.
>
> Your original point at the top of this thread was valid: a get-next-rows
> shouldn't look like a re-execute. We can call it something else if you
> like, as long as we can tell the difference.
>
> We'll only see the output for case (3) when someone has programmed
> things that way by using setFetchSize.
>
> > Also note that the JDBC driver doesn't exercise all of the extended
> > protocol -- for example it's possible to re-Bind the same unnamed
> > statement repeatedly, or have multiple Executes on an unnamed portal
> > with a row limit, but the JDBC driver never does that.
>
> I agree there's not much gained from displaying the BIND statement as it
> is. I argued previously against including the BIND parameters. Now I
> would say we should either include them or leave out BIND altogether.

Agreed.  We should output BIND parameters at some point.  We do log
client-side PREPARE parameters now.

> Here's a new suggestion and patch that brings together
> - Oliver and Simon's wish to remove BIND from normal logging
> - Oliver's suggestion to remove the PREPARE logging for unnamed
> statements, which would otherwise double-up logging for case(1)
> - Bruce and Simon's view to keep some form of FETCH logging
> - Tom's view to rationalise the way ROWS is mentioned
>
> (lines beginning jdbc don't show in the log, but are just there to show
> clearly the time sequence of activities and what gets subsequently
> logged)
>
> (1)
> >   Parse (unnamed statement) "SELECT * from pg_proc"
> >   Bind (unnamed statement -> unnamed portal)
> >   Execute (unnamed portal, no row limit)
>
> (1)
> jdbc parse
> jdbc bind
> jdbc execute
> LOG:  statement: SELECT * from pg_proc
>
> jdbc parse
> jdbc bind
> jdbc execute
> LOG:  statement: SELECT * from pg_proc
>
> jdbc parse
> jdbc bind
> jdbc execute
> LOG:  statement: SELECT * from pg_proc
>
>
> Notice that the parse of the unnamed statement does *not* now generate a
> log record.

What is the reason for this?  I am not so worried about what JDBC uses
but what the protocol supports.  From my reading of the documentatation
is seems to support a single prepare and multiple executes of an unnamed
statement.

> (2)
> >   Parse (named statement S_1) "SELECT * from pg_proc"
> >   repeatedly:
> >     Bind (named statement S_1 -> unnamed portal)
> >     Execute (unnamed portal, no row limit)
>
> (2)
> jdbc parse S_1
> LOG:  statement: PREPARE S_1 AS SELECT * from pg_proc
> (perhaps this should be logged at BIND time, just like the
> optimization?)
>
> jdbc bind S_1
> jdbc execute
> LOG:  statement: EXECUTE <unnamed> [PREPARE:  SELECT * from pg_proc]
>
> jdbc bind S_1
> jdbc execute
> LOG:  statement: EXECUTE <unnamed> [PREPARE:  SELECT * from pg_proc]
>
> jdbc bind S_1
> jdbc execute
> LOG:  statement: EXECUTE <unnamed> [PREPARE:  SELECT * from pg_proc]
>
>
> ...I wonder if <unnamed> just confuses what is going on here? I've left
> it in for now, but suggest that we take that out again?

What do you want to replace it with?  A missing name seems confusing.

> (3)
> >   Parse (named statement S_2) "SELECT * from pg_proc"
> >   repeatedly:
> >     Bind (named statement S_2 -> named portal C_2)
> >     repeatedly:
> >       Execute (named portal C_2, row limit 42)
>
> (3)
> jdbc prepare S_2
> LOG:  statement: PREPARE S_2 AS SELECT * from pg_proc
>
> jdbc bind S_2 to C_2
> jdbc execute C_2
> LOG:  statement: EXECUTE C_2 ROWS 42 [PREPARE:  SELECT * from pg_proc]
> jdbc next (after cache has run out on 42nd row)
> v3 protocol sends E for Execute, execution halts at 49 rows for this set
> of bind parameters
> LOG:  statement: FETCH C_2 ROWS 7
>
> jdbc bind S_2 to C_2
> jdbc execute C_2
> LOG:  statement: EXECUTE C_2 ROWS 42 [PREPARE:  SELECT * from pg_proc]
> jdbc next (after cache has run out on 42nd row)
> v3 protocol sends E for Execute
> LOG:  statement: FETCH C_2 ROWS 42
> jdbc next (after cache has run out on 84th row)
> v3 protocol sends E for Execute, execution halts at 95 rows for this set
> of bind parameters
> LOG:  statement: FETCH C_2 ROWS 11
>
> Note: log_min_duration_statement logs after execution so can give
> accurate row counts of what was retrieved for first execute and
> subsequent fetches. In that case we log using the word ROWS.
> log_statement=all logs before execution and so only knows what the
> maximum number of rows requested is, not what the actual number of rows
> retrieved will be. In that case we log using the word MAXROWS.
> ROWS and MAXROWS are *not* mentioned unless we specifically set max_rows
> in the execute request using the v3 protocol.
>
> If we agree, I'd suggest this goes into the docs...
>
> I've not written a comprehensive test program that covers all of the
> different settings of v2/v3, named/unnamed, allrows/restricted rows,
> log_statement=all/log_min_duration_statement. I'm not sure that will fit
> within the existing test framework. So this patch is still prototype.

Here are my comments on the patch:

> Index: src/backend/tcop/postgres.c
> ===================================================================
> RCS file: /projects/cvsroot/pgsql/src/backend/tcop/postgres.c,v
> retrieving revision 1.458
> diff -c -c -r1.458 postgres.c
> *** src/backend/tcop/postgres.c 2 Sep 2005 21:50:54 -0000   1.458
> --- src/backend/tcop/postgres.c 9 Sep 2005 10:06:46 -0000
> ***************
> *** 1162,1173 ****
>     if (save_log_statement_stats)
>         ResetUsage();
>
> -   if (log_statement == LOGSTMT_ALL)
> -       ereport(LOG,
> -               (errmsg("statement: PREPARE %s AS %s",
> -                       (*stmt_name != '\0') ? stmt_name : "<unnamed>",
> -                       query_string)));
> -
>     /*
>      * Start up a transaction command so we can run parse analysis etc.
>      * (Note that this will normally change current memory context.)
> --- 1162,1167 ----
> ***************
> *** 1217,1222 ****
> --- 1211,1222 ----
>
>     QueryContext = CurrentMemoryContext;
>
> +
> +     /* Log parse only when using named statements, unless in debug1 mode */
> +       if (log_statement == LOGSTMT_ALL)
> +           ereport((is_named ? DEBUG1 : LOG),
> +               (errmsg("statement: PREPARE %s AS %s", stmt_name, query_string)));
> +

This seems backwards.  The comments says log only named statements, but
the '?' test makes named statements DEBUG.  Is this intended?

Why have you dropped the "<unnamed>"?  Whether it is DEBUG or not we
should display meaningful output.

>     /*
>      * Do basic parsing of the query or queries (this should be safe even
>      * if we are in aborted transaction state!)
> ***************
> *** 1467,1473 ****
>         portal = CreatePortal(portal_name, false, false);
>
>     if (log_statement == LOGSTMT_ALL)
> !       ereport(LOG,
>                 (errmsg("statement: <BIND> %s", portal_name)));
>
>     /*
> --- 1467,1473 ----
>         portal = CreatePortal(portal_name, false, false);
>
>     if (log_statement == LOGSTMT_ALL)
> !       ereport(DEBUG1,
>                 (errmsg("statement: <BIND> %s", portal_name)));

Can we get the BIND parameters here?  They seem significant for
debugging.

>     /*
> ***************
> *** 1683,1688 ****
> --- 1683,1689 ----
>     bool        save_log_duration = log_duration;
>     int         save_log_min_duration_statement = log_min_duration_statement;
>     bool        save_log_statement_stats = log_statement_stats;
> +     bool        subsequent_fetch = false;

Can we call this "execute_is_fetch".  That seems clearer.

>
>     /* Adjust destination to tell printtup.c what to do */
>     dest = whereToSendOutput;
> ***************
> *** 1695,1700 ****
> --- 1696,1710 ----
>                 (errcode(ERRCODE_UNDEFINED_CURSOR),
>                  errmsg("portal \"%s\" does not exist", portal_name)));
>
> +     /*
> +      * If we re-issue an Execute protocol request against an existing
> +      * portal, then we are only fetching more rows rather than
> +      * completely re-executing the query from the start. atStart is never
> +      * reset for a v3 portal, so we are safe to use this check.
> +      */
> +     if (!portal->atStart)
> +         subsequent_fetch = true;
> +
>     /*
>      * If the original query was a null string, just return
>      * EmptyQueryResponse.
> ***************
> *** 1706,1712 ****
>         return;
>     }
>
> !   if (portal->sourceText)
>     {
>         debug_query_string = portal->sourceText;
>         pgstat_report_activity(portal->sourceText);
> --- 1716,1727 ----
>         return;
>     }
>
> !     if (subsequent_fetch)
> !     {
> !       debug_query_string = "fetch message";
> !       pgstat_report_activity("<FETCH>");
> !     }
> !     else if (portal->sourceText)

Shouldn't we supply the name of the prepare here, or don't we have one?
If not, we should call it "unnamed".

>     {
>         debug_query_string = portal->sourceText;
>         pgstat_report_activity(portal->sourceText);
> ***************
> *** 1731,1742 ****
>     if (save_log_statement_stats)
>         ResetUsage();
>
>     if (log_statement == LOGSTMT_ALL)
> !       /* We have the portal, so output the source query. */
> !       ereport(LOG,
> !               (errmsg("statement: EXECUTE %s  [PREPARE:  %s]",
> !                       (*portal_name != '\0') ? portal_name : "<unnamed>",
>                         portal->sourceText ? portal->sourceText : "")));
>
>     BeginCommand(portal->commandTag, dest);
>
> --- 1746,1774 ----
>     if (save_log_statement_stats)
>         ResetUsage();
>
> +     /*
> +      * log statement details - when using log_statement=all we log the
> +      * phrase MAXROWS because this occurs prior to execution
> +      */
>     if (log_statement == LOGSTMT_ALL)
> !     {
> !         if (subsequent_fetch)
> !           ereport(LOG,
> !               (errmsg("statement: FETCH %s MAXROWS %ld", portal_name,
> !                         max_rows)));
> !         else
> !           /* We have the portal, so output the source query. */
> !             if (max_rows <= 0)
> !               ereport(LOG,
> !                   (errmsg("statement: EXECUTE %s [PREPARE:  %s]",
> !                         portal_name,
>                         portal->sourceText ? portal->sourceText : "")));
> +             else
> +                   ereport(LOG,
> +                   (errmsg("statement: EXECUTE %s MAXROWS %ld [PREPARE:  %s]",
> +                         portal_name, max_rows,
> +                       portal->sourceText ? portal->sourceText : "")));
> +     }

MAXROWS seems useful.  Good.

>     BeginCommand(portal->commandTag, dest);
>
> ***************
> *** 1865,1877 ****
>         if (save_log_min_duration_statement == 0 ||
>             (save_log_min_duration_statement > 0 &&
>              usecs >= save_log_min_duration_statement * 1000))
> !           ereport(LOG,
> !                   (errmsg("duration: %ld.%03ld ms  statement: EXECUTE %s  [PREPARE:  %s]",
>                         (long) ((stop_t.tv_sec - start_t.tv_sec) * 1000 +
>                               (stop_t.tv_usec - start_t.tv_usec) / 1000),
>                         (long) (stop_t.tv_usec - start_t.tv_usec) % 1000,
> !                           (*portal_name != '\0') ? portal_name : "<unnamed>",
> !                           portal->sourceText ? portal->sourceText : "")));
>     }
>
>     if (save_log_statement_stats)
> --- 1897,1929 ----
>         if (save_log_min_duration_statement == 0 ||
>             (save_log_min_duration_statement > 0 &&
>              usecs >= save_log_min_duration_statement * 1000))
> !         {
> !             if (subsequent_fetch)

Should the duration be snprintf into a local buffer and then used in
each ereport, rather than duplicating the code three times?

> !               ereport(LOG,
> !                   (errmsg("duration: %ld.%03ld ms  statement: FETCH %s ROWS %ld ",
>                         (long) ((stop_t.tv_sec - start_t.tv_sec) * 1000 +
>                               (stop_t.tv_usec - start_t.tv_usec) / 1000),
>                         (long) (stop_t.tv_usec - start_t.tv_usec) % 1000,
> !                           portal_name,
> !                             max_rows)));
> !             else
> !                 if (completed)
> !                   ereport(LOG,
> !                       (errmsg("duration: %ld.%03ld ms  statement: EXECUTE %s [PREPARE:  %s]",
> !                           (long) ((stop_t.tv_sec - start_t.tv_sec) * 1000 +
> !                                 (stop_t.tv_usec - start_t.tv_usec) / 1000),
> !                           (long) (stop_t.tv_usec - start_t.tv_usec) % 1000,
> !                               portal_name,
> !                               portal->sourceText ? portal->sourceText : "")));
> !                 else
> !                   ereport(LOG,
> !                       (errmsg("duration: %ld.%03ld ms  statement: EXECUTE %s ROWS %ld [PREPARE:  %s]",
> !                           (long) ((stop_t.tv_sec - start_t.tv_sec) * 1000 +
> !                                 (stop_t.tv_usec - start_t.tv_usec) / 1000),
> !                           (long) (stop_t.tv_usec - start_t.tv_usec) % 1000,
> !                               portal_name, max_rows,
> !                               portal->sourceText ? portal->sourceText : "")));
> !         }
>     }
>
>     if (save_log_statement_stats)

--
  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

Re: [HACKERS] statement logging / extended query protocol issues

From
Simon Riggs
Date:
On Thu, 2005-09-22 at 21:54 -0400, Bruce Momjian wrote:
> Here are comments on this posting and the patch (it is long):

Thanks for reading through this. I understand now why nobody had gone
into this detail before...

> > (1)
> > >   Parse (unnamed statement) "SELECT * from pg_proc"
> > >   Bind (unnamed statement -> unnamed portal)
> > >   Execute (unnamed portal, no row limit)
> >
> > (1)
> > jdbc parse
> > jdbc bind
> > jdbc execute
> > LOG:  statement: SELECT * from pg_proc
> >
> > jdbc parse
> > jdbc bind
> > jdbc execute
> > LOG:  statement: SELECT * from pg_proc
> >
> > jdbc parse
> > jdbc bind
> > jdbc execute
> > LOG:  statement: SELECT * from pg_proc
> >
> >
> > Notice that the parse of the unnamed statement does *not* now generate a
> > log record.
>
> What is the reason for this?  I am not so worried about what JDBC uses
> but what the protocol supports.  From my reading of the documentatation
> is seems to support a single prepare and multiple executes of an unnamed
> statement.

OK, in terms of the documented protocol, this represents a SimpleQuery
message. i.e. parse then immediate execute - produces only ONE log of
the statement.

I agree we should be doing this in terms of the protocol, not the
driver.

(2) and (3) represent the Extended Query protocol.

> > (2)
> > >   Parse (named statement S_1) "SELECT * from pg_proc"
> > >   repeatedly:
> > >     Bind (named statement S_1 -> unnamed portal)
> > >     Execute (unnamed portal, no row limit)

...

> > jdbc bind S_1
> > jdbc execute
> > LOG:  statement: EXECUTE <unnamed> [PREPARE:  SELECT * from pg_proc]
> >
> >
> > ...I wonder if <unnamed> just confuses what is going on here? I've left
> > it in for now, but suggest that we take that out again?
>
> What do you want to replace it with?  A missing name seems confusing.

OK, no change then

> Here are my comments on the patch:
> > +
> > +     /* Log parse only when using named statements, unless in debug1 mode */
> > +       if (log_statement == LOGSTMT_ALL)
> > +           ereport((is_named ? DEBUG1 : LOG),
> > +               (errmsg("statement: PREPARE %s AS %s", stmt_name, query_string)));
> > +
>
> This seems backwards.  The comments says log only named statements, but
> the '?' test makes named statements DEBUG.  Is this intended?
>
> Why have you dropped the "<unnamed>"?  Whether it is DEBUG or not we
> should display meaningful output.

As above, I'll remove that part of the code.

> >     /*
> >      * Do basic parsing of the query or queries (this should be safe even
> >      * if we are in aborted transaction state!)
> > ***************
> > *** 1467,1473 ****
> >         portal = CreatePortal(portal_name, false, false);
> >
> >     if (log_statement == LOGSTMT_ALL)
> > !       ereport(LOG,
> >                 (errmsg("statement: <BIND> %s", portal_name)));
> >
> >     /*
> > --- 1467,1473 ----
> >         portal = CreatePortal(portal_name, false, false);
> >
> >     if (log_statement == LOGSTMT_ALL)
> > !       ereport(DEBUG1,
> >                 (errmsg("statement: <BIND> %s", portal_name)));
>
> Can we get the BIND parameters here?  They seem significant for
> debugging.

Maybe, but I'll punt on this for now in an attempt to not overextend
myself.

I think this would be best handled with a log_bind_parms = (none | first
| all) so that all would be happy.

> >     /*
> > ***************
> > *** 1683,1688 ****
> > --- 1683,1689 ----
> >     bool        save_log_duration = log_duration;
> >     int         save_log_min_duration_statement = log_min_duration_statement;
> >     bool        save_log_statement_stats = log_statement_stats;
> > +     bool        subsequent_fetch = false;
>
> Can we call this "execute_is_fetch".  That seems clearer.

Will do.

> > ***************
> > *** 1706,1712 ****
> >         return;
> >     }
> >
> > !   if (portal->sourceText)
> >     {
> >         debug_query_string = portal->sourceText;
> >         pgstat_report_activity(portal->sourceText);
> > --- 1716,1727 ----
> >         return;
> >     }
> >
> > !     if (subsequent_fetch)
> > !     {
> > !       debug_query_string = "fetch message";
> > !       pgstat_report_activity("<FETCH>");
> > !     }
> > !     else if (portal->sourceText)
>
> Shouldn't we supply the name of the prepare here, or don't we have one?
> If not, we should call it "unnamed".

Yes we can, and yes will do.

> > ***************
> > *** 1865,1877 ****
> >         if (save_log_min_duration_statement == 0 ||
> >             (save_log_min_duration_statement > 0 &&
> >              usecs >= save_log_min_duration_statement * 1000))
> > !           ereport(LOG,
> > !                   (errmsg("duration: %ld.%03ld ms  statement: EXECUTE %s  [PREPARE:  %s]",
> >                         (long) ((stop_t.tv_sec - start_t.tv_sec) * 1000 +
> >                               (stop_t.tv_usec - start_t.tv_usec) / 1000),
> >                         (long) (stop_t.tv_usec - start_t.tv_usec) % 1000,
> > !                           (*portal_name != '\0') ? portal_name : "<unnamed>",
> > !                           portal->sourceText ? portal->sourceText : "")));
> >     }
> >
> >     if (save_log_statement_stats)
> > --- 1897,1929 ----
> >         if (save_log_min_duration_statement == 0 ||
> >             (save_log_min_duration_statement > 0 &&
> >              usecs >= save_log_min_duration_statement * 1000))
> > !         {
> > !             if (subsequent_fetch)
>
> Should the duration be snprintf into a local buffer and then used in
> each ereport, rather than duplicating the code three times?

Yes (this was never going to be the final patch...)

Best Regards, Simon Riggs



Re: [HACKERS] statement logging / extended query protocol

From
Bruce Momjian
Date:
Simon Riggs wrote:
> On Thu, 2005-09-22 at 21:54 -0400, Bruce Momjian wrote:
> > Here are comments on this posting and the patch (it is long):
>
> Thanks for reading through this. I understand now why nobody had gone
> into this detail before...
>
> > > (1)
> > > >   Parse (unnamed statement) "SELECT * from pg_proc"
> > > >   Bind (unnamed statement -> unnamed portal)
> > > >   Execute (unnamed portal, no row limit)
> > >
> > > (1)
> > > jdbc parse
> > > jdbc bind
> > > jdbc execute
> > > LOG:  statement: SELECT * from pg_proc
> > >
> > > jdbc parse
> > > jdbc bind
> > > jdbc execute
> > > LOG:  statement: SELECT * from pg_proc
> > >
> > > jdbc parse
> > > jdbc bind
> > > jdbc execute
> > > LOG:  statement: SELECT * from pg_proc
> > >
> > >
> > > Notice that the parse of the unnamed statement does *not* now generate a
> > > log record.
> >
> > What is the reason for this?  I am not so worried about what JDBC uses
> > but what the protocol supports.  From my reading of the documentatation
> > is seems to support a single prepare and multiple executes of an unnamed
> > statement.
>
> OK, in terms of the documented protocol, this represents a SimpleQuery
> message. i.e. parse then immediate execute - produces only ONE log of
> the statement.
>
> I agree we should be doing this in terms of the protocol, not the
> driver.

I am confused.  I don't see SimpleQuery mentioned anywhere in our
documentation.  Is it a JDBC function?  Are you saying an unnamed
prepare should only be logged once?  Why?

> > Can we get the BIND parameters here?  They seem significant for
> > debugging.
>
> Maybe, but I'll punt on this for now in an attempt to not overextend
> myself.
>
> I think this would be best handled with a log_bind_parms = (none | first
> | all) so that all would be happy.

I see no reason they should not always be logged if we are logging
all or mod statements.

> > Should the duration be snprintf into a local buffer and then used in
> > each ereport, rather than duplicating the code three times?
>
> Yes (this was never going to be the final patch...)

OK.  At this stage it should all just wait for 8.2.  I think the only
missing things we have now is that BIND parameters are not logged, and a
fetch of an already-executed statement appears as another execute.

Added to TODO:

    * Allow protocol-level BIND parameter values to be logged
    * Allow protocol-level EXECUTE that is actually a fetch to appear
      in the logs as a fetch rather than another execute

--
  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

Re: [HACKERS] statement logging / extended query protocol

From
Tom Lane
Date:
Bruce Momjian <pgman@candle.pha.pa.us> writes:
> OK.  At this stage it should all just wait for 8.2.

Haven't we already committed some feature changes in this area?  I
dislike the idea of shipping a transient state just because "we ran out
of time".  Once we ship 8.1, that will be another behavior that we have
to consider backwards compatibility with.  We should either fix it
right, or revert to the 8.0 behavior for this release.

            regards, tom lane

Re: [HACKERS] statement logging / extended query protocol

From
Bruce Momjian
Date:
Tom Lane wrote:
> Bruce Momjian <pgman@candle.pha.pa.us> writes:
> > OK.  At this stage it should all just wait for 8.2.
>
> Haven't we already committed some feature changes in this area?  I
> dislike the idea of shipping a transient state just because "we ran out
> of time".  Once we ship 8.1, that will be another behavior that we have
> to consider backwards compatibility with.  We should either fix it
> right, or revert to the 8.0 behavior for this release.

I documented in TODO what doesn't log properly in 8.1.  I don't see how
logging output has to be backward compatible.  To revert would be to
remove logging of server-level prepare/execute.  I don't see that as a
win.

--
  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

Re: [HACKERS] statement logging / extended query protocol

From
David Fetter
Date:
On Sun, Sep 25, 2005 at 11:41:11PM -0400, Bruce Momjian wrote:
> Tom Lane wrote:
> > Bruce Momjian <pgman@candle.pha.pa.us> writes:
> > > OK.  At this stage it should all just wait for 8.2.
> >
> > Haven't we already committed some feature changes in this area?  I
> > dislike the idea of shipping a transient state just because "we
> > ran out of time".  Once we ship 8.1, that will be another behavior
> > that we have to consider backwards compatibility with.  We should
> > either fix it right, or revert to the 8.0 behavior for this
> > release.
>
> I documented in TODO what doesn't log properly in 8.1.  I don't see
> how logging output has to be backward compatible.

Dunno about this particular case, but not having backward-compatible
logging output has already broken pqa.  Proposal on logging to
-hackers follows...

Cheers,
D
--
David Fetter david@fetter.org http://fetter.org/
phone: +1 510 893 6100   mobile: +1 415 235 3778

Remember to vote!

Re: [HACKERS] statement logging / extended query protocol

From
Bruce Momjian
Date:
David Fetter wrote:
> On Sun, Sep 25, 2005 at 11:41:11PM -0400, Bruce Momjian wrote:
> > Tom Lane wrote:
> > > Bruce Momjian <pgman@candle.pha.pa.us> writes:
> > > > OK.  At this stage it should all just wait for 8.2.
> > >
> > > Haven't we already committed some feature changes in this area?  I
> > > dislike the idea of shipping a transient state just because "we
> > > ran out of time".  Once we ship 8.1, that will be another behavior
> > > that we have to consider backwards compatibility with.  We should
> > > either fix it right, or revert to the 8.0 behavior for this
> > > release.
> >
> > I documented in TODO what doesn't log properly in 8.1.  I don't see
> > how logging output has to be backward compatible.
>
> Dunno about this particular case, but not having backward-compatible
> logging output has already broken pqa.  Proposal on logging to
> -hackers follows...

Yes, that is one area that is of concern for logging changes.  What I
have done is to get minimal logging of the FETCH behavior into 8.1,
along with what we already have added in 8.1.

--
  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