diff options
| -rw-r--r-- | doc/src/sgml/config.sgml | 29 | ||||
| -rw-r--r-- | src/backend/tcop/fastpath.c | 24 | ||||
| -rw-r--r-- | src/backend/tcop/postgres.c | 96 | ||||
| -rw-r--r-- | 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, |