From b952d61c545e6c5fd827187a3ec6b9871cc0ebed Mon Sep 17 00:00:00 2001 From: Bruce Momjian Date: Wed, 11 Jun 2003 18:01:14 +0000 Subject: [PATCH] Add log_min_duration_statement. Christopher Kings-Lynne --- doc/src/sgml/runtime.sgml | 19 ++++++++- src/backend/tcop/postgres.c | 41 ++++++++++++++----- src/backend/utils/misc/guc.c | 9 +++- src/backend/utils/misc/postgresql.conf.sample | 4 ++ src/bin/psql/tab-complete.c | 3 +- src/include/utils/guc.h | 4 +- 6 files changed, 66 insertions(+), 14 deletions(-) diff --git a/doc/src/sgml/runtime.sgml b/doc/src/sgml/runtime.sgml index b59cda7e35..f90800ab5e 100644 --- a/doc/src/sgml/runtime.sgml +++ b/doc/src/sgml/runtime.sgml @@ -1,5 +1,5 @@ @@ -1051,6 +1051,23 @@ SET ENABLE_SEQSCAN TO OFF; + + LOG_MIN_DURATION_STATEMENT (integer) + + + Sets a minimum statement execution time (in milliseconds) + above which a statement will be logged. All SQL statements + that run longer than the time specified will be logged together + with the duration, in seconds. The default is 0 + (turning this feature off). For example, if you set it + to 250 then all SQL statements that run longer + than 250ms will be logged along with the duration. Enabling this + option can be useful in tracking down unoptimized queries in + your applications. + + + + LOG_MIN_ERROR_STATEMENT (string) diff --git a/src/backend/tcop/postgres.c b/src/backend/tcop/postgres.c index 6fa751640d..96f3ca00e6 100644 --- a/src/backend/tcop/postgres.c +++ b/src/backend/tcop/postgres.c @@ -8,7 +8,7 @@ * * * IDENTIFICATION - * $Header: /cvsroot/pgsql/src/backend/tcop/postgres.c,v 1.346 2003/05/27 17:49:46 momjian Exp $ + * $Header: /cvsroot/pgsql/src/backend/tcop/postgres.c,v 1.347 2003/06/11 18:01:14 momjian Exp $ * * NOTES * this is the "main" module of the postgres backend and @@ -663,6 +663,7 @@ exec_simple_query(const char *query_string) struct timeval start_t, stop_t; bool save_log_duration = log_duration; + int save_log_min_duration_statement = log_min_duration_statement; bool save_log_statement_stats = log_statement_stats; /* @@ -673,11 +674,12 @@ exec_simple_query(const char *query_string) pgstat_report_activity(query_string); /* - * We use save_log_duration so "SET log_duration = true" doesn't - * report incorrect time because gettimeofday() wasn't called. + * We use save_log_* so "SET log_duration = true" and + * "SET log_min_duration_statement = true" don't report incorrect + * time because gettimeofday() wasn't called. * Similarly, log_statement_stats has to be captured once. */ - if (save_log_duration) + if (save_log_duration || save_log_min_duration_statement > 0) gettimeofday(&start_t, NULL); if (save_log_statement_stats) @@ -915,19 +917,38 @@ exec_simple_query(const char *query_string) QueryContext = NULL; /* - * Finish up monitoring. + * Combine processing here as we need to calculate the query + * duration in both instances. */ - if (save_log_duration) + if (save_log_duration || save_log_min_duration_statement > 0) { + long usecs; gettimeofday(&stop_t, NULL); if (stop_t.tv_usec < start_t.tv_usec) { stop_t.tv_sec--; stop_t.tv_usec += 1000000; } - elog(LOG, "duration: %ld.%06ld sec", - (long) (stop_t.tv_sec - start_t.tv_sec), - (long) (stop_t.tv_usec - start_t.tv_usec)); + usecs = (long) (stop_t.tv_sec - start_t.tv_sec) * 1000000 + (long) (stop_t.tv_usec - start_t.tv_usec); + + /* + * Output a duration_query to the log if the query has exceeded the + * min duration. + */ + if (usecs >= save_log_min_duration_statement * 1000) + elog(LOG, "duration_statement: %ld.%06ld %s", + (long) (stop_t.tv_sec - start_t.tv_sec), + (long) (stop_t.tv_usec - start_t.tv_usec), + query_string); + + /* + * If the user is requesting logging of all durations, then log + * that as well. + */ + if (save_log_duration) + elog(LOG, "duration: %ld.%06ld sec", + (long) (stop_t.tv_sec - start_t.tv_sec), + (long) (stop_t.tv_usec - start_t.tv_usec)); } if (save_log_statement_stats) @@ -2526,7 +2547,7 @@ PostgresMain(int argc, char *argv[], const char *username) if (!IsUnderPostmaster) { puts("\nPOSTGRES backend interactive interface "); - puts("$Revision: 1.346 $ $Date: 2003/05/27 17:49:46 $\n"); + puts("$Revision: 1.347 $ $Date: 2003/06/11 18:01:14 $\n"); } /* diff --git a/src/backend/utils/misc/guc.c b/src/backend/utils/misc/guc.c index 94e7e5b65d..d75803621c 100644 --- a/src/backend/utils/misc/guc.c +++ b/src/backend/utils/misc/guc.c @@ -10,7 +10,7 @@ * Written by Peter Eisentraut . * * IDENTIFICATION - * $Header: /cvsroot/pgsql/src/backend/utils/misc/guc.c,v 1.128 2003/06/11 05:04:51 momjian Exp $ + * $Header: /cvsroot/pgsql/src/backend/utils/misc/guc.c,v 1.129 2003/06/11 18:01:14 momjian Exp $ * *-------------------------------------------------------------------- */ @@ -55,6 +55,8 @@ #include "utils/pg_locale.h" #include "pgstat.h" +int log_min_duration_statement = 0; + #ifndef PG_KRB_SRVTAB #define PG_KRB_SRVTAB "" @@ -735,6 +737,11 @@ static struct config_int 0, -15, 2, NULL, NULL }, + { + {"log_min_duration_statement", PGC_USERSET}, &log_min_duration_statement, + 0, 0, INT_MAX / 1000, NULL, NULL + }, + { {NULL, 0}, NULL, 0, 0, 0, NULL, NULL } diff --git a/src/backend/utils/misc/postgresql.conf.sample b/src/backend/utils/misc/postgresql.conf.sample index 9c0bb8caea..77858388c3 100644 --- a/src/backend/utils/misc/postgresql.conf.sample +++ b/src/backend/utils/misc/postgresql.conf.sample @@ -140,6 +140,10 @@ # debug5, debug4, debug3, debug2, debug1, # info, notice, warning, error, panic(off) +#log_min_duration_statement = 0 # Log all statements whose + # execution time exceeds the value, in + # milliseconds. Zero disables. + #debug_print_parse = false #debug_print_rewritten = false #debug_print_plan = false diff --git a/src/bin/psql/tab-complete.c b/src/bin/psql/tab-complete.c index ea2295cca4..0946bab9cd 100644 --- a/src/bin/psql/tab-complete.c +++ b/src/bin/psql/tab-complete.c @@ -3,7 +3,7 @@ * * Copyright 2000-2002 by PostgreSQL Global Development Group * - * $Header: /cvsroot/pgsql/src/bin/psql/tab-complete.c,v 1.77 2003/05/14 03:26:02 tgl Exp $ + * $Header: /cvsroot/pgsql/src/bin/psql/tab-complete.c,v 1.78 2003/06/11 18:01:14 momjian Exp $ */ /*---------------------------------------------------------------------- @@ -538,6 +538,7 @@ psql_completion(char *text, int start, int end) "lc_time", "log_duration", "log_executor_stats", + "log_min_duration_statement", "log_min_error_statement", "log_min_messages", "log_parser_stats", diff --git a/src/include/utils/guc.h b/src/include/utils/guc.h index c9b4b93ce5..2926f0a413 100644 --- a/src/include/utils/guc.h +++ b/src/include/utils/guc.h @@ -7,7 +7,7 @@ * Copyright 2000-2003 by PostgreSQL Global Development Group * Written by Peter Eisentraut . * - * $Id: guc.h,v 1.31 2003/05/06 20:26:28 tgl Exp $ + * $Id: guc.h,v 1.32 2003/06/11 18:01:14 momjian Exp $ *-------------------------------------------------------------------- */ #ifndef GUC_H @@ -142,4 +142,6 @@ void write_nondefault_variables(GucContext context); void read_nondefault_variables(void); #endif +extern int log_min_duration_statement; + #endif /* GUC_H */