From b59d31c21571995ca717c29eabd4022f35c35169 Mon Sep 17 00:00:00 2001
From: Tom Lane <tgl@sss.pgh.pa.us>
Date: Fri, 8 Sep 2006 15:55:53 +0000
Subject: [PATCH] Tweak the behavior of log_duration as proposed by Guillaume
Smet: rather than being equivalent to setting log_min_duration_statement to
zero, this option now forces logging of all query durations, but doesn't
force logging of query text. Also, add duration logging coverage for
fastpath function calls.
---
doc/src/sgml/config.sgml | 29 ++++++-----
src/backend/tcop/fastpath.c | 24 +++++++++-
src/backend/tcop/postgres.c | 96 ++++++++++++++++++++++++-------------
src/include/tcop/tcopprot.h | 3 +-
4 files changed, 103 insertions(+), 49 deletions(-)
diff --git a/doc/src/sgml/config.sgml b/doc/src/sgml/config.sgml
index 669110a5fda..2dcde4c14d1 100644
--- a/doc/src/sgml/config.sgml
+++ b/doc/src/sgml/config.sgml
@@ -1,4 +1,4 @@
-<!-- $PostgreSQL: pgsql/doc/src/sgml/config.sgml,v 1.84 2006/09/07 22:51:59 tgl Exp $ -->
+<!-- $PostgreSQL: pgsql/doc/src/sgml/config.sgml,v 1.85 2006/09/08 15:55:52 tgl Exp $ -->
<chapter Id="runtime-config">
<title>Server Configuration</title>
@@ -2718,23 +2718,22 @@ SELECT * FROM parent WHERE key = 2400;
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>
+ <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.
+ The difference between setting this option and setting
+ <xref linkend="guc-log-min-duration-statement"> to zero is that
+ exceeding <varname>log_min_duration_statement</> forces the text of
+ the query to be logged, but this option doesn't. Thus, if
+ <varname>log_duration</> is <literal>on</> and
+ <varname>log_min_duration_statement</> has a positive value, all
+ durations are logged but the query text is included only for
+ statements exceeding the threshold. This behavior can be useful for
+ gathering statistics in high-load installations.
</para>
</note>
</listitem>
diff --git a/src/backend/tcop/fastpath.c b/src/backend/tcop/fastpath.c
index a031a212cca..26931e0a6d7 100644
--- a/src/backend/tcop/fastpath.c
+++ b/src/backend/tcop/fastpath.c
@@ -8,7 +8,7 @@
*
*
* IDENTIFICATION
- * $PostgreSQL: pgsql/src/backend/tcop/fastpath.c,v 1.91 2006/07/14 14:52:23 momjian Exp $
+ * $PostgreSQL: pgsql/src/backend/tcop/fastpath.c,v 1.92 2006/09/08 15:55:53 tgl Exp $
*
* NOTES
* This cruft is the server side of PQfn.
@@ -274,6 +274,8 @@ HandleFunctionRequest(StringInfo msgBuf)
struct fp_info my_fp;
struct fp_info *fip;
bool callit;
+ bool was_logged = false;
+ char msec_str[32];
/*
* Read message contents if not already done.
@@ -314,10 +316,14 @@ HandleFunctionRequest(StringInfo msgBuf)
fid = (Oid) pq_getmsgint(msgBuf, 4); /* function oid */
+ /* Log as soon as we have the function OID */
if (log_statement == LOGSTMT_ALL)
+ {
ereport(LOG,
(errmsg("fastpath function call: function OID %u",
fid)));
+ was_logged = true;
+ }
/*
* There used to be a lame attempt at caching lookup info here. Now we
@@ -387,6 +393,22 @@ HandleFunctionRequest(StringInfo msgBuf)
SendFunctionResult(retval, fcinfo.isnull, fip->rettype, rformat);
+ /*
+ * Emit duration logging if appropriate.
+ */
+ switch (check_log_duration(msec_str, was_logged))
+ {
+ case 1:
+ ereport(LOG,
+ (errmsg("duration: %s ms", msec_str)));
+ break;
+ case 2:
+ ereport(LOG,
+ (errmsg("duration: %s ms fastpath function call: function OID %u",
+ msec_str, fid)));
+ break;
+ }
+
return 0;
}
diff --git a/src/backend/tcop/postgres.c b/src/backend/tcop/postgres.c
index 30c722f4adb..0344eec53fc 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.507 2006/09/07 22:52:01 tgl Exp $
+ * $PostgreSQL: pgsql/src/backend/tcop/postgres.c,v 1.508 2006/09/08 15:55:53 tgl Exp $
*
* NOTES
* this is the "main" module of the postgres backend and
@@ -159,7 +159,6 @@ static int ReadCommand(StringInfo inBuf);
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);
@@ -995,16 +994,18 @@ exec_simple_query(const char *query_string)
/*
* Emit duration logging if appropriate.
*/
- if (check_log_duration(msec_str))
+ switch (check_log_duration(msec_str, was_logged))
{
- if (was_logged)
+ case 1:
ereport(LOG,
(errmsg("duration: %s ms", msec_str)));
- else
+ break;
+ case 2:
ereport(LOG,
(errmsg("duration: %s ms statement: %s",
msec_str, query_string),
errdetail_execute(parsetree_list)));
+ break;
}
if (save_log_statement_stats)
@@ -1247,12 +1248,20 @@ exec_parse_message(const char *query_string, /* string to execute */
/*
* 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 : "<unnamed>",
- query_string)));
+ switch (check_log_duration(msec_str, false))
+ {
+ case 1:
+ ereport(LOG,
+ (errmsg("duration: %s ms", msec_str)));
+ break;
+ case 2:
+ ereport(LOG,
+ (errmsg("duration: %s ms parse %s: %s",
+ msec_str,
+ *stmt_name ? stmt_name : "<unnamed>",
+ query_string)));
+ break;
+ }
if (save_log_statement_stats)
ShowUsage("PARSE MESSAGE STATISTICS");
@@ -1593,14 +1602,22 @@ exec_bind_message(StringInfo input_message)
/*
* 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 : "<unnamed>",
- *stmt_name ? stmt_name : "<unnamed>",
- pstmt->query_string ? pstmt->query_string : "<source not stored>"),
- errdetail_params(params)));
+ switch (check_log_duration(msec_str, false))
+ {
+ case 1:
+ ereport(LOG,
+ (errmsg("duration: %s ms", msec_str)));
+ break;
+ case 2:
+ ereport(LOG,
+ (errmsg("duration: %s ms bind %s to %s: %s",
+ msec_str,
+ *portal_name ? portal_name : "<unnamed>",
+ *stmt_name ? stmt_name : "<unnamed>",
+ pstmt->query_string ? pstmt->query_string : "<source not stored>"),
+ errdetail_params(params)));
+ break;
+ }
if (save_log_statement_stats)
ShowUsage("BIND MESSAGE STATISTICS");
@@ -1794,12 +1811,13 @@ exec_execute_message(const char *portal_name, long max_rows)
/*
* Emit duration logging if appropriate.
*/
- if (check_log_duration(msec_str))
+ switch (check_log_duration(msec_str, was_logged))
{
- if (was_logged)
+ case 1:
ereport(LOG,
(errmsg("duration: %s ms", msec_str)));
- else
+ break;
+ case 2:
ereport(LOG,
(errmsg("duration: %s ms %s %s%s%s%s%s",
msec_str,
@@ -1812,6 +1830,7 @@ exec_execute_message(const char *portal_name, long max_rows)
sourceText ? ": " : "",
sourceText ? sourceText : ""),
errdetail_params(portalParams)));
+ break;
}
if (save_log_statement_stats)
@@ -1878,17 +1897,26 @@ check_log_statement_cooked(List *parsetree_list)
* check_log_duration
* Determine whether current command's duration should be logged
*
+ * Returns:
+ * 0 if no logging is needed
+ * 1 if just the duration should be logged
+ * 2 if duration and query details should be logged
+ *
* If logging is needed, the duration in msec is formatted into msec_str[],
* which must be a 32-byte buffer.
+ *
+ * was_logged should be TRUE if caller already logged query details (this
+ * essentially prevents 2 from being returned).
*/
-static bool
-check_log_duration(char *msec_str)
+int
+check_log_duration(char *msec_str, bool was_logged)
{
if (log_duration || log_min_duration_statement >= 0)
{
long secs;
int usecs;
int msecs;
+ bool exceeded;
TimestampDifference(GetCurrentStatementStartTimestamp(),
GetCurrentTimestamp(),
@@ -1896,24 +1924,28 @@ check_log_duration(char *msec_str)
msecs = usecs / 1000;
/*
- * The odd-looking test for log_min_duration_statement being
+ * This 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)))
+ exceeded = (log_min_duration_statement == 0 ||
+ (log_min_duration_statement > 0 &&
+ (secs > log_min_duration_statement / 1000 ||
+ secs * 1000 + msecs >= log_min_duration_statement)));
+
+ if (exceeded || log_duration)
{
snprintf(msec_str, 32, "%ld.%03d",
secs * 1000 + msecs, usecs % 1000);
- return true;
+ if (exceeded && !was_logged)
+ return 2;
+ else
+ return 1;
}
}
- return false;
+ return 0;
}
/*
diff --git a/src/include/tcop/tcopprot.h b/src/include/tcop/tcopprot.h
index fd87d87adba..a2913e95a15 100644
--- a/src/include/tcop/tcopprot.h
+++ b/src/include/tcop/tcopprot.h
@@ -7,7 +7,7 @@
* Portions Copyright (c) 1996-2006, PostgreSQL Global Development Group
* Portions Copyright (c) 1994, Regents of the University of California
*
- * $PostgreSQL: pgsql/src/include/tcop/tcopprot.h,v 1.82 2006/07/13 18:01:02 momjian Exp $
+ * $PostgreSQL: pgsql/src/include/tcop/tcopprot.h,v 1.83 2006/09/08 15:55:53 tgl Exp $
*
* OLD COMMENTS
* This file was created so that other c files could get the two
@@ -64,6 +64,7 @@ extern void client_read_ended(void);
extern int PostgresMain(int argc, char *argv[], const char *username);
extern void ResetUsage(void);
extern void ShowUsage(const char *title);
+extern int check_log_duration(char *msec_str, bool was_logged);
extern void set_debug_options(int debug_flag,
GucContext context, GucSource source);
extern bool set_plan_disabling_options(const char *arg,
--
GitLab