From b8382c26884f4adcf525e0bc7fdf0c671d57b84d Mon Sep 17 00:00:00 2001 From: Bruce Momjian Date: Wed, 8 Oct 2003 03:49:38 +0000 Subject: [PATCH] Have log_min_duration_statement = 0 always print duration/statement. Change log line to be "duration: ms query:" Indent multi-line queries with a tab in the server logs. --- doc/src/sgml/runtime.sgml | 22 +++++++------- src/backend/tcop/postgres.c | 23 ++++++++------- src/backend/utils/error/elog.c | 29 +++++++++++++++++-- src/backend/utils/misc/guc.c | 8 ++--- src/backend/utils/misc/postgresql.conf.sample | 5 ++-- 5 files changed, 58 insertions(+), 29 deletions(-) diff --git a/doc/src/sgml/runtime.sgml b/doc/src/sgml/runtime.sgml index 443cd40387..d1b398425d 100644 --- a/doc/src/sgml/runtime.sgml +++ b/doc/src/sgml/runtime.sgml @@ -1,5 +1,5 @@ @@ -1689,16 +1689,16 @@ SET ENABLE_SEQSCAN TO OFF; 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 their actual duration. Setting this to zero (the default) - disables time-based logging. For example, if you set it - to 250 then all SQL statements that run longer - than 250ms will be logged. Enabling this - option can be useful in tracking down unoptimized queries in - your applications. - Only superusers can increase this or set it to zero if this option - is set to non-zero by the administrator. + for statement to be logged. All SQL statements + that run in the time specified or longer will be logged with + their duration. Setting this to zero will print + all queries and their durations. Minus-one (the default) + disables this. For example, if you set it to + 250 then all SQL statements that run 250ms + or longer will be logged. Enabling this option can be + useful in tracking down unoptimized queries in your applications. + Only superusers can increase this or set it to minus-one if this + option is set by the administrator. diff --git a/src/backend/tcop/postgres.c b/src/backend/tcop/postgres.c index 1d17f977cd..80cc526213 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.370 2003/10/04 02:47:04 momjian Exp $ + * $Header: /cvsroot/pgsql/src/backend/tcop/postgres.c,v 1.371 2003/10/08 03:49:37 momjian Exp $ * * NOTES * this is the "main" module of the postgres backend and @@ -694,7 +694,7 @@ exec_simple_query(const char *query_string) * because gettimeofday() wasn't called. Similarly, * log_statement_stats has to be captured once. */ - if (save_log_duration || save_log_min_duration_statement > 0) + if (save_log_duration || save_log_min_duration_statement != -1) gettimeofday(&start_t, NULL); if (save_log_statement_stats) @@ -940,7 +940,7 @@ exec_simple_query(const char *query_string) * Combine processing here as we need to calculate the query duration * in both instances. */ - if (save_log_duration || save_log_min_duration_statement > 0) + if (save_log_duration || save_log_min_duration_statement != -1) { long usecs; bool print_statement; @@ -957,15 +957,17 @@ exec_simple_query(const char *query_string) * Output a duration_statement to the log if the query has exceeded * the min duration, or if we are to print all durations. */ - print_statement = (save_log_min_duration_statement > 0 && - usecs >= save_log_min_duration_statement * 1000); + print_statement = (save_log_min_duration_statement == 0 || + (save_log_min_duration_statement > 0 && + usecs >= save_log_min_duration_statement * 1000)); if (save_log_duration || print_statement) ereport(LOG, - (errmsg("duration(secs): %ld.%06ld%s%s", - (long) (stop_t.tv_sec - start_t.tv_sec), - (long) (stop_t.tv_usec - start_t.tv_usec), - print_statement ? " " : "", + (errmsg("duration: %ld.%03ld ms%s%s", + (long) ((stop_t.tv_sec - start_t.tv_sec) * 1000 + + (stop_t.tv_usec - start_t.tv_usec) / 1000), + (long) (stop_t.tv_usec - start_t.tv_usec) % 1000, + print_statement ? " query: " : "", print_statement ? query_string : ""))); } @@ -2655,7 +2657,7 @@ PostgresMain(int argc, char *argv[], const char *username) if (!IsUnderPostmaster) { puts("\nPOSTGRES backend interactive interface "); - puts("$Revision: 1.370 $ $Date: 2003/10/04 02:47:04 $\n"); + puts("$Revision: 1.371 $ $Date: 2003/10/08 03:49:37 $\n"); } /* @@ -3196,3 +3198,4 @@ ShowUsage(const char *title) pfree(str.data); } + diff --git a/src/backend/utils/error/elog.c b/src/backend/utils/error/elog.c index 8fd5f41046..8c4774fd6f 100644 --- a/src/backend/utils/error/elog.c +++ b/src/backend/utils/error/elog.c @@ -37,7 +37,7 @@ * * * IDENTIFICATION - * $Header: /cvsroot/pgsql/src/backend/utils/error/elog.c,v 1.123 2003/09/25 06:58:05 petere Exp $ + * $Header: /cvsroot/pgsql/src/backend/utils/error/elog.c,v 1.124 2003/10/08 03:49:38 momjian Exp $ * *------------------------------------------------------------------------- */ @@ -145,6 +145,7 @@ static const char *useful_strerror(int errnum); static const char *error_severity(int elevel); static const char *print_timestamp(void); static const char *print_pid(void); +static char *str_prepend_tabs(const char *str); /* @@ -1135,6 +1136,8 @@ send_message_to_server_log(ErrorData *edata) /* Write to stderr, if enabled */ if (Use_syslog <= 1 || whereToSendOutput == Debug) { + char *p = str_prepend_tabs(buf.data); + /* * Timestamp and PID are only used for stderr output --- we assume * the syslog daemon will supply them for us in the other case. @@ -1142,7 +1145,8 @@ send_message_to_server_log(ErrorData *edata) fprintf(stderr, "%s%s%s", Log_timestamp ? print_timestamp() : "", Log_pid ? print_pid() : "", - buf.data); + p); + pfree(p); } pfree(buf.data); @@ -1450,3 +1454,24 @@ print_pid(void) snprintf(buf, sizeof(buf), "[%d] ", (int) MyProcPid); return buf; } + +/* + * str_prepend_tabs + * + * This string prepends a tab to message continuation lines. + */ +static char *str_prepend_tabs(const char *str) +{ + char *outstr = palloc(strlen(str) * 2 + 1); + int len = strlen(str); + int i, outlen = 0; + + for (i = 0; i < len; i++) + { + outstr[outlen++] = str[i]; + if (str[i] == '\n' && str[i+1] != '\0' ) + outstr[outlen++] = '\t'; + } + outstr[outlen++] = '\0'; + return outstr; +} diff --git a/src/backend/utils/misc/guc.c b/src/backend/utils/misc/guc.c index 377993a374..8e2c8517e5 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.162 2003/10/03 19:26:49 tgl Exp $ + * $Header: /cvsroot/pgsql/src/backend/utils/misc/guc.c,v 1.163 2003/10/08 03:49:38 momjian Exp $ * *-------------------------------------------------------------------- */ @@ -128,7 +128,7 @@ int log_min_error_statement = PANIC; int log_min_messages = NOTICE; int client_min_messages = NOTICE; -int log_min_duration_statement = 0; +int log_min_duration_statement = -1; /* @@ -1185,10 +1185,10 @@ static struct config_int ConfigureNamesInt[] = {"log_min_duration_statement", PGC_USERLIMIT, LOGGING_WHEN, gettext_noop("minimum execution time in milliseconds above which statements will " "be logged"), - gettext_noop("The default is 0 (turning this feature off).") + gettext_noop("Zero prints all queries. The default is -1 (turning this feature off).") }, &log_min_duration_statement, - 0, 0, INT_MAX / 1000, NULL, NULL + -1, -1, INT_MAX / 1000, NULL, NULL }, /* End-of-list marker */ diff --git a/src/backend/utils/misc/postgresql.conf.sample b/src/backend/utils/misc/postgresql.conf.sample index c880dc4031..1ead89e130 100644 --- a/src/backend/utils/misc/postgresql.conf.sample +++ b/src/backend/utils/misc/postgresql.conf.sample @@ -157,9 +157,10 @@ # debug5, debug4, debug3, debug2, debug1, # info, notice, warning, error, panic(off) -#log_min_duration_statement = 0 # Log all statements whose +#log_min_duration_statement = -1 # Log all statements whose # execution time exceeds the value, in - # milliseconds. Zero disables. + # milliseconds. Zero prints all queries. + # Minus-one disables. #silent_mode = false # DO NOT USE without Syslog!