Skip site navigation (1) Skip section navigation (2)

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

From: Bruce Momjian <bruce(at)momjian(dot)us>
To: Guillaume Smet <guillaume(dot)smet(at)gmail(dot)com>
Cc: Tom Lane <tgl(at)sss(dot)pgh(dot)pa(dot)us>, Oliver Jowett <oliver(at)opencloud(dot)com>, Dave Cramer <pg(at)fastcrypt(dot)com>, Csaba Nagy <nagy(at)ecircle-ag(dot)com>, Postgres JDBC <pgsql-jdbc(at)postgresql(dot)org>, PostgreSQL-patches <pgsql-patches(at)postgresql(dot)org>
Subject: Re: [HACKERS] [PATCHES] log_statement output for protocol
Date: 2006-08-29 02:08:33
Message-ID: 200608290208.k7T28Xg28730@momjian.us (view raw or flat)
Thread:
Lists: pgsql-hackerspgsql-jdbcpgsql-patches
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. +

Attachment: /bjm/diff
Description: text/x-diff (14.9 KB)

In response to

Responses

pgsql-hackers by date

Next:From: Bruce MomjianDate: 2006-08-29 02:09:51
Subject: Re: [HACKERS] Performance testing of COPY (SELECT)
Previous:From: Tom LaneDate: 2006-08-29 01:58:24
Subject: Re: Rtree circle ops

pgsql-patches by date

Next:From: Bruce MomjianDate: 2006-08-29 02:09:51
Subject: Re: [HACKERS] Performance testing of COPY (SELECT)
Previous:From: Bruno Wolff IIIDate: 2006-08-29 01:54:46
Subject: Re: [HACKERS] Performance testing of COPY (SELECT) TO

pgsql-jdbc by date

Next:From: Tom LaneDate: 2006-08-29 02:18:14
Subject: Re: [HACKERS] [PATCHES] log_statement output for protocol
Previous:From: Dave CramerDate: 2006-08-28 17:34:20
Subject: Re: Optimizations in the latest driver

Privacy Policy | About PostgreSQL
Copyright © 1996-2014 The PostgreSQL Global Development Group