Re: PGStatement#setPrepareThreshold
bruce wrote:
Tom Lane wrote:
Bruce Momjian <bruce@momjian.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@momjian.us
EnterpriseDB http://www.enterprisedb.com
+ If your life is a hard drive, Christ can be your backup. +
Attachments:
/bjm/difftext/x-diffDownload+18-18
Import Notes
Reply to msg id not found:
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:
Show quoted text
bruce wrote:
Tom Lane wrote:
Bruce Momjian <bruce@momjian.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@momjian.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@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? MaybeLOG: 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? MaybeLOG: 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. +
Sorry, this is the right patch.
---------------------------------------------------------------------------
bruce wrote:
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? MaybeLOG: 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. +
Attachments:
/pgpatches/preparetext/x-diffDownload+29-20
Import Notes
Reply to msg id not found: | Resolved by subject fallback
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
Bruce,
Am I missing something or this patch doesn't implement the logging of
the parameters? Do you think it will be possible to have it for 8.2?
I must admit I'd really like to be able to parse the prepared
statements log output as currently it's impossible to rebuild the
complete queries from the log file when people use parameterized
queries (which is now the default with the JDBC driver).
--
Guillaume
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. +
Attachments:
/pgpatches/preparetext/x-diffDownload+35-26
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. +
Attachments:
/pgpatches/preparetext/plainDownload+66-35
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. +