Re: fix log_min_duration_statement logic error

Tom Lane wrote:
> Bruce Momjian  writes:
> > Another example:
> > 	LOG:  duration: 4.228 ms; select *\nfrom pg_language;
> 
> Minor quibble: would it read better as
> 
> 	LOG:  duration n.nnn ms: query
> or
> 	LOG:  duration n.nnn ms for query

I like it:

	LOG:  duration: 4.056 ms for select * \nfrom pg_language;

Another idea if you like consistency would be:

	LOG:  duration: 4.056 ms  query: select * \nfrom pg_language;

Patch for "query:" version attached.

Do I need to pfree the memory returned by str_make_symbolic_eol() or is
that cleaned up automatically?

-- 
  Bruce Momjian                        |  http://candle.pha.pa.us
  pgman@candle.pha.pa.us               |  (610) 359-1001
  +  If your life is a hard drive,     |  13 Roberts Road
  +  Christ can be your backup.        |  Newtown Square, Pennsylvania 19073
Index: doc/src/sgml/runtime.sgml
===================================================================
RCS file: /cvsroot/pgsql-server/doc/src/sgml/runtime.sgml,v
retrieving revision 1.210
diff -c -c -r1.210 runtime.sgml
*** doc/src/sgml/runtime.sgml	3 Oct 2003 19:26:49 -0000	1.210
--- doc/src/sgml/runtime.sgml	5 Oct 2003 21:17:30 -0000
***************
*** 1691,1702 ****
           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.
          
--- 1691,1702 ----
           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 will print
!          all queries with their durations.  Minus-one (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.
          
Index: src/backend/tcop/postgres.c
===================================================================
RCS file: /cvsroot/pgsql-server/src/backend/tcop/postgres.c,v
retrieving revision 1.370
diff -c -c -r1.370 postgres.c
*** src/backend/tcop/postgres.c	4 Oct 2003 02:47:04 -0000	1.370
--- src/backend/tcop/postgres.c	5 Oct 2003 21:17:33 -0000
***************
*** 150,156 ****
  static void finish_xact_command(void);
  static void SigHupHandler(SIGNAL_ARGS);
  static void FloatExceptionHandler(SIGNAL_ARGS);
! 
  
  /* ----------------------------------------------------------------
   *		routines to obtain user input
--- 150,156 ----
  static void finish_xact_command(void);
  static void SigHupHandler(SIGNAL_ARGS);
  static void FloatExceptionHandler(SIGNAL_ARGS);
! static char *str_make_symbolic_eol(const char *str);
  
  /* ----------------------------------------------------------------
   *		routines to obtain user input
***************
*** 461,467 ****
  
  	if (log_statement)
  		ereport(LOG,
! 				(errmsg("query: %s", query_string)));
  
  	if (log_parser_stats)
  		ResetUsage();
--- 461,467 ----
  
  	if (log_statement)
  		ereport(LOG,
! 				(errmsg("query: %s", str_make_symbolic_eol(query_string))));
  
  	if (log_parser_stats)
  		ResetUsage();
***************
*** 686,692 ****
  	 */
  	debug_query_string = query_string;
  
! 	pgstat_report_activity(query_string);
  
  	/*
  	 * We use save_log_* so "SET log_duration = true"  and "SET
--- 686,692 ----
  	 */
  	debug_query_string = query_string;
  
! 	pgstat_report_activity(str_make_symbolic_eol(query_string));
  
  	/*
  	 * We use save_log_* so "SET log_duration = true"  and "SET
***************
*** 694,700 ****
  	 * because gettimeofday() wasn't called. Similarly,
  	 * log_statement_stats has to be captured once.
  	 */
! 	if (save_log_duration || save_log_min_duration_statement > 0)
  		gettimeofday(&start_t, NULL);
  
  	if (save_log_statement_stats)
--- 694,700 ----
  	 * because gettimeofday() wasn't called. Similarly,
  	 * log_statement_stats has to be captured once.
  	 */
! 	if (save_log_duration || save_log_min_duration_statement != -1)
  		gettimeofday(&start_t, NULL);
  
  	if (save_log_statement_stats)
***************
*** 940,946 ****
  	 * Combine processing here as we need to calculate the query duration
  	 * in both instances.
  	 */
! 	if (save_log_duration || save_log_min_duration_statement > 0)
  	{
  		long		usecs;
  		bool		print_statement;
--- 940,946 ----
  	 * Combine processing here as we need to calculate the query duration
  	 * in both instances.
  	 */
! 	if (save_log_duration || save_log_min_duration_statement != -1)
  	{
  		long		usecs;
  		bool		print_statement;
***************
*** 957,972 ****
  		 * 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);
  
  		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 ? " " : "",
! 							print_statement ? query_string : "")));
  	}
  
  	if (save_log_statement_stats)
--- 957,974 ----
  		 * 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 ||
! 						   (save_log_min_duration_statement > 0 &&
! 						    usecs >= save_log_min_duration_statement * 1000));
  
  		if (save_log_duration || print_statement)
  			ereport(LOG,
! 					(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 ? str_make_symbolic_eol(query_string) : "")));
  	}
  
  	if (save_log_statement_stats)
***************
*** 1000,1006 ****
  	 */
  	debug_query_string = query_string;
  
! 	pgstat_report_activity(query_string);
  
  	set_ps_display("PARSE");
  
--- 1002,1008 ----
  	 */
  	debug_query_string = query_string;
  
! 	pgstat_report_activity(str_make_symbolic_eol(query_string));
  
  	set_ps_display("PARSE");
  
***************
*** 3196,3198 ****
--- 3198,3236 ----
  
  	pfree(str.data);
  }
+ 
+ /*
+  *	str_make_symbolic_eol
+  *
+  *	This string coverts literal newlines to "\n" for log output.
+  */
+ static char *str_make_symbolic_eol(const char *str)
+ {
+ 	char *outstr = palloc(strlen(str) * 2 + 1);
+ 	int	len = strlen(str);
+ 	int i, outlen = 0;
+ 
+ 	for (i = 0; i < len; i++)
+ 	{
+ 		if (str[i] == '\n')
+ 		{
+ 			outstr[outlen++] = '\\';
+ 			outstr[outlen++] = 'n';
+ 		}
+ 		else if (str[i] == '\r')
+ 		{
+ 			outstr[outlen++] = '\\';
+ 			outstr[outlen++] = 'r';
+ 		}
+ 		else if (str[i] == '\\')
+ 		{
+ 			outstr[outlen++] = '\\';
+ 			outstr[outlen++] = '\\';
+ 		}
+ 		else
+ 			outstr[outlen++] = str[i];
+ 	}
+ 	outstr[outlen++]	= '\0';
+ 	return outstr;
+ }
+ 
Index: src/backend/utils/misc/guc.c
===================================================================
RCS file: /cvsroot/pgsql-server/src/backend/utils/misc/guc.c,v
retrieving revision 1.162
diff -c -c -r1.162 guc.c
*** src/backend/utils/misc/guc.c	3 Oct 2003 19:26:49 -0000	1.162
--- src/backend/utils/misc/guc.c	5 Oct 2003 21:17:37 -0000
***************
*** 128,134 ****
  int			log_min_messages = NOTICE;
  int			client_min_messages = NOTICE;
  
! int			log_min_duration_statement = 0;
  
  
  /*
--- 128,134 ----
  int			log_min_messages = NOTICE;
  int			client_min_messages = NOTICE;
  
! int			log_min_duration_statement = -1;
  
  
  /*
***************
*** 1185,1194 ****
  		{"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).")
  		},
  		&log_min_duration_statement,
! 		0, 0, INT_MAX / 1000, NULL, NULL
  	},
  
  	/* End-of-list marker */
--- 1185,1194 ----
  		{"log_min_duration_statement", PGC_USERLIMIT, LOGGING_WHEN,
  			gettext_noop("minimum execution time in milliseconds above which statements will "
  						 "be logged"),
! 			gettext_noop("Zero prints all queries.  The default is -1 (turning this feature off).")
  		},
  		&log_min_duration_statement,
! 		-1, -1, INT_MAX / 1000, NULL, NULL
  	},
  
  	/* End-of-list marker */
Index: src/backend/utils/misc/postgresql.conf.sample
===================================================================
RCS file: /cvsroot/pgsql-server/src/backend/utils/misc/postgresql.conf.sample,v
retrieving revision 1.91
diff -c -c -r1.91 postgresql.conf.sample
*** src/backend/utils/misc/postgresql.conf.sample	3 Oct 2003 19:26:49 -0000	1.91
--- src/backend/utils/misc/postgresql.conf.sample	5 Oct 2003 21:17:37 -0000
***************
*** 157,165 ****
  				 #   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.
  
  #silent_mode = false		 # DO NOT USE without Syslog!
  
--- 157,166 ----
  				 #   debug5, debug4, debug3, debug2, debug1,
  				 #   info, notice, warning, error, panic(off)
  				 
! #log_min_duration_statement = -1 # Log all statements whose
  				 # execution time exceeds the value, in
! 				 # milliseconds.  Zero prints all queries.
! 				 # Minus-one disables.
  
  #silent_mode = false		 # DO NOT USE without Syslog!