From 893632be4e17ccd791cfda17d2e99bb2312f6ff8 Mon Sep 17 00:00:00 2001 From: Tom Lane Date: Thu, 7 Sep 2006 22:52:01 +0000 Subject: [PATCH] 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 : SELECT * FROM test1 WHERE t = $1 DETAIL: parameters: $1 = 'joe''s place' LOG: statement: execute : 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 : SELECT * FROM test1 WHERE t = $1 LOG: duration: 2.335 ms bind to : SELECT * FROM test1 WHERE t = $1 DETAIL: parameters: $1 = 'joe''s place' LOG: duration: 0.394 ms execute : SELECT * FROM test1 WHERE t = $1 DETAIL: parameters: $1 = 'joe''s place' LOG: duration: 1.251 ms parse : SELECT * FROM test1 WHERE i = $1::int4 LOG: duration: 0.566 ms bind to : SELECT * FROM test1 WHERE i = $1::int4 DETAIL: parameters: $1 = '2' LOG: duration: 0.173 ms execute : 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. --- doc/src/sgml/config.sgml | 98 +++-- src/backend/commands/portalcmds.c | 5 +- src/backend/commands/prepare.c | 3 +- src/backend/executor/spi.c | 3 +- src/backend/tcop/postgres.c | 597 ++++++++++++++++------------- src/backend/tcop/utility.c | 394 ++++++++++++++++++- src/backend/utils/mmgr/README | 16 +- src/backend/utils/mmgr/portalmem.c | 10 +- src/include/tcop/utility.h | 8 +- src/include/utils/portal.h | 13 +- 10 files changed, 828 insertions(+), 319 deletions(-) diff --git a/doc/src/sgml/config.sgml b/doc/src/sgml/config.sgml index 2472c16a3f..669110a5fd 100644 --- a/doc/src/sgml/config.sgml +++ b/doc/src/sgml/config.sgml @@ -1,4 +1,4 @@ - + Server Configuration @@ -2492,18 +2492,36 @@ SELECT * FROM parent WHERE key = 2400; - 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 250 + 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 250 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 log_statement and - log_duration. 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. + + + For clients using extended query protocol, durations of the Parse, + Bind, and Execute steps are logged independently. + + + + + When using this option together with + , + the text of statements that are logged because of + log_statement will not be repeated in the + duration log message. + If you are not using syslog, it is recommended + that you log the PID or session ID using + + so that you can link the statement message to the later + duration message using the process ID or session ID. + + @@ -2695,14 +2713,30 @@ SELECT * FROM parent WHERE key = 2400; - Causes the duration of every completed statement which satisfies - log_statement to be logged. When using this option, - if you are not using syslog, it is recommended - that you log the PID or session ID using 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 - off. Only superusers can change this setting. + Causes the duration of every completed statement to be logged. + The default is off. + Only superusers can change this setting. + + + For clients using extended query protocol, durations of the Parse, + Bind, and Execute steps are logged independently. + + + + + When using this option together with + , + the text of statements that are logged because of + log_statement will not be repeated in the + duration log message. + If you are not using syslog, it is recommended + that you log the PID or session ID using + + so that you can link the statement message to the later + duration message using the process ID or session ID. + + @@ -2829,18 +2863,20 @@ SELECT * FROM parent WHERE key = 2400; Controls which SQL statements are logged. Valid values are none, ddl, mod, and all. ddl logs all data definition - commands like CREATE, ALTER, and - DROP commands. mod logs all - ddl statements, plus INSERT, - UPDATE, DELETE, TRUNCATE, - and COPY FROM. PREPARE and - 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 - log_statement is all. Bind parameter - values are also logged if they are supplied in text - format (literal single quotes are doubled). + statements, such as CREATE, ALTER, and + DROP statements. mod logs all + ddl statements, plus data-modifying statements + such as INSERT, + UPDATE, DELETE, TRUNCATE, + and COPY FROM. + PREPARE, EXECUTE, and + 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). + The default is none. Only superusers can change this setting. @@ -2848,9 +2884,7 @@ SELECT * FROM parent WHERE key = 2400; - The EXECUTE statement is not considered a - ddl or mod statement. Statements that - generate syntax errors are not logged. Set + Statements that generate syntax errors are not logged. Set log_min_error_statement to error to log such statements. diff --git a/src/backend/commands/portalcmds.c b/src/backend/commands/portalcmds.c index e418fabfc5..48833e7dc0 100644 --- a/src/backend/commands/portalcmds.c +++ b/src/backend/commands/portalcmds.c @@ -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), diff --git a/src/backend/commands/prepare.c b/src/backend/commands/prepare.c index dc26430671..eccce9d10d 100644 --- a/src/backend/commands/prepare.c +++ b/src/backend/commands/prepare.c @@ -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, diff --git a/src/backend/executor/spi.c b/src/backend/executor/spi.c index dc3ab9e7c3..eb8d11fed9 100644 --- a/src/backend/executor/spi.c +++ b/src/backend/executor/spi.c @@ -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, diff --git a/src/backend/tcop/postgres.c b/src/backend/tcop/postgres.c index 2e128ece13..30c722f4ad 100644 --- a/src/backend/tcop/postgres.c +++ b/src/backend/tcop/postgres.c @@ -8,7 +8,7 @@ * * * IDENTIFICATION - * $PostgreSQL: pgsql/src/backend/tcop/postgres.c,v 1.506 2006/09/06 20:40:48 tgl Exp $ + * $PostgreSQL: pgsql/src/backend/tcop/postgres.c,v 1.507 2006/09/07 22:52:01 tgl Exp $ * * NOTES * this is the "main" module of the postgres backend and @@ -156,9 +156,12 @@ static int UseNewLine = 0; /* Use EOF as query delimiters */ static int InteractiveBackend(StringInfo inBuf); static int SocketBackend(StringInfo inBuf); static int ReadCommand(StringInfo inBuf); -static bool log_after_parse(List *raw_parsetree_list, - const char *query_string, char **prepare_string); static List *pg_rewrite_queries(List *querytree_list); +static bool check_log_statement_raw(List *raw_parsetree_list); +static bool check_log_statement_cooked(List *parsetree_list); +static bool check_log_duration(char *msec_str); +static int errdetail_execute(List *raw_parsetree_list); +static int errdetail_params(ParamListInfo params); static void start_xact_command(void); static void finish_xact_command(void); static bool IsTransactionExitStmt(Node *parsetree); @@ -533,83 +536,6 @@ pg_parse_query(const char *query_string) return raw_parsetree_list; } -static bool -log_after_parse(List *raw_parsetree_list, const char *query_string, - char **prepare_string) -{ - ListCell *parsetree_item; - bool log_this_statement = (log_statement == LOGSTMT_ALL); - - *prepare_string = NULL; - - /* Check if we need to log the statement, and get prepare_string. */ - foreach(parsetree_item, raw_parsetree_list) - { - Node *parsetree = (Node *) lfirst(parsetree_item); - const char *commandTag; - - if (IsA(parsetree, ExplainStmt) && - ((ExplainStmt *) parsetree)->analyze) - parsetree = (Node *) (((ExplainStmt *) parsetree)->query); - - if (IsA(parsetree, PrepareStmt)) - parsetree = (Node *) (((PrepareStmt *) parsetree)->query); - - if (IsA(parsetree, SelectStmt) && - ((SelectStmt *) parsetree)->into == NULL) - continue; /* optimization for frequent command */ - - if (log_statement == LOGSTMT_MOD && - (IsA(parsetree, InsertStmt) || - IsA(parsetree, UpdateStmt) || - IsA(parsetree, DeleteStmt) || - IsA(parsetree, TruncateStmt) || - (IsA(parsetree, CopyStmt) && - ((CopyStmt *) parsetree)->is_from))) /* COPY FROM */ - log_this_statement = true; - - commandTag = CreateCommandTag(parsetree); - if ((log_statement == LOGSTMT_MOD || - log_statement == LOGSTMT_DDL) && - (strncmp(commandTag, "CREATE ", strlen("CREATE ")) == 0 || - IsA(parsetree, SelectStmt) || /* SELECT INTO, CREATE AS */ - strncmp(commandTag, "ALTER ", strlen("ALTER ")) == 0 || - strncmp(commandTag, "DROP ", strlen("DROP ")) == 0 || - IsA(parsetree, GrantStmt) || /* GRANT or REVOKE */ - IsA(parsetree, CommentStmt))) - log_this_statement = true; - - /* - * 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)) - { - ExecuteStmt *stmt = (ExecuteStmt *) parsetree; - PreparedStatement *entry; - - 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 - return false; -} - - /* * Given a raw parsetree (gram.y output), and optionally information about * types of parameter symbols ($n), perform parse analysis and rule rewriting. @@ -817,8 +743,8 @@ exec_simple_query(const char *query_string) List *parsetree_list; ListCell *parsetree_item; bool save_log_statement_stats = log_statement_stats; - char *prepare_string = NULL; bool was_logged = false; + char msec_str[32]; /* * Report query to various monitoring facilities. @@ -871,9 +797,13 @@ exec_simple_query(const char *query_string) parsetree_list = pg_parse_query(query_string); /* Log immediately if dictated by log_statement */ - if (log_statement != LOGSTMT_NONE || log_duration || - log_min_duration_statement >= 0) - was_logged = log_after_parse(parsetree_list, query_string, &prepare_string); + if (check_log_statement_raw(parsetree_list)) + { + ereport(LOG, + (errmsg("statement: %s", query_string), + errdetail_execute(parsetree_list))); + was_logged = true; + } /* * Switch back to transaction context to enter the loop. @@ -954,7 +884,6 @@ exec_simple_query(const char *query_string) PortalDefineQuery(portal, NULL, query_string, - NULL, commandTag, querytree_list, plantree_list, @@ -1066,49 +995,21 @@ exec_simple_query(const char *query_string) /* * Emit duration logging if appropriate. */ - if (log_duration || log_min_duration_statement >= 0) + if (check_log_duration(msec_str)) { - long secs; - int usecs; - int msecs; - - TimestampDifference(GetCurrentStatementStartTimestamp(), - GetCurrentTimestamp(), - &secs, &usecs); - msecs = usecs / 1000; - - /* - * The odd-looking test for log_min_duration_statement being - * exceeded is designed to avoid integer overflow with very - * long durations: don't compute secs * 1000 until we've - * verified it will fit in int. - */ - if (log_duration || - log_min_duration_statement == 0 || - (log_min_duration_statement > 0 && - (secs > log_min_duration_statement / 1000 || - secs * 1000 + msecs >= log_min_duration_statement))) - { - if (was_logged) - ereport(LOG, - (errmsg("duration: %ld.%03d ms", - 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)); - } + if (was_logged) + ereport(LOG, + (errmsg("duration: %s ms", msec_str))); + else + ereport(LOG, + (errmsg("duration: %s ms statement: %s", + msec_str, query_string), + errdetail_execute(parsetree_list))); } if (save_log_statement_stats) ShowUsage("QUERY STATISTICS"); - if (prepare_string != NULL) - pfree(prepare_string); - debug_query_string = NULL; } @@ -1131,6 +1032,7 @@ exec_parse_message(const char *query_string, /* string to execute */ *param_list; bool is_named; bool save_log_statement_stats = log_statement_stats; + char msec_str[32]; /* * Report query to various monitoring facilities. @@ -1144,11 +1046,10 @@ exec_parse_message(const char *query_string, /* string to execute */ if (save_log_statement_stats) ResetUsage(); - if (log_statement == LOGSTMT_ALL) - ereport(LOG, - (errmsg("statement: prepare %s: %s", - *stmt_name ? stmt_name : "", - query_string))); + ereport(DEBUG2, + (errmsg("parse %s: %s", + *stmt_name ? stmt_name : "", + query_string))); /* * Start up a transaction command so we can run parse analysis etc. (Note @@ -1343,6 +1244,16 @@ exec_parse_message(const char *query_string, /* string to execute */ if (whereToSendOutput == DestRemote) pq_putemptymessage('1'); + /* + * Emit duration logging if appropriate. + */ + if (check_log_duration(msec_str)) + ereport(LOG, + (errmsg("duration: %s ms parse %s: %s", + msec_str, + *stmt_name ? stmt_name : "", + query_string))); + if (save_log_statement_stats) ShowUsage("PARSE MESSAGE STATISTICS"); @@ -1368,12 +1279,44 @@ exec_bind_message(StringInfo input_message) Portal portal; ParamListInfo params; List *plan_list; - StringInfoData bind_values_str; + MemoryContext qContext; + bool save_log_statement_stats = log_statement_stats; + char msec_str[32]; - pgstat_report_activity(""); + /* Get the fixed part of the message */ + portal_name = pq_getmsgstring(input_message); + stmt_name = pq_getmsgstring(input_message); + + ereport(DEBUG2, + (errmsg("bind %s to %s", + *portal_name ? portal_name : "", + *stmt_name ? stmt_name : ""))); + + /* Find prepared statement */ + if (stmt_name[0] != '\0') + pstmt = FetchPreparedStatement(stmt_name, true); + else + { + /* special-case the unnamed statement */ + pstmt = unnamed_stmt_pstmt; + if (!pstmt) + ereport(ERROR, + (errcode(ERRCODE_UNDEFINED_PSTATEMENT), + errmsg("unnamed prepared statement does not exist"))); + } + + /* + * Report query to various monitoring facilities. + */ + debug_query_string = "bind message"; + + pgstat_report_activity(pstmt->query_string ? pstmt->query_string : ""); set_ps_display("BIND", false); + if (save_log_statement_stats) + ResetUsage(); + /* * Start up a transaction command so we can call functions etc. (Note that * this will normally change current memory context.) Nothing happens if @@ -1384,12 +1327,6 @@ exec_bind_message(StringInfo input_message) /* Switch back to message context */ MemoryContextSwitchTo(MessageContext); - initStringInfo(&bind_values_str); - - /* Get the fixed part of the message */ - portal_name = pq_getmsgstring(input_message); - stmt_name = pq_getmsgstring(input_message); - /* Get the parameter format codes */ numPFormats = pq_getmsgint(input_message, 2); if (numPFormats > 0) @@ -1410,19 +1347,6 @@ exec_bind_message(StringInfo input_message) errmsg("bind message has %d parameter formats but %d parameters", numPFormats, numParams))); - /* Find prepared statement */ - if (stmt_name[0] != '\0') - pstmt = FetchPreparedStatement(stmt_name, true); - else - { - /* special-case the unnamed statement */ - pstmt = unnamed_stmt_pstmt; - if (!pstmt) - ereport(ERROR, - (errcode(ERRCODE_UNDEFINED_PSTATEMENT), - errmsg("unnamed prepared statement does not exist"))); - } - if (numParams != list_length(pstmt->argtype_list)) ereport(ERROR, (errcode(ERRCODE_PROTOCOL_VIOLATION), @@ -1521,7 +1445,7 @@ exec_bind_message(StringInfo input_message) { Oid typinput; Oid typioparam; - char *pstring, *p; + char *pstring; getTypeInputInfo(ptype, &typinput, &typioparam); @@ -1536,24 +1460,6 @@ exec_bind_message(StringInfo input_message) pval = OidInputFunctionCall(typinput, pstring, typioparam, -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); @@ -1582,8 +1488,6 @@ exec_bind_message(StringInfo input_message) (errcode(ERRCODE_INVALID_BINARY_REPRESENTATION), errmsg("incorrect binary data format in bind parameter %d", paramno + 1))); - - /* XXX TODO: convert value to text and log it */ } else { @@ -1617,19 +1521,6 @@ exec_bind_message(StringInfo input_message) else params = NULL; - if (log_statement == LOGSTMT_ALL) - { - ereport(LOG, - (errmsg("statement: bind %s%s%s%s%s", - *stmt_name ? stmt_name : "", - *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 */ numRFormats = pq_getmsgint(input_message, 2); if (numRFormats > 0) @@ -1654,32 +1545,37 @@ exec_bind_message(StringInfo input_message) * * XXX because the planner has a bad habit of scribbling on its input, * we have to make a copy of the parse trees, just in case someone binds - * and executes an unnamed statement multiple times. FIXME someday + * and executes an unnamed statement multiple times; this also means that + * the portal's queryContext becomes its own heap context rather than the + * prepared statement's context. FIXME someday */ if (pstmt->plan_list == NIL && pstmt->query_list != NIL) { MemoryContext oldContext; - oldContext = MemoryContextSwitchTo(PortalGetHeapMemory(portal)); + qContext = PortalGetHeapMemory(portal); + oldContext = MemoryContextSwitchTo(qContext); plan_list = pg_plan_queries(copyObject(pstmt->query_list), params, true); MemoryContextSwitchTo(oldContext); } else + { plan_list = pstmt->plan_list; + qContext = pstmt->context; + } /* * Define portal and start execution. */ PortalDefineQuery(portal, - *stmt_name ? pstrdup(stmt_name) : NULL, + *pstmt->stmt_name ? pstmt->stmt_name : NULL, pstmt->query_string, - bind_values_str.len ? pstrdup(bind_values_str.data) : NULL, pstmt->commandTag, pstmt->query_list, plan_list, - pstmt->context); + qContext); PortalStart(portal, params, InvalidSnapshot); @@ -1693,6 +1589,23 @@ exec_bind_message(StringInfo input_message) */ if (whereToSendOutput == DestRemote) pq_putemptymessage('2'); + + /* + * Emit duration logging if appropriate. + */ + if (check_log_duration(msec_str)) + ereport(LOG, + (errmsg("duration: %s ms bind %s to %s: %s", + msec_str, + *portal_name ? portal_name : "", + *stmt_name ? stmt_name : "", + pstmt->query_string ? pstmt->query_string : ""), + errdetail_params(params))); + + if (save_log_statement_stats) + ShowUsage("BIND MESSAGE STATISTICS"); + + debug_query_string = NULL; } /* @@ -1708,12 +1621,14 @@ exec_execute_message(const char *portal_name, long max_rows) Portal portal; bool completed; char completionTag[COMPLETION_TAG_BUFSIZE]; - const char *sourceText = NULL; - const char *bindText = NULL; + const char *sourceText; const char *prepStmtName; + ParamListInfo portalParams; bool save_log_statement_stats = log_statement_stats; bool is_xact_command; bool execute_is_fetch; + bool was_logged = false; + char msec_str[32]; /* Adjust destination to tell printtup.c what to do */ dest = whereToSendOutput; @@ -1737,6 +1652,18 @@ exec_execute_message(const char *portal_name, long max_rows) return; } + /* + * Report query to various monitoring facilities. + */ + debug_query_string = "execute message"; + + pgstat_report_activity(portal->sourceText ? portal->sourceText : ""); + + set_ps_display(portal->commandTag, false); + + if (save_log_statement_stats) + ResetUsage(); + /* Does the portal contain a transaction command? */ is_xact_command = IsTransactionStmtList(portal->parseTrees); @@ -1748,62 +1675,33 @@ exec_execute_message(const char *portal_name, long max_rows) */ execute_is_fetch = !portal->atStart; - /* Should we display the portal names here? */ - if (execute_is_fetch) - { - debug_query_string = "fetch message"; - pgstat_report_activity(""); - } - else - { - debug_query_string = "execute message"; - pgstat_report_activity(""); - } - - set_ps_display(portal->commandTag, false); - - /* copy prepStmtName now too, in case portal is destroyed */ - if (portal->prepStmtName) - prepStmtName = pstrdup(portal->prepStmtName); - else - prepStmtName = ""; - /* - * We must copy the sourceText and bindText into MessageContext + * We must copy the sourceText and prepStmtName 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); + sourceText = pstrdup(portal->sourceText); + if (portal->prepStmtName) + prepStmtName = pstrdup(portal->prepStmtName); else - bindText = portal->bindText; + prepStmtName = ""; + /* + * An xact command shouldn't have any parameters, which is a good + * thing because they wouldn't be around after finish_xact_command. + */ + portalParams = NULL; + } + else + { + sourceText = portal->sourceText; + if (portal->prepStmtName) + prepStmtName = portal->prepStmtName; + else + prepStmtName = ""; + portalParams = portal->portalParams; } - - /* - * We use save_log_statement_stats so ShowUsage doesn't report incorrect - * results because ResetUsage wasn't called. - */ - if (save_log_statement_stats) - ResetUsage(); - - 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); @@ -1819,6 +1717,23 @@ exec_execute_message(const char *portal_name, long max_rows) */ start_xact_command(); + /* Log immediately if dictated by log_statement */ + if (check_log_statement_cooked(portal->parseTrees)) + { + ereport(LOG, + (errmsg("%s %s%s%s%s%s", + execute_is_fetch ? + _("statement: execute fetch from") : + _("statement: execute"), + prepStmtName, + *portal_name ? "/" : "", + *portal_name ? portal_name : "", + sourceText ? ": " : "", + sourceText ? sourceText : ""), + errdetail_params(portalParams))); + was_logged = true; + } + /* * If we are in aborted transaction state, the only portals we can * actually run are those containing COMMIT or ROLLBACK commands. @@ -1879,6 +1794,96 @@ exec_execute_message(const char *portal_name, long max_rows) /* * Emit duration logging if appropriate. */ + if (check_log_duration(msec_str)) + { + if (was_logged) + ereport(LOG, + (errmsg("duration: %s ms", msec_str))); + else + ereport(LOG, + (errmsg("duration: %s ms %s %s%s%s%s%s", + msec_str, + execute_is_fetch ? + _("execute fetch from") : + _("execute"), + prepStmtName, + *portal_name ? "/" : "", + *portal_name ? portal_name : "", + sourceText ? ": " : "", + sourceText ? sourceText : ""), + errdetail_params(portalParams))); + } + + if (save_log_statement_stats) + ShowUsage("EXECUTE MESSAGE STATISTICS"); + + debug_query_string = NULL; +} + +/* + * check_log_statement_raw + * Determine whether command should be logged because of log_statement + * + * raw_parsetree_list is the raw grammar output + */ +static bool +check_log_statement_raw(List *raw_parsetree_list) +{ + ListCell *parsetree_item; + + if (log_statement == LOGSTMT_NONE) + return false; + if (log_statement == LOGSTMT_ALL) + return true; + + /* Else we have to inspect the statement(s) to see whether to log */ + foreach(parsetree_item, raw_parsetree_list) + { + Node *parsetree = (Node *) lfirst(parsetree_item); + + if (GetCommandLogLevel(parsetree) <= log_statement) + return true; + } + + return false; +} + +/* + * check_log_statement_cooked + * As above, but work from already-analyzed querytrees + */ +static bool +check_log_statement_cooked(List *parsetree_list) +{ + ListCell *parsetree_item; + + if (log_statement == LOGSTMT_NONE) + return false; + if (log_statement == LOGSTMT_ALL) + return true; + + /* Else we have to inspect the statement(s) to see whether to log */ + foreach(parsetree_item, parsetree_list) + { + Query *parsetree = (Query *) lfirst(parsetree_item); + + if (GetQueryLogLevel(parsetree) <= log_statement) + return true; + } + + return false; +} + +/* + * check_log_duration + * Determine whether current command's duration should be logged + * + * If logging is needed, the duration in msec is formatted into msec_str[], + * which must be a 32-byte buffer. + */ +static bool +check_log_duration(char *msec_str) +{ if (log_duration || log_min_duration_statement >= 0) { long secs; @@ -1902,29 +1907,109 @@ exec_execute_message(const char *portal_name, long max_rows) (secs > log_min_duration_statement / 1000 || secs * 1000 + msecs >= log_min_duration_statement))) { - if (log_statement == LOGSTMT_ALL) /* already logged? */ - ereport(LOG, - (errmsg("duration: %ld.%03d ms", - 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 : ""))); + snprintf(msec_str, 32, "%ld.%03d", + secs * 1000 + msecs, usecs % 1000); + return true; } } - if (save_log_statement_stats) - ShowUsage("QUERY STATISTICS"); + return false; +} - debug_query_string = NULL; +/* + * errdetail_execute + * + * Add an errdetail() line showing the query referenced by an EXECUTE, if any. + * The argument is the raw parsetree list. + */ +static int +errdetail_execute(List *raw_parsetree_list) +{ + ListCell *parsetree_item; + + foreach(parsetree_item, raw_parsetree_list) + { + Node *parsetree = (Node *) lfirst(parsetree_item); + + if (IsA(parsetree, ExecuteStmt)) + { + ExecuteStmt *stmt = (ExecuteStmt *) parsetree; + PreparedStatement *pstmt; + + pstmt = FetchPreparedStatement(stmt->name, false); + if (pstmt && pstmt->query_string) + { + errdetail("prepare: %s", pstmt->query_string); + return 0; + } + } + } + + return 0; +} + +/* + * errdetail_params + * + * Add an errdetail() line showing bind-parameter data, if available. + */ +static int +errdetail_params(ParamListInfo params) +{ + /* We mustn't call user-defined I/O functions when in an aborted xact */ + if (params && params->numParams > 0 && !IsAbortedTransactionBlockState()) + { + StringInfoData param_str; + MemoryContext oldcontext; + int paramno; + + /* Make sure any trash is generated in MessageContext */ + oldcontext = MemoryContextSwitchTo(MessageContext); + + initStringInfo(¶m_str); + + for (paramno = 0; paramno < params->numParams; paramno++) + { + ParamExternData *prm = ¶ms->params[paramno]; + Oid typoutput; + bool typisvarlena; + char *pstring; + char *p; + + appendStringInfo(¶m_str, "%s$%d = ", + paramno > 0 ? ", " : "", + paramno + 1); + + if (prm->isnull || !OidIsValid(prm->ptype)) + { + appendStringInfoString(¶m_str, "NULL"); + continue; + } + + getTypeOutputInfo(prm->ptype, &typoutput, &typisvarlena); + + pstring = OidOutputFunctionCall(typoutput, prm->value); + + appendStringInfoCharMacro(¶m_str, '\''); + for (p = pstring; *p; p++) + { + if (*p == '\'') /* double single quotes */ + appendStringInfoCharMacro(¶m_str, *p); + appendStringInfoCharMacro(¶m_str, *p); + } + appendStringInfoCharMacro(¶m_str, '\''); + + pfree(pstring); + } + + errdetail("parameters: %s", param_str.data); + + pfree(param_str.data); + + MemoryContextSwitchTo(oldcontext); + } + + return 0; } /* diff --git a/src/backend/tcop/utility.c b/src/backend/tcop/utility.c index 781026b323..868da2d5ff 100644 --- a/src/backend/tcop/utility.c +++ b/src/backend/tcop/utility.c @@ -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; +} diff --git a/src/backend/utils/mmgr/README b/src/backend/utils/mmgr/README index 8c60ad4884..a91dfe3d76 100644 --- a/src/backend/utils/mmgr/README +++ b/src/backend/utils/mmgr/README @@ -1,4 +1,4 @@ -$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 diff --git a/src/backend/utils/mmgr/portalmem.c b/src/backend/utils/mmgr/portalmem.c index cae91572cc..e29ffb53c9 100644 --- a/src/backend/utils/mmgr/portalmem.c +++ b/src/backend/utils/mmgr/portalmem.c @@ -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; diff --git a/src/include/tcop/utility.h b/src/include/tcop/utility.h index 6674dec129..985cfb507b 100644 --- a/src/include/tcop/utility.h +++ b/src/include/tcop/utility.h @@ -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); diff --git a/src/include/utils/portal.h b/src/include/utils/portal.h index 4a546bdda9..a377b0ca21 100644 --- a/src/include/utils/portal.h +++ b/src/include/utils/portal.h @@ -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,