Thread: log_statement output for protocol prepare/bind/execute
Tom Lane wrote:
> Bruce Momjian <bruce@momjian.us> writes:
> > ! (errmsg("statement: [protocol] <BIND> %s", portal_name)));
>
> > --- 1452,1460 ----
> > ! (errmsg("statement: <protocol> <BIND> %s [PREPARE: %s]",
> > ! *portal_name ? portal_name : "<unnamed>",
> > ! portal->sourceText ? portal->sourceText : "")));
>
> This is getting less readable not more so; and you still haven't got the
> prepared statement's name in there, let alone any place to put the
> parameter values.
>
> Perhaps we should give up on the idea that this can all fit on one log
> line? Maybe
>
> LOG: parse: <statement-name>
> DETAIL: statement: <source-text>
>
> LOG: bind: <portal-name> to <statement-name>
> DETAIL: statement: <source-text>
> parameter 1: <parameter value>
> parameter 2: <parameter value>
> ...
>
> LOG: execute: <portal-name>
> DETAIL: statement: <source-text>
>
> The $64 question here is whether we want to repeat the source-text
> in all three messages (parse, bind, execute) or try to reduce the
> verbosity.
I modified the code to store the user statement name in the portal for
protocol execute, so I can print the user name at that time. Here is
the new output:
LOG: statement protocol prepare sel1: SELECT 1;
LOG: statement protocol bind sel1: SELECT 1;
LOG: statement protocol execute sel1: SELECT 1;
Patch attached. I am also attaching my test program. Should I put that
in CVS somewhere? Libpq.sgml.
I had to pstrdup() the statement name. Is that OK?
--
Bruce Momjian bruce@momjian.us
EnterpriseDB http://www.enterprisedb.com
+ If your life is a hard drive, Christ can be your backup. +
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,
/*
* testlibpq.c
*
* Test the C version of libpq, the PostgreSQL frontend library.
*/
#include <stdio.h>
#include <stdlib.h>
#include "libpq-fe.h"
static void
exit_nicely(PGconn *conn)
{
PQfinish(conn);
exit(1);
}
int
main(int argc, char **argv)
{
const char *conninfo;
PGconn *conn;
PGresult *res;
int nFields;
int i,
j;
/*
* If the user supplies a parameter on the command line, use it as the
* conninfo string; otherwise default to setting dbname=postgres and using
* environment variables or defaults for all other connection parameters.
*/
if (argc > 1)
conninfo = argv[1];
else
conninfo = "dbname = postgres";
/* Make a connection to the database */
conn = PQconnectdb(conninfo);
/* Check to see that the backend connection was successfully made */
if (PQstatus(conn) != CONNECTION_OK)
{
fprintf(stderr, "Connection to database failed: %s",
PQerrorMessage(conn));
exit_nicely(conn);
}
res = PQexec(conn, "SET log_statement = 'all';");
if (PQresultStatus(res) != PGRES_COMMAND_OK)
{
fprintf(stderr, "BEGIN command failed: %s", PQerrorMessage(conn));
PQclear(res);
exit_nicely(conn);
}
/*
* Should PQclear PGresult whenever it is no longer needed to avoid memory
* leaks
*/
PQclear(res);
/*
* Our test case here involves using a cursor, for which we must be inside
* a transaction block. We could do the whole thing with a single
* PQexec() of "select * from pg_database", but that's too trivial to make
* a good example.
*/
/*
* Fetch rows from pg_database, the system catalog of databases
*/
res = PQprepare(conn, "sel1", "SELECT 1;", 0, NULL);
if (PQresultStatus(res) != PGRES_COMMAND_OK)
{
fprintf(stderr, "prepared failed: %s", PQerrorMessage(conn));
PQclear(res);
exit_nicely(conn);
}
PQclear(res);
res = PQexecPrepared(conn, "sel1", 0, NULL, NULL, NULL, 0);
if (PQresultStatus(res) != PGRES_TUPLES_OK)
{
fprintf(stderr, "exec failed: %s", PQerrorMessage(conn));
PQclear(res);
exit_nicely(conn);
}
/* first, print out the attribute names */
nFields = PQnfields(res);
for (i = 0; i < nFields; i++)
printf("%-15s", PQfname(res, i));
printf("\n\n");
/* next, print out the rows */
for (i = 0; i < PQntuples(res); i++)
{
for (j = 0; j < nFields; j++)
printf("%-15s", PQgetvalue(res, i, j));
printf("\n");
}
PQclear(res);
/* close the connection to the database and cleanup */
PQfinish(conn);
return 0;
}
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? Maybe
> >
> > LOG: parse: <statement-name>
> > DETAIL: statement: <source-text>
> >
> > LOG: bind: <portal-name> to <statement-name>
> > DETAIL: statement: <source-text>
> > parameter 1: <parameter value>
> > parameter 2: <parameter value>
> > ...
> >
> > LOG: execute: <portal-name>
> > DETAIL: statement: <source-text>
> >
> > The $64 question here is whether we want to repeat the source-text
> > in all three messages (parse, bind, execute) or try to reduce the
> > verbosity.
>
> I modified the code to store the user statement name in the portal for
> protocol execute, so I can print the user name at that time. Here is
> the new output:
>
> LOG: statement protocol prepare sel1: SELECT 1;
> LOG: statement protocol bind sel1: SELECT 1;
> LOG: statement protocol execute sel1: SELECT 1;
>
> Patch attached. I am also attaching my test program. Should I put that
> in CVS somewhere? Libpq.sgml.
>
> I had to pstrdup() the statement name. Is that OK?
--
Bruce Momjian bruce@momjian.us
EnterpriseDB http://www.enterprisedb.com
+ If your life is a hard drive, Christ can be your backup. +
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 = 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
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. +
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. +
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,
/*
* testlibpq.c
*
* Test the C version of libpq, the PostgreSQL frontend library.
*/
#include <stdio.h>
#include <stdlib.h>
#include "libpq-fe.h"
static void
exit_nicely(PGconn *conn)
{
PQfinish(conn);
exit(1);
}
int
main(int argc, char **argv)
{
const char *conninfo;
PGconn *conn;
PGresult *res;
int nFields;
int i,
j;
const char *val[2];
int types[2];
/*
* If the user supplies a parameter on the command line, use it as the
* conninfo string; otherwise default to setting dbname=postgres and using
* environment variables or defaults for all other connection parameters.
*/
if (argc > 1)
conninfo = argv[1];
else
conninfo = "dbname = postgres";
/* Make a connection to the database */
conn = PQconnectdb(conninfo);
/* Check to see that the backend connection was successfully made */
if (PQstatus(conn) != CONNECTION_OK)
{
fprintf(stderr, "Connection to database failed: %s",
PQerrorMessage(conn));
exit_nicely(conn);
}
res = PQexec(conn, "SET log_statement = 'all';");
if (PQresultStatus(res) != PGRES_COMMAND_OK)
{
fprintf(stderr, "BEGIN command failed: %s", PQerrorMessage(conn));
PQclear(res);
exit_nicely(conn);
}
/*
* Should PQclear PGresult whenever it is no longer needed to avoid memory
* leaks
*/
PQclear(res);
/*
* Our test case here involves using a cursor, for which we must be inside
* a transaction block. We could do the whole thing with a single
* PQexec() of "select * from pg_database", but that's too trivial to make
* a good example.
*/
/*
* Fetch rows from pg_database, the system catalog of databases
*/
types[0] = 23;
types[1] = 23;
res = PQprepare(conn, "sel1", "SELECT $1 + $2;", 2, types);
if (PQresultStatus(res) != PGRES_COMMAND_OK)
{
fprintf(stderr, "prepared failed: %s", PQerrorMessage(conn));
PQclear(res);
exit_nicely(conn);
}
PQclear(res);
val[0] = "8";
val[1] = "5";
res = PQexecPrepared(conn, "sel1", 2, val, NULL, NULL, 0);
if (PQresultStatus(res) != PGRES_TUPLES_OK)
{
fprintf(stderr, "exec failed: %s", PQerrorMessage(conn));
PQclear(res);
exit_nicely(conn);
}
/* first, print out the attribute names */
nFields = PQnfields(res);
for (i = 0; i < nFields; i++)
printf("%-15s", PQfname(res, i));
printf("\n\n");
/* next, print out the rows */
for (i = 0; i < PQntuples(res); i++)
{
for (j = 0; j < nFields; j++)
printf("%-15s", PQgetvalue(res, i, j));
printf("\n");
}
PQclear(res);
/* close the connection to the database and cleanup */
PQfinish(conn);
return 0;
}
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. + 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. +
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
Attachment
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. +
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. +
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. +