From 6e3e6cc0e884a6091e1094dff29db430af08fb93 Mon Sep 17 00:00:00 2001 From: Tomas Vondra Date: Mon, 4 Nov 2019 01:57:45 +0100 Subject: Allow sampling of statements depending on duration This allows logging a sample of statements, without incurring excessive log traffic (which may impact performance). This can be useful when analyzing workloads with lots of short queries. The sampling is configured using two new GUC parameters: * log_min_duration_sample - minimum required statement duration * log_statement_sample_rate - sample rate (0.0 - 1.0) Only statements with duration exceeding log_min_duration_sample are considered for sampling. To enable sampling, both those GUCs have to be set correctly. The existing log_min_duration_statement GUC has a higher priority, i.e. statements with duration exceeding log_min_duration_statement will be always logged, irrespectedly of how the sampling is configured. This means only configurations log_min_duration_sample < log_min_duration_statement do actually sample the statements, instead of logging everything. Author: Adrien Nayrat Reviewed-by: David Rowley, Vik Fearing, Tomas Vondra Discussion: https://postgr.es/m/bbe0a1a8-a8f7-3be2-155a-888e661cc06c@anayrat.info --- src/backend/tcop/postgres.c | 40 +++++++++++++++++++++++++++++----------- 1 file changed, 29 insertions(+), 11 deletions(-) (limited to 'src/backend/tcop/postgres.c') diff --git a/src/backend/tcop/postgres.c b/src/backend/tcop/postgres.c index 4bec40aa287..82894eadc66 100644 --- a/src/backend/tcop/postgres.c +++ b/src/backend/tcop/postgres.c @@ -2235,12 +2235,15 @@ check_log_statement(List *stmt_list) int check_log_duration(char *msec_str, bool was_logged) { - if (log_duration || log_min_duration_statement >= 0 || xact_is_sampled) + if (log_duration || log_min_duration_sample >= 0 || + log_min_duration_statement >= 0 || xact_is_sampled) { long secs; int usecs; int msecs; - bool exceeded; + bool exceeded_duration; + bool exceeded_sample_duration; + bool in_sample = false; TimestampDifference(GetCurrentStatementStartTimestamp(), GetCurrentTimestamp(), @@ -2248,20 +2251,35 @@ check_log_duration(char *msec_str, bool was_logged) msecs = usecs / 1000; /* - * 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. + * This odd-looking test for log_min_duration_* 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. */ - exceeded = (log_min_duration_statement == 0 || - (log_min_duration_statement > 0 && - (secs > log_min_duration_statement / 1000 || - secs * 1000 + msecs >= log_min_duration_statement))); + exceeded_duration = (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 || xact_is_sampled) + exceeded_sample_duration = (log_min_duration_sample == 0 || + (log_min_duration_sample > 0 && + (secs > log_min_duration_sample / 1000 || + secs * 1000 + msecs >= log_min_duration_sample))); + + /* + * Do not log if log_statement_sample_rate = 0. Log a sample if + * log_statement_sample_rate <= 1 and avoid unecessary random() call + * if log_statement_sample_rate = 1. + */ + if (exceeded_sample_duration) + in_sample = log_statement_sample_rate != 0 && + (log_statement_sample_rate == 1 || + random() <= log_statement_sample_rate * MAX_RANDOM_VALUE); + + if (exceeded_duration || in_sample || log_duration || xact_is_sampled) { snprintf(msec_str, 32, "%ld.%03d", secs * 1000 + msecs, usecs % 1000); - if ((exceeded || xact_is_sampled) && !was_logged) + if ((exceeded_duration || in_sample || xact_is_sampled) && !was_logged) return 2; else return 1; -- cgit v1.2.3