提交 893632be 编写于 作者: T Tom Lane

Clean up logging for extended-query-protocol operations, as per my recent

proposal.  Parameter logging works even for binary-format parameters, and
logging overhead is avoided when disabled.

log_statement = all output for the src/test/examples/testlibpq3.c example
now looks like

LOG:  statement: execute <unnamed>: SELECT * FROM test1 WHERE t = $1
DETAIL:  parameters: $1 = 'joe''s place'
LOG:  statement: execute <unnamed>: SELECT * FROM test1 WHERE i = $1::int4
DETAIL:  parameters: $1 = '2'

and log_min_duration_statement = 0 results in

LOG:  duration: 2.431 ms  parse <unnamed>: SELECT * FROM test1 WHERE t = $1
LOG:  duration: 2.335 ms  bind <unnamed> to <unnamed>: SELECT * FROM test1 WHERE t = $1
DETAIL:  parameters: $1 = 'joe''s place'
LOG:  duration: 0.394 ms  execute <unnamed>: SELECT * FROM test1 WHERE t = $1
DETAIL:  parameters: $1 = 'joe''s place'
LOG:  duration: 1.251 ms  parse <unnamed>: SELECT * FROM test1 WHERE i = $1::int4
LOG:  duration: 0.566 ms  bind <unnamed> to <unnamed>: SELECT * FROM test1 WHERE i = $1::int4
DETAIL:  parameters: $1 = '2'
LOG:  duration: 0.173 ms  execute <unnamed>: SELECT * FROM test1 WHERE i = $1::int4
DETAIL:  parameters: $1 = '2'

(This example demonstrates the folly of ignoring parse/bind steps for duration
logging purposes, BTW.)

Along the way, create a less ad-hoc mechanism for determining which commands
are logged by log_statement = mod and log_statement = ddl.  The former coding
was actually missing quite a few things that look like ddl to me, and it
did not handle EXECUTE or extended query protocol correctly at all.

This commit does not do anything about the question of whether log_duration
should be removed or made less redundant with log_min_duration_statement.
上级 b6eab50c
<!-- $PostgreSQL: pgsql/doc/src/sgml/config.sgml,v 1.83 2006/09/03 19:06:15 tgl Exp $ -->
<!-- $PostgreSQL: pgsql/doc/src/sgml/config.sgml,v 1.84 2006/09/07 22:51:59 tgl Exp $ -->
<chapter Id="runtime-config">
<title>Server Configuration</title>
......@@ -2492,18 +2492,36 @@ SELECT * FROM parent WHERE key = 2400;
</indexterm>
<listitem>
<para>
Logs the statement and its duration on a single log line if its
duration is greater than or equal to the specified number of
milliseconds. Setting this to zero will print all statements
and their durations. Minus-one (the default) disables the
feature. For example, if you set it to <literal>250</literal>
Causes the duration of each completed statement to be logged
if the statement ran for at least the specified number of
milliseconds. Setting this to zero prints all statement durations.
Minus-one (the default) disables logging statement durations.
For example, if you set it to <literal>250</literal>
then all SQL statements that run 250ms or longer will be
logged. Enabling this parameter can be useful in tracking down
unoptimized queries in your applications. This setting is
independent of <varname>log_statement</varname> and
<varname>log_duration</varname>. Only superusers can change
this setting.
logged. Enabling this parameter can be helpful in tracking down
unoptimized queries in your applications.
Only superusers can change this setting.
</para>
<para>
For clients using extended query protocol, durations of the Parse,
Bind, and Execute steps are logged independently.
</para>
<note>
<para>
When using this option together with
<xref linkend="guc-log-statement">,
the text of statements that are logged because of
<varname>log_statement</> will not be repeated in the
duration log message.
If you are not using <application>syslog</>, it is recommended
that you log the PID or session ID using
<xref linkend="guc-log-line-prefix">
so that you can link the statement message to the later
duration message using the process ID or session ID.
</para>
</note>
</listitem>
</varlistentry>
......@@ -2695,14 +2713,30 @@ SELECT * FROM parent WHERE key = 2400;
</indexterm>
<listitem>
<para>
Causes the duration of every completed statement which satisfies
<varname>log_statement</> to be logged. When using this option,
if you are not using <application>syslog</>, it is recommended
that you log the PID or session ID using <varname>log_line_prefix</>
so that you can link the statement message to the later
duration message using the process ID or session ID. The default is
<literal>off</>. Only superusers can change this setting.
Causes the duration of every completed statement to be logged.
The default is <literal>off</>.
Only superusers can change this setting.
</para>
<para>
For clients using extended query protocol, durations of the Parse,
Bind, and Execute steps are logged independently.
</para>
<note>
<para>
When using this option together with
<xref linkend="guc-log-statement">,
the text of statements that are logged because of
<varname>log_statement</> will not be repeated in the
duration log message.
If you are not using <application>syslog</>, it is recommended
that you log the PID or session ID using
<xref linkend="guc-log-line-prefix">
so that you can link the statement message to the later
duration message using the process ID or session ID.
</para>
</note>
</listitem>
</varlistentry>
......@@ -2829,18 +2863,20 @@ SELECT * FROM parent WHERE key = 2400;
Controls which SQL statements are logged. Valid values are
<literal>none</>, <literal>ddl</>, <literal>mod</>, and
<literal>all</>. <literal>ddl</> logs all data definition
commands like <literal>CREATE</>, <literal>ALTER</>, and
<literal>DROP</> commands. <literal>mod</> logs all
<literal>ddl</> statements, plus <literal>INSERT</>,
<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 (literal single quotes are doubled).
statements, such as <command>CREATE</>, <command>ALTER</>, and
<command>DROP</> statements. <literal>mod</> logs all
<literal>ddl</> statements, plus data-modifying statements
such as <command>INSERT</>,
<command>UPDATE</>, <command>DELETE</>, <command>TRUNCATE</>,
and <command>COPY FROM</>.
<command>PREPARE</>, <command>EXECUTE</>, and
<command>EXPLAIN ANALYZE</> statements are also logged if their
contained command is of an appropriate type. For clients using
extended query protocol, logging occurs when an Execute message
is received, and values of the Bind parameters are included
(with any embedded single-quote marks doubled).
</para>
<para>
The default is <literal>none</>. Only superusers can change this
setting.
......@@ -2848,9 +2884,7 @@ SELECT * FROM parent WHERE key = 2400;
<note>
<para>
The <command>EXECUTE</command> statement is not considered a
<literal>ddl</> or <literal>mod</> statement. Statements that
generate syntax errors are not logged. Set
Statements that generate syntax errors are not logged. Set
<varname>log_min_error_statement</> to <literal>error</> to
log such statements.
</para>
......
......@@ -14,7 +14,7 @@
*
*
* IDENTIFICATION
* $PostgreSQL: pgsql/src/backend/commands/portalcmds.c,v 1.54 2006/09/06 20:40:47 tgl Exp $
* $PostgreSQL: pgsql/src/backend/commands/portalcmds.c,v 1.55 2006/09/07 22:52:00 tgl Exp $
*
*-------------------------------------------------------------------------
*/
......@@ -109,12 +109,11 @@ PerformCursorOpen(DeclareCursorStmt *stmt, ParamListInfo params)
/*
* XXX: debug_query_string is wrong here: the user might have
* submitted more than one semicolon delimited queries.
* submitted multiple semicolon delimited queries.
*/
PortalDefineQuery(portal,
NULL,
pstrdup(debug_query_string),
NULL,
"SELECT", /* cursor's query is always a SELECT */
list_make1(query),
list_make1(plan),
......
......@@ -10,7 +10,7 @@
* Copyright (c) 2002-2006, PostgreSQL Global Development Group
*
* IDENTIFICATION
* $PostgreSQL: pgsql/src/backend/commands/prepare.c,v 1.63 2006/09/06 20:40:47 tgl Exp $
* $PostgreSQL: pgsql/src/backend/commands/prepare.c,v 1.64 2006/09/07 22:52:00 tgl Exp $
*
*-------------------------------------------------------------------------
*/
......@@ -203,7 +203,6 @@ ExecuteQuery(ExecuteStmt *stmt, ParamListInfo params,
PortalDefineQuery(portal,
NULL,
query_string,
NULL,
entry->commandTag,
query_list,
plan_list,
......
......@@ -8,7 +8,7 @@
*
*
* IDENTIFICATION
* $PostgreSQL: pgsql/src/backend/executor/spi.c,v 1.162 2006/09/06 20:40:47 tgl Exp $
* $PostgreSQL: pgsql/src/backend/executor/spi.c,v 1.163 2006/09/07 22:52:00 tgl Exp $
*
*-------------------------------------------------------------------------
*/
......@@ -921,7 +921,6 @@ SPI_cursor_open(const char *name, void *plan,
PortalDefineQuery(portal,
NULL, /* no statement name */
spiplan->query,
NULL,
CreateQueryTag(PortalListGetPrimaryQuery(qtlist)),
qtlist,
ptlist,
......
此差异已折叠。
......@@ -10,7 +10,7 @@
*
*
* IDENTIFICATION
* $PostgreSQL: pgsql/src/backend/tcop/utility.c,v 1.267 2006/08/25 04:06:53 tgl Exp $
* $PostgreSQL: pgsql/src/backend/tcop/utility.c,v 1.268 2006/09/07 22:52:01 tgl Exp $
*
*-------------------------------------------------------------------------
*/
......@@ -1815,6 +1815,8 @@ CreateQueryTag(Query *parsetree)
{
const char *tag;
Assert(IsA(parsetree, Query));
switch (parsetree->commandType)
{
case CMD_SELECT:
......@@ -1856,3 +1858,393 @@ CreateQueryTag(Query *parsetree)
return tag;
}
/*
* GetCommandLogLevel
* utility to get the minimum log_statement level for a command,
* given a raw (un-analyzed) parsetree.
*
* This must handle all raw command types, but since the vast majority
* of 'em are utility commands, it seems sensible to keep it here.
*/
LogStmtLevel
GetCommandLogLevel(Node *parsetree)
{
LogStmtLevel lev;
switch (nodeTag(parsetree))
{
case T_InsertStmt:
case T_DeleteStmt:
case T_UpdateStmt:
lev = LOGSTMT_MOD;
break;
case T_SelectStmt:
if (((SelectStmt *) parsetree)->into)
lev = LOGSTMT_DDL; /* CREATE AS, SELECT INTO */
else
lev = LOGSTMT_ALL;
break;
case T_TransactionStmt:
lev = LOGSTMT_ALL;
break;
case T_DeclareCursorStmt:
lev = LOGSTMT_ALL;
break;
case T_ClosePortalStmt:
lev = LOGSTMT_ALL;
break;
case T_FetchStmt:
lev = LOGSTMT_ALL;
break;
case T_CreateDomainStmt:
lev = LOGSTMT_DDL;
break;
case T_CreateSchemaStmt:
lev = LOGSTMT_DDL;
break;
case T_CreateStmt:
lev = LOGSTMT_DDL;
break;
case T_CreateTableSpaceStmt:
lev = LOGSTMT_DDL;
break;
case T_DropTableSpaceStmt:
lev = LOGSTMT_DDL;
break;
case T_DropStmt:
lev = LOGSTMT_DDL;
break;
case T_TruncateStmt:
lev = LOGSTMT_MOD;
break;
case T_CommentStmt:
lev = LOGSTMT_DDL;
break;
case T_CopyStmt:
if (((CopyStmt *) parsetree)->is_from)
lev = LOGSTMT_MOD;
else
lev = LOGSTMT_ALL;
break;
case T_RenameStmt:
lev = LOGSTMT_DDL;
break;
case T_AlterObjectSchemaStmt:
lev = LOGSTMT_DDL;
break;
case T_AlterOwnerStmt:
lev = LOGSTMT_DDL;
break;
case T_AlterTableStmt:
lev = LOGSTMT_DDL;
break;
case T_AlterDomainStmt:
lev = LOGSTMT_DDL;
break;
case T_AlterFunctionStmt:
lev = LOGSTMT_DDL;
break;
case T_GrantStmt:
lev = LOGSTMT_DDL;
break;
case T_GrantRoleStmt:
lev = LOGSTMT_DDL;
break;
case T_DefineStmt:
lev = LOGSTMT_DDL;
break;
case T_CompositeTypeStmt:
lev = LOGSTMT_DDL;
break;
case T_ViewStmt:
lev = LOGSTMT_DDL;
break;
case T_CreateFunctionStmt:
lev = LOGSTMT_DDL;
break;
case T_IndexStmt:
lev = LOGSTMT_DDL;
break;
case T_RuleStmt:
lev = LOGSTMT_DDL;
break;
case T_CreateSeqStmt:
lev = LOGSTMT_DDL;
break;
case T_AlterSeqStmt:
lev = LOGSTMT_DDL;
break;
case T_RemoveFuncStmt:
lev = LOGSTMT_DDL;
break;
case T_CreatedbStmt:
lev = LOGSTMT_DDL;
break;
case T_AlterDatabaseStmt:
lev = LOGSTMT_DDL;
break;
case T_AlterDatabaseSetStmt:
lev = LOGSTMT_DDL;
break;
case T_DropdbStmt:
lev = LOGSTMT_DDL;
break;
case T_NotifyStmt:
lev = LOGSTMT_ALL;
break;
case T_ListenStmt:
lev = LOGSTMT_ALL;
break;
case T_UnlistenStmt:
lev = LOGSTMT_ALL;
break;
case T_LoadStmt:
lev = LOGSTMT_ALL;
break;
case T_ClusterStmt:
lev = LOGSTMT_DDL;
break;
case T_VacuumStmt:
lev = LOGSTMT_ALL;
break;
case T_ExplainStmt:
{
ExplainStmt *stmt = (ExplainStmt *) parsetree;
/* Look through an EXPLAIN ANALYZE to the contained stmt */
if (stmt->analyze)
return GetCommandLogLevel((Node *) stmt->query);
/* Plain EXPLAIN isn't so interesting */
lev = LOGSTMT_ALL;
}
break;
case T_VariableSetStmt:
lev = LOGSTMT_ALL;
break;
case T_VariableShowStmt:
lev = LOGSTMT_ALL;
break;
case T_VariableResetStmt:
lev = LOGSTMT_ALL;
break;
case T_CreateTrigStmt:
lev = LOGSTMT_DDL;
break;
case T_DropPropertyStmt:
lev = LOGSTMT_DDL;
break;
case T_CreatePLangStmt:
lev = LOGSTMT_DDL;
break;
case T_DropPLangStmt:
lev = LOGSTMT_DDL;
break;
case T_CreateRoleStmt:
lev = LOGSTMT_DDL;
break;
case T_AlterRoleStmt:
lev = LOGSTMT_DDL;
break;
case T_AlterRoleSetStmt:
lev = LOGSTMT_DDL;
break;
case T_DropRoleStmt:
lev = LOGSTMT_DDL;
break;
case T_DropOwnedStmt:
lev = LOGSTMT_DDL;
break;
case T_ReassignOwnedStmt:
lev = LOGSTMT_DDL;
break;
case T_LockStmt:
lev = LOGSTMT_ALL;
break;
case T_ConstraintsSetStmt:
lev = LOGSTMT_ALL;
break;
case T_CheckPointStmt:
lev = LOGSTMT_ALL;
break;
case T_ReindexStmt:
lev = LOGSTMT_ALL; /* should this be DDL? */
break;
case T_CreateConversionStmt:
lev = LOGSTMT_DDL;
break;
case T_CreateCastStmt:
lev = LOGSTMT_DDL;
break;
case T_DropCastStmt:
lev = LOGSTMT_DDL;
break;
case T_CreateOpClassStmt:
lev = LOGSTMT_DDL;
break;
case T_RemoveOpClassStmt:
lev = LOGSTMT_DDL;
break;
case T_PrepareStmt:
{
PrepareStmt *stmt = (PrepareStmt *) parsetree;
/* Look through a PREPARE to the contained stmt */
return GetCommandLogLevel((Node *) stmt->query);
}
break;
case T_ExecuteStmt:
{
ExecuteStmt *stmt = (ExecuteStmt *) parsetree;
PreparedStatement *pstmt;
ListCell *l;
/* Look through an EXECUTE to the referenced stmt(s) */
lev = LOGSTMT_ALL;
pstmt = FetchPreparedStatement(stmt->name, false);
if (pstmt)
{
foreach(l, pstmt->query_list)
{
Query *query = (Query *) lfirst(l);
LogStmtLevel stmt_lev;
stmt_lev = GetQueryLogLevel(query);
lev = Min(lev, stmt_lev);
}
}
}
break;
case T_DeallocateStmt:
lev = LOGSTMT_ALL;
break;
case T_Query:
/*
* In complicated situations (eg, EXPLAIN ANALYZE in an extended
* Query protocol), we might find an already-analyzed query
* within a utility statement. Cope.
*/
lev = GetQueryLogLevel((Query *) parsetree);
break;
default:
elog(WARNING, "unrecognized node type: %d",
(int) nodeTag(parsetree));
lev = LOGSTMT_ALL;
break;
}
return lev;
}
/*
* GetQueryLogLevel
* utility to get the minimum log_statement level for a Query operation.
*
* This is exactly like GetCommandLogLevel, except it works on a Query
* that has already been through parse analysis (and possibly further).
*/
LogStmtLevel
GetQueryLogLevel(Query *parsetree)
{
LogStmtLevel lev;
Assert(IsA(parsetree, Query));
switch (parsetree->commandType)
{
case CMD_SELECT:
if (parsetree->into != NULL)
lev = LOGSTMT_DDL; /* CREATE AS, SELECT INTO */
else
lev = LOGSTMT_ALL;
break;
case CMD_UPDATE:
case CMD_INSERT:
case CMD_DELETE:
lev = LOGSTMT_MOD;
break;
case CMD_UTILITY:
lev = GetCommandLogLevel(parsetree->utilityStmt);
break;
default:
elog(WARNING, "unrecognized commandType: %d",
(int) parsetree->commandType);
lev = LOGSTMT_ALL;
break;
}
return lev;
}
$PostgreSQL: pgsql/src/backend/utils/mmgr/README,v 1.8 2004/08/04 21:34:04 tgl Exp $
$PostgreSQL: pgsql/src/backend/utils/mmgr/README,v 1.9 2006/09/07 22:52:01 tgl Exp $
Notes about memory allocation redesign
--------------------------------------
......@@ -202,13 +202,13 @@ data kept here is pending NOTIFY messages, which are sent at top-level commit,
but only if the generating subtransaction did not abort.
QueryContext --- this is not actually a separate context, but a global
variable pointing to the context that holds the current command's parse
and plan trees. (In simple-Query mode this points to MessageContext;
when executing a prepared statement it will point at the prepared
statement's private context.) Generally it is not appropriate for any
code to use QueryContext as an allocation target --- from the point of
view of any code that would be referencing the QueryContext variable,
it's a read-only context.
variable pointing to the context that holds the current command's parse tree.
(In simple-Query mode this points to MessageContext; when executing a
prepared statement it will point to the prepared statement's private context.
Note that the plan tree may or may not be in this same context.)
Generally it is not appropriate for any code to use QueryContext as an
allocation target --- from the point of view of any code that would be
referencing the QueryContext variable, it's a read-only context.
PortalContext --- this is not actually a separate context either, but a
global variable pointing to the per-portal context of the currently active
......
......@@ -12,7 +12,7 @@
* Portions Copyright (c) 1994, Regents of the University of California
*
* IDENTIFICATION
* $PostgreSQL: pgsql/src/backend/utils/mmgr/portalmem.c,v 1.93 2006/08/29 02:11:30 momjian Exp $
* $PostgreSQL: pgsql/src/backend/utils/mmgr/portalmem.c,v 1.94 2006/09/07 22:52:01 tgl Exp $
*
*-------------------------------------------------------------------------
*/
......@@ -266,15 +266,14 @@ CreateNewPortal(void)
* Notes: commandTag shall be NULL if and only if the original query string
* (before rewriting) was an empty string. Also, the passed commandTag must
* be a pointer to a constant string, since it is not copied. The caller is
* responsible for ensuring that the passed sourceText (if any), parse and
* plan trees have adequate lifetime. Also, queryContext must accurately
* describe the location of the parse and plan trees.
* responsible for ensuring that the passed prepStmtName (if any), sourceText
* (if any), parse and plan trees have adequate lifetime. Also, queryContext
* must accurately describe the location of the parse trees.
*/
void
PortalDefineQuery(Portal portal,
const char *prepStmtName,
const char *sourceText,
const char *bindText,
const char *commandTag,
List *parseTrees,
List *planTrees,
......@@ -289,7 +288,6 @@ PortalDefineQuery(Portal portal,
portal->prepStmtName = prepStmtName;
portal->sourceText = sourceText;
portal->bindText = bindText;
portal->commandTag = commandTag;
portal->parseTrees = parseTrees;
portal->planTrees = planTrees;
......
......@@ -7,14 +7,14 @@
* Portions Copyright (c) 1996-2006, PostgreSQL Global Development Group
* Portions Copyright (c) 1994, Regents of the University of California
*
* $PostgreSQL: pgsql/src/include/tcop/utility.h,v 1.28 2006/08/12 20:05:56 tgl Exp $
* $PostgreSQL: pgsql/src/include/tcop/utility.h,v 1.29 2006/09/07 22:52:01 tgl Exp $
*
*-------------------------------------------------------------------------
*/
#ifndef UTILITY_H
#define UTILITY_H
#include "executor/execdesc.h"
#include "tcop/tcopprot.h"
extern void ProcessUtility(Node *parsetree, ParamListInfo params,
......@@ -28,6 +28,10 @@ extern const char *CreateCommandTag(Node *parsetree);
extern const char *CreateQueryTag(Query *parsetree);
extern LogStmtLevel GetCommandLogLevel(Node *parsetree);
extern LogStmtLevel GetQueryLogLevel(Query *parsetree);
extern bool QueryReturnsTuples(Query *parsetree);
extern bool QueryIsReadOnly(Query *parsetree);
......
......@@ -39,7 +39,7 @@
* Portions Copyright (c) 1996-2006, PostgreSQL Global Development Group
* Portions Copyright (c) 1994, Regents of the University of California
*
* $PostgreSQL: pgsql/src/include/utils/portal.h,v 1.69 2006/09/03 03:19:45 momjian Exp $
* $PostgreSQL: pgsql/src/include/utils/portal.h,v 1.70 2006/09/07 22:52:01 tgl Exp $
*
*-------------------------------------------------------------------------
*/
......@@ -110,7 +110,7 @@ typedef struct PortalData
{
/* Bookkeeping data */
const char *name; /* portal's name */
const char *prepStmtName; /* protocol prepare name */
const char *prepStmtName; /* source prepared statement (NULL if none) */
MemoryContext heap; /* subsidiary memory for portal */
ResourceOwner resowner; /* resources owned by portal */
void (*cleanup) (Portal portal); /* cleanup hook */
......@@ -122,20 +122,20 @@ typedef struct PortalData
*/
/* 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 *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) */
MemoryContext queryContext; /* where the above trees live */
MemoryContext queryContext; /* where the parse trees live */
/*
* Note: queryContext effectively identifies which prepared statement the
* portal depends on, if any. The queryContext is *not* owned by the
* portal and is not to be deleted by portal destruction. (But for a
* cursor it is the same as "heap", and that context is deleted by portal
* destruction.)
* destruction.) The plan trees may be in either queryContext or heap.
*/
ParamListInfo portalParams; /* params to pass to query */
/* Features/options */
......@@ -216,7 +216,6 @@ extern Portal GetPortalByName(const char *name);
extern void PortalDefineQuery(Portal portal,
const char *prepStmtName,
const char *sourceText,
const char *bindText,
const char *commandTag,
List *parseTrees,
List *planTrees,
......
Markdown is supported
0% .
You are about to add 0 people to the discussion. Proceed with caution.
先完成此消息的编辑!
想要评论请 注册