diff --git a/src/backend/commands/prepare.c b/src/backend/commands/prepare.c
index 2a6cbd77f0a169b3de0ce2e8b32f726f46072da2..ada9d534de305fbf16585d235a0282a3fde0c893 100644
--- a/src/backend/commands/prepare.c
+++ b/src/backend/commands/prepare.c
@@ -10,7 +10,7 @@
* Copyright (c) 2002-2005, PostgreSQL Global Development Group
*
* IDENTIFICATION
- * $PostgreSQL: pgsql/src/backend/commands/prepare.c,v 1.36 2005/01/01 05:43:06 momjian Exp $
+ * $PostgreSQL: pgsql/src/backend/commands/prepare.c,v 1.37 2005/05/24 04:18:04 momjian Exp $
*
*-------------------------------------------------------------------------
*/
@@ -104,9 +104,12 @@ PrepareQuery(PrepareStmt *stmt)
/* Generate plans for queries. Snapshot is already set. */
plan_list = pg_plan_queries(query_list, NULL, false);
- /* Save the results. */
+ /*
+ * Save the results. We don't have the query string for this PREPARE,
+ * but we do have the string we got from the client, so use that.
+ */
StorePreparedStatement(stmt->name,
- NULL, /* text form not available */
+ debug_query_string,
commandTag,
query_list,
plan_list,
diff --git a/src/backend/tcop/postgres.c b/src/backend/tcop/postgres.c
index 2872d939ca8fe75d6a1ea6d5907f8e8d2d330e17..3c6c6d992ed12e0f41e5b63336b155f0fbde06b7 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.443 2005/04/21 19:18:13 tgl Exp $
+ * $PostgreSQL: pgsql/src/backend/tcop/postgres.c,v 1.444 2005/05/24 04:18:04 momjian Exp $
*
* NOTES
* this is the "main" module of the postgres backend and
@@ -82,9 +82,6 @@ bool Log_disconnections = false;
LogStmtLevel log_statement = LOGSTMT_NONE;
-/* flag indicating if the statement satisfies log_statement */
-bool statement_logged;
-
/* GUC variable for maximum stack depth (measured in kilobytes) */
int max_stack_depth = 2048;
@@ -152,6 +149,8 @@ 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 void start_xact_command(void);
static void finish_xact_command(void);
static void SigHupHandler(SIGNAL_ARGS);
@@ -465,74 +464,94 @@ List *
pg_parse_query(const char *query_string)
{
List *raw_parsetree_list;
- ListCell *parsetree_item;
-
- statement_logged = false;
- if (log_statement == LOGSTMT_ALL)
- {
- ereport(LOG,
- (errmsg("statement: %s", query_string)));
- statement_logged = true;
- }
if (log_parser_stats)
ResetUsage();
raw_parsetree_list = raw_parser(query_string);
- /* do log_statement tests for mod and ddl */
- if (log_statement == LOGSTMT_MOD ||
- log_statement == LOGSTMT_DDL)
+ if (log_parser_stats)
+ ShowUsage("PARSER STATISTICS");
+
+ 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)
{
- 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))
+ 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 ||
+ 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.
+ */
+ if (IsA(parsetree, ExecuteStmt))
{
- 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))
- 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 */
- {
- ereport(LOG,
- (errmsg("statement: %s", query_string)));
- statement_logged = true;
- break;
- }
- commandTag = CreateCommandTag(parsetree);
- if (strncmp(commandTag, "CREATE ", strlen("CREATE ")) == 0 ||
- strncmp(commandTag, "ALTER ", strlen("ALTER ")) == 0 ||
- strncmp(commandTag, "DROP ", strlen("DROP ")) == 0 ||
- IsA(parsetree, GrantStmt) || /* GRANT or REVOKE */
- IsA(parsetree, CommentStmt))
+ ExecuteStmt *stmt = (ExecuteStmt *) parsetree;
+ PreparedStatement *entry;
+
+ if ((entry = FetchPreparedStatement(stmt->name, false)) != NULL &&
+ entry->query_string)
{
- ereport(LOG,
- (errmsg("statement: %s", query_string)));
- statement_logged = true;
- break;
+ *prepare_string = palloc(strlen(entry->query_string) +
+ strlen(" [client PREPARE: %s]") - 1);
+ sprintf(*prepare_string, " [client PREPARE: %s]",
+ entry->query_string);
}
}
}
-
- if (log_parser_stats)
- ShowUsage("PARSER STATISTICS");
-
- return raw_parsetree_list;
+
+ if (log_this_statement)
+ {
+ ereport(LOG,
+ (errmsg("statement: %s%s", query_string,
+ *prepare_string ? *prepare_string : "")));
+ 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.
@@ -735,12 +754,13 @@ exec_simple_query(const char *query_string)
MemoryContext oldcontext;
List *parsetree_list;
ListCell *parsetree_item;
- struct timeval start_t,
- stop_t;
+ struct timeval start_t, stop_t;
bool save_log_duration = log_duration;
int save_log_min_duration_statement = log_min_duration_statement;
bool save_log_statement_stats = log_statement_stats;
-
+ char *prepare_string = NULL;
+ bool was_logged = false;
+
/*
* Report query to various monitoring facilities.
*/
@@ -796,6 +816,10 @@ exec_simple_query(const char *query_string)
*/
parsetree_list = pg_parse_query(query_string);
+ if (log_statement != LOGSTMT_NONE || save_log_min_duration_statement != -1)
+ was_logged = log_after_parse(parsetree_list, query_string,
+ &prepare_string);
+
/*
* Switch back to transaction context to enter the loop.
*/
@@ -1011,10 +1035,11 @@ exec_simple_query(const char *query_string)
stop_t.tv_sec--;
stop_t.tv_usec += 1000000;
}
- usecs = (long) (stop_t.tv_sec - start_t.tv_sec) * 1000000 + (long) (stop_t.tv_usec - start_t.tv_usec);
+ usecs = (long) (stop_t.tv_sec - start_t.tv_sec) * 1000000 +
+ (long) (stop_t.tv_usec - start_t.tv_usec);
/* Only print duration if we previously printed the statement. */
- if (statement_logged && save_log_duration)
+ if (was_logged && save_log_duration)
ereport(LOG,
(errmsg("duration: %ld.%03ld ms",
(long) ((stop_t.tv_sec - start_t.tv_sec) * 1000 +
@@ -1029,16 +1054,20 @@ exec_simple_query(const char *query_string)
(save_log_min_duration_statement > 0 &&
usecs >= save_log_min_duration_statement * 1000))
ereport(LOG,
- (errmsg("duration: %ld.%03ld ms statement: %s",
+ (errmsg("duration: %ld.%03ld ms statement: %s%s",
(long) ((stop_t.tv_sec - start_t.tv_sec) * 1000 +
(stop_t.tv_usec - start_t.tv_usec) / 1000),
(long) (stop_t.tv_usec - start_t.tv_usec) % 1000,
- query_string)));
+ query_string,
+ prepare_string ? prepare_string : "")));
}
if (save_log_statement_stats)
ShowUsage("QUERY STATISTICS");
+ if (prepare_string != NULL)
+ pfree(prepare_string);
+
debug_query_string = NULL;
}
@@ -1074,6 +1103,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 AS %s", stmt_name, query_string)));
+
/*
* Start up a transaction command so we can run parse analysis etc.
* (Note that this will normally change current memory context.)
@@ -1371,6 +1404,10 @@ exec_bind_message(StringInfo input_message)
else
portal = CreatePortal(portal_name, false, false);
+ if (log_statement == LOGSTMT_ALL)
+ ereport(LOG,
+ (errmsg("statement: <BIND> %s", portal_name)));
+
/*
* Fetch parameters, if any, and store in the portal's memory context.
*
@@ -1579,6 +1616,10 @@ exec_execute_message(const char *portal_name, long max_rows)
bool is_trans_exit = false;
bool completed;
char completionTag[COMPLETION_TAG_BUFSIZE];
+ struct timeval start_t, stop_t;
+ bool save_log_duration = log_duration;
+ int save_log_min_duration_statement = log_min_duration_statement;
+ bool save_log_statement_stats = log_statement_stats;
/* Adjust destination to tell printtup.c what to do */
dest = whereToSendOutput;
@@ -1615,6 +1656,24 @@ exec_execute_message(const char *portal_name, long max_rows)
set_ps_display(portal->commandTag);
+ /*
+ * We use save_log_* so "SET log_duration = true" and "SET
+ * log_min_duration_statement = true" don't report incorrect time
+ * because gettimeofday() wasn't called. Similarly,
+ * log_statement_stats has to be captured once.
+ */
+ if (save_log_duration || save_log_min_duration_statement != -1)
+ gettimeofday(&start_t, NULL);
+
+ if (save_log_statement_stats)
+ ResetUsage();
+
+ if (log_statement == LOGSTMT_ALL)
+ /* We have the portal, so output the source query. */
+ ereport(LOG,
+ (errmsg("statement: EXECUTE %s [PREPARE: %s]", portal_name,
+ portal->sourceText ? portal->sourceText : "")));
+
BeginCommand(portal->commandTag, dest);
/* Check for transaction-control commands */
@@ -1709,6 +1768,50 @@ exec_execute_message(const char *portal_name, long max_rows)
pq_putemptymessage('s');
}
+ /*
+ * Combine processing here as we need to calculate the query duration
+ * in both instances.
+ */
+ if (save_log_duration || save_log_min_duration_statement != -1)
+ {
+ long usecs;
+
+ gettimeofday(&stop_t, NULL);
+ if (stop_t.tv_usec < start_t.tv_usec)
+ {
+ stop_t.tv_sec--;
+ stop_t.tv_usec += 1000000;
+ }
+ usecs = (long) (stop_t.tv_sec - start_t.tv_sec) * 1000000 +
+ (long) (stop_t.tv_usec - start_t.tv_usec);
+
+ /* Only print duration if we previously printed the statement. */
+ if (log_statement == LOGSTMT_ALL && save_log_duration)
+ ereport(LOG,
+ (errmsg("duration: %ld.%03ld ms",
+ (long) ((stop_t.tv_sec - start_t.tv_sec) * 1000 +
+ (stop_t.tv_usec - start_t.tv_usec) / 1000),
+ (long) (stop_t.tv_usec - start_t.tv_usec) % 1000)));
+
+ /*
+ * Output a duration_statement to the log if the query has
+ * exceeded the min duration, or if we are to print all durations.
+ */
+ if (save_log_min_duration_statement == 0 ||
+ (save_log_min_duration_statement > 0 &&
+ usecs >= save_log_min_duration_statement * 1000))
+ ereport(LOG,
+ (errmsg("duration: %ld.%03ld ms statement: EXECUTE %s [PREPARE: %s]",
+ (long) ((stop_t.tv_sec - start_t.tv_sec) * 1000 +
+ (stop_t.tv_usec - start_t.tv_usec) / 1000),
+ (long) (stop_t.tv_usec - start_t.tv_usec) % 1000,
+ portal_name,
+ portal->sourceText ? portal->sourceText : "")));
+ }
+
+ if (save_log_statement_stats)
+ ShowUsage("QUERY STATISTICS");
+
debug_query_string = NULL;
}