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

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