Unix Technical Forum

SEO

vBulletin Search Engine Optimization


Go Back   Unix Technical Forum > Database Server Software > PostgreSQL > Pgsql Patches

Register FAQ Members List Calendar Search Today's Posts Mark Forums Read
  #1 (permalink)  
Old 04-18-2008, 12:54 AM
Bruce Momjian
 
Posts: n/a
Default 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. +

/*
* 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;
}


---------------------------(end of broadcast)---------------------------
TIP 5: don't forget to increase your free space map settings

Digg this Post!Add Post to del.icio.usBookmark Post in TechnoratiFurl this Post!
Reply With Quote
  #2 (permalink)  
Old 04-18-2008, 12:54 AM
Tom Lane
 
Posts: n/a
Default Re: log_statement output for protocol prepare/bind/execute

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

---------------------------(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

Digg this Post!Add Post to del.icio.usBookmark Post in TechnoratiFurl this Post!
Reply With Quote
  #3 (permalink)  
Old 04-18-2008, 12:54 AM
Bruce Momjian
 
Posts: n/a
Default Re: [HACKERS] log_statement output for protocol

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

Digg this Post!Add Post to del.icio.usBookmark Post in TechnoratiFurl this Post!
Reply With Quote
  #4 (permalink)  
Old 04-18-2008, 12:54 AM
Bruce Momjian
 
Posts: n/a
Default Re: [HACKERS] log_statement output for protocol


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

/*
* 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;
}


---------------------------(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

Digg this Post!Add Post to del.icio.usBookmark Post in TechnoratiFurl this Post!
Reply With Quote
  #5 (permalink)  
Old 04-18-2008, 12:54 AM
Oliver Jowett
 
Posts: n/a
Default Re: [HACKERS] log_statement output for protocol

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

---------------------------(end of broadcast)---------------------------
TIP 4: Have you searched our list archives?

http://archives.postgresql.org

Digg this Post!Add Post to del.icio.usBookmark Post in TechnoratiFurl this Post!
Reply With Quote
  #6 (permalink)  
Old 04-18-2008, 12:54 AM
Tom Lane
 
Posts: n/a
Default Re: [HACKERS] log_statement output for protocol

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

---------------------------(end of broadcast)---------------------------
TIP 2: Don't 'kill -9' the postmaster

Digg this Post!Add Post to del.icio.usBookmark Post in TechnoratiFurl this Post!
Reply With Quote
  #7 (permalink)  
Old 04-18-2008, 12:54 AM
Bruce Momjian
 
Posts: n/a
Default Re: [HACKERS] log_statement output for protocol

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

---------------------------(end of broadcast)---------------------------
TIP 3: Have you checked our extensive FAQ?

http://www.postgresql.org/docs/faq

Digg this Post!Add Post to del.icio.usBookmark Post in TechnoratiFurl this Post!
Reply With Quote
  #8 (permalink)  
Old 04-18-2008, 12:54 AM
Bruce Momjian
 
Posts: n/a
Default Re: [HACKERS] log_statement output for protocol

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,


---------------------------(end of broadcast)---------------------------
TIP 2: Don't 'kill -9' the postmaster

Digg this Post!Add Post to del.icio.usBookmark Post in TechnoratiFurl this Post!
Reply With Quote
  #9 (permalink)  
Old 04-18-2008, 12:54 AM
Bruce Momjian
 
Posts: n/a
Default Re: [HACKERS] log_statement output for protocol


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

Digg this Post!Add Post to del.icio.usBookmark Post in TechnoratiFurl this Post!
Reply With Quote
  #10 (permalink)  
Old 04-18-2008, 12:54 AM
Bruce Momjian
 
Posts: n/a
Default Re: [HACKERS] log_statement output for protocol


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

---------------------------(end of broadcast)---------------------------
TIP 1: if posting/reading through Usenet, please send an appropriate
subscribe-nomail command to majordomo@postgresql.org so that your
message can get through to the mailing list cleanly

Digg this Post!Add Post to del.icio.usBookmark Post in TechnoratiFurl this Post!
Reply With Quote
Reply


Thread Tools
Display Modes

Posting Rules
You may not post new threads
You may not post replies
You may not post attachments
You may not edit your posts

vB code is On
Smilies are On
[IMG] code is On
HTML code is Off
Trackbacks are On
Pingbacks are On
Refbacks are On
Forum Jump


All times are GMT. The time now is 04:25 AM.


Powered by vBulletin® Version 3.6.5
Copyright ©2000 - 2008, Jelsoft Enterprises Ltd.
SEO by vBSEO 3.2.0
UnixAdminTalk.com

1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 26 27 28 29 30 31 32 33 34 35 36 37 38 39 40 41 42 43 44 45 46 47 48 49 50 51 52 53 54 55 56 57 58 59 60 61 62 63 64 65 66 67 68 69 70 71 72 73 74 75 76 77 78 79 80 81 82 83 84 85 86 87 88 89 90 91 92 93 94 95 96 97 98 99 100 101 102 103 104 105 106 107 108 109 110 111 112 113 114 115 116 117 118 119 120 121 122 123 124 125 126 127 128 129 130 131 132 133 134 135 136 137 138 139 140 141 142 143 144 145 146 147 148 149 150 151 152 153 154 155 156 157 158 159 160 161 162 163 164 165 166 167 168 169 170 171 172 173 174 175 176 177 178 179 180 181 182 183 184 185 186 187 188 189 190 191 192