Skip to content

Commit 88bdbd3

Browse files
alvherrealvherre
committed
Add log_statement_sample_rate parameter
This allows to set a lower log_min_duration_statement value without incurring excessive log traffic (which reduces performance). This can be useful to analyze workloads with lots of short queries. Author: Adrien Nayrat Reviewed-by: David Rowley, Vik Fearing Discussion: https://postgr.es/m/c30ee535-ee1e-db9f-fa97-146b9f62caed@anayrat.info
1 parent 826eff5 commit 88bdbd3

File tree

5 files changed

+62
-13
lines changed

5 files changed

+62
-13
lines changed

‎doc/src/sgml/config.sgml

Lines changed: 25 additions & 5 deletions
Original file line numberDiff line numberDiff line change
@@ -5721,11 +5721,11 @@ local0.* /var/log/postgresql
57215721
<para>
57225722
Causes the duration of each completed statement to be logged
57235723
if the statement ran for at least the specified number of
5724-
milliseconds. Setting this to zero prints all statement durations.
5725-
Minus-one (the default) disables logging statement durations.
5726-
For example, if you set it to <literal>250ms</literal>
5727-
then all SQL statements that run 250ms or longer will be
5728-
logged. Enabling this parameter can be helpful in tracking down
5724+
milliseconds, modulated by <varname>log_statement_sample_rate</varname>.
5725+
Setting this to zero prints all statement durations. Minus-one (the default)
5726+
disables logging statement durations. For example, if you set it to
5727+
<literal>250ms</literal> then all SQL statements that run 250ms or longer
5728+
will be logged. Enabling this parameter can be helpful in tracking down
57295729
unoptimized queries in your applications.
57305730
Only superusers can change this setting.
57315731
</para>
@@ -5752,6 +5752,26 @@ local0.* /var/log/postgresql
57525752
</listitem>
57535753
</varlistentry>
57545754

5755+
<varlistentry id="guc-log-statement-sample-rate" xreflabel="log_statement_sample_rate">
5756+
<term><varname>log_statement_sample_rate</varname> (<type>real</type>)
5757+
<indexterm>
5758+
<primary><varname>log_statement_sample_rate</varname> configuration parameter</primary>
5759+
</indexterm>
5760+
</term>
5761+
<listitem>
5762+
<para>
5763+
Determines the fraction of the statements that exceed
5764+
<xref linkend="guc-log-min-duration-statement"/> which to log.
5765+
The default is <literal>1</literal>, meaning log to all such
5766+
statements.
5767+
Setting this to zero disables logging, same as setting
5768+
<varname>log_min_duration_statement</varname>
5769+
to minus-one. <varname>log_statement_sample_rate</varname>
5770+
is helpful when the traffic is too high to log all queries.
5771+
</para>
5772+
</listitem>
5773+
</varlistentry>
5774+
57555775
</variablelist>
57565776

57575777
<para>

‎src/backend/tcop/postgres.c

Lines changed: 14 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -2201,7 +2201,8 @@ check_log_statement(List *stmt_list)
22012201

22022202
/*
22032203
* check_log_duration
2204-
* Determine whether current command's duration should be logged
2204+
* Determine whether current command's duration should be logged.
2205+
* If log_statement_sample_rate < 1.0, log only a sample.
22052206
*
22062207
* Returns:
22072208
* 0 if no logging is needed
@@ -2223,6 +2224,7 @@ check_log_duration(char *msec_str, bool was_logged)
22232224
int usecs;
22242225
int msecs;
22252226
bool exceeded;
2227+
bool in_sample;
22262228

22272229
TimestampDifference(GetCurrentStatementStartTimestamp(),
22282230
GetCurrentTimestamp(),
@@ -2239,7 +2241,17 @@ check_log_duration(char *msec_str, bool was_logged)
22392241
(secs > log_min_duration_statement / 1000 ||
22402242
secs * 1000 + msecs >= log_min_duration_statement)));
22412243

2242-
if (exceeded || log_duration)
2244+
/*
2245+
* Do not log if log_statement_sample_rate = 0. Log a sample if
2246+
* log_statement_sample_rate <= 1 and avoid unecessary random() call
2247+
* if log_statement_sample_rate = 1.
2248+
*/
2249+
if (exceeded)
2250+
in_sample = log_statement_sample_rate != 0 &&
2251+
(log_statement_sample_rate == 1 ||
2252+
random() <= log_statement_sample_rate * MAX_RANDOM_VALUE);
2253+
2254+
if ((exceeded && in_sample) || log_duration)
22432255
{
22442256
snprintf(msec_str, 32, "%ld.%03d",
22452257
secs * 1000 + msecs, usecs % 1000);

‎src/backend/utils/misc/guc.c

Lines changed: 14 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -486,6 +486,7 @@ int log_min_messages = WARNING;
486486
int client_min_messages = NOTICE;
487487
int log_min_duration_statement = -1;
488488
int log_temp_files = -1;
489+
double log_statement_sample_rate = 1.0;
489490
int trace_recovery_messages = LOG;
490491

491492
int temp_file_limit = -1;
@@ -2642,7 +2643,8 @@ static struct config_int ConfigureNamesInt[] =
26422643
{"log_min_duration_statement", PGC_SUSET, LOGGING_WHEN,
26432644
gettext_noop("Sets the minimum execution time above which "
26442645
"statements will be logged."),
2645-
gettext_noop("Zero prints all queries. -1 turns this feature off."),
2646+
gettext_noop("Zero prints all queries, subject to log_statement_sample_rate. "
2647+
"-1 turns this feature off."),
26462648
GUC_UNIT_MS
26472649
},
26482650
&log_min_duration_statement,
@@ -3319,6 +3321,17 @@ static struct config_real ConfigureNamesReal[] =
33193321
NULL, NULL, NULL
33203322
},
33213323

3324+
{
3325+
{"log_statement_sample_rate", PGC_SUSET, LOGGING_WHEN,
3326+
gettext_noop("Fraction of statements over log_min_duration_statement to log."),
3327+
gettext_noop("If you only want a sample, use a value between 0 (never "
3328+
"log) and 1.0 (always log).")
3329+
},
3330+
&log_statement_sample_rate,
3331+
1.0, 0.0, 1.0,
3332+
NULL, NULL, NULL
3333+
},
3334+
33223335
/* End-of-list marker */
33233336
{
33243337
{NULL, 0, 0, NULL, NULL}, NULL, 0.0, 0.0, 0.0, NULL, NULL, NULL

‎src/backend/utils/misc/postgresql.conf.sample

Lines changed: 8 additions & 5 deletions
Original file line numberDiff line numberDiff line change
@@ -483,11 +483,14 @@
483483
# fatal
484484
# panic (effectively off)
485485

486-
#log_min_duration_statement = -1 # -1 is disabled, 0 logs all statements
487-
# and their durations, > 0 logs only
488-
# statements running at least this number
489-
# of milliseconds
490-
486+
#log_min_duration_statement = -1 # logs statements and their durations
487+
# according to log_statement_sample_rate. -1 is disabled,
488+
# 0 logs all statement, > 0 logs only statements running at
489+
# least this number of milliseconds.
490+
491+
#log_statement_sample_rate = 1 # Fraction of logged statements over
492+
# log_min_duration_statement. 1.0 logs all statements,
493+
# 0 never logs.
491494

492495
# - What to Log -
493496

‎src/include/utils/guc.h

Lines changed: 1 addition & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -251,6 +251,7 @@ extern PGDLLIMPORT int log_min_messages;
251251
extern PGDLLIMPORT int client_min_messages;
252252
extern int log_min_duration_statement;
253253
extern int log_temp_files;
254+
extern double log_statement_sample_rate;
254255

255256
extern int temp_file_limit;
256257

0 commit comments

Comments
 (0)