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

bruce wrote:
> Tom Lane wrote:
> > Bruce Momjian <bruce(at)momjian(dot)us> writes:
> > > Dave Cramer wrote:
> > >> Bind also has a statement name, as well as a portal name ?
> > >>
> > >> Ideally I'd like to see the parameters which were bound and the
> > >> types, but I suspect I'm reaching here.
> >
> > > Right, but do we want to repeat the statement for every bind case?
> >
> > My upthread proposal was to print the statement and portal names
> > at bind time. The current printout is very clearly inadequate.
>
> Sure, I can do that.
>
> Did you like my idea of?
>
> statement: <protocol execute> ...
>
> You didn't reply. I want to keep the "statement:" prefix for scripts
> that process our log files, and because it is output by log_statement,
> which controls protocol output as well.

I have applied this patch to output the statemented referenced by BIND.
I also changed the "[protocol]" string to "<protocol>" for clarity. I
am ready to pull PREPARE|BIND|EXECUTED into the "protocol" bracket too
if someone says that is a good idea.

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

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

Bruce,

Doesn't it make more sense to use the statement name ?

If I prepare S_3 as "select * from foo"

then the bind log is going to show me "select * from foo" not S_3

I think in the case of named statements I'd prefer "S_3" however as I
think about this in the case of unnamed statements I'd prefer the
"select * from foo"

Comments ?

Dave
On 4-Aug-06, at 2:56 PM, Bruce Momjian wrote:

> bruce wrote:
>> Tom Lane wrote:
>>> Bruce Momjian <bruce(at)momjian(dot)us> writes:
>>>> Dave Cramer wrote:
>>>>> Bind also has a statement name, as well as a portal name ?
>>>>>
>>>>> Ideally I'd like to see the parameters which were bound and the
>>>>> types, but I suspect I'm reaching here.
>>>
>>>> Right, but do we want to repeat the statement for every bind case?
>>>
>>> My upthread proposal was to print the statement and portal names
>>> at bind time. The current printout is very clearly inadequate.
>>
>> Sure, I can do that.
>>
>> Did you like my idea of?
>>
>> statement: <protocol execute> ...
>>
>> You didn't reply. I want to keep the "statement:" prefix for scripts
>> that process our log files, and because it is output by
>> log_statement,
>> which controls protocol output as well.
>
> I have applied this patch to output the statemented referenced by
> BIND.
> I also changed the "[protocol]" string to "<protocol>" for clarity. I
> am ready to pull PREPARE|BIND|EXECUTED into the "protocol" bracket too
> if someone says that is a good idea.
>
> --
> Bruce Momjian bruce(at)momjian(dot)us
> EnterpriseDB http://www.enterprisedb.com
>
> + If your life is a hard drive, Christ can be your backup. +
> Index: src/backend/tcop/postgres.c
> ===================================================================
> RCS file: /cvsroot/pgsql/src/backend/tcop/postgres.c,v
> retrieving revision 1.493
> diff -c -c -r1.493 postgres.c
> *** src/backend/tcop/postgres.c 29 Jul 2006 03:02:56 -0000 1.493
> --- src/backend/tcop/postgres.c 4 Aug 2006 18:50:59 -0000
> ***************
> *** 1146,1153 ****
>
> if (log_statement == LOGSTMT_ALL)
> ereport(LOG,
> ! (errmsg("statement: [protocol] PREPARE %s AS %s",
> ! (*stmt_name != '\0') ? stmt_name : "<unnamed>",
> query_string)));
>
> /*
> --- 1146,1153 ----
>
> if (log_statement == LOGSTMT_ALL)
> ereport(LOG,
> ! (errmsg("statement: <protocol> PREPARE %s AS %s",
> ! *stmt_name ? stmt_name : "<unnamed>",
> query_string)));
>
> /*
> ***************
> *** 1452,1458 ****
> /* We need to output the parameter values someday */
> if (log_statement == LOGSTMT_ALL)
> ereport(LOG,
> ! (errmsg("statement: [protocol] <BIND> %s", portal_name)));
>
> /*
> * Fetch parameters, if any, and store in the portal's memory
> context.
> --- 1452,1460 ----
> /* We need to output the parameter values someday */
> if (log_statement == LOGSTMT_ALL)
> ereport(LOG,
> ! (errmsg("statement: <protocol> <BIND> %s [PREPARE: %s]",
> ! *portal_name ? portal_name : "<unnamed>",
> ! portal->sourceText ? portal->sourceText : "")));
>
> /*
> * Fetch parameters, if any, and store in the portal's memory
> context.
> ***************
> *** 1718,1726 ****
> if (log_statement == LOGSTMT_ALL)
> /* We have the portal, so output the source query. */
> ereport(LOG,
> ! (errmsg("statement: [protocol] %sEXECUTE %s [PREPARE: %s]",
> execute_is_fetch ? "FETCH from " : "",
> ! (*portal_name) ? portal_name : "<unnamed>",
> portal->sourceText ? portal->sourceText : "")));
>
> BeginCommand(portal->commandTag, dest);
> --- 1720,1728 ----
> if (log_statement == LOGSTMT_ALL)
> /* We have the portal, so output the source query. */
> ereport(LOG,
> ! (errmsg("statement: <protocol> %sEXECUTE %s [PREPARE: %s]",
> execute_is_fetch ? "FETCH from " : "",
> ! *portal_name ? portal_name : "<unnamed>",
> portal->sourceText ? portal->sourceText : "")));
>
> BeginCommand(portal->commandTag, dest);
> ***************
> *** 1826,1836 ****
> secs, msecs)));
> else
> ereport(LOG,
> ! (errmsg("duration: %ld.%03d ms statement: [protocol] %
> sEXECUTE %s [PREPARE: %s]",
> secs, msecs,
> execute_is_fetch ? "FETCH from " : "",
> ! (*portal_name) ? portal_name : "<unnamed>",
> ! portal->sourceText ? portal->sourceText : "")));
> }
> }
>
> --- 1828,1838 ----
> secs, msecs)));
> else
> ereport(LOG,
> ! (errmsg("duration: %ld.%03d ms statement: <protocol> %
> sEXECUTE %s [PREPARE: %s]",
> secs, msecs,
> execute_is_fetch ? "FETCH from " : "",
> ! *portal_name ? portal_name : "<unnamed>",
> ! portal->sourceText ? portal->sourceText : "")));
> }
> }
>

Dave Cramer wrote:
> Bruce,
>
> Doesn't it make more sense to use the statement name ?
>
> If I prepare S_3 as "select * from foo"
>
> then the bind log is going to show me "select * from foo" not S_3
>
> I think in the case of named statements I'd prefer "S_3" however as I
> think about this in the case of unnamed statements I'd prefer the
> "select * from foo"

The bind shows:

(errmsg("statement: <protocol> <BIND> %s [PREPARE: %s]",

The first %s is the statement name, and the second %s is the query.

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

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

Bruce Momjian <bruce(at)momjian(dot)us> writes:
> ! (errmsg("statement: [protocol] <BIND> %s", portal_name)));

> --- 1452,1460 ----
> ! (errmsg("statement: <protocol> <BIND> %s [PREPARE: %s]",
> ! *portal_name ? portal_name : "<unnamed>",
> ! portal->sourceText ? portal->sourceText : "")));

This is getting less readable not more so; and you still haven't got the
prepared statement's name in there, let alone any place to put the
parameter values.

Perhaps we should give up on the idea that this can all fit on one log
line? Maybe

LOG: parse: <statement-name>
DETAIL: statement: <source-text>

LOG: bind: <portal-name> to <statement-name>
DETAIL: statement: <source-text>
parameter 1: <parameter value>
parameter 2: <parameter value>
...

LOG: execute: <portal-name>
DETAIL: statement: <source-text>

The $64 question here is whether we want to repeat the source-text
in all three messages (parse, bind, execute) or try to reduce the
verbosity.

regards, tom lane

Tom Lane wrote:
> Bruce Momjian <bruce(at)momjian(dot)us> writes:
> > ! (errmsg("statement: [protocol] <BIND> %s", portal_name)));
>
> > --- 1452,1460 ----
> > ! (errmsg("statement: <protocol> <BIND> %s [PREPARE: %s]",
> > ! *portal_name ? portal_name : "<unnamed>",
> > ! portal->sourceText ? portal->sourceText : "")));
>
> This is getting less readable not more so; and you still haven't got the
> prepared statement's name in there, let alone any place to put the
> parameter values.

I thought the portal name was the statement name. Seems I was wrong.

> Perhaps we should give up on the idea that this can all fit on one log
> line? Maybe
>
> LOG: parse: <statement-name>
> DETAIL: statement: <source-text>
>
> LOG: bind: <portal-name> to <statement-name>
> DETAIL: statement: <source-text>
> parameter 1: <parameter value>
> parameter 2: <parameter value>
> ...
>
> LOG: execute: <portal-name>
> DETAIL: statement: <source-text>
>
> The $64 question here is whether we want to repeat the source-text
> in all three messages (parse, bind, execute) or try to reduce the
> verbosity.

We don't print DETAIL in the logs, do we?

Does anyone have C code that uses these features so I can test?

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

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

Bruce Momjian <bruce(at)momjian(dot)us> writes:
> The bind shows:
> (errmsg("statement: <protocol> <BIND> %s [PREPARE: %s]",
> The first %s is the statement name, and the second %s is the query.

No, it's the portal name. There's a difference.

regards, tom lane

Bruce Momjian <bruce(at)momjian(dot)us> writes:
> We don't print DETAIL in the logs, do we?

Yes, we do, unless you've set log_error_verbosity to less than the
default.

regards, tom lane

Tom Lane wrote:
> Bruce Momjian <bruce(at)momjian(dot)us> writes:
> > ! (errmsg("statement: [protocol] <BIND> %s", portal_name)));
>
> > --- 1452,1460 ----
> > ! (errmsg("statement: <protocol> <BIND> %s [PREPARE: %s]",
> > ! *portal_name ? portal_name : "<unnamed>",
> > ! portal->sourceText ? portal->sourceText : "")));
>
> This is getting less readable not more so; and you still haven't got the
> prepared statement's name in there, let alone any place to put the
> parameter values.
>
> Perhaps we should give up on the idea that this can all fit on one log
> line? Maybe
>
> LOG: parse: <statement-name>
> DETAIL: statement: <source-text>
>
> LOG: bind: <portal-name> to <statement-name>
> DETAIL: statement: <source-text>
> parameter 1: <parameter value>
> parameter 2: <parameter value>
> ...
>
> LOG: execute: <portal-name>
> DETAIL: statement: <source-text>
>
> The $64 question here is whether we want to repeat the source-text
> in all three messages (parse, bind, execute) or try to reduce the
> verbosity.

I modified the code to store the user statement name in the portal for
protocol execute, so I can print the user name at that time. Here is
the new output:

LOG: statement protocol prepare sel1: SELECT 1;
LOG: statement protocol bind sel1: SELECT 1;
LOG: statement protocol execute sel1: SELECT 1;

Patch attached. I am also attaching my test program. Should I put that
in CVS somewhere? Libpq.sgml.

I had to pstrdup() the statement name. Is that OK?

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

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

Bruce Momjian <bruce(at)momjian(dot)us> writes:
> I modified the code to store the user statement name in the portal for
> protocol execute, so I can print the user name at that time.

Please forget that and print the portal name. I'm getting tired of
repeating it, but: there are two different names here and they are
both important. The bind message should print both names.

> Here is
> the new output:

> LOG: statement protocol prepare sel1: SELECT 1;
> LOG: statement protocol bind sel1: SELECT 1;
> LOG: statement protocol execute sel1: SELECT 1;

If we could lose the noise words "statement protocol" we'd be getting
somewhere ...

regards, tom lane

Tom Lane wrote:
> Bruce Momjian <bruce(at)momjian(dot)us> writes:
> > I modified the code to store the user statement name in the portal for
> > protocol execute, so I can print the user name at that time.
>
> Please forget that and print the portal name. I'm getting tired of
> repeating it, but: there are two different names here and they are
> both important. The bind message should print both names.

OK, I added code to print an optional "/" and the portal name. However,
I can't get libpq to show a portal name. Looking at libpq, does it only
use "" portals, because the only place I see it sending a "B" shows a ""
portal name? How can I test a portal name display?

> > Here is
> > the new output:
>
> > LOG: statement protocol prepare sel1: SELECT 1;
> > LOG: statement protocol bind sel1: SELECT 1;
> > LOG: statement protocol execute sel1: SELECT 1;
>
> If we could lose the noise words "statement protocol" we'd be getting
> somewhere ...

OK, as no one has said they like "statement protocol", the new output is:

LOG: prepare sel1: SELECT 1;
LOG: bind sel1: SELECT 1;
LOG: execute sel1: SELECT 1;

I will take a look at printing out bind text parameters.

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

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

OK, updated patch, with output of text bind parameters. New output is:

LOG: prepare sel1: SELECT $1 + $2;
LOG: bind sel1: SELECT $1 + $2;
LOG: bind sel1: parameter 1: "8"
LOG: bind sel1: parameter 2: "5"
LOG: execute sel1: SELECT $1 + $2;

I put each bind parameter on a separate line. Is that OK?

I also updated the documentation. Test program also attached.

---------------------------------------------------------------------------

Bruce Momjian wrote:
> Tom Lane wrote:
> > Bruce Momjian <bruce(at)momjian(dot)us> writes:
> > > I modified the code to store the user statement name in the portal for
> > > protocol execute, so I can print the user name at that time.
> >
> > Please forget that and print the portal name. I'm getting tired of
> > repeating it, but: there are two different names here and they are
> > both important. The bind message should print both names.
>
> OK, I added code to print an optional "/" and the portal name. However,
> I can't get libpq to show a portal name. Looking at libpq, does it only
> use "" portals, because the only place I see it sending a "B" shows a ""
> portal name? How can I test a portal name display?
>
> > > Here is
> > > the new output:
> >
> > > LOG: statement protocol prepare sel1: SELECT 1;
> > > LOG: statement protocol bind sel1: SELECT 1;
> > > LOG: statement protocol execute sel1: SELECT 1;
> >
> > If we could lose the noise words "statement protocol" we'd be getting
> > somewhere ...
>
> OK, as no one has said they like "statement protocol", the new output is:
>
> LOG: prepare sel1: SELECT 1;
> LOG: bind sel1: SELECT 1;
> LOG: execute sel1: SELECT 1;
>
> I will take a look at printing out bind text parameters.
>
> --
> Bruce Momjian bruce(at)momjian(dot)us
> EnterpriseDB http://www.enterprisedb.com
>
> + If your life is a hard drive, Christ can be your backup. +

>
> ---------------------------(end of broadcast)---------------------------
> TIP 9: In versions below 8.0, the planner will ignore your desire to
> choose an index scan if your joining column's datatypes do not
> match

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

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

Bruce Momjian wrote:
> OK, updated patch, with output of text bind parameters. New output is:
>
> LOG: prepare sel1: SELECT $1 + $2;
> LOG: bind sel1: SELECT $1 + $2;
> LOG: bind sel1: parameter 1: "8"
> LOG: bind sel1: parameter 2: "5"
> LOG: execute sel1: SELECT $1 + $2;
>
> I put each bind parameter on a separate line. Is that OK?

My only comment here is that this is very verbose. The JDBC driver now
always uses the extended query protocol, even when not doing
"server-side prepare", so you're going to get multiple lines of output
all the time when using JDBC apps.

A 50-parameter query could be .. interesting ..

I realize that you need this level of output to reflect what is
happening at the protocol level, but seeing all the protocol detail is
not really what you expect when you turn on basic statement logging, is it?

-O

On Sat, Aug 05, 2006 at 07:39:48PM +1200, Oliver Jowett wrote:
> Bruce Momjian wrote:
> >OK, updated patch, with output of text bind parameters. New output
> >is:
> >
> > LOG: prepare sel1: SELECT $1 + $2;
> > LOG: bind sel1: SELECT $1 + $2;
> > LOG: bind sel1: parameter 1: "8"
> > LOG: bind sel1: parameter 2: "5"
> > LOG: execute sel1: SELECT $1 + $2;
> >
> >I put each bind parameter on a separate line. Is that OK?
>
> My only comment here is that this is very verbose. The JDBC driver
> now always uses the extended query protocol, even when not doing
> "server-side prepare", so you're going to get multiple lines of
> output all the time when using JDBC apps.

Does this mean that the JDBC driver needs work on this?

> A 50-parameter query could be .. interesting ..
>
> I realize that you need this level of output to reflect what is
> happening at the protocol level, but seeing all the protocol detail
> is not really what you expect when you turn on basic statement
> logging, is it?

Possibly not basic statement logging, but there are cases where I
would have saved a *lot* of time if it had been available.

Cheers,
D
--
David Fetter <david(at)fetter(dot)org> http://fetter.org/
phone: +1 415 235 3778 AIM: dfetter666
Skype: davidfetter

Remember to vote!

Oliver Jowett <oliver(at)opencloud(dot)com> writes:
> A 50-parameter query could be .. interesting ..

> I realize that you need this level of output to reflect what is
> happening at the protocol level, but seeing all the protocol detail is
> not really what you expect when you turn on basic statement logging, is it?

Well, we've certainly been beat up often enough about the lack of
logging bind parameter values --- I don't think there's any question
about the importance of printing them. I agree that the proposed format
is much too verbose though. In particular, a separate LOG message per
parameter is NOT what I had in mind; I want them in DETAIL lines of the
bind log message. (This'd perhaps also address Oliver's issue, since
if you didn't want to see the values you could turn down
log_error_verbosity.)

regards, tom lane

Tom Lane wrote:
> Oliver Jowett <oliver(at)opencloud(dot)com> writes:
> > A 50-parameter query could be .. interesting ..
>
> > I realize that you need this level of output to reflect what is
> > happening at the protocol level, but seeing all the protocol detail is
> > not really what you expect when you turn on basic statement logging, is it?
>
> Well, we've certainly been beat up often enough about the lack of
> logging bind parameter values --- I don't think there's any question
> about the importance of printing them. I agree that the proposed format
> is much too verbose though. In particular, a separate LOG message per
> parameter is NOT what I had in mind; I want them in DETAIL lines of the
> bind log message. (This'd perhaps also address Oliver's issue, since
> if you didn't want to see the values you could turn down
> log_error_verbosity.)

OK, I will continue in that direction. Will post a new patch.

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

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

Bruce Momjian wrote:
> Tom Lane wrote:
> > Oliver Jowett <oliver(at)opencloud(dot)com> writes:
> > > A 50-parameter query could be .. interesting ..
> >
> > > I realize that you need this level of output to reflect what is
> > > happening at the protocol level, but seeing all the protocol detail is
> > > not really what you expect when you turn on basic statement logging, is it?
> >
> > Well, we've certainly been beat up often enough about the lack of
> > logging bind parameter values --- I don't think there's any question
> > about the importance of printing them. I agree that the proposed format
> > is much too verbose though. In particular, a separate LOG message per
> > parameter is NOT what I had in mind; I want them in DETAIL lines of the
> > bind log message. (This'd perhaps also address Oliver's issue, since
> > if you didn't want to see the values you could turn down
> > log_error_verbosity.)
>
> OK, I will continue in that direction. Will post a new patch.

Updated patch attached. It prints the text bind parameters on a single
detail line. I still have not seen portal names generated by libpq.

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

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

Sorry, forgot to show sample output:

LOG: prepare sel1: SELECT $1 + $2;
LOG: bind sel1: SELECT $1 + $2;
DETAIL: $1 = "8", $2 = "5"
LOG: execute sel1: SELECT $1 + $2;

LOG: prepare sel1: SELECT 3;
LOG: bind sel1: SELECT 3;
LOG: execute sel1: SELECT 3;

---------------------------------------------------------------------------

Bruce Momjian wrote:
> Bruce Momjian wrote:
> > Tom Lane wrote:
> > > Oliver Jowett <oliver(at)opencloud(dot)com> writes:
> > > > A 50-parameter query could be .. interesting ..
> > >
> > > > I realize that you need this level of output to reflect what is
> > > > happening at the protocol level, but seeing all the protocol detail is
> > > > not really what you expect when you turn on basic statement logging, is it?
> > >
> > > Well, we've certainly been beat up often enough about the lack of
> > > logging bind parameter values --- I don't think there's any question
> > > about the importance of printing them. I agree that the proposed format
> > > is much too verbose though. In particular, a separate LOG message per
> > > parameter is NOT what I had in mind; I want them in DETAIL lines of the
> > > bind log message. (This'd perhaps also address Oliver's issue, since
> > > if you didn't want to see the values you could turn down
> > > log_error_verbosity.)
> >
> > OK, I will continue in that direction. Will post a new patch.
>
> Updated patch attached. It prints the text bind parameters on a single
> detail line. I still have not seen portal names generated by libpq.

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

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

Applied. Changes are:

For protocol-level prepare/bind/execute:

o print user name for all
o print portal name if defined for all
o print query for all
o reduce log_statement header to single keyword
o print bind parameters as DETAIL if text mode

---------------------------------------------------------------------------

Bruce Momjian wrote:
>
> Sorry, forgot to show sample output:
>
> LOG: prepare sel1: SELECT $1 + $2;
> LOG: bind sel1: SELECT $1 + $2;
> DETAIL: $1 = "8", $2 = "5"
> LOG: execute sel1: SELECT $1 + $2;
>
> LOG: prepare sel1: SELECT 3;
> LOG: bind sel1: SELECT 3;
> LOG: execute sel1: SELECT 3;
>
>
> ---------------------------------------------------------------------------
>
> Bruce Momjian wrote:
> > Bruce Momjian wrote:
> > > Tom Lane wrote:
> > > > Oliver Jowett <oliver(at)opencloud(dot)com> writes:
> > > > > A 50-parameter query could be .. interesting ..
> > > >
> > > > > I realize that you need this level of output to reflect what is
> > > > > happening at the protocol level, but seeing all the protocol detail is
> > > > > not really what you expect when you turn on basic statement logging, is it?
> > > >
> > > > Well, we've certainly been beat up often enough about the lack of
> > > > logging bind parameter values --- I don't think there's any question
> > > > about the importance of printing them. I agree that the proposed format
> > > > is much too verbose though. In particular, a separate LOG message per
> > > > parameter is NOT what I had in mind; I want them in DETAIL lines of the
> > > > bind log message. (This'd perhaps also address Oliver's issue, since
> > > > if you didn't want to see the values you could turn down
> > > > log_error_verbosity.)
> > >
> > > OK, I will continue in that direction. Will post a new patch.
> >
> > Updated patch attached. It prints the text bind parameters on a single
> > detail line. I still have not seen portal names generated by libpq.
>
> --
> Bruce Momjian bruce(at)momjian(dot)us
> EnterpriseDB http://www.enterprisedb.com
>
> + If your life is a hard drive, Christ can be your backup. +
>
> ---------------------------(end of broadcast)---------------------------
> TIP 2: Don't 'kill -9' the postmaster

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

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

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?

Regards,

--
Guillaume

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

Bruce Momjian <bruce(at)momjian(dot)us> writes:
> 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.

I have a feeling you just blew away the 4% savings in psql I've spent
the evening on. What's the overhead of this patch?

regards, tom lane

BTom Lane wrote:
> Bruce Momjian <bruce(at)momjian(dot)us> writes:
> > 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.
>
> I have a feeling you just blew away the 4% savings in psql I've spent
> the evening on. What's the overhead of this patch?

The only overhead I see is calling log_after_parse() all the time,
rather than only when log_statement is all. I could fix it by checking
log_statement and log_min_duration_statement >= 0. Does
log_after_parse() look heavy to you?

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

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

On 8/29/06, Bruce Momjian <bruce(at)momjian(dot)us> wrote:
> DETAIL: prepare: SELECT $1; bind: $1 = 'a''b'

I attached a trivial patch to add a dash between the prepare part and
the bind part. People usually don't finish their queries with a semi
colon so it's more readable with a separator.
DETAIL: prepare: SELECT $1 bind: $1 = 'a''b'
becomes
DETAIL: prepare: SELECT $1 - bind: $1 = 'a''b'

--
Guillaume

Guillaume Smet wrote:
> On 8/29/06, Bruce Momjian <bruce(at)momjian(dot)us> wrote:
> > DETAIL: prepare: SELECT $1; bind: $1 = 'a''b'
>
> I attached a trivial patch to add a dash between the prepare part and
> the bind part. People usually don't finish their queries with a semi
> colon so it's more readable with a separator.
> DETAIL: prepare: SELECT $1 bind: $1 = 'a''b'
> becomes
> DETAIL: prepare: SELECT $1 - bind: $1 = 'a''b'

Good point. I thought it was clear enough, but obviously not. I had a
similar case with bind, and used a comma to separate them:

LOG: statement: prepare sel1, SELECT $1;
LOG: statement: bind sel1, $1 = 'a''b'

I am concerned a dash isn't clear enough, and a semicolon is confusing.
Using a comma the new output is:

LOG: duration: 0.023 ms execute sel1
DETAIL: prepare: SELECT $1;, bind: $1 = 'a''b'

or with no semicolon:

LOG: duration: 0.023 ms execute sel1
DETAIL: prepare: SELECT $1, bind: $1 = 'a''b'

Is that OK? Patch attached and committed. I also fixed the null bind
parameter bug. It now displays $1 = NULL (no quotes used). Other
suggestions?

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

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

On 8/29/06, Bruce Momjian <bruce(at)momjian(dot)us> wrote:
> Good point. I thought it was clear enough, but obviously not. I had a
> similar case with bind, and used a comma to separate them:
>
> LOG: statement: prepare sel1, SELECT $1;
> LOG: statement: bind sel1, $1 = 'a''b'

For this one, I must admit I prefer the colon we used before.
Something like:
LOG: statement: prepare sel1: SELECT $1;
LOG: statement: bind sel1: $1 = 'a''b'
seems better to me as after the colon, we have the details of the
command which is the common sense of a colon.

> I am concerned a dash isn't clear enough, and a semicolon is confusing.
> Using a comma the new output is:
>
> LOG: duration: 0.023 ms execute sel1
> DETAIL: prepare: SELECT $1;, bind: $1 = 'a''b'

A dash is clearer in this case IMHO. ;, is not very readable. But I
can parse easily both forms so it's not a problem for me if you prefer
a comma.

> Is that OK? Patch attached and committed. I also fixed the null bind
> parameter bug. It now displays $1 = NULL (no quotes used).

Cool. I'll test that.

> Other suggestions?

I'll compile this new version and make tests in the next few days to
check everything is consistent and let you know.

I'm still struggling to find a regexp good enough to parse "statement:
execute y ('a', 4, 'text, with a comma'::text);" :).

Thanks a lot for your work on this subject. It will help us a lot when
we use the JDBC driver.

--
Guillaume

Guillaume Smet wrote:
> On 8/29/06, Bruce Momjian <bruce(at)momjian(dot)us> wrote:
> > Good point. I thought it was clear enough, but obviously not. I had a
> > similar case with bind, and used a comma to separate them:
> >
> > LOG: statement: prepare sel1, SELECT $1;
> > LOG: statement: bind sel1, $1 = 'a''b'
>
> For this one, I must admit I prefer the colon we used before.
> Something like:
> LOG: statement: prepare sel1: SELECT $1;
> LOG: statement: bind sel1: $1 = 'a''b'
> seems better to me as after the colon, we have the details of the
> command which is the common sense of a colon.

OK, done.

> > I am concerned a dash isn't clear enough, and a semicolon is confusing.
> > Using a comma the new output is:
> >
> > LOG: duration: 0.023 ms execute sel1
> > DETAIL: prepare: SELECT $1;, bind: $1 = 'a''b'
>
> A dash is clearer in this case IMHO. ;, is not very readable. But I
> can parse easily both forms so it's not a problem for me if you prefer
> a comma.

I thought about this, and because we are placing two pieces of
information on the same line, it seems "|" is the best choice.

> > Is that OK? Patch attached and committed. I also fixed the null bind
> > parameter bug. It now displays $1 = NULL (no quotes used).
>
> Cool. I'll test that.
>
> > Other suggestions?
>
> I'll compile this new version and make tests in the next few days to
> check everything is consistent and let you know.
>
> I'm still struggling to find a regexp good enough to parse "statement:
> execute y ('a', 4, 'text, with a comma'::text);" :).

Oh. You want to pull the parameters out of that. I am thinking you
need something that will go over the line character by character with
some type of state machine, rather than just regex.

> Thanks a lot for your work on this subject. It will help us a lot when
> we use the JDBC driver.

Patch attached and applied. New output:

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;
LOG: statement: set log_statement = 'none';
LOG: duration: 0.222 ms statement: set log_min_duration_statement = 0;
LOG: duration: 0.061 ms statement: begin;
LOG: duration: 0.113 ms statement: prepare y as select $1::text;
LOG: duration: 0.213 ms statement: execute y ('a');
DETAIL: prepare: prepare y as select $1::text;
LOG: duration: 0.081 ms statement: commit;
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'
LOG: duration: 0.445 ms statement: SET log_min_duration_statement = 0;
LOG: duration: 0.018 ms execute sel1
DETAIL: prepare: SELECT $1; | bind: $1 = 'a''b'

Additional comments?

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

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

On 8/30/06, Bruce Momjian <bruce(at)momjian(dot)us> wrote:
> I thought about this, and because we are placing two pieces of
> information on the same line, it seems "|" is the best choice.

Good idea. It's far more readable with a pipe.

> Oh. You want to pull the parameters out of that. I am thinking you
> need something that will go over the line character by character with
> some type of state machine, rather than just regex.

Yes, that's what I did but I usually prefer a regex.

> Additional comments?

I confirm it now works with NULL. I'm just wondering if the notation
is really consistent:
$result = pg_execute($dbconn, "insert_query", array(null));
gives:
DETAIL: prepare: INSERT INTO shop (name) VALUES($1) | bind: $1 = NULL
However:
$result = pg_execute($dbconn, "insert_query", array(4));
gives:
DETAIL: prepare: INSERT INTO shop (name) VALUES($1) | bind: $1 = '4'

But I don't think it's possible to have 4 in this case. Can you confirm?

I have all the different cases parsed correctly by my parser and I can
build the query from the logs so it's OK for me. In the above case,
with an int, I remove the quotes if the content is numeric. It's not
perfect but I suppose it will be OK most of the time.

--
Guillaume

Guillaume Smet wrote:
> On 8/30/06, Bruce Momjian <bruce(at)momjian(dot)us> wrote:
> > I thought about this, and because we are placing two pieces of
> > information on the same line, it seems "|" is the best choice.
>
> Good idea. It's far more readable with a pipe.
>
> > Oh. You want to pull the parameters out of that. I am thinking you
> > need something that will go over the line character by character with
> > some type of state machine, rather than just regex.
>
> Yes, that's what I did but I usually prefer a regex.
>
> > Additional comments?
>
> I confirm it now works with NULL. I'm just wondering if the notation
> is really consistent:
> $result = pg_execute($dbconn, "insert_query", array(null));
> gives:
> DETAIL: prepare: INSERT INTO shop (name) VALUES($1) | bind: $1 = NULL
> However:
> $result = pg_execute($dbconn, "insert_query", array(4));
> gives:
> DETAIL: prepare: INSERT INTO shop (name) VALUES($1) | bind: $1 = '4'
>
> But I don't think it's possible to have 4 in this case. Can you confirm?

All supplied parameters have single quotes around them. Only NULL doesn't.

> I have all the different cases parsed correctly by my parser and I can
> build the query from the logs so it's OK for me. In the above case,
> with an int, I remove the quotes if the content is numeric. It's not
> perfect but I suppose it will be OK most of the time.

Well, the parameter is supplied as text, so I always quote it in the
logs.

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

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