Bruce Momjian wrote:
> Tom Lane wrote:
> > Bruce Momjian <pgman@candle.pha.pa.us> writes:
> > > a null for the prepare string. Also, rather than change the API for
> > > pg_parse_query(), I use a global variable that I check after the
> > > function call.
> >
> > This is horribly ugly and will doubtless lead to pfree crashes. What
>
> Agreed, it needs work. I modified the patch to use malloc/free so that
> you can always free the memory at the top of the function.
>
> > was the point again?
>
> Simon said that the EXECUTE is pretty useless for debugging unless we
> show the prepare query. His patch shows the prepare query for
> client-side prepare, but not for server side when using the
> PREPARE/EXECUTE commands --- seems we should display it in both cases.

Here is an updated version of the patch. It pulls post-parse logging
out into a separate function, called log_after_parse(), so we only log
in places we want it. I added code to log client-side parse, and
prepare, were appropriate, and have the logging of client-side and
server-side execute with the PREPARE string.

--
Bruce Momjian | http://candle.pha.pa.us
pgman@candle.pha.pa.us | (610) 359-1001
+ If your life is a hard drive, | 13 Roberts Road
+ Christ can be your backup. | Newtown Square, Pennsylvania 19073

Index: src/backend/commands/prepare.c
================================================== =================
RCS file: /cvsroot/pgsql/src/backend/commands/prepare.c,v
retrieving revision 1.36
diff -c -c -r1.36 prepare.c
*** src/backend/commands/prepare.c 1 Jan 2005 05:43:06 -0000 1.36
--- src/backend/commands/prepare.c 20 May 2005 14:15:12 -0000
***************
*** 104,112 ****
/* Generate plans for queries. Snapshot is already set. */
plan_list = pg_plan_queries(query_list, NULL, false);

! /* Save the results. */
StorePreparedStatement(stmt->name,
! NULL, /* text form not available */
commandTag,
query_list,
plan_list,
--- 104,115 ----
/* Generate plans for queries. Snapshot is already set. */
plan_list = pg_plan_queries(query_list, NULL, false);

! /*
! * 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,
! debug_query_string,
commandTag,
query_list,
plan_list,
Index: src/backend/tcop/postgres.c
================================================== =================
RCS file: /cvsroot/pgsql/src/backend/tcop/postgres.c,v
retrieving revision 1.443
diff -c -c -r1.443 postgres.c
*** src/backend/tcop/postgres.c 21 Apr 2005 19:18:13 -0000 1.443
--- src/backend/tcop/postgres.c 20 May 2005 14:15:17 -0000
***************
*** 82,90 ****

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;

--- 82,87 ----
***************
*** 152,157 ****
--- 149,156 ----
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,538 ****
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)
- {
- 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 */
- {
- 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))
- {
- ereport(LOG,
- (errmsg("statement: %s", query_string)));
- statement_logged = true;
- break;
- }
- }
- }
-
if (log_parser_stats)
ShowUsage("PARSER STATISTICS");

return raw_parsetree_list;
}

/*
* Given a raw parsetree (gram.y output), and optionally information about
* types of parameter symbols ($n), perform parse analysis and rule rewriting.
--- 464,557 ----
pg_parse_query(const char *query_string)
{
List *raw_parsetree_list;

if (log_parser_stats)
ResetUsage();

raw_parsetree_list = raw_parser(query_string);

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)
+ {
+ 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))
+ {
+ ExecuteStmt *stmt = (ExecuteStmt *) parsetree;
+ PreparedStatement *entry;
+
+ if ((entry = FetchPreparedStatement(stmt->name, false)) != NULL &&
+ entry->query_string)
+ {
+ *prepare_string = palloc(strlen(entry->query_string) +
+ strlen(" [client PREPARE: %s]") - 1);
+ sprintf(*prepare_string, " [client PREPARE: %s]",
+ entry->query_string);
+ }
+ }
+ }
+
+ 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,746 ****
MemoryContext oldcontext;
List *parsetree_list;
ListCell *parsetree_item;
! 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;
!
/*
* Report query to various monitoring facilities.
*/
--- 754,766 ----
MemoryContext oldcontext;
List *parsetree_list;
ListCell *parsetree_item;
! 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,801 ****
--- 816,825 ----
*/
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,1020 ****
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 (statement_logged && save_log_duration)
ereport(LOG,
(errmsg("duration: %ld.%03ld ms",
(long) ((stop_t.tv_sec - start_t.tv_sec) * 1000 +
--- 1035,1045 ----
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 (was_logged && save_log_duration)
ereport(LOG,
(errmsg("duration: %ld.%03ld ms",
(long) ((stop_t.tv_sec - start_t.tv_sec) * 1000 +
***************
*** 1029,1044 ****
(save_log_min_duration_statement > 0 &&
usecs >= save_log_min_duration_statement * 1000))
ereport(LOG,
! (errmsg("duration: %ld.%03ld ms statement: %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)));
}

if (save_log_statement_stats)
ShowUsage("QUERY STATISTICS");

debug_query_string = NULL;
}

--- 1054,1073 ----
(save_log_min_duration_statement > 0 &&
usecs >= save_log_min_duration_statement * 1000))
ereport(LOG,
! (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,
! prepare_string ? prepare_string : "")));
}

if (save_log_statement_stats)
ShowUsage("QUERY STATISTICS");

+ if (prepare_string != NULL)
+ pfree(prepare_string);
+
debug_query_string = NULL;
}

***************
*** 1074,1079 ****
--- 1103,1112 ----
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,1376 ****
--- 1404,1413 ----
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,1584 ****
--- 1616,1625 ----
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,1620 ****
--- 1656,1679 ----

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,1714 ****
--- 1768,1817 ----
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;
}



---------------------------(end of broadcast)---------------------------
TIP 2: you can get off all lists at once with the unregister command
(send "unregister YourEmailAddressHere" to majordomo@postgresql.org)

Applied.

---------------------------------------------------------------------------

Bruce Momjian wrote:
> Bruce Momjian wrote:
> > Tom Lane wrote:
> > > Bruce Momjian <pgman@candle.pha.pa.us> writes:
> > > > a null for the prepare string. Also, rather than change the API for
> > > > pg_parse_query(), I use a global variable that I check after the
> > > > function call.
> > >
> > > This is horribly ugly and will doubtless lead to pfree crashes. What
> >
> > Agreed, it needs work. I modified the patch to use malloc/free so that
> > you can always free the memory at the top of the function.
> >
> > > was the point again?
> >
> > Simon said that the EXECUTE is pretty useless for debugging unless we
> > show the prepare query. His patch shows the prepare query for
> > client-side prepare, but not for server side when using the
> > PREPARE/EXECUTE commands --- seems we should display it in both cases.
>
> Here is an updated version of the patch. It pulls post-parse logging
> out into a separate function, called log_after_parse(), so we only log
> in places we want it. I added code to log client-side parse, and
> prepare, were appropriate, and have the logging of client-side and
> server-side execute with the PREPARE string.
>
> --
> Bruce Momjian | http://candle.pha.pa.us
> pgman@candle.pha.pa.us | (610) 359-1001
> + If your life is a hard drive, | 13 Roberts Road
> + Christ can be your backup. | Newtown Square, Pennsylvania 19073

> Index: src/backend/commands/prepare.c
> ================================================== =================
> RCS file: /cvsroot/pgsql/src/backend/commands/prepare.c,v
> retrieving revision 1.36
> diff -c -c -r1.36 prepare.c
> *** src/backend/commands/prepare.c 1 Jan 2005 05:43:06 -0000 1.36
> --- src/backend/commands/prepare.c 20 May 2005 14:15:12 -0000
> ***************
> *** 104,112 ****
> /* Generate plans for queries. Snapshot is already set. */
> plan_list = pg_plan_queries(query_list, NULL, false);
>
> ! /* Save the results. */
> StorePreparedStatement(stmt->name,
> ! NULL, /* text form not available */
> commandTag,
> query_list,
> plan_list,
> --- 104,115 ----
> /* Generate plans for queries. Snapshot is already set. */
> plan_list = pg_plan_queries(query_list, NULL, false);
>
> ! /*
> ! * 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,
> ! debug_query_string,
> commandTag,
> query_list,
> plan_list,
> Index: src/backend/tcop/postgres.c
> ================================================== =================
> RCS file: /cvsroot/pgsql/src/backend/tcop/postgres.c,v
> retrieving revision 1.443
> diff -c -c -r1.443 postgres.c
> *** src/backend/tcop/postgres.c 21 Apr 2005 19:18:13 -0000 1.443
> --- src/backend/tcop/postgres.c 20 May 2005 14:15:17 -0000
> ***************
> *** 82,90 ****
>
> 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;
>
> --- 82,87 ----
> ***************
> *** 152,157 ****
> --- 149,156 ----
> 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,538 ****
> 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)
> - {
> - 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 */
> - {
> - 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))
> - {
> - ereport(LOG,
> - (errmsg("statement: %s", query_string)));
> - statement_logged = true;
> - break;
> - }
> - }
> - }
> -
> if (log_parser_stats)
> ShowUsage("PARSER STATISTICS");
>
> return raw_parsetree_list;
> }
>
> /*
> * Given a raw parsetree (gram.y output), and optionally information about
> * types of parameter symbols ($n), perform parse analysis and rule rewriting.
> --- 464,557 ----
> pg_parse_query(const char *query_string)
> {
> List *raw_parsetree_list;
>
> if (log_parser_stats)
> ResetUsage();
>
> raw_parsetree_list = raw_parser(query_string);
>
> 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)
> + {
> + 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))
> + {
> + ExecuteStmt *stmt = (ExecuteStmt *) parsetree;
> + PreparedStatement *entry;
> +
> + if ((entry = FetchPreparedStatement(stmt->name, false)) != NULL &&
> + entry->query_string)
> + {
> + *prepare_string = palloc(strlen(entry->query_string) +
> + strlen(" [client PREPARE: %s]") - 1);
> + sprintf(*prepare_string, " [client PREPARE: %s]",
> + entry->query_string);
> + }
> + }
> + }
> +
> + 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,746 ****
> MemoryContext oldcontext;
> List *parsetree_list;
> ListCell *parsetree_item;
> ! 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;
> !
> /*
> * Report query to various monitoring facilities.
> */
> --- 754,766 ----
> MemoryContext oldcontext;
> List *parsetree_list;
> ListCell *parsetree_item;
> ! 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,801 ****
> --- 816,825 ----
> */
> 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,1020 ****
> 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 (statement_logged && save_log_duration)
> ereport(LOG,
> (errmsg("duration: %ld.%03ld ms",
> (long) ((stop_t.tv_sec - start_t.tv_sec) * 1000 +
> --- 1035,1045 ----
> 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 (was_logged && save_log_duration)
> ereport(LOG,
> (errmsg("duration: %ld.%03ld ms",
> (long) ((stop_t.tv_sec - start_t.tv_sec) * 1000 +
> ***************
> *** 1029,1044 ****
> (save_log_min_duration_statement > 0 &&
> usecs >= save_log_min_duration_statement * 1000))
> ereport(LOG,
> ! (errmsg("duration: %ld.%03ld ms statement: %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)));
> }
>
> if (save_log_statement_stats)
> ShowUsage("QUERY STATISTICS");
>
> debug_query_string = NULL;
> }
>
> --- 1054,1073 ----
> (save_log_min_duration_statement > 0 &&
> usecs >= save_log_min_duration_statement * 1000))
> ereport(LOG,
> ! (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,
> ! prepare_string ? prepare_string : "")));
> }
>
> if (save_log_statement_stats)
> ShowUsage("QUERY STATISTICS");
>
> + if (prepare_string != NULL)
> + pfree(prepare_string);
> +
> debug_query_string = NULL;
> }
>
> ***************
> *** 1074,1079 ****
> --- 1103,1112 ----
> 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,1376 ****
> --- 1404,1413 ----
> 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,1584 ****
> --- 1616,1625 ----
> 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,1620 ****
> --- 1656,1679 ----
>
> 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,1714 ****
> --- 1768,1817 ----
> 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;
> }
>

>
> ---------------------------(end of broadcast)---------------------------
> TIP 2: you can get off all lists at once with the unregister command
> (send "unregister YourEmailAddressHere" to majordomo@postgresql.org)

--
Bruce Momjian | http://candle.pha.pa.us
pgman@candle.pha.pa.us | (610) 359-1001
+ If your life is a hard drive, | 13 Roberts Road
+ Christ can be your backup. | Newtown Square, Pennsylvania 19073

---------------------------(end of broadcast)---------------------------
TIP 3: 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