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
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 : "")));
}
}
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. +
Attachments:
/pgpatches/preparetext/x-diffDownload
Index: src/backend/commands/portalcmds.c
===================================================================
RCS file: /cvsroot/pgsql/src/backend/commands/portalcmds.c,v
retrieving revision 1.48
diff -c -c -r1.48 portalcmds.c
*** src/backend/commands/portalcmds.c 13 Jul 2006 16:49:14 -0000 1.48
--- src/backend/commands/portalcmds.c 4 Aug 2006 22:22:19 -0000
***************
*** 112,117 ****
--- 112,118 ----
* submitted more than one semicolon delimited queries.
*/
PortalDefineQuery(portal,
+ "",
pstrdup(debug_query_string),
"SELECT", /* cursor's query is always a SELECT */
list_make1(query),
Index: src/backend/commands/prepare.c
===================================================================
RCS file: /cvsroot/pgsql/src/backend/commands/prepare.c,v
retrieving revision 1.58
diff -c -c -r1.58 prepare.c
*** src/backend/commands/prepare.c 14 Jul 2006 14:52:18 -0000 1.58
--- src/backend/commands/prepare.c 4 Aug 2006 22:22:19 -0000
***************
*** 201,206 ****
--- 201,207 ----
}
PortalDefineQuery(portal,
+ "",
query_string,
entry->commandTag,
query_list,
Index: src/backend/executor/spi.c
===================================================================
RCS file: /cvsroot/pgsql/src/backend/executor/spi.c,v
retrieving revision 1.152
diff -c -c -r1.152 spi.c
*** src/backend/executor/spi.c 14 Jul 2006 14:52:19 -0000 1.152
--- src/backend/executor/spi.c 4 Aug 2006 22:22:19 -0000
***************
*** 919,924 ****
--- 919,925 ----
* Set up the portal.
*/
PortalDefineQuery(portal,
+ "",
spiplan->query,
"SELECT", /* don't have the raw parse tree... */
list_make1(queryTree),
Index: src/backend/tcop/postgres.c
===================================================================
RCS file: /cvsroot/pgsql/src/backend/tcop/postgres.c,v
retrieving revision 1.494
diff -c -c -r1.494 postgres.c
*** src/backend/tcop/postgres.c 4 Aug 2006 18:53:46 -0000 1.494
--- src/backend/tcop/postgres.c 4 Aug 2006 22:22:21 -0000
***************
*** 955,960 ****
--- 955,961 ----
portal->visible = false;
PortalDefineQuery(portal,
+ "",
query_string,
commandTag,
querytree_list,
***************
*** 1146,1152 ****
if (log_statement == LOGSTMT_ALL)
ereport(LOG,
! (errmsg("statement: <protocol> PREPARE %s AS %s",
*stmt_name ? stmt_name : "<unnamed>",
query_string)));
--- 1147,1153 ----
if (log_statement == LOGSTMT_ALL)
ereport(LOG,
! (errmsg("statement protocol prepare %s: %s",
*stmt_name ? stmt_name : "<unnamed>",
query_string)));
***************
*** 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.
--- 1453,1461 ----
/* We need to output the parameter values someday */
if (log_statement == LOGSTMT_ALL)
ereport(LOG,
! (errmsg("statement protocol bind %s: %s",
! *stmt_name ? stmt_name : "<unnamed>",
! pstmt->query_string ? pstmt->query_string : "")));
/*
* Fetch parameters, if any, and store in the portal's memory context.
***************
*** 1624,1629 ****
--- 1625,1631 ----
* Define portal and start execution.
*/
PortalDefineQuery(portal,
+ pstrdup(stmt_name),
pstmt->query_string,
pstmt->commandTag,
pstmt->query_list,
***************
*** 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);
--- 1722,1730 ----
if (log_statement == LOGSTMT_ALL)
/* We have the portal, so output the source query. */
ereport(LOG,
! (errmsg("statement protocol execute %s%s: %s",
! execute_is_fetch ? "fetch from " : "",
! *portal->prepStmtName ? portal->prepStmtName : "<unnamed>",
portal->sourceText ? portal->sourceText : "")));
BeginCommand(portal->commandTag, dest);
***************
*** 1828,1837 ****
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 : "")));
}
}
--- 1830,1839 ----
secs, msecs)));
else
ereport(LOG,
! (errmsg("duration: %ld.%03d ms statement protocol execute %s%s: %s",
secs, msecs,
! execute_is_fetch ? "fetch from " : "",
! *portal->prepStmtName ? portal->prepStmtName : "<unnamed>",
portal->sourceText ? portal->sourceText : "")));
}
}
Index: src/backend/utils/mmgr/portalmem.c
===================================================================
RCS file: /cvsroot/pgsql/src/backend/utils/mmgr/portalmem.c,v
retrieving revision 1.90
diff -c -c -r1.90 portalmem.c
*** src/backend/utils/mmgr/portalmem.c 14 Jul 2006 14:52:25 -0000 1.90
--- src/backend/utils/mmgr/portalmem.c 4 Aug 2006 22:22:21 -0000
***************
*** 244,249 ****
--- 244,250 ----
*/
void
PortalDefineQuery(Portal portal,
+ const char *prepStmtName,
const char *sourceText,
const char *commandTag,
List *parseTrees,
***************
*** 257,262 ****
--- 258,264 ----
Assert(commandTag != NULL || parseTrees == NIL);
+ portal->prepStmtName = pstrdup(prepStmtName);
portal->sourceText = sourceText;
portal->commandTag = commandTag;
portal->parseTrees = parseTrees;
Index: src/include/utils/portal.h
===================================================================
RCS file: /cvsroot/pgsql/src/include/utils/portal.h,v
retrieving revision 1.63
diff -c -c -r1.63 portal.h
*** src/include/utils/portal.h 13 Jul 2006 18:01:02 -0000 1.63
--- src/include/utils/portal.h 4 Aug 2006 22:22:22 -0000
***************
*** 100,105 ****
--- 100,106 ----
{
/* Bookkeeping data */
const char *name; /* portal's name */
+ const char *prepStmtName; /* protocol prepare name */
MemoryContext heap; /* subsidiary memory for portal */
ResourceOwner resowner; /* resources owned by portal */
void (*cleanup) (Portal portal); /* cleanup hook */
***************
*** 202,207 ****
--- 203,209 ----
extern void DropDependentPortals(MemoryContext queryContext);
extern Portal GetPortalByName(const char *name);
extern void PortalDefineQuery(Portal portal,
+ const char *prepStmtName,
const char *sourceText,
const char *commandTag,
List *parseTrees,
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. +
Attachments:
/pgpatches/preparetext/x-diffDownload
Index: src/backend/commands/portalcmds.c
===================================================================
RCS file: /cvsroot/pgsql/src/backend/commands/portalcmds.c,v
retrieving revision 1.48
diff -c -c -r1.48 portalcmds.c
*** src/backend/commands/portalcmds.c 13 Jul 2006 16:49:14 -0000 1.48
--- src/backend/commands/portalcmds.c 5 Aug 2006 03:59:09 -0000
***************
*** 112,117 ****
--- 112,118 ----
* submitted more than one semicolon delimited queries.
*/
PortalDefineQuery(portal,
+ NULL,
pstrdup(debug_query_string),
"SELECT", /* cursor's query is always a SELECT */
list_make1(query),
Index: src/backend/commands/prepare.c
===================================================================
RCS file: /cvsroot/pgsql/src/backend/commands/prepare.c,v
retrieving revision 1.58
diff -c -c -r1.58 prepare.c
*** src/backend/commands/prepare.c 14 Jul 2006 14:52:18 -0000 1.58
--- src/backend/commands/prepare.c 5 Aug 2006 03:59:09 -0000
***************
*** 201,206 ****
--- 201,207 ----
}
PortalDefineQuery(portal,
+ NULL,
query_string,
entry->commandTag,
query_list,
Index: src/backend/executor/spi.c
===================================================================
RCS file: /cvsroot/pgsql/src/backend/executor/spi.c,v
retrieving revision 1.152
diff -c -c -r1.152 spi.c
*** src/backend/executor/spi.c 14 Jul 2006 14:52:19 -0000 1.152
--- src/backend/executor/spi.c 5 Aug 2006 03:59:09 -0000
***************
*** 919,924 ****
--- 919,925 ----
* Set up the portal.
*/
PortalDefineQuery(portal,
+ NULL,
spiplan->query,
"SELECT", /* don't have the raw parse tree... */
list_make1(queryTree),
Index: src/backend/tcop/postgres.c
===================================================================
RCS file: /cvsroot/pgsql/src/backend/tcop/postgres.c,v
retrieving revision 1.494
diff -c -c -r1.494 postgres.c
*** src/backend/tcop/postgres.c 4 Aug 2006 18:53:46 -0000 1.494
--- src/backend/tcop/postgres.c 5 Aug 2006 03:59:10 -0000
***************
*** 955,960 ****
--- 955,961 ----
portal->visible = false;
PortalDefineQuery(portal,
+ NULL,
query_string,
commandTag,
querytree_list,
***************
*** 1146,1152 ****
if (log_statement == LOGSTMT_ALL)
ereport(LOG,
! (errmsg("statement: <protocol> PREPARE %s AS %s",
*stmt_name ? stmt_name : "<unnamed>",
query_string)));
--- 1147,1153 ----
if (log_statement == LOGSTMT_ALL)
ereport(LOG,
! (errmsg("prepare %s: %s",
*stmt_name ? stmt_name : "<unnamed>",
query_string)));
***************
*** 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.
--- 1453,1463 ----
/* We need to output the parameter values someday */
if (log_statement == LOGSTMT_ALL)
ereport(LOG,
! (errmsg("bind %s%s%s: %s",
! *stmt_name ? stmt_name : "<unnamed>",
! *portal->name ? "/" : "",
! *portal->name ? portal->name : "",
! pstmt->query_string ? pstmt->query_string : "")));
/*
* Fetch parameters, if any, and store in the portal's memory context.
***************
*** 1624,1629 ****
--- 1627,1633 ----
* Define portal and start execution.
*/
PortalDefineQuery(portal,
+ *stmt_name ? pstrdup(stmt_name) : NULL,
pstmt->query_string,
pstmt->commandTag,
pstmt->query_list,
***************
*** 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);
--- 1724,1734 ----
if (log_statement == LOGSTMT_ALL)
/* We have the portal, so output the source query. */
ereport(LOG,
! (errmsg("execute %s%s%s%s: %s",
! execute_is_fetch ? "fetch from " : "",
! portal->prepStmtName ? portal->prepStmtName : "<unnamed>",
! *portal->name ? "/" : "",
! *portal->name ? portal->name : "",
portal->sourceText ? portal->sourceText : "")));
BeginCommand(portal->commandTag, dest);
***************
*** 1828,1837 ****
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 : "")));
}
}
--- 1834,1845 ----
secs, msecs)));
else
ereport(LOG,
! (errmsg("duration: %ld.%03d ms execute %s%s%s%s: %s",
secs, msecs,
! execute_is_fetch ? "fetch from " : "",
! portal->prepStmtName ? portal->prepStmtName : "<unnamed>",
! *portal->name ? "/" : "",
! *portal->name ? portal->name : "",
portal->sourceText ? portal->sourceText : "")));
}
}
Index: src/backend/utils/mmgr/portalmem.c
===================================================================
RCS file: /cvsroot/pgsql/src/backend/utils/mmgr/portalmem.c,v
retrieving revision 1.90
diff -c -c -r1.90 portalmem.c
*** src/backend/utils/mmgr/portalmem.c 14 Jul 2006 14:52:25 -0000 1.90
--- src/backend/utils/mmgr/portalmem.c 5 Aug 2006 03:59:11 -0000
***************
*** 244,249 ****
--- 244,250 ----
*/
void
PortalDefineQuery(Portal portal,
+ const char *prepStmtName,
const char *sourceText,
const char *commandTag,
List *parseTrees,
***************
*** 257,262 ****
--- 258,264 ----
Assert(commandTag != NULL || parseTrees == NIL);
+ portal->prepStmtName = prepStmtName;
portal->sourceText = sourceText;
portal->commandTag = commandTag;
portal->parseTrees = parseTrees;
Index: src/include/utils/portal.h
===================================================================
RCS file: /cvsroot/pgsql/src/include/utils/portal.h,v
retrieving revision 1.63
diff -c -c -r1.63 portal.h
*** src/include/utils/portal.h 13 Jul 2006 18:01:02 -0000 1.63
--- src/include/utils/portal.h 5 Aug 2006 03:59:11 -0000
***************
*** 100,105 ****
--- 100,106 ----
{
/* Bookkeeping data */
const char *name; /* portal's name */
+ const char *prepStmtName; /* protocol prepare name */
MemoryContext heap; /* subsidiary memory for portal */
ResourceOwner resowner; /* resources owned by portal */
void (*cleanup) (Portal portal); /* cleanup hook */
***************
*** 202,207 ****
--- 203,209 ----
extern void DropDependentPortals(MemoryContext queryContext);
extern Portal GetPortalByName(const char *name);
extern void PortalDefineQuery(Portal portal,
+ const char *prepStmtName,
const char *sourceText,
const char *commandTag,
List *parseTrees,
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. +
Attachments:
/pgpatches/preparetext/x-diffDownload
Index: doc/src/sgml/config.sgml
===================================================================
RCS file: /cvsroot/pgsql/doc/src/sgml/config.sgml,v
retrieving revision 1.71
diff -c -c -r1.71 config.sgml
*** doc/src/sgml/config.sgml 27 Jul 2006 08:30:41 -0000 1.71
--- doc/src/sgml/config.sgml 5 Aug 2006 04:55:50 -0000
***************
*** 2808,2814 ****
<literal>UPDATE</>, <literal>DELETE</>, <literal>TRUNCATE</>,
and <literal>COPY FROM</>. <literal>PREPARE</> and
<literal>EXPLAIN ANALYZE</> statements are also logged if their
! contained command is of an appropriate type.
</para>
<para>
The default is <literal>none</>. Only superusers can change this
--- 2808,2818 ----
<literal>UPDATE</>, <literal>DELETE</>, <literal>TRUNCATE</>,
and <literal>COPY FROM</>. <literal>PREPARE</> and
<literal>EXPLAIN ANALYZE</> statements are also logged if their
! contained command is of an appropriate type. Protocol-level
! prepare, bind, and execute commands are logged only if
! <varname>log_statement</> is <literal>all</>. Bind parameter
! values are also logged if they are supplied in <literal>text</>
! format.
</para>
<para>
The default is <literal>none</>. Only superusers can change this
Index: src/backend/commands/portalcmds.c
===================================================================
RCS file: /cvsroot/pgsql/src/backend/commands/portalcmds.c,v
retrieving revision 1.48
diff -c -c -r1.48 portalcmds.c
*** src/backend/commands/portalcmds.c 13 Jul 2006 16:49:14 -0000 1.48
--- src/backend/commands/portalcmds.c 5 Aug 2006 04:55:50 -0000
***************
*** 112,117 ****
--- 112,118 ----
* submitted more than one semicolon delimited queries.
*/
PortalDefineQuery(portal,
+ NULL,
pstrdup(debug_query_string),
"SELECT", /* cursor's query is always a SELECT */
list_make1(query),
Index: src/backend/commands/prepare.c
===================================================================
RCS file: /cvsroot/pgsql/src/backend/commands/prepare.c,v
retrieving revision 1.58
diff -c -c -r1.58 prepare.c
*** src/backend/commands/prepare.c 14 Jul 2006 14:52:18 -0000 1.58
--- src/backend/commands/prepare.c 5 Aug 2006 04:55:51 -0000
***************
*** 201,206 ****
--- 201,207 ----
}
PortalDefineQuery(portal,
+ NULL,
query_string,
entry->commandTag,
query_list,
Index: src/backend/executor/spi.c
===================================================================
RCS file: /cvsroot/pgsql/src/backend/executor/spi.c,v
retrieving revision 1.152
diff -c -c -r1.152 spi.c
*** src/backend/executor/spi.c 14 Jul 2006 14:52:19 -0000 1.152
--- src/backend/executor/spi.c 5 Aug 2006 04:55:51 -0000
***************
*** 919,924 ****
--- 919,925 ----
* Set up the portal.
*/
PortalDefineQuery(portal,
+ NULL,
spiplan->query,
"SELECT", /* don't have the raw parse tree... */
list_make1(queryTree),
Index: src/backend/tcop/postgres.c
===================================================================
RCS file: /cvsroot/pgsql/src/backend/tcop/postgres.c,v
retrieving revision 1.494
diff -c -c -r1.494 postgres.c
*** src/backend/tcop/postgres.c 4 Aug 2006 18:53:46 -0000 1.494
--- src/backend/tcop/postgres.c 5 Aug 2006 04:55:52 -0000
***************
*** 955,960 ****
--- 955,961 ----
portal->visible = false;
PortalDefineQuery(portal,
+ NULL,
query_string,
commandTag,
querytree_list,
***************
*** 1146,1152 ****
if (log_statement == LOGSTMT_ALL)
ereport(LOG,
! (errmsg("statement: <protocol> PREPARE %s AS %s",
*stmt_name ? stmt_name : "<unnamed>",
query_string)));
--- 1147,1153 ----
if (log_statement == LOGSTMT_ALL)
ereport(LOG,
! (errmsg("prepare %s: %s",
*stmt_name ? stmt_name : "<unnamed>",
query_string)));
***************
*** 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.
--- 1453,1463 ----
/* We need to output the parameter values someday */
if (log_statement == LOGSTMT_ALL)
ereport(LOG,
! (errmsg("bind %s%s%s: %s",
! *stmt_name ? stmt_name : "<unnamed>",
! *portal->name ? "/" : "",
! *portal->name ? portal->name : "",
! pstmt->query_string ? pstmt->query_string : "")));
/*
* Fetch parameters, if any, and store in the portal's memory context.
***************
*** 1517,1523 ****
else
pformat = 0; /* default = text */
! if (pformat == 0)
{
Oid typinput;
Oid typioparam;
--- 1520,1526 ----
else
pformat = 0; /* default = text */
! if (pformat == 0) /* text mode */
{
Oid typinput;
Oid typioparam;
***************
*** 1538,1548 ****
pstring,
typioparam,
-1);
/* Free result of encoding conversion, if any */
if (pstring && pstring != pbuf.data)
pfree(pstring);
}
! else if (pformat == 1)
{
Oid typreceive;
Oid typioparam;
--- 1541,1559 ----
pstring,
typioparam,
-1);
+
+ if (log_statement == LOGSTMT_ALL)
+ ereport(LOG,
+ (errmsg("bind %s%s%s: parameter %d: \"%s\"",
+ *stmt_name ? stmt_name : "<unnamed>",
+ *portal->name ? "/" : "",
+ *portal->name ? portal->name : "", i + 1, pstring)));
+
/* Free result of encoding conversion, if any */
if (pstring && pstring != pbuf.data)
pfree(pstring);
}
! else if (pformat == 1) /* binary mode */
{
Oid typreceive;
Oid typioparam;
***************
*** 1624,1629 ****
--- 1635,1641 ----
* Define portal and start execution.
*/
PortalDefineQuery(portal,
+ *stmt_name ? pstrdup(stmt_name) : NULL,
pstmt->query_string,
pstmt->commandTag,
pstmt->query_list,
***************
*** 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);
--- 1732,1742 ----
if (log_statement == LOGSTMT_ALL)
/* We have the portal, so output the source query. */
ereport(LOG,
! (errmsg("execute %s%s%s%s: %s",
! execute_is_fetch ? "fetch from " : "",
! portal->prepStmtName ? portal->prepStmtName : "<unnamed>",
! *portal->name ? "/" : "",
! *portal->name ? portal->name : "",
portal->sourceText ? portal->sourceText : "")));
BeginCommand(portal->commandTag, dest);
***************
*** 1828,1837 ****
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 : "")));
}
}
--- 1842,1853 ----
secs, msecs)));
else
ereport(LOG,
! (errmsg("duration: %ld.%03d ms execute %s%s%s%s: %s",
secs, msecs,
! execute_is_fetch ? "fetch from " : "",
! portal->prepStmtName ? portal->prepStmtName : "<unnamed>",
! *portal->name ? "/" : "",
! *portal->name ? portal->name : "",
portal->sourceText ? portal->sourceText : "")));
}
}
Index: src/backend/utils/mmgr/portalmem.c
===================================================================
RCS file: /cvsroot/pgsql/src/backend/utils/mmgr/portalmem.c,v
retrieving revision 1.90
diff -c -c -r1.90 portalmem.c
*** src/backend/utils/mmgr/portalmem.c 14 Jul 2006 14:52:25 -0000 1.90
--- src/backend/utils/mmgr/portalmem.c 5 Aug 2006 04:55:53 -0000
***************
*** 244,249 ****
--- 244,250 ----
*/
void
PortalDefineQuery(Portal portal,
+ const char *prepStmtName,
const char *sourceText,
const char *commandTag,
List *parseTrees,
***************
*** 257,262 ****
--- 258,264 ----
Assert(commandTag != NULL || parseTrees == NIL);
+ portal->prepStmtName = prepStmtName;
portal->sourceText = sourceText;
portal->commandTag = commandTag;
portal->parseTrees = parseTrees;
Index: src/include/utils/portal.h
===================================================================
RCS file: /cvsroot/pgsql/src/include/utils/portal.h,v
retrieving revision 1.63
diff -c -c -r1.63 portal.h
*** src/include/utils/portal.h 13 Jul 2006 18:01:02 -0000 1.63
--- src/include/utils/portal.h 5 Aug 2006 04:55:54 -0000
***************
*** 100,105 ****
--- 100,106 ----
{
/* Bookkeeping data */
const char *name; /* portal's name */
+ const char *prepStmtName; /* protocol prepare name */
MemoryContext heap; /* subsidiary memory for portal */
ResourceOwner resowner; /* resources owned by portal */
void (*cleanup) (Portal portal); /* cleanup hook */
***************
*** 202,207 ****
--- 203,209 ----
extern void DropDependentPortals(MemoryContext queryContext);
extern Portal GetPortalByName(const char *name);
extern void PortalDefineQuery(Portal portal,
+ const char *prepStmtName,
const char *sourceText,
const char *commandTag,
List *parseTrees,
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
Index: doc/src/sgml/config.sgml
===================================================================
RCS file: /cvsroot/pgsql/doc/src/sgml/config.sgml,v
retrieving revision 1.71
diff -c -c -r1.71 config.sgml
*** doc/src/sgml/config.sgml 27 Jul 2006 08:30:41 -0000 1.71
--- doc/src/sgml/config.sgml 7 Aug 2006 03:44:47 -0000
***************
*** 2808,2814 ****
<literal>UPDATE</>, <literal>DELETE</>, <literal>TRUNCATE</>,
and <literal>COPY FROM</>. <literal>PREPARE</> and
<literal>EXPLAIN ANALYZE</> statements are also logged if their
! contained command is of an appropriate type.
</para>
<para>
The default is <literal>none</>. Only superusers can change this
--- 2808,2818 ----
<literal>UPDATE</>, <literal>DELETE</>, <literal>TRUNCATE</>,
and <literal>COPY FROM</>. <literal>PREPARE</> and
<literal>EXPLAIN ANALYZE</> statements are also logged if their
! contained command is of an appropriate type. Protocol-level
! prepare, bind, and execute commands are logged only if
! <varname>log_statement</> is <literal>all</>. Bind parameter
! values are also logged if they are supplied in <literal>text</>
! format.
</para>
<para>
The default is <literal>none</>. Only superusers can change this
Index: src/backend/commands/portalcmds.c
===================================================================
RCS file: /cvsroot/pgsql/src/backend/commands/portalcmds.c,v
retrieving revision 1.48
diff -c -c -r1.48 portalcmds.c
*** src/backend/commands/portalcmds.c 13 Jul 2006 16:49:14 -0000 1.48
--- src/backend/commands/portalcmds.c 7 Aug 2006 03:44:47 -0000
***************
*** 112,117 ****
--- 112,118 ----
* submitted more than one semicolon delimited queries.
*/
PortalDefineQuery(portal,
+ NULL,
pstrdup(debug_query_string),
"SELECT", /* cursor's query is always a SELECT */
list_make1(query),
Index: src/backend/commands/prepare.c
===================================================================
RCS file: /cvsroot/pgsql/src/backend/commands/prepare.c,v
retrieving revision 1.58
diff -c -c -r1.58 prepare.c
*** src/backend/commands/prepare.c 14 Jul 2006 14:52:18 -0000 1.58
--- src/backend/commands/prepare.c 7 Aug 2006 03:44:47 -0000
***************
*** 201,206 ****
--- 201,207 ----
}
PortalDefineQuery(portal,
+ NULL,
query_string,
entry->commandTag,
query_list,
Index: src/backend/executor/spi.c
===================================================================
RCS file: /cvsroot/pgsql/src/backend/executor/spi.c,v
retrieving revision 1.152
diff -c -c -r1.152 spi.c
*** src/backend/executor/spi.c 14 Jul 2006 14:52:19 -0000 1.152
--- src/backend/executor/spi.c 7 Aug 2006 03:44:48 -0000
***************
*** 919,924 ****
--- 919,925 ----
* Set up the portal.
*/
PortalDefineQuery(portal,
+ NULL,
spiplan->query,
"SELECT", /* don't have the raw parse tree... */
list_make1(queryTree),
Index: src/backend/tcop/postgres.c
===================================================================
RCS file: /cvsroot/pgsql/src/backend/tcop/postgres.c,v
retrieving revision 1.495
diff -c -c -r1.495 postgres.c
*** src/backend/tcop/postgres.c 6 Aug 2006 02:00:52 -0000 1.495
--- src/backend/tcop/postgres.c 7 Aug 2006 03:44:49 -0000
***************
*** 955,960 ****
--- 955,961 ----
portal->visible = false;
PortalDefineQuery(portal,
+ NULL,
query_string,
commandTag,
querytree_list,
***************
*** 1146,1152 ****
if (log_statement == LOGSTMT_ALL)
ereport(LOG,
! (errmsg("statement: <protocol> PREPARE %s AS %s",
*stmt_name ? stmt_name : "<unnamed>",
query_string)));
--- 1147,1153 ----
if (log_statement == LOGSTMT_ALL)
ereport(LOG,
! (errmsg("prepare %s: %s",
*stmt_name ? stmt_name : "<unnamed>",
query_string)));
***************
*** 1367,1372 ****
--- 1368,1374 ----
PreparedStatement *pstmt;
Portal portal;
ParamListInfo params;
+ StringInfoData str;
pgstat_report_activity("<BIND>");
***************
*** 1382,1387 ****
--- 1384,1392 ----
/* Switch back to message context */
MemoryContextSwitchTo(MessageContext);
+ if (log_statement == LOGSTMT_ALL)
+ initStringInfo(&str);
+
/* Get the fixed part of the message */
portal_name = pq_getmsgstring(input_message);
stmt_name = pq_getmsgstring(input_message);
***************
*** 1450,1462 ****
else
portal = CreatePortal(portal_name, false, false);
- /* 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.
*/
--- 1455,1460 ----
***************
*** 1519,1525 ****
else
pformat = 0; /* default = text */
! if (pformat == 0)
{
Oid typinput;
Oid typioparam;
--- 1517,1523 ----
else
pformat = 0; /* default = text */
! if (pformat == 0) /* text mode */
{
Oid typinput;
Oid typioparam;
***************
*** 1540,1550 ****
pstring,
typioparam,
-1);
/* Free result of encoding conversion, if any */
if (pstring && pstring != pbuf.data)
pfree(pstring);
}
! else if (pformat == 1)
{
Oid typreceive;
Oid typioparam;
--- 1538,1553 ----
pstring,
typioparam,
-1);
+
+ if (log_statement == LOGSTMT_ALL)
+ appendStringInfo(&str, "%s$%d = \"%s\"",
+ *str.data ? ", " : "", paramno + 1, pstring);
+
/* Free result of encoding conversion, if any */
if (pstring && pstring != pbuf.data)
pfree(pstring);
}
! else if (pformat == 1) /* binary mode */
{
Oid typreceive;
Oid typioparam;
***************
*** 1595,1600 ****
--- 1598,1623 ----
else
params = NULL;
+ if (log_statement == LOGSTMT_ALL)
+ {
+ if (*str.data)
+ ereport(LOG,
+ (errmsg("bind %s%s%s: %s",
+ *stmt_name ? stmt_name : "<unnamed>",
+ *portal->name ? "/" : "",
+ *portal->name ? portal->name : "",
+ pstmt->query_string ? pstmt->query_string : ""),
+ errdetail(str.data)));
+ else
+ ereport(LOG,
+ (errmsg("bind %s%s%s: %s",
+ *stmt_name ? stmt_name : "<unnamed>",
+ *portal->name ? "/" : "",
+ *portal->name ? portal->name : "",
+ pstmt->query_string ? pstmt->query_string : "")));
+ pfree(str.data);
+ }
+
/* Get the result format codes */
numRFormats = pq_getmsgint(input_message, 2);
if (numRFormats > 0)
***************
*** 1628,1633 ****
--- 1651,1657 ----
* Define portal and start execution.
*/
PortalDefineQuery(portal,
+ *stmt_name ? pstrdup(stmt_name) : NULL,
pstmt->query_string,
pstmt->commandTag,
pstmt->query_list,
***************
*** 1724,1732 ****
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);
--- 1748,1758 ----
if (log_statement == LOGSTMT_ALL)
/* We have the portal, so output the source query. */
ereport(LOG,
! (errmsg("execute %s%s%s%s: %s",
! execute_is_fetch ? "fetch from " : "",
! portal->prepStmtName ? portal->prepStmtName : "<unnamed>",
! *portal->name ? "/" : "",
! *portal->name ? portal->name : "",
portal->sourceText ? portal->sourceText : "")));
BeginCommand(portal->commandTag, dest);
***************
*** 1832,1841 ****
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 : "")));
}
}
--- 1858,1869 ----
secs, msecs)));
else
ereport(LOG,
! (errmsg("duration: %ld.%03d ms execute %s%s%s%s: %s",
secs, msecs,
! execute_is_fetch ? "fetch from " : "",
! portal->prepStmtName ? portal->prepStmtName : "<unnamed>",
! *portal->name ? "/" : "",
! *portal->name ? portal->name : "",
portal->sourceText ? portal->sourceText : "")));
}
}
Index: src/backend/utils/mmgr/portalmem.c
===================================================================
RCS file: /cvsroot/pgsql/src/backend/utils/mmgr/portalmem.c,v
retrieving revision 1.90
diff -c -c -r1.90 portalmem.c
*** src/backend/utils/mmgr/portalmem.c 14 Jul 2006 14:52:25 -0000 1.90
--- src/backend/utils/mmgr/portalmem.c 7 Aug 2006 03:44:49 -0000
***************
*** 244,249 ****
--- 244,250 ----
*/
void
PortalDefineQuery(Portal portal,
+ const char *prepStmtName,
const char *sourceText,
const char *commandTag,
List *parseTrees,
***************
*** 257,262 ****
--- 258,264 ----
Assert(commandTag != NULL || parseTrees == NIL);
+ portal->prepStmtName = prepStmtName;
portal->sourceText = sourceText;
portal->commandTag = commandTag;
portal->parseTrees = parseTrees;
Index: src/include/utils/portal.h
===================================================================
RCS file: /cvsroot/pgsql/src/include/utils/portal.h,v
retrieving revision 1.63
diff -c -c -r1.63 portal.h
*** src/include/utils/portal.h 13 Jul 2006 18:01:02 -0000 1.63
--- src/include/utils/portal.h 7 Aug 2006 03:44:50 -0000
***************
*** 100,105 ****
--- 100,106 ----
{
/* Bookkeeping data */
const char *name; /* portal's name */
+ const char *prepStmtName; /* protocol prepare name */
MemoryContext heap; /* subsidiary memory for portal */
ResourceOwner resowner; /* resources owned by portal */
void (*cleanup) (Portal portal); /* cleanup hook */
***************
*** 202,207 ****
--- 203,209 ----
extern void DropDependentPortals(MemoryContext queryContext);
extern Portal GetPortalByName(const char *name);
extern void PortalDefineQuery(Portal portal,
+ const char *prepStmtName,
const char *sourceText,
const char *commandTag,
List *parseTrees,
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. +
Attachments:
/bjm/difftext/x-diffDownload
Index: doc/src/sgml/config.sgml
===================================================================
RCS file: /cvsroot/pgsql/doc/src/sgml/config.sgml,v
retrieving revision 1.75
diff -c -c -r1.75 config.sgml
*** doc/src/sgml/config.sgml 17 Aug 2006 23:04:03 -0000 1.75
--- doc/src/sgml/config.sgml 28 Aug 2006 23:59:41 -0000
***************
*** 2839,2845 ****
prepare, bind, and execute commands are logged only if
<varname>log_statement</> is <literal>all</>. Bind parameter
values are also logged if they are supplied in <literal>text</>
! format.
</para>
<para>
The default is <literal>none</>. Only superusers can change this
--- 2839,2845 ----
prepare, bind, and execute commands are logged only if
<varname>log_statement</> is <literal>all</>. Bind parameter
values are also logged if they are supplied in <literal>text</>
! format (literal single quotes are doubled).
</para>
<para>
The default is <literal>none</>. Only superusers can change this
Index: src/backend/commands/portalcmds.c
===================================================================
RCS file: /cvsroot/pgsql/src/backend/commands/portalcmds.c,v
retrieving revision 1.50
diff -c -c -r1.50 portalcmds.c
*** src/backend/commands/portalcmds.c 12 Aug 2006 20:05:54 -0000 1.50
--- src/backend/commands/portalcmds.c 28 Aug 2006 23:59:42 -0000
***************
*** 114,119 ****
--- 114,120 ----
PortalDefineQuery(portal,
NULL,
pstrdup(debug_query_string),
+ NULL,
"SELECT", /* cursor's query is always a SELECT */
list_make1(query),
list_make1(plan),
Index: src/backend/commands/prepare.c
===================================================================
RCS file: /cvsroot/pgsql/src/backend/commands/prepare.c,v
retrieving revision 1.61
diff -c -c -r1.61 prepare.c
*** src/backend/commands/prepare.c 14 Aug 2006 22:57:15 -0000 1.61
--- src/backend/commands/prepare.c 28 Aug 2006 23:59:42 -0000
***************
*** 203,208 ****
--- 203,209 ----
PortalDefineQuery(portal,
NULL,
query_string,
+ NULL,
entry->commandTag,
query_list,
plan_list,
Index: src/backend/executor/spi.c
===================================================================
RCS file: /cvsroot/pgsql/src/backend/executor/spi.c,v
retrieving revision 1.157
diff -c -c -r1.157 spi.c
*** src/backend/executor/spi.c 14 Aug 2006 22:57:15 -0000 1.157
--- src/backend/executor/spi.c 28 Aug 2006 23:59:42 -0000
***************
*** 920,925 ****
--- 920,926 ----
PortalDefineQuery(portal,
NULL, /* no statement name */
spiplan->query,
+ NULL,
CreateQueryTag(PortalListGetPrimaryQuery(qtlist)),
qtlist,
ptlist,
Index: src/backend/tcop/postgres.c
===================================================================
RCS file: /cvsroot/pgsql/src/backend/tcop/postgres.c,v
retrieving revision 1.499
diff -c -c -r1.499 postgres.c
*** src/backend/tcop/postgres.c 15 Aug 2006 18:26:58 -0000 1.499
--- src/backend/tcop/postgres.c 28 Aug 2006 23:59:45 -0000
***************
*** 583,588 ****
--- 583,589 ----
* For the first EXECUTE we find, record the client statement used by
* the PREPARE. PREPARE doesn't save the parse tree so we have no
* way to conditionally output based on the type of query prepared.
+ * Parse does save the command tag, so perhaps we can use that.
*/
if (IsA(parsetree, ExecuteStmt))
{
***************
*** 592,611 ****
if (*prepare_string == NULL &&
(entry = FetchPreparedStatement(stmt->name, false)) != NULL &&
entry->query_string)
! {
! *prepare_string = palloc(strlen(entry->query_string) +
! strlen(" [PREPARE: %s]") - 2 + 1);
! sprintf(*prepare_string, " [PREPARE: %s]",
! entry->query_string);
! }
}
}
if (log_this_statement)
{
ereport(LOG,
! (errmsg("statement: %s%s", query_string,
! *prepare_string ? *prepare_string : "")));
return true;
}
else
--- 593,608 ----
if (*prepare_string == NULL &&
(entry = FetchPreparedStatement(stmt->name, false)) != NULL &&
entry->query_string)
! *prepare_string = pstrdup(entry->query_string);
}
}
if (log_this_statement)
{
ereport(LOG,
! (errmsg("statement: %s", query_string),
! *prepare_string ? errdetail("prepare: %s",
! *prepare_string) : 0));
return true;
}
else
***************
*** 874,882 ****
parsetree_list = pg_parse_query(query_string);
/* Log immediately if dictated by log_statement */
! if (log_statement != LOGSTMT_NONE)
! was_logged = log_after_parse(parsetree_list, query_string,
! &prepare_string);
/*
* Switch back to transaction context to enter the loop.
--- 871,878 ----
parsetree_list = pg_parse_query(query_string);
/* Log immediately if dictated by log_statement */
! was_logged = log_after_parse(parsetree_list, query_string,
! &prepare_string);
/*
* Switch back to transaction context to enter the loop.
***************
*** 957,962 ****
--- 953,959 ----
PortalDefineQuery(portal,
NULL,
query_string,
+ NULL,
commandTag,
querytree_list,
plantree_list,
***************
*** 1097,1106 ****
secs * 1000 + msecs, usecs % 1000)));
else
ereport(LOG,
! (errmsg("duration: %ld.%03d ms statement: %s%s",
secs * 1000 + msecs, usecs % 1000,
! query_string,
! prepare_string ? prepare_string : "")));
}
}
--- 1094,1104 ----
secs * 1000 + msecs, usecs % 1000)));
else
ereport(LOG,
! (errmsg("duration: %ld.%03d ms statement: %s",
secs * 1000 + msecs, usecs % 1000,
! query_string),
! prepare_string ? errdetail("prepare: %s",
! prepare_string) : 0));
}
}
***************
*** 1147,1153 ****
if (log_statement == LOGSTMT_ALL)
ereport(LOG,
! (errmsg("prepare %s: %s",
*stmt_name ? stmt_name : "<unnamed>",
query_string)));
--- 1145,1151 ----
if (log_statement == LOGSTMT_ALL)
ereport(LOG,
! (errmsg("statement: prepare %s, %s",
*stmt_name ? stmt_name : "<unnamed>",
query_string)));
***************
*** 1384,1391 ****
/* Switch back to message context */
MemoryContextSwitchTo(MessageContext);
! if (log_statement == LOGSTMT_ALL)
! initStringInfo(&bind_values_str);
/* Get the fixed part of the message */
portal_name = pq_getmsgstring(input_message);
--- 1382,1388 ----
/* Switch back to message context */
MemoryContextSwitchTo(MessageContext);
! initStringInfo(&bind_values_str);
/* Get the fixed part of the message */
portal_name = pq_getmsgstring(input_message);
***************
*** 1521,1527 ****
{
Oid typinput;
Oid typioparam;
! char *pstring;
getTypeInputInfo(ptype, &typinput, &typioparam);
--- 1518,1524 ----
{
Oid typinput;
Oid typioparam;
! char *pstring, *p;
getTypeInputInfo(ptype, &typinput, &typioparam);
***************
*** 1540,1551 ****
typioparam,
-1);
! /* Log the parameter value if needed */
! if (log_statement == LOGSTMT_ALL)
! appendStringInfo(&bind_values_str, "%s$%d = \"%s\"",
! bind_values_str.len ? ", " : "",
! paramno + 1,
! pstring);
/* Free result of encoding conversion, if any */
if (pstring && pstring != pbuf.data)
--- 1537,1553 ----
typioparam,
-1);
! /* Save the parameter values */
! appendStringInfo(&bind_values_str, "%s$%d = '",
! bind_values_str.len ? ", " : "",
! paramno + 1);
! for (p = pstring; *p; p++)
! {
! if (*p == '\'') /* double single quotes */
! appendStringInfoChar(&bind_values_str, *p);
! appendStringInfoChar(&bind_values_str, *p);
! }
! appendStringInfoChar(&bind_values_str, '\'');
/* Free result of encoding conversion, if any */
if (pstring && pstring != pbuf.data)
***************
*** 1607,1619 ****
if (log_statement == LOGSTMT_ALL)
{
ereport(LOG,
! (errmsg("bind %s%s%s: %s",
*stmt_name ? stmt_name : "<unnamed>",
*portal->name ? "/" : "",
*portal->name ? portal->name : "",
! pstmt->query_string ? pstmt->query_string : ""),
! bind_values_str.len ? errdetail(bind_values_str.data) : 0));
! pfree(bind_values_str.data);
}
/* Get the result format codes */
--- 1609,1622 ----
if (log_statement == LOGSTMT_ALL)
{
ereport(LOG,
! (errmsg("statement: bind %s%s%s%s%s",
*stmt_name ? stmt_name : "<unnamed>",
*portal->name ? "/" : "",
*portal->name ? portal->name : "",
! /* print bind parameters if we have them */
! bind_values_str.len ? ", " : "",
! bind_values_str.len ? bind_values_str.data : ""),
! errdetail("prepare: %s", pstmt->query_string)));
}
/* Get the result format codes */
***************
*** 1651,1656 ****
--- 1654,1660 ----
PortalDefineQuery(portal,
*stmt_name ? pstrdup(stmt_name) : NULL,
pstmt->query_string,
+ bind_values_str.len ? pstrdup(bind_values_str.data) : NULL,
pstmt->commandTag,
pstmt->query_list,
pstmt->plan_list,
***************
*** 1684,1689 ****
--- 1688,1694 ----
bool completed;
char completionTag[COMPLETION_TAG_BUFSIZE];
const char *sourceText = NULL;
+ const char *bindText = NULL;
const char *prepStmtName;
bool save_log_statement_stats = log_statement_stats;
bool is_xact_command;
***************
*** 1728,1748 ****
debug_query_string = "fetch message";
pgstat_report_activity("<FETCH>");
}
- else if (portal->sourceText)
- {
- /*
- * We must copy the sourceText into MessageContext in case the
- * portal is destroyed during finish_xact_command. Can avoid
- * the copy if it's not an xact command, though.
- */
- if (is_xact_command)
- sourceText = pstrdup(portal->sourceText);
- else
- sourceText = portal->sourceText;
-
- debug_query_string = sourceText;
- pgstat_report_activity(sourceText);
- }
else
{
debug_query_string = "execute message";
--- 1733,1738 ----
***************
*** 1758,1763 ****
--- 1748,1771 ----
prepStmtName = "<unnamed>";
/*
+ * We must copy the sourceText and bindText into MessageContext
+ * in case the portal is destroyed during finish_xact_command.
+ * Can avoid the copy if it's not an xact command, though.
+ */
+ if (is_xact_command)
+ sourceText = pstrdup(portal->sourceText);
+ else
+ sourceText = portal->sourceText;
+
+ if (portal->bindText)
+ {
+ if (is_xact_command)
+ bindText = pstrdup(portal->bindText);
+ else
+ bindText = portal->bindText;
+ }
+
+ /*
* We use save_log_statement_stats so ShowUsage doesn't report incorrect
* results because ResetUsage wasn't called.
*/
***************
*** 1766,1777 ****
if (log_statement == LOGSTMT_ALL)
ereport(LOG,
! (errmsg("execute %s%s%s%s: %s",
execute_is_fetch ? "fetch from " : "",
prepStmtName,
*portal_name ? "/" : "",
! *portal_name ? portal_name : "",
! sourceText ? sourceText : "")));
BeginCommand(portal->commandTag, dest);
--- 1774,1788 ----
if (log_statement == LOGSTMT_ALL)
ereport(LOG,
! (errmsg("statement: execute %s%s%s%s",
execute_is_fetch ? "fetch from " : "",
prepStmtName,
*portal_name ? "/" : "",
! *portal_name ? portal_name : ""),
! errdetail("prepare: %s%s%s", sourceText,
! /* optionally print bind parameters */
! bindText ? " bind: " : "",
! bindText ? bindText : "")));
BeginCommand(portal->commandTag, dest);
***************
*** 1876,1888 ****
secs * 1000 + msecs, usecs % 1000)));
else
ereport(LOG,
! (errmsg("duration: %ld.%03d ms execute %s%s%s%s: %s",
secs * 1000 + msecs, usecs % 1000,
execute_is_fetch ? "fetch from " : "",
prepStmtName,
*portal_name ? "/" : "",
! *portal_name ? portal_name : "",
! sourceText ? sourceText : "")));
}
}
--- 1887,1902 ----
secs * 1000 + msecs, usecs % 1000)));
else
ereport(LOG,
! (errmsg("duration: %ld.%03d ms execute %s%s%s%s",
secs * 1000 + msecs, usecs % 1000,
execute_is_fetch ? "fetch from " : "",
prepStmtName,
*portal_name ? "/" : "",
! *portal_name ? portal_name : ""),
! errdetail("prepare: %s%s%s", sourceText,
! /* optionally print bind parameters */
! bindText ? " bind: " : "",
! bindText ? bindText : "")));
}
}
Index: src/backend/utils/mmgr/portalmem.c
===================================================================
RCS file: /cvsroot/pgsql/src/backend/utils/mmgr/portalmem.c,v
retrieving revision 1.92
diff -c -c -r1.92 portalmem.c
*** src/backend/utils/mmgr/portalmem.c 14 Aug 2006 22:57:15 -0000 1.92
--- src/backend/utils/mmgr/portalmem.c 28 Aug 2006 23:59:47 -0000
***************
*** 274,279 ****
--- 274,280 ----
PortalDefineQuery(Portal portal,
const char *prepStmtName,
const char *sourceText,
+ const char *bindText,
const char *commandTag,
List *parseTrees,
List *planTrees,
***************
*** 288,293 ****
--- 289,295 ----
portal->prepStmtName = prepStmtName;
portal->sourceText = sourceText;
+ portal->bindText = bindText;
portal->commandTag = commandTag;
portal->parseTrees = parseTrees;
portal->planTrees = planTrees;
Index: src/include/utils/portal.h
===================================================================
RCS file: /cvsroot/pgsql/src/include/utils/portal.h,v
retrieving revision 1.66
diff -c -c -r1.66 portal.h
*** src/include/utils/portal.h 14 Aug 2006 22:57:15 -0000 1.66
--- src/include/utils/portal.h 28 Aug 2006 23:59:48 -0000
***************
*** 122,128 ****
*/
/* The query or queries the portal will execute */
! const char *sourceText; /* text of query, if known (may be NULL) */
const char *commandTag; /* command tag for original query */
List *parseTrees; /* parse tree(s) */
List *planTrees; /* plan tree(s) */
--- 122,129 ----
*/
/* The query or queries the portal will execute */
! const char *sourceText; /* text of query, if known, might be NULL */
! const char *bindText; /* text of bind parameters, might be NULL */
const char *commandTag; /* command tag for original query */
List *parseTrees; /* parse tree(s) */
List *planTrees; /* plan tree(s) */
***************
*** 215,220 ****
--- 216,222 ----
extern void PortalDefineQuery(Portal portal,
const char *prepStmtName,
const char *sourceText,
+ const char *bindText,
const char *commandTag,
List *parseTrees,
List *planTrees,
Bruce Momjian <bruce@momjian.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@momjian.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@momjian.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@momjian.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
Attachments:
prepare_bind_separator.difftext/plain; charset=ANSI_X3.4-1968; name=prepare_bind_separator.diffDownload
Index: src/backend/tcop/postgres.c
===================================================================
RCS file: /projects/cvsroot/pgsql/src/backend/tcop/postgres.c,v
retrieving revision 1.501
diff -c -r1.501 postgres.c
*** src/backend/tcop/postgres.c 29 Aug 2006 02:32:41 -0000 1.501
--- src/backend/tcop/postgres.c 29 Aug 2006 11:46:15 -0000
***************
*** 1782,1788 ****
*portal_name ? portal_name : ""),
errdetail("prepare: %s%s%s", sourceText,
/* optionally print bind parameters */
! bindText ? " bind: " : "",
bindText ? bindText : "")));
BeginCommand(portal->commandTag, dest);
--- 1782,1788 ----
*portal_name ? portal_name : ""),
errdetail("prepare: %s%s%s", sourceText,
/* optionally print bind parameters */
! bindText ? " - bind: " : "",
bindText ? bindText : "")));
BeginCommand(portal->commandTag, dest);
***************
*** 1896,1902 ****
*portal_name ? portal_name : ""),
errdetail("prepare: %s%s%s", sourceText,
/* optionally print bind parameters */
! bindText ? " bind: " : "",
bindText ? bindText : "")));
}
}
--- 1896,1902 ----
*portal_name ? portal_name : ""),
errdetail("prepare: %s%s%s", sourceText,
/* optionally print bind parameters */
! bindText ? " - bind: " : "",
bindText ? bindText : "")));
}
}
Guillaume Smet wrote:
On 8/29/06, Bruce Momjian <bruce@momjian.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@momjian.us
EnterpriseDB http://www.enterprisedb.com
+ If your life is a hard drive, Christ can be your backup. +
Attachments:
/bjm/difftext/x-diffDownload
Index: src/backend/tcop/postgres.c
===================================================================
RCS file: /cvsroot/pgsql/src/backend/tcop/postgres.c,v
retrieving revision 1.501
diff -c -c -r1.501 postgres.c
*** src/backend/tcop/postgres.c 29 Aug 2006 02:32:41 -0000 1.501
--- src/backend/tcop/postgres.c 29 Aug 2006 19:54:08 -0000
***************
*** 1539,1555 ****
-1);
/* Save the parameter values */
! appendStringInfo(&bind_values_str, "%s$%d = '",
bind_values_str.len ? ", " : "",
paramno + 1);
! for (p = pstring; *p; p++)
{
! if (*p == '\'') /* double single quotes */
appendStringInfoChar(&bind_values_str, *p);
! appendStringInfoChar(&bind_values_str, *p);
}
! appendStringInfoChar(&bind_values_str, '\'');
!
/* Free result of encoding conversion, if any */
if (pstring && pstring != pbuf.data)
pfree(pstring);
--- 1539,1561 ----
-1);
/* Save the parameter values */
! appendStringInfo(&bind_values_str, "%s$%d = ",
bind_values_str.len ? ", " : "",
paramno + 1);
! if (pstring)
{
! appendStringInfoChar(&bind_values_str, '\'');
! for (p = pstring; *p; p++)
! {
! if (*p == '\'') /* double single quotes */
! appendStringInfoChar(&bind_values_str, *p);
appendStringInfoChar(&bind_values_str, *p);
! }
! appendStringInfoChar(&bind_values_str, '\'');
}
! else
! appendStringInfo(&bind_values_str, "NULL");
!
/* Free result of encoding conversion, if any */
if (pstring && pstring != pbuf.data)
pfree(pstring);
***************
*** 1782,1788 ****
*portal_name ? portal_name : ""),
errdetail("prepare: %s%s%s", sourceText,
/* optionally print bind parameters */
! bindText ? " bind: " : "",
bindText ? bindText : "")));
BeginCommand(portal->commandTag, dest);
--- 1788,1794 ----
*portal_name ? portal_name : ""),
errdetail("prepare: %s%s%s", sourceText,
/* optionally print bind parameters */
! bindText ? ", bind: " : "",
bindText ? bindText : "")));
BeginCommand(portal->commandTag, dest);
***************
*** 1896,1902 ****
*portal_name ? portal_name : ""),
errdetail("prepare: %s%s%s", sourceText,
/* optionally print bind parameters */
! bindText ? " bind: " : "",
bindText ? bindText : "")));
}
}
--- 1902,1908 ----
*portal_name ? portal_name : ""),
errdetail("prepare: %s%s%s", sourceText,
/* optionally print bind parameters */
! bindText ? ", bind: " : "",
bindText ? bindText : "")));
}
}
On 8/29/06, Bruce Momjian <bruce@momjian.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@momjian.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@momjian.us
EnterpriseDB http://www.enterprisedb.com
+ If your life is a hard drive, Christ can be your backup. +
Attachments:
/bjm/difftext/x-diffDownload
Index: src/backend/tcop/postgres.c
===================================================================
RCS file: /cvsroot/pgsql/src/backend/tcop/postgres.c,v
retrieving revision 1.502
diff -c -c -r1.502 postgres.c
*** src/backend/tcop/postgres.c 29 Aug 2006 20:10:42 -0000 1.502
--- src/backend/tcop/postgres.c 30 Aug 2006 17:59:05 -0000
***************
*** 1146,1152 ****
if (log_statement == LOGSTMT_ALL)
ereport(LOG,
! (errmsg("statement: prepare %s, %s",
*stmt_name ? stmt_name : "<unnamed>",
query_string)));
--- 1146,1152 ----
if (log_statement == LOGSTMT_ALL)
ereport(LOG,
! (errmsg("statement: prepare %s: %s",
*stmt_name ? stmt_name : "<unnamed>",
query_string)));
***************
*** 1621,1627 ****
*portal->name ? "/" : "",
*portal->name ? portal->name : "",
/* print bind parameters if we have them */
! bind_values_str.len ? ", " : "",
bind_values_str.len ? bind_values_str.data : ""),
errdetail("prepare: %s", pstmt->query_string)));
}
--- 1621,1627 ----
*portal->name ? "/" : "",
*portal->name ? portal->name : "",
/* print bind parameters if we have them */
! bind_values_str.len ? ": " : "",
bind_values_str.len ? bind_values_str.data : ""),
errdetail("prepare: %s", pstmt->query_string)));
}
***************
*** 1788,1794 ****
*portal_name ? portal_name : ""),
errdetail("prepare: %s%s%s", sourceText,
/* optionally print bind parameters */
! bindText ? ", bind: " : "",
bindText ? bindText : "")));
BeginCommand(portal->commandTag, dest);
--- 1788,1794 ----
*portal_name ? portal_name : ""),
errdetail("prepare: %s%s%s", sourceText,
/* optionally print bind parameters */
! bindText ? " | bind: " : "",
bindText ? bindText : "")));
BeginCommand(portal->commandTag, dest);
***************
*** 1902,1908 ****
*portal_name ? portal_name : ""),
errdetail("prepare: %s%s%s", sourceText,
/* optionally print bind parameters */
! bindText ? ", bind: " : "",
bindText ? bindText : "")));
}
}
--- 1902,1908 ----
*portal_name ? portal_name : ""),
errdetail("prepare: %s%s%s", sourceText,
/* optionally print bind parameters */
! bindText ? " | bind: " : "",
bindText ? bindText : "")));
}
}
On 8/30/06, Bruce Momjian <bruce@momjian.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@momjian.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@momjian.us
EnterpriseDB http://www.enterprisedb.com
+ If your life is a hard drive, Christ can be your backup. +