Re: [HACKERS] statement logging / extended query protocol issues - Mailing list pgsql-patches

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