Re: [HACKERS] [PATCHES] log_statement output for protocol

Guillaume Smet wrote:
> On 8/7/06, Bruce Momjian <bruce(at)momjian(dot)us> wrote:
> > Updated patch attached. It prints the text bind parameters on a single
> > detail line. I still have not seen portal names generated by libpq.
>
> I'm currently testing CVS tip to generate sample log files. I noticed
> that Bruce only patched log_statement and not
> log_min_duration_statement which still has the old behaviour ie:
> [1-1] LOG: duration: 0.097 ms execute my_query: SELECT * FROM shop
> WHERE name = $1
> The problem of not having the bind parameters still remains.
>
> A lot of people use log_min_duration_statement and it's usually
> recommended to use it instead of log_statement because log_statement
> generates far too much output.
> I tried to find a way to fix it but it's not so simple as when we bind
> the statement, we don't know if the query will be slower than
> log_min_duration_statement.
>
> My first idea is that we should add a DETAIL line with the parameter
> values to the execute log line when we are in the
> log_min_duration_statement case. AFAICS the values are in the portal
> but I don't know the overhead introduced by generating the detail line
> from the portal.
>
> Does anyone have a better idea on how we could fix it?

Yes, I do. I have applied the attached patch to fix this issue and
several others. The fix was to save the bind parameters in the portal,
and display those in the executor output, if available.

The other changes were to use single quotes for bind values, instead of
double quotes, and double literal single quotes in bind values (and
document that). I also made use of the DETAIL line to have much cleaner
output.

With the new output, bind displays prepare as detail, and execute
displays prepare and optionally bind. I re-added the "statement:" label
so people will understand why the line is being printed (it is
log_*statement behavior). I am now happy that the display is clear and
not cluttered.

-- SQL using log_statement
LOG: set log_statement = 'all';
LOG: statement: begin;
LOG: statement: prepare x as select $1::text;
LOG: statement: execute x ('a');
DETAIL: prepare: prepare x as select $1::text;
LOG: statement: commit;

-- SQL using log_min_duration_statement
LOG: statement: set log_statement = 'none';
LOG: duration: 0.242 ms statement: set log_min_duration_statement = 0;
LOG: duration: 0.155 ms statement: begin;
LOG: duration: 0.174 ms statement: prepare y as select $1::text;
LOG: duration: 0.252 ms statement: execute y ('a');
DETAIL: prepare: prepare y as select $1::text;
LOG: duration: 0.093 ms statement: commit;

-- protocol using log_statement
LOG: statement: prepare sel1, SELECT $1;
LOG: statement: bind sel1, $1 = 'a''b'
DETAIL: prepare: SELECT $1;
LOG: statement: execute sel1
DETAIL: prepare: SELECT $1; bind: $1 = 'a''b'

-- protocol using log_min_duration_statement
LOG: duration: 0.497 ms statement: SET log_min_duration_statement = 0;
LOG: duration: 0.027 ms execute sel1
DETAIL: prepare: SELECT $1; bind: $1 = 'a''b'

The last output doesn't have bind or prepare because we don't print
those because we don't do any duration timing for them. Should we print
the statement: lines of log_min_duration_statement == 0?

Also, this code assumes that a protocol bind and execute always has
prepared statement text, which I believe is true.

The use of brackets is gone. :-)

--
Bruce Momjian bruce(at)momjian(dot)us
EnterpriseDB http://www.enterprisedb.com

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