Movatterモバイル変換

[0]ホーム
URL:

Skip to content

Navigation Menu

Sign in
Appearance settings

Search code, repositories, users, issues, pull requests...

Provide feedback

We read every piece of feedback, and take your input very seriously.

Saved searches

Use saved searches to filter your results more quickly

 Sign up
Appearance settings

Commitb59d31c

Browse files
committed
Tweak the behavior of log_duration as proposed by Guillaume Smet: rather
than being equivalent to setting log_min_duration_statement to zero, thisoption now forces logging of all query durations, but doesn't force loggingof query text. Also, add duration logging coverage for fastpath functioncalls.
1 parent0b33c56 commitb59d31c

File tree

4 files changed

+103
-49
lines changed

4 files changed

+103
-49
lines changed

‎doc/src/sgml/config.sgml‎

Lines changed: 14 additions & 15 deletions
Original file line numberDiff line numberDiff line change
@@ -1,4 +1,4 @@
1-
<!-- $PostgreSQL: pgsql/doc/src/sgml/config.sgml,v 1.84 2006/09/07 22:51:59 tgl Exp $ -->
1+
<!-- $PostgreSQL: pgsql/doc/src/sgml/config.sgml,v 1.85 2006/09/08 15:55:52 tgl Exp $ -->
22

33
<chapter Id="runtime-config">
44
<title>Server Configuration</title>
@@ -2718,23 +2718,22 @@ SELECT * FROM parent WHERE key = 2400;
27182718
Only superusers can change this setting.
27192719
</para>
27202720

2721-
<para>
2722-
For clients using extended query protocol, durations of the Parse,
2723-
Bind, and Execute steps are logged independently.
2724-
</para>
2721+
<para>
2722+
For clients using extended query protocol, durations of the Parse,
2723+
Bind, and Execute steps are logged independently.
2724+
</para>
27252725

27262726
<note>
27272727
<para>
2728-
When using this option together with
2729-
<xref linkend="guc-log-statement">,
2730-
the text of statements that are logged because of
2731-
<varname>log_statement</> will not be repeated in the
2732-
duration log message.
2733-
If you are not using <application>syslog</>, it is recommended
2734-
that you log the PID or session ID using
2735-
<xref linkend="guc-log-line-prefix">
2736-
so that you can link the statement message to the later
2737-
duration message using the process ID or session ID.
2728+
The difference between setting this option and setting
2729+
<xref linkend="guc-log-min-duration-statement"> to zero is that
2730+
exceeding <varname>log_min_duration_statement</> forces the text of
2731+
the query to be logged, but this option doesn't. Thus, if
2732+
<varname>log_duration</> is <literal>on</> and
2733+
<varname>log_min_duration_statement</> has a positive value, all
2734+
durations are logged but the query text is included only for
2735+
statements exceeding the threshold. This behavior can be useful for
2736+
gathering statistics in high-load installations.
27382737
</para>
27392738
</note>
27402739
</listitem>

‎src/backend/tcop/fastpath.c‎

Lines changed: 23 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -8,7 +8,7 @@
88
*
99
*
1010
* IDENTIFICATION
11-
* $PostgreSQL: pgsql/src/backend/tcop/fastpath.c,v 1.91 2006/07/14 14:52:23 momjian Exp $
11+
* $PostgreSQL: pgsql/src/backend/tcop/fastpath.c,v 1.92 2006/09/08 15:55:53 tgl Exp $
1212
*
1313
* NOTES
1414
* This cruft is the server side of PQfn.
@@ -274,6 +274,8 @@ HandleFunctionRequest(StringInfo msgBuf)
274274
structfp_infomy_fp;
275275
structfp_info*fip;
276276
boolcallit;
277+
boolwas_logged= false;
278+
charmsec_str[32];
277279

278280
/*
279281
* Read message contents if not already done.
@@ -314,10 +316,14 @@ HandleFunctionRequest(StringInfo msgBuf)
314316

315317
fid= (Oid)pq_getmsgint(msgBuf,4);/* function oid */
316318

319+
/* Log as soon as we have the function OID */
317320
if (log_statement==LOGSTMT_ALL)
321+
{
318322
ereport(LOG,
319323
(errmsg("fastpath function call: function OID %u",
320324
fid)));
325+
was_logged= true;
326+
}
321327

322328
/*
323329
* There used to be a lame attempt at caching lookup info here. Now we
@@ -387,6 +393,22 @@ HandleFunctionRequest(StringInfo msgBuf)
387393

388394
SendFunctionResult(retval,fcinfo.isnull,fip->rettype,rformat);
389395

396+
/*
397+
* Emit duration logging if appropriate.
398+
*/
399+
switch (check_log_duration(msec_str,was_logged))
400+
{
401+
case1:
402+
ereport(LOG,
403+
(errmsg("duration: %s ms",msec_str)));
404+
break;
405+
case2:
406+
ereport(LOG,
407+
(errmsg("duration: %s ms fastpath function call: function OID %u",
408+
msec_str,fid)));
409+
break;
410+
}
411+
390412
return0;
391413
}
392414

‎src/backend/tcop/postgres.c‎

Lines changed: 64 additions & 32 deletions
Original file line numberDiff line numberDiff line change
@@ -8,7 +8,7 @@
88
*
99
*
1010
* IDENTIFICATION
11-
* $PostgreSQL: pgsql/src/backend/tcop/postgres.c,v 1.507 2006/09/07 22:52:01 tgl Exp $
11+
* $PostgreSQL: pgsql/src/backend/tcop/postgres.c,v 1.508 2006/09/08 15:55:53 tgl Exp $
1212
*
1313
* NOTES
1414
* this is the "main" module of the postgres backend and
@@ -159,7 +159,6 @@ static intReadCommand(StringInfo inBuf);
159159
staticList*pg_rewrite_queries(List*querytree_list);
160160
staticboolcheck_log_statement_raw(List*raw_parsetree_list);
161161
staticboolcheck_log_statement_cooked(List*parsetree_list);
162-
staticboolcheck_log_duration(char*msec_str);
163162
staticinterrdetail_execute(List*raw_parsetree_list);
164163
staticinterrdetail_params(ParamListInfoparams);
165164
staticvoidstart_xact_command(void);
@@ -995,16 +994,18 @@ exec_simple_query(const char *query_string)
995994
/*
996995
* Emit duration logging if appropriate.
997996
*/
998-
if (check_log_duration(msec_str))
997+
switch (check_log_duration(msec_str,was_logged))
999998
{
1000-
if (was_logged)
999+
case1:
10011000
ereport(LOG,
10021001
(errmsg("duration: %s ms",msec_str)));
1003-
else
1002+
break;
1003+
case2:
10041004
ereport(LOG,
10051005
(errmsg("duration: %s ms statement: %s",
10061006
msec_str,query_string),
10071007
errdetail_execute(parsetree_list)));
1008+
break;
10081009
}
10091010

10101011
if (save_log_statement_stats)
@@ -1247,12 +1248,20 @@ exec_parse_message(const char *query_string,/* string to execute */
12471248
/*
12481249
* Emit duration logging if appropriate.
12491250
*/
1250-
if (check_log_duration(msec_str))
1251-
ereport(LOG,
1252-
(errmsg("duration: %s ms parse %s: %s",
1253-
msec_str,
1254-
*stmt_name ?stmt_name :"<unnamed>",
1255-
query_string)));
1251+
switch (check_log_duration(msec_str, false))
1252+
{
1253+
case1:
1254+
ereport(LOG,
1255+
(errmsg("duration: %s ms",msec_str)));
1256+
break;
1257+
case2:
1258+
ereport(LOG,
1259+
(errmsg("duration: %s ms parse %s: %s",
1260+
msec_str,
1261+
*stmt_name ?stmt_name :"<unnamed>",
1262+
query_string)));
1263+
break;
1264+
}
12561265

12571266
if (save_log_statement_stats)
12581267
ShowUsage("PARSE MESSAGE STATISTICS");
@@ -1593,14 +1602,22 @@ exec_bind_message(StringInfo input_message)
15931602
/*
15941603
* Emit duration logging if appropriate.
15951604
*/
1596-
if (check_log_duration(msec_str))
1597-
ereport(LOG,
1598-
(errmsg("duration: %s ms bind %s to %s: %s",
1599-
msec_str,
1600-
*portal_name ?portal_name :"<unnamed>",
1601-
*stmt_name ?stmt_name :"<unnamed>",
1602-
pstmt->query_string ?pstmt->query_string :"<source not stored>"),
1603-
errdetail_params(params)));
1605+
switch (check_log_duration(msec_str, false))
1606+
{
1607+
case1:
1608+
ereport(LOG,
1609+
(errmsg("duration: %s ms",msec_str)));
1610+
break;
1611+
case2:
1612+
ereport(LOG,
1613+
(errmsg("duration: %s ms bind %s to %s: %s",
1614+
msec_str,
1615+
*portal_name ?portal_name :"<unnamed>",
1616+
*stmt_name ?stmt_name :"<unnamed>",
1617+
pstmt->query_string ?pstmt->query_string :"<source not stored>"),
1618+
errdetail_params(params)));
1619+
break;
1620+
}
16041621

16051622
if (save_log_statement_stats)
16061623
ShowUsage("BIND MESSAGE STATISTICS");
@@ -1794,12 +1811,13 @@ exec_execute_message(const char *portal_name, long max_rows)
17941811
/*
17951812
* Emit duration logging if appropriate.
17961813
*/
1797-
if (check_log_duration(msec_str))
1814+
switch (check_log_duration(msec_str,was_logged))
17981815
{
1799-
if (was_logged)
1816+
case1:
18001817
ereport(LOG,
18011818
(errmsg("duration: %s ms",msec_str)));
1802-
else
1819+
break;
1820+
case2:
18031821
ereport(LOG,
18041822
(errmsg("duration: %s ms %s %s%s%s%s%s",
18051823
msec_str,
@@ -1812,6 +1830,7 @@ exec_execute_message(const char *portal_name, long max_rows)
18121830
sourceText ?": " :"",
18131831
sourceText ?sourceText :""),
18141832
errdetail_params(portalParams)));
1833+
break;
18151834
}
18161835

18171836
if (save_log_statement_stats)
@@ -1878,42 +1897,55 @@ check_log_statement_cooked(List *parsetree_list)
18781897
* check_log_duration
18791898
*Determine whether current command's duration should be logged
18801899
*
1900+
* Returns:
1901+
*0 if no logging is needed
1902+
*1 if just the duration should be logged
1903+
*2 if duration and query details should be logged
1904+
*
18811905
* If logging is needed, the duration in msec is formatted into msec_str[],
18821906
* which must be a 32-byte buffer.
1907+
*
1908+
* was_logged should be TRUE if caller already logged query details (this
1909+
* essentially prevents 2 from being returned).
18831910
*/
1884-
staticbool
1885-
check_log_duration(char*msec_str)
1911+
int
1912+
check_log_duration(char*msec_str,boolwas_logged)
18861913
{
18871914
if (log_duration||log_min_duration_statement >=0)
18881915
{
18891916
longsecs;
18901917
intusecs;
18911918
intmsecs;
1919+
boolexceeded;
18921920

18931921
TimestampDifference(GetCurrentStatementStartTimestamp(),
18941922
GetCurrentTimestamp(),
18951923
&secs,&usecs);
18961924
msecs=usecs /1000;
18971925

18981926
/*
1899-
*The odd-looking test for log_min_duration_statement being
1927+
*This odd-looking test for log_min_duration_statement being
19001928
* exceeded is designed to avoid integer overflow with very
19011929
* long durations: don't compute secs * 1000 until we've
19021930
* verified it will fit in int.
19031931
*/
1904-
if (log_duration||
1905-
log_min_duration_statement==0||
1906-
(log_min_duration_statement>0&&
1907-
(secs>log_min_duration_statement /1000||
1908-
secs*1000+msecs >=log_min_duration_statement)))
1932+
exceeded= (log_min_duration_statement==0||
1933+
(log_min_duration_statement>0&&
1934+
(secs>log_min_duration_statement /1000||
1935+
secs*1000+msecs >=log_min_duration_statement)));
1936+
1937+
if (exceeded||log_duration)
19091938
{
19101939
snprintf(msec_str,32,"%ld.%03d",
19111940
secs*1000+msecs,usecs %1000);
1912-
return true;
1941+
if (exceeded&& !was_logged)
1942+
return2;
1943+
else
1944+
return1;
19131945
}
19141946
}
19151947

1916-
returnfalse;
1948+
return0;
19171949
}
19181950

19191951
/*

‎src/include/tcop/tcopprot.h‎

Lines changed: 2 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -7,7 +7,7 @@
77
* Portions Copyright (c) 1996-2006, PostgreSQL Global Development Group
88
* Portions Copyright (c) 1994, Regents of the University of California
99
*
10-
* $PostgreSQL: pgsql/src/include/tcop/tcopprot.h,v 1.82 2006/07/13 18:01:02 momjian Exp $
10+
* $PostgreSQL: pgsql/src/include/tcop/tcopprot.h,v 1.83 2006/09/08 15:55:53 tgl Exp $
1111
*
1212
* OLD COMMENTS
1313
* This file was created so that other c files could get the two
@@ -64,6 +64,7 @@ extern void client_read_ended(void);
6464
externintPostgresMain(intargc,char*argv[],constchar*username);
6565
externvoidResetUsage(void);
6666
externvoidShowUsage(constchar*title);
67+
externintcheck_log_duration(char*msec_str,boolwas_logged);
6768
externvoidset_debug_options(intdebug_flag,
6869
GucContextcontext,GucSourcesource);
6970
externboolset_plan_disabling_options(constchar*arg,

0 commit comments

Comments
 (0)
[8]ページ先頭
©2009-2025 Movatter.jp