rdelaage
/
postgresql
mirror of https://git.postgresql.org/git/postgresql.git
1
0
Fork 0
Code Issues Packages Projects Releases Wiki Activity

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.
This commit is contained in:
Tom Lane 2006-09-08 15:55:53 +00:00
parent 0b33c56297
commit b59d31c215
4 changed files with 103 additions and 49 deletions
Show Stats Download Patch File Download Diff File Expand all files Collapse all files

29
doc/src/sgml/config.sgml
View File

@ -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"> <chapter Id="runtime-config">
<title>Server Configuration</title> <title>Server Configuration</title>
@ -2718,23 +2718,22 @@ SELECT * FROM parent WHERE key = 2400;
Only superusers can change this setting. Only superusers can change this setting.
</para> </para>
<para> <para>
For clients using extended query protocol, durations of the Parse, For clients using extended query protocol, durations of the Parse,
Bind, and Execute steps are logged independently. Bind, and Execute steps are logged independently.
</para> </para>
<note> <note>
<para> <para>
When using this option together with The difference between setting this option and setting
<xref linkend="guc-log-statement">, <xref linkend="guc-log-min-duration-statement"> to zero is that
the text of statements that are logged because of exceeding <varname>log_min_duration_statement</> forces the text of
<varname>log_statement</> will not be repeated in the the query to be logged, but this option doesn't. Thus, if
duration log message. <varname>log_duration</> is <literal>on</> and
If you are not using <application>syslog</>, it is recommended <varname>log_min_duration_statement</> has a positive value, all
that you log the PID or session ID using durations are logged but the query text is included only for
<xref linkend="guc-log-line-prefix"> statements exceeding the threshold. This behavior can be useful for
so that you can link the statement message to the later gathering statistics in high-load installations.
duration message using the process ID or session ID.
</para> </para>
</note> </note>
</listitem> </listitem>

24
src/backend/tcop/fastpath.c
View File

@ -8,7 +8,7 @@
* *
* *
* IDENTIFICATION * 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 * NOTES
* This cruft is the server side of PQfn. * This cruft is the server side of PQfn.
@ -274,6 +274,8 @@ HandleFunctionRequest(StringInfo msgBuf)
struct fp_info my_fp; struct fp_info my_fp;
struct fp_info *fip; struct fp_info *fip;
bool callit; bool callit;
bool was_logged = false;
char msec_str[32];
/* /*
* Read message contents if not already done. * Read message contents if not already done.
@ -314,10 +316,14 @@ HandleFunctionRequest(StringInfo msgBuf)
fid = (Oid) pq_getmsgint(msgBuf, 4); /* function oid */ fid = (Oid) pq_getmsgint(msgBuf, 4); /* function oid */
/* Log as soon as we have the function OID */
if (log_statement == LOGSTMT_ALL) if (log_statement == LOGSTMT_ALL)
{
ereport(LOG, ereport(LOG,
(errmsg("fastpath function call: function OID %u", (errmsg("fastpath function call: function OID %u",
fid))); fid)));
was_logged = true;
}
/* /*
* There used to be a lame attempt at caching lookup info here. Now we * 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); 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; return 0;
} }

96
src/backend/tcop/postgres.c
View File

@ -8,7 +8,7 @@
* *
* *
* IDENTIFICATION * 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 * NOTES
* this is the "main" module of the postgres backend and * 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 List *pg_rewrite_queries(List *querytree_list);
static bool check_log_statement_raw(List *raw_parsetree_list); static bool check_log_statement_raw(List *raw_parsetree_list);
static bool check_log_statement_cooked(List *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_execute(List *raw_parsetree_list);
static int errdetail_params(ParamListInfo params); static int errdetail_params(ParamListInfo params);
static void start_xact_command(void); static void start_xact_command(void);
@ -995,16 +994,18 @@ exec_simple_query(const char *query_string)
/* /*
* Emit duration logging if appropriate. * 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, ereport(LOG,
(errmsg("duration: %s ms", msec_str))); (errmsg("duration: %s ms", msec_str)));
else break;
case 2:
ereport(LOG, ereport(LOG,
(errmsg("duration: %s ms statement: %s", (errmsg("duration: %s ms statement: %s",
msec_str, query_string), msec_str, query_string),
errdetail_execute(parsetree_list))); errdetail_execute(parsetree_list)));
break;
} }
if (save_log_statement_stats) if (save_log_statement_stats)
@ -1247,12 +1248,20 @@ exec_parse_message(const char *query_string, /* string to execute */
/* /*
* Emit duration logging if appropriate. * Emit duration logging if appropriate.
*/ */
if (check_log_duration(msec_str)) switch (check_log_duration(msec_str, false))
ereport(LOG, {
(errmsg("duration: %s ms parse %s: %s", case 1:
msec_str, ereport(LOG,
*stmt_name ? stmt_name : "<unnamed>", (errmsg("duration: %s ms", msec_str)));
query_string))); 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) if (save_log_statement_stats)
ShowUsage("PARSE MESSAGE STATISTICS"); ShowUsage("PARSE MESSAGE STATISTICS");
@ -1593,14 +1602,22 @@ exec_bind_message(StringInfo input_message)
/* /*
* Emit duration logging if appropriate. * Emit duration logging if appropriate.
*/ */
if (check_log_duration(msec_str)) switch (check_log_duration(msec_str, false))
ereport(LOG, {
(errmsg("duration: %s ms bind %s to %s: %s", case 1:
msec_str, ereport(LOG,
*portal_name ? portal_name : "<unnamed>", (errmsg("duration: %s ms", msec_str)));
*stmt_name ? stmt_name : "<unnamed>", break;
pstmt->query_string ? pstmt->query_string : "<source not stored>"), case 2:
errdetail_params(params))); 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) if (save_log_statement_stats)
ShowUsage("BIND MESSAGE STATISTICS"); ShowUsage("BIND MESSAGE STATISTICS");
@ -1794,12 +1811,13 @@ exec_execute_message(const char *portal_name, long max_rows)
/* /*
* Emit duration logging if appropriate. * 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, ereport(LOG,
(errmsg("duration: %s ms", msec_str))); (errmsg("duration: %s ms", msec_str)));
else break;
case 2:
ereport(LOG, ereport(LOG,
(errmsg("duration: %s ms %s %s%s%s%s%s", (errmsg("duration: %s ms %s %s%s%s%s%s",
msec_str, msec_str,
@ -1812,6 +1830,7 @@ exec_execute_message(const char *portal_name, long max_rows)
sourceText ? ": " : "", sourceText ? ": " : "",
sourceText ? sourceText : ""), sourceText ? sourceText : ""),
errdetail_params(portalParams))); errdetail_params(portalParams)));
break;
} }
if (save_log_statement_stats) if (save_log_statement_stats)
@ -1878,17 +1897,26 @@ check_log_statement_cooked(List *parsetree_list)
* check_log_duration * check_log_duration
* Determine whether current command's duration should be logged * 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[], * If logging is needed, the duration in msec is formatted into msec_str[],
* which must be a 32-byte buffer. * 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 int
check_log_duration(char *msec_str) check_log_duration(char *msec_str, bool was_logged)
{ {
if (log_duration || log_min_duration_statement >= 0) if (log_duration || log_min_duration_statement >= 0)
{ {
long secs; long secs;
int usecs; int usecs;
int msecs; int msecs;
bool exceeded;
TimestampDifference(GetCurrentStatementStartTimestamp(), TimestampDifference(GetCurrentStatementStartTimestamp(),
GetCurrentTimestamp(), GetCurrentTimestamp(),
@ -1896,24 +1924,28 @@ check_log_duration(char *msec_str)
msecs = usecs / 1000; 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 * exceeded is designed to avoid integer overflow with very
* long durations: don't compute secs * 1000 until we've * long durations: don't compute secs * 1000 until we've
* verified it will fit in int. * verified it will fit in int.
*/ */
if (log_duration || exceeded = (log_min_duration_statement == 0 ||
log_min_duration_statement == 0 || (log_min_duration_statement > 0 &&
(log_min_duration_statement > 0 && (secs > log_min_duration_statement / 1000 ||
(secs > log_min_duration_statement / 1000 || secs * 1000 + msecs >= log_min_duration_statement)));
secs * 1000 + msecs >= log_min_duration_statement)))
if (exceeded || log_duration)
{ {
snprintf(msec_str, 32, "%ld.%03d", snprintf(msec_str, 32, "%ld.%03d",
secs * 1000 + msecs, usecs % 1000); secs * 1000 + msecs, usecs % 1000);
return true; if (exceeded && !was_logged)
return 2;
else
return 1;
} }
} }
return false; return 0;
} }
/* /*

3
src/include/tcop/tcopprot.h
View File

@ -7,7 +7,7 @@
* Portions Copyright (c) 1996-2006, PostgreSQL Global Development Group * Portions Copyright (c) 1996-2006, PostgreSQL Global Development Group
* Portions Copyright (c) 1994, Regents of the University of California * 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 * OLD COMMENTS
* This file was created so that other c files could get the two * 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 int PostgresMain(int argc, char *argv[], const char *username);
extern void ResetUsage(void); extern void ResetUsage(void);
extern void ShowUsage(const char *title); 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, extern void set_debug_options(int debug_flag,
GucContext context, GucSource source); GucContext context, GucSource source);
extern bool set_plan_disabling_options(const char *arg, extern bool set_plan_disabling_options(const char *arg,