Re: PGStatement#setPrepareThreshold

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:

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@momjian.us
EnterpriseDB http://www.enterprisedb.com

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

Bruce Momjian <bruce@momjian.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@momjian.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@momjian.us
EnterpriseDB http://www.enterprisedb.com

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

Bruce Momjian <bruce@momjian.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@momjian.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@momjian.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@momjian.us
EnterpriseDB http://www.enterprisedb.com

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

Bruce Momjian <bruce@momjian.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@momjian.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@momjian.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@momjian.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@momjian.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@momjian.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@fetter.org> http://fetter.org/
phone: +1 415 235 3778 AIM: dfetter666
Skype: davidfetter

Remember to vote!

Oliver Jowett <oliver@opencloud.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@opencloud.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@momjian.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@opencloud.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@momjian.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@opencloud.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@momjian.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@opencloud.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@momjian.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@momjian.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@momjian.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@momjian.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@momjian.us
EnterpriseDB http://www.enterprisedb.com

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